Hi all, I was examining my Postfix logs and saw two sequential sessions using the same queue ID. I was a bit surprised as I had the assumption that queue IDs were generated randomly, which means they should be practically unique.
Okay, so this could be a wrong assumption... My question is, how are queue IDs exactly generated? I couldn't find this info in the Postfix documentation, but I might have overlooked it. Well, now some details for anyone interested in what happened. I'm running two machines (mail servers) with Debian 5.0 (lenny) and Postfix 2.5.5. Let's call them box A and box B. Box A was the machine using the same queue ID for two sessions. The accompanying log entries (and explanations): #### Box A (session 1): > Nov 13 17:44:26 box-a postfix/smtpd[27915]: connect from > localhost[127.0.0.1]> Nov 13 17:44:26 box-a postfix/smtpd[27915]: 1C96531C9D: client=localhost[127.0.0.1] > Nov 13 17:44:26 box-a postfix/cleanup[27917]: 1C96531C9D: message-id=<[EMAIL PROTECTED]> > Nov 13 17:44:26 box-a postfix/qmgr[1917]: 1C96531C9D: from=<[EMAIL PROTECTED]>, size=409, nrcpt=1 (queue active) > Nov 13 17:44:26 box-a postfix/smtpd[27915]: disconnect from localhost[127.0.0.1] On the machine itself, [EMAIL PROTECTED] sends a mail to [EMAIL PROTECTED] Queued as 1C96531C9D. > Nov 13 17:44:26 box-a postfix/smtp[27920]: 1C96531C9D: to=<[EMAIL PROTECTED]>, relay=box-b.example.org[192.168.0.3]:25, delay=0, delays=0/0/0/0, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 1D0A81039FA5) > Nov 13 17:44:26 box-a postfix/qmgr[1917]: 1C96531C9D: removed The mail can't be delivered locally, so is relayed to box B. Queued as 1D0A81039FA5. #### Box B (session 1): > Nov 13 17:44:26 box-b postfix/smtpd[16249]: connect from box-a.example.org[192.168.0.2] > Nov 13 17:44:26 box-b postfix/smtpd[16249]: 1D0A81039FA5: client=box-a.example.org[192.168.0.2] > Nov 13 17:44:26 box-b postfix/cleanup[16251]: 1D0A81039FA5: message-id=<[EMAIL PROTECTED]> > Nov 13 17:44:26 box-b postfix/qmgr[1893]: 1D0A81039FA5: from=<[EMAIL PROTECTED]>, size=616, nrcpt=1 (queue active) > Nov 13 17:44:26 box-b postfix/cleanup[16251]: 1E50E1039FB4: message-id=<[EMAIL PROTECTED]> > Nov 13 17:44:26 box-b postfix/smtpd[16249]: disconnect from box-a.example.org[192.168.0.2] Mail is received from box A. Indeed queued as 1D0A81039FA5. > Nov 13 17:44:26 box-b postfix/local[16252]: 1D0A81039FA5: to=<[EMAIL PROTECTED]>, relay=local, delay=0.01, delays=0/0/0/0.01, dsn=2.0.0, status=sent (forwarded as 1E50E1039FB4) > Nov 13 17:44:26 box-b postfix/qmgr[1893]: 1D0A81039FA5: removed There's an alias for bill on box B, so the mail is forwarded. Queued as 1E50E1039FB4. > Nov 13 17:44:26 box-b postfix/qmgr[1893]: 1E50E1039FB4: from=<[EMAIL PROTECTED]>, size=753, nrcpt=1 (queue active) > Nov 13 17:44:26 box-b postfix/smtp[16253]: 1E50E1039FB4: to=<[EMAIL PROTECTED]>, orig_to=<[EMAIL PROTECTED]>, relay=box-a.example.org[192.168.0.2]:25, delay=0.01, delays=0.01/0/0/0, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 1C96531C9D) > Nov 13 17:44:26 box-b postfix/qmgr[1893]: 1E50E1039FB4: removed The alias' target is on box A, so box B relays the mail to box A. Queued as 1C96531C9D. Hey, didn't we see this ID before? #### Box A (session 2): > Nov 13 17:44:26 box-a postfix/smtpd[27915]: connect from box-b.example.org[192.168.0.3] > Nov 13 17:44:26 box-a postfix/smtpd[27915]: 1C96531C9D: client=box-b.example.org[192.168.0.3] > Nov 13 17:44:26 box-a postfix/cleanup[27917]: 1C96531C9D: message-id=<[EMAIL PROTECTED]> > Nov 13 17:44:26 box-a postfix/qmgr[1917]: 1C96531C9D: from=<[EMAIL PROTECTED]>, size=959, nrcpt=1 (queue active) > Nov 13 17:44:26 box-a postfix/smtpd[27915]: disconnect from box-b.example.org[192.168.0.3] > Nov 13 17:44:26 box-a postfix/virtual[27922]: 1C96531C9D: to=<[EMAIL PROTECTED]>, relay=virtual, delay=0.01, delays=0/0/0/0.01, dsn=2.0.0, status=sent (delivered to maildir) > Nov 13 17:44:26 box-a postfix/qmgr[1917]: 1C96531C9D: removed The mail is finally delivered. Indeed queued as 1C96531C9D. Yeah, we saw this ID before... in the beginning, when [EMAIL PROTECTED] sent the mail to the local Postfix daemon on the same machine. Some observations: - The "reused" queue ID is in a session that is in some way related to the first used of the queue ID. - The process is really fast, everything happens in the same second. - While replaying this scenario the duplicate queue ID isn't always reproducible. Like 2 times out of 10. I'm wondering if this behaviour of Postfix is normal. Thanks in advance for any information regarding this subeject! Durk
