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

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.

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?

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

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

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?

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

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

Problem fixed!