Bug 13317 - rsync returns success when target filesystem is full
Summary: rsync returns success when target filesystem is full
Status: NEW
Alias: None
Product: rsync
Classification: Unclassified
Component: core (show other bugs)
Version: 3.1.2
Hardware: x64 FreeBSD
: P5 major (vote)
Target Milestone: ---
Assignee: Wayne Davison
QA Contact: Rsync QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-03-01 16:38 UTC by Rui DeSousa
Modified: 2018-03-07 23:26 UTC (History)
0 users

See Also:


Attachments
Test patch to see whether fdatasync() or fsync() detects a write failure (987 bytes, patch)
2018-03-06 19:57 UTC, Dave Gordon
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Rui DeSousa 2018-03-01 16:38:07 UTC
rsync returns success when the target filesystem is full (ZFS using quotas).  It leaves a corrupted truncated or sparsely populated file on the target while returning success.

i.e. Target system does not have enough space; however the rsync does not fail on the syncing of the file but on the rename of file.  If however, there is just enough space left over for the rename; then the complete operation is marked as success and a truncated or corrupted sparse file is left on the target filesystem.  This causes issues with application that rely on the return code like Postgresql's archive process which will then delete the original WAL file after a success code is returned.  The result is that WAL file was never archive properly resulting in corrupted database backup.   

[postgres@hades ~/dbc1/pg_wal]$ rsync -a 000000010000005B00000035 ~/arch/dbc1/wal/000000010000005B00000035 
rsync: rename "/usr/home/postgres/arch/dbc1/wal/.000000010000005B00000035.6bjO94" -> "000000010000005B00000035": Disc quota exceeded (69) 
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1200) [sender=3.1.2] 


i.e. more detail example: 

https://www.postgresql.org/message-id/21AF0CB4-0873-4960-BA14-E72FA08B352E%40icloud.com
Comment 1 Kevin Korb 2018-03-01 17:07:50 UTC
Are you saying that it is exiting with an exit code of 0 after outputting that error or that sometimes in the same condition it shows no error and exits code 0?  Either way it would probably be helpful to see an output with -v and -i.

Also, in your link, that isn't what -c does.  It does not verify that the file was transferred correctly.
Comment 2 Rui DeSousa 2018-03-01 17:18:23 UTC
(In reply to Kevin Korb from comment #1)

I saying that in some cases the rename does not fail; and in those cases it returns success despite there not being enough space to store the original file.  It looks like it should have error before the rename occurs but does not; thus leaving a truncated or sparsely populated file.
Comment 3 Dave Gordon 2018-03-05 20:26:41 UTC
(In reply to Rui DeSousa from comment #2)

Here's a snippet from Oracle's ZFS help ...
https://docs.oracle.com/cd/E19253-01/819-5461/gitfx/index.html

"Enforcement of user and group quotas might be delayed by several seconds. This delay means that users might exceed their quota before the system notices that they are over quota and refuses additional writes with the EDQUOT error message."

So, rsync(1) might
(a) successfully write a bunch of data that falls just short of the quota,
(b) "successfully" (i.e. with no reported error) write some more that takes it over quota
(c) close the file (ignoring any result)
(d) rename the file -- which may or may not work.

ZFS probably notices the quota problem somewhere between (b) and (c), drops the excess data, and returns EDQUOT to the close(2) call.

The success of the rename depends only on whether there is sufficient free space at that instant; any previous failure in writing the file won't affect the rename directly. Rename may not always need any extra space anyway.

BTW: apropos your comment about "cat" in thread
https://www.postgresql.org/message-id/E6AB850C-D05E-405B-8D4E-DE18E128F402%40icloud.com
it's not the cat that makes this reliable, it's the ssh! :)

HTH,
.Dave.
Comment 4 Dave Gordon 2018-03-05 20:42:39 UTC
To see whether rsync is getting any errors reported by any system calls it makes, one could run it under strace(1) on Linux, or dtrace on Solaris. Presumably FreeBSD has at least one of these, or something similar?

Linux:
$ strace -ff -o rsync-trace -e trace=file,desc rsync ...
$ grep -w 'E[[:upper:][:digit:]]*' rsync-trace.*
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/etc/popt", O_RDONLY)         = -1 ENOENT (No such file or directory)
open("/etc/popt", O_RDONLY)             = -1 ENOENT (No such file or directory)
stat("/etc/popt.d", 0x7ffdafe82860)     = -1 ENOENT (No such file or directory)

The output is a list of all filename- or descriptor-related syscalls that failed. If any of them show up as EDQUOT or relate to the problematic output file, that might be a big clue :)

HTH,
.Dave.
Comment 5 Rui DeSousa 2018-03-05 22:05:17 UTC
(In reply to Dave Gordon from comment #4)

Hi Dave,

I'm not seeing any errors on the write calls. Would an fsync() be required to force the error?

[postgres@hades ~]$ grep ERR rsync.test.log 
52419: lstat("/usr/local/etc/libmap.d",0x7fffffffc728) ERR#2 'No such file or directory'
52419: access("/lib/libiconv.so.2",F_OK)	 ERR#2 'No such file or directory'
52419: access("/usr/lib/libiconv.so.2",F_OK)	 ERR#2 'No such file or directory'
52419: access("/usr/lib/compat/libiconv.so.2",F_OK) ERR#2 'No such file or directory'
52419: readlink("/etc/malloc.conf",0x7fffffffd7e0,1024) ERR#2 'No such file or directory'
52419: openat(AT_FDCWD,"/etc/popt",O_RDONLY,00)	 ERR#2 'No such file or directory'
52419: openat(AT_FDCWD,"/usr/home/postgres/.popt",O_RDONLY,00) ERR#2 'No such file or directory'
52881: stat("arch/000000010000005E00000017",0x7fffffffca10) ERR#2 'No such file or directory'
52881: __acl_get_file(0x455d12,0x3,0x8012ca000)	 ERR#22 'Invalid argument'
52881: lstat("000000010000005E00000017",0x7fffffffbc60) ERR#2 'No such file or directory'
52987: openat(AT_FDCWD,"000000010000005E00000017",O_RDONLY,00) ERR#2 'No such file or directory'
52987: __acl_get_file(0x455d12,0x3,0x8012ca000)	 ERR#22 'Invalid argument'
52987: rename(".000000010000005E00000017.kmkocG","000000010000005E00000017") ERR#69 'Disc quota exceeded'
52987: stat("/usr/share/nls/C/libc.cat",0x7fffffff9e28) ERR#2 'No such file or directory'
52987: stat("/usr/share/nls/libc/C",0x7fffffff9e28) ERR#2 'No such file or directory'
52987: stat("/usr/local/share/nls/C/libc.cat",0x7fffffff9e28) ERR#2 'No such file or directory'
52987: stat("/usr/local/share/nls/libc/C",0x7fffffff9e28) ERR#2 'No such file or directory'
52987: select(1,{ 0 },{ },{ 0 },{ 60.000000 })	 ERR#4 'Interrupted system call'
52881: nanosleep({ 0.020000000 })		 ERR#4 'Interrupted system call'
52881: wait4(-1,0x7fffffffc3d4,WNOHANG,0x0)	 ERR#10 'No child processes'
52881: sigreturn(0x7fffffffc400)		 ERR#4 'Interrupted system call'
52881: wait4(52987,0x7fffffffc9d4,WNOHANG,0x0)	 ERR#10 'No child processes'
52419: nanosleep({ 0.020000000 })		 ERR#4 'Interrupted system call'
52419: wait4(-1,0x7fffffffc4d4,WNOHANG,0x0)	 ERR#10 'No child processes'
52419: sigreturn(0x7fffffffc500)		 ERR#4 'Interrupted system call'
52419: wait4(52881,0x7fffffffcaf4,WNOHANG,0x0)	 ERR#10 'No child processes'
52419: wait4(52881,0x7fffffffcaf4,WNOHANG,0x0)	 ERR#10 'No child processes'
Comment 6 Rui DeSousa 2018-03-05 23:09:53 UTC
(In reply to Rui DeSousa from comment #5)

It looks like no error is returned and result is a sparse file. I think a sync() would be required otherwise the file is truncated on close to meet the quota.  

[postgres@hades ~]$ df -h arch 
Filesystem                  Size    Used   Avail Capacity  Mounted on
hydra/home/postgres/arch    1.0G    1.0G    316K   100%    /usr/home/postgres/arch

[postgres@hades ~]$ rsync -av --inplace 000000010000005E00000017 arch/000000010000005E00000017
sending incremental file list
000000010000005E00000017

sent 67,125,370 bytes  received 35 bytes  8,950,054.00 bytes/sec
total size is 67,108,864  speedup is 1.00
[postgres@hades ~]$ ls -lh  arch/000000010000005E00000017
-rw-------  1 postgres  postgres    64M Mar  5 16:02 arch/000000010000005E00000017
[postgres@hades ~]$ du -h  arch/000000010000005E00000017
362K	arch/000000010000005E00000017


Here's example of dd exceeding the quota; however, it ends up with a truncated file instead of it being sparse.  

[postgres@hades ~/arch]$ dd if=/dev/random of=test.dmp bs=256k
^C3080+0 records in
2+6156 records out
807403520 bytes transferred in 10.843296 secs (74461081 bytes/sec)
[postgres@hades ~/arch]$ ls -lh test.dmp 
-rw-r--r--  1 postgres  postgres   384K Mar  5 18:05 test.dmp
[postgres@hades ~/arch]$ du -h test.dmp 
393K	test.dmp
Comment 7 Dave Gordon 2018-03-05 23:57:33 UTC
(In reply to Rui DeSousa from comment #5)

That was a run where the rename failed. Do you know whether the temporary file was truncated or corrupted in that scenario?

[HINT: one can stop the rsync with a signal, find the temporary file, create a hardlink to it, and then let rsync resume; in the event of an error, the temporary won't disappear because of the hardlink, and then one can examine it to see what state it was in when rsync quit].

Another thing to try would be adding the options --itemize-changes and  --debug=deltasum3,recv2,io2

BTW I checked whether the return code from close() is verified, and, while there are many close() calls whose result is ignored, the specific one at the end of a file transfer *is* checked. So if ZFS did return a delayed error at that point, it would be detected and cause the transfer to fail.

.Dave.
Comment 8 Ben RUBSON 2018-03-06 00:08:27 UTC
(In reply to Dave Gordon from comment #3)
> ZFS probably notices the quota problem somewhere between (b) and (c), drops the excess data, and returns EDQUOT to the close(2) call.

(In reply to Dave Gordon from comment #7)
> So if ZFS did return a delayed error at that point, it would be detected and cause the transfer to fail.

I confirm ZFS does not return delayed errors.
userquota are delayed, so user may store more than the userquota, however what is stored is stored.
The other types of ZFS quotas, quota and refquota, are not delayed and ZFS extremely takes care to the last bytes stored around the limit to return EDQUOT after the very last allowed bytes (throughput is then here terribly slow).
Comment 9 Dave Gordon 2018-03-06 00:11:24 UTC
(In reply to Rui DeSousa from comment #6)

In your example:
$ rsync -av --inplace 000000010000005E00000017 arch/000000010000005E00000017
sending incremental file list
000000010000005E00000017

sent 67,125,370 bytes  received 35 bytes  8,950,054.00 bytes/sec
total size is 67,108,864  speedup is 1.00
$ ls -lh  arch/000000010000005E00000017
-rw-------  1 postgres  postgres    64M Mar  5 16:02 arch/000000010000005E00000017
$ du -h  arch/000000010000005E00000017
362K	arch/000000010000005E00000017

how much of the source file is non-sparse? 'Cos ZFS can "sparsify" a file if it detects that you've got big chunks of zeros. For that matter, if you've got dedup  enabled, it should be able to detect any repeated pattern that's block-sized and -aligned. That might let you create files that go over quota, since they're not really using very much space.

In your dd(1) example, do you get a different result if you source /dev/zero rather than /dev/(u)random?

.Dave.
Comment 10 Dave Gordon 2018-03-06 00:34:52 UTC
BTW, have you tried *either* --sparse *or* --preallocate (but not both together, please, as that will trigger bug 13320 - https://bugzilla.samba.org/show_bug.cgi?id=13320)

Does you get the same problem (i.e. file corruption with no reported error) with each of these, or an error, or some different type of misbehaviour?

.Dave.
Comment 11 Rui DeSousa 2018-03-06 01:51:58 UTC
(In reply to Dave Gordon from comment #7)

This is the result of hard link on the temp file where the rename failed.

root@hades:~postgres/arch # ls -lh rsync.temp ; du -h rsync.temp 
-rw-------  1 postgres  postgres   1.1M Mar  5 16:02 rsync.temp
329K	rsync.temp

The file system has LZ4 compression; thus the file is actually 19MB on disk.

root@hades:~postgres # ls -lh 000000010000005E00000017 
-rw-------  1 postgres  postgres    64M Mar  5 16:02 000000010000005E00000017
root@hades:~postgres # du -h 000000010000005E00000017 
 19M	000000010000005E00000017


Since it's using compression; I thought /dev/zero would be a bad option to test with.
Comment 12 Rui DeSousa 2018-03-06 01:56:44 UTC
(In reply to Dave Gordon from comment #10)

The sparse option errors out :).

[postgres@hades ~]$ rsync -av --sparse 000000010000005E00000017 arch/000000010000005E00000017 
sending incremental file list
000000010000005E00000017
rsync: write failed on "/usr/home/postgres/arch/000000010000005E00000017": Disc quota exceeded (69)
rsync error: error in file IO (code 11) at receiver.c(400) [receiver=3.1.2]
rsync: [sender] write error: Broken pipe (32)



[postgres@hades ~]$ rsync -av --preallocate 000000010000005E00000017 arch/000000010000005E00000017 
preallocation is not supported on this Server
rsync error: syntax or usage error (code 1) at compat.c(205) [Receiver=3.1.2]
rsync: connection unexpectedly closed (0 bytes received so far) [sender]
rsync error: error in rsync protocol data stream (code 12) at io.c(226) [sender=3.1.2]
Comment 13 Rui DeSousa 2018-03-06 02:09:25 UTC
(In reply to Rui DeSousa from comment #12)

Running truss on the --sparse option does show the error being is returned during the write call.


[postgres@hades ~]$ truss -f -o sparse.log rsync -av --sparse 000000010000005E00000017 arch/000000010000005E00000017 
sending incremental file list
000000010000005E00000017
rsync: write failed on "/usr/home/postgres/arch/000000010000005E00000017": Disc quota exceeded (69)
rsync error: error in file IO (code 11) at receiver.c(400) [receiver=3.1.2]
rsync: [sender] write error: Broken pipe (32)


[postgres@hades ~]$ grep 68408 sparse.log |grep ERR
68408: openat(AT_FDCWD,"000000010000005E00000017",O_RDONLY,00) ERR#2 'No such file or directory'
68408: write(1,"\M^W\M-P\^E\0\^A\0\0\0\0\0\^P\\^"...,1024) ERR#69 'Disc quota exceeded'
68408: stat("/usr/share/nls/C/libc.cat",0x7fffffff9dd8) ERR#2 'No such file or directory'
68408: stat("/usr/share/nls/libc/C",0x7fffffff9dd8) ERR#2 'No such file or directory'
68408: stat("/usr/local/share/nls/C/libc.cat",0x7fffffff9dd8) ERR#2 'No such file or directory'
68408: stat("/usr/local/share/nls/libc/C",0x7fffffff9dd8) ERR#2 'No such file or directory'
Comment 14 Dave Gordon 2018-03-06 13:33:49 UTC
(In reply to Rui DeSousa from comment #6)

So you now have an example which reliably produces a bad outcome (corrupted file)? With the combination of
(a) insufficient space before copying, and
(b) --inplace so that no rename is needed
you get no error from rsync but the file uses far less space than it should? And the contents are not as expected?

Perhaps you could try this sequence:
$ src=000000010000005E00000017
$ dst=arch/000000010000005E00000017
$ rm $dst
$ rsync -avi --inplace --debug=deltasum2,recv2,io2 $src $dst
$ touch $src
$ rsync -avic --inplace --debug=deltasum3,recv2,io2 $src $dst
$ md5sum $src $dst
and if the md5sum shows a discrepancy then also capture a truss listing of all the syscalls made by the first run of rsync (where the destination does not exist).

Rationale:
I'm wondering whether ZFS if able to detect that the destination file is identical to the source file (even though it's on a different logical filesystem, it's probably still in the same pool) and merge the disk blocks (retrospectively?)

So we start with a file whose logical size is 64M, but which is compressed to 19M on disk. ZFS uncompresses it on the fly and delivers 64M of data to the first rsync. rsync sequentially writes 64M, checking the success of each write. The last write should end at an offset of 64M, then the destination file is closed (and the return from that is checked). The truss listing will show how many writes were made, and whether any of them failed. ZFS will recompress (and dedup?) the written data, resulting in an unknown amount of new space being used.

The second rsync will read both the source and destination files -- presumably both now being decompressed on demand -- and compare checksums. Any mismatch here will result in (parts of) the file being retransferred; obviously, this shouldn't happen if the first transfer succeeded.

md5sum will check whether the files really do match.

HTH,
.Dave.
Comment 15 Ben RUBSON 2018-03-06 13:39:08 UTC
Rui just to be sure, which type of ZFS quota are you using ?
quota ? refquota ? userquota ?
Comment 16 Rui DeSousa 2018-03-06 15:31:57 UTC
(In reply to Ben RUBSON from comment #15)

I just set the quota property.

NAME                      PROPERTY       VALUE     SOURCE
hydra/home/postgres/arch  quota          1G        local
hydra/home/postgres/arch  reservation    none      default
hydra/home/postgres/arch  refquota       none      default
hydra/home/postgres/arch  compression    lz4       inherited from hydra/home/postgres
hydra/home/postgres/arch  compressratio  3.66x     -
Comment 17 Rui DeSousa 2018-03-06 17:11:44 UTC
(In reply to Dave Gordon from comment #14)

Here's the output you requested.  ZFS would use the same block even if it's the same data as don't have dedup enabled.

[postgres@hades ~]$ ls arch/
dbc1
[postgres@hades ~]$ du -h 000000010000005E00000017 ; df -h arch/
 19M	000000010000005E00000017
Filesystem                  Size    Used   Avail Capacity  Mounted on
hydra/home/postgres/arch    977M    975M    1.9M   100%    /usr/home/postgres/arch
[postgres@hades ~]$ rsync -avi --inplace --debug=deltasum2,recv2,io2 000000010000005E00000017 arch/000000010000005E00000017
[Receiver] safe_read(0)=4
[sender] safe_read(5)=4
[sender] safe_read(5)=1
[sender] safe_read(5)=4
sending incremental file list
server_recv(2) starting pid=64788
get_local_name count=1 arch/000000010000005E00000017
send_files mapped 000000010000005E00000017 of size 67108864
calling match_sums 000000010000005E00000017
>f+++++++++ 000000010000005E00000017
sending file_sum
false_alarms=0 hash_hits=0 matches=0
recv_files(1) starting
recv_files(000000010000005E00000017)
got file_sum
finishing 000000010000005E00000017
[receiver] send_msg_int(100, 1)
recv_files phase=1
total: matches=0  hash_hits=0  false_alarms=0 data=67108864
recv_files phase=2
recv_files finished
[receiver] send_msg(10, 8)

sent 67,125,370 bytes  received 313 bytes  2,200,842.07 bytes/sec
total size is 67,108,864  speedup is 1.00
[postgres@hades ~]$ echo $?
0
[postgres@hades ~]$ du -h arch/000000010000005E00000017; md5 000000010000005E00000017 arch/000000010000005E00000017 
1.9M	arch/000000010000005E00000017
MD5 (000000010000005E00000017) = b607d345c5527152450c02c23d778cf2
MD5 (arch/000000010000005E00000017) = f90772e440b04b63490a88e7dafeac84
[postgres@hades ~]$ touch 000000010000005E00000017 
[postgres@hades ~]$ rsync -avic --inplace --debug=deltasum3,recv2,io2 000000010000005E00000017 arch/000000010000005E00000017
[Receiver] safe_read(0)=4
[sender] safe_read(5)=4
[sender] safe_read(5)=1
[sender] safe_read(5)=4
sending incremental file list
server_recv(2) starting pid=67722
get_local_name count=1 arch/000000010000005E00000017
count=0 n=0 rem=0
send_files mapped 000000010000005E00000017 of size 67108864
calling match_sums 000000010000005E00000017
>fc.t...... 000000010000005E00000017
recv_files(1) starting
recv_files(000000010000005E00000017)
recv mapped 000000010000005E00000017 of size 67108864
data recv 32768 at 0
data recv 32768 at 32768
data recv 32768 at 65536
data recv 32768 at 98304
data recv 32768 at 131072
data recv 32768 at 163840
data recv 32768 at 196608
data recv 32768 at 229376
data recv 32768 at 262144
data recv 32768 at 294912
data recv 32768 at 327680
data recv 32768 at 360448
data recv 32768 at 393216
data recv 32768 at 425984
data recv 32768 at 458752
data recv 32768 at 491520
data recv 32768 at 524288
data recv 32768 at 557056
data recv 32768 at 589824
data recv 32768 at 622592
data recv 32768 at 655360
data recv 32768 at 688128
data recv 32768 at 720896
data recv 32768 at 753664
data recv 32768 at 786432
data recv 32768 at 819200
data recv 32768 at 851968
data recv 32768 at 884736
data recv 32768 at 917504
data recv 32768 at 950272
data recv 32768 at 983040
data recv 32768 at 1015808
data recv 32768 at 1048576
data recv 32768 at 1081344
data recv 32768 at 1114112
data recv 32768 at 1146880
data recv 32768 at 1179648
data recv 32768 at 1212416
data recv 32768 at 1245184
data recv 32768 at 1277952
data recv 32768 at 1310720
data recv 32768 at 1343488
data recv 32768 at 1376256
data recv 32768 at 1409024
data recv 32768 at 1441792
data recv 32768 at 1474560
data recv 32768 at 1507328
data recv 32768 at 1540096
data recv 32768 at 1572864
data recv 32768 at 1605632
data recv 32768 at 1638400
data recv 32768 at 1671168
data recv 32768 at 1703936
data recv 32768 at 1736704
data recv 32768 at 1769472
data recv 32768 at 1802240
data recv 32768 at 1835008
data recv 32768 at 1867776
data recv 32768 at 1900544
data recv 32768 at 1933312
data recv 32768 at 1966080
data recv 32768 at 1998848
data recv 32768 at 2031616
data recv 32768 at 2064384
data recv 32768 at 2097152
data recv 32768 at 2129920
data recv 32768 at 2162688
data recv 32768 at 2195456
data recv 32768 at 2228224
data recv 32768 at 2260992
data recv 32768 at 2293760
data recv 32768 at 2326528
data recv 32768 at 2359296
data recv 32768 at 2392064
data recv 32768 at 2424832
data recv 32768 at 2457600
data recv 32768 at 2490368
data recv 32768 at 2523136
data recv 32768 at 2555904
data recv 32768 at 2588672
data recv 32768 at 2621440
data recv 32768 at 2654208
data recv 32768 at 2686976
data recv 32768 at 2719744
data recv 32768 at 2752512
data recv 32768 at 2785280
data recv 32768 at 2818048
data recv 32768 at 2850816
data recv 32768 at 2883584
data recv 32768 at 2916352
data recv 32768 at 2949120
data recv 32768 at 2981888
data recv 32768 at 3014656
data recv 32768 at 3047424
data recv 32768 at 3080192
data recv 32768 at 3112960
data recv 32768 at 3145728
data recv 32768 at 3178496
data recv 32768 at 3211264
data recv 32768 at 3244032
data recv 32768 at 3276800
data recv 32768 at 3309568
data recv 32768 at 3342336
data recv 32768 at 3375104
data recv 32768 at 3407872
data recv 32768 at 3440640
data recv 32768 at 3473408
data recv 32768 at 3506176
data recv 32768 at 3538944
data recv 32768 at 3571712
data recv 32768 at 3604480
data recv 32768 at 3637248
data recv 32768 at 3670016
data recv 32768 at 3702784
data recv 32768 at 3735552
data recv 32768 at 3768320
data recv 32768 at 3801088
data recv 32768 at 3833856
data recv 32768 at 3866624
data recv 32768 at 3899392
data recv 32768 at 3932160
data recv 32768 at 3964928
data recv 32768 at 3997696
data recv 32768 at 4030464
data recv 32768 at 4063232
data recv 32768 at 4096000
data recv 32768 at 4128768
data recv 32768 at 4161536
data recv 32768 at 4194304
data recv 32768 at 4227072
data recv 32768 at 4259840
data recv 32768 at 4292608
data recv 32768 at 4325376
data recv 32768 at 4358144
data recv 32768 at 4390912
data recv 32768 at 4423680
data recv 32768 at 4456448
data recv 32768 at 4489216
data recv 32768 at 4521984
data recv 32768 at 4554752
data recv 32768 at 4587520
data recv 32768 at 4620288
data recv 32768 at 4653056
data recv 32768 at 4685824
data recv 32768 at 4718592
data recv 32768 at 4751360
data recv 32768 at 4784128
data recv 32768 at 4816896
data recv 32768 at 4849664
data recv 32768 at 4882432
data recv 32768 at 4915200
data recv 32768 at 4947968
data recv 32768 at 4980736
data recv 32768 at 5013504
data recv 32768 at 5046272
data recv 32768 at 5079040
data recv 32768 at 5111808
data recv 32768 at 5144576
data recv 32768 at 5177344
data recv 32768 at 5210112
data recv 32768 at 5242880
data recv 32768 at 5275648
data recv 32768 at 5308416
data recv 32768 at 5341184
data recv 32768 at 5373952
data recv 32768 at 5406720
data recv 32768 at 5439488
data recv 32768 at 5472256
data recv 32768 at 5505024
data recv 32768 at 5537792
data recv 32768 at 5570560
data recv 32768 at 5603328
data recv 32768 at 5636096
data recv 32768 at 5668864
data recv 32768 at 5701632
data recv 32768 at 5734400
data recv 32768 at 5767168
data recv 32768 at 5799936
data recv 32768 at 5832704
data recv 32768 at 5865472
data recv 32768 at 5898240
data recv 32768 at 5931008
data recv 32768 at 5963776
data recv 32768 at 5996544
data recv 32768 at 6029312
data recv 32768 at 6062080
data recv 32768 at 6094848
data recv 32768 at 6127616
data recv 32768 at 6160384
sending file_sum
false_alarms=0 hash_hits=0 matches=0
data recv 32768 at 6193152
data recv 32768 at 6225920
data recv 32768 at 6258688
[receiver] send_msg(1, 100)
[generator] send_msg(1, 100)
rsync: write failed on "/usr/home/postgres/arch/000000010000005E00000017": Disc quota exceeded (69)
[receiver] send_msg(3, 76)
[generator] send_msg(3, 76)
rsync error: error in file IO (code 11) at receiver.c(400) [receiver=3.1.2]
[receiver] send_msg_int(86, 11)
[generator] send_msg_int(86, 11)
[sender] send_msg(86, 0)
rsync: [sender] write error: Broken pipe (32)
[postgres@hades ~]$ echo $?
11
Comment 18 Rui DeSousa 2018-03-06 17:19:15 UTC
I also wrote a little util as well; I get the correct error in write spot.

[postgres@hades ~]$ cat 000000010000005E00000017 | ./fwrite/fwrite arch/000000010000005E00000017
fwrite: write: Disc quota exceeded
[postgres@hades ~]$ echo $?
1
[postgres@hades ~]$ du -h arch/000000010000005E00000017.GghJVR 
1.9M	arch/000000010000005E00000017.GghJVR


Here's the code:

#include <sys/stat.h>
#include <err.h>
#include <fcntl.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <string.h>


#define	BUFSIZE 131072

int
main(int argc, char *argv[])
{
  int fd, r, w;
  char *buf;
  char *name;
  
  if (argc != 2) {
    fprintf(stderr, "usage: fwrite [file]\n");
    exit(1);
  }

  if ((buf = malloc(BUFSIZE)) == NULL)
    err(1, "malloc");

  ++argv;
  if ((name = (char *) malloc(strlen(*argv) + 10)) == NULL)
    err(1, "malloc");

  strcat(strcpy(name, *argv), ".XXXXXX");

  if ((fd = mkstemp(name)) < 0)
    err(1, "mkstemp");

  while ((r = read(STDIN_FILENO, buf, BUFSIZE)) > 0)
    if ((w = write(fd, buf, r)) == -1)
      err(1, "write");

  if (r < 0)
   err(1, "read");

  if (fsync(fd) != 0)
   err(1, "fsync");

  if (close(fd) != 0)
   err(1, "close");

  if (rename(name, *argv) != 0)
   err(1, "rename");
 
  free(name);
  exit(0);
}
Comment 19 Ben RUBSON 2018-03-06 18:16:35 UTC
I managed to reproduce the issue on 11.0-RELEASE-p16.
Below a simple test case, without compression, without deduplication.
Note that issue is reproductible with quota, but not with userquota.

# f=/test
# z=zroot/ROOT/default$f

### quota / refquota (same results)

# zfs destroy $z
# zfs create $z
# zfs set compression=off $z
# zfs set dedup=off $z
# zfs set quota=1G $z

# dd if=/dev/random bs=1M count=600 of=$f/f1
# rsync -a --inplace $f/f1 $f/f2 ; echo $? ; diff $f/f1 $f/f2 ; rm $f/f2
0
Files /test/f1 and /test/f2 differ

# rsync -a $f/f1 $f/f2 ; echo $? ; rm $f/f2
rsync: rename "/test/.f2.6NVNwD" -> "f2": Disc quota exceeded (69)
rsync error: some files/attrs were not transferred (see previous errors)
(code 23) at main.c(1192) [sender=3.1.3]
23
// the quota error should have triggered on write instead //

### userquota

# zfs destroy $z
# zfs create $z
# zfs set compression=off $z
# zfs set dedup=off $z
# zfs set userquota@root=1G $z

# dd if=/dev/random bs=1M count=600 of=$f/f1
# rsync -a --inplace $f/f1 $f/f2 ; echo $? ; diff $f/f1 $f/f2 ; rm $f/f2
rsync: [sender] write error: Broken pipe (32)
rsync: write failed on "/test/f2": Disc quota exceeded (69)
rsync error: error in file IO (code 11) at receiver.c(404) [receiver=3.1.3]
11
Files /test/f1 and /test/f2 differ

# rsync -a $f/f1 $f/f2 ; echo $? ; rm $f/f2
rsync: [sender] write error: Broken pipe (32)
rsync: write failed on "/test/f2": Disc quota exceeded (69)
rsync error: error in file IO (code 11) at receiver.c(404) [receiver=3.1.3]
11

# dd if=/dev/random bs=1M count=535 of=$f/f1
# rsync -a --inplace $f/f1 $f/f2 ; echo $? ; diff $f/f1 $f/f2
0
# zfs get -Hp -o value used,userquota@root $z
1123188736
1073741824
# touch $f/file
touch: /test/file: Disc quota exceeded
Comment 20 Dave Gordon 2018-03-06 19:18:59 UTC
So, looking like a ZFS issue but triggered in some way by the specific behaviour of rsync (e.g. writing a certain block size/pattern causes the quota error to be lost). The truss listing from a failing case should show exactly what operations were performed on the destination filesystem; maybe someone from the ZFS team could see whether there's some pathological case that's not handled properly.

.Dave.
Comment 21 Dave Gordon 2018-03-06 19:57:55 UTC
Created attachment 14019 [details]
Test patch to see whether fdatasync() or fsync() detects a write failure
Comment 22 Dave Gordon 2018-03-06 20:15:17 UTC
(In reply to Ben RUBSON from comment #19)

Just to be totally certain about what ZFS may or may not share between files, could you try this variant of your testcase:

# zfs destroy $z
# zfs create $z
# zfs set compression=off $z
# zfs set dedup=off $z
# zfs set quota=1G $z

Then with "tmpfs" referring to any non-ZFS filesystem:
# dd if=/dev/random bs=1M count=600 of=$tmpfs/f1
# rsync -a --inplace $tmpfs/f1 $f/f2 ; echo $? ; diff $tmpfs/f1 $f/f2
# dd if=/dev/random bs=1M count=600 of=$tmpfs/f1
# rsync -a --inplace $tmpfs/f1 $f/f3 ; echo $? ; diff $tmpfs/f1 $f/f3

The first rsync should succeed, and the files should be identical.
The second should fail, but if it doesn't then at least it can't be down to ZFS finding matching datablocks.

.Dave.
Comment 23 Dave Gordon 2018-03-06 20:48:08 UTC
Looks like this ZFS problem could be a FreeBSD-specific issue; one of the commits mentioned in this FreeNAS bug report has the subject
  zfs_write: fix problem with writes appearing to succeed when over quota

See https://redmine.ixsystems.com/issues/26650

FreeNAS Bug #26650: Correctly report ZFS dataset quota overflows

Updated by Alexander Motin 4 months ago

Investigation of the problem brought me to FreeBSD-specific change r298105 by avg@ on 2016-04-16. If quota overflow detected during write, the write will fail, but the error status can be lost, falsely reporting partial completion. As result written data are flowing to nowhere and indefinitely, as fast as CPU can handle the loop.

HTH,
.Dave.
Comment 24 Ben RUBSON 2018-03-06 20:53:33 UTC
ZFS only shares between files with dedup on.
So first rsync / diff succeeded, second gave same result as before :
# rsync -a --inplace $tmpfs/f1 $f/f3 ; echo $? ; diff $tmpfs/f1 $f/f3
0
Files /mnt/f1 and /test/f3 differ

# ls -l $f
total 1048593
-rw-------  1 root  wheel  629145600  6 Mar 09:38 f2
-rw-------  1 root  wheel  629145600  6 Mar 09:40 f3
# du -sm $f/*
601	/test/f2
424	/test/f3
Comment 25 Ben RUBSON 2018-03-06 21:23:58 UTC
And here is the patch applied to FreeBSD stable/10 :
https://reviews.freebsd.org/rS326428
And to FreeBSD stable/11 :
https://reviews.freebsd.org/rS326427

Will then be in FreeBSD 11.3.

Note that this patch depends on another one as per its description.

Would be nice to give stable/10 or stable/11 branch a try.

But I think this ticket can then now be closed.
Comment 26 Rui DeSousa 2018-03-06 21:51:40 UTC
(In reply to Ben RUBSON from comment #25)

That is awesome.  Thanks you for all of your efforts!
Comment 27 Carson Gaspar 2018-03-07 14:52:33 UTC
(In reply to Dave Gordon from comment #23)
Reading this, I took a look at the rsync sources, and, indeed, rsync has a bug.

perform_io() does not correctly check the return code from write(). safe_write() does - please steal the correct logic from it. perform_io() only checks for write returning <=0, not for write returning something != len. So in the case of a partial write() it will corrupt the destination file.

I haven't looked for additional coding errors of this type.
Comment 28 Dave Gordon 2018-03-07 23:26:10 UTC
(In reply to Carson Gaspar from comment #27)
Hmm? If you're referring to line 810 of io.c, which is the only write(2) call I can see in perform_io(), in the current HEAD it looks like this:

 810  if ((n = write(iobuf.out_fd, out->buf + out->pos, len)) <= 0) {
      ...
 822  }
      ...
 835  if ((out->pos += n) == out->size) {
      ...

so that while the immediate test is only for <= 0, the actual result is stored in n and subsequently used to adjust counters, pointers, etc. I don't think there's a bug there.

BTW, AFAICT perform_io() is only used for IPC. The received file is written out by write_file() in fileio.c:

140 /* write_file does not allow incomplete writes.  It loops internally
141  * until len bytes are written or errno is set.  Note that use_seek and
142  * offset are only used in sparse processing (see write_sparse()). */
143 int write_file(int f, int use_seek, OFF_T offset, const char *buf, int len)

.Dave.