Re: [exim] Connection not timing out

Top Page
Delete this message
Reply to this message
Author: Andrew C Aitchison
Date:  
To: Michael Fischer v. Mollard
CC: exim-users
Subject: Re: [exim] Connection not timing out
On Mon, 21 Mar 2016, Michael Fischer v. Mollard wrote:

> -- Am 03/20/16 19:54:35 +0100 schrieb Heiko Schlittermann:
>
>> Hi,
>>
>> Michael Fischer v. Mollard <lists@???> (Sa 19 Mär 2016
>> 19:41:39 CET):
>> > Hello,
>> >
>> > I've a strange problem with the connection timeout on an Exim 4.86:
>> >
> […]
>> > Ignoring that the strange behavior of the receiving side (I explicitly
>> > killed the client, so it closed the connection as seen in the logs) I'd
>> > expect that the sending exim quit the connection after final_timeout
>> > (not explicitly given, so it should be 10 minutes). Is there an
>> > explanation why the sending exim is not closing the connection? Could
>> > this be a regression as I've never seen that before?
>>
>> I do not see any indication that some process is exceeding it's timeout.
>> The only thing I see is, that a process (probably the queue runner)
>> can't lock the spool file, because it's locked already. The last log
>> line shows a forceful closed connection, but we've no idea if this is
>> the same process as started just after the messages came in.
>>
>> You may add the +pid log_selector to get an idea about the processes
>> (not) handling a message.
>
> Hello,
>
> another example:
>
> # exiwhat
> […]
> 29077 delivering 1ai1bZ-0007Yw-Qf: waiting for a remote delivery subprocess
> to finish
> 29079 delivering 1ai1bZ-0007Yw-Qf to XXX [XXX] (XXX)
>
> # kill 29079
>
> # exigrep 1ai1bZ-0007Yw-Qf /var/log/exim4/mainlog
> 2016-03-21 16:18:54 [29074] 1ai1bZ-0007Yw-Qf <= XXX H=XXX [XXX] P=smtp
> S=17032 id=XXX
> 2016-03-21 16:26:04 [30608] 1ai1bZ-0007Yw-Qf Spool file is locked (another
> process is handling this message)
> 2016-03-21 16:51:49 [3046] 1ai1bZ-0007Yw-Qf Spool file is locked (another
> process is handling this message)
> 2016-03-21 16:54:17 [3424] 1ai1bZ-0007Yw-Qf Spool file is locked (another
> process is handling this message)
> 2016-03-21 17:03:11 [4875] 1ai1bZ-0007Yw-Qf Spool file is locked (another
> process is handling this message)
> 2016-03-21 17:08:48 [5951] 1ai1bZ-0007Yw-Qf Spool file is locked (another
> process is handling this message)
> 2016-03-21 17:21:35 [9861] 1ai1bZ-0007Yw-Qf Spool file is locked (another
> process is handling this message)
> 2016-03-21 17:26:05 [11602] 1ai1bZ-0007Yw-Qf Spool file is locked (another
> process is handling this message)
> 2016-03-21 17:33:49 [29077] 1ai1bZ-0007Yw-Qf == XXX R=dnslookup
> T=T_local_smtp defer (-1): smtp transport process returned non-zero status
> 0x000f: terminated by signal 15
> 2016-03-21 17:37:13 [16247] 1ai1bZ-0007Yw-Qf => XXX R=dnslookup
> T=T_local_smtp S=17197 H=XXX X=TLS1.2… CV=no C="250 OK id=1ai2pL-0001mF-Hs"
> QT=1h18m20s DT=2s
> 2016-03-21 17:37:13 [16247] 1ai1bZ-0007Yw-Qf Completed
>
> So if I'm not getting something terribly wrong the delevering process 29079
> which is started by the receiving process 29074 exist for about seventyfive
> minutes until I killed it manually. After that a queue runner picked it up
> and delivered it smoothly.


Hmm. I read that differently. My take (perhaps wrong)
is that 29079 was started by 29077 (since ...7 died when you kill ...9).
Once pids wrap it is hard to guess correctly ...

Some clever use of ps (perhaps ps -f) *before killing anything*
might give more clue.

Is there any other sign of (this) process 29074 in the log ?
It wasn't in the exiwhat output, so I'd guess it had finished.

Next time it happens, can you use fuser to see which process
is holding the lock/locked file ?

> What I'd expect (and strangely enough find in the
> same logfile) would be something like:
>
> 2016-03-21 12:06:01 [6616] 1ahxer-0001ii-CZ <= XXX H=XXX P=esmtps X=TLS1.0
> CV=no S=6481 id=XXX
> 2016-03-21 12:16:02 [6639] 1ahxer-0001ii-CZ SMTP timeout after end of data
> (6636 bytes written): Connection timed out
> 2016-03-21 12:16:03 [6624] 1ahxer-0001ii-CZ => XXX R=dnslookup T=T_local_smtp
> S=6636 H=XXX
> 2016-03-21 12:16:03 [6624] 1ahxer-0001ii-CZ Completed
>
> Regards
>      Michael

>
>
>
> --
> ## List details at https://lists.exim.org/mailman/listinfo/exim-users
> ## Exim details at http://www.exim.org/
> ## Please use the Wiki with this list - http://wiki.exim.org/
>