sync_client problems

Bron Gondwana brong at fastmail.fm
Thu May 11 19:38:54 EDT 2017 

It looked like the '148.' file was corrupted in some way.  I assume you've deleted all the evidence now, so we can't see how!  Oh well :(

Bron.

On Fri, 12 May 2017, at 04:55, Eric Cunningham wrote:
> Just to close the loop on this, once the corrupted cdm-lit account on my 
> copy server successfully reconstructed, the backlog of replication has 
> completed successfully and is now caught up.
> 
> -Eric
> 
> On 05/11/2017 02:20 PM, Eric Cunningham wrote:
> > -G didn't seem to help, but I tried a "reconstruct -f -r" command 
> > without having previously deleted all occurrences of the cyrus.* files 
> > and it was then successful.
> > 
> > 
> > 
> > On 05/11/2017 01:44 PM, Patrick Boutilier wrote:
> >> 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
> >>
> >>
> >>
> >> ----
> >> 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


-- 
  Bron Gondwana
  brong at fastmail.fm

More information about the Info-cyrus mailing list