Edgewall Software
Modify

Opened 6 months ago

Closed 5 months ago

#13378 closed defect (fixed)

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

Reported by: anonymous Owned by: Jun Omae
Priority: normal Milestone: 1.5.3
Component: notification Version: 1.5.2
Severity: blocker Keywords:
Cc: Branch:
Release Notes:

Add workaround for SmtpEmailSender with unicode credentials.

API Changes:
Internal Changes:

Description (last modified by 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.

Attachments (0)

Change History (15)

comment:1 by anonymous, 6 months ago

Description: modified (diff)

comment:2 by Ryan J Ollos, 6 months ago

Component: web frontend/tracdnotification
Milestone: 1.5.3

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

comment:3 by Jun Omae, 6 months ago

Keywords: needinfo added

comment:4 by anonymous, 6 months ago

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?

comment:5 by anonymous, 6 months ago

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…

comment:6 by anonymous, 6 months ago

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@*

comment:7 by anonymous, 6 months ago

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.

comment:8 by Bruce <bruce@…>, 6 months ago

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'

comment:9 by anonymous, 6 months ago

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.)

comment:10 by Bruce <bruce@…>, 6 months ago

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?

comment:11 by Jun Omae, 5 months ago

Keywords: needinfo removed
Owner: set to Jun Omae
Status: newassigned

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

comment:12 by Jun Omae, 5 months ago

Updated jomae.git@t13378:

Last edited 5 months ago by Jun Omae (previous) (diff)

comment:13 by Jun Omae, 5 months ago

Updated jomae.git@t13378 (diff):

Last edited 5 months ago by Jun Omae (previous) (diff)

comment:14 by Ryan J Ollos, 5 months ago

Tests pass for me with Python 3.9.4 on macOS.

comment:15 by Jun Omae, 5 months ago

Release Notes: modified (diff)
Resolution: fixed
Status: assignedclosed

Thanks for the testing. Committed in [17528].

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Jun Omae.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from Jun Omae to the specified user.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.