sync_client problems

Thu May 11 13:44:13 EDT 2017

Try a -G with reconstruct?

-G     Force  re-parsing  of the underlying message (checks GUID 
correctness).  Reconstruct with -G should fix all possible individual 
message issues, including corrupted data files.

On 05/11/2017 02:37 PM, Eric Cunningham wrote:
> I have to walk this back.  In looking slightly further back in my 
> logfiles, before every instance of a failure to sync some folder, I see 
> a common error reported prior to every "bailing out! Bad protocol" error 
> - "IOERROR: GUID mismatch /var/spool/cyrus/mail/c/user/cdm-lit/Sent/148."
> 
> May 11 12:44:09 imap1 sync_client[48590]: IOERROR: GUID mismatch 
> /var/spool/cyrus/mail/c/user/cdm-lit/Sent/148.
> May 11 12:44:22 imap1 sync_client[48590]: IOERROR: zero length response 
> to MAILBOX (end of file reached)
> May 11 12:44:22 imap1 sync_client[48590]: do_folders(): update failed: 
> user.cdm-lit.Sent 'Bad protocol'
> May 11 12:44:22 imap1 sync_client[48590]: sync_mailboxes: doing 1000
> May 11 12:44:22 imap1 sync_client[48590]: IOERROR: zero length response 
> to MAILBOXES (end of file reached)
> May 11 12:44:22 imap1 sync_client[48590]: sync_mailboxes: doing 1000
> May 11 12:44:22 imap1 sync_client[48590]: IOERROR: zero length response 
> to MAILBOXES (end of file reached)
> May 11 12:44:22 imap1 sync_client[48590]: sync_mailboxes: doing 1000
> May 11 12:44:22 imap1 sync_client[48590]: IOERROR: zero length response 
> to MAILBOXES (end of file reached)
> May 11 12:44:22 imap1 sync_client[48590]: sync_mailboxes: doing 1000
> May 11 12:44:22 imap1 sync_client[48590]: IOERROR: zero length response 
> to MAILBOXES (end of file reached)
> May 11 12:44:22 imap1 sync_client[48590]: sync_mailboxes: doing 1000
> May 11 12:44:22 imap1 sync_client[48590]: IOERROR: zero length response 
> to MAILBOXES (end of file reached)
> May 11 12:44:22 imap1 sync_client[48590]: sync_mailboxes: doing 1000
> May 11 12:44:22 imap1 sync_client[48590]: IOERROR: zero length response 
> to MAILBOXES (end of file reached)
> May 11 12:44:22 imap1 sync_client[48590]: IOERROR: zero length response 
> to MAILBOXES (end of file reached)
> May 11 12:44:22 imap1 sync_client[48590]: IOERROR: zero length response 
> to UNMAILBOX (end of file reached)
> May 11 12:44:22 imap1 sync_client[48590]: folder_delete(): failed: 
> user.guest-student-coordinator.Trash.Aarflot 'Bad protocol'
> May 11 12:44:22 imap1 sync_client[48590]: Error in do_sync(): bailing 
> out! Bad protocol
> May 11 12:44:22 imap1 sync_client[48590]: Processing sync log file 
> /var/spool/CyrusDB-Sieve/cyrusdb/sync/log-run failed: Bad protocol
> 
> When I recontructed this cdm-lit account, it ran successfully on my 
> master host, but fails on my copy host:
> 
> [cyrus at imap2 ~]$ reconstruct -f -r user.cdm-lit
> user.cdm-lit
> user.cdm-lit.Sea Trail 2013
> user.cdm-lit.Sent uid 1 found - adding
> user.cdm-lit.Sent uid 2 found - adding
> user.cdm-lit.Sent uid 3 found - adding
> user.cdm-lit.Sent uid 4 found - adding
> ....
> user.cdm-lit.Sent uid 146 found - adding
> user.cdm-lit.Sent uid 147 found - adding
> user.cdm-lit.Sent uid 148 found - adding
> fatal error: Internal error: assertion failed: imap/mailbox.c: 2847: 
> record->size
> 
> Since I couldn't get a successful reconstruct on this account, I deleted 
> it and recreated it from my master host.  However, I'm still unable to 
> get a successful reconstruct with "failed to read index header" for 
> every subfolder and "fatal error: Internal error: assertion failed: 
> imap/mailbox.c: 2847: record->size"
> 
> Any ideas on how to correct this so I can see if I can then get past the 
> replication error?
> 
> Thanks!
> 
> -Eric
> 
> 
> On 05/11/2017 11:46 AM, Eric Cunningham wrote:
>> Thanks Bron, but that doesn't seem to work for me, unless I'm missing 
>> something.
>>
>> I ran reconstructs for this account on both my master and copy hosts:
>>
>> [cyrus at imap1 ~]$ reconstruct -f -r user.scramer
>> user.scramer
>> user.scramer.Archive
>> user.scramer.Archives
>> user.scramer.Archives.2004
>> ...
>> user.scramer.Trash.IS Networking and Operations
>> user.scramer.Trash.IS Security
>> user.scramer.Trash.IS Servers
>> user.scramer.Trash.IS Staff
>> user.scramer.Trash.IS Surveys
>> ...
>>
>>
>> [cyrus at imap2 ~]$ reconstruct -f -r user.scramer
>> user.scramer
>> user.scramer.Archive
>> user.scramer.Archives
>> user.scramer.Archives.2004
>> ...
>> user.scramer.Trash.IS Networking and Operations
>> user.scramer.Trash.IS Security
>> user.scramer.Trash.IS Servers
>> user.scramer.Trash.IS Staff
>> user.scramer.Trash.IS Surveys
>> ...
>>
>>
>> I then restart the replication against the log-run file and it again 
>> fails on a folder that no longer exists in that account:
>>
>> ...
>> May 11 11:40:51 imap1 sync_client[60696]: sync_mailboxes: doing 1000
>> May 11 11:40:51 imap1 sync_client[60696]: IOERROR: zero length 
>> response to MAILBOXES (end of file reached)
>> May 11 11:40:51 imap1 sync_client[60696]: IOERROR: zero length 
>> response to MAILBOXES (end of file reached)
>> May 11 11:40:51 imap1 sync_client[60696]: IOERROR: zero length 
>> response to UNMAILBOX (end of file reached)
>> May 11 11:40:51 imap1 sync_client[60696]: folder_delete(): failed: 
>> user.scramer.Trash.IS Software Management 'Bad protocol'
>> May 11 11:40:51 imap1 sync_client[60696]: Error in do_sync(): bailing 
>> out! Bad protocol
>> May 11 11:40:51 imap1 sync_client[60696]: Processing sync log file 
>> /var/spool/CyrusDB-Sieve/cyrusdb/sync/log-run failed: Bad protocol
>>
>>
>> -Eric
>>
>>
>> On 05/11/2017 02:14 AM, Bron Gondwana wrote:
>>> Looks like you have a corrupted mailboxes database - if you run a 
>>> reconstruct at each end then it should be fine.  Replication won't 
>>> bail for an actually-doesn't-exist mailbox, but it can't fix broken 
>>> mailboxes, that's what reconstruct is for.
>>>
>>> Bron.
>>>
>>>
>>> On Thu, 11 May 2017, at 01:01, Eric Cunningham wrote:
>>>> Hi list, I'm running cyrus replication on cyrus 2.5.10.  It seems
>>>> whenever a folder is encountered in log-run that doesn't exist on the
>>>> client and/or the server, the replication process logs "Error in
>>>> do_sync(): bailing out! Bad protocol".  Sometimes, it dies completely,
>>>> other times it restarts at the beginning of the log-run file.  But when
>>>> it re-encounters the folder in question, the same failure occurs and 
>>>> the
>>>> problem continuously loops until some manual action is taken.  I have a
>>>> checker script that attempts to restart a stopped sync but I haven't
>>>> tried to code it to get past these types of folder errors.  In the
>>>> meantime, replication effectively stops and the replication log
>>>> continuously builds in size.  You might imagine my horror at 
>>>> discovering
>>>> yesterday that replication of my production server with 1200 accounts
>>>> had been failing for over 7 weeks unnoticed, generating 9.5 million
>>>> lines in the replication log files.  I had gotten out of the habit of
>>>> daily monitoring of replication as it had been running fine and I
>>>> eventually moved on to other things.  I'm trying to get replication to
>>>> run through the enormous backlog but am running into more similar 
>>>> folder
>>>> issues that cause the process to fail, I make manual fixes, and start
>>>> the process again.  In my experience with this, reconstruction of the
>>>> affected folders on the master host and copy host has no effect.
>>>>
>>>> Can this otherwise excellent feature be made more robust to work past
>>>> these folder issues?
>>>>
>>>> Here are a couple of examples I've observed thus far of how the process
>>>> is failing for me.
>>>>
>>>> --------------
>>>>
>>>> In this example, the subfolder "Fly America Foreign Travel" no longer
>>>> existed on the master host but did exist on the copy host.  To resolve
>>>> this, I had to manually delete that folder from the copy host.
>>>>
>>>> May  9 15:17:48 imap1 sync_client[34614]: inefficient replication (8 >
>>>> 5) user.jtaft.PO.Fly America Foreign Travel
>>>> May  9 15:17:48 imap1 sync_client[34614]: FULLMAILBOX received NO
>>>> response: IMAP_MAILBOX_NONEXISTENT No Such Mailbox
>>>> May  9 15:17:48 imap1 sync_client[34614]: do_folders(): update failed:
>>>> user.jtaft.PO.Fly America Foreign Travel 'Mailbox does not exist'
>>>> May  9 15:17:48 imap1 sync_client[34614]: IOERROR: Mailbox does not 
>>>> exist
>>>> May  9 15:17:48 imap1 sync_client[34614]: Error in do_sync(): bailing
>>>> out! Mailbox does not exist
>>>> May  9 15:17:48 imap1 sync_client[34614]: Processing sync log file
>>>> /var/spool/CyrusDB-Sieve/cyrusdb/sync/log-run failed: Mailbox does 
>>>> not exist
>>>> May  9 15:17:48 imap1 sync_client[34614]: Reprocessing sync log file
>>>> /var/spool/CyrusDB-Sieve/cyrusdb/sync/log-run
>>>>
>>>> --------------
>>>>
>>>> In this example, the subfolder "Sohn" did not exist on the master host
>>>> nor on the copy host.  To resolve, I had to edit log-run and completely
>>>> remove all entries for this "Sohn" subfolder.
>>>>
>>>> May 10 10:13:26 imap1 sync_client[47011]: IOERROR: zero length response
>>>> to MAILBOXES (end of file reached)
>>>> May 10 10:13:26 imap1 sync_client[47011]: IOERROR: zero length response
>>>> to MAILBOXES (end of file reached)
>>>> May 10 10:13:26 imap1 sync_client[47011]: IOERROR: zero length response
>>>> to UNMAILBOX (end of file reached)
>>>> May 10 10:13:26 imap1 sync_client[47011]: folder_delete(): failed:
>>>> user.gg-chair.Trash.Sohn 'Bad protocol'
>>>> May 10 10:13:26 imap1 sync_client[47011]: Error in do_sync(): bailing
>>>> out! Bad protocol
>>>> May 10 10:13:26 imap1 sync_client[47011]: Processing sync log file
>>>> /var/spool/CyrusDB-Sieve/cyrusdb/sync/log-run failed: Bad protocol
>>>>
>>>> --------------
>>>>
>>>> Often, errors are logged without "bailing out!" and replication
>>>> continues to run:
>>>>
>>>> May 10 10:45:00 imap1 sync_client[87438]: sync_mailboxes: doing 1000
>>>> May 10 10:45:01 imap1 sync_client[87438]: sync_mailboxes: doing 1000
>>>> May 10 10:45:24 imap1 sync_client[87438]: IOERROR: GUID mismatch
>>>> /var/spool/cyrus/mail/c/user/cdm-lit/Sent/148.
>>>> May 10 10:45:37 imap1 sync_client[87438]: IOERROR: zero length response
>>>> to MAILBOX (end of file reached)
>>>> May 10 10:45:37 imap1 sync_client[87438]: do_folders(): update failed:
>>>> user.cdm-lit.Sent 'Bad protocol'
>>>> May 10 10:45:37 imap1 sync_client[87438]: sync_mailboxes: doing 1000
>>>>
>>>> --------------
>>>>
>>>> Thank you, list!
>>>>
>>>> -Eric
>>>>
>>>> ----
>>>> Cyrus Home Page: http://www.cyrusimap.org/
>>>> List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/
>>>> To Unsubscribe:
>>>> https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus
>>>
>>>
>>
> 
> ----
> Cyrus Home Page: http://www.cyrusimap.org/
> List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/
> To Unsubscribe:
> https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus

-------------- next part --------------
A non-text attachment was scrubbed...
Name: boutilpj.vcf
Type: text/x-vcard
Size: 286 bytes
Desc: not available
URL: <http://lists.andrew.cmu.edu/pipermail/info-cyrus/attachments/20170511/18650dcd/attachment.vcf>