Support parsing the boottime legacy log format (i.e processing actions)

b/62394657

Test: OK (257 tests).
Change-Id: Ib5f5f9db27426b1a334e3c05faa6eb183a2e2975

2 files changed, 59 insertions, 46 deletions

diff --git a/src/com/android/loganalysis/parser/DmesgParser.java b/src/com/android/loganalysis/parser/DmesgParser.java
index ce3d389..63026d4 100644
--- a/src/com/android/loganalysis/parser/DmesgParser.java
+++ b/src/com/android/loganalysis/parser/DmesgParser.java
@@ -71,13 +71,22 @@ public class DmesgParser implements IParser {
     private static final Pattern START_STAGE = Pattern.compile(
             String.format("%s%s", SERVICE_PREFIX, START_STAGE_PREFIX));
 
+    // Matches: init: processing action (early-init) from (/init.rc:14)
+    private static final String START_PROCESSING_ACTION_PREFIX =
+            String.format("processing action \\((?<%s>.*)\\) from.*$", ACTION);
+
     // Matches: init: processing action (early-init)
-    private static final String START_PROCESSING_ACTION_PREFIX = String.format(
-            "processing action \\((?<%s>.*)\\) from.*$", ACTION);
+    private static final String START_PROCESSING_ACTION_PREFIX_LEGACY =
+            String.format("processing action \\((?<%s>.*)\\).*$", ACTION);
+
+    // Matches: init: processing action (early-init) from (/init.rc:14)
+    private static final Pattern START_PROCESSING_ACTION =
+            Pattern.compile(String.format("%s%s", SERVICE_PREFIX, START_PROCESSING_ACTION_PREFIX));
 
-    // Matches: [   14.942872] init: processing action (early-init)
-    private static final Pattern START_PROCESSING_ACTION = Pattern.compile(
-            String.format("%s%s", SERVICE_PREFIX, START_PROCESSING_ACTION_PREFIX));
+    // Matches: init: processing action (early-init)
+    private static final Pattern START_PROCESSING_ACTION_LEGACY =
+            Pattern.compile(
+                    String.format("%s%s", SERVICE_PREFIX, START_PROCESSING_ACTION_PREFIX_LEGACY));
 
     // Matches: [    3.791635] ueventd: Coldboot took 0.695055 seconds
     private static final String STAGE_SUFFIX= String.format(
@@ -216,7 +225,8 @@ public class DmesgParser implements IParser {
     @VisibleForTesting
     boolean parseActionInfo(String line) {
         Matcher match = null;
-        if ((match = matches(START_PROCESSING_ACTION, line)) != null) {
+        if ((match = matches(START_PROCESSING_ACTION, line)) != null
+                || (match = matches(START_PROCESSING_ACTION_LEGACY, line)) != null) {
             DmesgActionInfoItem actionInfoItem = new DmesgActionInfoItem();
             actionInfoItem.setActionName(match.group(ACTION));
             actionInfoItem.setStartTime((long) (Double.parseDouble(
diff --git a/tests/src/com/android/loganalysis/parser/DmesgParserTest.java b/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
index 7db2c49..20665ea 100644
--- a/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
+++ b/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
@@ -38,27 +38,30 @@ public class DmesgParserTest extends TestCase {
 
     private static final String BOOT_ANIMATION = "bootanim";
     private static final String NETD = "netd";
-    private static final String[] LINES = new String[] {
-            "[    3.786943] ueventd: Coldboot took 0.701291 seconds",
-            "[   22.962730] init: starting service 'bootanim'...",
-            "[   23.252321] init: starting service 'netd'...",
-            "[   29.331069] ipa-wan ipa_wwan_ioctl:1428 dev(rmnet_data0) register to IPA",
-            "[   32.182592] ueventd: fixup /sys/devices/virtual/input/poll_delay 0 1004 660",
-            "[   35.642666] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts",
-            "[   39.855818] init: Service 'bootanim' (pid 588) exited with status 0",
-            "[   41.665818] init: init first stage started!",
-            "[   44.942872] init: processing action (early-init) from (/init.rc:13)",
-            "[   47.233446] init: processing action (set_mmap_rnd_bits) from (<Builtin Action>:0)",
-            "[   47.240083] init: processing action (set_kptr_restrict) from (<Builtin Action>:0)",
-            "[   47.245778] init: processing action (keychord_init) from (<Builtin Action>:0)",
-            "[   52.361049] init: processing action (persist.sys.usb.config=* boot) from (<Builtin Action>:0)",
-            "[   52.361108] init: processing action (enable_property_trigger) from (<Builtin Action>:0)",
-            "[   52.361313] init: processing action (security.perf_harden=1) from (/init.rc:677)",
-            "[   52.361495] init: processing action (ro.debuggable=1) from (/init.rc:700)",
-            "[   59.331069] ipa-wan ipa_wwan_ioctl:1428 dev(rmnet_data0) register to IPA",
-            "[   62.182592] ueventd: fixup /sys/devices/virtual/input/poll_delay 0 1004 660",
-            "[   65.642666] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts",
-            "[   69.855818] init: Service 'bootanim' (pid 588) exited with status 0"};
+    private static final String[] LINES =
+            new String[] {
+                "[    3.786943] ueventd: Coldboot took 0.701291 seconds",
+                "[   22.962730] init: starting service 'bootanim'...",
+                "[   23.252321] init: starting service 'netd'...",
+                "[   29.331069] ipa-wan ipa_wwan_ioctl:1428 dev(rmnet_data0) register to IPA",
+                "[   32.182592] ueventd: fixup /sys/devices/virtual/input/poll_delay 0 1004 660",
+                "[   35.642666] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts",
+                "[   39.855818] init: Service 'bootanim' (pid 588) exited with status 0",
+                "[   41.665818] init: init first stage started!",
+                "[   44.942872] init: processing action (early-init) from (/init.rc:13)",
+                "[   47.233446] init: processing action (set_mmap_rnd_bits) from (<Builtin Action>:0)",
+                "[   47.240083] init: processing action (set_kptr_restrict) from (<Builtin Action>:0)",
+                "[   47.245778] init: processing action (keychord_init) from (<Builtin Action>:0)",
+                "[   52.361049] init: processing action (persist.sys.usb.config=* boot) from (<Builtin Action>:0)",
+                "[   52.361108] init: processing action (enable_property_trigger) from (<Builtin Action>:0)",
+                "[   52.361313] init: processing action (security.perf_harden=1) from (/init.rc:677)",
+                "[   52.361495] init: processing action (ro.debuggable=1) from (/init.rc:700)",
+                "[   58.298293] init: processing action (sys.boot_completed=1)",
+                "[   59.331069] ipa-wan ipa_wwan_ioctl:1428 dev(rmnet_data0) register to IPA",
+                "[   62.182592] ueventd: fixup /sys/devices/virtual/input/poll_delay 0 1004 660",
+                "[   65.642666] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts",
+                "[   69.855818] init: Service 'bootanim' (pid 588) exited with status 0"
+            };
 
     private static final Map<String, DmesgServiceInfoItem> EXPECTED_SERVICE_INFO_ITEMS =
             getExpectedServiceInfoItems();
@@ -93,9 +96,9 @@ public class DmesgParserTest extends TestCase {
 
         assertEquals("Service info items list size should be 2", 2,
                 dmesgParser.getServiceInfoItems().size());
-        assertEquals("Stage info items list size should be 2", 2,
+        assertEquals("Stage info items list size should be 2",2,
                 dmesgParser.getStageInfoItems().size());
-        assertEquals("Action info items list size should be 8", 8,
+        assertEquals("Action info items list size should be 9",9,
                 dmesgParser.getActionInfoItems().size());
 
         assertEquals(EXPECTED_SERVICE_INFO_ITEMS, actualDmesgItem.getServiceInfoItems());
@@ -115,7 +118,7 @@ public class DmesgParserTest extends TestCase {
                     dmesgParser.getServiceInfoItems().size());
             assertEquals("Stage info items list size should be 2", 2,
                     dmesgParser.getStageInfoItems().size());
-            assertEquals("Action info items list size should be 8", 8,
+            assertEquals("Action info items list size should be 9",9,
                     dmesgParser.getActionInfoItems().size());
         }
     }
@@ -198,35 +201,35 @@ public class DmesgParserTest extends TestCase {
         assertEquals(EXPECTED_STAGE_INFO_ITEMS, stageInfoItems);
     }
 
-    /**
-     * Test processing action start time logs
-     */
+    /** Test processing action start time logs */
     public void testCompleteActionInfo() {
         DmesgParser dmesgParser = new DmesgParser();
         for (String line : LINES) {
             dmesgParser.parseActionInfo(line);
         }
         List<DmesgActionInfoItem> actualActionInfoItems = dmesgParser.getActionInfoItems();
-        assertEquals(8, actualActionInfoItems.size());
+        assertEquals(9, actualActionInfoItems.size());
         assertEquals(EXPECTED_ACTION_INFO_ITEMS, actualActionInfoItems);
     }
 
     private static List<DmesgActionInfoItem> getExpectedActionInfoItems() {
         return Arrays.asList(
                 new DmesgActionInfoItem("early-init", (long) (Double.parseDouble("44942.872"))),
-                new DmesgActionInfoItem("set_mmap_rnd_bits",
-                        (long) (Double.parseDouble("47233.446"))),
-                new DmesgActionInfoItem("set_kptr_restrict",
-                        (long) (Double.parseDouble("47240.083"))),
+                new DmesgActionInfoItem(
+                        "set_mmap_rnd_bits", (long) (Double.parseDouble("47233.446"))),
+                new DmesgActionInfoItem(
+                        "set_kptr_restrict", (long) (Double.parseDouble("47240.083"))),
                 new DmesgActionInfoItem("keychord_init", (long) (Double.parseDouble("47245.778"))),
-                new DmesgActionInfoItem("persist.sys.usb.config=* boot",
-                        (long) (Double.parseDouble("52361.049"))),
-                new DmesgActionInfoItem("enable_property_trigger",
-                        (long) (Double.parseDouble("52361.108"))),
-                new DmesgActionInfoItem("security.perf_harden=1",
-                        (long) (Double.parseDouble("52361.313"))),
-                new DmesgActionInfoItem("ro.debuggable=1",
-                        (long) (Double.parseDouble("52361.495"))));
+                new DmesgActionInfoItem(
+                        "persist.sys.usb.config=* boot", (long) (Double.parseDouble("52361.049"))),
+                new DmesgActionInfoItem(
+                        "enable_property_trigger", (long) (Double.parseDouble("52361.108"))),
+                new DmesgActionInfoItem(
+                        "security.perf_harden=1", (long) (Double.parseDouble("52361.313"))),
+                new DmesgActionInfoItem(
+                        "ro.debuggable=1", (long) (Double.parseDouble("52361.495"))),
+                new DmesgActionInfoItem(
+                        "sys.boot_completed=1", (long) (Double.parseDouble("58298.293"))));
     }
 
     private static List<DmesgStageInfoItem> getExpectedStageInfoItems() {