rsync - Sep 2015 - [Bug 11496] New: itemized logging of transferred bytes is cumulative instead of per file

https://bugzilla.samba.org/show_bug.cgi?id=11496

            Bug ID: 11496
           Summary: itemized logging of transferred bytes is cumulative
                    instead of per file
           Product: rsync
           Version: 3.1.0
          Hardware: x64
                OS: Linux
            Status: NEW
          Severity: normal
          Priority: P5
         Component: core
          Assignee: wayned at samba.org
          Reporter: cwygerde at gmail.com
        QA Contact: rsync-qa at samba.org

I am using the tym script to do backups.
It uses:  --log-file-format='%o %i %3b %5l  %-f'

The manpage says: %b the number of bytes actually transferred
For directories (which are part of the filelist and therefore not transferred
separately as files) it shows a value of 0.
But for files it shows the cumulative number of transferred bytes instead of
the amount per file.

I did a local test using /sbin as source and /test as destination:
2015/09/06 14:21:28 [987] building file list
2015/09/06 14:21:28 [987] send cd+++++++++   0 12288  sbin
2015/09/06 14:21:28 [987] send >f+++++++++ 58785 52466  sbin/MAKEDEV
2015/09/06 14:21:28 [987] send >f+++++++++ 65077  6248  sbin/acpi_available
2015/09/06 14:21:28 [987] send >f+++++++++ 97232 32112  sbin/agetty
2015/09/06 14:21:28 [987] send >f+++++++++ 102851  5576  sbin/alsa
2015/09/06 14:21:28 [987] send >f+++++++++ 109166  6272  sbin/apm_available
2015/09/06 14:21:28 [987] send >f+++++++++ 958357 849048 
sbin/apparmor_parser
2015/09/06 14:21:28 [987] send >f+++++++++ 985560 27160  sbin/badblocks
2015/09/06 14:21:28 [987] send >f+++++++++ 1017147 31544  sbin/blkid

I looked at the code and the previous value seems to be stored in a static
using a call to the function below:

void remember_initial_stats(void)
{
    initial_data_read = total_data_read;
    initial_data_written = total_data_written;
}

In function 'log_formatted' the following code is used:

case 'b':
            if (!(iflags & ITEM_TRANSFER))
                b = 0;
            else if (am_sender)
                b = total_data_written - initial_data_written;
            else
                b = total_data_read - initial_data_read;
            strlcat(fmt, "s", sizeof fmt);
            snprintf(buf2, sizeof buf2, fmt,
                 do_big_num(b, humanize, NULL));
            n = buf2;
            break;

This looks fine so I would expect this to work correctly.
Maybe the call to remember_initial_stats is not happening at the right time.

While looking at this I saw the code for %c (received checksum bytes) has the
same code as for %b so it will print transferred bytes instead of received
checksum bytes. That is a bug.

I am using 3.10.0 on Ubuntu 14.04.3 but I checked the 3.12 version of the code
and saw no changes in that area nor other bug-reports on this topic.

rsync  version 3.1.0  protocol version 31
Copyright (C) 1996-2013 by Andrew Tridgell, Wayne Davison, and others.
Web site: http://rsync.samba.org/
Capabilities:
    64-bit files, 64-bit inums, 64-bit timestamps, 64-bit long ints,
    socketpairs, hardlinks, symlinks, IPv6, batchfiles, inplace,
    append, ACLs, xattrs, iconv, symtimes, prealloc

-rwxr-xr-x 1 root root 390704 apr 17  2014 /usr/bin/rsync

I have run rsync with -vvv but I don't see anything strange there.

-- 
You are receiving this mail because:
You are the QA Contact for the bug.

https://bugzilla.samba.org/show_bug.cgi?id=11496

Wayne Davison <wayned at samba.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|---                         |FIXED

--- Comment #1 from Wayne Davison <wayned at samba.org> ---
Yeah, the combination of using --log-file=FILE with %b/%c was not correct.  It
was working right for a daemon's transfer logging and for
--out-format='%b/%c',
but not for the --log-file option.

Since the "tym" script does not output client progress, it could
switch from
using --log-file to using a combination of --out-format (with "%t [%p]
"
prefixed to match the current log lines) and output redirection (>>) to
get the
expected values even on older rsync versions.
> While looking at this I saw the code for %c (received checksum bytes) has
the
> same code as for %b so it will print transferred bytes instead of received
> checksum bytes.
No, you missed the negated am_sender conditional that makes the %c output
different from %b.

Thanks for the report.

-- 
You are receiving this mail because:
You are the QA Contact for the bug.