Bug #73431 for Net-IMAP-Simple: + go ahead error from google

Thu Dec 22 10:07:19 2011 MSTEVENS [...] cpan.org - Ticket created

CC:	michael.stevens [...] dianomi.com, michael.smith [...] dianomi.com
Subject:	+ go ahead error from google

Hi. I'm connecting to gmail with Net::IMAP::Simple and getting a number of messages in a folder. Intermittently I get an error from this code: my $message = $imap->get($i) or die "IMAP get error: " . $imap->errstr; of IMAP get error: warning unknown return string (id=96): + go ahead I'm not necessarily saying this is a bug, but can you provide any help?

Thu Dec 22 10:08:30 2011 MSTEVENS [...] cpan.org - Broken in 1.2019 added

Thu Dec 22 10:08:57 2011 MSTEVENS [...] cpan.org - Correspondence added

On Thu Dec 22 10:07:19 2011, MSTEVENS wrote: Show quoted text

> Hi. > > I'm connecting to gmail with Net::IMAP::Simple and getting a number of > messages in a folder. > > Intermittently I get an error from this code: > > my $message = $imap->get($i) or die "IMAP get error: " . $imap- >errstr; > > of > > IMAP get error: warning unknown return string (id=96): + go ahead > > I'm not necessarily saying this is a bug, but can you provide any

help? I'm using 1.2019 on perl 5.12.2.

Thu Dec 22 10:08:58 2011 MSTEVENS [...] cpan.org - Status changed from 'new' to 'open'

Thu Dec 22 10:33:38 2011 jettero [...] cpan.org - Correspondence added

On Thu Dec 22 10:07:19 2011, MSTEVENS wrote: Show quoted text

> IMAP get error: warning unknown return string (id=96): + go ahead

I believe that's a pretty standard IMAP thing to say. It's odd that it's never come up before. Do you know what imap server you're running against? I can't reproduce that here (or I'd have fixed it), so any information, logs, or patches you can produce are most welcome — patches most welcome via github, but anything will do. -Paul If riding in an airplane is flying, then riding in a boat is swimming. 116 jumps, 48.6 minutes of freefall, 92.9 freefall miles.

Thu Dec 22 10:44:37 2011 mstevens [...] etla.org - Correspondence added

CC:	MSTEVENS [...] cpan.org, michael.smith [...] dianomi.com, michael.stevens [...] dianomi.com
Subject:	Re: [rt.cpan.org #73431] + go ahead error from google
Date:	Thu, 22 Dec 2011 15:44:22 +0000
To:	Paul Miller via RT <bug-Net-IMAP-Simple [...] rt.cpan.org>
From:	Michael Stevens <mstevens [...] etla.org>

On Thu, Dec 22, 2011 at 10:33:39AM -0500, Paul Miller via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=73431 > > > On Thu Dec 22 10:07:19 2011, MSTEVENS wrote:

> > IMAP get error: warning unknown return string (id=96): + go ahead

> > I believe that's a pretty standard IMAP thing to say. It's odd that > it's never come up before. Do you know what imap server you're running > against? I can't reproduce that here (or I'd have fixed it), so any > information, logs, or patches you can produce are most welcome — patches > most welcome via github, but anything will do.

It's running against the gmail IMAP server. Here's some sample logs: [...l/5.12.2/Net/IMAP/Simple.pm line 1069 in sub _send_cmd] 14 FETCH 5 RFC822\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 616 in sub _process_cmd] * 5 FETCH (RFC822 {2510}\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1083 in sub _read_multiline] [0] censored email content goes here [...l/5.12.2/Net/IMAP/Simple.pm line 616 in sub _process_cmd] FLAGS (\Seen))\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] FLAGS (\Seen))\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1035 in sub _seterrstr] warning unknown return string (id=14): FLAGS (\Seen))\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 616 in sub _process_cmd] 14 OK Success\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] 14 OK Success\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1069 in sub _send_cmd] 15 APPEND "OldBounces" () {2510}\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 657 in sub _process_cmd] + go ahead\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] + go ahead\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1035 in sub _seterrstr] warning unknown return string (id=15): + go ahead\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 657 in sub _process_cmd] * 4 EXPUNGE\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] * 4 EXPUNGE\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 657 in sub _process_cmd] * 4 EXISTS\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] * 4 EXISTS\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 657 in sub _process_cmd] 15 OK [APPENDUID 44 11988] (Success)\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] 15 OK [APPENDUID 44 11988] (Success)\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1069 in sub _send_cmd] 16 STORE 5 +FLAGS (\Deleted)\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 758 in sub _process_cmd] 16 OK Success\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] 16 OK Success\r\n Getting message 6 [...l/5.12.2/Net/IMAP/Simple.pm line 1069 in sub _send_cmd] 17 FETCH 6 RFC822\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 616 in sub _process_cmd] 17 OK Success\r\n [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] 17 OK Success\r\n IMAP get error: warning unknown return string (id=15): + go ahead I've edited out the actual message content. If there's something more specific you're after let me know. Michael

Thu Dec 22 10:47:52 2011 MSTEVENS [...] cpan.org - Correspondence added

On Thu Dec 22 10:33:38 2011, JETTERO wrote: Show quoted text

> On Thu Dec 22 10:07:19 2011, MSTEVENS wrote:

> > IMAP get error: warning unknown return string (id=96): + go ahead

> > I believe that's a pretty standard IMAP thing to say. It's odd that > it's never come up before. Do you know what imap server you're running > against? I can't reproduce that here (or I'd have fixed it), so any > information, logs, or patches you can produce are most welcome —

patches Show quoted text

> most welcome via github, but anything will do.

Separate question, where can I find the github repo? it doesn't seem to be in the man page.

Thu Dec 22 10:55:53 2011 jettero [...] cpan.org - Correspondence added

On Thu Dec 22 10:47:52 2011, MSTEVENS wrote: Show quoted text

> Separate question, where can I find the github repo? it doesn't seem to > be in the man page.

Nope, just the Makefile.PL (shows up on the CPAN I believe). https://github.com/jettero/net--imap--simple -- If riding in an airplane is flying, then riding in a boat is swimming. 116 jumps, 48.6 minutes of freefall, 92.9 freefall miles.

Thu Dec 22 11:00:37 2011 jettero [...] cpan.org - Correspondence added

On Thu Dec 22 10:44:37 2011, mstevens@etla.org wrote: Show quoted text

> [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] 14 OK > Success\r\n > [...l/5.12.2/Net/IMAP/Simple.pm line 1069 in sub _send_cmd] 15 APPEND > "OldBounces" () {2510}\r\n > [...l/5.12.2/Net/IMAP/Simple.pm line 657 in sub _process_cmd] + go > ahead\r\n > [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] + go > ahead\r\n > [...l/5.12.2/Net/IMAP/Simple.pm line 1035 in sub _seterrstr] warning > unknown return string (id=15): + go ahead\r\n

This part is interesting to me. Why is it trying to append, and why doesn't it append something? I think the error is showing up on the next command (quirk of error checking) rather than being associated with the get(). I use this module with gmail every 3 minutes (literally) and I've never seen this before. I use get() and put() frequently to move things around my folders there. So I wish to know more about what functions you called in what order and whether you somehow (accidentally) posted an 2510 byte APPEND command without actually appending the 2510 bytes. That's what the go ahead is saying: ok, send me the 2510 bytes you promised. -- If riding in an airplane is flying, then riding in a boat is swimming. 116 jumps, 48.6 minutes of freefall, 92.9 freefall miles.

Thu Dec 22 11:07:10 2011 mstevens [...] etla.org - Correspondence added

CC:	MSTEVENS [...] cpan.org, michael.smith [...] dianomi.com, michael.stevens [...] dianomi.com
Subject:	Re: [rt.cpan.org #73431] + go ahead error from google
Date:	Thu, 22 Dec 2011 16:07:01 +0000
To:	Paul Miller via RT <bug-Net-IMAP-Simple [...] rt.cpan.org>
From:	Michael Stevens <mstevens [...] etla.org>

On Thu, Dec 22, 2011 at 11:00:38AM -0500, Paul Miller via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=73431 > > > On Thu Dec 22 10:44:37 2011, mstevens@etla.org wrote:

> > [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] 14 OK > > Success\r\n > > [...l/5.12.2/Net/IMAP/Simple.pm line 1069 in sub _send_cmd] 15 APPEND > > "OldBounces" () {2510}\r\n > > [...l/5.12.2/Net/IMAP/Simple.pm line 657 in sub _process_cmd] + go > > ahead\r\n > > [...l/5.12.2/Net/IMAP/Simple.pm line 1089 in sub _cmd_ok] + go > > ahead\r\n > > [...l/5.12.2/Net/IMAP/Simple.pm line 1035 in sub _seterrstr] warning > > unknown return string (id=15): + go ahead\r\n

> > This part is interesting to me. Why is it trying to append, and why > doesn't it append something? I think the error is showing up on the > next command (quirk of error checking) rather than being associated with > the get(). > > I use this module with gmail every 3 minutes (literally) and I've never > seen this before. I use get() and put() frequently to move things > around my folders there. > > So I wish to know more about what functions you called in what order and > whether you somehow (accidentally) posted an 2510 byte APPEND command > without actually appending the 2510 bytes. > > That's what the go ahead is saying: ok, send me the 2510 bytes you promised.

There's nothing I've censored from the log there. I cut out a bit after "FETCH 5" with the message body. I've attached the code I'm using (it's not too long) after some censorship to remove login details. I could perhaps provide a fuller session log privately but I'd like to keep it out of RT. Michael

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

Thu Dec 22 14:49:09 2011 jettero [...] cpan.org - Correspondence added

On Thu Dec 22 11:07:10 2011, mstevens@etla.org wrote: Show quoted text

> I could perhaps provide a fuller session log privately but I'd like to > keep it out of RT.

No, that won't be necessary. I'll clearly just have to grab the go ahead and clear it out or something. Your code looks totally legit to me. I can't see any reason it'd fail to send the message after the APPEND. Gmail does really weird things with some of the special mailboxes (non-imap things), but it doesn't even look like one of those cases. I have literally no idea why you're seeing this as an error. I have some ideas for fixes, but without knowing why it's causing a problem, they're just guesses. Does it do it every time? or just randomly? -- If riding in an airplane is flying, then riding in a boat is swimming. 116 jumps, 48.6 minutes of freefall, 92.9 freefall miles.

Fri Dec 23 05:50:01 2011 mstevens [...] etla.org - Correspondence added

CC:	MSTEVENS [...] cpan.org, michael.smith [...] dianomi.com, michael.stevens [...] dianomi.com
Subject:	Re: [rt.cpan.org #73431] + go ahead error from google
Date:	Fri, 23 Dec 2011 10:49:51 +0000
To:	Paul Miller via RT <bug-Net-IMAP-Simple [...] rt.cpan.org>
From:	Michael Stevens <mstevens [...] etla.org>

On Thu, Dec 22, 2011 at 02:49:11PM -0500, Paul Miller via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=73431 > > > On Thu Dec 22 11:07:10 2011, mstevens@etla.org wrote:

> > I could perhaps provide a fuller session log privately but I'd like to > > keep it out of RT.

> > No, that won't be necessary. I'll clearly just have to grab the go > ahead and clear it out or something. Your code looks totally legit to > me. I can't see any reason it'd fail to send the message after the > APPEND. Gmail does really weird things with some of the special > mailboxes (non-imap things), but it doesn't even look like one of those > cases. I have literally no idea why you're seeing this as an error. > > I have some ideas for fixes, but without knowing why it's causing a > problem, they're just guesses. > > Does it do it every time? or just randomly?

It seems to be intermittent - the script you saw is moving messages from one mailbox to another, it happens maybe every few dozen messages. Possibly I'll lose the ability to test once it finishes cleaning out the first mailbox. I also sometimes see a slightly different error: IMAP get error: warning unknown return string (id=22): FLAGS (\Seen)) Michael

Fri Dec 23 09:33:46 2011 jettero [...] cpan.org - Correspondence added

OK, first of all, the problem seems to have been that imap does not produce an error when a message doesn't exist. NiS was just returning whatever random warning happened to have happened last. I believe this is due to gmail randomly disappearing things they shouldn't. I didn't look it up, but I'm pretty sure imap servers are supposed to preserve the message numbers from a select until you're done with the select session. Whatever. I taught NiS to do two things: first, generate a meaningful error in the case that a message doesn't exist. Second, return (spuriously) a \n in the case that the message is 0 bytes. This can happen in certain weird kinds of internal imap errors and things. The new version, 1.2027, should be on the cpan today or tomorrow maybe. Or you can get it at http://jettero.pl/ I also have some bug-irrelevant processing tips for you. The download upload method works, but it's really slow. It's better to copy things internal to the server in as few commands as possible. This also has a side effect of working around message number changes (grr, google). $msg = $imap->get($i); # do things push @to_copy, $i if $something; push @to_delete, $i; # almost always? # later $imap->copy( $imap->list2range(@to_copy), "oldMailBox" ); # BAMN!! $imap->delete( $imap->list2range(@to_delete) ); # see ya $imap->quit; -Paul -- If riding in an airplane is flying, then riding in a boat is swimming. 116 jumps, 48.6 minutes of freefall, 92.9 freefall miles.

Fri Dec 23 09:33:47 2011 jettero [...] cpan.org - Status changed from 'open' to 'resolved'

Mon Dec 26 09:37:21 2011 mstevens [...] etla.org - Correspondence added

CC:	MSTEVENS [...] cpan.org, michael.smith [...] dianomi.com, michael.stevens [...] dianomi.com
Subject:	Re: [rt.cpan.org #73431] + go ahead error from google
Date:	Mon, 26 Dec 2011 14:37:12 +0000
To:	Paul Miller via RT <bug-Net-IMAP-Simple [...] rt.cpan.org>
From:	Michael Stevens <mstevens [...] etla.org>

On Fri, Dec 23, 2011 at 09:33:47AM -0500, Paul Miller via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=73431 > > > OK, first of all, the problem seems to have been that imap does not > produce an error when a message doesn't exist. NiS was just returning > whatever random warning happened to have happened last. I believe this > is due to gmail randomly disappearing things they shouldn't. I didn't > look it up, but I'm pretty sure imap servers are supposed to preserve > the message numbers from a select until you're done with the select > session. Whatever. > > I taught NiS to do two things: first, generate a meaningful error in the > case that a message doesn't exist. Second, return (spuriously) a \n in > the case that the message is 0 bytes. This can happen in certain weird > kinds of internal imap errors and things. > > The new version, 1.2027, should be on the cpan today or tomorrow maybe. > Or you can get it at http://jettero.pl/

I've just upgraded to this and will see if it fixes the problem. Show quoted text

> I also have some bug-irrelevant processing tips for you. The download > upload method works, but it's really slow. It's better to copy things > internal to the server in as few commands as possible. This also has a > side effect of working around message number changes (grr, google). > > $msg = $imap->get($i); > # do things > push @to_copy, $i if $something; > push @to_delete, $i; # almost always? > > > # later > > $imap->copy( $imap->list2range(@to_copy), "oldMailBox" ); # BAMN!! > $imap->delete( $imap->list2range(@to_delete) ); # see ya > $imap->quit;

Thanks, I might give that a go.

Mon Dec 26 09:37:23 2011 The RT System itself - Status changed from 'resolved' to 'open'

Tue Dec 27 07:34:45 2011 michael.stevens [...] dianomi.com - Correspondence added

CC:	michael.smith [...] dianomi.com
Subject:	Re: [rt.cpan.org #73431] + go ahead error from google
Date:	Tue, 27 Dec 2011 12:34:14 +0000
To:	bug-Net-IMAP-Simple [...] rt.cpan.org
From:	Michael Stevens <michael.stevens [...] dianomi.com>

On 26 December 2011 14:37, mstevens@etla.org via RT < bug-Net-IMAP-Simple@rt.cpan.org> wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=73431 > > > On Fri, Dec 23, 2011 at 09:33:47AM -0500, Paul Miller via RT wrote:

> > <URL: https://rt.cpan.org/Ticket/Display.html?id=73431 > > > > > OK, first of all, the problem seems to have been that imap does not > > produce an error when a message doesn't exist. NiS was just returning > > whatever random warning happened to have happened last. I believe this > > is due to gmail randomly disappearing things they shouldn't. I didn't > > look it up, but I'm pretty sure imap servers are supposed to preserve > > the message numbers from a select until you're done with the select > > session. Whatever. > > > > I taught NiS to do two things: first, generate a meaningful error in the > > case that a message doesn't exist. Second, return (spuriously) a \n in > > the case that the message is 0 bytes. This can happen in certain weird > > kinds of internal imap errors and things. > > > > The new version, 1.2027, should be on the cpan today or tomorrow maybe. > > Or you can get it at http://jettero.pl/

> > I've just upgraded to this and will see if it fixes the problem. >

> > I also have some bug-irrelevant processing tips for you. The download > > upload method works, but it's really slow. It's better to copy things > > internal to the server in as few commands as possible. This also has a > > side effect of working around message number changes (grr, google). > > > > $msg = $imap->get($i); > > # do things > > push @to_copy, $i if $something; > > push @to_delete, $i; # almost always? > > > > > > # later > > > > $imap->copy( $imap->list2range(@to_copy), "oldMailBox" ); # BAMN!! > > $imap->delete( $imap->list2range(@to_delete) ); # see ya > > $imap->quit;

> > Thanks, I might give that a go. >

Since upgrading I'm seeing a different error: IMAP get error: message not found at /opt/www/bin/bounce-scanner.pl line 24. I'm wondering if this is, as you suggeted, something with message numbers changing. Michael

Wed Dec 28 07:12:53 2011 jettero [...] cpan.org - Correspondence added

Show quoted text

> Since upgrading I'm seeing a different error: > > IMAP get error: message not found at /opt/www/bin/bounce-scanner.pl

line 24. That is the error that I added and it was the error you should have been getting all along. It is correct. The original error was just whatever error happened to be sitting on the stack at the time you requested a message that wasn't there. -- If riding in an airplane is flying, then riding in a boat is swimming. 116 jumps, 48.6 minutes of freefall, 92.9 freefall miles.

Fri Dec 30 13:18:59 2011 mstevens [...] etla.org - Correspondence added

CC:	michael.smith [...] dianomi.com
Subject:	Re: [rt.cpan.org #73431] + go ahead error from google
Date:	Fri, 30 Dec 2011 18:18:47 +0000
To:	Paul Miller via RT <bug-Net-IMAP-Simple [...] rt.cpan.org>
From:	Michael Stevens <mstevens [...] etla.org>

On Wed, Dec 28, 2011 at 07:12:56AM -0500, Paul Miller via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=73431 > > >

> > Since upgrading I'm seeing a different error: > > > > IMAP get error: message not found at /opt/www/bin/bounce-scanner.pl

> line 24. > > > That is the error that I added and it was the error you should have been > getting all along. It is correct. The original error was just whatever > error happened to be sitting on the stack at the time you requested a > message that wasn't there.

Thanks. Trying your serverside copy solution now, it seems to be behaving a lot better. Michael

Mon Jan 30 06:55:16 2012 jettero [...] cpan.org - Correspondence added

(forgot to close this)

Mon Jan 30 06:55:17 2012 jettero [...] cpan.org - Status changed from 'open' to 'resolved'

Mon Jan 30 06:57:20 2012 mstevens [...] etla.org - Correspondence added

CC:	michael.smith [...] dianomi.com
Subject:	Re: [rt.cpan.org #73431] + go ahead error from google
Date:	Mon, 30 Jan 2012 11:57:10 +0000
To:	Paul Miller via RT <bug-Net-IMAP-Simple [...] rt.cpan.org>
From:	Michael Stevens <mstevens [...] etla.org>

On Mon, Jan 30, 2012 at 06:55:17AM -0500, Paul Miller via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=73431 > > > (forgot to close this)

Just to be annoying and possibly reopen, I've noticed I've been seeing "FLAGS (\Seen)" as part of my message bodies. Michael

Mon Jan 30 06:57:20 2012 The RT System itself - Status changed from 'resolved' to 'open'

Mon Jan 30 07:00:11 2012 jettero [...] cpan.org - Correspondence added

Subject:	Re: [rt.cpan.org #73431] + go ahead error from google
Date:	Mon, 30 Jan 2012 06:59:58 -0500
To:	bug-Net-IMAP-Simple [...] rt.cpan.org
From:	Paul Miller <jettero [...] cpan.org>

Thought that was just my school mailserver. Please open a new ticket for that. -- Message brief, sent from phone. On Jan 30, 2012 6:57 AM, "mstevens@etla.org via RT" < bug-Net-IMAP-Simple@rt.cpan.org> wrote: Show quoted text

> Queue: Net-IMAP-Simple > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=73431 > > > On Mon, Jan 30, 2012 at 06:55:17AM -0500, Paul Miller via RT wrote:

> > <URL: https://rt.cpan.org/Ticket/Display.html?id=73431 > > > > > (forgot to close this)

> > Just to be annoying and possibly reopen, I've noticed I've been seeing > "FLAGS (\Seen)" as part of my message bodies. > > Michael > >

Mon Jan 30 07:13:31 2012 jettero [...] cpan.org - Correspondence added

(replying reopens tickets)

Mon Jan 30 07:13:32 2012 jettero [...] cpan.org - Status changed from 'open' to 'resolved'