backupd and sync_client IOERROR

[Marco]

Hi Ellie,

Il 19/06/2020 03:01, ellie timoney ha scritto:
> I think you might need to add the usual recover entry to the START section:
>      
> recover       cmd="ctl_cyrusdb -r"
> 
> I notice this is missing from the backups documentation -- please let me know if it this sorts it out, and I'll fix it up!

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.

>> 2) Is there a way to delete a user from backupd host?
> That's an interesting question...
> 
> Under normal use, if a user is deleted from their imap server, then, after the deletion has replicated to the backup server, and after the "backup_retention" period has elapsed, and after a subsequent "ctl_backups compact ..." has been run, then the backup file should be approximately empty.  But I think it will still exist; nothing actually deletes it yet.
> 
> To get rid of it manually, you can use "ctl_backups list ..." to find the filename where it exists on disk.  You can also find it by using cyr_dbtool to look up the user's key in backups.db.  You will then need to:
> 
> a) use cyr_dbtool to delete that user's key from backups.db
> b) delete the named file (it will be like "/some/path/userid_XXXXXX")
> c) also delete the corresponding "/some/path/userid_XXXXXX.index" file
> 
> Note that if the user still really exists, and a rolling sync_client replicates them to the same backup server again, then the backup file will be recreated (with a new XXXXXX) -- with the same problems as above wrt no-initial-sync.

It works!
Making some tests and the initial sync, it's easy with sync_client 
insert a wrong non-existent userid (I added "/user" before the userid). 
And that wrong userid is immediately created on the backupd server :)
With the above procedure I can delete the wrong entry.


Definitively I think that this backup feature is a very good idea.

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.

Thank you very very much for these detailed answers!!


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.

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.
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.
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?

I checked the backup, is ok:
$ ctl_backups verify -u utente.archivista at example.com
verify utente.archivista at example.com: ok


Thank you very much
Cheers
marco