Fix LogAnalysis App Versions dump. (cherry-picked from unsubmitted change in oc-dev ag/2549006 and updated)
am: 3a879098fe
Change-Id: If38678bd4e96e1389bb8ff0cda32355a098991e8
diff --git a/OWNERS b/OWNERS
new file mode 100644
index 0000000..e4533e0
--- /dev/null
+++ b/OWNERS
@@ -0,0 +1,4 @@
+erowe@google.com
+guangzhu@google.com
+siniavine@google.com
+tobiast@google.com
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 @@
private static final Pattern START_STAGE = Pattern.compile(
String.format("%s%s", SERVICE_PREFIX, START_STAGE_PREFIX));
- // Matches: init: processing action (early-init)
- private static final String START_PROCESSING_ACTION_PREFIX = String.format(
- "processing action \\((?<%s>.*)\\) from.*$", ACTION);
+ // 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: [ 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 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: 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 @@
@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/BugreportParserTest.java b/tests/src/com/android/loganalysis/parser/BugreportParserTest.java
index 4f40820..5f3fc10 100644
--- a/tests/src/com/android/loganalysis/parser/BugreportParserTest.java
+++ b/tests/src/com/android/loganalysis/parser/BugreportParserTest.java
@@ -491,6 +491,79 @@
}
/**
+ * Add a test that ensures that the "new" style of stack dumping works. Traces aren't written to
+ * a global trace file. Instead, each ANR event is written to a separate trace file (note the
+ * "/data/anr/anr_4376042170248254515" instead of "/data/anr/traces.txt").
+ */
+ public void testAnrTraces_not_global_traceFile() {
+ List<String> lines =
+ Arrays.asList(
+ "========================================================",
+ "== dumpstate: 2017-06-12 16:46:29",
+ "========================================================",
+ "------ SYSTEM LOG (logcat -v threadtime -v printable -v uid -d *:v) ------",
+ "--------- beginning of main ",
+ "02-18 04:26:31.829 logd 468 468 W auditd : type=2000 audit(0.0:1): initialized",
+ "02-18 04:26:33.783 logd 468 468 I auditd : type=1403 audit(0.0:2): policy loaded auid=4294967295 ses=4294967295",
+ "02-18 04:26:33.783 logd 468 468 W auditd : type=1404 audit(0.0:3): enforcing=1 old_enforcing=0 auid=4294967295 ses=4294967295",
+ "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: ANR in com.example.android.helloactivity (com.example.android.helloactivity/.HelloActivity)",
+ "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: PID: 7176",
+ "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: Reason: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)",
+ "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: Load: 6.85 / 7.07 / 5.31",
+ "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: CPU usage from 235647ms to 0ms ago (2017-06-12 16:41:49.415 to 2017-06-12 16:45:45.062):",
+ "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: 7.7% 1848/com.ustwo.lwp: 4% user + 3.7% kernel / faults: 157 minor",
+ "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: 7.7% 2536/com.google.android.googlequicksearchbox:search: 5.6% user + 2.1% kernel / faults: 195 minor",
+ "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: 7.2% 1050/system_server: 4.5% user + 2.6% kernel / faults: 27117 minor ",
+ "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: 5.3% 489/surfaceflinger: 2.9% user + 2.3% kernel / faults: 15 minor ",
+ "",
+ "------ VM TRACES AT LAST ANR (/data/anr/anr_4376042170248254515: 2017-06-12 16:45:47) ------",
+ "",
+ "----- pid 7176 at 2017-06-12 16:45:45 -----",
+ "Cmd line: com.example.android.helloactivity",
+ "",
+ "DALVIK THREADS:",
+ "(mutexes: tll=0 tsl=0 tscl=0 ghl=0)",
+ "",
+ "\"main\" daemon prio=5 tid=5 Waiting",
+ " | group=\"system\" sCount=1 dsCount=0 flags=1 obj=0x140805e8 self=0x7caf4bf400",
+ " | sysTid=7184 nice=4 cgrp=default sched=0/0 handle=0x7c9b4e44f0",
+ " | state=S schedstat=( 507031 579062 19 ) utm=0 stm=0 core=3 HZ=100",
+ " | stack=0x7c9b3e2000-0x7c9b3e4000 stackSize=1037KB",
+ " | held mutexes=",
+ " at java.lang.Object.wait(Native method)",
+ " - waiting on <0x0281f7b7> (a java.lang.Class<java.lang.ref.ReferenceQueue>)",
+ " at java.lang.Daemons$ReferenceQueueDaemon.runInternal(Daemons.java:178)",
+ " - locked <0x0281f7b7> (a java.lang.Class<java.lang.ref.ReferenceQueue>)",
+ " at java.lang.Daemons$Daemon.run(Daemons.java:103)",
+ " at java.lang.Thread.run(Thread.java:764)",
+ "",
+ "----- end 7176 -----");
+
+ // NOTE: The parser only extracts the main thread from the traces.
+ List<String> expectedStack =
+ Arrays.asList(
+ "\"main\" daemon prio=5 tid=5 Waiting",
+ " | group=\"system\" sCount=1 dsCount=0 flags=1 obj=0x140805e8 self=0x7caf4bf400",
+ " | sysTid=7184 nice=4 cgrp=default sched=0/0 handle=0x7c9b4e44f0",
+ " | state=S schedstat=( 507031 579062 19 ) utm=0 stm=0 core=3 HZ=100",
+ " | stack=0x7c9b3e2000-0x7c9b3e4000 stackSize=1037KB",
+ " | held mutexes=",
+ " at java.lang.Object.wait(Native method)",
+ " - waiting on <0x0281f7b7> (a java.lang.Class<java.lang.ref.ReferenceQueue>)",
+ " at java.lang.Daemons$ReferenceQueueDaemon.runInternal(Daemons.java:178)",
+ " - locked <0x0281f7b7> (a java.lang.Class<java.lang.ref.ReferenceQueue>)",
+ " at java.lang.Daemons$Daemon.run(Daemons.java:103)",
+ " at java.lang.Thread.run(Thread.java:764)");
+
+ BugreportItem bugreport = new BugreportParser().parse(lines);
+ assertNotNull(bugreport.getSystemLog());
+ assertEquals(1, bugreport.getSystemLog().getAnrs().size());
+ assertEquals(
+ ArrayUtil.join("\n", expectedStack),
+ bugreport.getSystemLog().getAnrs().get(0).getTrace());
+ }
+
+ /**
* Test that missing sections in bugreport are set to {@code null}, not empty {@link IItem}s.
*/
public void testNoSections() {
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 @@
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 @@
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 @@
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 @@
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() {
