[Zodb-checkins] SVN: ZODB/branches/3.3/ Collector 1327: FileStorage init confused by time travel

[Tim Peters]

Log message for revision 25929:
Collector 1327:  FileStorage init confused by time travel

If the system clock moved back in time more than 30 days between
a FileStorage close and (re)open, new txn ids could be smaller
than txn ids already in the database.  Plugged that hole.



-=-
Modified: ZODB/branches/3.3/NEWS.txt
===================================================================
--- ZODB/branches/3.3/NEWS.txt	2004-06-21 20:23:08 UTC (rev 25928)
+++ ZODB/branches/3.3/NEWS.txt	2004-06-21 20:43:04 UTC (rev 25929)
@@ -1,3 +1,22 @@
+What's new in ZODB3 3.3
+=======================
+Release date: DD-MMM-2004
+
+Storages
+--------
+
+Collector #1327 FileStorage init confused by time travel.
+If the system clock "went backwards" a long time between the times a
+FileStorage was closed and reopened, new transaction ids could be
+smaller than transaction ids already in the storage, violating a
+key invariant.  Now transaction ids are guaranteed to be increasing
+even when this happens.  If time appears to have run backwards at all
+when a FileStorage is opened, a new message saying so is logged at
+warning level; if time appears to have run backwards at least 30
+minutes, the message is logged at critical level (and you should
+investigate to find and repair the true cause).
+
+
 What's new in ZODB3 3.3 beta 1
 ==============================
 Release date: 07-Jun-2004

Modified: ZODB/branches/3.3/src/ZODB/FileStorage/FileStorage.py
===================================================================
--- ZODB/branches/3.3/src/ZODB/FileStorage/FileStorage.py	2004-06-21 20:23:08 UTC (rev 25928)
+++ ZODB/branches/3.3/src/ZODB/FileStorage/FileStorage.py	2004-06-21 20:43:04 UTC (rev 25929)
@@ -191,10 +191,12 @@
         t = time.time()
         t = TimeStamp(*time.gmtime(t)[:5] + (t % 60,))
         if tid > t:
-            logger.warning("%s Database records in the future", file_name);
-            if tid.timeTime() - t.timeTime() > 86400*30:
-                # a month in the future? This is bogus, use current time
-                self._ts = t
+            seconds = tid.timeTime() - t.timeTime()
+            complainer = logger.warning
+            if seconds > 30 * 60:   # 30 minutes -- way screwed up
+                complainer = logger.critical
+            complainer("%s Database records %d seconds in the future",
+                       file_name, seconds)
 
         self._quota = quota
 

Copied: ZODB/branches/3.3/src/ZODB/tests/loggingsupport.py (from rev 25927, Zope3/trunk/src/zope/testing/loggingsupport.py)

Modified: ZODB/branches/3.3/src/ZODB/tests/testFileStorage.py
===================================================================
--- ZODB/branches/3.3/src/ZODB/tests/testFileStorage.py	2004-06-21 20:23:08 UTC (rev 25928)
+++ ZODB/branches/3.3/src/ZODB/tests/testFileStorage.py	2004-06-21 20:43:04 UTC (rev 25929)
@@ -205,12 +205,109 @@
             self._storage.tpc_vote(t)
             self._storage.tpc_finish(t)
 
+# Raise an exception if the tids in FileStorage fs aren't
+# strictly increasing.
+def checkIncreasingTids(fs):
+    lasttid = '\0' * 8
+    for txn in fs.iterator():
+        if lasttid >= txn.tid:
+            raise ValueError("tids out of order %r >= %r" % (lasttid, tid))
+        lasttid = txn.tid
 
+# Return a TimeStamp object 'minutes' minutes in the future.
+def timestamp(minutes):
+    import time
+    from persistent.TimeStamp import TimeStamp
+
+    t = time.time() + 60 * minutes
+    return TimeStamp(*time.gmtime(t)[:5] + (t % 60,))
+
+def testTimeTravelOnOpen():
+    """
+    >>> from ZODB.FileStorage import FileStorage
+    >>> from ZODB.DB import DB
+    >>> import transaction
+    >>> from ZODB.tests.loggingsupport import InstalledHandler
+
+    Arrange to capture log messages -- they're an important part of
+    this test!
+
+    >>> handler = InstalledHandler('ZODB.FileStorage')
+
+    Create a new file storage.
+
+    >>> st = FileStorage('temp.fs', create=True)
+    >>> db = DB(st)
+    >>> db.close()
+
+    First check the normal case:  transactions are recorded with
+    increasing tids, and time doesn't run backwards.
+
+    >>> st = FileStorage('temp.fs')
+    >>> db = DB(st)
+    >>> conn = db.open()
+    >>> conn.root()['xyz'] = 1
+    >>> transaction.get().commit()
+    >>> checkIncreasingTids(st)
+    >>> db.close()
+    >>> st.cleanup() # remove .fs, .index, etc files
+    >>> handler.records   # i.e., no log messages
+    []
+
+    Now force the database to have transaction records with tids from
+    the future.
+
+    >>> st = FileStorage('temp.fs', create=True)
+    >>> st._ts = timestamp(15)  # 15 minutes in the future
+    >>> db = DB(st)
+    >>> db.close()
+
+    >>> st = FileStorage('temp.fs') # this should log a warning
+    >>> db = DB(st)
+    >>> conn = db.open()
+    >>> conn.root()['xyz'] = 1
+    >>> transaction.get().commit()
+    >>> checkIncreasingTids(st)
+    >>> db.close()
+    >>> st.cleanup()
+
+    >>> [record.levelname for record in handler.records]
+    ['WARNING']
+    >>> handler.clear()
+
+    And one more time, with transaction records far in the future.
+    We expect to log a critical error then, as a time so far in the
+    future probably indicates a real problem with the system.  Shorter
+    spans may be due to clock drift.
+
+    >>> st = FileStorage('temp.fs', create=True)
+    >>> st._ts = timestamp(60)  # an hour in the future
+    >>> db = DB(st)
+    >>> db.close()
+
+    >>> st = FileStorage('temp.fs') # this should log a critical error
+    >>> db = DB(st)
+    >>> conn = db.open()
+    >>> conn.root()['xyz'] = 1
+    >>> transaction.get().commit()
+    >>> checkIncreasingTids(st)
+    >>> db.close()
+    >>> st.cleanup()
+
+    >>> [record.levelname for record in handler.records]
+    ['CRITICAL']
+    >>> handler.clear()
+    >>> handler.uninstall()
+    """
+
 def test_suite():
+    import doctest
+
     suite = unittest.TestSuite()
     for klass in [FileStorageTests, Corruption.FileStorageCorruptTests,
                   FileStorageRecoveryTest, SlowFileStorageTest]:
         suite.addTest(unittest.makeSuite(klass, "check"))
+    suite.addTest(doctest.DocTestSuite())
     return suite
 
 if __name__=='__main__':