infinite loop after several hours of restore

GoogleCodeExporter commented 9 years ago

What steps will reproduce the problem?
1. gyb backup a large gmail account (in my case 130k msgs)
2. gyb restore to a different gmail account
3. when it stalls in CPU loop ^C
4. gyb restore --resume 
5. when it stalls again in CPU loop (after several hours sometimes) ^C

What is the expected output? What do you see instead?
I expected it to eventually finish, or at least keep making progress.
Instead, I saw it "stall" at some point ("restore message x of y" stops 
updating) and the CPU maxed out.

What version of the product are you using? On what operating system?
alpha-16 on MacOS Lion with Python 2.7.1

Please provide any additional information below.
new-host:google alan$ date; gyb --email alantest@test.columbia.edu --restore 
--folder ~/google/GYB-GMail-Backup-ac45\@test.columbia.edu; date
Thu Mar  1 13:49:36 EST 2012
GYB will now open a web browser page in order for you to grant GYB access to 
your Gmail. Please make sure you're logged in to the correct Gmail account 
before granting access. Press enter to open the browser. Once you've granted 
access you can switch back to GYB.
You should now see the web page. If you don't, you can manually open:

https://www.google.com/accounts/OAuthAuthorizeToken?oauth_token=XXXX

Once you've granted GYB access, press the Enter key.

Using backup folder /Users/alan/google/GYB-GMail-Backup-ac45@test.columbia.edu
restoring message 5600 of 164321
^C
Fri Mar  2 09:06:09 EST 2012

I left this running overnight.  When I came in this morning, Python was in an 
infinite loop and hadn’t made any further progress:

$ ps x67232
  PID   TT  STAT      TIME COMMAND
67232 s001  R+   918:55.13 python /Users/alan/google/gyb/gyb.py --email 
alantest@test.columbia.edu --restore

Original issue reported on code.google.com by a...@test.columbia.edu on 5 Mar 2012 at 6:02

GoogleCodeExporter commented 9 years ago

I've run this under rdb2 for a long time and it finally started looping and I 
captured where the loop is happening.

See 
https://docs.google.com/document/d/1p4A4VtsCqm0JDkISkzAayzeaC5rGoT67zlcv9m6YS88/
edit

It looks like a protocol violation or just a TCP session breaking in the SSL 
code, getting an unexpected EOF.

ssl.py called from gimaplib.

Original comment by a...@test.columbia.edu on 13 Mar 2012 at 3:33

GoogleCodeExporter commented 9 years ago

Further inspection reveals that gimpalib.py has a read() function that has an 
infinite loop (around line 38) in the case of an unexpected SSL EOF because 
ssl.py/__init__() defaults suppress_ragged_eof = True, causing it to return an 
empty string instead of raising an exception on SSL EOF.

I think the patch might be to fail in read() when the returned length is zero 
or initialize with suppress_ragged_eof=False. Is there ever the case when a 
zero-length string is acceptable?

Original comment by a...@test.columbia.edu on 13 Mar 2012 at 3:52

GoogleCodeExporter commented 9 years ago

I ran into this problem trying to restore 90K+ messages. Every 1000 messages or 
so, it would just hang.

I tried adding the line "if len(data) == 0: break" to the loop in MySSL.read in 
gimaplib.py, and restarted my --restore. It's been running continuously now for 
several hours, with an occasional error message, but it does appear to be 
working. Here's a sample of the messages I'm getting:

restoring message 1400 of 89072
imaplib.abort error:command: APPEND => socket error: EOF, retrying...
restoring message 2267 of 89072
imaplib.abort error:command: APPEND => socket error: EOF, retrying...
restoring message 3793 of 89072
imaplib.abort error:command: UID => socket error: EOF, retrying...
restoring message 5392 of 89072
imaplib.abort error:command: UID => socket error: EOF, retrying...
restoring message 6992 of 89072
imaplib.abort error:command: APPEND => socket error: EOF, retrying...
restoring message 8399 of 89072
imaplib.abort error:command: UID => socket error: EOF, retrying...
restoring message 9751 of 89072
imaplib.abort error:command: APPEND => socket error: EOF, retrying...
restoring message 11410 of 89072
imaplib.abort error:command: UID => socket error: EOF, retrying...
restoring message 13210 of 89072
imaplib.abort error:command: UID => socket error: EOF, retrying...

I'm guessing that these are just transient errors from the IMAP server, and the 
correct thing to do is simply retry.

Original comment by ccout...@gmail.com on 22 Jun 2012 at 6:15

GoogleCodeExporter commented 9 years ago

I'm seeing the same issue, but in my case the patch (adding len(data) == 0) 
hasn't solved it. It is still seems stuck sending a single message (with the 
socket error on APPEND happening in a loop). At least no CPU to 100%.

restoring message 1 of 10387
imaplib.abort error:command: APPEND => socket error: EOF, retrying...

imaplib.abort error:command: APPEND => socket error: EOF, retrying...

imaplib.abort error:command: APPEND => socket error: EOF, retrying...

Original comment by dayve...@gmail.com on 8 Oct 2012 at 3:23

GoogleCodeExporter commented 9 years ago

So is this ultimately caused by an issue with the Google IMAP server? Is there 
nothing that can be done other than to retry?

Original comment by geo...@damacy.net on 9 Feb 2013 at 9:59

GoogleCodeExporter commented 9 years ago

This seems to have fixed my problem as well.

Original comment by andy.ser...@deltahotels.com on 15 Feb 2013 at 8:02

GoogleCodeExporter commented 9 years ago

This is still a problem in the latest version, as far as I can tell.

Trying to restore 90.000 messages, eventually it gets to a point where it fails 
like this in an infinite loop. If I resume restoring, it picks right up at the 
same message and goes into the "EOF, retrying..." loop.

I'm using Python 2.7.2 on OS X 10.8.5.
The error message that loops infinitely is:

imaplib.abort error:command: APPEND => socket error: EOF, retrying...

Original comment by set...@gmail.com on 18 Sep 2013 at 7:17

GoogleCodeExporter commented 9 years ago

Btw, this is completely reproducible. I'll happily run some tests, apply 
patches or whatever.
I'm not a python developer, but I'm a software developer with lots of 
experience in other languages, and a bit of dabbling in python.

I'll happily help someone get this fixed, but I lack the prerequisite insight 
and python skills (and time) to troubleshoot and fix this on my own.

Original comment by set...@gmail.com on 18 Sep 2013 at 7:20

GoogleCodeExporter commented 9 years ago

Btw, this is completely reproducible. I'll happily run some tests, apply 
patches or whatever.
I'm not a python developer, but I'm a software developer with lots of 
experience in other languages, and a bit of dabbling in python.

I'll happily help someone get this fixed, but I lack the prerequisite insight 
and python skills (and time) to troubleshoot and fix this on my own.

Original comment by set...@gmail.com on 18 Sep 2013 at 7:22

GoogleCodeExporter commented 9 years ago

This is what is repeated every time the error message is repeated, when I 
enable debug mode.

imaplib.abort error:command: APPEND => socket error: EOF, retrying...
  13:40.90 > LILF1 AUTHENTICATE XOAUTH2
  13:40.92 < +
  13:40.92 write literal size 128
  13:41.14 < * CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 UIDPLUS COMPRESS=DEFLATE ENABLE MOVE CONDSTORE ESEARCH
  13:41.14 < LILF1 OK xxx@xxx.dk Xxx Xxx authenticated (Success)
  13:41.14 > LILF2 CAPABILITY
  13:41.27 < * CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 UIDPLUS COMPRESS=DEFLATE ENABLE MOVE CONDSTORE ESEARCH
  13:41.27 < LILF2 OK Success
  13:41.27 > LILF3 ID ("name" "Got Your Back: Gmail Backup" "version" "0.20 Alpha" "vendor" "Jay Lee" "contact" "jay0lee@gmail.com")
  13:41.30 < * ID ("name" "GImap" "vendor" "Google, Inc." "support-url" "http://support.google.com/mail" "version" "gmail_imap_130910.00_p0" "remote-host" "176.222.237.30")
  13:41.30 < LILF3 OK Success
  13:41.30 > LILF4 SELECT "[Gmail]/All Mail"
  13:44.74 < * FLAGS (\Answered \Flagged \Draft \Deleted \Seen junkrecorded OIB-Seen-[Gmail]/Important NonJunk forwarded Junk $label2 $notjunk $label3 $Forwarded OIB-Seen-[Gmail]/All $junk $label1 $MDNSent OIB-Seen-INBOX $label4 $label5 NotJunk Mail)
  13:44.74 < * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen junkrecorded OIB-Seen-[Gmail]/Important NonJunk forwarded Junk $label2 $notjunk $label3 $Forwarded OIB-Seen-[Gmail]/All $junk $label1 $MDNSent OIB-Seen-INBOX $label4 $label5 NotJunk Mail \*)] Flags permitted.
  13:44.74 < * OK [UIDVALIDITY 657914141] UIDs valid.
  13:44.74 < * 123101 EXISTS
  13:44.74 < * 0 RECENT
  13:44.74 < * OK [UIDNEXT 217103] Predicted next UID.
  13:44.74 < * OK [HIGHESTMODSEQ 4157646]
  13:44.74 < LILF4 OK [READ-WRITE] [Gmail]/All Mail selected. (Success)
  13:44.74 > LILF5 APPEND "[Gmail]/All Mail" (Junk \Seen) "27-May-2009 00:21:09 +0200" {4115}
  13:44.78 < + go ahead
  13:44.78 write literal size 4115
  13:44.89 last 4 IMAP4 interactions:
  13:40.87 < * OK Gimap ready for requests from 176.222.237.30 f3if11228781eeh.221
  13:40.87 > LILF0 CAPABILITY
  13:40.90 < * CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 XYZZY SASL-IR AUTH=XOAUTH AUTH=XOAUTH2 AUTH=PLAIN AUTH=PLAIN-CLIENTTOKEN
  13:40.90 < LILF0 OK Thats all she wrote! f3if11228781eeh.221

Original comment by set...@gmail.com on 18 Sep 2013 at 7:24

GoogleCodeExporter commented 9 years ago

I'm having the same problem with doing a large backup, 108,000 messages and 
about 10 gigs; haven't tried the restore yet. I tried to resume using a smaller 
batch size, and it worked for a moment, backing up about 3 batches of 10, and 
then started doing the loop again. Now every time I try to resume the backup it 
just goes into the loop.

GYB Windows .2 alpha, Windows 7 version 6.1.7601

Microsoft Windows [Version 6.1.7601]
Copyright (c) 2009 Microsoft Corporation.  All rights reserved.

D:\gyb>gyb --email xyz@gmail.com --local-folder "D:\xyz"

Using backup folder D:\xyz
GYB needs to examine 110054 messages
GYB already has a backup of 108540 messages
GYB needs to backup 1514 messages
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...

Original comment by caroli...@gmail.com on 27 Sep 2013 at 5:12

GoogleCodeExporter commented 9 years ago

And still doing it, with this error sequence, when backing up.

Microsoft Windows [Version 6.1.7601]

D:\gyb>gyb --email xyz@gmail.com --action backup --local-folder "D:\xyz" 
--batch-size 4

Using backup folder D:\xyz
GYB needs to examine 110242 messages
GYB already has a backup of 108540 messages
GYB needs to backup 1702 messages
imaplib.abort error:System Error, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:command: UID => socket error: EOF, retrying...
imaplib.abort error:System Error, retrying...
imaplib.abort error:System Error, retrying...

Original comment by caroli...@gmail.com on 30 Sep 2013 at 3:31

GoogleCodeExporter commented 9 years ago

Is there a way to identify the email message so that it can be removed?

Original comment by bbr...@mylawfunds.com on 3 Oct 2013 at 5:19

GoogleCodeExporter commented 9 years ago

HOW TO FIX THIS PROBLEM IF YOU ARE AFFECTED:
These are all Linux style shell commands. It won't work on Windows without 
Cygwin or similar.

1. Inspect your output, the message # also has a timestamp, make note of the 
timestamp.
  restoring message 1 of 3859 from 2009-03-25 14:54:50
  imaplib.abort error:command: APPEND => socket error: EOF, retrying...

2. Find the affected file.
  grep "<minutes:seconds>" <my GYB backup directory>/<year>/<month>/<day>/*
  ex: grep "54:50" GYB-GMail-Backup-my.email@gmail.com/2009/3/25/*

3. Delete the affected file.
  The last command will output the filename of the affected file. Delete it with "rm".
  Binary file GYB-GMail-Backup-my.email@gmail.com/2009/3/25/643582869-2988.eml matches
  $ rm GYB-GMail-Backup-my.email@gmail.com/2009/3/25/643582869-2988.eml

4. Re-run GYB --action restore

Original comment by tgrei...@gmail.com on 4 May 2014 at 6:52

AChesser011384 / got-your-back

infinite loop after several hours of restore #37