The Saturday 2004-12-11 at 01:40 +0100, Theo v. Werkhoven wrote:
The logs would be a good place to start. Postfix doesn't just stop for the heck of it.
Mine does... has been doing so for months, since I updated to suse 9.1.
Dec 10 12:43:15 nimrodel fetchmail[6645]: 65 messages for * at pop.tiscali.es (339598 octets).
Dec 10 12:43:15 nimrodel fetchmail[6645]: POP3> LIST 1
Dec 10 12:43:15 nimrodel fetchmail[6645]: POP3< +OK 1 2766
Dec 10 12:43:15 nimrodel fetchmail[6645]: POP3> RETR 1
Dec 10 12:43:15 nimrodel fetchmail[6645]: POP3< +OK 2766 bytes
Dec 10 12:43:15 nimrodel fetchmail[6645]: reading message *@pop.tiscali.es:1 of 65 (2766 octets)
Dec 10 12:43:31 nimrodel ip-up.local.doit: -> FidoNet polled.
Dec 10 12:43:55 nimrodel ip-up.local.doit: -> FidoNet tossed and linked
Dec 10 12:44:25 nimrodel fetchmail[6645]: smtp listener protocol error
Dec 10 12:45:35 nimrodel fetchmail[6645]: smtp listener protocol error
Dec 10 12:45:35 nimrodel fetchmail[6645]: SMTP connect to localhost failed
Notice that fetchmail gives up after 70 seconds trying to connect to
postfix locally. Also, if I happen to try sending an email from Pine at
that exact moment, it also times out. When I notice this, I restart
postfix (I'm using a modem, so I'm normally looking). If I don't notice,
the next round of fetchmail works.
Previous to this timeout, mails seem to work. This usually happen on the
very first email I fetch from tiscali (and not from the two other servers
I fetch before tiscali) on the first fetchmail run after my first
connection of the day - but sometimes also happens later on the day.
Another one, previous day. I'll copy much more details from the logs. You
see that there is a send that works;
Dec 10 00:57:51 nimrodel fetchmail[13587]: POP3< +OK 57 messages
Dec 10 00:57:52 nimrodel postfix/smtp[13590]: connect to *.com[*.*.*.65]: server dropped connection without sending the initial SMTP greeting (port 25)
Dec 10 00:57:53 nimrodel postfix/smtp[13590]: 0E5BE20C3D: to=<*@*.*.com>, relay=gandalf.*.com[*.*.*.243], delay=12989, status=sent (250 Ok: queued as 608566787D)
And a minute before, not shown, fetchmail gets email from several other
servers, sucessfully. But a few seconds later, that same first fetchmail
run for this connection of server tiscali, fails:
Dec 10 00:57:53 nimrodel postfix/qmgr[5362]: 0E5BE20C3D: removed
Dec 10 00:57:54 nimrodel fetchmail[13587]: POP3> STAT
Dec 10 00:57:54 nimrodel fetchmail[13587]: POP3< +OK 57 177537
Dec 10 00:57:54 nimrodel fetchmail[13587]: 57 messages for * at pop.tiscali.es (177537 octets).
Dec 10 00:57:54 nimrodel fetchmail[13587]: POP3> LIST 1
Dec 10 00:57:54 nimrodel fetchmail[13587]: POP3< +OK 1 2460
Dec 10 00:57:54 nimrodel fetchmail[13587]: POP3> RETR 1
Dec 10 00:57:55 nimrodel fetchmail[13587]: POP3< +OK 2460 bytes
Dec 10 00:57:55 nimrodel fetchmail[13587]: reading message *@pop.tiscali.es:1 of 57 (2460 octets)
Dec 10 00:58:30 nimrodel ip-up.local.doit: -> FidoNet polled.
Dec 10 00:58:39 nimrodel ip-up.local.doit: -> FidoNet tossed and linked
Dec 10 00:59:05 nimrodel fetchmail[13587]: smtp listener protocol error
70 seconds timeout of fetchmail (70 seconds is my seting, because at 85"
I have the pppd daemon drop the connection).
Dec 10 00:59:25 nimrodel amavis[4748]: (04748-04-3) Requesting a process rundown after 10 tasks
Dec 10 01:00:15 nimrodel fetchmail[13587]: smtp listener protocol error
Dec 10 01:00:15 nimrodel fetchmail[13587]: SMTP connect to localhost failed
Connection to local smtp fails, and fetchmail aborts this server.
Dec 10 01:00:15 nimrodel fetchmail[13587]: POP3> QUIT
Dec 10 01:00:15 nimrodel fetchmail[13587]: POP3< * Laurent Renard <*@*.be> [12-09-04 14:37]:
Dec 10 01:00:15 nimrodel fetchmail[13587]: SMTP transaction error while fetching from pop.tiscali.es
Fetchmail complains.
Dec 10 01:00:15 nimrodel fetchmail[13587]: 6.2.5 querying pop.tiscali.es (protocol POP3) at Fri Dec 10 01:00:15 2004: poll completed
Dec 10 01:00:15 nimrodel fetchmail[13587]: Query status=10 (SMTP)
A bit later, after polling some more servers (empty), I see:
Dec 10 01:00:25 nimrodel fetchmail[13587]: No mail for *@* at *susemania.org
...
Dec 10 01:00:26 nimrodel fetchmail[13587]: 6.2.5 querying *susemania.org (protocol IMAP) at Fri Dec 10 01:00:26 2004:
Dec 10 01:00:26 nimrodel fetchmail[13587]: SMTP> QUIT
Dec 10 01:00:26 nimrodel postfix/smtpd[13606]: disconnect from localhost[127.0.0.1]
Dec 10 01:00:26 nimrodel fetchmail[13587]: SMTP< 221 Bye
Dec 10 01:00:26 nimrodel fetchmail[13587]: SMTP> QUIT
Dec 10 01:00:26 nimrodel postfix/smtpd[13606]: connect from localhost[127.0.0.1]
Dec 10 01:00:26 nimrodel postfix/smtpd[13606]: lost connection after CONNECT from localhost[127.0.0.1]
Dec 10 01:00:26 nimrodel postfix/smtpd[13606]: disconnect from localhost[127.0.0.1]
Dec 10 01:00:26 nimrodel postfix/smtpd[13606]: connect from localhost[127.0.0.1]
Dec 10 01:00:26 nimrodel postfix/smtpd[13606]: lost connection after CONNECT from localhost[127.0.0.1]
Dec 10 01:00:26 nimrodel postfix/smtpd[13606]: disconnect from localhost[127.0.0.1]
Dec 10 01:00:26 nimrodel postfix/smtpd[13617]: disconnect from localhost[127.0.0.1]
I don't know what are these connections that postfix is dropping here. PID
13606 was used previously for the first email fetched from the first
server of this run, sucessfully, it seems. PID 13617 was used by the
second. Could these two connections be pending for about 2'30" and hog
postfix? I wonder, because around 8 emails were sucessfully downloaded
after those two, and before it stops at tiscali - it only happens at the
first email of tiscali, on the first run of the connection, and not every
connection.
Dec 10 01:00:26 nimrodel fetchmail[13587]: SMTP< 221 Bye
Dec 10 01:00:26 nimrodel fetchmail[13587]: normal termination, status 0
Dec 10 01:00:26 nimrodel ip-up.local.doit: -> Mail fetched - second poll in 30"
and now it works - without me resetting postfix this time:
Dec 10 01:01:34 nimrodel fetchmail[13695]: 58 messages for * at pop.tiscali.es (180498 octets).
Dec 10 01:01:34 nimrodel fetchmail[13695]: POP3> LIST 1
Dec 10 01:01:34 nimrodel fetchmail[13695]: POP3< +OK 1 2460
Dec 10 01:01:34 nimrodel fetchmail[13695]: POP3> RETR 1
Dec 10 01:01:34 nimrodel fetchmail[13695]: POP3< +OK 2460 bytes
Dec 10 01:01:34 nimrodel fetchmail[13695]: reading message *@pop.tiscali.es:1 of 58 (2460 octets)
Dec 10 01:01:34 nimrodel postfix/smtpd[13606]: connect from localhost[127.0.0.1]
Dec 10 01:01:34 nimrodel fetchmail[13695]: SMTP< 220 nimrodel.valinor ESMTP Postfix
Dec 10 01:01:34 nimrodel fetchmail[13695]: SMTP> EHLO localhost
Dec 10 01:01:34 nimrodel fetchmail[13695]: SMTP< 250-nimrodel.valinor
Dec 10 01:01:34 nimrodel fetchmail[13695]: SMTP< 250-PIPELINING
Dec 10 01:01:34 nimrodel fetchmail[13695]: SMTP< 250-SIZE 10240000
Dec 10 01:01:34 nimrodel fetchmail[13695]: SMTP< 250-VRFY
Dec 10 01:01:34 nimrodel fetchmail[13695]: SMTP< 250-ETRN
Dec 10 01:01:34 nimrodel fetchmail[13695]: SMTP< 250 8BITMIME
Dec 10 01:01:34 nimrodel fetchmail[13695]: SMTP> MAIL FROM: