Hello there!
running ASSP version: 2.6.2(18148)
Some relayservers running postfix is running into problems sending mail to
our users via assp.
At first I could not find anything in our logs in assp so I turned on debug
for those IP's and got some hits.
I have attached a txt file with the typical debug of a session. (all
sessions look the same just different IP's)
To me it seems like the client stops sending, timeout.
Getting logs from the sending side it seems like the connection is stopped
from the server side:
postfix/smtp[1122]: 48F3A5C61278: to=<x...@xxxxx.xx <mailto:x...@xxxxx.xx> >,
relay=some.domain[x.x.x.x]:25, delay=63548, delays=63548/0.01/0.34/0.02,
dsn=4.4.2, status=deferred (lost connection with some.domain [x.x.x.x] while
sending MAIL FROM)
And if one checks the debug, assp is waiting for the client to send never
getting to the MAIL FROM part.
Am I missing a clue to why this sessions brakes?
Is it postfix that don't want to talk over TLS, doing something wrong
relaying?
Do the offering of TLS go wrong?
Regards,
Pontus
---
Detta e-postmeddelande har sökts igenom efter virus med antivirusprogram från
Avast.
https://www.avast.com/antivirus
running ASSP version: 2.6.2(18148)
1528370080.860989 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
noMaxSMTPSessions>
1528370080.862263 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
noProcessingIPs>
1528370080.862550 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
whiteListedIPs>
1528370080.862991 Jun-07-18 13:14:40 [Worker_1] <try to connect to server at
192.168.10.60:25>
Jun-07-18 13:14:40 [Worker_1] info: wrote 25 byte to server
1528370080.865604 Jun-07-18 13:14:40 [Worker_1] <connected to server
IO::Socket::INET=GLOB(0x112337f0) at 192.168.10.60:25>
1528370080.865835 Jun-07-18 13:14:40 [Worker_1] <addfh>
1528370080.866208 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) select (readable) from main sub main::addfh
6[LF]>
1528370080.866607 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) select (writable) from main sub main::addfh
7[LF]>
1528370080.867275 Jun-07-18 13:14:40 [Worker_1] <addfh>
1528370080.868081 Jun-07-18 13:14:40 [Worker_1] <Connected: SID=DA8B038
IO::Socket::INET=GLOB(0xda8b038) -- IO::Socket::INET=GLOB(0x112337f0)>
1528370080.868269 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
acceptAllMail>
1528370080.868632 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
acceptAllMail>
1528370080.869104 Jun-07-18 13:14:40 [Worker_1] <TimeZoneDiff: 7200 seconds to
GMT>
1528370080.869385 Jun-07-18 13:14:40 [Worker_1] <* connect SID=DA8B038
ip=79.99.3.135 relay=<0> *>
1528370080.869622 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 - noLog>
1528370080.870262 Jun-07-18 13:14:40 [Worker_1] <ThreadGetNewCon>
1528370080.873105 Jun-07-18 13:14:40 [Worker_1] <rh: 2 - read: 1 - wait: 0.002
- act: 1>
1528370080.875608 Jun-07-18 13:14:40 [Worker_1] <rh: 2 - read: 1 - wh: 2 -
write: 2 - wait: 0.002 - act: 1>
1528370080.877205 Jun-07-18 13:14:40 [Worker_1]
<IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=>
1528370080.877417 Jun-07-18 13:14:40 [Worker_1] <SMTPWrite -
IO::Socket::INET=GLOB(0xda8b038)>
1528370080.877777 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) unselect (writable) from main sub main::unpoll
7[LF]>
1528370080.878158 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) unselect (writable) from main sub main::unpoll
7[LF]>
1528370080.878410 Jun-07-18 13:14:40 [Worker_1]
<IO::Socket::INET=GLOB(0x112337f0) l=>
1528370080.878587 Jun-07-18 13:14:40 [Worker_1] <SMTPWrite -
IO::Socket::INET=GLOB(0x112337f0)>
1528370080.878902 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 server
IO::Socket::INET=GLOB(0x112337f0) unselect (writable) from main sub
main::unpoll 7[LF]>
1528370080.879232 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 server
IO::Socket::INET=GLOB(0x112337f0) unselect (writable) from main sub
main::unpoll 7[LF]>
1528370080.880720 Jun-07-18 13:14:40 [Worker_1] <SMTPTraffic -
IO::Socket::INET=GLOB(0x112337f0)>
1528370080.881398 Jun-07-18 13:14:40 [Worker_1] <SMTPTraffic - read OK>
1528370080.881699 Jun-07-18 13:14:40 [Worker_1] <SMTPTraffic - process read>
1528370080.881959 Jun-07-18 13:14:40 [Worker_1] <doing line <220
scandinavianhosting.se ESMTP MailEnable Service, Version: 8.03--8.03 ready at
06/07/18 13:14:34[CR][LF]
>>
1528370080.882245 Jun-07-18 13:14:40 [Worker_1] <reply - 220
scandinavianhosting.se ESMTP MailEnable Service, Version: 8.03--8.03 ready at
06/07/18 13:14:34[CR][LF]>
1528370080.882670 Jun-07-18 13:14:40 [Worker_1] <noop to server 1: <>>
1528370080.882902 Jun-07-18 13:14:40 [Worker_1] <sendque:
IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=101>
1528370080.883270 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) select (writable) from main sub main::sendque
24[LF]>
1528370080.893917 Jun-07-18 13:14:40 [Worker_1]
<IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=101>
1528370080.894183 Jun-07-18 13:14:40 [Worker_1] <SMTPWrite -
IO::Socket::INET=GLOB(0xda8b038)>
1528370080.894875 Jun-07-18 13:14:40 [Worker_1] <wrote:
IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 (101)>
1528370080.895429 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) unselect (writable) from main sub main::unpoll
7[LF]>
1528370080.895864 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) unselect (writable) from main sub main::unpoll
7[LF]>
1528370080.919445 Jun-07-18 13:14:40 [Worker_1] <SMTPTraffic -
IO::Socket::INET=GLOB(0xda8b038)>
1528370080.920258 Jun-07-18 13:14:40 [Worker_1] <SMTPTraffic - read OK>
1528370080.920490 Jun-07-18 13:14:40 [Worker_1] <SMTPTraffic - process read>
1528370080.920748 Jun-07-18 13:14:40 [Worker_1] <doing line <EHLO
smtp02.ebutiken.nu[CR][LF]
>>
1528370080.920978 Jun-07-18 13:14:40 [Worker_1] <getline>
1528370080.921207 Jun-07-18 13:14:40 [Worker_1] <getline: <EHLO
smtp02.ebutiken.nu[CR][LF]
>>
1528370080.921687 Jun-07-18 13:14:40 [Worker_1] <sendque:
IO::Socket::INET=GLOB(0x112337f0) l=25>
1528370080.922088 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 server
IO::Socket::INET=GLOB(0x112337f0) select (writable) from main sub main::sendque
24[LF]>
1528370080.934490 Jun-07-18 13:14:40 [Worker_1]
<IO::Socket::INET=GLOB(0x112337f0) l=25>
1528370080.934736 Jun-07-18 13:14:40 [Worker_1] <SMTPWrite -
IO::Socket::INET=GLOB(0x112337f0)>
1528370080.935786 Jun-07-18 13:14:40 [Worker_1] <wrote:
IO::Socket::INET=GLOB(0x112337f0) (25)>
1528370080.936436 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 server
IO::Socket::INET=GLOB(0x112337f0) unselect (writable) from main sub
main::unpoll 7[LF]>
1528370080.936816 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 server
IO::Socket::INET=GLOB(0x112337f0) unselect (writable) from main sub
main::unpoll 7[LF]>
1528370080.944803 Jun-07-18 13:14:40 [Worker_1] <SMTPTraffic -
IO::Socket::INET=GLOB(0x112337f0)>
1528370080.945553 Jun-07-18 13:14:40 [Worker_1] <SMTPTraffic - read OK>
1528370080.945831 Jun-07-18 13:14:40 [Worker_1] <SMTPTraffic - process read>
1528370080.946167 Jun-07-18 13:14:40 [Worker_1] <doing line
<250-scandinavianhosting.se [192.168.10.51], this server offers 6
extensions[CR][LF]
>>
1528370080.946414 Jun-07-18 13:14:40 [Worker_1] <reply -
250-scandinavianhosting.se [192.168.10.51], this server offers 6
extensions[CR][LF]>
1528370080.946773 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
noTLSIP>
1528370080.947129 Jun-07-18 13:14:40 [Worker_1] <sendque:
IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=77>
1528370080.947703 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) select (writable) from main sub main::sendque
24[LF]>
1528370080.947991 Jun-07-18 13:14:40 [Worker_1] <doing line <250-AUTH CRAM-MD5
LOGIN[CR][LF]
>>
1528370080.948214 Jun-07-18 13:14:40 [Worker_1] <reply - 250-AUTH CRAM-MD5
LOGIN[CR][LF]>
1528370080.948554 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
noTLSIP>
1528370080.948867 Jun-07-18 13:14:40 [Worker_1] <info: Reply: registered
authmethode CRAM-MD5>
1528370080.949073 Jun-07-18 13:14:40 [Worker_1] <info: Reply: registered
authmethode LOGIN>
1528370080.949306 Jun-07-18 13:14:40 [Worker_1] <sendque:
IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=25>
1528370080.949655 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) select (writable) from main sub main::sendque
24[LF]>
1528370080.949935 Jun-07-18 13:14:40 [Worker_1] <doing line <250-SIZE
104857600[CR][LF]
>>
1528370080.950177 Jun-07-18 13:14:40 [Worker_1] <reply - 250-SIZE
104857600[CR][LF]>
1528370080.950453 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
noTLSIP>
1528370080.950723 Jun-07-18 13:14:40 [Worker_1] <sendque:
IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=20>
1528370080.951067 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) select (writable) from main sub main::sendque
24[LF]>
1528370080.951340 Jun-07-18 13:14:40 [Worker_1] <doing line <250-HELP[CR][LF]
>>
1528370080.951548 Jun-07-18 13:14:40 [Worker_1] <reply - 250-HELP[CR][LF]>
1528370080.951823 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
noTLSIP>
1528370080.952110 Jun-07-18 13:14:40 [Worker_1] <sendque:
IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=10>
1528370080.953964 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) select (writable) from main sub main::sendque
24[LF]>
1528370080.954300 Jun-07-18 13:14:40 [Worker_1] <doing line
<250-AUTH=LOGIN[CR][LF]
>>
1528370080.954533 Jun-07-18 13:14:40 [Worker_1] <reply - 250-AUTH=LOGIN[CR][LF]>
1528370080.954859 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
noTLSIP>
1528370080.955171 Jun-07-18 13:14:40 [Worker_1] <info: Reply: registered
authmethode LOGIN>
1528370080.955434 Jun-07-18 13:14:40 [Worker_1] <sendque:
IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=16>
1528370080.955766 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) select (writable) from main sub main::sendque
24[LF]>
1528370080.956022 Jun-07-18 13:14:40 [Worker_1] <doing line
<250-STARTTLS[CR][LF]
>>
1528370080.956283 Jun-07-18 13:14:40 [Worker_1] <reply - 250-STARTTLS[CR][LF]>
1528370080.956633 Jun-07-18 13:14:40 [Worker_1] <matchIP - 79.99.3.135 -
noTLSIP>
1528370080.956880 Jun-07-18 13:14:40 [Worker_1] <noop to client 2>
1528370080.957097 Jun-07-18 13:14:40 [Worker_1] <removed '250-STARTTLS' from
reply>
1528370080.957344 Jun-07-18 13:14:40 [Worker_1] <sendque:
IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=10>
1528370080.957677 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) select (writable) from main sub main::sendque
24[LF]>
1528370080.957936 Jun-07-18 13:14:40 [Worker_1] <doing line <250
XSAVETOSENT[CR][LF]
>>
1528370080.958200 Jun-07-18 13:14:40 [Worker_1] <reply - 250
XSAVETOSENT[CR][LF]>
1528370080.958695 Jun-07-18 13:14:40 [Worker_1] <noop to server 1: <>>
1528370080.958927 Jun-07-18 13:14:40 [Worker_1] <sendque:
IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=17>
1528370080.959255 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) select (writable) from main sub main::sendque
24[LF]>
1528370080.969871 Jun-07-18 13:14:40 [Worker_1]
<IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 l=175>
1528370080.970155 Jun-07-18 13:14:40 [Worker_1] <SMTPWrite -
IO::Socket::INET=GLOB(0xda8b038)>
1528370080.970820 Jun-07-18 13:14:40 [Worker_1] <wrote:
IO::Socket::INET=GLOB(0xda8b038) 79.99.3.135 (175)>
1528370080.971400 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) unselect (writable) from main sub main::unpoll
7[LF]>
1528370080.971787 Jun-07-18 13:14:40 [Worker_1] <Jun-07-18 13:14:40 client
IO::Socket::INET=GLOB(0xda8b038) unselect (writable) from main sub main::unpoll
7[LF]>
1528370108.689274 Jun-07-18 13:15:08 [Worker_1] <SMTPTraffic -
IO::Socket::INET=GLOB(0xda8b038)>
1528370108.690472 Jun-07-18 13:15:08 [Worker_1] <SMTPTraffic - no more data -
Connection reset by peer>
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Assp-test mailing list
Assp-test@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/assp-test
