doveadm backup has problems with some accounts
I try to setup for our mailserver (in a dc) a job backup to a secondary server (in our office) with "doveadm backup" via the -R option. (rsync , rsnapshot and so on tooks too long at the moment)
For the most user accounts all work as expected, but for three users it always fails
First run: /usr/bin/doveadm -Dv backup -Ru user1 tcp:mua01.domain.intra:12345
Dec 01 08:54:21 doveadm(user1)<70126><qfzHDjyfaWXuEQEAy5X8iQ>: Debug: Mailbox INBOX: Mailbox opened because: copy caching decisions Dec 01 08:54:22 doveadm(user1)<70126><qfzHDjyfaWXuEQEAy5X8iQ>: Warning: Deleting mailbox 'Archiv.Allgemein unsortiert': UID=1 GUID=1350559209.P2052Q54.lin-mail1.intra is missing locally Dec 01 08:54:22 doveadm(user1)<70126><qfzHDjyfaWXuEQEAy5X8iQ>: Debug: brain M: Import Archiv.Allgemein unsortiert: Import change type=save GUID=1350559209.P2052Q54.mail1.intra UID=1 > hdr_hash= result=Reverting local change by deleting mailbox - No more local mails found Dec 01 08:54:22 doveadm(70126): Debug: brain M: Import Archiv.Allgemein unsortiert: Saved UIDs: Dec 01 08:54:22 doveadm(70126): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9)
So it aborts on the lines above and a incomplete maildir is on the local server. so the next doveadm try say's that he can't delete INBOX , etc.
Dec 01 09:03:33 doveadm(user1)<70169><TzH+MmKhaWUZEgEAy5X8iQ>: Error: Mailbox INBOX sync: mailbox_delete failed: INBOX can't be deleted.
This a very old account on our server which was migrated over different iterations of our dovecot mailserver. The user behind the account uses outlook over years. Is the space here a problem?
Another user with a similiar issue has the following error message at the end:
Dec 01 09:22:14 doveadm(user2)<70354><RU12FsWlaWXSEgEAy5X8iQ>: Debug: Mailbox INBOX: Mailbox opened because: copy caching decisions Dec 01 09:22:56 doveadm(user2)<70354><RU12FsWlaWXSEgEAy5X8iQ>: Error: read(mua01.domain.intra) failed: EOF (last sent=mailbox, last recv=mailbox) Dec 01 09:22:56 doveadm(70354): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9)
I see that the user has a very big inbox? when i check in the source server in the "cur" folder of the INBOX it count's around 269372 mails. Is this perhaps the issue for this message?
And on the last user it looks like:
Dec 01 09:25:19 doveadm(user3)<70376><UoiQAHWmaWXoEgEAy5X8iQ>: Warning: Deleting mailbox 'Entwürfe': UID=1265 GUID=1521832311.M6830P7652.mail-mx1.intra,S=1764,W=1809 is missing locally Dec 01 09:25:19 doveadm(user3)<70376><UoiQAHWmaWXoEgEAy5X8iQ>: Debug: brain M: Import Entwürfe: Import change type=save GUID=1521832311.M6830P7652.mail-mx1.intra,S=1764,W=1809 UID=1265 hdr_hash= result=Reverting local change by deleting mailbox - No more local mails found Dec 01 09:25:19 doveadm(70376): Debug: brain M: Import Entwürfe: Saved UIDs: Dec 01 09:25:19 doveadm(70376): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9)
The "Entwürfe" folder directly cannot be the issue? On the filesystem the folder has the name ".Entw&APw-rfe" and also other users has similar folders in their mailboxes.
The source server has dovecot version 2.2.36 (centos 7.9.2009) and the current destination server dovecot version 2.3.16 (ubuntu 22.04 lts)
On 01/12/2023 11:34 EET roger.meier--- via dovecot dovecot@dovecot.org wrote:
I try to setup for our mailserver (in a dc) a job backup to a secondary server (in our office) with "doveadm backup" via the -R option. (rsync , rsnapshot and so on tooks too long at the moment)
For the most user accounts all work as expected, but for three users it always fails
First run: /usr/bin/doveadm -Dv backup -Ru user1 tcp:mua01.domain.intra:12345
Dec 01 08:54:21 doveadm(user1)<70126><qfzHDjyfaWXuEQEAy5X8iQ>: Debug: Mailbox INBOX: Mailbox opened because: copy caching decisions Dec 01 08:54:22 doveadm(user1)<70126><qfzHDjyfaWXuEQEAy5X8iQ>: Warning: Deleting mailbox 'Archiv.Allgemein unsortiert': UID=1 GUID=1350559209.P2052Q54.lin-mail1.intra is missing locally Dec 01 08:54:22 doveadm(user1)<70126><qfzHDjyfaWXuEQEAy5X8iQ>: Debug: brain M: Import Archiv.Allgemein unsortiert: Import change type=save GUID=1350559209.P2052Q54.mail1.intra UID=1 > hdr_hash= result=Reverting local change by deleting mailbox - No more local mails found Dec 01 08:54:22 doveadm(70126): Debug: brain M: Import Archiv.Allgemein unsortiert: Saved UIDs: Dec 01 08:54:22 doveadm(70126): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9)
So it aborts on the lines above and a incomplete maildir is on the local server. so the next doveadm try say's that he can't delete INBOX , etc.
Dec 01 09:03:33 doveadm(user1)<70169><TzH+MmKhaWUZEgEAy5X8iQ>: Error: Mailbox INBOX sync: mailbox_delete failed: INBOX can't be deleted.
This a very old account on our server which was migrated over different iterations of our dovecot mailserver. The user behind the account uses outlook over years. Is the space here a problem?
Another user with a similiar issue has the following error message at the end:
Dec 01 09:22:14 doveadm(user2)<70354><RU12FsWlaWXSEgEAy5X8iQ>: Debug: Mailbox INBOX: Mailbox opened because: copy caching decisions Dec 01 09:22:56 doveadm(user2)<70354><RU12FsWlaWXSEgEAy5X8iQ>: Error: read(mua01.domain.intra) failed: EOF (last sent=mailbox, last recv=mailbox) Dec 01 09:22:56 doveadm(70354): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9)
I see that the user has a very big inbox? when i check in the source server in the "cur" folder of the INBOX it count's around 269372 mails. Is this perhaps the issue for this message?
And on the last user it looks like:
Dec 01 09:25:19 doveadm(user3)<70376><UoiQAHWmaWXoEgEAy5X8iQ>: Warning: Deleting mailbox 'Entwürfe': UID=1265 GUID=1521832311.M6830P7652.mail-mx1.intra,S=1764,W=1809 is missing locally Dec 01 09:25:19 doveadm(user3)<70376><UoiQAHWmaWXoEgEAy5X8iQ>: Debug: brain M: Import Entwürfe: Import change type=save GUID=1521832311.M6830P7652.mail-mx1.intra,S=1764,W=1809 UID=1265 hdr_hash= result=Reverting local change by deleting mailbox - No more local mails found Dec 01 09:25:19 doveadm(70376): Debug: brain M: Import Entwürfe: Saved UIDs: Dec 01 09:25:19 doveadm(70376): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9)
The "Entwürfe" folder directly cannot be the issue? On the filesystem the folder has the name ".Entw&APw-rfe" and also other users has similar folders in their mailboxes.
The source server has dovecot version 2.2.36 (centos 7.9.2009) and the current destination server dovecot version 2.3.16 (ubuntu 22.04 lts)
Try deleting the target mailbox completely. This usually sorts these kind of things out. Also please see https://doc.dovecot.org/admin_manual/migrating_mailboxes/
Aki
Hi Aki
I wondered, why is my answere here missing in the mailing list and now see that the answer was directly to your email adress. ( i only pressed answer in thunderbird and don't looked a the recipient, so i now use the webui )
My Answer was:
I already tried to deleting of the destination folder. The folder is then freshly created via doveadm, but is unfinished because the backup jobs aborts on the > messages mentioned above. If i don't delete the destination folder, the backup job gives me a clearer error message:
doveadm(user3)<68274></THVECElaWWyCgEAy5X8iQ>: Error: Mailbox INBOX sync: mailbox_delete failed: INBOX can't be deleted.
The other 450 accounts on the server have no issue and doveadm backup works as expected.
I don't have any special namespaces configured on the server or acls. The server is a simple setup, mariadb as user backend and most settings are default settings. I enabled managesieve for filtering.
Also the logfiles on the source server don't give me more hints, what the issue could be.
I also do some tests since then, when i completly remove the folder/mailbox and den start the sync again it's always aborts on a different mail/position
/usr/bin/doveadm -D -v backup -Ru user3 tcp:mua01.zh01.4s-zh.intra:12345
Dec 13 11:03:47 doveadm(user3)<150241><jksWEI6PeWXhSgIAy5X8iQ>: Debug: brain M: Import Archives.2022: Import change type=expunge GUID=<unknown> UID=7 hdr_hash= result=Expunged mail not found locally Dec 13 11:03:47 doveadm(user3)<150241><jksWEI6PeWXhSgIAy5X8iQ>: Warning: Deleting mailbox 'Archives.2022': UID=8 GUID=1659511136.M535616P21860.mail1.intra,S=4965,W=5057 is missing locally Dec 13 11:03:47 doveadm(user3)<150241><jksWEI6PeWXhSgIAy5X8iQ>: Debug: brain M: Import Archives.2022: Import change type=save GUID=1659511136.M535616P21860.mail1.intra,S=4965,W=5057 UID=8 hdr_hash= result=Reverting local change by deleting mailbox - No more local mails found Dec 13 11:03:47 doveadm(150241): Debug: brain M: Import Archives.2022: Saved UIDs: Dec 13 11:03:47 doveadm(150241): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9)
or
Dec 13 11:09:47 doveadm(user3)<150308><amjnGveQeWUkSwIAy5X8iQ>: Debug: brain M: Import Archives.2023: Import change type=expunge GUID=<unknown> UID=1 hdr_hash= result=Expunged mail not found locally Dec 13 11:09:47 doveadm(user3)<150308><amjnGveQeWUkSwIAy5X8iQ>: Warning: Deleting mailbox 'Archives.2023': UID=2 GUID=1681916185.M428555P22295.mail1.intra,S=160923,W=163399 is missing locally Dec 13 11:09:47 doveadm(user3)<150308><amjnGveQeWUkSwIAy5X8iQ>: Debug: brain M: Import Archives.2023: Import change type=save GUID=1681916185.M428555P22295.mail1.intra,S=160923,W=163399 UID=2 hdr_hash= result=Reverting local change by deleting mailbox - No more local mails found Dec 13 11:09:47 doveadm(150308): Debug: brain M: Import Archives.2023: Saved UIDs: Dec 13 11:09:47 doveadm(150308): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9)
On the source server it looks then like this:
Dec 13 12:09:44 mail1.intra dovecot: doveadm: Debug: brain S: Mailbox Notes: local=ebb1da135a923659d72400009c0bcd07/0/1, remote=00000000000000000000000000000000/0/0: mailbox not selectable yet Dec 13 12:09:44 mail1.intra dovecot: doveadm: Debug: brain S: Mailbox Sent: local=8d6c930873a63459521600009c0bcd07/0/1, remote=00000000000000000000000000000000/0/0: mailbox not selectable yet Dec 13 12:09:44 mail1.intra dovecot: doveadm: Debug: brain S: Mailbox Sent Messages: local=3d9ceb18dae35f59753a00009c0bcd07/0/1, remote=00000000000000000000000000000000/0/0: mailbox not selectable yet Dec 13 12:09:44 mail1.intra dovecot: doveadm: Debug: brain S: Mailbox Spam: local=03b2da135a923659d72400009c0bcd07/0/1, remote=00000000000000000000000000000000/0/0: mailbox not selectable yet Dec 13 12:09:44 mail1.intra dovecot: doveadm: Debug: brain S: Mailbox Trash: local=0c644e24dad134593b6b00009c0bcd07/0/1, remote=00000000000000000000000000000000/0/0: mailbox not selectable yet Dec 13 12:09:46 mail1.intra dovecot: doveadm: Debug: brain S: Skipping unchanged mailbox 40303c0fb2fc015d9c6d0000b5363f5c Dec 13 12:09:46 mail1.intra dovecot: doveadm: Debug: brain S: Skipping unchanged mailbox cf131a0513dd926057390000449ae907 Dec 13 12:09:46 mail1.intra dovecot: doveadm: Debug: Mailbox Archives.2022: Opened mail UID=8 because: prefetch Dec 13 12:09:46 mail1.intra dovecot: doveadm: Debug: Mailbox Archives.2022: Opened mail UID=8 because: access Dec 13 12:09:46 mail1.intra dovecot: doveadm: Debug: Mailbox Archives.2022: Opened mail UID=8 because: mail stream Dec 13 12:09:46 mail1.intra dovecot: doveadm: Debug: Mailbox Archives.2022: Opened mail UID=10 because: prefetch Dec 13 12:09:46 mail1.intra dovecot: doveadm: Debug: Mailbox Archives.2022: Opened mail UID=10 because: access Dec 13 12:09:46 mail1.intra dovecot: doveadm: Debug: Mailbox Archives.2022: Opened mail UID=10 because: mail stream
Because, that perhaps the version missmatch of the servers coul'd be the issue , and centos 7 eol comes in two months, i setup a complete new main mailserver, based on ubuntu 22.04 (24.04 was not out on starting to setup the stuff) so now both servers had dovecot 2.3.16.
But it doesn't help, still the backup jobs abort in the middle of the transfer, now with complete different error messages.
On the destination server i started it with the following command ( the corresponding user folder & files is deleted under /var/spool/vmail and /var/indexes )
/usr/bin/doveadm -D -v backup -t 1200 -Ru user1 tcp:mua02.domain.intra:12345
The first run is finished with the following:
Apr 29 09:36:26 doveadm(user1)<56317><HR0xHXlML2b92wAAy5X8iQ>: Debug: brain M: Import Sent Messages: Saved UIDs: 3127:3144 Apr 29 09:36:26 doveadm(user1)<56317><HR0xHXlML2b92wAAy5X8iQ>: Debug: brain M: Import Sent Messages: Finish update: min_next_uid=3145 min_first_recent_uid=3145 min_highest_modseq=8 min_highest_pvt_modseq=0 Apr 29 09:36:26 doveadm(user1)<56317><HR0xHXlML2b92wAAy5X8iQ>: Debug: brain M: Import Sent Messages: Reassign UIDs: 5,15:16,56,79:82,90,97,138,158,168,173,176,183:185,201,207,218:220,250:252,254:257,281,285,289,333,336:337,348,351:366,370,389,414,431:432,437:441,444:446,461,534,577:584,610:611,628,632,646,653,655:657,665:668,671:674,701,704,720:721,743:749,808:809,835,844:845,868,870,872:873,878:879,888:894,909:910,921,955:958,1055:1076,1104:1106,1115:1120,1135,1175,1179,1181,1184:1187,1193:1195,1205,1222:1224,1272:1273,1276:1279,1282:1284,1287,1294,1298,1306:1309,1312,1351,1374,1380:1384,1395,1408,1416,1419:1420,1448,1450:1456,1473:1476,1478:1479,1488:1491,1507:1509,1511:1512,1517:1520,1535:1540,1550,1559:1563,1565:1567,1570:1571,1576,1578:1582,1585:1590,1596:1598,1600:1602,1607:1609,1620:1622,1624:1630,1633,1641,1646:1649,1672:1673,1676:1680,1688,1712:1715,1727:1728,1733,1741,1754:1755,1766,1775:1776,1778:1792,1795,1811:1825,1838:1846,1848:1849,1851,1854,1856,1858,1861,1863,1865:1870,1886:1892,1898:1904,1916:1919,1924,1927,1929:1931,1937,1969:1984,1991,1993,2000:2002,2007:2022,2024,2036,2039,2044:2047,2052:2074,2078:2080,2092,2108,2117:2120,2124,2126,2130:2153,2163:2165,2170,2177:2178,2181:2184,2186,2189,2192,2194:2195,2200:2205,2208,2219:2246,2258,2269:2270,2273,2281:2287,2292:2298,2300:2301,2305:2323,2325:2326,2344,2346:2350,2378:2382,2386,2388,2390:2393,2395,2400,2409,2416:2417,2425:2429,2439,2443:2447,2460,2468:2470,2476,2494,2496,2504,2521:2526,2536,2546:2547,2552:2555,2608,2616,2618,2621,2631:2632,2637:2638,2663,2676:2679,2718:2721,2728:2730,2746,2748:2749,2756:2759,2764:2765,2767,2770:2779,2781,2790:2794,2819,2825,2838,2842:2843,2854,2860,2862:2866,2871,2887,2897:2900,2939,2972:2976,2986,3001:3004,3014:3015,3024:3026,3030:3035,3048,3076:3079,3113:3116
And when i start the second run (for update the changes):
r 29 09:39:38 doveadm(user1)<56385><RtY+IrlOL2ZB3AAAy5X8iQ>: Panic: file dsync-mailbox-import.c: line 1368 (dsync_mailbox_import_want_change): assertion failed: (change->received_timestamp > 0) Apr 29 09:39:38 doveadm(user1)<56385><RtY+IrlOL2ZB3AAAy5X8iQ>: Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(backtrace_append+0x46) [0x7f5f6d233de6] -> /usr/lib/dovecot/libdovecot.so.0(backtrace_get+0x22) [0x7f5f6d233f02] -> /usr/lib/dovecot/libdovecot.so.0(+0x109cdb) [0x7f5f6d240cdb] -> /usr/lib/dovecot/libdovecot.so.0(+0x109d17) [0x7f5f6d240d17] -> /usr/lib/dovecot/libdovecot.so.0(+0x5cf73) [0x7f5f6d193f73] -> /usr/bin/doveadm(+0x24475) [0x55cfe91a4475] -> /usr/bin/doveadm(dsync_mailbox_import_change+0x25b) [0x55cfe91d715b] -> /usr/bin/doveadm(dsync_brain_sync_mails+0x2ac) [0x55cfe91d25ec] -> /usr/bin/doveadm(dsync_brain_run+0x228) [0x55cfe91ce358] -> /usr/bin/doveadm(+0x4e96d) [0x55cfe91ce96d] -> /usr/bin/doveadm(+0x5fdf3) [0x55cfe91dfdf3] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x6d) [0x7f5f6d256f8d] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x13a) [0x7f5f6d25868a] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x54) [0x7f5f6d257034] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x40) [0x7f5f6d2571f0] -> /usr/bin/doveadm(+0x356ac) [0x55cfe91b56ac] -> /usr/bin/doveadm(+0x3665d) [0x55cfe91b665d] -> /usr/bin/doveadm(+0x37112) [0x55cfe91b7112] -> /usr/bin/doveadm(doveadm_mail_try_run+0x24a) [0x55cfe91b7a9a] -> /usr/bin/doveadm(main+0x4dc) [0x55cfe91a6f8c] -> /lib/x86_64-linux-gnu/libc.so.6(+0x29d90) [0x7f5f6cdf8d90] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80) [0x7f5f6cdf8e40] -> /usr/bin/doveadm(_start+0x25) [0x55cfe91a70a5] Aborted (core dumped)
Both servers are synced with the same ntp servers and have the same time when i check it.
participants (2)
-
Aki Tuomi
-
roger.meier＠4synergy.com