I have a bash script with a line like this:
/usr/bin/time rsync -av user@host:/some/remote/path/ /some/nfs/path/
Sometimes, the output looks like this:
0.03user 0.02system 0:00.21elapsed 26%CPU (0avgtext+0avgdata 4652maxresident)k
0inputs+152outputs (0major+2334minor)pagefaults 0swaps
receiving incremental file list
sent 416 bytes received 281706 bytes 564244.00 bytes/sec
total size is 820553959 speedup is 2908.51
That is, with the output of time before the output of rsync! Needless to say, this makes interpretation of the log more annoying that it would otherwise be.
I should add that this script writes all it output to a log file; somewhere near the top, it does:
exec >>$LOG_FILE 2>&1
So, for both time and rsync, standard output and standard error are the same file descriptor, a handle to a disk file.
I have also tried this script using bash's
time builtin, and i believe i have seen the same behaviour.
How is this happening? Something to do with stderr vs stdout buffering? Something to do with rsync forking a subprocess which outlives the top-level process?
Moreover, how can i stop this happening?