Re: Nulls instead of data

On Tue, 20 Sep 2005, Wayne Davison wrote:
> On Tue, Sep 20, 2005 at 03:56:24PM +0200, Wojtek.Pilorz wrote:
> > When reading at offset 262144, we got 45056=0xb000 bytes instead of
> > 262144 requested; After that there are nulls in resulting file up to
> > 0x80000;
>
> Yes, the file-reading in map_ptr() was assuming that any reduction in
> the amount of data requested was an error instead of trying to read more
> data to finish filling the buffer. The attached patch should hopefully
> fix this for you.
>
> ..wayne..
>
After patching rsync with the patch provided, rsync did not quietly
produced bad file, which is good, and, unfortunately, it did not produce
any data, so there is still some room for improvement;

This time the messages were as follows:

[transftest]$ date; strace -tt -ff -o /mnt/tmp/rsync266a_tr07.strace rsync266a -av -W --bwlimit=2 /mnt/somedir/transftest/rsync-2.6.6.tar.gz ./; date
Wed Sep 21 08:47:11 CEST 2005
Process 12810 attached
building file list ... done
Process 12811 attached
rsync-2.6.6.tar.gz
rsync: read errors mapping "/mnt/somedir/transftest/rsync-2.6.6.tar.gz": Input/output error (5)
WARNING: rsync-2.6.6.tar.gz failed verification -- update discarded (will try again).
rsync-2.6.6.tar.gz
rsync: read errors mapping "/mnt/somedir/transftest/rsync-2.6.6.tar.gz": Input/output error (5)
ERROR: rsync-2.6.6.tar.gz failed verification -- update discarded.
Process 12811 detached
Process 12810 detached

sent 1380475 bytes received 64 bytes 1029.10 bytes/sec
total size is 690066 speedup is 0.50
rsync error: some files could not be transferred (code 23) at main.c(791)
Wed Sep 21 09:09:32 CEST 2005

I am enclosing below selected lines from trace file.

Best regards,

Wojtek

------------------------------------------------------------------------------

08:47:12.861456 open("/mnt/somedir/transftest/rsync-2.6.6.tar.gz", O_RDONLY|O_LARGEFILE) = 3
....
08:47:12.905079 read(3, "\37\213\10\0\3102\351B\0\3\354<ks\333\266\262\371 j\375"..., 262144) = 262144
08:49:54.573207 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
08:49:54.573396 write(4, "\37\213\10\0\3102\351B\0\3\354<ks\333\266\262\371 j\375"..., 512) = 512
....
08:52:02.524982 read(3, "o\257\236\3546\17\3266\33\315\203\264\2f\36*\214\ 31_\315"..., 262144) = 81920
08:54:36.386600 read(3, 0x402f0008, 180224) = -1 EIO (Input/output error)
08:54:36.386981 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
08:54:36.387140 write(4, "o\257\236\3546\17\3266\33\315\203\264\2f\36*\214\ 31_\315"..., 512) = 512
08:54:36.387316 gettimeofday({1127285676, 387336}, NULL) = 0
08:54:36.387526 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
08:54:36.387666 write(4, "g\22<y\35\27Z\37\340\321L\7\303\332\241\221\214\2 20\232"..., 512) = 512
08:54:36.387808 gettimeofday({1127285676, 387822}, NULL) = 0
08:54:36.388001 select(0, NULL, NULL, NULL, {0, 249856}) = 0 (Timeout)
08:54:36.634089 gettimeofday({1127285676, 634113}, NULL) = 0
08:54:36.634150 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
08:54:36.634294 write(4, "\316\356\2447{\225\313e\205\27l;\307\2650\267(\27 0h\263"..., 512) = 512

....

08:56:44.064245 write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\ 0\0\0"..., 512) = 512
08:56:44.064410 gettimeofday({1127285804, 64428}, NULL) = 0
08:56:44.064778 select(0, NULL, NULL, NULL, {0, 249856}) = 0 (Timeout)
08:56:44.314252 gettimeofday({1127285804, 314275}, NULL) = 0
08:56:44.314493 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
08:56:44.314642 write(4, "\0\200\0\0", 4) = 4
08:56:44.314784 gettimeofday({1127285804, 314801}, NULL) = 0
08:56:44.314965 read(3, "M\350e\23e\t\311\235\375\300\314\224l\340\342\375 \313\356"..., 165778) = 61440
08:58:32.987089 read(3, 0x402eb008, 104338) = -1 EIO (Input/output error)
08:58:32.987444 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
08:58:32.987601 write(4, "M\350e\23e\t\311\235\375\300\314\224l\340\342\375 \313\356"..., 512) = 512
08:58:32.987772 gettimeofday({1127285912, 987793}, NULL) = 0

....

08:59:53.799098 read(5, "V\0\0\t", 4) = 4
08:59:53.799391 select(6, [5], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
08:59:53.799647 read(5, "WARNING: rsync-2.6.6.tar.gz fail"..., 86) = 86
08:59:53.799791 write(1, "WARNING: rsync-2.6.6.tar.gz fail"..., 86) = 86
08:59:53.800277 select(6, [5], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
08:59:53.800605 read(5, "\26\0\0\7", 4) = 4
08:59:53.800684 select(6, [5], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
08:59:53.800899 read(5, "\0\0\0\0\0\240\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\ 0", 22) = 22
08:59:53.801149 open("/mnt/somedir/transftest/rsync-2.6.6.tar.gz", O_RDONLY|O_LARGEFILE) = 3
08:59:55.578893 fstat64(3, {st_mode=S_IFREG|0640, st_size=690066, ...}) = 0
08:59:55.579002 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})

....

08:59:55.581715 write(1, "rsync-2.6.6.tar.gz\n", 19) = 19
08:59:55.582028 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
08:59:55.582182 write(4, "\0\200\0\0", 4) = 4
08:59:55.582320 gettimeofday({1127285995, 582336}, NULL) = 0
08:59:55.582512 mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x402dc000
08:59:55.582578 read(3, "\37\213\10\0\3102\351B\0\3\354<ks\333\266\262\371 j\375"..., 262144) = 262144
08:59:55.583436 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
08:59:55.583593 write(4, "\37\213\10\0\3102\351B\0\3\354<ks\333\266\262\371 j\375"..., 512) = 512
08:59:55.583752 gettimeofday({1127285995, 583771}, NULL) = 0
08:59:55.583975 select(0, NULL, NULL, NULL, {0, 259128}) = 0 (Timeout)
08:59:55.844068 gettimeofday({1127285995, 844093}, NULL) = 0
08:59:55.844130 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
08:59:55.844275 write(4, "-\342%K\27b\305\270\24\10\vcR\311#5\23R\n\317al\230 \2\376"..., 512) = 512
08:59:55.844434 gettimeofday({1127285995, 844453}, NULL) = 0
08:59:55.844636 select(0, NULL, NULL, NULL, {0, 248880}) = 0 (Timeout)

....

09:02:03.514488 write(4, "\266\326=\203\241\244\316\223^\337\f\225\30\2 04-\336M\304"..., 512) = 512
09:02:03.514647 gettimeofday({1127286123, 514663}, NULL) = 0
09:02:03.515022 select(0, NULL, NULL, NULL, {0, 249368}) = 0 (Timeout)
09:02:03.764049 gettimeofday({1127286123, 764075}, NULL) = 0
09:02:03.764286 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:02:03.764435 write(4, "\0\200\0\0", 4) = 4
09:02:03.764576 gettimeofday({1127286123, 764592}, NULL) = 0
09:02:03.764758 read(3, "o\257\236\3546\17\3266\33\315\203\264\2f\36*\214\ 31_\315"..., 262144) = 258048
09:05:21.096637 read(3, 0x4031b008, 4096) = -1 EIO (Input/output error)
09:05:21.096756 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:05:21.096906 write(4, "o\257\236\3546\17\3266\33\315\203\264\2f\36*\214\ 31_\315"..., 512) = 512
09:05:21.097070 gettimeofday({1127286321, 97089}, NULL) = 0
09:05:21.097278 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:05:21.097417 write(4, "g\22<y\35\27Z\37\340\321L\7\303\332\241\221\214\2 20\232"..., 512) = 512
09:05:21.097559 gettimeofday({1127286321, 97574}, NULL) = 0

....

09:07:28.514611 write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\ 0\0\0"..., 512) = 512
09:07:28.514774 gettimeofday({1127286448, 514791}, NULL) = 0
09:07:28.514983 select(0, NULL, NULL, NULL, {0, 249368}) = 0 (Timeout)
09:07:28.764049 gettimeofday({1127286448, 764074}, NULL) = 0
09:07:28.764112 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:07:28.764257 write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\ 0\0\0"..., 512) = 512
09:07:28.764420 gettimeofday({1127286448, 764437}, NULL) = 0
09:07:28.764778 select(0, NULL, NULL, NULL, {0, 249856}) = 0 (Timeout)
09:07:29.014046 gettimeofday({1127286449, 14068}, NULL) = 0
09:07:29.014278 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:07:29.014427 write(4, "\0\200\0\0", 4) = 4
09:07:29.014569 gettimeofday({1127286449, 14587}, NULL) = 0
09:07:29.014753 read(3, "^\25\0160\375\360\216J\367\341;\264s\27\212\343\3 4\264"..., 165778) = 24576
09:08:11.947124 read(3, 0x402e2008, 141202) = -1 EIO (Input/output error)
09:08:11.947530 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:08:11.947689 write(4, "^\25\0160\375\360\216J\367\341;\264s\27\212\343\3 4\264"..., 512) = 512
09:08:11.947864 gettimeofday({1127286491, 947885}, NULL) = 0
09:08:11.948079 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:08:11.948218 write(4, "oT\233U\350\177\253\315\365\277\364\277\177\306\2 07 \264"..., 512) = 512
09:08:11.948362 gettimeofday({1127286491, 948376}, NULL) = 0

....

09:09:31.805119 write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\ 0\0\0"..., 512) = 512
09:09:31.805270 gettimeofday({1127286571, 805285}, NULL) = 0
09:09:31.805468 select(0, NULL, NULL, NULL, {0, 251320}) = 0 (Timeout)
09:09:32.064039 gettimeofday({1127286572, 64064}, NULL) = 0
09:09:32.064101 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:09:32.064247 write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\ 0\0\0"..., 512) = 512
09:09:32.064411 gettimeofday({1127286572, 64428}, NULL) = 0
09:09:32.064617 select(0, NULL, NULL, NULL, {0, 242536}) = 0 (Timeout)
09:09:32.314109 gettimeofday({1127286572, 314135}, NULL) = 0
09:09:32.314171 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:09:32.314316 write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\ 0\0\0"..., 512) = 512
09:09:32.314481 gettimeofday({1127286572, 314500}, NULL) = 0
09:09:32.314689 select(0, NULL, NULL, NULL, {0, 243024}) = 0 (Timeout)
09:09:32.564039 gettimeofday({1127286572, 564063}, NULL) = 0
09:09:32.564101 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:09:32.564247 write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\ 0\0\0"..., 402) = 402
09:09:32.564411 gettimeofday({1127286572, 564428}, NULL) = 0
09:09:32.564637 select(0, NULL, NULL, NULL, {0, 189832}) = 0 (Timeout)
09:09:32.754040 gettimeofday({1127286572, 754065}, NULL) = 0
09:09:32.754102 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:09:32.754246 write(4, "\0\0\0\0", 4) = 4
09:09:32.754385 gettimeofday({1127286572, 754402}, NULL) = 0
09:09:32.754516 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:09:32.755449 write(4, "\320\320[\2m\16\237\273\'\357\247A\24;\345\25", 16) = 16
09:09:32.755599 gettimeofday({1127286572, 755618}, NULL) = 0
09:09:32.755699 munmap(0x402dc000, 266240) = 0
09:09:32.755936 write(2, "rsync: read errors mapping \"/mnt"..., 112) = 112
09:09:32.757074 close(3) = 0
09:09:32.757311 select(6, [5], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
09:09:32.757636 read(5, "\10\0\0\7", 4) = 4
09:09:32.757764 select(6, [5], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
09:09:32.758047 read(5, "\377\377\377\377\377\377\377\377", 8) = 8
09:09:32.758201 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:09:32.758370 write(4, "\377\377\377\377", 4) = 4
09:09:32.758443 gettimeofday({1127286572, 758455}, NULL) = 0
09:09:32.758616 select(5, NULL, [4], NULL, {60, 0}) = 1 (out [4], left {60, 0})
09:09:32.758753 write(4, "\377\377\377\377", 4) = 4
09:09:32.758795 gettimeofday({1127286572, 758823}, NULL) = 0
09:09:32.758851 time(NULL) = 1127286572
09:09:32.758893 select(6, [5], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
09:09:32.759071 read(5, "C\0\0\10", 4) = 4
09:09:32.759117 select(6, [5], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
09:09:32.759295 read(5, "ERROR: rsync-2.6.6.tar.gz failed"..., 67) = 67
09:09:32.759348 write(2, "ERROR: rsync-2.6.6.tar.gz failed"..., 67) = 67
09:09:32.759674 select(6, [5], [], NULL, {60, 0}) = 1 (in [5], left {59, 990000})
09:09:32.771389 read(5, "\4\0\0\7", 4) = 4
09:09:32.771465 select(6, [5], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
09:09:32.771702 read(5, "\377\377\377\377", 4) = 4
09:09:32.771836 wait4(12810, 0xbfffddc8, WNOHANG, NULL) = 0
09:09:32.772153 gettimeofday({1127286572, 772721}, NULL) = 0
09:09:32.772817 select(0, NULL, NULL, NULL, {0, 20000}) = 0 (Timeout)
09:09:32.785797 gettimeofday({1127286572, 785841}, NULL) = 0
09:09:32.785893 select(0, NULL, NULL, NULL, {0, 7000}) = 0 (Timeout)
09:09:32.794111 gettimeofday({1127286572, 794148}, NULL) = 0
09:09:32.794202 wait4(12810, 0xbfffddc8, WNOHANG, NULL) = 0
09:09:32.794297 gettimeofday({1127286572, 794340}, NULL) = 0
09:09:32.794407 select(0, NULL, NULL, NULL, {0, 20000}) = ? ERESTARTNOHAND (To be restarted)
09:09:32.795118 --- SIGCHLD (Child exited) @ 0 (0) ---
09:09:32.795169 wait4(-1, [WIFEXITED(s) && WEXITSTATUS(s) == 0], WNOHANG, NULL) = 12810
09:09:32.795225 wait4(-1, 0xbfffda34, WNOHANG, NULL) = -1 ECHILD (No child processes)
09:09:32.795266 sigreturn() = ? (mask now [])
09:09:32.795340 gettimeofday({1127286572, 795352}, NULL) = 0
09:09:32.795383 select(0, NULL, NULL, NULL, {0, 19000}) = 0 (Timeout)
09:09:32.814058 gettimeofday({1127286572, 814083}, NULL) = 0
09:09:32.814117 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout)
09:09:32.824054 gettimeofday({1127286572, 824068}, NULL) = 0
09:09:32.824101 wait4(12810, 0xbfffddc8, WNOHANG, NULL) = -1 ECHILD (No child processes)
09:09:32.824206 write(1, "\nsent 1380475 bytes received 64"..., 58) = 58
09:09:32.824595 write(1, "total size is 690066 speedup is"..., 38) = 38
09:09:32.824842 rt_sigaction(SIGUSR1, {SIG_IGN}, {0x8055a68, [USR1], SA_RESTORER|SA_RESTART, 0x420277b8}, 8) = 0
09:09:32.824922 rt_sigaction(SIGUSR2, {SIG_IGN}, {0x8055a84, [USR2], SA_RESTORER|SA_RESTART, 0x420277b8}, 8) = 0
09:09:32.824985 wait4(12810, 0xbfffdd98, WNOHANG, NULL) = -1 ECHILD (No child processes)
09:09:32.825047 write(2, "rsync error: some files could no"..., 74) = 74
09:09:32.825387 munmap(0x4001d000, 4096) = 0
09:09:32.825442 exit_group(23) = ?


--
To unsubscribe or change options: https://lists.samba.org/mailman/listinfo/rsync
Before posting, read: http://www.catb.org/~esr/faqs/smart-questions.html