Notifications fail in Trac 1.5.2 with what appears to be a Python3 porting error

[anonymous]

Running Trac 1.5.2 on Alpine Linux with Python3, I see the following error whenever a ticket is updated.

2021-03-26 20:02:52,029 Trac[web_ui] ERROR: Failure sending notification on change to ticket #1901: AttributeError: 'bytes' object has no attribute 'encode'

According to the following Stack Overflow post, the root cause may be a defect introduced in the Python3 port.

​https://stackoverflow.com/questions/60368956/attributeerrorbytes-object-has-no-attribute-encode

# uname -a
Linux da318296525d 4.15.0-139-generic #143-Ubuntu SMP Tue Mar 16 01:30:17 UTC 2021 x86_64 Linux
# python3 --version
Python 3.7.10

/usr/bin/tracd -b 0.0.0.0 -p 8000 --auth <redacted>,/var/www/trac/auth.digest,Trac -e /var/www/trac --base-path /trac

I searched the open tickets and did not find this issue reported anywhere else. The only issue that manifest a similar error is #5515.

[Ryan J Ollos]

Thanks for reporting. Could you please attach the traceback from the logs?: TracTroubleshooting#ChecktheLogs

[anonymous]

Ok, I enabled debug logging and restarted Trac 1.5.2 but I am not getting a traceback. Here is the log file with PII redacted.

2021-03-30 15:32:54,797 Trac[perm] DEBUG: DefaultPermissionPolicy allows blacey performing TICKET_EDIT_COMMENT on <Resource 'ticket:1901, comment:None'>
2021-03-30 15:32:54,886 Trac[api] DEBUG: Adding (user1 [1]) for 'always' on rule (TicketOwnerSubscriber) for (email)
2021-03-30 15:32:54,886 Trac[api] DEBUG: Adding (user2 [1]) for 'always' on rule (TicketPreviousUpdatersSubscriber) for (email)
2021-03-30 15:32:54,887 Trac[mail] DEBUG: EmailDistributor has found the following formats capable of handling 'email' of 'ticket': text/plain
2021-03-30 15:32:54,932 Trac[mail] DEBUG: EmailDistributor is sending event as 'text/plain' to: user1@somewhere.com, user2@somewhere.com
2021-03-30 15:32:54,960 Trac[mail] INFO: Sending notification through SMTP at mail.somewhere.com to ['user1@somewhere.com', 'user2@somewhere.com']
2021-03-30 15:32:57,152 Trac[web_ui] ERROR: Failure sending notification on change to ticket #1901: AttributeError: 'bytes' object has no attribute 'encode'
2021-03-30 15:32:57,153 Trac[chrome] DEBUG: Prepare chrome data for request
2021-03-30 15:32:57,155 Trac[authz_policy] DEBUG: Checking TRAC_ADMIN on admin:general/basics@*
20

This is the Warning message presented on the UI.

Warning: The change has been saved, but an error occurred while sending notifications: 'bytes' object has no attribute 'encode'

Any other suggestions of what I can do to provide insight into the root cause?

[anonymous]

Here is the Trac startup log snippet in case it offers any insight…

2021-03-30 15:32:23,757 Trac[env] INFO: -------------------------------- environment startup [Trac 1.5.2] --------------------------------
2021-03-30 15:32:23,781 Trac[loader] DEBUG: Loading plugin "trac.about" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:23,885 Trac[loader] DEBUG: Loading plugin "trac.admin.console" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:23,901 Trac[loader] DEBUG: Loading plugin "trac.admin.web_ui" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:23,904 Trac[loader] DEBUG: Loading plugin "trac.attachment" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:23,910 Trac[loader] DEBUG: Loading plugin "trac.db.mysql" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:23,922 Trac[loader] DEBUG: Skipping "trac.db.mysql = trac.db.mysql_backend [mysql]": DistributionNotFound: The 'PyMySQL; extra == "mysql"' distribution was not found and is required by the application
2021-03-30 15:32:23,922 Trac[loader] DEBUG: Loading plugin "trac.db.postgres" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:23,925 Trac[loader] DEBUG: Skipping "trac.db.postgres = trac.db.postgres_backend": DistributionNotFound: The 'psycopg2>=2.0 or psycopg2-binary' distribution was not found and is required by Trac
2021-03-30 15:32:23,926 Trac[loader] DEBUG: Loading plugin "trac.db.sqlite" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:23,927 Trac[loader] DEBUG: Loading plugin "trac.mimeview.patch" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:23,929 Trac[loader] DEBUG: Loading plugin "trac.mimeview.pygments" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:23,951 Trac[loader] DEBUG: Loading plugin "trac.mimeview.rst" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,089 Trac[loader] DEBUG: Loading plugin "trac.mimeview.txtl" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,182 Trac[loader] DEBUG: Loading plugin "trac.notification.api" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,183 Trac[loader] DEBUG: Loading plugin "trac.notification.mail" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,184 Trac[loader] DEBUG: Loading plugin "trac.notification.prefs" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,188 Trac[loader] DEBUG: Loading plugin "trac.prefs" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,190 Trac[loader] DEBUG: Loading plugin "trac.search" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,192 Trac[loader] DEBUG: Loading plugin "trac.ticket.admin" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,212 Trac[loader] DEBUG: Loading plugin "trac.ticket.batch" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,214 Trac[loader] DEBUG: Loading plugin "trac.ticket.notification" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,215 Trac[loader] DEBUG: Loading plugin "trac.ticket.query" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,221 Trac[loader] DEBUG: Loading plugin "trac.ticket.report" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,227 Trac[loader] DEBUG: Loading plugin "trac.ticket.roadmap" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,228 Trac[loader] DEBUG: Loading plugin "trac.ticket.web_ui" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,235 Trac[loader] DEBUG: Loading plugin "trac.timeline" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,239 Trac[loader] DEBUG: Loading plugin "trac.versioncontrol.admin" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,241 Trac[loader] DEBUG: Loading plugin "trac.versioncontrol.svn_authz" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,243 Trac[loader] DEBUG: Loading plugin "trac.versioncontrol.web_ui" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,258 Trac[loader] DEBUG: Loading plugin "trac.web.auth" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,259 Trac[loader] DEBUG: Loading plugin "trac.web.main" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,260 Trac[loader] DEBUG: Loading plugin "trac.web.session" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,261 Trac[loader] DEBUG: Loading plugin "trac.wiki.admin" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,263 Trac[loader] DEBUG: Loading plugin "trac.wiki.interwiki" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,264 Trac[loader] DEBUG: Loading plugin "trac.wiki.macros" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,265 Trac[loader] DEBUG: Loading plugin "trac.wiki.web_api" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,267 Trac[loader] DEBUG: Loading plugin "trac.wiki.web_ui" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,269 Trac[loader] DEBUG: Loading plugin "tracopt.perm.authz_policy" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,272 Trac[loader] DEBUG: Loading plugin "tracopt.perm.config_perm_provider" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,274 Trac[loader] DEBUG: Loading plugin "tracopt.ticket.clone" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,276 Trac[loader] DEBUG: Loading plugin "tracopt.ticket.commit_updater" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,280 Trac[loader] DEBUG: Loading plugin "tracopt.ticket.deleter" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,281 Trac[loader] DEBUG: Loading plugin "tracopt.versioncontrol.git.git_fs" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,293 Trac[loader] DEBUG: Loading plugin "tracopt.versioncontrol.svn.svn_fs" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,298 Trac[loader] DEBUG: Loading plugin "tracopt.versioncontrol.svn.svn_prop" from "/usr/lib/python3.7/site-packages"
2021-03-30 15:32:24,303 Trac[default_workflow] DEBUG: Workflow actions at initialization: defaultdict(<class 'dict'>, {'accept': {'oldstates': ['new'], 'newstate': 'assigned', 'operations': ['set_owner_to_self'], 'permissions': ['TICKET_MODIFY'], 'label': 'accept', 'name': '', 'default': 0}, 'create': {'oldstates': [None], 'newstate': 'new', 'default': 1, 'label': 'create', 'name': '', 'operations': [], 'permissions': []}, 'create_and_assign': {'oldstates': [None], 'newstate': 'assigned', 'label': 'assign', 'operations': ['may_set_owner'], 'permissions': ['TICKET_MODIFY'], 'name': '', 'default': 0}, 'leave': {'oldstates': ['*'], 'newstate': '*', 'default': 1, 'operations': ['leave_status'], 'label': 'leave', 'name': '', 'permissions': []}, 'reassign': {'oldstates': ['new', 'assigned', 'reopened'], 'newstate': 'new', 'operations': ['set_owner'], 'permissions': ['TICKET_MODIFY'], 'label': 'reassign', 'name': '', 'default': 0}, 'reopen': {'oldstates': ['closed'], 'newstate': 'reopened', 'operations': ['del_resolution'], 'permissions': ['TICKET_CREATE'], 'label': 'reopen', 'name': '', 'default': 0}, 'resolve': {'oldstates': ['new', 'assigned', 'reopened'], 'newstate': 'closed', 'operations': ['set_resolution'], 'permissions': ['TICKET_MODIFY'], 'label': 'resolve', 'name': '', 'default': 0}, '_reset': {'default': 0, 'label': 'Reset', 'newstate': 'new', 'oldstates': [], 'operations': ['reset_workflow'], 'permissions': ['TICKET_ADMIN']}})

Let me know what else I can provide…

[anonymous]

One more thing - I know tracebacks are enabled because I am seeing the following in my log:

2021-03-30 15:32:24,643 Trac[git_fs] INFO: detected GIT version b'2.22.5'
2021-03-30 15:32:24,645 Trac[svn_fs] INFO: Failed to load Subversion bindings
Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/tracopt/versioncontrol/svn/svn_fs.py", line 303, in __init__
    _import_svn()
  File "/usr/lib/python3.7/site-packages/tracopt/versioncontrol/svn/svn_fs.py", line 77, in _import_svn
    from svn import fs, repos, core, delta
ModuleNotFoundError: No module named 'svn'
2021-03-30 15:32:24,647 Trac[authz_policy] DEBUG: Checking VERSIONCONTROL_ADMIN on admin:versioncontrol/repository@*

[anonymous]

Changing in source:tags/trac-1.5.2/trac/ticket/web_ui.py#L1391​ exception_to_unicode(e)) to exception_to_unicode(e, traceback=True)) would maybe help diagnose this problem.

[Bruce <bruce@…>]

Here you go:

2021-03-31 01:38:48,144 Trac[web_ui] ERROR: Failure sending notification on change to ticket #1901: 
Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/trac/ticket/web_ui.py", line 1387, in _do_save
    NotificationSystem(self.env).notify(event)
  File "/usr/lib/python3.7/site-packages/trac/notification/api.py", line 356, in notify
    self.distribute_event(event, self.subscriptions(event))
  File "/usr/lib/python3.7/site-packages/trac/notification/api.py", line 380, in distribute_event
    distributor.distribute(transport, recipients, event)
  File "/usr/lib/python3.7/site-packages/trac/notification/mail.py", line 579, in distribute
    self._do_send(transport, event, message, cc_addrs, bcc_addrs)
  File "/usr/lib/python3.7/site-packages/trac/notification/mail.py", line 660, in _do_send
    notify_sys.send_email(from_addr, list(to_addrs), message.as_bytes())
  File "/usr/lib/python3.7/site-packages/trac/notification/api.py", line 349, in send_email
    self.email_sender.send(from_addr, recipients, message)
  File "/usr/lib/python3.7/site-packages/trac/notification/mail.py", line 712, in send
    self.smtp_password.encode('utf-8'))
  File "/usr/lib/python3.7/smtplib.py", line 721, in login
    initial_response_ok=initial_response_ok)
  File "/usr/lib/python3.7/smtplib.py", line 630, in auth
    response = encode_base64(initial_response.encode('ascii'), eol='')
AttributeError: 'bytes' object has no attribute 'encode'

[anonymous]

​Python smtplib does not support non-ASCII strings / bytes usernames or passwords.

So source:tags/trac-1.5.2/trac/notification/mail.py#L712​ should maybe change self.smtp_password.encode('utf-8') to self.smtp_password (and similar for self.smtp_user) and will likely fail for usernames / passwords containing "special" unicode characters.

(For example ​zope.sendmail hit the same problem.)

[Bruce <bruce@…>]

I implemented the suggested work-around and confirmed that is remedies the problem.

Is this be the official Trac 1.5.x solution or will the implementation be something different?

[Jun Omae]

Proposed changes in jomae.git@t13378 (diff):

• Use smtpd.SMTPServer in order to implement AUTH command
• Add tests for sending mail through SMTP with authentication PLAIN, LOGIN, CRAM-MD5
• Add logging with traceback for errors except SMTPException in such a case

[Jun Omae]

Updated jomae.git@t13378:

• [04519136/jomae.git] Add tests for SMTP AUTH with unicode credentials (XFAIL)

[Jun Omae]

Updated jomae.git@t13378 (diff):

• [6d25c6600/jomae.git] Workaround for smtplib.SMTP with unicode credentials
• [a0338f41f/jomae.git] Use workaround only when the credentials have non-ascii characters
• [c05bfeb69/jomae.git] Revise workaround because AUTH LOGIN failing on Python 3.8.9 and 3.9.4

[Ryan J Ollos]

Tests pass for me with Python 3.9.4 on macOS.

[Jun Omae]

Thanks for the testing. Committed in [17528].