Bug 1944132

Description of problem:

A customer reported that "rsync --timeout <timeout> ..." doesn't work when target directory is on NFS and the customer cuts the traffic to simulate a NFS issue on the receiver side.

Reproducing myself, I could find out that the customer is right: the code never enters the timeout condition because there is always traffic between the rsync processes (a few bytes, which look like some sort of keep-alive).
These bytes make the "last_io_out" variable always be updated, which prevents check_timeout() to reach the conditional block on line 191+:

rsync-3.1.3/io.c:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
 547 static char *perform_io(size_t needed, int flags)
 548 {
 :
 810                         if ((n = write(iobuf.out_fd, out->buf + out->pos, len)) <= 0) {
 811                                 if (errno == EINTR || errno == EWOULDBLOCK || errno == EAGAIN)
 812                                         n = 0;    <<<<< HERE in case of non-blocking mode (or EINTR)
 813                                 else {
 :
 821                                 }
 822                         }
 :
 828                         if (io_timeout)
 829                                 last_io_out = time(NULL);        <<<<< HERE
 830                         stats.total_written += n;
 831 
 :


 158 static void check_timeout(BOOL allow_keepalive, int keepalive_flags)
 159 {
 :
 189         chk = MAX(last_io_out, last_io_in);
 190         if (t - chk >= io_timeout) {
 191                 if (am_server)        <<<<< HERE BLOCK
 192                         msgs2stderr = 1;
 193                 rprintf(FERROR, "[%s] io timeout after %d seconds -- exiting\n",
 194                         who_am_i(), (int)(t-chk));
 195                 exit_cleanup(RERR_TIMEOUT);
 196         }
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

Cherry on the cake, on line 812, we can see that even if write() returned 0, "last_io_out" will be updated, which is non-sense.

Using a systemtap script to check the various "last_io_out" / "last_io_in" values in check_timeout() and "last_io_out" updates in perform_io(), I was able to find out the following trend:

- check_timeout() runs every half-period (hence if timeout = 60, it will run every 30 seconds)
- last_io_out is updated just after check_timeout(), and is always updated

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
# stap -v ./rsync_trace_check_timeout.stp
[...]
6967: (check_timeout) t: 1617016659, last_io_out: 1617016644, last_io_in: 1617016644
6967: (perform_io) setting last_io_out: 1617016644
[...]
6967: (check_timeout) t: 1617016674, last_io_out: 1617016659, last_io_in: 1617016659
6967: (perform_io) setting last_io_out: 1617016659
[...]
6967: (check_timeout) t: 1617016695, last_io_out: 1617016674, last_io_in: 1617016680
6967: (perform_io) setting last_io_out: 1617016674
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

systemtap script in attachment for convenience.

From above, we see that "last_io_out" is immediately updated after check_timeout() executed, hence the timeout code cannot be reached in that condition.


Version-Release number of selected component (if applicable):

rsync-3.1.3-9.el8.x86_64


How reproducible:

Always


Steps to Reproduce:
1. Mount a NFS filesystem as target directory

  # mkdir /nfsmount
  # mount <server>:<share> /nfsmount

2. rsync a large file

  # truncate -s 10G /tmp/zero
  # rsync --timeout=30 --progress=2 /tmp/zero /nfsmount/zero

3. From another terminal, drop the outgoing traffic to NFS server

  # iptables -A OUTPUT -d <serverip>/32 -p tcp -m tcp --dport 2049 -j DROP

Actual results:

rsync traffic stops but timeout is never reached.


Expected results:

timeout being reached.