Bug 11496 - itemized logging of transferred bytes is cumulative instead of per file
Summary: itemized logging of transferred bytes is cumulative instead of per file
Status: RESOLVED FIXED
Alias: None
Product: rsync
Classification: Unclassified
Component: core (show other bugs)
Version: 3.1.0
Hardware: x64 Linux
: P5 normal (vote)
Target Milestone: ---
Assignee: Wayne Davison
QA Contact: Rsync QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-09-06 12:43 UTC by Cees Wijgerde
Modified: 2015-09-07 17:12 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Cees Wijgerde 2015-09-06 12:43:12 UTC
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.
Comment 1 Wayne Davison 2015-09-07 17:12:04 UTC
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.