Prev: Simple hack to get $3000 to your home
Next: compile Postfix in static linking
From: Stan Hoeppner on 11 Aug 2010 05:10
Stan Hoeppner put forth on 8/11/2010 3:31 AM:

> I was just looking at a Logwatch summary. The data the OP is requesting _is_
> in the Postfix logs somewhere, as Logwatch is tallying the disconnection phases:
>
> 81 Connections lost (inbound)
> 61 After DATA
> 11 After CONNECT
> 7 After RCPT
> 2 After EHLO
>
> If you need this information _per msg_ with detail, you'll have to go digging
> and figure it out for yourself. The data _is_ in there though. And, yes, I
> use smtpd_delay_reject=yes, the default.

Found it. And not really hard to find:

~$ grep " lost connection " /var/log/mail.log|mawk {print'($6, $7, $8, $9,
$10, $11, $12, $13)}'

This won't tell you if/what restriction caused the disconnection, but you'll
definitely know during which SMTP phase the disconnection occurred.

--
Stan

lost connection after CONNECT from unknown[119.158.85.98]
lost connection after DATA (10150 bytes) from unknown[109.126.140.66]
lost connection after RCPT from 59-126-95-178.pool.ukrtel.net[178.95.126.59]
lost connection after CONNECT from unknown[41.174.21.83]
lost connection after DATA (0 bytes) from unknown[41.141.110.166]
lost connection after CONNECT from unknown[190.178.115.115]
lost connection after CONNECT from unknown[200.75.242.87]
lost connection after CONNECT from 5ac15e25.bb.sky.com[90.193.94.37]
lost connection after DATA (0 bytes) from unknown[117.204.161.4]
lost connection after CONNECT from unknown[120.162.51.31]
lost connection after MAIL from unknown[201.221.239.203]
lost connection after MAIL from unknown[201.221.239.203]
lost connection after MAIL from unknown[201.221.239.203]
lost connection after CONNECT from unknown[187.89.103.249]
lost connection after DATA (0 bytes) from unknown[121.97.150.20]
lost connection after RCPT from unknown[118.96.255.42]
lost connection after RCPT from unknown[210.122.170.6]
lost connection after RCPT from unknown[205.209.161.181]
lost connection after DATA (0 bytes) from unknown[211.161.193.9]
lost connection after RCPT from unknown[122.100.104.100]
lost connection after DATA (49642 bytes) from unknown[117.206.234.89]
lost connection after DATA (55333 bytes) from unknown[117.206.234.89]
lost connection after DATA (0 bytes) from unknown[190.189.11.16]
lost connection after DATA (0 bytes) from unknown[213.182.94.250]
lost connection after DATA (0 bytes) from unknown[83.149.42.62]
lost connection after CONNECT from unknown[123.26.72.52]
lost connection after DATA (0 bytes) from unknown[119.30.38.43]
lost connection after DATA (0 bytes) from unknown[91.205.168.11]
lost connection after DATA (0 bytes) from unknown[91.205.168.11]
lost connection after DATA (0 bytes) from unknown[91.205.168.11]

From: Noel Jones on 11 Aug 2010 07:20
On 8/11/2010 4:10 AM, Stan Hoeppner wrote:
> Stan Hoeppner put forth on 8/11/2010 3:31 AM:
>
>> I was just looking at a Logwatch summary. The data the OP is requesting _is_
>> in the Postfix logs somewhere, as Logwatch is tallying the disconnection phases:
>>
>> 81 Connections lost (inbound)
>> 61 After DATA
>> 11 After CONNECT
>> 7 After RCPT
>> 2 After EHLO
>>
>> If you need this information _per msg_ with detail, you'll have to go digging
>> and figure it out for yourself. The data _is_ in there though. And, yes, I
>> use smtpd_delay_reject=yes, the default.
>
> Found it. And not really hard to find:
>
> ~$ grep " lost connection " /var/log/mail.log|mawk {print'($6, $7, $8, $9,
> $10, $11, $12, $13)}'
>
> This won't tell you if/what restriction caused the disconnection, but you'll
> definitely know during which SMTP phase the disconnection occurred.


This is logged when the client disconnected in the middle of
the transaction -- postfix lost the connection -- NOT a reject.

You won't find reject log entries for the lost connections
after EHLO or CONNECT, although the ones for RCPT and DATA
*might* be proceeded by rejects.

This can be confusing because typically most of the lost
connections are zombies/bots that you would reject anyway.

-- Noel Jones

From: Stan Hoeppner on 11 Aug 2010 07:54
Noel Jones put forth on 8/11/2010 6:20 AM:

> This is logged when the client disconnected in the middle of the
> transaction -- postfix lost the connection -- NOT a reject.
>
> You won't find reject log entries for the lost connections after EHLO or
> CONNECT, although the ones for RCPT and DATA *might* be proceeded by
> rejects.
>
> This can be confusing because typically most of the lost connections are
> zombies/bots that you would reject anyway.

Are you sure about that Noel?

Aug 8 13:22:49 greer postfix/smtpd[14798]: connect from
59-126-95-178.pool.ukrtel.net[178.95.126.59]
Aug 8 13:22:50 greer postfix/smtpd[14798]: NOQUEUE: reject: RCPT from
59-126-95-178.pool.ukrtel.net[178.95.126.59]: 554 5.7.1
<59-126-95-178.pool.ukrtel.net[178.95.126.59]>: Client host rejected: Generic
- Please relay via ISP (ukrtel.net); from=<info(a)hardwarefreak.com>
to=<info(a)hardwarefreak.com> proto=SMTP helo=<59-126-95-178.pool.ukrtel.net>
Aug 8 13:22:50 greer postfix/smtpd[14798]: lost connection after RCPT from
59-126-95-178.pool.ukrtel.net[178.95.126.59]
Aug 8 13:22:50 greer postfix/smtpd[14798]: disconnect from
59-126-95-178.pool.ukrtel.net[178.95.126.59]

This example clearly shows the disconnect at RCPT was due to a rejection.
This example was in my previous list.

And how about this one?

Aug 10 23:02:46 greer postfix/smtpd[30689]: connect from unknown[113.91.134.58]
Aug 10 23:02:47 greer postfix/smtpd[30689]: NOQUEUE: reject: RCPT from
unknown[113.91.134.58]: 554 5.7.1 <unknown[113.91.134.58]>: Client host
rejected: Mail not accepted from China; from=<theiro7(a)robertharding.com>
to=<stan(a)hardwarefreak.com> proto=ESMTP helo=<QOYCLTMTN>
Aug 10 23:02:48 greer postfix/smtpd[30689]: lost connection after DATA (0
bytes) from unknown[113.91.134.58]
Aug 10 23:02:48 greer postfix/smtpd[30689]: disconnect from unknown[113.91.134.58]

Again, the disconnection was due to rejection. This one was also in my
previous example. In fact, every one of my rejections shows a disconnect
stamp pretty much identical to those which are simply clients prematurely
disconnecting for whatever reason.

This leads me to believe the SMTP stage of disconnection is logged for all
disconnects, including those due to rejections. I guess we'll find out when
Wietse jumps in to educate us on this.

--
Stan

From: Noel Jones on 11 Aug 2010 08:51
On 8/11/2010 6:54 AM, Stan Hoeppner wrote:
> Noel Jones put forth on 8/11/2010 6:20 AM:
>
>> This is logged when the client disconnected in the middle of the
>> transaction -- postfix lost the connection -- NOT a reject.
>>
>> You won't find reject log entries for the lost connections after EHLO or
>> CONNECT, although the ones for RCPT and DATA *might* be proceeded by
>> rejects.
>>
>> This can be confusing because typically most of the lost connections are
>> zombies/bots that you would reject anyway.
>
> Are you sure about that Noel?

Absolutely.

>
> Aug 8 13:22:49 greer postfix/smtpd[14798]: connect from
> 59-126-95-178.pool.ukrtel.net[178.95.126.59]
> Aug 8 13:22:50 greer postfix/smtpd[14798]: NOQUEUE: reject: RCPT from
> 59-126-95-178.pool.ukrtel.net[178.95.126.59]: 554 5.7.1
> <59-126-95-178.pool.ukrtel.net[178.95.126.59]>: Client host rejected: Generic
> - Please relay via ISP (ukrtel.net); from=<info(a)hardwarefreak.com>
> to=<info(a)hardwarefreak.com> proto=SMTP helo=<59-126-95-178.pool.ukrtel.net>
> Aug 8 13:22:50 greer postfix/smtpd[14798]: lost connection after RCPT from
> 59-126-95-178.pool.ukrtel.net[178.95.126.59]
> Aug 8 13:22:50 greer postfix/smtpd[14798]: disconnect from
> 59-126-95-178.pool.ukrtel.net[178.95.126.59]
>
> This example clearly shows the disconnect at RCPT was due to a rejection.
> This example was in my previous list.

Don't confuse "disconnect from" with "lost connection". The
disconnect is always logged; lost connection is logged when
the client drops the connection in the middle of the conversation.

This entry shows the client dropped the connection after you
sent a reject. Many, but not all, spambots seem to do that.

>
> And how about this one?
>
> Aug 10 23:02:46 greer postfix/smtpd[30689]: connect from unknown[113.91.134.58]
> Aug 10 23:02:47 greer postfix/smtpd[30689]: NOQUEUE: reject: RCPT from
> unknown[113.91.134.58]: 554 5.7.1<unknown[113.91.134.58]>: Client host
> rejected: Mail not accepted from China; from=<theiro7(a)robertharding.com>
> to=<stan(a)hardwarefreak.com> proto=ESMTP helo=<QOYCLTMTN>
> Aug 10 23:02:48 greer postfix/smtpd[30689]: lost connection after DATA (0
> bytes) from unknown[113.91.134.58]
> Aug 10 23:02:48 greer postfix/smtpd[30689]: disconnect from unknown[113.91.134.58]
>
> Again, the disconnection was due to rejection. This one was also in my
> previous example. In fact, every one of my rejections shows a disconnect
> stamp pretty much identical to those which are simply clients prematurely
> disconnecting for whatever reason.

Here the client sent the DATA command before it dropped the
connection. It dropped the connection because it's a spambot
and you rejected the recipient.

>
> This leads me to believe the SMTP stage of disconnection is logged for all
> disconnects, including those due to rejections.

When the client drops the connection in the middle of a
transaction the stage is logged. Normal clients don't drop
the connection after a reject, but spambots often do.

You can see this for yourself in your logs; not every reject
is followed by a "lost connection" message, not every lost
connection is proceeded by a reject.

I expect most of the lost connection after RCPT or DATA are
proceeded by a reject simply because most of these are
spambots. But one does not equal the other.

Don't confuse "disconnect" with "lost connection". A
disconnect message is always logged at the end of the
conversation when the client disconnects. A lost connection
is logged when postfix is still trying to talk to the client
but the client dropped the connection early.

> I guess we'll find out when
> Wietse jumps in to educate us on this.
>

This has been discussed before. Search the archives.


-- Noel Jones

From: JunkYardMail1 on 11 Aug 2010 21:44
With smtpd_delay_reject = yes

Which of the restriction sections was the following logged rejection for?
Or put another way, in which of the restriction sections was the rejection
option "reject_rbl_client pbl.spamhaus.org" that resulted in the logged
rejection?

Restriction Options:
smtpd_client_restrictions
smtpd_helo_restrictions
smtpd_etrn_restrictions
smtpd_sender_restrictions
smtpd_recipient_restrictions
smtpd_data_restrictions
smtpd_end_of_data_restrictions

Aug 10 19:00:14 RapidVPS1 postfix-mx/smtpd[9301]: NOQUEUE: reject: RCPT from
unknown[190.40.76.65]: 521 5.7.1 Service unavailable; Client host
[190.40.76.65] blocked using pbl.spamhaus.org;
http://www.spamhaus.org/query/bl?ip=190.40.76.65; from=<code(a)blah.com>
to=<code(a)blah.com> proto=SMTP helo=<client-190.40.76.65.speedy.net.pe>

It says RCPT because that is the stage at which the rejections are processed
when smtpd_delay_reject is enable. But that is not the restriction section
the rejection was for.

It was actually an smtpd_client_restrictions, so when smtpd_delay_reject is
enabled would like it to be logged similarly to how it would be if
smtpd_delay_reject was disabled. Designation of CONNECT rather than RCPT.
Aug 10 19:00:14 RapidVPS1 postfix-mx/smtpd[9301]: NOQUEUE: reject: CONNECT
from unknown[190.40.76.65]: 521 5.7.1 Service unavailable; Client host
[190.40.76.65] blocked using pbl.spamhaus.org;
http://www.spamhaus.org/query/bl?ip=190.40.76.65; from=<code(a)mydomain.com>
to=<code(a)mydomain.com> proto=SMTP helo=<client-190.40.76.65.speedy.net.pe>

When smtpd_delay_reject is disabled it would be logged as:
Aug 10 19:00:14 RapidVPS1 postfix-mx/smtpd[9301]: NOQUEUE: reject: CONNECT
from unknown[190.40.76.65]: 521 5.7.1 Service unavailable; Client host
[190.40.76.65] blocked using pbl.spamhaus.org;
http://www.spamhaus.org/query/bl?ip=190.40.76.65; proto=SMTP

Hope this clarifies rather then muddies.


First  |  Prev  |  Next  |  Last
Pages: 1 2 3 4 5
Prev: Simple hack to get $3000 to your home
Next: compile Postfix in static linking