Difference between postfix/pickup and postfix/smtpd

Question

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=<[email protected]>
Mar 29 03:04:12 dedy postfix/cleanup[14704]: 5BF612027E1: message-id=<[email protected]>

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

Mar 29 03:04:12 dedy postfix/qmgr[23001]: 5BF612027E1: from=<[email protected]>, 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=<[email protected]>
Mar 29 03:04:41 dedy opendkim[4792]: 338A6202793 "DKIM-Signature" header added

Mar 29 03:04:41 dedy postfix/qmgr[23001]: 338A6202793: from=<[email protected]>, size=2885, nrcpt=1 (queue active)
Mar 29 03:04:41 dedy amavis[14879]: (14879-02-42) Passed CLEAN, <[email protected]> -> <[email protected]>, Message-ID: <[email protected]>, mail_id: S9mHT5YBZUEe, Hits: 2.344, size: 2392, queued_as: 338A6202793, 721 ms
Mar 29 03:04:41 dedy postfix/smtp[14903]: 5BF612027E1: to=<[email protected]>, 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=<[email protected]>, 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.

Solution 1

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=<[email protected]>, 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.

Solution 2

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.

Comments

[Laurentiu Roescu]

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.

[Hugo H]

Si I have to look for logs with mail id 338A6202793 ?

[Laurentiu Roescu]

Yes, this is correct.

[Laurentiu Roescu]

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.

[Hugo H]

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 ?

[Hugo H]

Sorry I can't upvote your answer, too low reputation. But thanks for reply.

[NickW]

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.

[Hugo H]

But this line is the one that says there's an error : Mar 29 03:04:41 dedy postfix/smtp[12591]: 338A6202793: to=<[email protected]>, 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.

[NickW]

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

[Hugo H]

I double check my logs, and that's the same mail. There's only one recipient by mail. I don't understand. This two entries hve different ID but same mail.

[NickW]

They are two different mails. They may have been sent twice, they have different sizes, and one is delivered, the other isn't!

[Hugo H]

As @Laurentiu Roescu it appears to be the same mail.

[Hugo H]

Thanks for your reply. I have now understant how it works. :)

[NickW]

I wasn't clear about that, it is the same message (to you), but postfix sees it as two different messages because it delivers it outside it's ecosystem. Once smtp delivers it, to amavisd, to Dovecot, to a remote mailserver, or to any other non postfix daemon, it is no longer the same email (to postfix).