Bug 753642

Description of problem:

Noticed symptom was that the initial DHCP lease IP address was being 
thrown away after every reboot, within 15 minutes of booting.  Every 
ssh session that was too quick would get disconnected and hosts file 
would have to be updated for new IP address.  No further IP address 
changes would occur until after next reboot.

After a couple days of characterizing this, I feel this is _not_ a 
DHCP fault, but rather something wonky about how the clock is set up 
by initial installation.  

The workaround is non-obvious.  If one runs system-config-date and
changes the timezone, such as from CST to EST and then back again,
any further reboots do *not* have the problem.  Something is being
done by the config app that is not being done by install.

After all the discussion below, I come to the conclusion:
  I think install is not correctly implementing "System clock uses UTC".


Version-Release number of selected component (if applicable):
Fedora 16 fresh installation


How reproducible:
Every time (5+ installs now)


Steps to Reproduce:
1. Install new F16, selecting a western timezone (EST,CST), 
   and leaving the defaults set to "System clock uses UTC"
2. On first and subsequent boots, logged time is seen to 
   change by several hours-worth during boot.  This causes 
   dhclient (and user) grief.
3. Run config date/time app and change timezones, such as
   CST->EST, or EST->CST, or even CST->EST->CST
4. Any further reboots do not demonstrate problem.  Initial
   logged time is correct and does not change drastically.
  

Actual results:
Every reboot causes a new DHCP lease to be acquired, discarding
any older leases, withing 15 minutes after rebooting.  IP address 
changes once for every reboot.  Quite irritating.


Expected results:
DHCP lease is _renewed_ during each reboot so that IP address 
does not change.  This is the behavior seen with F15.  This is
the behavior seen after the workaround of manually setting 
timezone using system-config-date.


Additional info:

Running under VMware Workstation 6.5 with Windows host.  (Hmm, 
such flexibility has cost me two+ days, given the nice ability
to keep retrying and characterizing - maybe not worth it....?)

On first boot, DHCP writes lease information into file
    /var/lib/dhclient/dhclient-5fb06bd0-0bb0-7ffb-45f1-d6edd65f3e03-eth0.lease
including timestamps of 'when' the lease information might or 
should expire, e.g. lines like:
      fixed-address 192.168.57.166;
      option dhcp-lease-time 1800;
      renew 0 2011/11/13 14:05:39;
      rebind 0 2011/11/13 14:19:15;
      expire 0 2011/11/13 14:23:00;
Later and on subsequent reboots it reads these timestamps and 
apparently gives priority to this info over and above whether the 
DHCP server says an IP address is okay.  If an expiration time
has "gone past" then the lease is thrown away and new one requested.

The problem arises in that dhclient first writes/reads the timestamps
*before* the clock is drastically changed.  With initial apparent 
boot time of 08:53, it will write out timestamps such as the above.

At a later point in boot processing chronyd suddenly decides the 
clock is off by hours and leaps to another time, e.g.
    Nov 13 08:54:44 tlsf16c chronyd[963]: chronyd version 1.26-20110831gitb088b7 starting
    Nov 13 08:54:44 tlsf16c chronyd[963]: Linux kernel major=3 minor=1 patch=0
    Nov 13 08:54:44 tlsf16c chronyd[963]: hz=100 shift_hz=7 freq_scale=1.00000000 nominal_tick=10000 slew_delta_tick=833 max_tick_bias=1000
    Nov 13 08:54:45 tlsf16c systemd[1]: Reloading.
    Nov 13 08:54:49 tlsf16c chronyd[963]: Selected source 67.18.187.111
    Nov 13 08:54:49 tlsf16c chronyd[963]: System clock wrong by 21598.511303 seconds, adjustment started
    Nov 13 14:54:48 tlsf16c chronyd[963]: System clock was stepped by 21598.511 seconds
    Nov 13 14:54:52 tlsf16c firstboot[787]: error reading information on service smolt: No such file or directory

After boot is done and after some more minutes, say 10 minutes, 
dhclient checks on the state of DHCP leases.  It finds that the 
lease is now 'stale' as the expiration time is long past 
(2011/11/13 14:23:00 vs current time of 15:05) and discards the
old IP address and requests a new one.
    Nov 13 15:05:38 tlsf16c NetworkManager[703]: <info> (eth0): DHCPv4 state changed bound -> expire
    Nov 13 15:05:38 tlsf16c NetworkManager[703]: <info> (eth0): DHCPv4 state changed expire -> preinit
    Nov 13 15:05:45 tlsf16c NetworkManager[703]: <info> (eth0): DHCPv4 state changed preinit -> bound
    Nov 13 15:05:45 tlsf16c NetworkManager[703]: bound to 192.168.57.167 -- renewal in 832 seconds.
    Nov 13 15:05:45 tlsf16c avahi-daemon[705]: Withdrawing address record for 192.168.57.166 on eth0.
    Nov 13 15:05:45 tlsf16c avahi-daemon[705]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.57.166.
    Nov 13 15:05:45 tlsf16c avahi-daemon[705]: Interface eth0.IPv4 no longer relevant for mDNS.
    Nov 13 15:05:45 tlsf16c avahi-daemon[705]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.57.167.
    Nov 13 15:05:45 tlsf16c avahi-daemon[705]: New relevant interface eth0.IPv4 for mDNS.
    Nov 13 15:05:45 tlsf16c avahi-daemon[705]: Registering new address record for 192.168.57.167 on eth0.IPv4.

It is the drastic time change between initial lease info file access and the second access that confuses dhclient.

I have various captured snippets of /var/log/messages from the
various test installations.  One bit stood out finally, the
boot-time log messages noting RTC clock values:
    Nov 13 08:52:53 tlsf16c kernel: [    0.161296] RTC time: 13:52:30, date: 11/13/11
    Nov 13 09:35:13 tlsf16c kernel: [    0.145052] RTC time: 14:34:37, date: 11/13/11
    Nov 13 15:09:53 tlsf16c kernel: [    0.081239] RTC time: 21:09:29, date: 11/13/11
The first is during initial boot.  The second during first reboot.
The third is the second reboot after I had used system-config-date 
to manually change timezones. 

In the first and second, the RTC is set to _correct_ local time, 
and logged times are... a back-formation assuming RTC is UTC time?

In the third, after timezone set manually, the RTC is apparently
set to UTC time, and the logged time is correct local time.

Also note that in first and second, installation-set timezone was
EST -5, and so logged time was RTC-5 hours, yet RTC was correct
local time for *CST*.  Only in the third instance do we see the 
correct time and delta for CST.  Very strange.

I think install is not correctly implementing "System clock uses UTC".


Possibly related is 
    https://bugzilla.redhat.com/show_bug.cgi?id=749516
    "kcm_clock (kcontrol/dateandtime) doesn't set persistent date"
which is impressive for the 45 comments and the arguing back and forth
about what config apps should do, libs should do, install should do, 
yeesh!  And again muttering about UTC....

At one point in those comments the assertion is made that the 
system-config-date app is doing the correct thing and that that should 
be the reference point for correctness.  If so, then initial installation 
for F16 is *not* doing the "correct thing".  (Whatever that is)