Take the 2-minute tour ×
Server Fault is a question and answer site for professional system and network administrators. It's 100% free, no registration required.

I'm working on my postfix logs for a mailing system.

I don't understand why the same mail appears with two differents ID, once with "postfix/pickup" and another with "postfix/smtpd".

Mar 29 03:04:12 dedy postfix/pickup[11199]: 5BF612027E1: uid=5022 from=<mailer-daemon@domain.com>
Mar 29 03:04:12 dedy postfix/cleanup[14704]: 5BF612027E1: message-id=<18b02ebfc90865d8f5199b3baaff7d25@mailing.domain.com>

Mar 29 03:04:12 dedy opendkim[4792]: 5BF612027E1 "DKIM-Signature" header added

Mar 29 03:04:12 dedy postfix/qmgr[23001]: 5BF612027E1: from=<mailer-daemon@domain.com>, size=2031, nrcpt=1 (queue active)

Mar 29 03:04:41 dedy postfix/smtpd[12194]: 338A6202793: client=localhost[127.0.0.1]
Mar 29 03:04:41 dedy postfix/cleanup[15283]: 338A6202793: message-id=<18b02ebfc90865d8f5199b3baaff7d25@mailing.domain.com>
Mar 29 03:04:41 dedy opendkim[4792]: 338A6202793 "DKIM-Signature" header added

Mar 29 03:04:41 dedy postfix/qmgr[23001]: 338A6202793: from=<mailer-daemon@domain.com>, size=2885, nrcpt=1 (queue active)
Mar 29 03:04:41 dedy amavis[14879]: (14879-02-42) Passed CLEAN, <mailer-daemon@domain.com> -> <mail@hotmail.fr>, Message-ID: <18b02ebfc90865d8f5199b3baaff7d25@mailing.domain.com>, mail_id: S9mHT5YBZUEe, Hits: 2.344, size: 2392, queued_as: 338A6202793, 721 ms
Mar 29 03:04:41 dedy postfix/smtp[14903]: 5BF612027E1: to=<mail@hotmail.fr>, relay=127.0.0.1[127.0.0.1]:10024, conn_use=42, delay=29, delays=0.24/28/0/0.74, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=14879-02-42, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 338A6202793)
Mar 29 03:04:41 dedy postfix/qmgr[23001]: 5BF612027E1: removed

Mar 29 03:04:41 dedy postfix/smtp[12591]: 338A6202793: to=<mail@hotmail.fr>, relay=mx2.hotmail.com[65.nn.nn.168]:25, delay=0.79, delays=0.09/0/0.36/0.33, dsn=5.0.0, status=bounced (host mx2.hotmail.com[65.nn.nn.168] said: 550 Requested action not taken: mailbox unavailable (in reply to RCPT TO command))

Mar 29 03:04:42 dedy postfix/bounce[14707]: 338A6202793: sender non-delivery notification: 1D3B5202773
Mar 29 03:04:42 dedy postfix/qmgr[23001]: 338A6202793: removed

I make some research and cannot figure it out.

Thanks by advance.

share|improve this question
    
Email message is inserted through pickup (postfix.org/pickup.8.html). Than is passed to opendkim for signing and injected back into postfix through smtpd. –  Laurentiu Roescu Apr 26 '13 at 9:16
    
Si I have to look for logs with mail id 338A6202793 ? –  Tyrius Apr 26 '13 at 9:31
    
Yes, this is correct. –  Laurentiu Roescu Apr 26 '13 at 9:37
    
I actually made a mistake, its not opendkim but amavis the on which receive email for checking and then re-injecting it to postfix through smtpd. –  Laurentiu Roescu Apr 26 '13 at 10:01
add comment

2 Answers

up vote 1 down vote accepted

Your email was received by pickup. It was after that relayed to amavis (for virus and spam checking):

Mar 29 03:04:41 dedy postfix/smtp[14903]: 5BF612027E1: to=<mail@hotmail.fr>, relay=127.0.0.1[127.0.0.1]:10024, conn_use=42, delay=29, delays=0.24/28/0/0.74, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=14879-02-42, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 338A6202793)

And then amavis re-injected it to postfix through smtpd:

Mar 29 03:04:41 dedy postfix/smtpd[12194]: 338A6202793: client=localhost[127.0.0.1]

So it is the same email message.

share|improve this answer
    
Thanks for your reply. I have now understant how it works. :) –  Tyrius Apr 26 '13 at 13:09
add comment

The pickup daemon is basically a process which watches a directory (maildrop) where other processes place files. It doesn't talk with the outside world (like smtpd or others), it just waits for a process like postdrop or other local delivery processes (for example a content scanning program like amavisd-new) to give the mail to them. It then passes them to the cleanup daemon, who will set them up for delivery (remote or local) after altering things that need altering.

share|improve this answer
    
So, if I want to know if my mail has been sent to client server (here, hotmail), I have to look for mail with id 338A6202793 ? –  Tyrius Apr 26 '13 at 9:29
    
Sorry I can't upvote your answer, too low reputation. But thanks for reply. –  Tyrius Apr 26 '13 at 9:31
    
Don't worry about the upvote, usually mail can be tracked with its ID 5BF612027E1 you should be able to see every daemon which the mail passed through filtering for that ID, or any other. –  NickW Apr 26 '13 at 10:22
    
But this line is the one that says there's an error : Mar 29 03:04:41 dedy postfix/smtp[12591]: 338A6202793: to=<mail@hotmail.fr>, relay=mx2.hotmail.com[65.nn.nn.168]:25, delay=0.79, delays=0.09/0/0.36/0.33, dsn=5.0.0, status=bounced (host mx2.hotmail.com[65.nn.nn.168] said: 550 Requested action not taken: mailbox unavailable (in reply to RCPT TO command)) and no mention of 5BF612027E1. –  Tyrius Apr 26 '13 at 11:14
    
No, that's a different email, each one will have its ID, follow each one as a separate entity, it could be the same "email" but if it has two recipients, each recipient will have an email (and therefor a separate ID in the maillog). –  NickW Apr 26 '13 at 11:21
show 4 more comments

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.