Merge "Accomodate new log format logged in dmesg during boot"

3 files changed, 56 insertions, 16 deletions

diff --git a/src/com/android/loganalysis/item/DmesgStageInfoItem.java b/src/com/android/loganalysis/item/DmesgStageInfoItem.java
index a5bfd39..a446090 100644
--- a/src/com/android/loganalysis/item/DmesgStageInfoItem.java
+++ b/src/com/android/loganalysis/item/DmesgStageInfoItem.java
@@ -30,9 +30,11 @@ public class DmesgStageInfoItem extends GenericItem {
     public static final String STAGE_NAME = "STAGE_NAME";
     /** Constant for JSON output */
     public static final String STAGE_START_TIME = "STAGE_START_TIME";
+    /** Constant for JSON output */
+    public static final String STAGE_DURATION = "STAGE_DURATION";
 
     private static final Set<String> ATTRIBUTES = new HashSet<String>(Arrays.asList(
-            STAGE_NAME, STAGE_START_TIME));
+            STAGE_NAME, STAGE_START_TIME, STAGE_DURATION));
 
     /**
      * The constructor for {@link DmesgStageInfoItem}.
@@ -44,10 +46,11 @@ public class DmesgStageInfoItem extends GenericItem {
     /**
      * The constructor for {@link DmesgStageInfoItem}.
      */
-    public DmesgStageInfoItem(String name, Long startTime) {
+    public DmesgStageInfoItem(String name, Long startTime, Long duration) {
         super(ATTRIBUTES);
         setAttribute(STAGE_NAME, name);
         setAttribute(STAGE_START_TIME, startTime);
+        setAttribute(STAGE_DURATION, duration);
     }
 
     /**
@@ -78,10 +81,24 @@ public class DmesgStageInfoItem extends GenericItem {
         setAttribute(STAGE_START_TIME, startTime);
     }
 
+    /**
+     * Get the duration in msecs
+     */
+    public Long getDuration() {
+        return (Long) getAttribute(STAGE_DURATION);
+    }
+
+    /**
+     * Set the duration in msecs
+     */
+    public void setDuration(Long duration) {
+        setAttribute(STAGE_DURATION, duration);
+    }
+
     @Override
     public String toString() {
         return "StageInfoItem [getStageName()=" + getStageName() + ", getStartTime()="
-                + getStartTime() + "]";
+                + getStartTime() + ", getDuration()=" + getDuration() + "]";
     }
 
 }
diff --git a/src/com/android/loganalysis/parser/DmesgParser.java b/src/com/android/loganalysis/parser/DmesgParser.java
index bd0d8e4..ce3d389 100644
--- a/src/com/android/loganalysis/parser/DmesgParser.java
+++ b/src/com/android/loganalysis/parser/DmesgParser.java
@@ -20,6 +20,7 @@ import com.android.loganalysis.item.DmesgActionInfoItem;
 import com.android.loganalysis.item.DmesgItem;
 import com.android.loganalysis.item.DmesgServiceInfoItem;
 import com.android.loganalysis.item.DmesgStageInfoItem;
+
 import com.google.common.annotations.VisibleForTesting;
 
 import java.io.BufferedReader;
@@ -39,15 +40,22 @@ public class DmesgParser implements IParser {
     private static final String TIMESTAMP = "TIMESTAMP";
     private static final String STAGE = "STAGE";
     private static final String ACTION = "ACTION";
+    private static final String DURATION = "DURATION";
+    private static final String UEVENTD = "ueventd";
+
     // Matches: [ 14.822691] init:
     private static final String SERVICE_PREFIX = String.format("^\\[\\s+(?<%s>.*)\\] init:\\s+",
             TIMESTAMP);
+    // Matches: [    3.791635] ueventd:
+    private static final String UEVENTD_PREFIX = String.format("^\\[\\s+(?<%s>.*)\\] ueventd:\\s+",
+            TIMESTAMP);
+
     // Matches: starting service 'ueventd'...
     private static final String START_SERVICE_SUFFIX = String.format("starting service "
             + "\\'(?<%s>.*)\\'...", SERVICENAME);
     // Matches: Service 'ueventd' (pid 439) exited with status 0
     private static final String EXIT_SERVICE_SUFFIX = String.format("Service \\'(?<%s>.*)\\'\\s+"
-            + "\\((?<PID>.*)\\) exited with status 0", SERVICENAME);
+            + "\\((?<PID>.*)\\) exited with status 0.*", SERVICENAME);
 
     private static final Pattern START_SERVICE = Pattern.compile(
             String.format("%s%s", SERVICE_PREFIX, START_SERVICE_SUFFIX));
@@ -65,12 +73,18 @@ public class DmesgParser implements IParser {
 
     // Matches: init: processing action (early-init)
     private static final String START_PROCESSING_ACTION_PREFIX = String.format(
-            "processing action \\((?<%s>.*)\\)", ACTION);
+            "processing action \\((?<%s>.*)\\) from.*$", ACTION);
 
     // 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: [    3.791635] ueventd: Coldboot took 0.695055 seconds
+    private static final String STAGE_SUFFIX= String.format(
+            "(?<%s>.*)\\s+took\\s+(?<%s>.*)\\s+seconds$", STAGE, DURATION);
+    private static final Pattern UEVENTD_STAGE_INFO = Pattern.compile(
+            String.format("%s%s", UEVENTD_PREFIX, STAGE_SUFFIX));
+
 
     private DmesgItem mDmesgItem = new DmesgItem();
 
@@ -163,7 +177,8 @@ public class DmesgParser implements IParser {
 
     /**
      * Parse init stages log from each {@code line} of dmesg log and
-     * store the stage name and start time in a {@link DmesgStageInfoItem} object
+     * store the stage name, start time and duration if available in a
+     * {@link DmesgStageInfoItem} object
      *
      * @param individual line of the dmesg log
      * @return {@code true}, if the {@code line} indicates start of a boot stage,
@@ -180,6 +195,13 @@ public class DmesgParser implements IParser {
             mDmesgItem.addStageInfoItem(stageInfoItem);
             return true;
         }
+        if((match = matches(UEVENTD_STAGE_INFO, line)) != null) {
+            DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
+            stageInfoItem.setStageName(String.format("%s_%s", UEVENTD, match.group(STAGE)));
+            stageInfoItem.setDuration((long) (Double.parseDouble(
+                    match.group(DURATION)) * 1000));
+            mDmesgItem.addStageInfoItem(stageInfoItem);
+        }
         return false;
     }
 
diff --git a/tests/src/com/android/loganalysis/parser/DmesgParserTest.java b/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
index 2206733..7db2c49 100644
--- a/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
+++ b/tests/src/com/android/loganalysis/parser/DmesgParserTest.java
@@ -39,6 +39,7 @@ 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",
@@ -46,15 +47,14 @@ public class DmesgParserTest extends TestCase {
             "[   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!",
-            "[   42.425056] init: init second stage started!",
-            "[   44.942872] init: processing action (early-init)",
-            "[   47.233446] init: processing action (set_mmap_rnd_bits)",
-            "[   47.240083] init: processing action (set_kptr_restrict)",
-            "[   47.245778] init: processing action (keychord_init)",
-            "[   52.361049] init: processing action (persist.sys.usb.config=* boot)",
-            "[   52.361108] init: processing action (enable_property_trigger)",
-            "[   52.361313] init: processing action (security.perf_harden=1)",
-            "[   52.361495] init: processing action (ro.debuggable=1)",
+            "[   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",
@@ -231,7 +231,8 @@ public class DmesgParserTest extends TestCase {
 
     private static List<DmesgStageInfoItem> getExpectedStageInfoItems() {
         return Arrays.asList(
-                new DmesgStageInfoItem("first", 41665L), new DmesgStageInfoItem("second", 42425L));
+                new DmesgStageInfoItem("ueventd_Coldboot", null, 701L),
+                new DmesgStageInfoItem("first", 41665L, null));
     }
 
     private static Map<String, DmesgServiceInfoItem> getExpectedServiceInfoItems() {