Merge ubuntu-debuginfod:fix-poller-timestamp into ubuntu-debuginfod:master

[Sergio Durigan Junior]

Recently I noticed (kudos to schopin for his ping) that the poller has been missing several ddebs. I'm not entirely sure why that's happening, but I have a strong feeling that this has something to do with timestamps. ddeb-retriever does some manipulation in order to guarantee that it doesn't miss "publications arriving out of order". So I'm implementing the same thing here, in the hopes that it solves the problem.

I would like to deploy this in production and keep monitoring to check if the problem is solved.

[Lena Voytek (lvoytek)]

The changes make sense and should work fine with the Python datetime library. I have some additional suggestions below but otherwise looks good to me

review: Approve

[Sergio Durigan Junior (sergiodj)]

Thanks, Lena. I've addressed your comments and will merge the code.

diff --git a/ddebpoller.py b/ddebpoller.py
index 09f3a1c..67a61b8 100644
--- a/ddebpoller.py
+++ b/ddebpoller.py
@@ -19,6 +19,7 @@
 
 import os
 from urllib import parse
+import datetime
 from debugpoller import DebugPoller
 
 
@@ -26,6 +27,10 @@ class DdebPoller(DebugPoller):
     """Perform the Launchpad polling and obtain a list of ddebs and source
     packages."""
 
+    # The delta we subtract from a timestamp in order to make sure we
+    # don't miss publications that may arrive out of order.
+    TIMESTAMP_DELTA = datetime.timedelta(hours=1)
+
     def __init__(self, initial_interval=1, force_initial_interval=False, dry_run=False):
         """Initialize the object using 'ddeb' as its name.
 
@@ -37,38 +42,38 @@ class DdebPoller(DebugPoller):
             dry_run=dry_run,
         )
 
-    def _get_and_generate_timestamps(self):
-        """Get the previous timestamp and generate a new one."""
+    def _get_normal_and_real_timestamps(self):
+        """Get the previous timestamp and adjust it to account for
+        publications arriving out of order."""
         timestamp = self._get_timestamp()
         if timestamp is None:
             raise RuntimeError("_get_timestamp returned None")
-        if timestamp == "":
-            raise RuntimeError("_get_timestamp returned a blank timestamp")
-        new_timestamp = self._generate_timestamp()
-        if new_timestamp is None:
-            raise RuntimeError("_generate_timestamp returned None")
-        if new_timestamp == "":
-            raise RuntimeError("_generate_timestamp returned a blank timestamp")
-        return timestamp, new_timestamp
+        if not isinstance(timestamp, datetime.datetime):
+            raise RuntimeError(
+                f"_get_timestamp returned an invalid timestamp ({timestamp})"
+            )
+        # Allow a grace period to cope with publications arriving out of
+        # order during long transactions.
+        real_timestamp = timestamp - self.TIMESTAMP_DELTA
+        return timestamp, real_timestamp
 
     def get_ddebs(self):
         """Get the list of ddebs that have been published since the last
         timestamp from Launchpad.
 
-        :rtype: dict, str
+        :rtype: dict, datetime.datetime
 
         Return a dictionary containing all ddebs found, and also the
         new timestamp that should then be recorded by calling
         record_timestamp."""
-        timestamp, new_timestamp = self._get_and_generate_timestamps()
+        timestamp, real_timestamp = self._get_normal_and_real_timestamps()
 
-        self._logger.info(
-            f"Polling ddebs created since '{timestamp}' (it's now '{new_timestamp}')"
-        )
+        self._logger.info(f"Polling ddebs created since '{real_timestamp}'")
 
         result = []
+        latest_timestamp_created = timestamp
         for pkg in self._main_archive.getPublishedBinaries(
-            order_by_date=True, created_since_date=timestamp
+            order_by_date=True, created_since_date=real_timestamp
         ):
             if pkg.status not in ("Pending", "Published"):
                 continue
@@ -80,6 +85,9 @@ class DdebPoller(DebugPoller):
                 # Safety check.
                 continue
 
+            if pkg.date_created > latest_timestamp_created:
+                latest_timestamp_created = pkg.date_created
+
             srcname = pkg.source_package_name
             srcver = pkg.source_package_version
             component = pkg.component_name
@@ -104,26 +112,25 @@ class DdebPoller(DebugPoller):
                 }
                 result.append(msg)
 
-        return result, new_timestamp
+        return result, latest_timestamp_created
 
     def get_sources(self):
         """Get the list of source packages that have been published since the
         last timestamp from Launchpad.
 
-        :rtype: dict, str
+        :rtype: dict, datetime.datetime
 
         Return a dictionary containing all source packages found, and
         also the new timestamp that should then be recorded by calling
         record_timestamp."""
-        timestamp, new_timestamp = self._get_and_generate_timestamps()
+        timestamp, real_timestamp = self._get_normal_and_real_timestamps()
 
-        self._logger.info(
-            f"Polling source packages created since '{timestamp}' (it's now '{new_timestamp}')"
-        )
+        self._logger.info(f"Polling source packages created since '{real_timestamp}'")
 
         result = []
+        latest_timestamp_created = timestamp
         for pkg in self._main_archive.getPublishedSources(
-            order_by_date=True, created_since_date=timestamp
+            order_by_date=True, created_since_date=real_timestamp
         ):
             if pkg.status not in ("Pending", "Published"):
                 continue
@@ -133,6 +140,9 @@ class DdebPoller(DebugPoller):
                 # Safety check.
                 continue
 
+            if pkg.date_created > latest_timestamp_created:
+                latest_timestamp_created = pkg.date_created
+
             srcname = pkg.source_package_name
             srcver = pkg.source_package_version
             component = pkg.component_name
@@ -146,4 +156,4 @@ class DdebPoller(DebugPoller):
             }
             result.append(msg)
 
-        return result, new_timestamp
+        return result, latest_timestamp_created
diff --git a/debugpoller.py b/debugpoller.py
index 2d74723..c29ea5d 100644
--- a/debugpoller.py
+++ b/debugpoller.py
@@ -31,9 +31,6 @@ class DebugPoller:
     # The timestamp file we will save our timestamp into.
     TIMESTAMP_FILE = os.path.expanduser("~/.config/ubuntu-debuginfod/timestamp")
 
-    # The timestamp format we use.  Launchpad requires this format.
-    TIMESTAMP_FORMAT = "%Y-%m-%dT%H:%M:%S"
-
     def __init__(
         self,
         module_name,
@@ -92,8 +89,8 @@ class DebugPoller:
             self._logger.debug(f"Generating timestamp with interval {interval}")
             d = d - datetime.timedelta(hours=interval)
 
-        self._logger.debug(f"Generated timestamp '{d.strftime(self.TIMESTAMP_FORMAT)}'")
-        return d.strftime(self.TIMESTAMP_FORMAT)
+        self._logger.debug(f"Generated timestamp '{d}'")
+        return d
 
     def _get_timestamp(self):
         """Get the timestamp from the timestamp file, or generate a
@@ -109,13 +106,15 @@ class DebugPoller:
             return self._generate_timestamp(interval=self._initial_interval)
 
         with open(self.TIMESTAMP_FILE, "r", encoding="UTF-8") as f:
-            return f.readline().rstrip()
+            ts = int(f.readline().rstrip())
+            d = datetime.datetime.fromtimestamp(ts, tz=datetime.timezone.utc)
+            return d
 
     def record_timestamp(self, timestamp):
         """Save the timestamp into the timestamp file.
 
-        :param str timestamp: Timestamp that should be saved into the
-            TIMESTAMP_FILE."""
+        :param datetime.datetime timestamp: Timestamp that should be
+            saved into the TIMESTAMP_FILE."""
         if self._dry_run:
             self._logger.debug("dry_run enabled, not recording timestamp file")
             return
@@ -123,7 +122,9 @@ class DebugPoller:
         dirname = os.path.dirname(self.TIMESTAMP_FILE)
         os.makedirs(dirname, mode=0o755, exist_ok=True)
         with open(self.TIMESTAMP_FILE, "w", encoding="UTF-8") as f:
-            f.write(timestamp)
+            epoch = datetime.datetime.fromtimestamp(0, tz=datetime.timezone.utc)
+            ts = int((timestamp - epoch).total_seconds())
+            f.write("%d" % ts)
 
     def set_initial_interval(self, initial_interval):
         """Set the initial_interval value.
diff --git a/poll_launchpad.py b/poll_launchpad.py
index baeab6f..77259b4 100644
--- a/poll_launchpad.py
+++ b/poll_launchpad.py
@@ -97,17 +97,18 @@ def poll_launchpad(conn, cursor):
     poller = DdebPoller()
 
     # Process ddebs.
-    messages, new_timestamp = poller.get_ddebs()
+    messages, new_timestamp_ddebs = poller.get_ddebs()
     for msg in messages:
         _process_msg(msg, conn, cursor)
 
-    # Process source packages.  We ignore the new timestamp returned
-    # by the method because we'll use the one returned previously by
-    # get_ddebs.
-    messages, _ = poller.get_sources()
+    # Process source packages.
+    messages, new_timestamp_src = poller.get_sources()
     for msg in messages:
         _process_msg(msg, conn, cursor)
 
+    # Choose the earliest timestamp.
+    new_timestamp = min(new_timestamp_ddebs, new_timestamp_src)
+
     poller.record_timestamp(new_timestamp)