RE: Deciphering maillog transaction that resulted in reply to spammer

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

RE: Deciphering maillog transaction that resulted in reply to spammer

techlist06
>Did you configure your content filter to send a bounce message?

Not intentionally.

>Jul 26 19:05:57 mail1 postfix/smtpd[11093]: 67FB13910:
>    client=localhost[127.0.0.1]
>
>Jul 26 19:05:57 mail1 postfix/cleanup[11094]: 67FB13910:
>    message-id=<[hidden email]>
>
>That is not a Postfix-generated message ID. Is that from your content
filter?

I presume it must be then.  Amavis

It appears as if the message gets sent through amavis;  amavis has some
trouble with it, and it comes back to postfix as a reject, then it appears
to get sent back through amavis again on its way to attempt a reject reply?

I was hoping someone would help me with a tour of the log steps of what's
handing off to what along the way.  I get the jist of what's happening, but
I'm trying to learn the details.

Or even better someone who uses amavis happens to know what I'm doing wrong.
Or if I'm trying to fix something that's not broken.


Here's my master.cf FWIW
Aside, I just noticed 2 lines starting with smtp.  Is that an error on my
part?

Thanks, Scott

submission inet  n       -       n       -       -       smtpd -o
content_filter= -o
smtpd_recipient_restrictions=permit_sasl_authenticated,reject -o
smtpd_sasl_type=dovecot -o smtpd_sasl_path=private/auth -o
smtpd_sasl_security_options=noanonymous -o smtpd_tls_security_level=encrypt
-o smtpd_sasl_auth_enable=yes -o syslog_name=postfix-submission -o
milter_macro_daemon_name=ORIGINATING
smtp-amavis unix -       -       n       -       3       smtp -o
disable_dns_lookups=yes -o smtp_send_xforward_command=yes
smtp       inet  n       -       n       -       1       postscreen
smtpd      pass  -       -       n       -       -       smtpd -o
cleanup_service_name=pre-cleanup
tlsproxy   unix  -       -       n       -       0       tlsproxy
dnsblog    unix  -       -       n       -       0       dnsblog
pickup     fifo  n       -       n       60      1       pickup -o
cleanup_service_name=pre-cleanup
pre-cleanup unix n       -       n       -       0       cleanup -o
virtual_alias_maps= -o canonical_maps= -o sender_canonical_maps= -o
recipient_canonical_maps= -o masquerade_domains=
cleanup    unix  n       -       n       -       0       cleanup -o
mime_header_checks= -o nested_header_checks= -o body_checks=
127.0.0.1:10025 inet n   -       n       -       -       smtpd -o
content_filter= -o local_recipient_maps= -o relay_recipient_maps= -o
smtpd_restriction_classes= -o smtpd_delay_reject=no -o
smtpd_client_restrictions=permit_mynetworks,reject -o
smtpd_helo_restrictions= -o smtpd_sender_restrictions= -o
smtpd_recipient_restrictions=permit_mynetworks,reject -o
mynetworks_style=host -o mynetworks=127.0.0.0/8 -o
strict_rfc821_envelopes=yes -o smtpd_client_connection_count_limit=0 -o
smtpd_client_connection_rate_limit=0 -o
receive_override_options=no_header_body_checks,no_unknown_recipient_checks
qmgr       unix  n       -       n       300     1       qmgr
rewrite    unix  -       -       n       -       -       trivial-rewrite
bounce     unix  -       -       n       -       0       bounce
defer      unix  -       -       n       -       0       bounce
trace      unix  -       -       n       -       0       bounce
verify     unix  -       -       n       -       1       verify
flush      unix  n       -       n       1000?   0       flush
proxymap   unix  -       -       n       -       -       proxymap
smtp       unix  -       -       n       -       -       smtp
relay      unix  -       -       n       -       -       smtp
showq      unix  n       -       n       -       -       showq
error      unix  -       -       n       -       -       error
local      unix  -       n       n       -       -       local
virtual    unix  -       n       n       -       -       virtual
lmtp       unix  -       -       n       -       -       lmtp
anvil      unix  -       -       n       -       1       anvil
scache     unix  -       -       n       -       1       scache
discard    unix  -       -       n       -       -       discard
tlsmgr     unix  -       -       n       1000?   1       tlsmgr
retry      unix  -       -       n       -       -       error
proxywrite unix  -       -       n       -       1       proxymap




Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Deciphering maillog transaction that resulted in reply to spammer

Wietse Venema
Scott Techlist:
> I was hoping someone would help me with a tour of the log steps of what's
> handing off to what along the way.  I get the jist of what's happening, but
> I'm trying to learn the details.

Sorry, that is an unreasonable request. Your logging was word-wrapped
into one pile of text, removing existing line breaks, and adding
line breaks where none should be.

To split the log into individual mail delivery transactions, you
can use the 'collate.pl' script. It's in the auxiliary/collate
subdirectory of the Postfix source-code distribution. The README
is below.

        Wietse

This script, by Viktor Dukhovni, untangles a Postfix logfile and
groups the records one "session" at a time based on queue ID and
process ID information.

Records from different sessions are separated by an empty line.
Such text is easy to process with $/="" in perl, or RS="" in awk.

Usage:
    perl collate.pl file...

It reads standard input when no file is specified.
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Deciphering maillog transaction that resulted in reply to spammer

Bastian Blank-3
In reply to this post by techlist06
On Thu, Jul 27, 2017 at 06:06:27PM -0500, Scott Techlist wrote:
> amavis[5520]: (05520-17) Blocked BAD-HEADER-0 {BouncedInbound,Quarantined},

Here is the message result.  "Bounced" is the relevant part.

Fix %final_destiny_by_ccat, do it now.

Bastian

--
Each kiss is as the first.
                -- Miramanee, Kirk's wife, "The Paradise Syndrome",
                   stardate 4842.6
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Deciphering maillog transaction that resulted in reply to spammer

techlist06
This post has NOT been accepted by the mailing list yet.
In reply to this post by Wietse Venema
Sorry about the formatting.  Damn Outlook client I guess.  Hopefully below is not messed up format wise.

Thanks for the pointer to Viktor's script.  It appears to just have the postfix entries, not the handoffs back and forth.  Seems to pickup 6 of the 20+ realted lines.  I get that it's just doing postfix, but it did not appear get all of postfix

###### collate.pl output ##############

Jul 26 19:05:56 mail1 postfix/smtpd[11088]: connect from unknown[5.133.8.185]
Jul 26 19:05:56 mail1 postfix/smtpd[11088]: E58673D02: client=unknown[5.133.8.185]
Jul 26 19:05:57 mail1 postfix/cleanup[11090]: E58673D02: message-id=<5ad4d5216a4bc054e796b681c153b4ca.16322808.16275482@pearls.preal.us_jt0>
Jul 26 19:05:57 mail1 postfix/qmgr[910]: E58673D02: from=<Online.Casino.Games@pearls.preal.us>, size=6760, nrcpt=1 (queue active)
Jul 26 19:05:57 mail1 postfix/smtp[11091]: E58673D02: to=<myuser@userdomain.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.66, delays=0.49/0.01/0.01/0.15, dsn=2.5.0, status=sent (250 2.5.0 Ok, id=05520-17, BOUNCE)
Jul 26 19:05:57 mail1 postfix/qmgr[910]: E58673D02: removed

#####  collate.pl end ##########

Hopefully this is clean enough for some instruction on what these steps are.

##### log entries ############
Jul 26 19:05:48 mail1 postfix/postscreen[11080]: CONNECT from [5.133.8.185]:44150 to [pp.pp.pp.pp]:25
Jul 26 19:05:55 mail1 postfix/postscreen[11080]: NOQUEUE: reject: RCPT from [5.133.8.185]:44150: 450 4.3.2 Service currently unavailable; from=<Online.Casino.Games@pearls.preal.us>, to=<myuser@userdomain.org>, proto=ESMTP, helo=<pearls.preal.us>
Jul 26 19:05:55 mail1 postfix/postscreen[11080]: PASS NEW [5.133.8.185]:44150
Jul 26 19:05:55 mail1 postfix/postscreen[11080]: DISCONNECT [5.133.8.185]:44150

# immediate retry on second connection to secondary IP:

Jul 26 19:05:55 mail1 postfix/postscreen[11080]: CONNECT from [5.133.8.185]:33753 to [ss.ss.ss.ss]:25
Jul 26 19:05:55 mail1 postfix/postscreen[11080]: PASS OLD [5.133.8.185]:33753
Jul 26 19:05:56 mail1 postfix/smtpd[11088]: warning: hostname accept.rootp.us does not resolve to address 5.133.8.185: Name or service not known
Jul 26 19:05:56 mail1 postfix/smtpd[11088]: connect from unknown[5.133.8.185]
Jul 26 19:05:56 mail1 postfix/smtpd[11088]: E58673D02: client=unknown[5.133.8.185]
Jul 26 19:05:57 mail1 postfix/cleanup[11090]: E58673D02: message-id=<5ad4d5216a4bc054e796b681c153b4ca.16322808.16275482@pearls.preal.us_jt0>
Jul 26 19:05:57 mail1 postfix/qmgr[910]: E58673D02: from=<Online.Casino.Games@pearls.preal.us>, size=6760, nrcpt=1 (queue active)
Jul 26 19:05:57 mail1 amavis[5520]: (05520-17) ESMTP :10024 /var/spool/amavisd/tmp/amavis-20170726T133617-05520-rH4yYe3A: <Online.Casino.Games@pearls.preal.us> -> <myuser@userdomain.org> SIZE=6760 BODY=8BITMIME RET=HDRS Received:
from mail1.myserver.com ([127.0.0.1]) by localhost (mail1.myserver.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <myuser@userdomain.org>; Wed, 26 Jul 2017 19:05:57 -0500 (CDT)
Jul 26 19:05:57 mail1 amavis[5520]: (05520-17) Checking: pqyogYJQxVad [5.133.8.185] <Online.Casino.Games@pearls.preal.us> -> <myuser@userdomain.org>
Jul 26 19:05:57 mail1 amavis[5520]: (05520-17) WARN: MIME::Parser error: unexpected end of header; ; error: couldn't parse head; error near:; ; ; error: part did not end with expected boundary; ; error: unexpected end of parts before epilogue
Jul 26 19:05:57 mail1 clamd[788]: SelfCheck: Database status OK.
Jul 26 19:05:57 mail1 postfix/smtpd[11093]: connect from localhost[127.0.0.1]
Jul 26 19:05:57 mail1 postfix/smtpd[11093]: 67FB13910: client=localhost[127.0.0.1]
Jul 26 19:05:57 mail1 postfix/cleanup[11094]: 67FB13910: message-id=<DSNpqyogYJQxVad@mail1.myserver.com>
Jul 26 19:05:57 mail1 postfix/qmgr[910]: 67FB13910: from=<>, size=3222, nrcpt=1 (queue active)
Jul 26 19:05:57 mail1 postfix/smtpd[11093]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jul 26 19:05:57 mail1 amavis[5520]: (05520-17) waLiP0ZsHz9C(pqyogYJQxVad) SEND from <> -> <Online.Casino.Games@pearls.preal.us>, ENVID=AM.waLiP0ZsHz9C.20170727T000557Z@mail1.myserver.com BODY=7BIT 250 2.0.0 from MTA(sm
tp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 67FB13910
Jul 26 19:05:57 mail1 amavis[5520]: (05520-17) Blocked BAD-HEADER-0 {BouncedInbound,Quarantined}, [5.133.8.185]:33753 [5.133.8.185] <Online.Casino.Games@pearls.preal.us> -> <myuser@userdomain.org>, Queue-ID: E58673D02, Message-ID: <5ad4d5216a4bc054e796b681c153b4ca.16322808.16275482@pearls.preal.us_jt0>, mail_id: pqyogYJQxVad, Hits: -, size: 6763, 160 ms
Jul 26 19:05:57 mail1 postfix/smtp[11091]: E58673D02: to=<myuser@userdomain.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.66, delays=0.49/0.01/0.01/0.15, dsn=2.5.0, status=sent (250 2.5.0 Ok, id=05520-17, BOUNCE)

##################

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Deciphering maillog transaction that resulted in reply to spammer

techlist06
In reply to this post by Bastian Blank-3
Bastian:  I know this is getting off list-subject.  I appreciate the pointer.  That option is not in my amavisd.conf.  I'm looking to see how to get it set.  The examples I see discussing aren't very clear (to me).

Once I understand what's going on at the postfix level I'll have a better idea hopefully.

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Deciphering maillog transaction that resulted in reply to spammer

techlist06
In reply to this post by Wietse Venema
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=<jdoe@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: <jdoe@thesender.com> -> <bsmith@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 <bsmith@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] <jdoe@thesender.com> -> <bsmith@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=<jdoe@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 <jdoe@thesender.com> -> <bsmith@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] <jdoe@thesender.com> -> <bsmith@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=<bsmith@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=<bsmith@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










Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Deciphering maillog transaction that resulted in reply to spammer

Matus UHLAR - fantomas
On 30.07.17 10:21, techlist06 wrote:
>Subject: Re: Deciphering maillog transaction that resulted in reply to
> spammer

...are you receiving spam messages with NOTIFY=SUCCESS?
(I don't see bounce of this message in logs)


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

>(Posted via nabble, hopefully that prevents any wrapping issues)

it does not prevent from wrapping where it should not, but at least it did
not merge lines...

># ???  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]

correct

># ??? new queue of filtered message #230F69E7 from amavis

correct

># ??? 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=<[hidden email]>, 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)

this is the original mail that was sent to amavis and amavis just confirmed
that it was successfully delivered back to postfix.

--
Matus UHLAR - fantomas, [hidden email] ; http://www.fantomas.sk/
Warning: I wish NOT to receive e-mail advertising to this address.
Varovanie: na tuto adresu chcem NEDOSTAVAT akukolvek reklamnu postu.
The early bird may get the worm, but the second mouse gets the cheese.
Loading...