Bug #52313 for Mail-IMAPClient: Getting read errors if Fast

Tue Dec 01 04:15:20 2009 jukka.huhta [...] helsinki.fi - Ticket created

Subject:	Getting read errors if Fast_io is set to 1
Date:	Tue, 1 Dec 2009 11:14:40 +0200 (EET)
To:	bug-Mail-IMAPClient [...] rt.cpan.org
From:	Jukka Huhta <jukka.huhta [...] helsinki.fi>

As requested in Fast_io()'s documentation, I'm reporting of a bug(?) triggered by setting Fast_io to 1. The problem is a read error with Resource temporarily unavailable error message. When issued an IMAP search command, the response arrives too late, after the client has sent the next IMAP command. This is reproducible with my simple IMAP search client (attached; uses currently STARTTLS and DIGEST-MD5). Here is a excerpt from an IMAP conversation with the error messages: Read: 3 OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID MUPDATE=mupdate://mupdate-server/ LOGINDISABLED COMPRESS=DEFLATE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY SORT SORT=MODSEQ THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE CATENATE CONDSTORE SCAN IDLE LISTEXT LIST-SUBSCRIBED X-NETSCAPE URLAUTH] Success (tls protection) Sending: 4 SELECT folder Sent 19 bytes Read: * FLAGS (\Answered \Flagged \Draft \Deleted \Seen) * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)] * 7649 EXISTS * 0 RECENT * OK [UNSEEN 1] * OK [UIDVALIDITY 1181805448] * OK [UIDNEXT 150908] * OK [NOMODSEQ] Sorry, modsequences have not been enabled on this mailbox * OK [URLMECH INTERNAL] 4 OK [READ-WRITE] Completed Sending: 5 UID SEARCH ALL Sent 18 bytes ERROR: error while reading data from server: Resource temporarily unavailable at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 1542 Mail::IMAPClient::_read_line('Mail::IMAPClient=HASH(0x9b02418)') called at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 1306 Mail::IMAPClient::_get_response('Mail::IMAPClient=HASH(0x9b02418)', 5, 'undef') called at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 1277 Mail::IMAPClient::_imap_command_do('Mail::IMAPClient=HASH(0x9b02418)', 'UID SEARCH ALL') called at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 1183 Mail::IMAPClient::_imap_command('Mail::IMAPClient=HASH(0x9b02418)', 'UID SEARCH ALL') called at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 1358 Mail::IMAPClient::_imap_uid_command('Mail::IMAPClient=HASH(0x9b02418)', 'SEARCH', 'ALL') called at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 2449 Mail::IMAPClient::search('Mail::IMAPClient=HASH(0x9b02418)', 'ALL') called at ./simple_imap_search.pl line 74 ERROR: error while reading data from server: Resource temporarily unavailable at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 1228 Mail::IMAPClient::_imap_command('Mail::IMAPClient=HASH(0x9b02418)', 'UID SEARCH ALL') called at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 1358 Mail::IMAPClient::_imap_uid_command('Mail::IMAPClient=HASH(0x9b02418)', 'SEARCH', 'ALL') called at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 2449 Mail::IMAPClient::search('Mail::IMAPClient=HASH(0x9b02418)', 'ALL') called at ./simple_imap_search.pl line 74 Use of uninitialized value in concatenation (.) or string at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 2242, <GEN0> line 2. split_sequence: length(1000-70) parts: 0 Use of uninitialized value in hash element at /usr/lib/perl5/vendor_perl/5.8.5/Mail/IMAPClient.pm line 2310, <GEN0> line 2. Error getting message, skipping... Sending: 6 LOGOUT Sent 10 bytes Using on Mail::IMAPClient 3.20 with perl 5.8.5 on CentOS 4.8. Server is Cyrus 2.3.15.

Message body is not shown because sender requested not to inline it.

Tue Dec 01 12:55:46 2009 PLOBBES [...] cpan.org - Correspondence added

If I am reading things correctly, it does appear the code isn't paranoid enough for non-blocking sysread() calls. There is a check via select() that must be returning true before the call to sysread() but even then I believe sysread() isn't guaranteed to not return EAGAIN. The same code is duplicated in two places in the module. When I get some free time, I'll see if I can get a patch in place. If you're interested and have the time feel free patches are certainly welcome. In the mean time, using Fastio(0) hopefully isn't too much of an inconvenience. Also, if you have time please attach output when having Debug set to 1 (please ensure no private data is in that attachment though).

Tue Dec 01 12:55:47 2009 The RT System itself - Status changed from 'new' to 'open'

Tue Dec 01 12:55:51 2009 PLOBBES [...] cpan.org - Given to PLOBBES

Wed Dec 02 04:45:23 2009 jukka.huhta [...] helsinki.fi - Correspondence added

Subject:	Re: [rt.cpan.org #52313] Getting read errors if Fast_io is set to 1
Date:	Wed, 2 Dec 2009 11:45:04 +0200 (EET)
To:	Phil Lobbes via RT <bug-Mail-IMAPClient [...] rt.cpan.org>
From:	Jukka Huhta <jukka.huhta [...] helsinki.fi>

On Tue, 1 Dec 2009, Phil Lobbes via RT wrote: Show quoted text

> Also, if you have time please attach output when having Debug set to > 1 (please ensure no private data is in that attachment though).

But I already had debug set to 1 as you can see from the code. The only thing I omitted from the copy-paste output was the "AUTHENTICATE DIGEST-MD5" part. Here you have it for completeness (with private parts removed): $ ./simple_imap_search.pl --host=myhost --username=an_user \ --folder=folder --password=pass Started at Wed Dec 2 11:31:12 2009 Using Mail::IMAPClient version 3.20 on perl 5.008005 Sending: 2 CAPABILITY Sent 14 bytes Read: * CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID MUPDATE=mupdate://mupdate-server/ AUTH=PLAIN AUTH=LOGIN AUTH=DIGEST-MD5 SASL-IR COMPRESS=DEFLATE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY SORT SORT=MODSEQ THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE CATENATE CONDSTORE SCAN IDLE LISTEXT LIST-SUBSCRIBED X-NETSCAPE URLAUTH 2 OK Completed Sending: 3 AUTHENTICATE DIGEST-MD5 Sent 27 bytes Read: + <snip> Use of uninitialized value in numeric eq (==) at /usr/lib/perl5/vendor_perl/5.8.5/Authen/SASL/Perl/DIGEST_MD5.pm line 167, <GEN0> line 2. Sending: <snip> Sent 362 bytes Read: + <snip> Use of uninitialized value in numeric eq (==) at /usr/lib/perl5/vendor_perl/5.8.5/Authen/SASL/Perl/DIGEST_MD5.pm line 167, <GEN0> line 2. Sending: Sent 2 bytes Okay, there's also other error messages, but I suppose they're not related to this. Didn't have time to dig into them...

Mon Dec 14 11:50:01 2009 PLOBBES [...] cpan.org - Correspondence added

I have been able to reproduce the bug and have a patch that I intend to include in the next release to fix this bug. FWIW, I will also have support for starting TLS on a connection as well.

Fri Jan 22 13:55:38 2010 PLOBBES [...] cpan.org - Fixed in 3.22 added

Fri Jan 22 13:55:43 2010 PLOBBES [...] cpan.org - Correspondence added

Version 3.22 has been release and should fix this problem. If you get a chance to test and notice any problems please let me know.

Fri Jan 22 13:55:51 2010 PLOBBES [...] cpan.org - Status changed from 'open' to 'resolved'

Bug #52313 for Mail-IMAPClient: Getting read errors if Fast_io is set to 1