Skip to content

Wrong timing in rsync daemon log #729

New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Open
mruprich opened this issue Jan 31, 2025 · 0 comments · May be fixed by #730
Open

Wrong timing in rsync daemon log #729

mruprich opened this issue Jan 31, 2025 · 0 comments · May be fixed by #730

Comments

@mruprich
Copy link
Contributor

When running rsync against a remote daemon, if the daemon is using chroot, time in the log file will be off. I used the following config for the daemon:

lock file          = /var/run/rsyncd-mirrors.lock
read only          = true
max connections    = 16
log file           = /var/log/rsyncd/rpms.log
transfer logging   = yes
timeout            = 900
ignore nonreadable = yes
dont compress      = *.gz *.tgz *.zip *.z *.Z *.rpm *.deb *.bz2
refuse options     = checksum
uid                = test
gid                = test
use chroot         = yes
hosts allow        = 10.45.224.124

[test]
      comment      = Just a testing repo
      path         = /home/test/rpms

I've put some files in /home/test/rpms. Then I run rsync from an allowed host:

$ rsync -av test@10.X.X.X::test rpms/
receiving incremental file list
./
...
...
sent 1,000 bytes  received 43,040,520 bytes  1,179,219.73 bytes/sec
total size is 43,025,373  speedup is 1.00

When I look at the log file at the daemon's side:

2025/01/31 08:16:34 [2235] rsyncd version 3.4.1 starting, listening on port 873
2025/01/31 08:16:50 [2239] name lookup failed for 10.X.X.X: Name or service not known
2025/01/31 08:16:50 [2239] connect from UNKNOWN (10.X.X.X)
2025/01/31 08:16:51 [2239] rsync allowed access on module test from UNKNOWN (10.X.X.X)
2025/01/31 13:16:51 [2239] rsync on test/ from UNKNOWN (10.X.X.X)
2025/01/31 13:16:52 [2239] building file list
2025/01/31 13:16:52 [2239] send UNKNOWN [10.X.X.X] test () finch-2.14.10-2.fc35.x86_64.rpm 143985
2025/01/31 13:16:54 [2239] send UNKNOWN [10.X.X.X] test () finch-debuginfo-2.14.10-2.fc35.x86_64.rpm 348677
...

The 08:16 is the actual correct time, the 13:16 is the time on the host. I've seen this before and it is an ancient bug actually (almost 20 years) - https://bugzilla.samba.org/show_bug.cgi?id=2607. I will open a PR with a fix. The key is to use glibc functions for getting the time that end with _r - for instance localtime_r() instead of localtime(). The reason is that localtime_r() does not call tzset function which fails after chroot.

All the credit for discovering the bug and for the fix goes to @remicollet

@mruprich mruprich linked a pull request Jan 31, 2025 that will close this issue
# for free to join this conversation on GitHub. Already have an account? # to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant