[fetchmail-users] fetchmail daemon problem

[Martin S. <mar...@in...>]

Hello,

I'm running fetchmail 6.2.5 version of fetchmail from Debian Etch 
package. I noticed that the daemon fails retrieving IMAP mails after a 
certain time. I launch fetchmail as daemon with the init.d script 
provided by debian. To analyse the problem, I added -v option, and here 
is the full log illustrating the problem. It is quite long but quite 
clear too.

I'm running Exim 4, procmail, courier imap. 3 polls are configures, 
POP3, IMAP4 + SSL, IMAP4

here everything's ok (it is ok for hours, sometimes 1-2 days):

Aug 30 00:51:49 localhost fetchmail[2498]: awakened at Tue Aug 30 
00:51:49 2005
Aug 30 00:51:49 localhost fetchmail[2498]: 6.2.5 querying pop3.evhr.net 
(protocol POP3) at Tue Aug 30 00:51:49 2005: poll started
Aug 30 00:51:49 localhost imaplogin: LOGOUT, user=martin, 
ip=[::ffff:62.129.161.22], headers=0, body=0, time=0
Aug 30 00:51:49 localhost last message repeated 2 times
Aug 30 00:51:49 localhost fetchmail[2498]: POP3< +OK POP3 Ready 
pop.evc.net 0001d8f1
Aug 30 00:51:49 localhost fetchmail[2498]: POP3> CAPA
Aug 30 00:51:49 localhost fetchmail[2498]: POP3< +OK Capability list 
follows, mate
Aug 30 00:51:49 localhost fetchmail[2498]: POP3< UIDL
Aug 30 00:51:49 localhost fetchmail[2498]: POP3< USER
Aug 30 00:51:49 localhost fetchmail[2498]: POP3< .
Aug 30 00:51:49 localhost fetchmail[2498]: POP3> USER evhr_mart
Aug 30 00:51:49 localhost fetchmail[2498]: POP3< +OK USER evhr_mart set, 
mate
Aug 30 00:51:49 localhost fetchmail[2498]: POP3> PASS *
Aug 30 00:51:49 localhost fetchmail[2498]: POP3< +OK You are so in
Aug 30 00:51:52 localhost fetchmail[2498]: POP3> STAT
Aug 30 00:51:52 localhost fetchmail[2498]: POP3< +OK 0 0
Aug 30 00:51:52 localhost fetchmail[2498]: No mail for evhr_mart at 
pop3.evhr.net
Aug 30 00:51:52 localhost fetchmail[2498]: POP3> QUIT
Aug 30 00:51:52 localhost fetchmail[2498]: POP3< +OK Done
Aug 30 00:51:52 localhost fetchmail[2498]: 6.2.5 querying pop3.evhr.net 
(protocol POP3) at Tue Aug 30 00:51:52 2005: poll completed
Aug 30 00:51:52 localhost fetchmail[2498]: 6.2.5 querying 
imap4.orange.fr (protocol IMAP) at Tue Aug 30 00:51:52 2005: poll started
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< * OK IMAP4 server ready 
(6.7.015)
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP> A0001 CAPABILITY
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< * CAPABILITY IMAP4rev1 
UIDPLUS IDLE LOGIN-REFERRALS NAMESPACE QUOTA CHILDREN AUTH=CRAM-MD5 
AUTH=DIGEST-MD5 AUTH=PLAIN
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< A0001 OK capabilities 
listed
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP> A0002 AUTHENTICATE 
CRAM-MD5
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< + 
PEExM0JBNTNGRjVBRkNGNUFFMkQwRjE4ODE3NDY3QzkxRkVCOENCMjFAcG9wMS5vcmFuZ2UuZnI+ 

Aug 30 00:51:52 localhost fetchmail[2498]: IMAP> 
bWFydC5zY2ggYjE0OTc1OTU2MGI4MzIwMmEwY2FmZmU1NWExZWVjNGY=
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< A0002 OK login successful
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP> A0003 SELECT "INBOX"
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< * 1 EXISTS
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< * 0 RECENT
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< * FLAGS (\Answered 
\Flagged \Deleted \Seen \Draft $MDNSent)
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< * OK [PERMANENTFLAGS 
(\Answered \Flagged \Deleted \Seen \Draft $MDNSent)] flags can be changed
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< * OK [UIDVALIDITY 
1055529069] mailbox UID validity
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< * OK [UIDNEXT 5194] 
predicted next UID
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< A0003 OK [READ-WRITE] 
SELECT complete
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP> A0004 EXPUNGE
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< A0004 OK EXPUNGE complete
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP> A0005 SEARCH UNSEEN NOT 
DELETED
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< * SEARCH
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< A0005 OK SEARCH complete
Aug 30 00:51:52 localhost fetchmail[2498]: 1 message (1 seen) for 
mart.sch at imap4.orange.fr.
Aug 30 00:51:52 localhost fetchmail[2498]: skipping message 
mar...@im...:1 not flushed
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP> A0006 LOGOUT
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< * BYE disconnecting
Aug 30 00:51:52 localhost fetchmail[2498]: IMAP< A0006 OK LOGOUT complete
Aug 30 00:51:52 localhost fetchmail[2498]: 6.2.5 querying 
imap4.orange.fr (protocol IMAP) at Tue Aug 30 00:51:52 2005: poll completed
Aug 30 00:51:52 localhost fetchmail[2498]: 6.2.5 querying 
mail.insa-lyon.fr (protocol IMAP) at Tue Aug 30 00:51:52 2005: poll started
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< * OK 
csiges9.insa-lyon.fr Cyrus IMAP4 v2.2.12-INSA-LYON server ready
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP> A0001 CAPABILITY
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< * CAPABILITY IMAP4 
IMAP4rev1 ACL QUOTA LITERAL+ MAILBOX-REFERRALS NAMESPACE UIDPLUS ID 
NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY SORT 
THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE IDLE STARTTLS 
LISTEXT LIST-SUBSCRIBED X-NETSCAPE
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< A0001 OK Completed
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP> A0002 STARTTLS
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< A0002 OK Begin TLS 
negotiation now
Aug 30 00:51:53 localhost fetchmail[2498]: Issuer Organization: INSA Lyon
Aug 30 00:51:53 localhost fetchmail[2498]: Issuer CommonName: 
mail.insa-lyon.fr
Aug 30 00:51:53 localhost fetchmail[2498]: Server CommonName: 
mail.insa-lyon.fr
Aug 30 00:51:53 localhost fetchmail[2498]: mail.insa-lyon.fr key 
fingerprint: 31:D9:BD:88:82:75:B4:92:62:0E:BB:CC:97:7C:2D:3B
Aug 30 00:51:53 localhost fetchmail[2498]: Warning: server certificate 
verification: self signed certificate
Aug 30 00:51:53 localhost fetchmail[2498]: Issuer Organization: INSA Lyon
Aug 30 00:51:53 localhost fetchmail[2498]: Issuer CommonName: 
mail.insa-lyon.fr
Aug 30 00:51:53 localhost fetchmail[2498]: Server CommonName: 
mail.insa-lyon.fr
Aug 30 00:51:53 localhost fetchmail[2498]: Warning: server certificate 
verification: self signed certificate
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP> A0003 CAPABILITY
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< * CAPABILITY IMAP4 
IMAP4rev1 ACL QUOTA LITERAL+ MAILBOX-REFERRALS NAMESPACE UIDPLUS ID 
NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY SORT 
THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE IDLE AUTH=PLAIN 
SASL-IR LISTEXT LIST-SUBSCRIBED X-NETSCAPE
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< A0003 OK Completed
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP> A0004 LOGIN 
"mschlienger" *
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< A0004 OK User logged in
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP> A0005 SELECT "INBOX"
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< * FLAGS (\Answered 
\Flagged \Draft \Deleted \Seen)
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< * OK [PERMANENTFLAGS 
(\Answered \Flagged \Draft \Deleted \Seen \*)]
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< * 0 EXISTS
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< * 0 RECENT
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< * OK [UIDVALIDITY 
1094806947]
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< * OK [UIDNEXT 1215]
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< A0005 OK [READ-WRITE] 
Completed
Aug 30 00:51:53 localhost fetchmail[2498]: No mail for mschlienger at 
mail.insa-lyon.fr
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP> A0006 LOGOUT
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< * BYE LOGOUT received
Aug 30 00:51:53 localhost fetchmail[2498]: IMAP< A0006 OK Completed
Aug 30 00:51:53 localhost fetchmail[2498]: 6.2.5 querying 
mail.insa-lyon.fr (protocol IMAP) at Tue Aug 30 00:51:53 2005: poll 
completed
Aug 30 00:51:53 localhost fetchmail[2498]: sleeping at Tue Aug 30 
00:51:53 2005

This check  was successful.

5 minutes later...


Aug 30 00:56:53 localhost fetchmail[2498]: awakened at Tue Aug 30 
00:56:53 2005
Aug 30 00:56:53 localhost fetchmail[2498]: 6.2.5 querying pop3.evhr.net 
(protocol POP3) at Tue Aug 30 00:56:53 2005: poll started
Aug 30 00:56:53 localhost fetchmail[2498]: POP3< +OK POP3 Ready 
pop.evc.net 0001d8f1
Aug 30 00:56:53 localhost fetchmail[2498]: POP3> CAPA
Aug 30 00:56:53 localhost fetchmail[2498]: POP3< +OK Capability list 
follows, mate
Aug 30 00:56:53 localhost fetchmail[2498]: POP3< UIDL
Aug 30 00:56:53 localhost fetchmail[2498]: POP3< USER
Aug 30 00:56:53 localhost fetchmail[2498]: POP3< .
Aug 30 00:56:53 localhost fetchmail[2498]: POP3> USER evhr_mart
Aug 30 00:56:53 localhost fetchmail[2498]: POP3< +OK USER evhr_mart set, 
mate
Aug 30 00:56:53 localhost fetchmail[2498]: POP3> PASS *
Aug 30 00:56:53 localhost fetchmail[2498]: POP3< +OK You are so in
Aug 30 00:56:56 localhost fetchmail[2498]: POP3> STAT
Aug 30 00:56:56 localhost fetchmail[2498]: POP3< +OK 0 0
Aug 30 00:56:56 localhost fetchmail[2498]: No mail for evhr_mart at 
pop3.evhr.net
Aug 30 00:56:56 localhost fetchmail[2498]: POP3> QUIT
Aug 30 00:56:56 localhost fetchmail[2498]: POP3< +OK Done
Aug 30 00:56:56 localhost fetchmail[2498]: 6.2.5 querying pop3.evhr.net 
(protocol POP3) at Tue Aug 30 00:56:56 2005: poll completed
Aug 30 00:56:56 localhost fetchmail[2498]: 6.2.5 querying 
imap4.orange.fr (protocol IMAP) at Tue Aug 30 00:56:56 2005: poll started
Aug 30 00:56:56 localhost fetchmail[2498]: IMAP< * OK IMAP4 server ready 
(6.7.015)
Aug 30 00:56:56 localhost fetchmail[2498]: IMAP> A0001 CAPABILITY
Aug 30 00:56:56 localhost fetchmail[2498]: IMAP< * CAPABILITY IMAP4rev1 
UIDPLUS IDLE LOGIN-REFERRALS NAMESPACE QUOTA CHILDREN AUTH=CRAM-MD5 
AUTH=DIGEST-MD5 AUTH=PLAIN
Aug 30 00:56:56 localhost fetchmail[2498]: IMAP< A0001 OK capabilities 
listed
Aug 30 00:56:56 localhost fetchmail[2498]: IMAP> A0002 AUTHENTICATE 
CRAM-MD5
Aug 30 00:56:56 localhost fetchmail[2498]: IMAP< + 
PEZCRjkyMEExNDlFQzlBRTEwRjU4MzY0RjY0ODE0RENFOUY0RDFFMzhAcG9wMS5vcmFuZ2UuZnI+ 

Aug 30 00:56:56 localhost fetchmail[2498]: IMAP> 
bWFydC5zY2ggNGE5MzA2NDNhZWEzZjA1ZTJhY2Y3OWVjODE3NWZkNGQ=

Here comes a timeout on one IMAP Server. Then every IMAP check doesn't 
work on both server.

Aug 30 01:01:56 localhost fetchmail[2498]: timeout after 300 seconds 
waiting for server imap4.orange.fr.
Aug 30 01:01:56 localhost fetchmail[2498]: socket error while fetching 
from imap4.orange.fr
Aug 30 01:01:56 localhost fetchmail[2498]: 6.2.5 querying 
imap4.orange.fr (protocol IMAP) at Tue Aug 30 01:01:56 2005: poll completed
Aug 30 01:01:56 localhost fetchmail[2498]: Query status=2 (SOCKET)

Failure on next IMAP Server.

Aug 30 01:01:56 localhost fetchmail[2498]: 6.2.5 querying 
mail.insa-lyon.fr (protocol IMAP) at Tue Aug 30 01:01:56 2005: poll started
Aug 30 01:01:56 localhost fetchmail[2498]: IMAP< * OK 
csiges9.insa-lyon.fr Cyrus IMAP4 v2.2.12-INSA-LYON server ready
Aug 30 01:01:56 localhost fetchmail[2498]: IMAP> CAPABILITY
Aug 30 01:01:56 localhost fetchmail[2498]: IMAP< * BAD Invalid tag
Aug 30 01:01:56 localhost fetchmail[2498]: IMAP> LOGIN "mschlienger" *
Aug 30 01:01:56 localhost fetchmail[2498]: IMAP< LOGIN BAD Null command
Aug 30 01:01:56 localhost fetchmail[2498]: IMAP> SELECT "INBOX"
Aug 30 01:01:56 localhost fetchmail[2498]: IMAP< SELECT BAD Null command
Aug 30 01:01:56 localhost fetchmail[2498]: No mail for mschlienger at 
mail.insa-lyon.fr
Aug 30 01:01:56 localhost fetchmail[2498]: IMAP> LOGOUT
Aug 30 01:01:57 localhost fetchmail[2498]: IMAP< * BAD Invalid tag
Aug 30 01:01:57 localhost fetchmail[2498]: 6.2.5 querying 
mail.insa-lyon.fr (protocol IMAP) at Tue Aug 30 01:01:57 2005: poll 
completed
Aug 30 01:01:57 localhost fetchmail[2498]: sleeping at Tue Aug 30 
01:01:57 2005

Next poll checks: every IMAP fails indefinitely...


Aug 30 01:06:57 localhost fetchmail[2498]: awakened at Tue Aug 30 
01:06:57 2005
Aug 30 01:06:57 localhost fetchmail[2498]: 6.2.5 querying pop3.evhr.net 
(protocol POP3) at Tue Aug 30 01:06:57 2005: poll started
Aug 30 01:06:57 localhost fetchmail[2498]: POP3< +OK POP3 Ready 
pop.evc.net 0001d8f1
Aug 30 01:06:57 localhost fetchmail[2498]: POP3> CAPA
Aug 30 01:06:57 localhost fetchmail[2498]: POP3< +OK Capability list 
follows, mate
Aug 30 01:06:57 localhost fetchmail[2498]: POP3< UIDL
Aug 30 01:06:57 localhost fetchmail[2498]: POP3< USER
Aug 30 01:06:57 localhost fetchmail[2498]: POP3< .
Aug 30 01:06:57 localhost fetchmail[2498]: POP3> USER evhr_mart
Aug 30 01:06:57 localhost fetchmail[2498]: POP3< +OK USER evhr_mart set, 
mate
Aug 30 01:06:57 localhost fetchmail[2498]: POP3> PASS *
Aug 30 01:06:57 localhost fetchmail[2498]: POP3< +OK You are so in
Aug 30 01:07:00 localhost fetchmail[2498]: POP3> STAT
Aug 30 01:07:00 localhost fetchmail[2498]: POP3< +OK 0 0
Aug 30 01:07:00 localhost fetchmail[2498]: No mail for evhr_mart at 
pop3.evhr.net
Aug 30 01:07:00 localhost fetchmail[2498]: POP3> QUIT
Aug 30 01:07:00 localhost fetchmail[2498]: POP3< +OK Done
Aug 30 01:07:00 localhost fetchmail[2498]: 6.2.5 querying pop3.evhr.net 
(protocol POP3) at Tue Aug 30 01:07:00 2005: poll completed
Aug 30 01:07:00 localhost fetchmail[2498]: 6.2.5 querying 
imap4.orange.fr (protocol IMAP) at Tue Aug 30 01:07:00 2005: poll started
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP< * OK IMAP4 server ready 
(6.7.015)
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP> CAPABILITY
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP< CAPABILITY BAD no space 
between tag and command
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP> LOGIN "mart.sch" *
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP< LOGIN BAD unrecognized 
IMAP4 command
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP> SELECT "INBOX"
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP< SELECT BAD unrecognized 
IMAP4 command
Aug 30 01:07:00 localhost fetchmail[2498]: No mail for mart.sch at 
imap4.orange.fr
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP> LOGOUT
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP< LOGOUT BAD no space 
between tag and command
Aug 30 01:07:00 localhost fetchmail[2498]: 6.2.5 querying 
imap4.orange.fr (protocol IMAP) at Tue Aug 30 01:07:00 2005: poll completed
Aug 30 01:07:00 localhost fetchmail[2498]: 6.2.5 querying 
mail.insa-lyon.fr (protocol IMAP) at Tue Aug 30 01:07:00 2005: poll started
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP< * OK 
csiges9.insa-lyon.fr Cyrus IMAP4 v2.2.12-INSA-LYON server ready
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP> CAPABILITY
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP< * BAD Invalid tag
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP> LOGIN "mschlienger" *
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP< LOGIN BAD Null command
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP> SELECT "INBOX"
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP< SELECT BAD Null command
Aug 30 01:07:00 localhost fetchmail[2498]: No mail for mschlienger at 
mail.insa-lyon.fr
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP> LOGOUT
Aug 30 01:07:00 localhost fetchmail[2498]: IMAP< * BAD Invalid tag
Aug 30 01:07:00 localhost fetchmail[2498]: 6.2.5 querying 
mail.insa-lyon.fr (protocol IMAP) at Tue Aug 30 01:07:00 2005: poll 
completed
Aug 30 01:07:00 localhost fetchmail[2498]: sleeping at Tue Aug 30 
01:07:00 2005
                                                                                   


Thanks for any help!

regards,

martin.