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

[Václav Ovsík]

Hello,

On Sun, Feb 18, 2007 at 08:07:04PM +0100, Matthias Andree wrote:
> Vaclav,
> 
> this needs more information, particularly information on the timing.
> Please re-run your command with "--syslog" enabled and extract the
> fetchmail logging from your mail log.

Ok. Instead syslog I piped fetchmails output through `ts' utility:

One term:

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

Second term:
zito at bobek:~$ fetchmail -N -v |ts
...
Feb 19 18:00:00 fetchmail: awakened by User defined signal 1
Feb 19 18:00:00 fetchmail: awakened at Mon Feb 19 18:00:00 2007
Feb 19 18:00:00 fetchmail: 6.2.5 querying sprg11.i.cz (protocol IMAP) at Mon Feb 19 18:00:00 2007: poll started
Feb 19 18:00:00 fetchmail: Issuer Organization: ICZ a.s.
Feb 19 18:00:00 fetchmail: Issuer CommonName: ICZ Private CA 2005
Feb 19 18:00:00 fetchmail: Server CommonName: sprg11.i.cz
Feb 19 18:00:00 fetchmail: sprg11.i.cz key fingerprint: 2C:B1:43:31:F8:E0:C4:D3:BE:52:10:AD:31:34:24:6A
Feb 19 18:00:01 fetchmail: IMAP< * OK Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 (sprg11.ad.i.cz) ready.
Feb 19 18:00:01 fetchmail: IMAP> A0001 CAPABILITY
Feb 19 18:00:01 fetchmail: IMAP< * CAPABILITY IMAP4 IMAP4rev1 IDLE LOGIN-REFERRALS MAILBOX-REFERRALS NAMESPACE LITERAL+ UIDPLUS CHILDREN
Feb 19 18:00:01 fetchmail: IMAP< A0001 OK CAPABILITY completed.
Feb 19 18:00:01 fetchmail: IMAP> A0002 LOGIN "zito" *
Feb 19 18:00:01 fetchmail: IMAP< A0002 OK LOGIN completed.
Feb 19 18:00:01 fetchmail: IMAP> A0003 SELECT "INBOX"
Feb 19 18:00:01 fetchmail: IMAP< * 1 EXISTS
Feb 19 18:00:01 fetchmail: IMAP< * 1 RECENT
Feb 19 18:00:01 fetchmail: IMAP< * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
Feb 19 18:00:01 fetchmail: IMAP< * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
Feb 19 18:00:01 fetchmail: IMAP< * OK [UNSEEN 1] Is the first unseen message
Feb 19 18:00:01 fetchmail: IMAP< * OK [UIDVALIDITY 1837] UIDVALIDITY value
Feb 19 18:00:01 fetchmail: IMAP< A0003 OK [READ-WRITE] SELECT completed.
Feb 19 18:00:01 fetchmail: IMAP> A0004 EXPUNGE
Feb 19 18:00:01 fetchmail: IMAP< * 1 EXISTS
Feb 19 18:00:01 fetchmail: IMAP< A0004 OK EXPUNGE completed.
Feb 19 18:00:01 fetchmail: 1 message for zito at sprg11.i.cz.
Feb 19 18:00:01 fetchmail: IMAP> A0005 FETCH 1 RFC822.SIZE
Feb 19 18:00:01 fetchmail: IMAP< * 1 FETCH (RFC822.SIZE 1476)
Feb 19 18:00:01 fetchmail: IMAP< A0005 OK FETCH completed.
Feb 19 18:00:01 fetchmail: IMAP> A0006 FETCH 1 RFC822.HEADER
Feb 19 18:00:01 fetchmail: IMAP< * 1 FETCH (RFC822.HEADER {1451}
Feb 19 18:00:01 fetchmail: reading message zito at sprg11.i.cz:1 of 1 (1451 header octets)
Feb 19 18:00:02 fetchmail: SMTP< 220 bobek.pm.i.cz ESMTP Exim 4.50 Mon, 19 Feb 2007 18:00:02 +0100
Feb 19 18:00:02 fetchmail: SMTP> EHLO localhost
Feb 19 18:00:02 fetchmail: SMTP< 250-bobek.pm.i.cz Hello localhost [127.0.0.1]
Feb 19 18:00:02 fetchmail: SMTP< 250-SIZE 52428800
Feb 19 18:00:02 fetchmail: SMTP< 250-PIPELINING
Feb 19 18:00:02 fetchmail: SMTP< 250 HELP
Feb 19 18:00:02 fetchmail: SMTP> MAIL FROM:<vaclav.ovsik at i.cz> SIZE=1476
Feb 19 18:00:02 fetchmail: SMTP< 250 OK
Feb 19 18:00:02 fetchmail: SMTP> RCPT TO:<zito at localhost>
Feb 19 18:00:02 fetchmail: SMTP< 250 Accepted
Feb 19 18:00:02 fetchmail: SMTP> DATA
Feb 19 18:00:02 fetchmail: SMTP< 354 Enter message, ending with "." on a line by itself
Feb 19 18:00:02 #
Feb 19 18:00:02 fetchmail: IMAP< )
Feb 19 18:00:02 fetchmail: IMAP< A0006 OK FETCH completed.
Feb 19 18:00:02 fetchmail: IMAP> A0007 FETCH 1 BODY.PEEK[TEXT]
Feb 19 18:00:02 fetchmail: IMAP< * 1 FETCH (BODY[TEXT] {25}
Feb 19 18:00:02 fetchmail:  (25 body octets) *
Feb 19 18:00:02 fetchmail: IMAP< )
Feb 19 18:00:02 fetchmail: IMAP< A0007 OK FETCH completed.
Feb 19 18:00:02 fetchmail: SMTP>. (EOM)
fetchmail: smtp listener protocol error
Feb 19 18:00:32 fetchmail:  not flushed
Feb 19 18:00:32 fetchmail: IMAP> A0008 LOGOUT
Feb 19 18:00:32 fetchmail: IMAP< * BYE Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 signing off.
Feb 19 18:00:32 fetchmail: IMAP< A0008 OK LOGOUT completed.
Feb 19 18:00:32 fetchmail: 6.2.5 querying sprg11.i.cz (protocol IMAP) at Mon Feb 19 18:00:32 2007: poll completed
Feb 19 18:00:32 fetchmail: sleeping at Mon Feb 19 18:00:32 2007


First term - break dd huge load (35MiB/s) to hdd
and fetchmail...


Feb 19 18:01:11 fetchmail: awakened by User defined signal 1
Feb 19 18:01:11 fetchmail: awakened at Mon Feb 19 18:01:11 2007
Feb 19 18:01:11 fetchmail: 6.2.5 querying sprg11.i.cz (protocol IMAP) at Mon Feb 19 18:01:11 2007: poll started
Feb 19 18:01:11 fetchmail: Issuer Organization: ICZ a.s.
Feb 19 18:01:11 fetchmail: Issuer CommonName: ICZ Private CA 2005
Feb 19 18:01:11 fetchmail: Server CommonName: sprg11.i.cz
Feb 19 18:01:11 fetchmail: sprg11.i.cz key fingerprint: 2C:B1:43:31:F8:E0:C4:D3:BE:52:10:AD:31:34:24:6A
Feb 19 18:01:11 fetchmail: IMAP< * OK Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 (sprg11.ad.i.cz) ready.
Feb 19 18:01:11 fetchmail: IMAP> A0001 CAPABILITY
Feb 19 18:01:11 fetchmail: IMAP< * CAPABILITY IMAP4 IMAP4rev1 IDLE LOGIN-REFERRALS MAILBOX-REFERRALS NAMESPACE LITERAL+ UIDPLUS CHILDREN
Feb 19 18:01:11 fetchmail: IMAP< A0001 OK CAPABILITY completed.
Feb 19 18:01:11 fetchmail: IMAP> A0002 LOGIN "zito" *
Feb 19 18:01:11 fetchmail: IMAP< A0002 OK LOGIN completed.
Feb 19 18:01:11 fetchmail: IMAP> A0003 SELECT "INBOX"
Feb 19 18:01:11 fetchmail: IMAP< * 1 EXISTS
Feb 19 18:01:11 fetchmail: IMAP< * 0 RECENT
Feb 19 18:01:11 fetchmail: IMAP< * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
Feb 19 18:01:11 fetchmail: IMAP< * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
Feb 19 18:01:11 fetchmail: IMAP< * OK [UNSEEN 1] Is the first unseen message
Feb 19 18:01:11 fetchmail: IMAP< * OK [UIDVALIDITY 1837] UIDVALIDITY value
Feb 19 18:01:11 fetchmail: IMAP< A0003 OK [READ-WRITE] SELECT completed.
Feb 19 18:01:11 fetchmail: IMAP> A0004 EXPUNGE
Feb 19 18:01:11 fetchmail: IMAP< * 1 EXISTS
Feb 19 18:01:11 fetchmail: IMAP< A0004 OK EXPUNGE completed.
Feb 19 18:01:11 fetchmail: 1 message for zito at sprg11.i.cz.
Feb 19 18:01:11 fetchmail: IMAP> A0005 FETCH 1 RFC822.SIZE
Feb 19 18:01:11 fetchmail: IMAP< * 1 FETCH (RFC822.SIZE 1476)
Feb 19 18:01:11 fetchmail: IMAP< A0005 OK FETCH completed.
Feb 19 18:01:11 fetchmail: IMAP> A0006 FETCH 1 RFC822.HEADER
Feb 19 18:01:11 fetchmail: IMAP< * 1 FETCH (RFC822.HEADER {1451}
Feb 19 18:01:11 fetchmail: reading message zito at sprg11.i.cz:1 of 1 (1451 header octets)
Feb 19 18:01:11 fetchmail: SMTP< 220 bobek.pm.i.cz ESMTP Exim 4.50 Mon, 19 Feb 2007 18:01:11 +0100
Feb 19 18:01:11 fetchmail: SMTP> EHLO localhost
Feb 19 18:01:11 fetchmail: SMTP< 250-bobek.pm.i.cz Hello localhost [127.0.0.1]
Feb 19 18:01:11 fetchmail: SMTP< 250-SIZE 52428800
Feb 19 18:01:11 fetchmail: SMTP< 250-PIPELINING
Feb 19 18:01:11 fetchmail: SMTP< 250 HELP
Feb 19 18:01:11 fetchmail: SMTP> MAIL FROM:<vaclav.ovsik at i.cz> SIZE=1476
Feb 19 18:01:11 fetchmail: SMTP< 250 OK
Feb 19 18:01:11 fetchmail: SMTP> RCPT TO:<zito at localhost>
Feb 19 18:01:11 fetchmail: SMTP< 250 Accepted
Feb 19 18:01:11 fetchmail: SMTP> DATA
Feb 19 18:01:11 fetchmail: SMTP< 354 Enter message, ending with "." on a line by itself
Feb 19 18:01:11 #
Feb 19 18:01:11 fetchmail: IMAP< )
Feb 19 18:01:11 fetchmail: IMAP< A0006 OK FETCH completed.
Feb 19 18:01:11 fetchmail: IMAP> A0007 FETCH 1 BODY.PEEK[TEXT]
Feb 19 18:01:11 fetchmail: IMAP< * 1 FETCH (BODY[TEXT] {25}
Feb 19 18:01:11 fetchmail:  (25 body octets) *
Feb 19 18:01:11 fetchmail: IMAP< )
Feb 19 18:01:11 fetchmail: IMAP< A0007 OK FETCH completed.
Feb 19 18:01:11 fetchmail: SMTP>. (EOM)
Feb 19 18:01:11 fetchmail: SMTP< 250 OK id=1HJBt1-0000U6-K4
Feb 19 18:01:11 fetchmail:  flushed
Feb 19 18:01:11 fetchmail: IMAP> A0008 STORE 1 +FLAGS (\Seen \Deleted)
Feb 19 18:01:11 fetchmail: IMAP< * 1 FETCH (FLAGS (\Seen \Deleted))
Feb 19 18:01:11 fetchmail: IMAP< A0008 OK STORE completed.
Feb 19 18:01:11 fetchmail: IMAP> A0009 EXPUNGE
Feb 19 18:01:12 fetchmail: IMAP< * 1 EXPUNGE
Feb 19 18:01:12 fetchmail: IMAP< * 0 EXISTS
Feb 19 18:01:12 fetchmail: IMAP< A0009 OK EXPUNGE completed.
Feb 19 18:01:12 fetchmail: IMAP> A0010 LOGOUT
Feb 19 18:01:12 fetchmail: IMAP< * BYE Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 signing off.
Feb 19 18:01:12 fetchmail: IMAP< A0010 OK LOGOUT completed.
Feb 19 18:01:12 fetchmail: 6.2.5 querying sprg11.i.cz (protocol IMAP) at Mon Feb 19 18:01:12 2007: poll completed
Feb 19 18:01:12 fetchmail: SMTP> QUIT
Feb 19 18:01:12 fetchmail: SMTP< 221 bobek.pm.i.cz closing connection
Feb 19 18:01:12 fetchmail: sleeping at Mon Feb 19 18:01:12 2007


Now I have two messages in INBOX...
-- 
Zito