Bug 1051658

+++ This bug was initially created as a clone of Bug #1038207 +++

Description of problem:

Satellite sync is failing for supplementary channels: 

rhel-x86_64-server-supplementary-5 
rhel-x86_64-server-supplementary-6
rhel-x86_64-workstation-supplementary-6
rhel-x86_64-client-supplementary-6

Believe this might be a possible CDN issue. We are currently trying to get a dump to a customer to confirm syncs against a dump will succeed. 

How reproducible:

satellite-sync for supplementary channels

so far only external customers, not internal


 Error when syncing satellite:

 ------------------------------------------------------------ 
   SYNC ERROR: unhandled exception occurred:

  Exception reported from its-rhnwb
  Time: Tue Nov 26 04:13:27 2013
  Exception type <type 'exceptions.TypeError'>

  Exception Handler Information
  Traceback (most recent call last):
   File "/usr/bin/satellite-sync", line 139, in main
     return satsync.Runner().main()
   File "/usr/lib/python2.6/site-packages/spacewalk/satellite_tools/satsync.py", line 225, in main
     ret = method()

   [...]

  File "/usr/lib/python2.6/site-packages/spacewalk/server/importlib/errataImport.py", line 56, in _preprocessErratum
     self._processPackage(package)
   File "/usr/lib/python2.6/site-packages/spacewalk/server/importlib/importLib.py", line 666, in _processPackage
     Import._processPackage(self, package)
   File "/usr/lib/python2.6/site-packages/spacewalk/server/importlib/importLib.py", line 646, in _processPackage
     evr.append(package[f])
  TypeError: 'NoneType' object is unsubscriptable

--- Additional comment from Shannon Hughes on 2014-01-09 11:40:51 EST ---

Some more progress this morning. This might be a DST related issue. There are no issues accessing the pickled satsync/short-packages/63/rhn-package-798463 file. We do read in the modified dates. From rhnLib.py we convert the value to a timestamp, 

1383466145.0

When looking at the cache we open a locked file object and then use the python os module to grab the modified timestamp: 

        if self.modified:
            if os.fstat(fd.fileno())[ST_MTIME] != self.modified:               
                fd.close()
                raise KeyError(name)

>>> import os
>>> import sys
>>> fd = open('/var/cache/rhn/satsync/short-packages/63/rhn-package-798463', 'r')
>>> import fcntl
>>> from stat import ST_MTIME
>>> s = os.fstat(fd.fileno())[ST_MTIME]
>>> s
1383462545

The two values are 3600 seconds apart, which screams DST issue to me. When i run the timestamp function from rhnLib in the python interpreter I get back a value that matches the os.fstat call: 

>>> t = rhnLib.timestamp("20131103010905")
>>> t
1383462545.0

--- Additional comment from Shannon Hughes on 2014-01-09 17:18:00 EST ---

Going to be changing this to a satellite bug as sherr and I have a good idea of the issue with the way mktime being called from satellite is deciding on DST. Full summary will be coming shortly.

--- Additional comment from Stephen Herr on 2014-01-09 17:22:56 EST ---

For some reason (that I have yet to determine) this bug affects only people whos Satellites are in MST or PST.

We can see on Satellites that reproduce this error that time.mktime (which just calls the linux C implementation of mktime, see 'man mktime'). That the same date-time string returns two different times during the course of the sat-sync. So for example (in mountain time) if the last_modified date of the package in question is "2013-11-03 01:09:05", then even though that date string does not change, at one point in the satsync time.mktime returns 1383462545.0 and at another point in the sat-sync time.mktime returns 1383466145.0.

Note that both are actually valid timestamps for that last_modified date. November 3rd is the end of daylight savings time in the US, so the 1:00 hour is repeated as we "fall back". Note also that in that last_modified date there is no timezone information or any other way for mktime to determine if it should return the dst timestamp or non-dst timestamp.

The mktime manpage states about the tm_isdst variable (which is -1 when we pass it in since we don't know if dst was in effect or not): "...and a negative value means that mktime() should (use timezone information and system databases to) attempt to determine whether  DST  is in effect at the specified time." Something during the sat-sync changes the system state such that mktime's guess as to whether to return the dst timestamp or not changes. The linux time functions save their state in a variable named "daylight", so the difference may be something as simple as "The previously evaluated time was in dst / non dst".

The timestamp that gets returned matters, because for some reason we lookup the package data from an in-memory cache by package_id *and* timestamp. This has always been the case as far back in the history as I am able to look. Because look up the package data by timestamp, when we use a different timestamp for a package we have previously read we get a None object back, which leads to the TypeError reported in comment 0.

I can't tell you why this only affects servers in Mountain or Pacific time. I can't tell you what exactly is changing to make linux's mktime function change its mind about what the timestamp should be. But this is the problem. I think the fix should be to update the sat-sync code to only use pid to look up package information, not pid and timestamp.