Do not add new topic - SMTPDataError: (553, '5.5.2 Bad Message ID')

[tonal@…]

How to Reproduce

While doing a POST operation on /discussion/1, Trac issued an internal error.

In latest revisions Trac & DiscussionPlugin I do not add new topic. Afte click Submit button I see error page.

Request parameters:

{'__FORM_TOKEN': u'c15d2f510dd4199aea3e9fe9',
 'author': u'tonal',
 'body': u'Enter your message here...',
 'discussion_action': u'post-add',
 'forum': u'1',
 'subject': u'Test',
 'submit': u'Submit'}

System Information

Trac	0.11dev-r6399
Python	2.5.1 (r251:54863, Oct 5 2007, 13:36:32) [GCC 4.1.3 20070929 (prerelease) (Ubuntu 4.1.2-16ubuntu2)]
setuptools	0.6c7
SQLite	3.4.2
pysqlite	2.3.4
Genshi	0.5dev-r789
Pygments	0.9
Subversion	1.4.4 (r25188)

Python Traceback

Traceback (most recent call last):
  File "/usr/lib/python2.5/site-packages/Trac-0.11dev_r6399-py2.5.egg/trac/web/main.py", line 406, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/lib/python2.5/site-packages/Trac-0.11dev_r6399-py2.5.egg/trac/web/main.py", line 195, in dispatch
    resp = chosen_handler.process_request(req)
  File "build/bdist.linux-i686/egg/tracdiscussion/core.py", line 77, in process_request
    return api.process_discussion(context) + (None,)
  File "build/bdist.linux-i686/egg/tracdiscussion/api.py", line 47, in process_discussion
    is_moderator)
  File "build/bdist.linux-i686/egg/tracdiscussion/api.py", line 567, in _do_action
    notifier.notify(context, mode, forum, new_topic, None, to, cc)
  File "build/bdist.linux-i686/egg/tracdiscussion/notification.py", line 84, in notify
    NotifyEmail.notify(self, id, subject)
  File "/usr/lib/python2.5/site-packages/Trac-0.11dev_r6399-py2.5.egg/trac/notification.py", line 239, in notify
    Notify.notify(self, resid)
  File "/usr/lib/python2.5/site-packages/Trac-0.11dev_r6399-py2.5.egg/trac/notification.py", line 129, in notify
    self.send(torcpts, ccrcpts)
  File "build/bdist.linux-i686/egg/tracdiscussion/notification.py", line 123, in send
    NotifyEmail.send(self, torcpts, ccrcpts, header)
  File "/usr/lib/python2.5/site-packages/Trac-0.11dev_r6399-py2.5.egg/trac/notification.py", line 404, in send
    self.server.sendmail(msg['From'], recipients, msgtext)
  File "smtplib.py", line 699, in sendmail
    raise SMTPDataError(code, resp)
SMTPDataError: (553, '5.5.2 Bad Message ID')

[Radek Bartoň]

Hello.

This seems as too strict spam filtering rules at your SMTP server. Can you use e-mail notification in Trac tickets or it's only caused by DiscussionPlugin? I was searching a little about this kind of error message but I dind't find anything direct yet. For some weird reason many undirect references was originally from Russia, so this would be some local problem. I'll search a bit aggain or I'll consult this problem with Trac developers lately. Can you see what is printed in your log with debug level loggin? There sould be printed whole e-mail content, IIRC.

[Radek Bartoň]

I found this ​http://www.opennet.ru/base/net/sendmail_regex.txt.html. Even if I can read azbuka, I can't understand russian much. Are there some usefull informations?

[tonal@…]

I recive notifycation for trac topic change. Bat I do not create forum topic. Maybe plagin forget commit transaction after save data to base?

Full trac log for error:

2008-01-23 12:52:51,824 Trac[main] DEBUG: Dispatching <Request "POST u'/admin/general/logging'">
2008-01-23 12:52:51,856 Trac[session] DEBUG: Retrieving session for ID u'tonal'
2008-01-23 12:52:51,881 Trac[main] DEBUG: Dispatching <Request "GET u'/admin/general/logging'">
2008-01-23 12:52:51,937 Trac[chrome] DEBUG: Prepare chrome data for request
2008-01-23 12:52:51,965 Trac[session] DEBUG: Retrieving session for ID u'tonal'
2008-01-23 12:53:12,457 Trac[main] DEBUG: Dispatching <Request "GET u'/discussion'">
2008-01-23 12:53:12,482 Trac[api] DEBUG: realm: discussion-core, action: None, preview: False, submit: False
2008-01-23 12:53:12,483 Trac[api] DEBUG: ['forum-list']
2008-01-23 12:53:12,488 Trac[session] DEBUG: Retrieving session for ID u'tonal'
2008-01-23 12:53:12,492 Trac[api] DEBUG: SELECT COUNT(f.id) FROM forum f WHERE f.forum_group = 0
2008-01-23 12:53:12,494 Trac[api] DEBUG: SELECT g.id, g.name, g.description, f.forums FROM  forum_group g LEFT JOIN (SELECT COUNT(id) AS forums,  forum_group FROM forum GROUP BY forum_group) f ON g.id =  f.forum_group ORDER BY g.id ASC
2008-01-23 12:53:12,496 Trac[api] DEBUG: SELECT f.id, f.name, f.author, f.time, f.moderators, f.forum_group, f.subject, f.description, ta.topics, ta.replies, ta.lasttopic, ta.lastreply FROM forum f LEFT JOIN (SELECT COUNT(t.id) AS topics, MAX(t.time) AS lasttopic, SUM(ma.replies) AS replies, MAX(ma.lastreply) AS lastreply, t.forum AS forum FROM  topic t LEFT JOIN (SELECT COUNT(m.id) AS replies, MAX(m.time) AS lastreply, m.topic AS topic FROM message m GROUP BY m.topic) ma ON t.id = ma.topic GROUP BY forum) ta ON f.id = ta.forum ORDER BY f.id ASC
2008-01-23 12:53:12,589 Trac[api] DEBUG: SELECT COUNT(id) FROM topic t WHERE t.forum = 1 AND t.time > 1201071099
2008-01-23 12:53:12,591 Trac[api] DEBUG: SELECT id FROM topic t WHERE t.forum = 1
2008-01-23 12:53:12,593 Trac[chrome] DEBUG: Prepare chrome data for request
2008-01-23 12:53:12,621 Trac[api] DEBUG: {'topic': None, 'group': None, 'forum': None, 'time': u'23.01.2008 12:53:12', 'is_moderator': True, 'mode': 'forum-list', 'groups': [{'description': 'No Group', 'forums': 1, 'id': 0, 'name': 'None'}], 'authname': u'tonal', 'realm': 'discussion-core', 'message': None, 'forums': [{'new_topics': 0, 'group': 0, 'name': u'import', 'author': u'tonal', 'description': <Markup u''>, 'replies': 0, 'topics': 0, 'moderators': <Markup u'tonal'>, 'lastreply': 'No replies', 'time': u'22.01.2008 16:44:33', 'new_replies': 0, 'lasttopic': 'No topics', 'id': 1, 'subject': <Markup u'\u041e\u0431\u0441\u0443\u0436\u0434\u0435\u043d\u0438\u0435 \u0438\u043c\u043f\u043e\u0440\u0442\u0430'>}], 'order': 'id', 'desc': None}
2008-01-23 12:53:16,049 Trac[main] DEBUG: Dispatching <Request "GET u'/discussion/1'">
2008-01-23 12:53:16,072 Trac[api] DEBUG: SELECT id, forum_group, name, subject, time, moderators, description FROM forum WHERE id = 1
2008-01-23 12:53:16,074 Trac[api] DEBUG: realm: discussion-core, action: None, preview: False, submit: False
2008-01-23 12:53:16,075 Trac[api] DEBUG: ['topic-list']
2008-01-23 12:53:16,076 Trac[session] DEBUG: Retrieving session for ID u'tonal'
2008-01-23 12:53:16,084 Trac[api] DEBUG: SELECT t.id, t.forum, t.time, t.subject, t.body, t.author, m.replies, m.lastreply FROM topic t LEFT JOIN (SELECT COUNT(id) AS replies, MAX(time) AS lastreply, topic FROM message GROUP BY topic) m ON t.id = m.topic WHERE t.forum = 1 ORDER BY t.id ASC
2008-01-23 12:53:16,093 Trac[chrome] DEBUG: Prepare chrome data for request
2008-01-23 12:53:16,121 Trac[api] DEBUG: {'topic': None, 'group': None, 'forum': {'group': 0, 'name': <Markup u'import'>, 'description': <Markup u''>, 'moderators': [u'tonal'], 'time': u'22.01.2008 16:44:33', 'id': 1, 'subject': <Markup u'\u041e\u0431\u0441\u0443\u0436\u0434\u0435\u043d\u0438\u0435 \u0438\u043c\u043f\u043e\u0440\u0442\u0430'>}, 'topics': [], 'time': u'23.01.2008 12:53:16', 'is_moderator': True, 'mode': 'topic-list', 'authname': u'tonal', 'realm': 'discussion-core', 'message': None, 'order': 'id', 'desc': None}
2008-01-23 12:53:19,394 Trac[main] DEBUG: Dispatching <Request "POST u'/discussion/1'">
2008-01-23 12:53:19,418 Trac[api] DEBUG: SELECT id, forum_group, name, subject, time, moderators, description FROM forum WHERE id = 1
2008-01-23 12:53:19,420 Trac[api] DEBUG: realm: discussion-core, action: add, preview: False, submit: False
2008-01-23 12:53:19,420 Trac[api] DEBUG: ['topic-add']
2008-01-23 12:53:19,421 Trac[session] DEBUG: Retrieving session for ID u'tonal'
2008-01-23 12:53:19,432 Trac[chrome] DEBUG: Prepare chrome data for request
2008-01-23 12:53:19,460 Trac[api] DEBUG: {'topic': None, 'group': None, 'forum': {'group': 0, 'name': <Markup u'import'>, 'description': <Markup u''>, 'moderators': [u'tonal'], 'time': u'22.01.2008 16:44:33', 'id': 1, 'subject': <Markup u'\u041e\u0431\u0441\u0443\u0436\u0434\u0435\u043d\u0438\u0435 \u0438\u043c\u043f\u043e\u0440\u0442\u0430'>}, 'time': u'23.01.2008 12:53:19', 'is_moderator': True, 'mode': 'topic-add', 'authname': u'tonal', 'realm': 'discussion-core', 'message': None}
2008-01-23 12:53:25,455 Trac[main] DEBUG: Dispatching <Request "POST u'/discussion/1'">
2008-01-23 12:53:25,479 Trac[api] DEBUG: SELECT id, forum_group, name, subject, time, moderators, description FROM forum WHERE id = 1
2008-01-23 12:53:25,481 Trac[api] DEBUG: realm: discussion-core, action: post-add, preview: False, submit: True
2008-01-23 12:53:25,482 Trac[api] DEBUG: ['topic-post-add', 'topic-list']
2008-01-23 12:53:25,483 Trac[session] DEBUG: Retrieving session for ID u'tonal'
2008-01-23 12:53:25,491 Trac[api] DEBUG: (u'aaa', u'Enter your message here...')
2008-01-23 12:53:25,492 Trac[api] DEBUG: INSERT INTO topic (forum, subject, time, author, body) VALUES (1, aaa, 1201071205, tonal, Enter your message here...)
2008-01-23 12:53:25,494 Trac[api] DEBUG: SELECT id, forum, subject, time, author, body FROM topic WHERE time = 1201071205
2008-01-23 12:53:25,495 Trac[api] DEBUG: SELECT t.author FROM topic t WHERE t.id = 1 UNION SELECT m.author FROM message m WHERE m.topic = 1
2008-01-23 12:53:25,603 Trac[chrome] DEBUG: Prepare chrome data for request
2008-01-23 12:53:25,720 Trac[notification] INFO: Sending SMTP notification to mail.nsib.ru:25 to [u'tonal@promsoft.ru']
2008-01-23 12:53:25,863 Trac[__init__] ERROR: (553, '5.5.2 Bad Message ID')
Traceback (most recent call last):
  File "/usr/lib/python2.5/site-packages/Trac-0.11dev_r6399-py2.5.egg/trac/web/main.py", line 406, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/lib/python2.5/site-packages/Trac-0.11dev_r6399-py2.5.egg/trac/web/main.py", line 195, in dispatch
    resp = chosen_handler.process_request(req)
  File "build/bdist.linux-i686/egg/tracdiscussion/core.py", line 77, in process_request
    return api.process_discussion(context) + (None,)
  File "build/bdist.linux-i686/egg/tracdiscussion/api.py", line 47, in process_discussion
    is_moderator)
  File "build/bdist.linux-i686/egg/tracdiscussion/api.py", line 567, in _do_action
    notifier.notify(context, mode, forum, new_topic, None, to, cc)
  File "build/bdist.linux-i686/egg/tracdiscussion/notification.py", line 84, in notify
    NotifyEmail.notify(self, id, subject)
  File "/usr/lib/python2.5/site-packages/Trac-0.11dev_r6399-py2.5.egg/trac/notification.py", line 239, in notify
    Notify.notify(self, resid)
  File "/usr/lib/python2.5/site-packages/Trac-0.11dev_r6399-py2.5.egg/trac/notification.py", line 129, in notify
    self.send(torcpts, ccrcpts)
  File "build/bdist.linux-i686/egg/tracdiscussion/notification.py", line 123, in send
    NotifyEmail.send(self, torcpts, ccrcpts, header)
  File "/usr/lib/python2.5/site-packages/Trac-0.11dev_r6399-py2.5.egg/trac/notification.py", line 404, in send
    self.server.sendmail(msg['From'], recipients, msgtext)
  File "smtplib.py", line 699, in sendmail
    raise SMTPDataError(code, resp)
SMTPDataError: (553, '5.5.2 Bad Message ID')

[anonymous]

in addition to tonal@… - we have not spam filter for our smtp server. And, Trac notification for tickets work smoothly.

[Radek Bartoň]

Yes, database is commited after notification is sent and if notification fails commit is not done. I'll make a change that error in notification is not critical (just displayed in GUI). Message ID is set in form <forum_id>-<topic_id>-<message_id>. Is there any reason why it is refused?

[tonal@…]

Maybe You generate incorrect Message-ID? see RFC 2822, email.utils.make_msgid or trac.ticket.notification.TicketNotifyEmail.get_message_id()

[Radek Bartoň]

Please try if r3160 fixed this. It should be RFC 2822 aware now.

[tonal@…]

Problem fixed!