Bug #97718 for Mail-IMAPClient: Problem with Reconnectretry and DONE command

Sun Aug 03 08:08:12 2014 ldarby [...] tuffmail.com - Ticket created

Subject:	Problem with Reconnectretry and DONE command
Date:	Sun, 3 Aug 2014 13:07:57 +0100
To:	bug-Mail-IMAPClient [...] rt.cpan.org
From:	Laurence Darby <ldarby [...] tuffmail.com>

Hi, If a client is IDLE'ing, the next thing it should do is call DONE. But with Reconnectretry enabled, if the tcp connection breaks while idling, then _imap_command() will reconnect and try to re-send the DONE command on a new connection where it doesn't make sense. The debug log is this: Sending: 4 IDLE Sent 8 bytes Read: + idling Sending: DONE Sent 6 bytes ERROR: timeout waiting 10s for data from server at /usr/local/share/perl5/Mail/IMAPClient.pm line 1812. reconnecting to mail.mxes.net, last error: timeout waiting 10s for data from server Connecting via IO::Socket::SSL to mail.mxes.net:993 Timeout 10 Connected to mail.mxes.net Read: * OK IMAP4 ready ... reconnect success(1) on try #1/2 Sending: DONE Sent 6 bytes Read: * BAD Invalid tag ERROR: timeout waiting 10s for data from server at /usr/local/share/perl5/Mail/IMAPClient.pm line 1812. After that it reconnects, over and over up to Reconnectretry times. For testing this I was triggering the initial timeout with this: iptables -I INPUT -p tcp --sport 993 -j DROP ; iptables -I OUTPUT -p tcp --dport 993 -j DROP ; then once it starts reconnecting, immediately delete those rules so the reconnect succeeds, so I'm not sure why there's another timeout after reading the "Invalid tag" error. I've modified IMAPClient.pm to avoid this behaviour for the DONE command: # diff -u /usr/local/share/perl5/Mail/IMAPClient.pm.orig /usr/local/share/perl5/Mail/IMAPClient.pm --- /usr/local/share/perl5/Mail/IMAPClient.pm.orig 2014-08-03 12:14:13.386009617 +0100 +++ /usr/local/share/perl5/Mail/IMAPClient.pm 2014-08-03 13:04:24.973848805 +0100 @@ -1204,6 +1204,7 @@ # wrapper for _imap_command_do to enable retrying on lost connections sub _imap_command { my $self = shift; + my @cmd = @_; my $tries = 0; my $retry = $self->Reconnectretry || 0; @@ -1214,7 +1215,7 @@ # do command on the first try or if Connected (reconnect ongoing) if ( $tries == 1 or $self->IsConnected ) { - $rc = $self->_imap_command_do(@_); + $rc = $self->_imap_command_do(@cmd); push( @err, $self->LastError ) if $self->LastError; } @@ -1232,6 +1233,14 @@ my $ret = $self->reconnect; if ($ret) { $self->_debug("reconnect success($ret) on try #$tries/$retry"); + if (defined ($cmd[1]) && $cmd[1] eq "DONE") { + #Don't retry DONE commands, because after a reconnect, + #the new connection is no longer idling. Also pretend + #to be successful, which will result in the client + #correctly changing its state to not idling. + $rc = $self; + last; + } } elsif ( defined $ret and $ret == 0 ) { # escaping recursion return undef; Does that look like an acceptable fix, and are there any other IMAP states that should be handled in the same way? Thanks, Laurence

Thu Aug 07 12:49:52 2014 PLOBBES [...] cpan.org - Broken in 3.17 added

Thu Aug 07 12:49:52 2014 PLOBBES [...] cpan.org - Status changed from 'new' to 'open'

Thu Aug 07 12:49:52 2014 PLOBBES [...] cpan.org - Taken

Thu Aug 13 14:06:50 2015 PLOBBES [...] cpan.org - Broken in 2.2.9 added

Thu Aug 13 14:06:50 2015 PLOBBES [...] cpan.org - Broken in 3.17 deleted

Thu Aug 13 14:06:51 2015 PLOBBES [...] cpan.org - Correspondence added

I've committed the following change to address this problem: https://github.com/plobbes/mail-imapclient/commit/5a8ac0a980d26330b1143a140db7eabe15410929 This fix will be in the next release. Thanks for reporting this and sorry for the delay in responding.

Thu Aug 13 14:06:57 2015 PLOBBES [...] cpan.org - Status changed from 'open' to 'patched'

Fri Aug 14 13:16:50 2015 PLOBBES [...] cpan.org - Status changed from 'patched' to 'resolved'

Fri Aug 14 13:16:51 2015 PLOBBES [...] cpan.org - Fixed in 3.36 added

Wed Mar 02 18:43:28 2016 ldarby [...] tuffmail.com - Correspondence added

Subject:	Re: [rt.cpan.org #97718] Problem with Reconnectretry and DONE command
Date:	Wed, 2 Mar 2016 23:43:10 +0000
To:	bug-Mail-IMAPClient [...] rt.cpan.org
From:	Laurence Darby <ldarby [...] tuffmail.com>

Hi, I've been using the fix for the last few months, thanks, and it's fixed the issue with the hang after the reconnect. But it hasn't fixed the issue where DONE is sent on the new connection, which is what my original patch addressed. The full debug logs using 3.38 (including my client's), with the iptables triggered timeout, are: ========================================================================== [2016-03-02 22:55:18 +0000] Was idling, sending done: Sending: DONE Sent 6 bytes ERROR: timeout waiting 10s for data from server at /usr/local/share/perl5/Mail/IMAPClient.pm line 1880. Mail::IMAPClient::__read_more(Mail::IMAPClient=HASH(0x36380b8), IO::Socket::INET=GLOB(0x2a95370), 10) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1846 Mail::IMAPClient::_read_more(Mail::IMAPClient=HASH(0x36380b8), IO::Socket::INET=GLOB(0x2a95370), 10) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1657 Mail::IMAPClient::_read_line(Mail::IMAPClient=HASH(0x36380b8)) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1393 Mail::IMAPClient::_get_response(Mail::IMAPClient=HASH(0x36380b8), qr((?:6|DONE)), undef) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1327 Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x36380b8), HASH(0x36756f0), "DONE") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1226 Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x36380b8), HASH(0x36756f0), "DONE") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1168 Mail::IMAPClient::done(Mail::IMAPClient=HASH(0x36380b8), 6) called at /home/ldarby/bin/imap_idle.pl line 419 main::done_if_idle() called at /home/ldarby/bin/imap_idle.pl line 297 reconnecting to localhost, last error: timeout waiting 10s for data from server Connecting with IO::Socket::INET PeerAddr localhost PeerPort 143 Proto tcp Timeout 10 Debug 1 Connected to localhost Read: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN] Dovecot ready. Sending: 8 LOGIN ldarby [Redact: Count=8 Showcredentials=OFF] Sent 24 bytes Read: 8 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE] Logged in Sending: 9 SELECT INBOX Sent 16 bytes Read: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft) * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted. * 6153 EXISTS * 0 RECENT * OK [UNSEEN 5] First unseen. * OK [UIDVALIDITY 1146522623] UIDs valid * OK [UIDNEXT 95836] Predicted next UID 9 OK [READ-WRITE] Select completed (0.000 secs). reconnect success(1) on try #1/2 Sending: DONE Sent 6 bytes Read: DONE BAD Error in IMAP command : Unknown command. ERROR: DONE BAD Error in IMAP command : Unknown command. at /usr/local/share/perl5/Mail/IMAPClient.pm line 1365. Mail::IMAPClient::__ANON__("DONE BAD Error in IMAP command : Unknown command.\x{d}\x{a}") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1401 Mail::IMAPClient::_get_response(Mail::IMAPClient=HASH(0x36380b8), qr((?:6|DONE)), undef) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1327 Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x36380b8), HASH(0x36756f0), "DONE") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1226 Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x36380b8), HASH(0x36756f0), "DONE") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1168 Mail::IMAPClient::done(Mail::IMAPClient=HASH(0x36380b8), 6) called at /home/ldarby/bin/imap_idle.pl line 419 main::done_if_idle() called at /home/ldarby/bin/imap_idle.pl line 297 ERROR: timeout waiting 10s for data from server; DONE BAD Error in IMAP command : Unknown command. at /usr/local/share/perl5/Mail/IMAPClient.pm line 1275. Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x36380b8), HASH(0x36756f0), "DONE") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1168 Mail::IMAPClient::done(Mail::IMAPClient=HASH(0x36380b8), 6) called at /home/ldarby/bin/imap_idle.pl line 419 main::done_if_idle() called at /home/ldarby/bin/imap_idle.pl line 297 [2016-03-02 22:55:31 +0000] ERROR: DONE command returned error: timeout waiting 10s for data from server; DONE BAD Error in IMAP command : Unknown command. [2016-03-02 22:55:31 +0000] Reconnecting in 5 seconds Started at Wed Mar 2 22:55:36 2016 Using Mail::IMAPClient version 3.38 on perl 5.022000 ... ========================================================================== With my patch, the logs are: ========================================================================== [2016-03-02 23:06:42 +0000] Was idling, sending done: Sending: DONE Sent 6 bytes ERROR: timeout waiting 10s for data from server at /usr/local/share/perl5/Mail/IMAPClient.pm line 1889. Mail::IMAPClient::__read_more(Mail::IMAPClient=HASH(0x1f7d160), IO::Socket::INET=GLOB(0x13da568), 10) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1855 Mail::IMAPClient::_read_more(Mail::IMAPClient=HASH(0x1f7d160), IO::Socket::INET=GLOB(0x13da568), 10) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1666 Mail::IMAPClient::_read_line(Mail::IMAPClient=HASH(0x1f7d160)) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1402 Mail::IMAPClient::_get_response(Mail::IMAPClient=HASH(0x1f7d160), qr((?:4|DONE)), undef) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1336 Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x1f7d160), HASH(0x1fbb6c0), "DONE") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1227 Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x1f7d160), HASH(0x1fbb6c0), "DONE") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1168 Mail::IMAPClient::done(Mail::IMAPClient=HASH(0x1f7d160), 4) called at /home/ldarby/bin/imap_idle.pl line 419 main::done_if_idle() called at /home/ldarby/bin/imap_idle.pl line 297 reconnecting to localhost, last error: timeout waiting 10s for data from server Connecting with IO::Socket::INET PeerAddr localhost PeerPort 143 Proto tcp Timeout 10 Debug 1 Connected to localhost Read: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN] Dovecot ready. Sending: 6 LOGIN ldarby [Redact: Count=6 Showcredentials=OFF] Sent 24 bytes Read: 6 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE] Logged in Sending: 7 SELECT INBOX Sent 16 bytes Read: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft) * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted. * 6153 EXISTS * 0 RECENT * OK [UNSEEN 5] First unseen. * OK [UIDVALIDITY 1146522623] UIDs valid * OK [UIDNEXT 95836] Predicted next UID 7 OK [READ-WRITE] Select completed (0.000 secs). reconnect success(1) on try #1/2 [2016-03-02 23:06:55 +0000] Idling: Sending: 8 IDLE Sent 8 bytes Read: + idling ... ========================================================================== So could you please consider my patch again? Thanks, Laurence

Thu Mar 03 00:54:14 2016 PLOBBES [...] cpan.org - Correspondence added

I'm not a fan of the patch as suggested. Issues I see: - it hides an error from the caller (returns $self to pretend to be successful) - a one-off that is specific to "DONE" - I expect there are probably a few other cases of commands where we may want to reconnect but not retry. Below is one alternative I would consider (untested). Features: - a new { doretry => 0 } optional argument which short circuits the retry part of reconnect+retry - returns the $rc from the last command run (from the failed DONE in your case) - note: the "caller" of done() should be able to do the "right thing" for their particular scenario (but if you feel that isn't the case, let me know). In some cases, ignoring done errors might be the wrong thing to do and the fact that an error occurred may actually be meaningful (apparently not the case for you). Thoughts? diff --git a/lib/Mail/IMAPClient.pm b/lib/Mail/IMAPClient.pm index 6df532f..4aab590 100644 --- a/lib/Mail/IMAPClient.pm +++ b/lib/Mail/IMAPClient.pm @@ -1165,7 +1165,8 @@ sub done { my $count = shift || $self->Count; # DONE looks like a tag when sent and not already in IDLE - $self->_imap_command( { addtag => 0, tag => qr/(?:$count|DONE)/ }, "DONE" ) + $self->_imap_command( + { addtag => 0, tag => qr/(?:$count|DONE)/, doretry => 0 }, "DONE" ) or return undef; return $self->Results; } @@ -1211,8 +1212,11 @@ sub reconnect { } # wrapper for _imap_command_do to enable retrying on lost connections +# options: +# doretry => 0|1 - suppress|allow retry after reconnect sub _imap_command { my $self = shift; + my $opt = ref( $_[0] ) eq "HASH" ? $_[0] : {}; my $tries = 0; my $retry = $self->Reconnectretry || 0; @@ -1241,6 +1245,7 @@ sub _imap_command { my $ret = $self->reconnect; if ($ret) { $self->_debug("reconnect success($ret) on try #$tries/$retry"); + last if exists $opt->{doretry} and !$opt->{doretry}; } elsif ( defined $ret and $ret == 0 ) { # escaping recursion return undef;

Thu Mar 03 16:37:58 2016 ldarby [...] tuffmail.com - Correspondence added

Subject:	Re: [rt.cpan.org #97718] Problem with Reconnectretry and DONE command
Date:	Thu, 3 Mar 2016 21:37:36 +0000
To:	bug-Mail-IMAPClient [...] rt.cpan.org
From:	Laurence Darby <ldarby [...] tuffmail.com>

Ok, I agree, that's a much better idea, thanks. Your patch didn't quite work, so how about this? --- /usr/local/share/perl5/Mail/IMAPClient.pm.orig 2016-03-03 21:24:46.994013737 +0000 +++ /usr/local/share/perl5/Mail/IMAPClient.pm 2016-03-03 21:20:10.168050666 +0000 @@ -1165,7 +1165,8 @@ my $count = shift || $self->Count; # DONE looks like a tag when sent and not already in IDLE - $self->_imap_command( { addtag => 0, tag => qr/(?:$count|DONE)/ }, "DONE" ) + $self->_imap_command( + { addtag => 0, tag => qr/(?:$count|DONE)/, doretry => 0 }, "DONE" ) or return undef; return $self->Results; } @@ -1211,11 +1212,17 @@ } # wrapper for _imap_command_do to enable retrying on lost connections +# options: +# doretry => 0|1 - suppress|allow retry after reconnect sub _imap_command { my $self = shift; + my $opt = ref( $_[0] ) eq "HASH" ? $_[0] : {}; my $tries = 0; my $retry = $self->Reconnectretry || 0; + if (exists $opt->{doretry} && !$opt->{doretry}) { + $retry = 0; + } my ( $rc, @err ); # LastError (if set) will be overwritten masking any earlier errors With that, my client (unmodified) does this, which is fine: [2016-03-03 21:22:03 +0000] Was idling, sending done: Sending: DONE Sent 6 bytes ERROR: timeout waiting 10s for data from server at /usr/local/share/perl5/Mail/IMAPClient.pm line 1887. Mail::IMAPClient::__read_more(Mail::IMAPClient=HASH(0x2574760), IO::Socket::INET=GLOB(0x19d1918), 10) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1853 Mail::IMAPClient::_read_more(Mail::IMAPClient=HASH(0x2574760), IO::Socket::INET=GLOB(0x19d1918), 10) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1664 Mail::IMAPClient::_read_line(Mail::IMAPClient=HASH(0x2574760)) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1400 Mail::IMAPClient::_get_response(Mail::IMAPClient=HASH(0x2574760), qr((?:4|DONE)), undef) called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1334 Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x2574760), HASH(0x25b1fb8), "DONE") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1233 Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x2574760), HASH(0x25b1fb8), "DONE") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1168 Mail::IMAPClient::done(Mail::IMAPClient=HASH(0x2574760), 4) called at /home/ldarby/bin/imap_idle.pl line 419 main::done_if_idle() called at /home/ldarby/bin/imap_idle.pl line 297 ERROR: timeout waiting 10s for data from server at /usr/local/share/perl5/Mail/IMAPClient.pm line 1282. Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x2574760), HASH(0x25b1fb8), "DONE") called at /usr/local/share/perl5/Mail/IMAPClient.pm line 1168 Mail::IMAPClient::done(Mail::IMAPClient=HASH(0x2574760), 4) called at /home/ldarby/bin/imap_idle.pl line 419 main::done_if_idle() called at /home/ldarby/bin/imap_idle.pl line 297 [2016-03-03 21:22:13 +0000] ERROR: DONE command returned error: timeout waiting 10s for data from server [2016-03-03 21:22:13 +0000] Reconnecting in 5 seconds Started at Thu Mar 3 21:22:18 2016 Using Mail::IMAPClient version 3.38 on perl 5.022000 ... (in case you're wondering, this is because I'm constantly switching my laptop between wired & wireless networks...) Thanks, Laurence

Thu Mar 03 17:04:56 2016 ldarby [...] tuffmail.com - Correspondence added

Subject:	Re: [rt.cpan.org #97718] Problem with Reconnectretry and DONE command
Date:	Thu, 3 Mar 2016 22:04:44 +0000
To:	bug-Mail-IMAPClient [...] rt.cpan.org
From:	Laurence Darby <ldarby [...] tuffmail.com>

Oh, wait a minute - with your patch it *should* reconnect, and not send DONE, and I just need to change my client to ignore the timeout error, and check it reconnected successfully, right?

Thu Mar 03 17:18:09 2016 PLOBBES [...] cpan.org - Correspondence added

On Thu Mar 03 17:04:56 2016, ldarby@tuffmail.com wrote: Show quoted text

> > Oh, wait a minute - with your patch it *should* reconnect, and not send > DONE, and I just need to change my client to ignore the timeout error, > and check it reconnected successfully, right?

That was the idea... so did my original one work?

Thu Mar 03 17:52:43 2016 ldarby [...] tuffmail.com - Correspondence added

CC:	DJKERNEN__NO_SOLICITING__ [...] cpan.org
Subject:	Re: [rt.cpan.org #97718] Problem with Reconnectretry and DONE command
Date:	Thu, 3 Mar 2016 22:52:31 +0000
To:	bug-Mail-IMAPClient [...] rt.cpan.org
From:	Laurence Darby <ldarby [...] tuffmail.com>

On Thu, 3 Mar 2016 17:18:10 -0500 Phil Pearl (Lobbes) via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=97718 > > > On Thu Mar 03 17:04:56 2016, ldarby@tuffmail.com wrote:

> > > > Oh, wait a minute - with your patch it *should* reconnect, and not > > send DONE, and I just need to change my client to ignore the > > timeout error, and check it reconnected successfully, right?

> > > That was the idea... so did my original one work?

Yes it does, thank you!

Fri Mar 04 14:13:23 2016 PLOBBES [...] cpan.org - Correspondence added

On Thu Mar 03 17:52:43 2016, ldarby@tuffmail.com wrote: Show quoted text

> Yes it does, thank you!

Great! This will be part of 3.39 whenever that comes out. Thanks for not giving up :-).