Re: [imapsync] Issue migrating large mailboxes from FirstClass to Dovecot

["Phil Pearl (Lobbes)" <phil at zimbra dot com>]

Hi Scott,

> OK, so the good news is that with the latest imapsync 1.321 and Mail::IMAPClient 3.25, the split/maxcommandlength stuff is working fine.
>
> Now, I am at some point running into what seems like an issue in the reconnect logic.

What is the full command line you are using for imapsync?  Any chance
you are specifying a timeout of 30?  I could speculate about a number
of things but I'd like to get the full command line that you're using
to get a little more big picture.  I would expect a timeout of 600s
if you had the default settings.

> Here, my connection to the server times out.  OK, so we go into reconnect...
>         UID 5043093)
> ERROR: timeout waiting 30s for data from server at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1852

In the Mail::IMAPClient _read_more() code we have:

1852    $self->LastError($msg);
1853    $self->_record( $transno,
1854        [ $self->_next_index($transno), "ERROR", "$transno * NO $msg" ] );
1855    $self->_disconnect;    # BUG: can not handle timeouts gracefully

Mail::IMAPClient tries to handle things (by calling the _disconnect()
method) but for some unknown reason things do not seem to be working
as expected here.

>        Mail::IMAPClient::_read_more('Mail::IMAPClient=HASH(0x10096e3a0)', 'IO::Socket::INET=GLOB(0x10096d2a8)', 30) called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1642
>        Mail::IMAPClient::_read_line('Mail::IMAPClient=HASH(0x10096e3a0)') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1435
>        Mail::IMAPClient::_get_response('Mail::IMAPClient=HASH(0x10096e3a0)', 2003, undef) called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1406
>        Mail::IMAPClient::_imap_command_do('Mail::IMAPClient=HASH(0x10096e3a0)', 'UID FETCH 5043093 BODY.PEEK[]') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1312
>        Mail::IMAPClient::_imap_command('Mail::IMAPClient=HASH(0x10096e3a0)', 'UID FETCH 5043093 BODY.PEEK[]') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1488
>        Mail::IMAPClient::_imap_uid_command('Mail::IMAPClient=HASH(0x10096e3a0)', 'FETCH', 5043093, 'BODY.PEEK[]') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 2107
>        Mail::IMAPClient::fetch('Mail::IMAPClient=HASH(0x10096e3a0)', 5043093, 'BODY.PEEK[]') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 731
>        Mail::IMAPClient::message_string('Mail::IMAPClient=HASH(0x10096e3a0)', 5043093) called at /usr/local/bin/imapsync line 1743
> reconnecting to xxxx.xxxx.xxx, last error: timeout waiting 30s for data from server

_disconnect() must have run and it calls ->close() I wonder if that needs
to be changed to ->shutdown(2).  I can't think of any reason that would
be necessary so far but might be worth a shot I suppose if we don't come
up with anything else.

> Connecting via IO::Socket::INET to xxxx.xxxx.xxx:143 Timeout 30
> Connected to xxxx.xxxx.xxx errno(Socket is already connected)
> ERROR: timeout waiting 30s for data from server: Socket is already connected at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1852
>        Mail::IMAPClient::_read_more('Mail::IMAPClient=HASH(0x10096e3a0)', 'IO::Socket::INET=GLOB(0x100bf96e8)', 30) called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1642
>        Mail::IMAPClient::_read_line('Mail::IMAPClient=HASH(0x10096e3a0)') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1435
>        Mail::IMAPClient::_get_response('Mail::IMAPClient=HASH(0x10096e3a0)', '*', 'PREAUTH') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 373
>        Mail::IMAPClient::Socket('Mail::IMAPClient=HASH(0x10096e3a0)', 'IO::Socket::INET=GLOB(0x100bf96e8)') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 344
>        Mail::IMAPClient::connect('Mail::IMAPClient=HASH(0x10096e3a0)') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1294
>        Mail::IMAPClient::reconnect('Mail::IMAPClient=HASH(0x10096e3a0)') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1327
>        Mail::IMAPClient::_imap_command('Mail::IMAPClient=HASH(0x10096e3a0)', 'UID FETCH 5043093 BODY.PEEK[]') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1488
>        Mail::IMAPClient::_imap_uid_command('Mail::IMAPClient=HASH(0x10096e3a0)', 'FETCH', 5043093, 'BODY.PEEK[]') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 2107
>        Mail::IMAPClient::fetch('Mail::IMAPClient=HASH(0x10096e3a0)', 5043093, 'BODY.PEEK[]') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 731
>        Mail::IMAPClient::message_string('Mail::IMAPClient=HASH(0x10096e3a0)', 5043093) called at /usr/local/bin/imapsync line 1743
> reconnect failed on try #1
>
> Noting that I get a "Socket is already connected" error message back.  At this point, we take another shot and an AUTHENTICATE CRAM-MD5 is sent this time:

I can't explain this at the moment as disconnect should have wiped out
the old connection and we did get a new IO::Socket::INET object:
  old one - GLOB(0x10096d2a8)
  new one - GLOB(0x100bf96e8)

> reconnecting to xxxx.xxxx.xxx, last error: timeout waiting 30s for data from server: Socket is already connected
> Connecting via IO::Socket::INET to xxxx.xxxx.xxx:143 Timeout 30
> Connected to xxxx.xxxx.xxx errno(Socket is already connected)

At this point I'm wondering if $! is just not reset and perhaps that
errno is bogus or if I'm missing some subtle bug.

> Read:   * OK FirstClass IMAP4rev1 server v10.010 at xxxx.xxxx.xxx ready

This is a banner from a new/fresh connection...

> Sending: 2004 AUTHENTICATE CRAM-MD5
> Sent 28 bytes
> Read:   + PDIwMTAwNzA5MjEzODE1LjIzNDE5MjA0OEBsa3NkLm9yZz4=
> Sending: Y2t1aG5zIDZhMWZmYzQ2Y2EyZjkyNDZjNjQ3NjY4ODQxMTAwZjc4
> Sent 54 bytes
> Read:   2004 NO AUTHENTICATE failed, invalid userid or password
>
> ERROR: 2004 NO AUTHENTICATE failed, invalid userid or password at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 3195
>        Mail::IMAPClient::authenticate('Mail::IMAPClient=HASH(0x10096e3a0)', 'CRAM-MD5', undef) called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 436
>        Mail::IMAPClient::login('Mail::IMAPClient=HASH(0x10096e3a0)') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 388
>        Mail::IMAPClient::Socket('Mail::IMAPClient=HASH(0x10096e3a0)', 'IO::Socket::INET=GLOB(0x111307c10)') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 344
>        Mail::IMAPClient::connect('Mail::IMAPClient=HASH(0x10096e3a0)') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1294
>        Mail::IMAPClient::reconnect('Mail::IMAPClient=HASH(0x10096e3a0)') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1327
>        Mail::IMAPClient::_imap_command('Mail::IMAPClient=HASH(0x10096e3a0)', 'UID FETCH 5043093 BODY.PEEK[]') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1488
>        Mail::IMAPClient::_imap_uid_command('Mail::IMAPClient=HASH(0x10096e3a0)', 'FETCH', 5043093, 'BODY.PEEK[]') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 2107
>        Mail::IMAPClient::fetch('Mail::IMAPClient=HASH(0x10096e3a0)', 5043093, 'BODY.PEEK[]') called at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 731
>        Mail::IMAPClient::message_string('Mail::IMAPClient=HASH(0x10096e3a0)', 5043093) called at /usr/local/bin/imapsync line 1743
>reconnect failed on try #2
>
>And now the reconnect fails -- I'm not sure why the authenticate fails, but perhaps we're not sending the userid again?

Based on the base64 encoded data here it appears we are sending a
userid, are you seeing something different?

> Except we just forge ahead and send the UID FETCH, which results in a BAD being thrown back to us (presumably since we are not authenticated):
>
> Sending: 2005 UID FETCH 5043093 BODY.PEEK[]
Sent 36 bytes
Read:   2005 BAD command not understood
ERROR: 2005 BAD command not understood at /Library/Perl/5.10.0/Mail/IMAPClient.pm line 1457

At this point clearly the library state is just broken.  Looks like I'll
need to revisit the retry logic to help ensure this doesn't happen.
It would be helpful to determine how that first _disconnect() fails
or if something else is causing the problems on reconnect...  If I get
a chance I may hit you off the list with some a patch and/or additional
diagnostics to gather if you have time.

> I'm going to try this with 2.2.9 now that the reconnect logic is presumably fixed to see if we have the same problems there, but this latest set of issues has me a bit confused.

Any better luck with that?

Phil