Bug 2607 - Rsync logging time incorrectly
Summary: Rsync logging time incorrectly
Status: RESOLVED FIXED
Alias: None
Product: rsync
Classification: Unclassified
Component: core (show other bugs)
Version: 2.6.9
Hardware: x86 Linux
: P3 normal (vote)
Target Milestone: ---
Assignee: Wayne Davison
QA Contact: Rsync QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2005-04-14 04:37 UTC by Kilburn Abrahams
Modified: 2006-10-25 21:33 UTC (History)
1 user (show)

See Also:


Attachments
Output timestamp after a chroot call (648 bytes, text/x-csrc)
2005-04-15 08:41 UTC, Wayne Davison
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Kilburn Abrahams 2005-04-14 04:37:14 UTC
I use Gentoo and rsync versions 2.6.4. I done an update on a number of packages
and then noticed that rsync was not logging correctly. It was previously working .

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

Time 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

Time 04:50:57,04:50:58 and 04:51:01 is the problem. The time in the first line
is correct than it seems to change the hour to 12 hour format instead of 24hr.
Comment 1 Paul Slootman 2005-04-14 07:32:21 UTC
What timezone is your system running in?
Comment 2 Wayne Davison 2005-04-14 09:50:51 UTC
You don't mention if you're using syslog() or direct-to-file logging.  Also, I
assume you have chroot enabled.

Rsync makes sure that it calls localtime() before it calls chroot(), so this
should ensure that it has loaded the local timezone before all the /etc files
vanish via chroot().  In the syslog case, the timestamp is out of rsync's
control, but rsync does also call openlog() before it calls chroot().

If you're using syslog, is syslogd running?

If the problem is a direct-to-file logging, try running a program that just
calls localtime() on a time_t of the current time, calls chroot(), and then
calls strftime().  If that has the same timezone problem, it would be good to
file a bug report with your C library provider.

Another work-around might be to set TZ in your environment (e.g. TZ=PST8PDT).

This all works fine for me under Debian Sarge (with or without TZ set).

Let me know if you can't figure out what's wrong.
Comment 3 Kilburn Abrahams 2005-04-14 18:13:47 UTC
I am using direct-to-file logging. 

My BIOS setting is local. My rc.conf is set CLOCK="local". I also set
TZ='Australia/Sydney'; export TZ in profile. 

Also set lrwxrwxrwx  1 root root 36 Apr 15 10:51 /etc/localtime ->
/usr/share/zoneinfo/Australia/Sydney which is how Gentoo sets the timezone.

After transfer, the localtime() is always using UTC (off by 10 hrs)

2005/04/15 11:00:45 [7209] name lookup failed for 192.168.1.250: Name or service
not known
2005/04/15 11:00:45 [7209] rsync to test from support#iservnetworks.com@unknown
(192.168.1.250)
2005/04/15 01:00:46 [7209] sent 69 bytes  received 695 bytes  total size 11321603

Any help would be appreciated. Might be a C lib issue. 
Comment 4 Wayne Davison 2005-04-15 08:41:45 UTC
Created attachment 1163 [details]
Output timestamp after a chroot call

Try this program out.  If it fails to output the current time, file a bug
report with gentoo about it.  If it succeeds, let me know.

Also, try the TZ work-around again, but format it like the example in comment
#2 -- you need two timezone abbreviations surrounding an offset from UTC.  For
instance, this works for me:

    export TZ=AST-10ADT

I don't know if the abbreviations are right, so use whatever is output by
"date" for your timezone -- put the standard-time abbreviation first, and the
datelight-savings-time abbreviation second (or omit it if you don't go on
daylight-savings-time).
Comment 5 Kilburn Abrahams 2005-04-15 22:42:44 UTC
Here is the output of the your program. It gives the correct time. 

tux tmp # gcc -o tztest tztest.c
tux tmp # ./tztest
2005/04/16 15:13:25 current time

I have also written a short C prog, similar to yours, and it too gives the
correct time result. The I wrote a perl script and it gives the correct time.

I spent a lot of time digging into forums, and this problem has surfaced many
times, but there has been no definitive solution. I have built a completely new
box and the problem still occurs.

I look after a 1TB storage and logging is used extensively. I changed to
chroot=no and the logging time is fine. I will look into the code, but the
problem seems to centred around chroot and glibc. I know that I upgraded glibc
and then this issue started.

I also tried the TZ=UTC10EST nad other combinatiins with no difference.  I also
used zic to create a new timezone file with no difference
Comment 6 John Van Essen 2005-04-17 02:02:31 UTC
So - to which version of glibc did you upgrade when this problem started?

I looked at the localtime/timezone related sources in

  http://ftp.gnu.org/pub/gnu/glibc/glibc-2.3.4.tar.gz

and as long at the TZ envariable does not change and tzset() is not explicitly
called, then the timezone info from the first localtime() is retained and no
further filesystem access is needed (that's how it's also worked in the past).

My guess is that the TZ variable is being clobbered/modified somehow.

Try this (as root) to see the parent daemon environment:

  cat /proc/`cat /var/run/rsyncd.pid`/environ

Then, start a child process by starting a transfer via your daemon that will
take a long time so you can look at the environment for the child.  Tail the
rsyncd log to get the child PID and do

  cat /proc/_PID_/environ

You don't have to report the whole environ content - just look for TZ= and
report what it has for a value in both cases.

The TZ envariable isn't needed as long as you have /etc/localtime set properly.
 So try this - in your rsyncd init script, before starting the daemon, insert

  unset TZ

so the daemon starts without a TZ variable and restart the daemon (also restore
chroot = yes in your config).  This should prevent any enviroment change from
affecting the timezone processing.

Then try a transfer and see if the child timestamp is now OK.
Comment 7 James Ranson 2005-11-23 14:09:09 UTC
(In reply to comment #6)

The problem is that glibc's implementation (2.3.5) of strftime() calls tzset(), which attempts to reload the timezone information.  If the environment variable TZ has not been set, and the timezone file has not been copied into the chroot jail, then the first attempt to use strftime() causes the timezone to revert to UTC for all future time accesses in the child process.  If one adjusts the config.h so that strftime is not used, the problem disappears.
Comment 8 Wayne Davison 2006-10-25 21:32:06 UTC
A while back I did some work on the timezone code so that this problem would be fixed.  The latest code (that is being released in 2.6.9) now calls more time-zone functions prior to the chroot() call, and this includes using strftime().

I'm reopening this bug so that I can give it a better resolution.
Comment 9 Wayne Davison 2006-10-25 21:33:05 UTC
The CVS version, and the upcoming 2.6.9 should have this fixed.