Jeremy Harris <jgh@???> wrote:
> On 21/07/15 10:09, Tony Finch wrote:
> > I tried to roll out 4.86 yesterday and encountered a fairly nasty bug.
>
> Ah, I should have looked at the Subject harder. A crasher was fixed
> for RC5; could you try that?
At last I have managed to clear my desk so I can look at this properly...
Current test with -RC5 (plus patches) isn't crashing but does exhibit some
kind of related bug:
2015-07-21 15:58:25 +0100 SMTP connection from [131.111.56.56]:10007 I=[131.111.8.135]:25 (TCP/IP connection count = 1)
2015-07-21 15:58:25 +0100 1ZHYzx-0007yr-El <= fanf9@??? H=black.csi.cam.ac.uk [131.111.56.56]:10007 I=[131.111.8.135]:25 P=esmtps X=TLSv1:DHE-RSA-AES256-SHA:256 CV=no S=524 for fanf2@???
2015-07-21 15:58:25 +0100 1ZHYzx-0007yr-El Spool file is locked (another process is handling this message)
2015-07-21 15:58:25 +0100 SMTP connection from black.csi.cam.ac.uk [131.111.56.56]:10007 I=[131.111.8.135]:25 closed by QUIT
Message was delivered, but nothing logged. exim -M gives us:
2015-07-21 15:58:59 +0100 1ZHYzx-0007yr-El Spool file 1ZHYzx-0007yr-El-D not found
The debug log says the queue runner delivered the message:
15:58:25 30681 LOG: MAIN
15:58:25 30681 <= fanf9@??? H=black.csi.cam.ac.uk [131.111.56.56]:10007 I=[131.111.8.135]:25 P=esmtps X=TLSv1:DHE-RSA-AES256-SHA:256 CV=no S=524
15:58:25 30681 SMTP>> 250 OK id=1ZHYzx-0007yr-El
15:58:25 30681 tls_do_write(0x6f8020, 28)
15:58:25 30681 SSL_write(SSL, 0x6f8020, 28)
15:58:25 30681 outbytes=28 error=0
15:58:25 30681 search_tidyup called
15:58:25 30681 Sender: fanf9@???
15:58:25 30681 Recipients:
15:58:25 30681 fanf2@???
15:58:25 30681 forked delivery process 30706
15:58:25 30681 Process 30681 is ready for new message
15:58:25 30681 smtp_setup_msg entered
15:58:25 30681 Calling SSL_read(0x744190, 0x753690, 4096)
15:58:25 30681 SMTP<< QUIT
15:58:25 30706 set_process_info: 30706 delivering 1ZHYzx-0007yr-El
15:58:25 30681 SMTP>> 221 ppsw-52.csi.cam.ac.uk closing connection
15:58:25 30681 tls_do_write(0x6f8020, 46)
15:58:25 30681 SSL_write(SSL, 0x6f8020, 46)
15:58:25 30706 LOG: skip_delivery MAIN
15:58:25 30706 Spool file is locked (another process is handling this message)
15:58:25 30681 outbytes=46 error=0
15:58:25 30681 tls_close(): shutting down SSL
15:58:25 30681 SSL info: SSL negotiation finished successfully
15:58:25 30706 search_tidyup called
15:58:25 30681 LOG: smtp_connection MAIN
15:58:25 30681 SMTP connection from black.csi.cam.ac.uk [131.111.56.56]:10007 I=[131.111.8.135]:25 closed by QUIT
15:58:25 30681 search_tidyup called
15:58:25 985 child 30681 ended: status=0x0
But I don't yet have debug logs from the queue runner because I am running
it in a very tight loop to make it easier to trigger the bug...
Tony.
--
f.anthony.n.finch <dot@???>
http://dotat.at/
Forties, Cromarty, Forth, Tyne, Dogger, Fisher, German Bight: West or
southwest 4 or 5, increasing 6 at times, becoming variable 3 or 4 for a time,
except in Dogger and German Bight. Slight or moderate. Showers. Good.
