[Assp-test] Antwort: IO::Socket::SSL=GLOB - Bad file descriptor

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 454-5900

reduce SSLtimeout = 60 to a max of 5 and a min of 2

Thomas 

Von:    "Marco (spam box)" <sp...@op...>
An:     "ass...@li..." 
<ass...@li...>, 
Datum:  30.07.2013 12:12
Betreff:        [Assp-test] IO::Socket::SSL=GLOB - Bad file descriptor

Hello,

This is an unsolved issue for me for a long time. Several times a day I 
get this messages. And most of the time assp does not accept connection on 
port 25 while this messages are looping:

Jul-30-13 06:48:59 [Worker_1] Error: Worker_1 accept to client failed 
IO::Socket::SSL=GLOB(0x14a2b864) (timeout: 60 s) : A connection attempt 
failed because the connected party did not properly respond after a period 
of time, or established connection failed because connected host has 
failed to respond.
Jul-30-13 06:48:59 [Worker_2] Worker_2 wakes up
Jul-30-13 06:48:59 [Worker_1] Info: Worker_1 freed Main_Thread (no accept)
[.]
Jul-30-13 06:50:30 [Main_Thread] Info: Worker_1 handles 0 sockets and does 
not answer - will try other worker
Jul-30-13 06:50:59 [Worker_1] Error: Worker_1 accept to client failed 
IO::Socket::SSL=GLOB(0x14a1db44) (timeout: 60 s) : A connection attempt 
failed because the connected party did not properly respond after a period 
of time, or established connection failed because connected host has 
failed to respond.
Jul-30-13 06:50:59 [Worker_2] Info: Worker_2 got connection from 
MainThread - 16/16
Jul-30-13 06:50:59 [Main_Thread] Info: Main_Thread will wait (max 30 s) 
for the answer of Worker_2 which handles 0 sockets
Jul-30-13 06:50:59 [Worker_1] Worker_1 prepare to sleep
Jul-30-13 06:50:59 [Worker_1] Worker_1 will sleep now
Jul-30-13 06:51:23 [Worker_10000] Info: (re)scheduled ReloadOptionFiles -> 
nextOptionCheck for Jul-30-13 06:52:23
Jul-30-13 06:51:23 [Worker_10000] Info: (re)scheduled ReloadOptionFiles -> 
nextHashFileCheck for Jul-30-13 06:52:23
Jul-30-13 06:51:30 [Main_Thread] Info: Worker_2 handles 0 sockets and does 
not answer - will try other worker
Jul-30-13 06:51:59 [Worker_2] Error: Worker_2 accept to client failed 
IO::Socket::SSL=GLOB(0x13cb09fc) (timeout: 60 s) : A connection attempt 
failed because the connected party did not properly respond after a period 
of time, or established connection failed because connected host has 
failed to respond.
Jul-30-13 06:51:59 [Worker_1] Worker_1 wakes up
Jul-30-13 06:51:59 [Worker_2] Info: Worker_2 freed Main_Thread (no accept)
Jul-30-13 06:51:59 [Worker_1] Info: Worker_1 got connection from 
MainThread - 16/16
Jul-30-13 06:51:59 [Main_Thread] Info: Main_Thread will wait (max 30 s) 
for the answer of Worker_1 which handles 0 sockets
Jul-30-13 06:51:59 [Worker_2] Worker_2 prepare to sleep
Jul-30-13 06:51:59 [Worker_2] Worker_2 will sleep now
Jul-30-13 06:52:18 [Worker_10000] Info: 'mysql' database connection was 
checked in 0.029 seconds for all tables
Jul-30-13 06:52:25 [Worker_10000] Info: (re)scheduled ReloadOptionFiles -> 
nextOptionCheck for Jul-30-13 06:53:25
Jul-30-13 06:52:25 [Worker_10000] Info: (re)scheduled ReloadOptionFiles -> 
nextHashFileCheck for Jul-30-13 06:53:25
Jul-30-13 06:52:30 [Main_Thread] Info: Worker_1 handles 0 sockets and does 
not answer - will try other worker
Jul-30-13 06:52:59 [Worker_1] Error: Worker_1 accept to client failed 
IO::Socket::SSL=GLOB(0x13aca184) (timeout: 60 s) : A connection attempt 
failed because the connected party did not properly respond after a period 
of time, or established connection failed because connected host has 
failed to respond.
Jul-30-13 06:52:59 [Worker_2] Worker_2 wakes up
Jul-30-13 06:52:59 [Worker_1] Info: Worker_1 freed Main_Thread (no accept)
Jul-30-13 06:52:59 [Worker_2] Info: Worker_2 got connection from 
MainThread - 16/16
Jul-30-13 06:52:59 [Main_Thread] Info: Main_Thread will wait (max 30 s) 
for the answer of Worker_2 which handles 0 sockets
Jul-30-13 06:52:59 [Worker_1] Worker_1 prepare to sleep
Jul-30-13 06:52:59 [Worker_1] Worker_1 will sleep now
[.]

Maybe the delivering server comes with SSL and does not talk proper? Don't 
know. Fact is that the smtp communication on port 25 will stuck sometimes 
after a while .
I have configured: doTLS, SSL_version SSLv2/3, the provided SSLCertFile 
and key from assp, SSLRetryOnError checked, SSLtimeout = 60 
This night there were similar looping messages for about 20 minutes. Only 
messages for Worker_1,_2, Main and _10000 and no messages for Workers _3 
to _5 ) .Till I killed assp. After that everything worked fine again.

If I configure a Thunderbird mailbox I can reproduce a similar situation. 
If I configure only the server host and set up port, SSL, authentification 
to auto. Clicking test button serveral times will lead into a not 
responding assp. Sometimes I can't connect via telnet sometimes I will get 
a blinking cursor at port 25 without plaintext output from the server. 
Sometimes assp comes back sometimes I have to kill it.

Logfile:
Jul-30-13 09:47:55 [Worker_1] [TLS-in] my.ip.xx.yy TLS-Connection idle for 
360 secs - timeout
Jul-30-13 09:47:55 [Worker_1] [TLS-in] my.ip.xx.yy [SMTP Status] 451 
Connection timeout, try later
Jul-30-13 09:47:55 [Worker_1] Disconnected: session:1334DADC my.ip.xx.yy - 
command list was 'EHLO,STARTTLS,EHLO' - used 3 SocketCalls - processing 
time 0 seconds
Jul-30-13 09:47:55 [Worker_1] Worker_1 prepare to sleep
Jul-30-13 09:47:55 [Worker_1] Worker_1 will sleep now
Jul-30-13 09:47:57 [Worker_3] Worker_3 wakes up
Jul-30-13 09:47:57 [Worker_3] Worker_3 will sleep now
Jul-30-13 09:48:03 [Main_Thread] Info: Main_Thread got connection request
Jul-30-13 09:48:03 [Main_Thread] Info: Main_Thread looks up the best 
Worker for new connection - 15
Jul-30-13 09:48:03 [Worker_1] Worker_1 wakes up
Jul-30-13 09:48:03 [Worker_1] Info: Worker_1 got connection from 
MainThread - 15/15
Jul-30-13 09:48:03 [Worker_1] Info: Worker_1 freed Main_Thread - 23
Jul-30-13 09:48:03 [Worker_1] Info: try to connect to server at 
127.0.0.1:225
Jul-30-13 09:48:03 [Worker_1] Info: connected to server at 127.0.0.1:225
Jul-30-13 09:48:03 [Worker_1] Connected: session:13350F44 
my.ip.xx.yy:28570 > my.ip.xx.yy:25 > 127.0.0.1:6289 > 127.0.0.1:225 , 
23-24
Jul-30-13 09:48:03 [Main_Thread] Info: Main_Thread will wait (max 30 s) 
for the answer of Worker_1 which handles 0 sockets
Jul-30-13 09:48:03 [Main_Thread] Info: Main_Thread freed by idle Worker_1 
in 0.019 seconds - got (ok)
Jul-30-13 09:48:03 [Worker_1] my.ip.xx.yy [SMTP Reply] 220 
xch.opti-serv.bruchsal Microsoft ESMTP MAIL Service ready at Tue, 30 Jul 
2013 09:48:03 +0200
Jul-30-13 09:48:03 [Worker_1] SC-Time Worker_1: 0.00218296051025391
Jul-30-13 09:48:03 [Worker_1] my.ip.xx.yy SC-Time Worker_1: 
0.0014348030090332
Jul-30-13 09:48:03 [Worker_1] my.ip.xx.yy info: injected '250-STARTTLS' 
offer in to EHLO reply
Jul-30-13 09:48:03 [Worker_1] my.ip.xx.yy info: send '250-STARTTLS' - 
injected for 127.0.0.1
Jul-30-13 09:48:03 [Worker_1] my.ip.xx.yy [SMTP Reply] 250 NOOP
Jul-30-13 09:48:03 [Worker_1] SC-Time Worker_1: 0.00768494606018066
Jul-30-13 09:48:03 [Worker_1] my.ip.xx.yy SC-Time Worker_1: 
0.00130295753479004
Jul-30-13 09:48:03 [Worker_1] my.ip.xx.yy [SMTP Reply] 221 2.0.0 Service 
closing transmission channel
Jul-30-13 09:48:03 [Worker_1] SC-Time Worker_1: 0.00184488296508789
Jul-30-13 09:48:03 [Worker_1] Disconnected: session:13350F44 my.ip.xx.yy - 
command list was 'EHLO,QUIT' - used 2 SocketCalls - processing time 0 
seconds
Jul-30-13 09:48:03 [Worker_1] Worker_1 prepare to sleep
Jul-30-13 09:48:03 [Worker_1] Worker_1 will sleep now
Jul-30-13 09:48:26 [Main_Thread] Info: Main_Thread got connection request
Jul-30-13 09:48:26 [Main_Thread] Info: Main_Thread looks up the best 
Worker for new connection - 16
Jul-30-13 09:48:26 [Worker_1] Worker_1 wakes up
Jul-30-13 09:48:26 [Worker_1] Info: Worker_1 got connection from 
MainThread - 16/16
Jul-30-13 09:48:26 [Main_Thread] Info: Main_Thread will wait (max 30 s) 
for the answer of Worker_1 which handles 0 sockets
Jul-30-13 09:48:28 [Worker_10000] Info: (re)scheduled ReloadOptionFiles -> 
nextOptionCheck for Jul-30-13 09:49:28
Jul-30-13 09:48:28 [Worker_10000] Info: (re)scheduled ReloadOptionFiles -> 
nextHashFileCheck for Jul-30-13 09:49:28
Jul-30-13 09:48:36 [Worker_1] Error: Worker_1 accept to client failed 
IO::Socket::SSL=GLOB(0x1345519c) (timeout: 360 s) : Bad file descriptor
Jul-30-13 09:48:36 [Worker_1] Info: Worker_1 freed Main_Thread (no accept)
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread freed by idle Worker_1 
in 10.063 seconds - got (failed)
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread got connection request
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread looks up the best 
Worker for new connection - 16
Jul-30-13 09:48:36 [Worker_2] Worker_2 wakes up
Jul-30-13 09:48:36 [Worker_2] Info: Worker_2 got connection from 
MainThread - 16/16
Jul-30-13 09:48:36 [Worker_1] Worker_1 prepare to sleep
Jul-30-13 09:48:36 [Worker_1] Worker_1 will sleep now
Jul-30-13 09:48:36 [Worker_2] Error: Worker_2 accept to client failed 
IO::Socket::SSL=GLOB(0x1345e1f4) (timeout: 360 s) : Bad file descriptor
Jul-30-13 09:48:36 [Worker_2] Info: Worker_2 freed Main_Thread (no accept)
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread will wait (max 30 s) 
for the answer of Worker_2 which handles 0 sockets
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread freed by idle Worker_2 
in 0.014 seconds - got (failed)
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread got connection request
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread looks up the best 
Worker for new connection - 15
Jul-30-13 09:48:36 [Worker_1] Worker_1 wakes up
Jul-30-13 09:48:36 [Worker_1] Info: Worker_1 got connection from 
MainThread - 15/15
Jul-30-13 09:48:36 [Worker_1] Info: Worker_1 freed Main_Thread - 23
Jul-30-13 09:48:36 [Worker_1] Info: try to connect to server at 
127.0.0.1:225
Jul-30-13 09:48:36 [Worker_1] Info: connected to server at 127.0.0.1:225
Jul-30-13 09:48:36 [Worker_2] Worker_2 prepare to sleep
Jul-30-13 09:48:36 [Worker_2] Worker_2 will sleep now
Jul-30-13 09:48:36 [Worker_1] Connected: session:13F0020C 
my.ip.xx.yy:57158 > my.ip.xx.yy:25 > 127.0.0.1:6290 > 127.0.0.1:225 , 
23-24
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread will wait (max 30 s) 
for the answer of Worker_1 which handles 0 sockets
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread freed by idle Worker_1 
in 0.017 seconds - got (ok)
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread got connection request
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread looks up the best 
Worker for new connection - 15
Jul-30-13 09:48:36 [Worker_1] my.ip.xx.yy [SMTP Reply] 220 
xch.opti-serv.bruchsal Microsoft ESMTP MAIL Service ready at Tue, 30 Jul 
2013 09:48:36 +0200
Jul-30-13 09:48:36 [Worker_1] SC-Time Worker_1: 0.00277495384216309
Jul-30-13 09:48:36 [Worker_1] my.ip.xx.yy info: no (more) data readable 
from my.ip.xx.yy (connection closed by peer) 
Jul-30-13 09:48:36 [Worker_1] my.ip.xx.yy SC-Time Worker_1: 
0.00135517120361328
Jul-30-13 09:48:36 [Worker_1] Disconnected: session:13F0020C my.ip.xx.yy - 
command list was 'n/a' - used 1 SocketCalls - processing time 0 seconds
Jul-30-13 09:48:36 [Worker_1] Worker_1 prepare to sleep
Jul-30-13 09:48:36 [Worker_1] Worker_1 will sleep now
Jul-30-13 09:48:36 [Worker_1] Worker_1 wakes up
Jul-30-13 09:48:36 [Worker_1] Info: Worker_1 got connection from 
MainThread - 15/15
Jul-30-13 09:48:36 [Worker_1] Info: Worker_1 freed Main_Thread - 23
Jul-30-13 09:48:36 [Worker_1] Info: try to connect to server at 
127.0.0.1:225
Jul-30-13 09:48:36 [Worker_1] Info: connected to server at 127.0.0.1:225
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread will wait (max 30 s) 
for the answer of Worker_1 which handles 0 sockets
Jul-30-13 09:48:36 [Main_Thread] Info: Main_Thread freed by idle Worker_1 
in 0.014 seconds - got (ok)
Jul-30-13 09:48:36 [Worker_1] Connected: session:990C4C4 my.ip.xx.yy:57159 
> my.ip.xx.yy:25 > 127.0.0.1:6291 > 127.0.0.1:225 , 23-24
Jul-30-13 09:48:36 [Worker_1] my.ip.xx.yy [SMTP Reply] 220 
xch.opti-serv.bruchsal Microsoft ESMTP MAIL Service ready at Tue, 30 Jul 
2013 09:48:36 +0200
Jul-30-13 09:48:36 [Worker_1] SC-Time Worker_1: 0.00216007232666016
Jul-30-13 09:48:36 [Worker_1] my.ip.xx.yy info: no (more) data readable 
from my.ip.xx.yy (connection closed by peer) 
Jul-30-13 09:48:36 [Worker_1] my.ip.xx.yy SC-Time Worker_1: 
0.000803947448730469
Jul-30-13 09:48:36 [Worker_1] Disconnected: session:990C4C4 my.ip.xx.yy - 
command list was 'n/a' - used 1 SocketCalls - processing time 0 seconds
Jul-30-13 09:48:36 [Worker_1] Worker_1 prepare to sleep
Jul-30-13 09:48:36 [Worker_1] Worker_1 will sleep now
[..]
Jul-30-13 10:10:57 [Worker_4] Worker_4 wakes up
Jul-30-13 10:10:57 [Main_Thread] Info: Main_Thread will wait (max 30 s) 
for the answer of Worker_4 which handles 0 sockets
Jul-30-13 10:10:57 [Worker_4] Worker_4 prepare to sleep
Jul-30-13 10:10:57 [Worker_4] Worker_4 will sleep now
Jul-30-13 10:11:28 [Main_Thread] Info: Worker_4 handles 0 sockets and does 
not answer - will try other worker
Jul-30-13 10:11:28 [Worker_5] Worker_5 wakes up
Jul-30-13 10:11:28 [Main_Thread] Info: Main_Thread will wait (max 30 s) 
for the answer of Worker_5 which handles 0 sockets
Jul-30-13 10:11:28 [Worker_5] Worker_5 prepare to sleep
Jul-30-13 10:11:28 [Worker_5] Worker_5 will sleep now
Jul-30-13 10:11:56 [Worker_10000] Info: (re)scheduled ReloadOptionFiles -> 
nextOptionCheck for Jul-30-13 10:12:56
Jul-30-13 10:11:56 [Worker_10000] Info: (re)scheduled ReloadOptionFiles -> 
nextHashFileCheck for Jul-30-13 10:12:56
Jul-30-13 10:11:56 [Worker_10000] Info: synchronizing all BerkeleyDB 
hashes to disk
Jul-30-13 10:11:56 [Worker_10000] Info: compacting all BerkeleyDB hashes 
on disk
Jul-30-13 10:11:59 [Main_Thread] Info: Worker_5 handles 0 sockets and does 
not answer - will try other worker
Jul-30-13 10:11:59 [Main_Thread] Info: unable to detect any running worker 
for a new connection - wait (max 30 seconds)
[..]
Jul-30-13 10:14:03 [Main_Thread] Info: unable to detect any running worker 
for a new connection - wait (max 30 seconds)
Jul-30-13 10:14:03 [Main_Thread] Info: ConnectionTransferTimeOut (30 
seconds) is now reached
Jul-30-13 10:14:03 [Main_Thread] Warning: Main_Thread is unable to 
transfer connection to any worker - try again!
Jul-30-13 10:14:03 [Main_Thread] Error: Main_Thread is unable to transfer 
connection to any worker within 120 seconds - restart ASSP!
Jul-30-13 10:14:03 [Main_Thread] Initializing shutdown sequence
Jul-30-13 10:14:03 [Shutdown] Info: removing all SMTP and Proxy listeners

This time assp restarted. I don't know how to fix it. Do I have to reduce 
the timeout, increase number for incoming connections/workers. Do I have 
to check some preferences or the certificate? Why does the sending server 
do not communicate with assp. 
Someone having advice or an idea? If you need further information let me 
know.

Right in this minutes I have the same problem with another installation 
again. Assp is not responding on port 25. Telnet at port 587 is possible. 
No connection possible for 1 and an half our at #25. Log messages are 
looping like above. Now I wanted to test if 587 is working properly. I 
send an email with SSL\TLS at 587 and suddenly everything worked fine like 
before. Connecting via 25 is possible again without restarting. I'm 
confused.

Kind Regards

Marco

------------------------------------------------------------------------------
Get your SQL database under version control now!
Version control is standard for application code, but databases havent 
caught up. So what steps can you take to put your SQL databases under 
version control? Why should you start doing it? Read more to find out.
http://pubads.g.doubleclick.net/gampad/clk?id=49501711&iu=/4140/ostg.clktrk

_______________________________________________
Assp-test mailing list
Ass...@li...
https://lists.sourceforge.net/lists/listinfo/assp-test

DISCLAIMER:
*******************************************************
This email and any files transmitted with it may be confidential, legally 
privileged and protected in law and are intended solely for the use of the 

individual to whom it is addressed.
This email was multiple times scanned for viruses. There should be no 
known virus in this email!
*******************************************************

[Assp-test] Antwort: IO::Socket::SSL=GLOB - Bad file descriptor

Anti-Spam SMTP Proxy Server implements multiple spam filters

[Assp-test] Antwort: IO::Socket::SSL=GLOB - Bad file descriptor