backupd and sync_client IOERROR

Sun Jun 21 21:29:18 EDT 2020

Hi Marco,

On Fri, Jun 19, 2020, at 6:44 PM, Marco wrote:
> wow, yes, it works. With this config, after the Cyrus restart the 
> mailboxes.db and the skipstamps dbs are created and the error disappears 
> from syslog.

Great! I've updated the documentation, and the website should update shortly.

> I suggested the possibility to choose the recovery date (ie: all 
> messages and mailboxes deleted or expunged from <dateA> to <dateB>). I 
> hope you could add this feature.

Yep, I saw that, thanks for the request :)

> I now tried a restore, but I still have some problems. I very appreciate 
> if you could read the following issue.
> 
> My goal is to recover a message that was removed (expunged) from the 
> IMAP server, ignoring already existing messages.
> 
> It seems the "-x" flag could help. It seems it allows to restore and 
> unexpunge a previously expunged messages in the IMAP server.

No, you've misunderstood.  The "-x" flag is to ONLY restore expunged messages.  If you've specified a list of mailboxes or messages on the command line, and some of them are not expunged, the "-x" option will cause it to ignore the ones that are not expunged, and only restore the expunged ones.  The "-X" option does the inverse -- they're filters.  Without one of these filters, it will restore everything you asked for, regardless of its expunged status.

So like, maybe a user has deleted some stuff, and you don't want to mess around figuring out which individual messages they need restored, so you just want to restore everything, and let the user figure it out.  This is what -x is for -- so you can say "restore the contents of mailbox foo, but only the expunged stuff" or "restore every mailbox (-a), but only the expunged stuff".

Think about it: if the messages _weren't_ expunged, there would usually be no need to restore them from backup!  You would simply remove the \Deleted flag over IMAP.  So, you are almost always using restore to bring back expunged messages, thus there is no special flag needed to enable this functionality.

(But, if you had lost an entire server to some disaster, and restoring to its replacement, then you would need to also restore the unexpunged stuff.)

> Yesterday I expunged the message 16ceead9802286784d7a54c5bc782891f76f2f2e:
> 
> 2020-06-18T15:44:37.374556+02:00 tst-msg03 cyrus/imap[9461]: auditlog: 
> expunge sessionid=<cyrus-1592487850-9461-1-3828781086337945617> 
> mailbox=<example.com!user.utente^archivista> 
> uniqueid=<nvf96uirjgfs6xaekwwc7g44> uid=<32092> modseq=<46828> 
> sysflags=<DE|SE|AR|EX> guid=<16ceead9802286784d7a54c5bc782891f76f2f2e>
> 
> 
> I tried today to restore it:
> cyr_restore -v -U -x tst-msg03.example.com -u 
> utente.archivista at example.com 16ceead9802286784d7a54c5bc782891f76f2f2e
> example.com!user.utente^archivista: trying to keep 
> uidvalidity(1550228105), uniqueid(nvf96uirjgfs6xaekwwc7g44), 
> highestmodseq(46828)
> 
> and I see:
> 2020-06-19T09:29:24.030624+02:00 tst-msg03 cyrus/imap[32742]: login: 
> tst-msg03-bck.example.com [10.102.42.169] cyr_restore LOGIN User logged 
> in SESSIONID=<cyrus-1592551763-32742-1-6306147161275335691>
> 
> 2020-06-19T09:29:24.162909+02:00 tst-msg03 cyrus/imap[32742]: auditlog: 
> append sessionid=<cyrus-1592551763-32742-1-6306147161275335691> 
> mailbox=<example.com!user.utente^archivista> 
> uniqueid=<nvf96uirjgfs6xaekwwc7g44> uid=<32096> modseq=<46829> 
> sysflags=<DE|SE|AR|EX> guid=<16ceead9802286784d7a54c5bc782891f76f2f2e> 
> messageid=<ab818c62-5f3a-089b-89d5-55059fd7265c at example.com>
> 
> 2020-06-19T09:29:24.163058+02:00 tst-msg03 cyrus/imap[32742]: auditlog: 
> expunge sessionid=<cyrus-1592551763-32742-1-6306147161275335691> 
> mailbox=<example.com!user.utente^archivista> 
> uniqueid=<nvf96uirjgfs6xaekwwc7g44> uid=<32096> modseq=<46829> 
> sysflags=<DE|SE|AR|EX> guid=<16ceead9802286784d7a54c5bc782891f76f2f2e>
> 
> 2020-06-19T09:29:24.167561+02:00 tst-msg03 cyrus/imap[32742]: auditlog: 
> modseq sessionid=<cyrus-1592551763-32742-1-6306147161275335691> 
> mailbox=<example.com!user.utente^archivista> 
> uniqueid=<nvf96uirjgfs6xaekwwc7g44> highestmodseq=<46829>
> 
> 2020-06-19T09:29:24.215036+02:00 tst-msg03 cyrus/imap[32742]: USAGE 
> cyr_restore user: 0.042492 sys: 0.015435
> 
> 2020-06-19T09:29:24.215191+02:00 tst-msg03 cyrus/imap[32742]: auditlog: 
> traffic sessionid=<cyrus-1592551763-32742-1-6306147161275335691> 
> bytes_in=<2412> bytes_out=<1039>
> 
> 2020-06-19T09:29:32.855379+02:00 tst-msg03 cyrus/sync_client[32566]: 
> IOERROR: zero length response to MAILBOXES (end of file reached)
> 
> 2020-06-19T09:29:32.855682+02:00 tst-msg03 cyrus/sync_client[32566]: 
> IOERROR: zero length response to RESTART (end of file reached)
> 
> 2020-06-19T09:29:32.855713+02:00 tst-msg03 cyrus/sync_client[32566]: 
> Error in do_sync(): bailing out! Bad protocol
> 
> 2020-06-19T09:29:32.855738+02:00 tst-msg03 cyrus/sync_client[32566]: 
> Processing sync log file /var/lib/imap/sync/bck/log-run failed: Bad protocol
> 
> I tried again and I see the same result, but without the IOERROR:
> 
> 2020-06-19T09:36:51.153939+02:00 tst-msg03 cyrus/imap[32762]: login: 
> tst-msg03-bck.example.com [10.102.42.169] cyr_restore LOGIN User logged 
> in SESSIONID=<cyrus-1592552211-32762-1-17619865152399331525>
> 
> 2020-06-19T09:36:51.199742+02:00 tst-msg03 cyrus/imap[32762]: 
> example.com!user.utente^archivista: same message appears twice 32096 32097
> 
> (why twice? It expunges 32096 just above)
> 
> 2020-06-19T09:36:51.225525+02:00 tst-msg03 cyrus/imap[32762]: auditlog: 
> append sessionid=<cyrus-1592552211-32762-1-17619865152399331525> 
> mailbox=<example.com!user.utente^archivista> 
> uniqueid=<nvf96uirjgfs6xaekwwc7g44> uid=<32097> modseq=<46834> 
> sysflags=<DE|SE|AR|EX> guid=<16ceead9802286784d7a54c5bc782891f76f2f2e> 
> messageid=<ab818c62-5f3a-089b-89d5-55059fd7265c at example.com>
> 
> 2020-06-19T09:36:51.225714+02:00 tst-msg03 cyrus/imap[32762]: auditlog: 
> expunge sessionid=<cyrus-1592552211-32762-1-17619865152399331525> 
> mailbox=<example.com!user.utente^archivista> 
> uniqueid=<nvf96uirjgfs6xaekwwc7g44> uid=<32097> modseq=<46834> 
> sysflags=<DE|SE|AR|EX> guid=<16ceead9802286784d7a54c5bc782891f76f2f2e>
> 
> So the message is restored and immediately expunged again.

I think this is happening because you're specifying the "-U" option, which tries very hard to put the message back into the same state as it was last in.  Its last state was having been expunged, and therefore the restored copy needs to be expunged...

The point of -U is so that you can recover from data loss, while preserving the IMAP state so the client doesn't need to completely resync.  For the "user accidentally deleted and expunged, and now wants it back" use case, it's not useful, because in that case you explicitly want the message back with a new state (i.e. not expunged).

> Finally I expunged a new message and after few seconds I tried to 
> recover it:
> 
> cyr_restore -v -U -x tst-msg03.example.com -u 
> utente.archivista at example.com 3cfd9e7dff35bcb38667ed5896db3cb82b05fd94
> example.com!user.utente^archivista: trying to keep 
> uidvalidity(1550228105), uniqueid(nvf96uirjgfs6xaekwwc7g44), 
> highestmodseq(46828)
> example.com!user.utente^archivista: excluding unexpunged message: 
> 3cfd9e7dff35bcb38667ed5896db3cb82b05fd94
> 
> A different behavior occurs. But the message is expunged, is not unexpunged:
> 
> # grep 3cfd9e7dff35bcb38667ed5896db3cb82b05fd94 cyruslog | tail
> 2020-06-19T09:35:11.349226+02:00 tst-msg03 cyrus/imap[32571]: auditlog: 
> expunge sessionid=<cyrus-1592551351-32571-1-6833532399537986033> 
> mailbox=<example.com!user.utente^archivista> 
> uniqueid=<nvf96uirjgfs6xaekwwc7g44> uid=<32087> modseq=<46833> 
> sysflags=<AN|DE|SE|AR|EX> guid=<3cfd9e7dff35bcb38667ed5896db3cb82b05fd94>
> 
> Uhm... removing the "-x" I finally obtain the result of restoring 
> expunged messages.

I'm not really sure why this would make a difference.  Maybe in this case the expunge hadn't replicated to the backup server yet?

> The same message still remains in the unexpunged list of the IMAP 
> server. If we use delayed expunge on the IMAP server and backupd some 
> confusion can occurs.
> 
> I'm confused about "-x". If a message is expunged in the IMAP server, 
> then isn't it flagged as expunged in the Backups server too?

That depends on whether the expunge has been replicated yet or not.  But generally, yes.

I think most of the confusion here is because you're using "-U", and therefore restoring an expunged message as an expunged message.

Cheers,

ellie