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