merge_logs: Enable parsing of new syslog compatible format.
Both chrome and powerd will start generating logs in syslog-compatible
formats. This patch enables merge_logs to parse both the old and new
format of logs for both apps.
Detail in http://go/cros-syslog-format-log-chrome
BUG=chromium:1132768
TEST=`./run_pytest` to run merge_logs_unittest
Change-Id: I64ed59fab4804e399b28a34ec69ab26e3aa1d170
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/chromite/+/2649948
Reviewed-by: Mike Frysinger <vapier@chromium.org>
Tested-by: Yuta Hijikata <ythjkt@chromium.org>
Commit-Queue: Yuta Hijikata <ythjkt@chromium.org>
diff --git a/scripts/merge_logs.py b/scripts/merge_logs.py
index 1faf349..5ae3958 100644
--- a/scripts/merge_logs.py
+++ b/scripts/merge_logs.py
@@ -153,20 +153,31 @@
Pattern(AUTOSERV_DATE_RE, ParseAutoservDate, lambda m: m.group(1))
]
+# 2021-07-31T07:28:33.409065Z VERBOSE1 chrome[1694:1694]: [main.cc(480)]
+CHROME_DATE_NEW_RE = re.compile(
+ r'^(\d\d\d\d-\d\d-\d\dT\d\d:\d\d:\d\d.\d\d\d\d\d\dZ) ')
+
# [8525:8525:0731/072833.409065:VERBOSE1:gaia_screen_handler.cc(480)] OnPortalDetectionCompleted Online
-CHROME_DATE_RE = re.compile(r'^\[\d+:\d+:(\d{4}/\d{6}.\d{6}):')
+CHROME_DATE_OLD_RE = re.compile(r'^\[\d+:\d+:(\d{4}/\d{6}.\d{6}):')
ChromePatterns = [
- Pattern(CHROME_DATE_RE, ParseChromeDate, lambda m: m.group(1))
+ Pattern(CHROME_DATE_NEW_RE, ParseDate, lambda m: m.group(1)),
+ Pattern(CHROME_DATE_OLD_RE, ParseChromeDate, lambda m: m.group(1)),
]
# 2017/07/31 09:18:08.871 DEBUG| remote_access:0659| The temporary working directory on the device is /mnt/stateful_partition/unencrypted/preserve/cros-update/tmp.S7y5vF3xQE
CROS_DATE_RE = re.compile(r'^(\d\d\d\d/\d\d/\d\d \d\d:\d\d:\d\d.\d\d\d) ')
CrOSPatterns = [Pattern(CROS_DATE_RE, ParseDate, lambda m: m.group(1))]
-# [0731/070232:INFO:main.cc(289)] System uptime: 5s
-POWERD_DATE_RE = re.compile(r'^\[(\d{4}/\d{6}):')
+# 2021-01-27T05:38:56.751227Z INFO powerd: [main.cc(289)] System uptime: 5s
+POWERD_DATE_NEW_RE = re.compile(
+ r'^(\d\d\d\d-\d\d-\d\dT\d\d:\d\d:\d\d.\d\d\d\d\d\dZ) ')
+
+# [0127/053856:INFO:main.cc(289)] System uptime: 5s
+POWERD_DATE_OLD_RE = re.compile(r'^\[(\d{4}/\d{6}):')
+
PowerdPatterns = [
- Pattern(POWERD_DATE_RE, ParsePowerdDate, lambda m: m.group(1))
+ Pattern(POWERD_DATE_NEW_RE, ParseDate, lambda m: m.group(1)),
+ Pattern(POWERD_DATE_OLD_RE, ParsePowerdDate, lambda m: m.group(1)),
]
# 2017-07-31 07:00:46,650 - DEBUG - Running hook: /usr/local/bin/hooks/check_ethernet.hook
diff --git a/scripts/merge_logs_unittest.py b/scripts/merge_logs_unittest.py
index 8c0590f..bbda0b5 100644
--- a/scripts/merge_logs_unittest.py
+++ b/scripts/merge_logs_unittest.py
@@ -94,8 +94,8 @@
TZOFFSET))
-class ParseFileContentsTest(cros_test_lib.TestCase):
- """Test that ParseFileContents behaves correctly."""
+class ParseFileContentsTest(ParseDateTestBase):
+ """Test that parsers can parse old and new log formats."""
def testParseSysinfoPatterns(self):
filename = 'messages'
@@ -104,13 +104,59 @@
logs = merge_logs.ParseFileContents(filename, content)
lines = content.splitlines()
+ expected_logs = [
+ merge_logs.Log(
+ filename=filename,
+ date=datetime.datetime(2017, 7, 31, 7, 5, 10, 257860, TZOFFSET),
+ log=lines[0]),
+ merge_logs.Log(
+ filename=filename,
+ date=datetime.datetime(2017, 7, 31, 7, 5, 10, 257860,
+ dateutil.tz.tzutc()),
+ log=lines[1])
+ ]
- self.assertEqual(len(logs), 2)
- self.assertEqual(logs[0].filename, filename)
- self.assertEqual(logs[0].date,
- datetime.datetime(2017, 7, 31, 7, 5, 10, 257860, TZOFFSET))
- self.assertEqual(logs[0].log, lines[0])
- self.assertEqual(
- logs[1].date,
- datetime.datetime(2017, 7, 31, 7, 5, 10, 257860, dateutil.tz.tzutc()))
- self.assertEqual(logs[1].log, lines[1])
+ self.assertCountEqual(logs, expected_logs)
+
+ def testParseChromePatterns(self):
+ filename = 'ui.LATEST'
+ content = """[1694:1694:0731/072833.409065:VERBOSE1:main.cc(480)] Error
+2017-01-27T05:34:14.464052Z ERROR chrome[1694:1694]: [main.cc(11)] Error"""
+
+ logs = merge_logs.ParseFileContents(filename, content)
+ lines = content.splitlines()
+ expected_logs = [
+ merge_logs.Log(
+ filename=filename,
+ date=datetime.datetime(2017, 7, 31, 7, 28, 33, 409065, TZOFFSET),
+ log=lines[0]),
+ merge_logs.Log(
+ filename=filename,
+ date=datetime.datetime(2017, 1, 27, 5, 34, 14, 464052,
+ dateutil.tz.tzutc()),
+ log=lines[1])
+ ]
+
+ self.assertCountEqual(logs, expected_logs)
+
+ def testParsePowerdPatterns(self):
+ filename = 'powerd.LATEST'
+ content = """[0731/070232:INFO:main.cc(289)] System uptime: 5s
+2017-01-27T05:34:14.464052Z INFO powerd: [main.cc(289)] System uptime: 5s"""
+
+ logs = merge_logs.ParseFileContents(filename, content)
+
+ lines = content.splitlines()
+ expected_logs = [
+ merge_logs.Log(
+ filename=filename,
+ date=datetime.datetime(2017, 7, 31, 7, 2, 32, 0, TZOFFSET),
+ log=lines[0]),
+ merge_logs.Log(
+ filename=filename,
+ date=datetime.datetime(2017, 1, 27, 5, 34, 14, 464052,
+ dateutil.tz.tzutc()),
+ log=lines[1])
+ ]
+
+ self.assertCountEqual(logs, expected_logs)
