Summary: | Rsync logging time incorrectly | ||
---|---|---|---|
Product: | Gentoo Linux | Reporter: | Kilburn Abrahams <kilburna> |
Component: | New packages | Assignee: | Gentoo's Team for Core System packages <base-system> |
Status: | RESOLVED UPSTREAM | ||
Severity: | normal | CC: | chris, custom_basses, euclid80, marcin.deranek |
Priority: | High | ||
Version: | 2005.0 | ||
Hardware: | x86 | ||
OS: | Linux | ||
URL: | https://bugzilla.samba.org/show_bug.cgi?id=2607 | ||
Whiteboard: | |||
Package list: | Runtime testing required: | --- | |
Attachments: |
fix to time logging problem
Sample c code demonstating problem |
Description
Kilburn Abrahams
2005-04-14 00:09:09 UTC
I have identified the same problem, but I can clarify the situation a bit. The rsyncd daemon is not consistently using localtime or GMT. instead, the first line entries are created using localtime and subsequent entries are created using GMT. My rsyncd.log files show a mixtrure of GMT timestamps and localtime timestamps. in each case, when the user logs on to perform an rsync, the initial log entry for that process ID is written in localtime, the transaction records are written in GMT, and the final log entry for that process ID is always written in GMT. is this the norm? is there some change that i can implement so that all of the timestamps use the same timezone? i've looked at the manpage and i couldn't find the answer. hopefully somebody can point out a simple oversight on my part. fyi here is a snippet from rsyncd.log: 2005/09/04 13:56:22 [7926] rsync on script from carton.764net (192.168.1.15) 2005/09/04 18:56:22 [7926] send script rsync-script-3.sh 1212 2005/09/04 18:56:22 [7926] wrote 2335 bytes read 97 bytes total size 9728 and another one: 2005/09/03 04:49:29 [1505] rsync on jackass from carton.764net (192.168.1.15) 2005/09/03 09:50:35 [1505] send jackass 2005.0/jackass-2005.0-pentium4.iso 167208960 2005/09/03 09:50:35 [1505] send jackass 2005.0/jackass-2005.0-pentium4.iso.md5 62 2005/09/03 09:50:35 [1505] send jackass rsync-jackass-2.sh 888 2005/09/03 09:50:35 [1505] wrote 167232215 bytes read 158 bytes total size 1201233200 in my case, my local timezone is GMT-5. i hope that this helps to clarify the problem. This bug was opened in mid-April and its already October. Is anyone taking responsibility for this bug, or has it just been ignored for the past 6 months? I had the same problem, until I made a /etc directory under the rsync path and copied (not linked) /etc/localtime into it. Now the chrooted daemon can get the time zone info. This relates to a "resolved" bug in rsync's own bugzilla (#2607), but it's more likely a bug in glibc (I'm using 2.3.5-r2). Another workaround is to turn off chroot. (In reply to comment #3) > I had the same problem, until I made a /etc directory under the rsync path and > copied (not linked) /etc/localtime into it. Now the chrooted daemon can get the > time zone info. In fact, this is standard procedure when preparing a chroot jail. Now, rsync tries to cache the timezone info before it chroots (witness the log_init function in log.c), but glibc is just too persistent about reloading it. (In reply to comment #4) The problem is that strftime() calls tzset(), which forces a reload of the timezone information. If that information is not supplied, either by the TZ environment variable, or by /etc/localtime in the chroot jail, then the first call to strftime causes a reversion to UTC that lasts for the lifetime of the child process. As a workaround, one can comment out "#define HAVE_STRFTIME" in config.h, but that restricts the abilility to format the log output. *** Bug 113576 has been marked as a duplicate of this bug. *** Reopen. thanks for reopening. the reason that i asked for this bug to be reopened is because this bug is not actually a duplicate of bug 110038. that bug report provides a solution of copying the file for /etc/localtime instead of using a symlink to the zoneinfo data file. unfortunately, that solution does not fix this bug. i have tried using the recommended solution to bug 110038 but it fails to resolve the problem. even after implementing the proposed changes rsync continues to report the wrong time, using a combination of localtime and GMT. This is not a system-wide problem. this problem is specific to rsync and only to rsync. Other daemons are not to be similarly effected. in my case, i performed the following steps -- as suggested in the referenced bug report -- but they FAILED to solve the problem: 1. i removed the symlink where /etc/localtime points to /usr/share/zoneinfo/America/Chicago. 2. i copied the timezone data file to /etc/localtime instead of creating a symlink for /etc/localtime that points to the timezone data file. 3. i restarted the daemon the result? nothing has changed. RSYNC continues to log using a hybrid of GMT and localtime in its logs. the problem is not being caused by the localtime symlink. when rsync chroots, the localtime data doesn't follow. one user has recommended copying the /etc/localtime data into the rsync data path FOR EVERY RSYNC MODULE be ing served. if the user does that, it seems that every rsync transfer would include a transfer of the /etc/localtime file that lies within the chroot path -- this is obviously not a good solution to the problem, as 1) it requires the user to copy /etc/localtime to a chroot path for every single module that is being provided by rsync, and 2) it forces users to download the /etc/localtime file when performing an rsync. FWIW none of the other daemons running on the system (HTTP Servers, FTP servers, NTP servers) are similarly effected. this is a problem that is unique to rsync. so i guess its safe to say that the problem is not being caused by the use of a symlink instead of by copying the time zone data file. or am i missing something really obvious??? thanks. Created attachment 73641 [details, diff]
fix to time logging problem
This fixes the time zone problem (at least on glibc 2.3.5) by removing all
calls to strftime. It changes the date format in the log, but for all I know,
that's not a problem.
i'm not about to add this sort of thing to rsync without it going through upstream first ... see upstream bug in URL field (In reply to comment #11) > i'm not about to add this sort of thing to rsync without it going through > upstream first ... see upstream bug in URL field OK. No problem. handled upstream *** Bug 185787 has been marked as a duplicate of this bug. *** It seems problem is still there (using rsync-3.0.4 and glibc-2.6.1 on amd64): Direct rsyncd logs: 2008/12/10 14:29:29 [15808] connect from localhost (127.0.0.1) 2008/12/10 14:29:29 [15808] rsync to test/ from localhost (127.0.0.1) 2008/12/10 13:29:29 [15808] receiving file list 2008/12/10 13:29:29 [15808] ./ 2008/12/10 13:29:29 [15808] sent 969 bytes received 85101 bytes total size 82177 I slightly modified tztest.c program taken from upstream bug to include multiple invocations of timestring() function inside chroot jail. First of them converts time correctly although every next one fails (shows UTC) - this seems to be the case here. Created attachment 174858 [details]
Sample c code demonstating problem
it's been fixed in glibc-2.7+, so nothing to be done here Not really: tried with glibc 2.8 & 2.9 on amd64 and still have the very same issue: 2009/01/03 21:07:09 [19409] connect from localhost (127.0.0.1) 2009/01/03 20:07:09 [19409] rsync to test/ from localhost (127.0.0.1) 2009/01/03 20:07:09 [19409] receiving file list 2009/01/03 20:07:09 [19409] ./ 2009/01/03 20:07:09 [19409] sent 874 bytes received 79045 bytes total size 76426 yes, isn't fixed for me either. I use also amd64 and glibc 2.11. Would be nice, if you fix it, because this time-difference is confusing... |