Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 89046 - Rsync logging time incorrectly
Summary: Rsync logging time incorrectly
Status: RESOLVED UPSTREAM
Alias: None
Product: Gentoo Linux
Classification: Unclassified
Component: New packages (show other bugs)
Hardware: x86 Linux
: High normal (vote)
Assignee: Gentoo's Team for Core System packages
URL: https://bugzilla.samba.org/show_bug.c...
Whiteboard:
Keywords:
: 113576 185787 (view as bug list)
Depends on:
Blocks:
 
Reported: 2005-04-14 00:09 UTC by Kilburn Abrahams
Modified: 2010-10-14 12:29 UTC (History)
4 users (show)

See Also:
Package list:
Runtime testing required: ---


Attachments
fix to time logging problem (logging_fix.patch,552 bytes, patch)
2005-11-26 09:20 UTC, euclid80
Details | Diff
Sample c code demonstating problem (tztest.c,701 bytes, text/plain)
2008-12-10 13:39 UTC, Marcin Deranek
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Kilburn Abrahams 2005-04-14 00:09:09 UTC
I done am emerge world and also built a completely new system. Used rsync versions 2.6.0r4, 2.6.3 and 2.6.4. All now have this problem. 

I did not get this problem before I done a emerge world, so it seems that the problem is not with rsync but 

Example 1:
2005/04/14 16:59:51 [14642] rsync to test from support@unknown (192.168.1.250)
2005/04/14 06:59:51 [14642] sent 69 bytes  received 695 bytes  total size 11321603

06:59:51 is the problem. 16:59:51 is correct.  

Example 2:
2005/04/14 14:50:56 [14371] rsync to test from support@unknown (192.168.1.250)
2005/04/14 04:50:57 [14371] [192.168.1.250] recv test (support#iservnetworks.com) Companies/Industries.QBB 315850
2005/04/14 04:50:58 [14371] [192.168.1.250] recv test (support#iservnetworks.com) Companies/Industries.QBW 1917952
2005/04/14 04:51:01 [14371] sent 69 bytes  received 2906168 bytes  total size 11321603

04:50:57,04:50:58 and 04:51:01 is the problem.
Comment 1 Bob 2005-09-05 10:54:43 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.
Comment 2 Bob 2005-10-07 14:41:39 UTC
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?  
Comment 3 euclid80 2005-11-23 10:19:50 UTC
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.
Comment 4 euclid80 2005-11-23 10:39:15 UTC
(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.
Comment 5 euclid80 2005-11-23 13:06:08 UTC
(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.
Comment 6 SpanKY gentoo-dev 2005-11-23 19:45:02 UTC

*** This bug has been marked as a duplicate of 110038 ***
Comment 7 Jakub Moc (RETIRED) gentoo-dev 2005-11-25 12:01:02 UTC
*** Bug 113576 has been marked as a duplicate of this bug. ***
Comment 8 Jakub Moc (RETIRED) gentoo-dev 2005-11-25 12:01:19 UTC
Reopen.
Comment 9 Bob 2005-11-25 20:46:08 UTC
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.
Comment 10 euclid80 2005-11-26 09:20:01 UTC
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.
Comment 11 SpanKY gentoo-dev 2005-11-26 11:58:11 UTC
i'm not about to add this sort of thing to rsync without it going through
upstream first ... see upstream bug in URL field
Comment 12 euclid80 2005-11-26 15:57:23 UTC
(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.
Comment 13 SpanKY gentoo-dev 2006-05-11 20:40:21 UTC
handled upstream
Comment 14 Jakub Moc (RETIRED) gentoo-dev 2007-07-18 18:22:37 UTC
*** Bug 185787 has been marked as a duplicate of this bug. ***
Comment 15 Marcin Deranek 2008-12-10 13:37:55 UTC
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.
Comment 16 Marcin Deranek 2008-12-10 13:39:04 UTC
Created attachment 174858 [details]
Sample c code demonstating problem
Comment 17 SpanKY gentoo-dev 2008-12-24 21:39:41 UTC
it's been fixed in glibc-2.7+, so nothing to be done here
Comment 18 Marcin Deranek 2009-01-03 20:10:22 UTC
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
Comment 19 Andre Gluecksmann 2010-10-14 12:29:55 UTC
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...