0

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.

4
  • 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. Apr 26, 2013 at 9:16
  • Si I have to look for logs with mail id 338A6202793 ?
    – Hugo H
    Apr 26, 2013 at 9:31
  • Yes, this is correct. Apr 26, 2013 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. Apr 26, 2013 at 10:01

2 Answers 2

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.

1
  • Thanks for your reply. I have now understant how it works. :)
    – Hugo H
    Apr 26, 2013 at 13:09
5

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.

9
  • 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
    Apr 26, 2013 at 9:29
  • Sorry I can't upvote your answer, too low reputation. But thanks for reply.
    – Hugo H
    Apr 26, 2013 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, 2013 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=<[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.
    – Hugo H
    Apr 26, 2013 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, 2013 at 11:21

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .