[fetchmail-devel] Fwd: [BUG] fetchmail hangs during pop3 pull after a mail with a null char

[Rob F. <rf...@fu...>]

This seems appropriate for fetchmail-devel.....

----------  Forwarded Message  ----------
Subject: [fetchmail][BUG] fetchmail hangs during pop3 pull after a mail 
with a null char
Date: Tuesday 17 August 2004 4:03 pm
From: David Greaves <da...@dg...>
To: fet...@li...

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

First : fetchmail is great - thanks :)

It's been working for years with these occasional hangs that have been
fixed by popping the bad messages and manually filing them. I finally
had a bad message arrive when I was in a position to debug!

Summary : fetchmail hangs during pop3 pull after a mail with a null char.

The mail with a null char is pulled OK but then rejected by local
Cyrus lmtp and bounced to postmaster via exim4.20
The next pop3 pull then fails.
I've made an effort to trace and I think the hang occurs due to a
double call to SMTP_ok which is empty the second time. I am pretty
sure the second call originates at sink.c line 1433.

in the config expunge 1 fixes the problem (which makes sense)

general config is pop3->lmtp->local Cyrus IMAP

FAQ G3:
1. OS: Linux RedHat 7.3 kernel 2.6.6
2. gcc version 2.96 20000731 (Red Hat Linux 7.3 2.96-110)
3. below
4. forwarding to lmtp listener on cyrus 2.2.3 (bounce goes to SMTP
exim 4.2)
5. -v -v -f /etc/fetchmailrc
6. at the end

nb: SMTP_ok loop start comments are my trace.

Aug 17 17:33:01 willow fetchmail[13648]: 6.2.5 querying pop3.ukfsn.org
(protocol POP3) at Tue 17 Aug 2004 05:33:01 PM BST: poll started
Aug 17 17:33:01 willow fetchmail[13648]: POP3< +OK
<aa5...@po...>
Aug 17 17:33:01 willow fetchmail[13648]: POP3> CAPA^M
Aug 17 17:33:01 willow fetchmail[13648]: POP3< +OK Capability list follows
Aug 17 17:33:01 willow fetchmail[13648]: POP3< PIPELINING
Aug 17 17:33:01 willow fetchmail[13648]: POP3< TOP
Aug 17 17:33:01 willow fetchmail[13648]: POP3< USER
Aug 17 17:33:01 willow fetchmail[13648]: POP3< UIDL
Aug 17 17:33:01 willow fetchmail[13648]: POP3< STLS
Aug 17 17:33:01 willow fetchmail[13648]: POP3< .
Aug 17 17:33:01 willow fetchmail[13648]: POP3> USER dgreaves^M
Aug 17 17:33:01 willow fetchmail[13648]: POP3< +OK Tell me your password.
Aug 17 17:33:01 willow fetchmail[13648]: POP3> PASS *^M
Aug 17 17:33:02 willow fetchmail[13648]: POP3< +OK Welcome aboard! You
have 55 messages.
Aug 17 17:33:05 willow fetchmail[13648]: POP3> STAT
Aug 17 17:33:05 willow fetchmail[13648]: POP3< +OK 55 429607
Aug 17 17:33:05 willow fetchmail[13648]: 55 messages for dgreaves at
pop3.ukfsn.org (429607 octets).



fetchmailrc:
set syslog
set postmaster "da...@dg..."
set nobouncemail
set properties ""
#set daemon 180
set idfile /var/run/fetchmail.ids

# The ukfsn accounts
poll pop3.ukfsn.org with proto POP3 tracepolls
~    user 'dgreaves' there with password 'xxxxxxx' is
da...@dg... here options fetchall lmtp smtp
/var/imap/socket/lmtp expunge 5
~    antispam 571 550 501 554

<more user accounts removed>

here is output from
~  ./fetchmail -v -v -f /etc/fetchmailrc

Aug 17 17:43:33 willow fetchmail[13675]: 6.2.5 querying pop3.ukfsn.org
(protocol POP3) at Tue 17 Aug 2004 05:43:33 PM BST: poll started
Aug 17 17:43:33 willow fetchmail[13675]: POP3< +OK
<40b...@po...>
Aug 17 17:43:33 willow fetchmail[13675]: POP3> CAPA^M
Aug 17 17:43:33 willow fetchmail[13675]: POP3< +OK Capability list follows
Aug 17 17:43:34 willow fetchmail[13675]: POP3< PIPELINING
Aug 17 17:43:34 willow fetchmail[13675]: POP3< TOP
Aug 17 17:43:34 willow fetchmail[13675]: POP3< USER
Aug 17 17:43:34 willow fetchmail[13675]: POP3< UIDL
Aug 17 17:43:34 willow fetchmail[13675]: POP3< STLS
Aug 17 17:43:34 willow fetchmail[13675]: POP3< .
Aug 17 17:43:34 willow fetchmail[13675]: POP3> USER dgreaves^M
Aug 17 17:43:34 willow fetchmail[13675]: POP3< +OK Tell me your password.
Aug 17 17:43:34 willow fetchmail[13675]: POP3> PASS *^M
Aug 17 17:43:34 willow fetchmail[13675]: POP3< +OK Welcome aboard! You
have 33 messages.
Aug 17 17:43:37 willow fetchmail[13675]: selecting or re-polling
default folder
Aug 17 17:43:37 willow fetchmail[13675]: POP3> STAT
Aug 17 17:43:37 willow fetchmail[13675]: POP3< +OK 33 186252
Aug 17 17:43:37 willow fetchmail[13675]: 33 messages for dgreaves at
pop3.ukfsn.org (186252 octets).
Aug 17 17:43:37 willow fetchmail[13675]: POP3> LIST 1
#**********************************************Aug 17 17:43:37 willow
fetchmail[13675]: POP3< +OK 1 9060
Aug 17 17:43:37 willow fetchmail[13675]: POP3> RETR 1
Aug 17 17:43:37 willow fetchmail[13675]: POP3< +OK Message follows
Aug 17 17:43:37 willow fetchmail[13675]: reading message
dgr...@po...:1 of 33 (9060 octets)
Aug 17 17:43:37 willow fetchmail[13675]: About to rewrite Return-Path:
<linux-kernel-owner+lkml=40d...@vg...>^M
Rewritten version is Return-Path:
<linux-kernel-owner+lkml=40d...@vg...>^M
Aug 17 17:43:38 willow fetchmail[13675]: About to rewrite From:
"O.Sezer" <se...@tt...>^M Rewritten version is From:
"O.Sezer" <se...@tt...>^M
Aug 17 17:43:38 willow fetchmail[13675]: About to rewrite To:
lin...@vg...^M Rewritten version is To:
lin...@vg...^M
Aug 17 17:43:38 willow fetchmail[13675]: About to rewrite Cc:
mar...@cy...^M Rewritten version is Cc:
mar...@cy...^M
Aug 17 17:43:38 willow fetchmail[13675]: About to rewrite Sender:
lin...@vg...^M Rewritten version is Sender:
lin...@vg...^M
Aug 17 17:43:38 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:38 willow fetchmail[13675]: LMTP< 220 willow LMTP Cyrus
v2.2.3 ready
Aug 17 17:43:38 willow fetchmail[13675]: LMTP> LHLO localhost
Aug 17 17:43:38 willow fetchmail[13675]: SMTP< 250-willow
Aug 17 17:43:38 willow fetchmail[13675]: SMTP< 250-8BITMIME
Aug 17 17:43:38 willow fetchmail[13675]: SMTP< 250-ENHANCEDSTATUSCODES
Aug 17 17:43:38 willow fetchmail[13675]: SMTP< 250-PIPELINING
Aug 17 17:43:38 willow fetchmail[13675]: SMTP< 250-SIZE
Aug 17 17:43:38 willow fetchmail[13675]: SMTP< 250-AUTH EXTERNAL
Aug 17 17:43:38 willow fetchmail[13675]: SMTP< 250 IGNOREQUOTA
Aug 17 17:43:38 willow fetchmail[13675]: forwarding to
/var/imap/socket/lmtp
Aug 17 17:43:38 willow fetchmail[13675]: LMTP> MAIL
FROM:<linux-kernel-owner+lkml=40d...@vg...rnel.o
rg> SIZE=9060
Aug 17 17:43:38 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:38 willow fetchmail[13675]: LMTP< 250 2.1.0 ok
Aug 17 17:43:38 willow fetchmail[13675]: LMTP> RCPT
TO:<da...@dg...>
Aug 17 17:43:38 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:38 willow fetchmail[13675]: LMTP< 250 2.1.5 ok
Aug 17 17:43:38 willow fetchmail[13675]: LMTP> DATA
Aug 17 17:43:38 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:38 willow fetchmail[13675]: LMTP< 354 go ahead
**************************************************************************
**************************************************************************
****************Aug 17 17:43:38 willow fetchmail[13675]: message
 dgr...@po...:1 was not the expected length (9317 actual !=
 9060 expected)
Aug 17 17:43:38 willow fetchmail[13675]: LMTP>. (EOM)
Aug 17 17:43:38 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:38 willow fetchmail[13675]: LMTP< 250 2.1.5 Ok
Aug 17 17:43:38 willow fetchmail[13675]:  flushed
Aug 17 17:43:38 willow fetchmail[13675]: POP3> DELE 1^M
Aug 17 17:43:38 willow fetchmail[13675]: POP3< +OK Done.
Aug 17 17:43:38 willow fetchmail[13675]: POP3> LIST 2
Aug 17 17:43:38 willow fetchmail[13675]: POP3< +OK 2 5098
Aug 17 17:43:38 willow fetchmail[13675]: POP3> RETR 2
Aug 17 17:43:39 willow fetchmail[13675]: POP3< +OK Message follows
Aug 17 17:43:39 willow fetchmail[13675]: reading message
dgr...@po...:2 of 33 (5098 octets)
Aug 17 17:43:39 willow fetchmail[13675]: About to rewrite Return-Path:
<linux-kernel-owner+lkml=40d...@vg...>^M
Rewritten version is Return-Path:
<linux-kernel-owner+lkml=40d...@vg...>^M
#****************************************************************Aug
17 17:43:39 willow fetchmail[13675]: About to rewrite From: Christoph
Hellwig <hc...@in...>^M Rewritten version is From: Christoph
Hellwig <hc...@in...>^M
Aug 17 17:43:39 willow fetchmail[13675]: About to rewrite To: Markus
Lidel <Mar...@sh...>^M Rewritten version is To:
Markus Lidel <Mar...@sh...>^M
Aug 17 17:43:39 willow fetchmail[13675]: About to rewrite Cc:
Christoph Hellwig <hc...@in...>,^M ^IWarren Togami
<wt...@re...>, lin...@vg...^M Rewritten version
is Cc: Christoph Hellwig <hc...@in...>,^M ^IWarren Togami
<wt...@re...>, lin...@vg...^M
Aug 17 17:43:39 willow fetchmail[13675]: About to rewrite Sender:
lin...@vg...^M Rewritten version is Sender:
lin...@vg...^M
Aug 17 17:43:39 willow fetchmail[13675]: forwarding to
/var/imap/socket/lmtp
Aug 17 17:43:39 willow fetchmail[13675]: LMTP> MAIL
FROM:<linux-kernel-owner+lkml=40d...@vg...rnel.o
rg> SIZE=5098
Aug 17 17:43:39 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:39 willow fetchmail[13675]: LMTP< 250 2.1.0 ok
Aug 17 17:43:39 willow fetchmail[13675]: LMTP> RCPT
TO:<da...@dg...>
Aug 17 17:43:39 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:39 willow fetchmail[13675]: LMTP< 250 2.1.5 ok
Aug 17 17:43:39 willow fetchmail[13675]: LMTP> DATA
Aug 17 17:43:39 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:39 willow fetchmail[13675]: LMTP< 354 go ahead
Aug 17 17:43:39 willow fetchmail[13675]: message
dgr...@po...:2 was not the expected length (5209 actual !=
5098 expected)
Aug 17 17:43:39 willow fetchmail[13675]: LMTP>. (EOM)
Aug 17 17:43:39 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:39 willow fetchmail[13675]: LMTP< 250 2.1.5 Ok
Aug 17 17:43:39 willow fetchmail[13675]:  flushed
Aug 17 17:43:39 willow fetchmail[13675]: POP3> DELE 2^M
Aug 17 17:43:39 willow fetchmail[13675]: POP3< +OK Done.
Aug 17 17:43:39 willow fetchmail[13675]: POP3> LIST 3
Aug 17 17:43:39 willow fetchmail[13675]: POP3< +OK 3 2147
Aug 17 17:43:39 willow fetchmail[13675]: POP3> RETR 3
Aug 17 17:43:40 willow fetchmail[13675]: POP3< +OK Message follows
Aug 17 17:43:40 willow fetchmail[13675]: reading message
dgr...@po...:3 of 33 (2147 octets)
Aug 17 17:43:40 willow fetchmail[13675]: About to rewrite Return-Path:
<reiserfs-list-return-20355-david=dgr...@na...>^M
Rewritten version is Return-Path:
<reiserfs-list-return-20355-david=dgr...@na...>^M
#********#****************************Aug 17 17:43:40 willow
fetchmail[13675]: About to rewrite From: elliott
<aur...@se...>^M Rewritten version is From: elliott
<aur...@se...>^M
Aug 17 17:43:40 willow fetchmail[13675]: About to rewrite To:
rei...@na...^M Rewritten version is To:
rei...@na...^M
Aug 17 17:43:40 willow fetchmail[13675]: forwarding to
/var/imap/socket/lmtp
Aug 17 17:43:40 willow fetchmail[13675]: LMTP> MAIL
FROM:<reiserfs-list-return-20355-david=dgr...@na...>
BODY=8BITMIME SIZE=2147
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: LMTP< 250 2.1.0 ok
Aug 17 17:43:40 willow fetchmail[13675]: LMTP> RCPT
TO:<da...@dg...>
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: LMTP< 250 2.1.5 ok
Aug 17 17:43:40 willow fetchmail[13675]: LMTP> DATA
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: LMTP< 354 go ahead
Aug 17 17:43:40 willow fetchmail[13675]: message
dgr...@po...:3 was not the expected length (2194 actual !=
2147 expected)
Aug 17 17:43:40 willow fetchmail[13675]: LMTP>. (EOM)
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: LMTP< 554 5.6.0 Message
contains NUL characters
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: SMTP< 220 willow ESMTP Exim
4.20 Tue, 17 Aug 2004 17:43:40 +0100
Aug 17 17:43:40 willow fetchmail[13675]: SMTP> HELO localhost
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: SMTP< 250 willow Hello
[AdFSF0x5m0a0vDWoZf1oPXMI8ichzbi7] at localhost.localdomain [127.0.0.1]
Aug 17 17:43:40 willow fetchmail[13675]: SMTP> MAIL
FROM:<FET...@wi...>
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: SMTP< 250 OK
Aug 17 17:43:40 willow fetchmail[13675]: SMTP> RCPT
TO:<da...@dg...>
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: SMTP< 250 Accepted
Aug 17 17:43:40 willow fetchmail[13675]: SMTP> DATA
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: SMTP< 354 Enter message,
ending with "." on a line by itself
Aug 17 17:43:40 willow fetchmail[13675]: SMTP: (bounce-message body)
Aug 17 17:43:40 willow fetchmail[13675]: SMTP>. (EOM)
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: SMTP< 250 OK id=1Bx73k-0003Ya-FK
Aug 17 17:43:40 willow fetchmail[13675]: SMTP> QUIT
Aug 17 17:43:40 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:40 willow fetchmail[13675]: SMTP< 221 willow closing
connection
Aug 17 17:43:40 willow fetchmail[13675]:  flushed
Aug 17 17:43:40 willow fetchmail[13675]: POP3> DELE 3^M
Aug 17 17:43:40 willow fetchmail[13675]: POP3< +OK Done.
Aug 17 17:43:40 willow fetchmail[13675]: POP3> LIST 4
Aug 17 17:43:40 willow fetchmail[13675]: POP3< +OK 4 4406
Aug 17 17:43:40 willow fetchmail[13675]: POP3> RETR 4
Aug 17 17:43:40 willow fetchmail[13675]: POP3< +OK Message follows
Aug 17 17:43:40 willow fetchmail[13675]: reading message
dgr...@po...:4 of 33 (4406 octets)
Aug 17 17:43:41 willow fetchmail[13675]: About to rewrite Return-Path:
<net...@os...>^M Rewritten version is Return-Path:
<net...@os...>^M
Aug 17 17:43:41 willow fetchmail[13675]: About to rewrite From:
Wensong Zhang <we...@li...>^M Rewritten version is From:
Wensong Zhang <we...@li...>^M
Aug 17 17:43:41 willow fetchmail[13675]: About to rewrite To:
ne...@os...^M Rewritten version is To: ne...@os...^M
Aug 17 17:43:41 willow fetchmail[13675]: About to rewrite Cc: Julian
Anastasov <ja...@ss...>^M Rewritten version is Cc: Julian Anastasov
<ja...@ss...>^M
Aug 17 17:43:41 willow fetchmail[13675]: About to rewrite Sender:
net...@os...^M Rewritten version is Sender:
net...@os...^M
Aug 17 17:43:41 willow fetchmail[13675]: forwarding to
/var/imap/socket/lmtp
Aug 17 17:43:41 willow fetchmail[13675]: SMTP> MAIL
FROM:<net...@os...> SIZE=4406
Aug 17 17:43:41 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:41 willow fetchmail[13675]: SMTP< 250 2.1.0 ok
Aug 17 17:43:41 willow fetchmail[13675]: SMTP> RCPT
TO:<da...@dg...>
Aug 17 17:43:41 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:41 willow fetchmail[13675]: SMTP< 250 2.1.5 ok
Aug 17 17:43:41 willow fetchmail[13675]: SMTP> DATA
Aug 17 17:43:41 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:41 willow fetchmail[13675]: SMTP< 354 go ahead
*******************************************************Aug 17 17:43:41
willow fetchmail[13675]: message dgr...@po...:4 was not the
expected length (4533 actual != 4406 expected)
Aug 17 17:43:41 willow fetchmail[13675]: SMTP>. (EOM)
Aug 17 17:43:41 willow fetchmail[13675]: SMTP_ok loop start
Aug 17 17:43:41 willow fetchmail[13675]: SMTP< 250 2.1.5 Ok

## 5 minute hang

Aug 17 17:48:41 willow fetchmail[13675]: smtp listener protocol error 2
Aug 17 17:48:41 willow fetchmail[13675]:  not flushed
Aug 17 17:48:41 willow fetchmail[13675]: POP3> LIST 5
Aug 17 17:48:41 willow fetchmail[13675]: POP3< -ERR Client has been
idle for too long.
Aug 17 17:48:41 willow fetchmail[13675]: Client has been idle for too
long.
Aug 17 17:48:41 willow fetchmail[13675]: POP3> QUIT^M
Aug 17 17:48:41 willow fetchmail[13675]: client/server protocol error
while fetching from pop3.ukfsn.org
Aug 17 17:48:41 willow fetchmail[13675]: 6.2.5 querying pop3.ukfsn.org
(protocol POP3) at Tue 17 Aug 2004 05:48:41 PM BST: poll completed
Aug 17 17:48:41 willow fetchmail[13675]: Query status=4 (PROTOCOL)

# ./fetchmail -V -v -v -f /etc/fetchmailrc
This is fetchmail release 6.2.5+NLS
Fallback MDA: (none)
Linux willow 2.6.6 #1 Wed Jun 2 12:15:21 BST 2004 i586 unknown
Taking options from command line and /etc/fetchmailrc
Idfile is /var/run/fetchmail.ids
Progress messages will be logged via syslog
Fetchmail will show progress dots even in logfiles.
Fetchmail will forward misaddressed multidrop messages to
da...@dg....
Fetchmail will direct error mail to the postmaster.
Options for retrieving from dgr...@po...:
~  True name of server is pop3.ukfsn.org.
~  This host will be queried when no host is specified.
~  Password = "xxxxxx".
~  Protocol is POP3 (using default port).
~  All available authentication methods will be tried.
~  Server nonresponse timeout is 300 seconds (default).
~  Default mailbox selected.
~  All messages will be retrieved (--all on).
~  Fetched messages will not be kept on the server (--keep off).
~  Old messages will not be flushed before message retrieval (--flush
off).
~  Rewrite of server-local addresses is enabled (--norewrite off).
~  Carriage-return stripping is disabled (stripcr off).
~  Carriage-return forcing is disabled (forcecr off).
~  Interpretation of Content-Transfer-Encoding is enabled (pass8bits off).
~  MIME decoding is disabled (mimedecode off).
~  Idle after poll is disabled (idle off).
~  Nonempty Status lines will be kept (dropstatus off)
~  Delivered-To lines will be kept (dropdelivered off)
~  No received-message limit (--fetchlimit 0).
~  Fetch message size limit is 100 (--fetchsizelimit 100).
~  Do binary search of UIDs during 9 out of 10 polls (--fastuidl 10).
~  No SMTP message batch limit (--batchlimit 0).
~  Deletion interval between expunges forced to 5 (--expunge 5).
~  Messages will be LMTP-forwarded to: /var/imap/socket/lmtp
~  Recognized listener spam block responses are: 571 550 501 554
~  No pre-connection command.
~  No post-connection command.
~  Single-drop mode: 1 local name(s) recognized.
~        da...@dg...
~  No interface requirement specified.
~  No monitor interface specified.
~  No plugin command specified.
~  No plugout command specified.
~  1 UIDs saved.
~        0bcc1e7633bb91ec04fbf4e1505b377d
~  Poll trace information will be added to the Received header.

other account info removed

David Greaves


-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.5 (GNU/Linux)
Comment: Using GnuPG with Thunderbird - http://enigmail.mozdev.org

iD8DBQFBImRz8LvjTle4P1gRAvSnAJ9IwApVKGz2R9rFX30S7VX6PPGzHgCggRDV
5Ya+ZOAplqk+vrBfwOua+r0=
=7Ndc
-----END PGP SIGNATURE-----
_______________________________________________
Fetchmail-friends mailing list
Fet...@li...
http://lists.ccil.org/cgi-bin/mailman/listinfo/fetchmail-friends
-------------------------------------------------------