backupd IOERROR reading backup files larger than 2GB

Sun Jun 16 20:44:16 EDT 2019

Hi Carlos,

Sudden overnight intuition, and I think this will fix the issue -- the problem isn't that the lseek is failing at >2GB; the problem is that its off_t return value is being truncated to an int before being checked to see if it's negative for the error case (so any "I succeeded, the offset is > 2GB" response looks like "negative, it's an error"). Doh!

I think this will fix the immediate issue:
https://github.com/cyrusimap/cyrus-imapd/commit/63f8c09fa2076c0e2fa55436e071e3e341fe48b6

But then I found and fixed some similar ones:
https://github.com/cyrusimap/cyrus-imapd/commit/0930d3af4ed9bd44d328db8cfa4d9f2e2be7bada

Remains to be seen whether more similar issues pop up -- since no-one's tripped over this previously, I guess you're the first person to try this with a >2GB backup file :(

Cheers,

ellie

On Fri, Jun 14, 2019, at 3:50 PM, ellie timoney wrote:
> Hi Carlos,
> 
> This is quite weird, I'm not sure why a 64bit platform would have any trouble around the 2GB mark??
> 
> What does the Cyrus ./configure report for your system's integer sizes? e.g. mine shows:
> 
>> checking size of int... 4 
>> checking size of long... 8 
>> checking size of size_t... 8 
>> checking size of off_t... 8 
>> checking size of time_t... 8 
>> checking size of long long int... 8 
>> checking size of unsigned long long int... 8 
>> checking whether byte ordering is bigendian... no
> 
> What's your level of comfort with C debugging? It'd be very helpful to see a core file+binary from the time that lseek error occurs?
> 
> Cheers,
> 
> ellie
> 
> On Fri, Jun 7, 2019, at 1:58 AM, Carlos Larrañaga wrote:
>> Hi Ellie,
>> 
>>  Thanks for answering. We use latest 64bit Oracle Linux (not CentOs like I said before, sorry) and zlib is also 64bit version:
>>> # uname -a
>>> Linux xxx 3.10.0-957.12.2.el7.x86_64 #1 SMP Tue May 14 17:35:45 PDT 2019 x86_64 x86_64 x86_64 GNU/Linux
>>> 
>>> # yum list installed zlib
>>> Loaded plugins: langpacks, ulninfo
>>> Installed Packages
>>> zlib.x86_64 1.2.7-18.el7 @ol7_latest
>>> 
>>>  # lsof -p 17005 |grep lib |grep -i z
>>>  backupd 17005 cyrus mem REG 253,0 90248 134400930 /usr/lib64/libz.so.1.2.7
>>> 
>>>  # file /usr/lib64/libz.so.1.2.7
>>>  /usr/lib64/libz.so.1.2.7: ELF 64-bit LSB shared object, x86-64, version 1 (SYSV), dynamically linked, BuildID[sha1]=b9d5f73428bd6ad68c96986b57bea3b7cedb9745, stripped
>>> 
>>>  # rpm -qf /usr/lib64/libz.so.1.2.7
>>>  zlib-1.2.7-18.el7.x86_64
>> I have summarized here some information about the backupd error reading the file descriptor 15, which is a backup larger than 2GB. The error is logged 1755 times. Instead, there is no error for fd 12, which is a backup of less than 2 GB:
>>> *#-- CLIENT SIDE*
>>> *-----------------------------------------------*
>>> 
>>> 
>>> # time sync_client -v -o -n backup -A
>>> Thu Jun 6 17:08:02 CEST 2019
>>> USER aaa
>>> QUOTA user.aaa
>>> USER ccc
>>> Error from do_user(ccc): bailing out!
>>> 
>>> real 30m16.223s
>>> user 0m0.006s
>>> sys 0m0.006s
>>> **
>>> 
>>> *#-- BACKUP SERVER SIDE ----------------------------------------*
>>> # LOGFILE
>>> 
>>> # tail -f /var/log/imapd.log
>>> Jun 6 17:09:11 bcrux cyrus/backupd[2584]: IOERROR: gzuc_read: lseek 15: No such file or directory
>>> Jun 6 17:09:11 bcrux cyrus/backupd[2584]: IOERROR: gzuc_read: lseek 15: No such file or directory
>>> Jun 6 17:09:11 bcrux cyrus/backupd[2584]: IOERROR: gzuc_read: lseek 15: No such file or directory
>>> Jun 6 17:09:11 bcrux cyrus/backupd[2584]: IOERROR: gzuc_read: lseek 15: No such file or directory
>>> 
>>> 
>>> *# lsof of the backupd PROCESS
*# lsof -P -p 2584 
>>> 
>>> COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
>>> backupd 2584 cyrus cwd DIR 253,0 4096 128 /
>>> backupd 2584 cyrus rtd DIR 253,0 4096 128 /
>>> backupd 2584 cyrus txt REG 253,0 768632 939542214 /usr/local/cyrus/libexec/backupd
>>> backupd 2584 cyrus mem REG 253,0 37208 135746334 /usr/lib64/libnss_sss.so.2
>>> backupd 2584 cyrus mem REG 253,0 31416 134406707 /usr/lib64/libnss_dns-2.17.so
>>> backupd 2584 cyrus mem REG 253,0 61632 134406709 /usr/lib64/libnss_files-2.17.so
>>> backupd 2584 cyrus mem REG 253,0 43336 68814977 /usr/lib64/sasl2/webmail.so.0.0.0
>>> backupd 2584 cyrus mem REG 253,0 57960 68856627 /usr/lib64/sasl2/libdigestmd5.so.3.0.0
>>> backupd 2584 cyrus mem REG 253,0 24232 68797220 /usr/lib64/sasl2/libcrammd5.so.3.0.0
>>> backupd 2584 cyrus mem REG 253,0 20088 68797044 /usr/lib64/sasl2/libplain.so.3.0.0
>>> backupd 2584 cyrus mem REG 253,0 20056 68797036 /usr/lib64/sasl2/liblogin.so.3.0.0
>>> backupd 2584 cyrus mem REG 253,0 1845816 135873512 /usr/lib64/libdb-5.3.so
>>> backupd 2584 cyrus mem REG 253,0 28272 67113426 /usr/lib64/sasl2/libsasldb.so.3.0.0
>>> backupd 2584 cyrus mem REG 253,0 20064 67113423 /usr/lib64/sasl2/libanonymous.so.3.0.0
>>> backupd 2584 cyrus mem REG 253,0 11448 135872733 /usr/lib64/libfreebl3.so
>>> backupd 2584 cyrus mem REG 253,0 155784 134400716 /usr/lib64/libselinux.so.1
>>> backupd 2584 cyrus mem REG 253,0 15464 134401447 /usr/lib64/libkeyutils.so.1.5
>>> backupd 2584 cyrus mem REG 253,0 40672 134399432 /usr/lib64/libcrypt-2.17.so
>>> backupd 2584 cyrus mem REG 253,0 105824 134781819 /usr/lib64/libresolv-2.17.so
>>> backupd 2584 cyrus mem REG 253,0 53944 134406785 /usr/lib64/libjansson.so.4.10.0
>>> backupd 2584 cyrus mem REG 253,0 88776 135352942 /usr/lib64/libgcc_s-4.8.5-20150702.so.1
>>> backupd 2584 cyrus mem REG 253,0 1137032 134400337 /usr/lib64/libm-2.17.so
>>> backupd 2584 cyrus mem REG 253,0 991616 135352396 /usr/lib64/libstdc++.so.6.0.19
>>> backupd 2584 cyrus mem REG 253,0 19296 134399434 /usr/lib64/libdl-2.17.so
>>> backupd 2584 cyrus mem REG 253,0 142008 134722750 /usr/lib64/libpthread-2.17.so
>>> backupd 2584 cyrus mem REG 253,0 2151704 134365659 /usr/lib64/libc-2.17.so
>>> backupd 2584 cyrus mem REG 253,0 753232 134401161 /usr/lib64/libsqlite3.so.0.8.6
>>> backupd 2584 cyrus mem REG 253,0 90248 134400930 /usr/lib64/libz.so.1.2.7
>>> backupd 2584 cyrus mem REG 253,0 11128 134400947 /usr/lib64/libpcreposix.so.0.0.1
>>> backupd 2584 cyrus mem REG 253,0 402384 134400940 /usr/lib64/libpcre.so.1.2.0
>>> backupd 2584 cyrus mem REG 253,0 67104 135269427 /usr/lib64/libkrb5support.so.0.1
>>> backupd 2584 cyrus mem REG 253,0 15920 135873508 /usr/lib64/libcom_err.so.2.1
>>> backupd 2584 cyrus mem REG 253,0 210832 134781960 /usr/lib64/libk5crypto.so.3.1
>>> backupd 2584 cyrus mem REG 253,0 967864 134781967 /usr/lib64/libkrb5.so.3.3
>>> backupd 2584 cyrus mem REG 253,0 320400 134781952 /usr/lib64/libgssapi_krb5.so.2.2
>>> backupd 2584 cyrus mem REG 253,0 115856 134400341 /usr/lib64/libnsl-2.17.so
>>> backupd 2584 cyrus mem REG 253,0 42168 134401419 /usr/lib64/libwrap.so.0.7.6
>>> backupd 2584 cyrus mem REG 253,0 2516640 134400708 /usr/lib64/libcrypto.so.1.0.2k
>>> backupd 2584 cyrus mem REG 253,0 470360 134400711 /usr/lib64/libssl.so.1.0.2k
>>> backupd 2584 cyrus mem REG 253,0 121208 134401258 /usr/lib64/libsasl2.so.3.0.0
>>> backupd 2584 cyrus mem REG 253,0 2898664 838888996 /usr/local/cyrus/lib/libcyrus_imap.so.0.0.0
>>> backupd 2584 cyrus mem REG 253,0 599528 838888999 /usr/local/cyrus/lib/libcyrus_sieve.so.0.0.0
>>> backupd 2584 cyrus mem REG 253,0 20112 134406704 /usr/lib64/libuuid.so.1.3.0
>>> backupd 2584 cyrus mem REG 253,0 20781704 136182553 /usr/lib64/libicudata.so.50.1.2
>>> backupd 2584 cyrus mem REG 253,0 1539544 136197152 /usr/lib64/libicuuc.so.50.1.2
>>> backupd 2584 cyrus mem REG 253,0 553264 838890012 /usr/local/cyrus/lib/libcyrus_min.so.0.0.0
>>> backupd 2584 cyrus mem REG 253,0 1961968 838888994 /usr/local/cyrus/lib/libcyrus.so.0.0.0
>>> backupd 2584 cyrus mem REG 253,0 163408 134355369 /usr/lib64/ld-2.17.so
>>> backupd 2584 cyrus 0u IPv4 2092952 0t0 TCP hostb1.upv.es:2005->host1.upv.es:27107 (ESTABLISHED)
>>> backupd 2584 cyrus 1u IPv4 2092952 0t0 TCP hostb1.upv.es:2005->host1.upv.es:27107 (ESTABLISHED)
>>> backupd 2584 cyrus 2u IPv4 2092952 0t0 TCP hostb1.upv.es:2005->host1.upv.es:27107 (ESTABLISHED)
>>> backupd 2584 cyrus 3w FIFO 0,9 0t0 2141764 pipe
>>> backupd 2584 cyrus 4u IPv4 2141763 0t0 TCP hostb1.upv.es:2005 (LISTEN)
>>> backupd 2584 cyrus 5u REG 0,20 0 86644 /run/cyrus-b1/socket/backupd-0.lock
>>> backupd 2584 cyrus 6r FIFO 0,9 0t0 2141754 pipe
>>> backupd 2584 cyrus 7w FIFO 0,9 0t0 2141754 pipe
>>> backupd 2584 cyrus 8r FIFO 0,9 0t0 2141755 pipe
>>> backupd 2584 cyrus 9w FIFO 0,9 0t0 2141755 pipe
>>> backupd 2584 cyrus 10u unix 0xffff9d9df53d4400 0t0 2093417 socket
>>> backupd 2584 cyrus 11w REG 253,5 680 18253611600 /b1/lib/log/admin/backupd-2584
>>> backupd 2584 cyrus 12uW REG 253,5 976281587 13958644353 /b1/bck/b1/a/aaa_ouuUx9
>>> backupd 2584 cyrus 13ur REG 253,5 3573760 13958644354 /b1/bck/b1/a/aaa_ouuUx9.index
>>> backupd 2584 cyrus 14u REG 253,5 2576 13958644355 /b1/bck/b1/a/aaa_ouuUx9.index-journal
>>> backupd 2584 cyrus 15uW REG 253,5 3104341527 12884902595 /b1/bck/b1/c/ccc_Mqmymx
>>> backupd 2584 cyrus 16u REG 253,5 47927296 12884902596 /b1/bck/b1/c/ccc_Mqmymx.index
>>> 
>>> *# BACKUP SIZES*
>>>  # ls -lh /b1/bck/b1/a/*
>>> /b1/bck/b1/c/* 
>>> *-rw------- 1 cyrus mail 932M Jun 6 17:08*
>>> /b1/bck/b1/a/*aaa_ouuUx9*
>>> -rw------- 1 cyrus mail 3.5M Jun 6 16:46
>>> /b1/bck/b1/a/aaa_ouuUx9.index
>>> -rw------- 1 cyrus mail 2.6K Jun 6 17:08
>>> /b1/bck/b1/a/aaa_ouuUx9.index-journal
>>> 
>>> -rw------- 1 cyrus mail 2.9G Jun 6 17:01 /b1/bck/b1/c/ccc_Mqmymx
>>> -rw------- 1 cyrus mail 46M Jun 6 17:01 /b1/bck/b1/c/ccc_Mqmymx.index
>>> 
>>> *# IMAP SESSION DEBUG*
>>> # cat /b1/lib/log/admin/backupd-2584
>>> ---------- admin Thu Jun 6 17:08:02 2019
>>> 
>>> <1559833682<COMPRESS DEFLATE
>>> >1559833682>OK DEFLATE active
>>> <1559833682<GET USER aaa
>>> >1559833698>* MAILBOX %(UNIQUEID acd014aa-7b1d-43c9-b1d3-f97b06540739 MBOXNAME user.aaa MBOXTYPE NIL LAST_UID 0 HIGHESTMODSEQ 2 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 UIDVALIDITY 1520512152 PARTITION default ACL "aaa lrswipkxtecdan group:super lrswipkxtecdan " OPTIONS P SYNC_CRC 0 SYNC_CRC_ANNOT 0 QUOTAROOT NIL XCONVMODSEQ 0)
>>> OK Success
>>> <1559833698<APPLY QUOTA %(ROOT user.aaa LIMIT 5120000 STORAGE 5120000)
>>> >1559833698>OK Success
>>> <1559833698<GET USER ccc
>> 
>> Best regards,
>> Carlos
>> 
>> 
>> 
>> El 06/06/2019 a las 4:04, ellie timoney escribió:
>>> It kinda sounds like your platform might be 32bit? Or your zlib is compiled to use 32bit integer sizes?
>>> 
>>> On Mon, Jun 3, 2019, at 10:07 PM, Carlos Larrañaga wrote:
>>>> Hi,
>>>> 
>>>> We're testing backup feature un cyrus-imapd 3.0.10. There's no problem when backup is created first time, but when the backup already exists and is larger than 2GB, we get the following error from the backupd: 
>>>>> cyrus/backupd[xxxx]: IOERROR: gzuc_read: lseek 12: No such file or directory
>>>> As said, it happens only when then backup file already exists and is larger than 2GB. The backupd process keeps reading de compressed backup file til sync_client exit with "Error from sync_do_user(xxx): bailing out!".
>>>> 
>>>>  We use xfs with latest CentOs. Seems like backupd is unable to read the compressed backup file.
>>>> 
>>>>  Anyone else with this problem? Any idea how to fix it? 
>>>> Thanks in advance for your help.
>>>> 
>>>>  Best regards,
>>>>  Carlos.
>>>> ----
>>>> 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
>>>> 
>>>> *Attachments:*
>>>>  * smime.p7s
>>> 
>>> 
>>> ----
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
>> 
>> 
>> *Attachments:*
>>  * smime.p7s
> 
> ----
> 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 --------------
An HTML attachment was scrubbed...
URL: <http://lists.andrew.cmu.edu/pipermail/info-cyrus/attachments/20190617/c71cff80/attachment-0001.html>