fix(analyze): warn before GNU date fallback

cloudinit/analyze/dump.py

@@ -1,12 +1,15 @@
 # This file is part of cloud-init. See LICENSE file for license information.
 
 import calendar
+import logging
 import sys
 from datetime import datetime, timezone
 from typing import IO, Any, Dict, List, Optional, TextIO, Tuple
 
 from cloudinit import atomic_helper, subp, util
 
+LOG = logging.getLogger(__name__)
+
 stage_to_description: Dict[str, str] = {
     "finished": "finished running cloud-init",
     "init-local": "starting search for local datasources",
@@ -76,6 +79,16 @@ def parse_timestamp_from_date(timestampstr: str) -> float:
         raise ValueError(
             f"Unable to parse timestamp without GNU date: [{timestampstr}]"
         )
+    # Transitional: shelling out to GNU date is slated for removal in favor of
+    # native Python parsing. Log the unrecognized timestamp so maintainers can
+    # collect formats that need direct support (see GH-4357).
+    LOG.warning(
+        "analyze: falling back to GNU %s(1) to parse unrecognized "
+        "timestamp %r; please report this format upstream so it can be "
+        "handled natively in Python.",
+        date,
+        timestampstr,
+    )
     return float(
         subp.subp([date, "-u", "+%s.%3N", "-d", timestampstr]).stdout.strip()
     )

tests/unittests/analyze/test_dump.py

@@ -1,5 +1,6 @@
 # This file is part of cloud-init. See LICENSE file for license information.
 
+import logging
 import warnings
 from contextlib import suppress
 from datetime import datetime, timezone
@@ -13,7 +14,9 @@
     has_gnu_date,
     parse_ci_logline,
     parse_timestamp,
+    parse_timestamp_from_date,
 )
+from cloudinit.subp import SubpResult
 from cloudinit.util import write_file
 
 
@@ -112,6 +115,61 @@ def test_parse_timestamp_handles_explicit_timezone(self):
             == "2020-09-12 12:39:20"
         )
 
+    @mock.patch("cloudinit.analyze.dump.subp.subp")
+    @mock.patch("cloudinit.analyze.dump.has_gnu_date", return_value=True)
+    @mock.patch("cloudinit.analyze.dump.util.is_Linux", return_value=True)
+    def test_parse_timestamp_from_date_warns_on_gnu_date_fallback(
+        self, _m_is_linux, _m_has_gnu, m_subp, caplog
+    ):
+        """A warning is emitted whenever GNU date(1) is used as a fallback."""
+        m_subp.return_value = SubpResult("1597333950.000\n", "")
+        timestampstr = "17:15 08/13"
+        with caplog.at_level(logging.WARNING, logger="cloudinit.analyze.dump"):
+            assert 1597333950.0 == parse_timestamp_from_date(timestampstr)
+        m_subp.assert_called_once_with(
+            ["date", "-u", "+%s.%3N", "-d", timestampstr]
+        )
+        warnings_logged = [
+            r for r in caplog.records if r.levelname == "WARNING"
+        ]
+        assert 1 == len(warnings_logged)
+        assert "date(1)" in warnings_logged[0].getMessage()
+        assert repr(timestampstr) in warnings_logged[0].getMessage()
+
+    @mock.patch("cloudinit.analyze.dump.subp.which", return_value="/bin/gdate")
+    @mock.patch("cloudinit.analyze.dump.subp.subp")
+    @mock.patch("cloudinit.analyze.dump.has_gnu_date", return_value=False)
+    @mock.patch("cloudinit.analyze.dump.util.is_Linux", return_value=False)
+    def test_parse_timestamp_from_date_warns_on_gdate_fallback(
+        self, _m_is_linux, _m_has_gnu, m_subp, _m_which, caplog
+    ):
+        """The warning identifies gdate when used on non-Linux systems."""
+        m_subp.return_value = SubpResult("1597333950.000\n", "")
+        timestampstr = "17:15 08/13"
+        with caplog.at_level(logging.WARNING, logger="cloudinit.analyze.dump"):
+            parse_timestamp_from_date(timestampstr)
+        m_subp.assert_called_once_with(
+            ["gdate", "-u", "+%s.%3N", "-d", timestampstr]
+        )
+        warnings_logged = [
+            r for r in caplog.records if r.levelname == "WARNING"
+        ]
+        assert 1 == len(warnings_logged)
+        assert "gdate(1)" in warnings_logged[0].getMessage()
+        assert repr(timestampstr) in warnings_logged[0].getMessage()
+
+    @mock.patch("cloudinit.analyze.dump.subp.which", return_value=None)
+    @mock.patch("cloudinit.analyze.dump.has_gnu_date", return_value=False)
+    @mock.patch("cloudinit.analyze.dump.util.is_Linux", return_value=True)
+    def test_parse_timestamp_from_date_no_warning_when_no_gnu_date(
+        self, _m_is_linux, _m_has_gnu, _m_which, caplog
+    ):
+        """No warning is logged when there is no GNU date to fall back to."""
+        with caplog.at_level(logging.WARNING, logger="cloudinit.analyze.dump"):
+            with pytest.raises(ValueError):
+                parse_timestamp_from_date("17:15 08/13")
+        assert [] == [r for r in caplog.records if r.levelname == "WARNING"]
+
 
 class TestParseCILogLine:
     def test_parse_logline_returns_none_without_separators(self):
@@ -222,15 +280,13 @@ def test_parse_logline_returns_event_for_amazon_linux_2_line(self):
         assert expected == parse_ci_logline(line)
 
 
-SAMPLE_LOGS = dedent(
-    """\
+SAMPLE_LOGS = dedent("""\
 Nov 03 06:51:06.074410 x2 cloud-init[106]: [CLOUDINIT] util.py[DEBUG]:\
  Cloud-init v. 0.7.8 running 'init-local' at Thu, 03 Nov 2016\
  06:51:06 +0000. Up 1.0 seconds.
 2016-08-30 21:53:25.972325+00:00 y1 [CLOUDINIT] handlers.py[DEBUG]: finish:\
  modules-final: SUCCESS: running modules for final
-"""
-)
+""")
 
 
 class TestDumpEvents: