[pkg-fetchmail-maint] Bug#398565: fetchmail: SMTP c. timeout for heavy loaded (slow) MTA

Mon May 7 08:56:36 UTC 2007

Hi,

On Mon, Apr 30, 2007 at 03:38:04PM +0200, Nico Golde wrote:
> since we have etch now, can you reproduce this with 6.3.6?

Ok. Results are the same. These are probably a bit patological
conditions. I tried overload system with stress utility (`stress --cpu
8 --io 4 --vm 2 --vm-bytes 128M -d 2 --hdd-bytes 200M') and problem
didn't occured. Beviour of scheduler or IO scheduler is ugly while
copying into logical volume.

So I have Etch box with:

zito at bobek:~$ uname -a
Linux bobek 2.6.18-4-xen-686 #1 SMP Wed Apr 18 14:39:43 UTC 2007 i686 GNU/Linux

zito at bobek:~$ dpkg -l exim4 fetchmail
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Installed/Config-files/Unpacked/Failed-config/Half-installed
|/ Err?=(none)/Hold/Reinst-required/X=both-problems (Status,Err: uppercase=bad)
||/ Name           Version        Description
+++-==============-==============-============================================
ii  exim4          4.63-17        metapackage to ease exim MTA (v4) installati
ii  fetchmail      6.3.6-1        SSL enabled POP3, APOP, IMAP mail gatherer/f

bobek:~# lvcreate -L 5G -n t vg
Logical volume "t" created
bobek:~# dd if=/dev/zero of=/dev/vg/t bs=64k

zito at bobek:~$ echo 'hello world!'|mail -s 'hellow world!' zito at i.cz

zito at bobek:~$ fetchmail -N -v|ts
...
May 07 10:33:24 fetchmail: awakened by User defined signal 1
May 07 10:33:24 fetchmail: awakened at Mon May  7 10:33:24 2007
May 07 10:33:24 fetchmail: 6.3.6 querying sprg11.i.cz (protocol IMAP) at Mon May  7 10:33:24 2007: poll started
May 07 10:33:25 fetchmail: Trying to connect to 192.168.30.71/993...connected.
May 07 10:33:25 fetchmail: Issuer Organization: ICZ a.s.
May 07 10:33:25 fetchmail: Issuer CommonName: ICZ Private CA 2005
May 07 10:33:25 fetchmail: Server CommonName: sprg11.i.cz
May 07 10:33:25 fetchmail: sprg11.i.cz key fingerprint: 2C:B1:43:31:F8:E0:C4:D3:BE:52:10:AD:31:34:24:6A
May 07 10:33:25 fetchmail: IMAP< * OK Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 (sprg11.ad.i.cz) ready.
May 07 10:33:25 fetchmail: IMAP> A0001 CAPABILITY
May 07 10:33:25 fetchmail: IMAP< * CAPABILITY IMAP4 IMAP4rev1 IDLE LOGIN-REFERRALS MAILBOX-REFERRALS NAMESPACE LITERAL+ UIDPLUS CHILDREN
May 07 10:33:25 fetchmail: IMAP< A0001 OK CAPABILITY completed.
May 07 10:33:25 fetchmail: IMAP> A0002 LOGIN "zito" *
May 07 10:33:25 fetchmail: IMAP< A0002 OK LOGIN completed.
May 07 10:33:25 fetchmail: IMAP> A0003 SELECT "INBOX"
May 07 10:33:26 fetchmail: IMAP< * 1 EXISTS
May 07 10:33:26 fetchmail: IMAP< * 1 RECENT
May 07 10:33:26 fetchmail: IMAP< * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
May 07 10:33:26 fetchmail: IMAP< * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
May 07 10:33:26 fetchmail: IMAP< * OK [UNSEEN 1] Is the first unseen message
May 07 10:33:26 fetchmail: IMAP< * OK [UIDVALIDITY 1837] UIDVALIDITY value
May 07 10:33:26 fetchmail: IMAP< A0003 OK [READ-WRITE] SELECT completed.
May 07 10:33:26 fetchmail: IMAP> A0004 EXPUNGE
May 07 10:33:26 fetchmail: IMAP< * 1 EXISTS
May 07 10:33:26 fetchmail: IMAP< A0004 OK EXPUNGE completed.
May 07 10:33:26 fetchmail: 1 message for zito at sprg11.i.cz.
May 07 10:33:26 fetchmail: IMAP> A0005 FETCH 1 RFC822.SIZE
May 07 10:33:26 fetchmail: IMAP< * 1 FETCH (RFC822.SIZE 1484)
May 07 10:33:26 fetchmail: IMAP< A0005 OK FETCH completed.
May 07 10:33:26 fetchmail: IMAP> A0006 FETCH 1 RFC822.HEADER
May 07 10:33:26 fetchmail: IMAP< * 1 FETCH (RFC822.HEADER {1470}
May 07 10:33:26 fetchmail: reading message zito at sprg11.i.cz:1 of 1 (1470 header octets)
May 07 10:33:26 fetchmail: Trying to connect to 127.0.0.1/25...connected.
May 07 10:33:26 fetchmail: SMTP< 220 bobek.localdomain ESMTP Exim 4.63 Mon, 07 May 2007 10:33:26 +0200
May 07 10:33:26 fetchmail: SMTP> EHLO bobek.localdomain
May 07 10:33:26 fetchmail: SMTP< 250-bobek.localdomain Hello localhost.localdomain [127.0.0.1]
May 07 10:33:26 fetchmail: SMTP< 250-SIZE 52428800
May 07 10:33:26 fetchmail: SMTP< 250-PIPELINING
May 07 10:33:26 fetchmail: SMTP< 250 HELP
May 07 10:33:26 fetchmail: SMTP> MAIL FROM:<vaclav.ovsik at i.cz> SIZE=1484
May 07 10:33:26 fetchmail: SMTP< 250 OK
May 07 10:33:26 fetchmail: SMTP> RCPT TO:<zito at localhost>
May 07 10:33:26 fetchmail: SMTP< 250 Accepted
May 07 10:33:26 fetchmail: SMTP> DATA
May 07 10:33:26 fetchmail: SMTP< 354 Enter message, ending with "." on a line by itself
May 07 10:33:26 #
May 07 10:33:26 fetchmail: IMAP< )
May 07 10:33:26 fetchmail: IMAP< A0006 OK FETCH completed.
May 07 10:33:26 fetchmail: IMAP> A0007 FETCH 1 BODY.PEEK[TEXT]
May 07 10:33:26 fetchmail: IMAP< * 1 FETCH (BODY[TEXT] {14}
May 07 10:33:26 *
May 07 10:33:26 fetchmail:  (14 body octets) (log message incomplete)fetchmail: IMAP< )
May 07 10:33:26 fetchmail: IMAP< A0007 OK FETCH completed.
May 07 10:33:26 fetchmail: SMTP>. (EOM)
fetchmail: smtp listener protocol error
May 07 10:33:56 fetchmail:  not flushed
May 07 10:33:56 fetchmail: IMAP> A0008 LOGOUT
May 07 10:33:56 fetchmail: IMAP< * BYE Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 signing off.
May 07 10:33:56 fetchmail: IMAP< A0008 OK LOGOUT completed.
May 07 10:33:56 fetchmail: 6.3.6 querying sprg11.i.cz (protocol IMAP) at Mon May  7 10:33:56 2007: poll completed
May 07 10:33:56 fetchmail: sleeping at Mon May  7 10:33:56 2007 for 60 seconds
May 07 10:34:36 fetchmail: awakened by User defined signal 1
May 07 10:34:36 fetchmail: awakened at Mon May  7 10:34:36 2007
May 07 10:34:36 fetchmail: 6.3.6 querying sprg11.i.cz (protocol IMAP) at Mon May  7 10:34:36 2007: poll started
May 07 10:34:36 fetchmail: Trying to connect to 192.168.30.71/993...connected.
May 07 10:34:36 fetchmail: Issuer Organization: ICZ a.s.
May 07 10:34:36 fetchmail: Issuer CommonName: ICZ Private CA 2005
May 07 10:34:36 fetchmail: Server CommonName: sprg11.i.cz
May 07 10:34:36 fetchmail: sprg11.i.cz key fingerprint: 2C:B1:43:31:F8:E0:C4:D3:BE:52:10:AD:31:34:24:6A
May 07 10:34:36 fetchmail: IMAP< * OK Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 (sprg11.ad.i.cz) ready.
May 07 10:34:36 fetchmail: IMAP> A0001 CAPABILITY
May 07 10:34:36 fetchmail: IMAP< * CAPABILITY IMAP4 IMAP4rev1 IDLE LOGIN-REFERRALS MAILBOX-REFERRALS NAMESPACE LITERAL+ UIDPLUS CHILDREN
May 07 10:34:36 fetchmail: IMAP< A0001 OK CAPABILITY completed.
May 07 10:34:36 fetchmail: IMAP> A0002 LOGIN "zito" *
May 07 10:34:37 fetchmail: IMAP< A0002 OK LOGIN completed.
May 07 10:34:37 fetchmail: IMAP> A0003 SELECT "INBOX"
May 07 10:34:37 fetchmail: IMAP< * 1 EXISTS
May 07 10:34:37 fetchmail: IMAP< * 0 RECENT
May 07 10:34:37 fetchmail: IMAP< * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
May 07 10:34:37 fetchmail: IMAP< * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
May 07 10:34:37 fetchmail: IMAP< * OK [UNSEEN 1] Is the first unseen message
May 07 10:34:37 fetchmail: IMAP< * OK [UIDVALIDITY 1837] UIDVALIDITY value
May 07 10:34:37 fetchmail: IMAP< A0003 OK [READ-WRITE] SELECT completed.
May 07 10:34:37 fetchmail: IMAP> A0004 EXPUNGE
May 07 10:34:37 fetchmail: IMAP< * 1 EXISTS
May 07 10:34:37 fetchmail: IMAP< A0004 OK EXPUNGE completed.
May 07 10:34:37 fetchmail: 1 message for zito at sprg11.i.cz.
May 07 10:34:37 fetchmail: IMAP> A0005 FETCH 1 RFC822.SIZE
May 07 10:34:37 fetchmail: IMAP< * 1 FETCH (RFC822.SIZE 1484)
May 07 10:34:37 fetchmail: IMAP< A0005 OK FETCH completed.
May 07 10:34:37 fetchmail: IMAP> A0006 FETCH 1 RFC822.HEADER
May 07 10:34:37 fetchmail: IMAP< * 1 FETCH (RFC822.HEADER {1470}
May 07 10:34:37 fetchmail: reading message zito at sprg11.i.cz:1 of 1 (1470 header octets)
May 07 10:34:37 fetchmail: Trying to connect to 127.0.0.1/25...connected.
May 07 10:34:37 fetchmail: SMTP< 220 bobek.localdomain ESMTP Exim 4.63 Mon, 07 May 2007 10:34:37 +0200
May 07 10:34:37 fetchmail: SMTP> EHLO bobek.localdomain
May 07 10:34:37 fetchmail: SMTP< 250-bobek.localdomain Hello localhost.localdomain [127.0.0.1]
May 07 10:34:37 fetchmail: SMTP< 250-SIZE 52428800
May 07 10:34:37 fetchmail: SMTP< 250-PIPELINING
May 07 10:34:37 fetchmail: SMTP< 250 HELP
May 07 10:34:37 fetchmail: SMTP> MAIL FROM:<vaclav.ovsik at i.cz> SIZE=1484
May 07 10:34:37 fetchmail: SMTP< 250 OK
May 07 10:34:37 fetchmail: SMTP> RCPT TO:<zito at localhost>
May 07 10:34:37 fetchmail: SMTP< 250 Accepted
May 07 10:34:37 fetchmail: SMTP> DATA
May 07 10:34:37 fetchmail: SMTP< 354 Enter message, ending with "." on a line by itself
May 07 10:34:37 #
May 07 10:34:37 fetchmail: IMAP< )
May 07 10:34:37 fetchmail: IMAP< A0006 OK FETCH completed.
May 07 10:34:37 fetchmail: IMAP> A0007 FETCH 1 BODY.PEEK[TEXT]
May 07 10:34:37 fetchmail: IMAP< * 1 FETCH (BODY[TEXT] {14}
May 07 10:34:37 *
May 07 10:34:37 fetchmail:  (14 body octets) (log message incomplete)fetchmail: IMAP< )
May 07 10:34:37 fetchmail: IMAP< A0007 OK FETCH completed.
May 07 10:34:37 fetchmail: SMTP>. (EOM)
May 07 10:34:37 fetchmail: SMTP< 250 OK id=1Hkyg1-0004cq-D7
May 07 10:34:37 fetchmail:  flushed
May 07 10:34:37 fetchmail: IMAP> A0008 STORE 1 +FLAGS (\Seen \Deleted)
May 07 10:34:37 fetchmail: IMAP< * 1 FETCH (FLAGS (\Seen \Deleted))
May 07 10:34:37 fetchmail: IMAP< A0008 OK STORE completed.
May 07 10:34:37 fetchmail: IMAP> A0009 EXPUNGE
May 07 10:34:37 fetchmail: IMAP< * 1 EXPUNGE
May 07 10:34:37 fetchmail: IMAP< * 0 EXISTS
May 07 10:34:37 fetchmail: IMAP< A0009 OK EXPUNGE completed.
May 07 10:34:37 fetchmail: IMAP> A0010 LOGOUT
May 07 10:34:37 fetchmail: IMAP< * BYE Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 signing off.
May 07 10:34:37 fetchmail: IMAP< A0010 OK LOGOUT completed.
May 07 10:34:37 fetchmail: SMTP> QUIT
May 07 10:34:37 fetchmail: SMTP< 221 bobek.localdomain closing connection

------</var/log/exim4/mainlog>------
...
2007-05-07 10:32:55 1Hkydp-0004c9-Aq <= vaclav.ovsik at i.cz U=zito P=local S=348
2007-05-07 10:33:10 1Hkydp-0004c9-Aq => zito at i.cz R=smarthost T=remote_smtp_smarthost H=ns.i.cz [192.168.24.10] X=TLS-1.0:RSA_AES_256_CBC_SHA1:32 DN="C=CZ,O=ICZ a.s.,OU=Machines,CN=ns.i.cz"
2007-05-07 10:33:10 1Hkydp-0004c9-Aq Completed
2007-05-07 10:34:02 1Hkyes-0004cQ-JG <= vaclav.ovsik at i.cz H=localhost.localdomain (bobek.localdomain) [127.0.0.1] P=esmtp S=1821 id=E1Hkydp-0004c9-Aq at bobek.localdomain
2007-05-07 10:34:29 1Hkyes-0004cQ-JG => zito <zito at localhost> R=procmail T=procmail_pipe
2007-05-07 10:34:29 1Hkyes-0004cQ-JG Completed
2007-05-07 10:34:37 1Hkyg1-0004cq-D7 <= vaclav.ovsik at i.cz H=localhost.localdomain (bobek.localdomain) [127.0.0.1] P=esmtp S=1821 id=E1Hkydp-0004c9-Aq at bobek.localdomain
2007-05-07 10:34:37 1Hkyg1-0004cq-D7 => zito <zito at localhost> R=procmail T=procmail_pipe
2007-05-07 10:34:37 1Hkyg1-0004cq-D7 Completed
...

I have duplicated message in INBOX. Fixed 30 second timeout on SMTP is too low.
Linux is not realtime system (today), so I think the timeout should be much
higher or configurable at least.

Regards
-- 
Zito