Instead of trying to decipher one with a problem, can someone check my laymen
descriptions of this single good message flow for me? I've tried to do my
homework and get them right. I think I have it, but would be grateful for
confirmation.
I have commented the steps of the full message flow with my descriptions of
what I understand is happening with that logged step. I did not parse it
with the collate script but it is from my quiet server, nothing else
happening on it to muddy the waters.
I have after-que content filtering setup, using amavisd-new. I have a
pre-cleanup and a regular cleanup service. The steps I'm a little shaky on
I have prefixed with "???" in the comments.
Just looking for some help understanding the log entries in this one message
flow, so I can better help myself on problems.
(Posted via nabble, hopefully that prevents any wrapping issues)
########### LOG START #######
# postscreen, whitelisted, and passes due to previous pass
Jul 30 11:18:12 mail1 postfix/postscreen[3483]: CONNECT from [1.1.1.1]:59992
to [2.2.2.2]:25
Jul 30 11:18:12 mail1 postfix/dnsblog[3488]: addr 1.1.1.1 listed by domain
list.dnswl.org as 127.0.4.0
Jul 30 11:18:12 mail1 postfix/postscreen[3483]: PASS OLD [1.1.1.1]:59992
# connect to main smtp. message QID? F1F5B14D5
Jul 30 11:18:12 mail1 postfix/smtpd[3491]: connect from
mail.myserver.com[1.1.1.1]
Jul 30 11:18:12 mail1 postfix/smtpd[3491]: F1F5B14D5:
client=mail.myserver.com[1.1.1.1]
# F1F5B14D5 to pre-cleanup
Jul 30 11:18:13 mail1 postfix/cleanup[3494]: F1F5B14D5:
message-id=<017101d3094f$6ef5df70$4ce19e50$@com>
# F1F5B14D5 into que manager
Jul 30 11:18:13 mail1 postfix/qmgr[3285]: F1F5B14D5:
from=<j...@thesender.com>, size=1022, nrcpt=1 (queue active)
# mainsmtp connection done, disconnect
Jul 30 11:18:13 mail1 postfix/smtpd[3491]: disconnect from
mail.myserver.com[1.1.1.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
# amavis picks up item from queue via amavis-smtpd lmtp service
Jul 30 11:18:13 mail1 amavis[1006]: (01006-05) LMTP :10024
/var/spool/amavisd/tmp/amavis-20170730T100904-01006-thTdWRtM:
<j...@thesender.com> -> <bsm...@mail1.myserver.com> SIZE=1022 Received: from
mail1.myserver.com ([127.0.0.1]) by localhost (mail1.myserver.com
[127.0.0.1]) (amavisd-new, port 10024) with LMTP for
<bsm...@mail1.myserver.com>; Sun, 30 Jul 2017 11:18:13 -0500 (CDT)
# amavis reports it starts checking the message F1F5B14D5
Jul 30 11:18:13 mail1 amavis[1006]: (01006-05) Checking: er8IU5nNU-RL MYNETS
[1.1.1.1] <j...@thesender.com> -> <bsm...@mail1.myserver.com>
# ??? Postfix gets connection from amavis on normal smtpd to send filtered
message. That message gets new QID? #230F69E7
Jul 30 11:18:13 mail1 postfix/smtpd[3498]: connect from localhost[127.0.0.1]
Jul 30 11:18:13 mail1 postfix/smtpd[3498]: 230F69E7:
client=localhost[127.0.0.1], orig_queue_id=F1F5B14D5,
orig_client=mail.myserver.com[1.1.1.1]
# after-filter cleanup on filtered message 230F69E7?
Jul 30 11:18:13 mail1 postfix/cleanup[3499]: 230F69E7:
message-id=<017101d3094f$6ef5df70$4ce19e50$@com>
# ??? new queue of filtered message #230F69E7 from amavis
Jul 30 11:18:13 mail1 postfix/qmgr[3285]: 230F69E7:
from=<j...@thesender.com>, size=1518, nrcpt=1 (queue active)
# amavis done talking to postfix, disconnects
Jul 30 11:18:13 mail1 postfix/smtpd[3498]: disconnect from
localhost[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 quit=1
commands=6
# ??? meanwhile, the same amavis, PID [1006] just logging/reporting what was
done
Jul 30 11:18:13 mail1 amavis[1006]: (01006-05) er8IU5nNU-RL FWD from
<j...@thesender.com> -> <bsm...@mail1.myserver.com>, BODY=7BIT 250 2.0.0
from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 230F69E7
Jul 30 11:18:13 mail1 amavis[1006]: (01006-05) Passed CLEAN
{RelayedInternal}, MYNETS LOCAL [1.1.1.1]:59992 [108.222.197.75]
<j...@thesender.com> -> <bsm...@mail1.myserver.com>, Queue-ID: F1F5B14D5,
Message-ID: <017101d3094f$6ef5df70$4ce19e50$@com>, mail_id: er8IU5nNU-RL,
Hits: -, size: 1022, queued_as: 230F69E7, 136 ms
# ??? postfix reports it got a message via lmtp from amavis (10024), and it
has sent it, although I think it actually sent the filtered version 230F69E7
per local delivery log line that follows
Jul 30 11:18:13 mail1 postfix/lmtp[3495]: F1F5B14D5:
to=<bsm...@mail1.myserver.com>, relay=127.0.0.1[127.0.0.1]:10024,
delay=0.18, delays=0.03/0.01/0.01/0.13, dsn=2.0.0, status=sent (250 2.0.0
from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 230F69E7)
# qmgr removes the original message received F1F5B14D5 ?
Jul 30 11:18:13 mail1 postfix/qmgr[3285]: F1F5B14D5: removed
# delivers locally
Jul 30 11:18:13 mail1 postfix/local[3500]: 230F69E7:
to=<bsm...@mail1.myserver.com>, relay=local, delay=0.04,
delays=0.01/0.03/0/0, dsn=2.0.0, status=sent (delivered to mailbox)
# qmgr removes the filtered message received 230F69E7 ?
Jul 30 11:18:13 mail1 postfix/qmgr[3285]: 230F69E7: removed
#### END
--
View this message in context:
http://postfix.1071664.n5.nabble.com/RE-Deciphering-maillog-transaction-that-resulted-in-reply-to-spammer-tp91584p91615.html
Sent from the Postfix Users mailing list archive at Nabble.com.
