1 /* 2 * Copyright (C) 2011 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 package com.android.loganalysis.parser; 17 18 import com.android.loganalysis.item.BugreportItem; 19 import com.android.loganalysis.item.IItem; 20 import com.android.loganalysis.item.MiscKernelLogItem; 21 import com.android.loganalysis.util.ArrayUtil; 22 23 import junit.framework.TestCase; 24 25 import java.text.DateFormat; 26 import java.text.ParseException; 27 import java.text.SimpleDateFormat; 28 import java.util.Arrays; 29 import java.util.Date; 30 import java.util.List; 31 32 /** 33 * Unit tests for {@link BugreportParser} 34 */ 35 public class BugreportParserTest extends TestCase { 36 37 /** 38 * Test that a bugreport can be parsed. 39 */ testParse()40 public void testParse() throws ParseException { 41 List<String> lines = 42 Arrays.asList( 43 "========================================================", 44 "== dumpstate: 2012-04-25 20:45:10", 45 "========================================================", 46 "------ SECTION ------", 47 "", 48 "------ MEMORY INFO (/proc/meminfo) ------", 49 "MemTotal: 353332 kB", 50 "MemFree: 65420 kB", 51 "Buffers: 20800 kB", 52 "Cached: 86204 kB", 53 "SwapCached: 0 kB", 54 "", 55 "------ CPU INFO (top -n 1 -d 1 -m 30 -t) ------", 56 "", 57 "User 3%, System 3%, IOW 0%, IRQ 0%", 58 "User 33 + Nice 0 + Sys 32 + Idle 929 + IOW 0 + IRQ 0 + SIRQ 0 = 994", 59 "", 60 "------ PROCRANK (procrank) ------", 61 " PID Vss Rss Pss Uss cmdline", 62 " 178 87136K 81684K 52829K 50012K system_server", 63 " 1313 78128K 77996K 48603K 45812K com.google.android.apps.maps", 64 " 3247 61652K 61492K 33122K 30972K com.android.browser", 65 " ------ ------ ------", 66 " 203624K 163604K TOTAL", 67 "RAM: 731448K total, 415804K free, 9016K buffers, 108548K cached", 68 "[procrank: 1.6s elapsed]", 69 "", 70 "------ KERNEL LOG (dmesg) ------", 71 "<6>[ 0.000000] Initializing cgroup subsys cpu", 72 "<3>[ 1.000000] benign message", 73 "", 74 "", 75 "------ SYSTEM LOG (logcat -v threadtime -d *:v) ------", 76 "04-25 09:55:47.799 3064 3082 E AndroidRuntime: java.lang.Exception", 77 "04-25 09:55:47.799 3064 3082 E AndroidRuntime: \tat class.method1(Class.java:1)", 78 "04-25 09:55:47.799 3064 3082 E AndroidRuntime: \tat class.method2(Class.java:2)", 79 "04-25 09:55:47.799 3064 3082 E AndroidRuntime: \tat class.method3(Class.java:3)", 80 "04-25 17:17:08.445 312 366 E ActivityManager: ANR (application not responding) in process: com.android.package", 81 "04-25 17:17:08.445 312 366 E ActivityManager: Reason: keyDispatchingTimedOut", 82 "04-25 17:17:08.445 312 366 E ActivityManager: Load: 0.71 / 0.83 / 0.51", 83 "04-25 17:17:08.445 312 366 E ActivityManager: 33% TOTAL: 21% user + 11% kernel + 0.3% iowait", 84 "04-25 18:33:27.273 115 115 I DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***", 85 "04-25 18:33:27.273 115 115 I DEBUG : Build fingerprint: 'product:build:target'", 86 "04-25 18:33:27.273 115 115 I DEBUG : pid: 3112, tid: 3112 >>> com.google.android.browser <<<", 87 "04-25 18:33:27.273 115 115 I DEBUG : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 00000000", 88 "", 89 "------ SYSTEM PROPERTIES ------", 90 "[dalvik.vm.dexopt-flags]: [m=y]", 91 "[dalvik.vm.heapgrowthlimit]: [48m]", 92 "[dalvik.vm.heapsize]: [256m]", 93 "[gsm.version.ril-impl]: [android moto-ril-multimode 1.0]", 94 "", 95 "------ LAST KMSG (/proc/last_kmsg) ------", 96 "[ 0.000000] Initializing cgroup subsys cpu", 97 "[ 16.203491] benign message", 98 "", 99 "------ SECTION ------", 100 "", 101 "------ VM TRACES AT LAST ANR (/data/anr/traces.txt: 2012-04-25 17:17:08) ------", 102 "", 103 "", 104 "----- pid 2887 at 2012-04-25 17:17:08 -----", 105 "Cmd line: com.android.package", 106 "", 107 "DALVIK THREADS:", 108 "(mutexes: tll=0 tsl=0 tscl=0 ghl=0)", 109 "", 110 "\"main\" prio=5 tid=1 SUSPENDED", 111 " | group=\"main\" sCount=1 dsCount=0 obj=0x00000001 self=0x00000001", 112 " | sysTid=2887 nice=0 sched=0/0 cgrp=foreground handle=0000000001", 113 " | schedstat=( 0 0 0 ) utm=5954 stm=1017 core=0", 114 " at class.method1(Class.java:1)", 115 " at class.method2(Class.java:2)", 116 " at class.method2(Class.java:2)", 117 "", 118 "----- end 2887 -----", 119 "", 120 "------ SECTION ------", 121 "", 122 "------ DUMPSYS (dumpsys) ------", 123 "DUMP OF SERVICE batterystats:", 124 "Battery History (0% used, 1636 used of 256KB, 15 strings using 794):", 125 " 0 (15) RESET:TIME: 1970-01-10-06-23-28", 126 " +45s702ms (2) 001 80080000 volt=4187", 127 " +1m15s525ms (2) 001 80080000 temp=299 volt=4155", 128 "Statistics since last charged:", 129 " Time on battery: 1h 5m 2s 4ms (9%) realtime, 1h 5m 2s 4ms (9%) uptime", 130 " Time on battery screen off: 1h 4m 5s 8ms (9%) realtime, 1h 4m 5s 8ms (9%) uptime", 131 " All kernel wake locks:", 132 " Kernel Wake lock PowerManagerService.WakeLocks: 5m 10s 6ms (2 times) realtime", 133 " Kernel Wake lock msm_serial_hs_rx: 2m 13s 612ms (258 times) realtime", 134 "", 135 " All partial wake locks:", 136 " Wake lock 1001 ProxyController: 1h 4m 47s 565ms (4 times) realtime", 137 " Wake lock 1013 AudioMix: 1s 979ms (3 times) realtime", 138 "", 139 " All wakeup reasons:", 140 " Wakeup reason 2:bcmsdh_sdmmc:2:qcom,smd:2:msmgio: 1m 5s 4ms (2 times) realtime", 141 " Wakeup reason 2:qcom,smd-rpm:2:fc4c.qcom,spmi: 7m 1s 914ms (7 times) realtime", 142 "", 143 "DUMP OF SERVICE package:", 144 "Package [com.google.android.calculator] (e075c9d):", 145 " userId=10071", 146 " secondaryCpuAbi=null", 147 " versionCode=73000302 minSdk=10000 targetSdk=10000", 148 " versionName=7.3 (3821978)", 149 " splits=[base]", 150 "========================================================", 151 "== Running Application Services", 152 "========================================================", 153 "------ APP SERVICES (dumpsys activity service all) ------", 154 "SERVICE com.google.android.gms/" 155 + "com.google.android.location.internal.GoogleLocationManagerService f4c9d pid=14", 156 " Location Request History By Package:", 157 "Interval effective/min/max 1/0/0[s] Duration: 140[minutes] [" 158 + "com.google.android.gms, PRIORITY_NO_POWER, UserLocationProducer] " 159 + "Num requests: 2 Active: true", 160 "Interval effective/min/max 284/285/3600[s] Duration: 140[minutes] " 161 + "[com.google.android.googlequicksearchbox, PRIORITY_BALANCED_POWER_ACCURACY] " 162 + "Num requests: 5 Active: true"); 163 164 BugreportItem bugreport = new BugreportParser().parse(lines); 165 assertNotNull(bugreport); 166 assertEquals(parseTime("2012-04-25 20:45:10.000"), bugreport.getTime()); 167 168 assertNotNull(bugreport.getMemInfo()); 169 assertEquals(5, bugreport.getMemInfo().size()); 170 171 assertNotNull(bugreport.getTop()); 172 assertEquals(994, bugreport.getTop().getTotal()); 173 174 assertNotNull(bugreport.getProcrank()); 175 assertEquals(3, bugreport.getProcrank().getPids().size()); 176 177 assertNotNull(bugreport.getKernelLog()); 178 assertEquals(1.0, bugreport.getKernelLog().getStopTime(), 0.000005); 179 180 assertNotNull(bugreport.getSystemLog()); 181 assertEquals(parseTime("2012-04-25 09:55:47.799"), bugreport.getSystemLog().getStartTime()); 182 assertEquals(parseTime("2012-04-25 18:33:27.273"), bugreport.getSystemLog().getStopTime()); 183 assertEquals(3, bugreport.getSystemLog().getEvents().size()); 184 assertEquals(1, bugreport.getSystemLog().getAnrs().size()); 185 assertNotNull(bugreport.getSystemLog().getAnrs().get(0).getTrace()); 186 187 assertNotNull(bugreport.getLastKmsg()); 188 assertEquals(16.203491, bugreport.getLastKmsg().getStopTime(), 0.000005); 189 190 assertNotNull(bugreport.getSystemProps()); 191 assertEquals(4, bugreport.getSystemProps().size()); 192 193 assertNotNull(bugreport.getDumpsys()); 194 assertNotNull(bugreport.getDumpsys().getBatteryStats()); 195 assertNotNull(bugreport.getDumpsys().getPackageStats()); 196 197 assertNotNull(bugreport.getActivityService()); 198 assertNotNull(bugreport.getActivityService().getLocationDumps().getLocationClients()); 199 assertEquals(bugreport.getActivityService().getLocationDumps().getLocationClients().size(), 200 2); 201 } 202 203 /** 204 * Test that the logcat year is set correctly from the bugreport timestamp. 205 */ testParse_set_logcat_year()206 public void testParse_set_logcat_year() throws ParseException { 207 List<String> lines = Arrays.asList( 208 "========================================================", 209 "== dumpstate: 1999-01-01 02:03:04", 210 "========================================================", 211 "------ SYSTEM LOG (logcat -v threadtime -d *:v) ------", 212 "01-01 01:02:03.000 1 1 I TAG : message", 213 "01-01 01:02:04.000 1 1 I TAG : message", 214 ""); 215 216 BugreportItem bugreport = new BugreportParser().parse(lines); 217 assertNotNull(bugreport); 218 assertEquals(parseTime("1999-01-01 02:03:04.000"), bugreport.getTime()); 219 assertNotNull(bugreport.getSystemLog()); 220 assertEquals(parseTime("1999-01-01 01:02:03.000"), bugreport.getSystemLog().getStartTime()); 221 assertEquals(parseTime("1999-01-01 01:02:04.000"), bugreport.getSystemLog().getStopTime()); 222 } 223 224 /** 225 * Test that the command line is parsed 226 */ testParse_command_line()227 public void testParse_command_line() { 228 List<String> lines = Arrays.asList("Command line:"); 229 BugreportItem bugreport = new BugreportParser().parse(lines); 230 assertTrue(bugreport.getCommandLine().isEmpty()); 231 232 lines = Arrays.asList("Command line: key=value"); 233 bugreport = new BugreportParser().parse(lines); 234 assertEquals(1, bugreport.getCommandLine().size()); 235 assertEquals("value", bugreport.getCommandLine().get("key")); 236 237 lines = Arrays.asList("Command line: key1=value1 key2=value2"); 238 bugreport = new BugreportParser().parse(lines); 239 assertEquals(2, bugreport.getCommandLine().size()); 240 assertEquals("value1", bugreport.getCommandLine().get("key1")); 241 assertEquals("value2", bugreport.getCommandLine().get("key2")); 242 243 // Test a bad strings 244 lines = Arrays.asList("Command line: key1=value=withequals key2= "); 245 bugreport = new BugreportParser().parse(lines); 246 assertEquals(2, bugreport.getCommandLine().size()); 247 assertEquals("value=withequals", bugreport.getCommandLine().get("key1")); 248 assertEquals("", bugreport.getCommandLine().get("key2")); 249 250 lines = Arrays.asList("Command line: key1=value1 nonkey key2="); 251 bugreport = new BugreportParser().parse(lines); 252 assertEquals(3, bugreport.getCommandLine().size()); 253 assertEquals("value1", bugreport.getCommandLine().get("key1")); 254 assertEquals("", bugreport.getCommandLine().get("key2")); 255 assertNull(bugreport.getCommandLine().get("nonkey")); 256 } 257 258 /** 259 * Test that a normal boot triggers a normal boot event and no unknown reason. 260 */ testParse_bootreason_kernel_good()261 public void testParse_bootreason_kernel_good() { 262 List<String> lines = Arrays.asList( 263 "========================================================", 264 "== dumpstate: 1999-01-01 02:03:04", 265 "========================================================", 266 "Command line: androidboot.bootreason=reboot", 267 ""); 268 BugreportItem bugreport = new BugreportParser().parse(lines); 269 assertNotNull(bugreport.getLastKmsg()); 270 assertEquals(1, bugreport.getLastKmsg().getEvents().size()); 271 assertEquals("Last boot reason: reboot", 272 bugreport.getLastKmsg().getEvents().get(0).getStack()); 273 assertEquals("NORMAL_REBOOT", bugreport.getLastKmsg().getEvents().get(0).getCategory()); 274 } 275 276 /** 277 * Test that a kernel reset boot triggers a kernel reset event and no unknown reason. 278 */ testParse_bootreason_kernel_bad()279 public void testParse_bootreason_kernel_bad() { 280 List<String> lines = Arrays.asList( 281 "========================================================", 282 "== dumpstate: 1999-01-01 02:03:04", 283 "========================================================", 284 "Command line: androidboot.bootreason=hw_reset", 285 ""); 286 BugreportItem bugreport = new BugreportParser().parse(lines); 287 assertNotNull(bugreport.getLastKmsg()); 288 assertEquals(1, bugreport.getLastKmsg().getEvents().size()); 289 assertEquals("Last boot reason: hw_reset", 290 bugreport.getLastKmsg().getEvents().get(0).getStack()); 291 assertEquals("KERNEL_RESET", bugreport.getLastKmsg().getEvents().get(0).getCategory()); 292 } 293 294 /** 295 * Test that a normal boot triggers a normal boot event and no unknown reason. 296 */ testParse_bootreason_prop_good()297 public void testParse_bootreason_prop_good() { 298 List<String> lines = Arrays.asList( 299 "========================================================", 300 "== dumpstate: 1999-01-01 02:03:04", 301 "========================================================", 302 "------ SYSTEM PROPERTIES ------", 303 "[ro.boot.bootreason]: [reboot]", 304 ""); 305 BugreportItem bugreport = new BugreportParser().parse(lines); 306 assertNotNull(bugreport.getLastKmsg()); 307 assertEquals(1, bugreport.getLastKmsg().getEvents().size()); 308 assertEquals("Last boot reason: reboot", 309 bugreport.getLastKmsg().getEvents().get(0).getStack()); 310 assertEquals("NORMAL_REBOOT", bugreport.getLastKmsg().getEvents().get(0).getCategory()); 311 } 312 313 /** 314 * Test that a kernel reset boot triggers a kernel reset event and no unknown reason. 315 */ testParse_bootreason_prop_bad()316 public void testParse_bootreason_prop_bad() { 317 List<String> lines = Arrays.asList( 318 "========================================================", 319 "== dumpstate: 1999-01-01 02:03:04", 320 "========================================================", 321 "------ SYSTEM PROPERTIES ------", 322 "[ro.boot.bootreason]: [hw_reset]", 323 ""); 324 BugreportItem bugreport = new BugreportParser().parse(lines); 325 assertNotNull(bugreport.getLastKmsg()); 326 assertEquals(1, bugreport.getLastKmsg().getEvents().size()); 327 assertEquals("Last boot reason: hw_reset", 328 bugreport.getLastKmsg().getEvents().get(0).getStack()); 329 assertEquals("KERNEL_RESET", bugreport.getLastKmsg().getEvents().get(0).getCategory()); 330 assertEquals("", bugreport.getLastKmsg().getEvents().get(0).getPreamble()); 331 assertEquals(0.0, bugreport.getLastKmsg().getEvents().get(0).getEventTime()); 332 assertEquals(0.0, bugreport.getLastKmsg().getStartTime()); 333 assertEquals(0.0, bugreport.getLastKmsg().getStopTime()); 334 } 335 336 /** 337 * Test that a kernel panic in the last kmsg and a kernel panic only triggers one kernel reset. 338 */ testParse_bootreason_duplicate()339 public void testParse_bootreason_duplicate() { 340 List<String> lines = Arrays.asList( 341 "========================================================", 342 "== dumpstate: 1999-01-01 02:03:04", 343 "========================================================", 344 "Command line: androidboot.bootreason=hw_reset", 345 "------ SYSTEM PROPERTIES ------", 346 "[ro.boot.bootreason]: [hw_reset]", 347 "", 348 "------ LAST KMSG (/proc/last_kmsg) ------", 349 "[ 0.000000] Initializing cgroup subsys cpu", 350 "[ 16.203491] Kernel panic", 351 ""); 352 BugreportItem bugreport = new BugreportParser().parse(lines); 353 assertNotNull(bugreport.getLastKmsg()); 354 assertEquals(1, bugreport.getLastKmsg().getEvents().size()); 355 assertEquals("Kernel panic", bugreport.getLastKmsg().getEvents().get(0).getStack()); 356 assertEquals("KERNEL_RESET", bugreport.getLastKmsg().getEvents().get(0).getCategory()); 357 } 358 359 /** 360 * Test that the trace is set correctly if there is only one ANR. 361 */ testSetAnrTrace_single()362 public void testSetAnrTrace_single() { 363 List<String> lines = Arrays.asList( 364 "========================================================", 365 "== dumpstate: 2012-04-25 20:45:10", 366 "========================================================", 367 "------ SYSTEM LOG (logcat -v threadtime -d *:v) ------", 368 "04-25 17:17:08.445 312 366 E ActivityManager: ANR (application not responding) in process: com.android.package", 369 "04-25 17:17:08.445 312 366 E ActivityManager: Reason: keyDispatchingTimedOut", 370 "04-25 17:17:08.445 312 366 E ActivityManager: Load: 0.71 / 0.83 / 0.51", 371 "04-25 17:17:08.445 312 366 E ActivityManager: 33% TOTAL: 21% user + 11% kernel + 0.3% iowait", 372 "", 373 "------ VM TRACES AT LAST ANR (/data/anr/traces.txt: 2012-04-25 17:17:08) ------", 374 "", 375 "----- pid 2887 at 2012-04-25 17:17:08 -----", 376 "Cmd line: com.android.package", 377 "", 378 "DALVIK THREADS:", 379 "(mutexes: tll=0 tsl=0 tscl=0 ghl=0)", 380 "", 381 "\"main\" prio=5 tid=1 SUSPENDED", 382 " | group=\"main\" sCount=1 dsCount=0 obj=0x00000001 self=0x00000001", 383 " | sysTid=2887 nice=0 sched=0/0 cgrp=foreground handle=0000000001", 384 " | schedstat=( 0 0 0 ) utm=5954 stm=1017 core=0", 385 " at class.method1(Class.java:1)", 386 " at class.method2(Class.java:2)", 387 " at class.method2(Class.java:2)", 388 "", 389 "----- end 2887 -----", 390 ""); 391 392 List<String> expectedStack = Arrays.asList( 393 "\"main\" prio=5 tid=1 SUSPENDED", 394 " | group=\"main\" sCount=1 dsCount=0 obj=0x00000001 self=0x00000001", 395 " | sysTid=2887 nice=0 sched=0/0 cgrp=foreground handle=0000000001", 396 " | schedstat=( 0 0 0 ) utm=5954 stm=1017 core=0", 397 " at class.method1(Class.java:1)", 398 " at class.method2(Class.java:2)", 399 " at class.method2(Class.java:2)"); 400 401 BugreportItem bugreport = new BugreportParser().parse(lines); 402 403 assertNotNull(bugreport.getSystemLog()); 404 assertEquals(1, bugreport.getSystemLog().getAnrs().size()); 405 assertEquals(ArrayUtil.join("\n", expectedStack), 406 bugreport.getSystemLog().getAnrs().get(0).getTrace()); 407 } 408 409 /** 410 * Test that the trace is set correctly if there are multiple ANRs. 411 */ testSetAnrTrace_multiple()412 public void testSetAnrTrace_multiple() { 413 List<String> lines = Arrays.asList( 414 "========================================================", 415 "== dumpstate: 2012-04-25 20:45:10", 416 "========================================================", 417 "------ SYSTEM LOG (logcat -v threadtime -d *:v) ------", 418 "04-25 17:17:08.445 312 366 E ActivityManager: ANR (application not responding) in process: com.android.package", 419 "04-25 17:17:08.445 312 366 E ActivityManager: Reason: keyDispatchingTimedOut", 420 "04-25 17:17:08.445 312 366 E ActivityManager: Load: 0.71 / 0.83 / 0.51", 421 "04-25 17:17:08.445 312 366 E ActivityManager: 33% TOTAL: 21% user + 11% kernel + 0.3% iowait", 422 "04-25 17:18:08.445 312 366 E ActivityManager: ANR (application not responding) in process: com.android.package", 423 "04-25 17:18:08.445 312 366 E ActivityManager: Reason: keyDispatchingTimedOut", 424 "04-25 17:18:08.445 312 366 E ActivityManager: Load: 0.71 / 0.83 / 0.51", 425 "04-25 17:18:08.445 312 366 E ActivityManager: 33% TOTAL: 21% user + 11% kernel + 0.3% iowait", 426 "04-25 17:19:08.445 312 366 E ActivityManager: ANR (application not responding) in process: com.android.different.pacakge", 427 "04-25 17:19:08.445 312 366 E ActivityManager: Reason: keyDispatchingTimedOut", 428 "04-25 17:19:08.445 312 366 E ActivityManager: Load: 0.71 / 0.83 / 0.51", 429 "04-25 17:19:08.445 312 366 E ActivityManager: 33% TOTAL: 21% user + 11% kernel + 0.3% iowait", 430 "", 431 "------ VM TRACES AT LAST ANR (/data/anr/traces.txt: 2012-04-25 17:18:08) ------", 432 "", 433 "----- pid 2887 at 2012-04-25 17:17:08 -----", 434 "Cmd line: com.android.package", 435 "", 436 "DALVIK THREADS:", 437 "(mutexes: tll=0 tsl=0 tscl=0 ghl=0)", 438 "", 439 "\"main\" prio=5 tid=1 SUSPENDED", 440 " | group=\"main\" sCount=1 dsCount=0 obj=0x00000001 self=0x00000001", 441 " | sysTid=2887 nice=0 sched=0/0 cgrp=foreground handle=0000000001", 442 " | schedstat=( 0 0 0 ) utm=5954 stm=1017 core=0", 443 " at class.method1(Class.java:1)", 444 " at class.method2(Class.java:2)", 445 " at class.method2(Class.java:2)", 446 "", 447 "----- end 2887 -----", 448 ""); 449 450 List<String> expectedStack = Arrays.asList( 451 "\"main\" prio=5 tid=1 SUSPENDED", 452 " | group=\"main\" sCount=1 dsCount=0 obj=0x00000001 self=0x00000001", 453 " | sysTid=2887 nice=0 sched=0/0 cgrp=foreground handle=0000000001", 454 " | schedstat=( 0 0 0 ) utm=5954 stm=1017 core=0", 455 " at class.method1(Class.java:1)", 456 " at class.method2(Class.java:2)", 457 " at class.method2(Class.java:2)"); 458 459 BugreportItem bugreport = new BugreportParser().parse(lines); 460 461 assertNotNull(bugreport.getSystemLog()); 462 assertEquals(3, bugreport.getSystemLog().getAnrs().size()); 463 assertNull(bugreport.getSystemLog().getAnrs().get(0).getTrace()); 464 assertEquals(ArrayUtil.join("\n", expectedStack), 465 bugreport.getSystemLog().getAnrs().get(1).getTrace()); 466 assertNull(bugreport.getSystemLog().getAnrs().get(2).getTrace()); 467 } 468 469 /** 470 * Test that the trace is set correctly if there is not traces file. 471 */ testSetAnrTrace_no_traces()472 public void testSetAnrTrace_no_traces() { 473 List<String> lines = Arrays.asList( 474 "========================================================", 475 "== dumpstate: 2012-04-25 20:45:10", 476 "========================================================", 477 "------ SYSTEM LOG (logcat -v threadtime -d *:v) ------", 478 "04-25 17:17:08.445 312 366 E ActivityManager: ANR (application not responding) in process: com.android.package", 479 "04-25 17:17:08.445 312 366 E ActivityManager: Reason: keyDispatchingTimedOut", 480 "04-25 17:17:08.445 312 366 E ActivityManager: Load: 0.71 / 0.83 / 0.51", 481 "04-25 17:17:08.445 312 366 E ActivityManager: 33% TOTAL: 21% user + 11% kernel + 0.3% iowait", 482 "", 483 "*** NO ANR VM TRACES FILE (/data/anr/traces.txt): No such file or directory", 484 ""); 485 486 BugreportItem bugreport = new BugreportParser().parse(lines); 487 488 assertNotNull(bugreport.getSystemLog()); 489 assertEquals(1, bugreport.getSystemLog().getAnrs().size()); 490 assertNull(bugreport.getSystemLog().getAnrs().get(0).getTrace()); 491 } 492 493 /** 494 * Add a test that ensures that the "new" style of stack dumping works. Traces aren't written to 495 * a global trace file. Instead, each ANR event is written to a separate trace file (note the 496 * "/data/anr/anr_4376042170248254515" instead of "/data/anr/traces.txt"). 497 */ testAnrTraces_not_global_traceFile()498 public void testAnrTraces_not_global_traceFile() { 499 List<String> lines = 500 Arrays.asList( 501 "========================================================", 502 "== dumpstate: 2017-06-12 16:46:29", 503 "========================================================", 504 "------ SYSTEM LOG (logcat -v threadtime -v printable -v uid -d *:v) ------", 505 "--------- beginning of main ", 506 "02-18 04:26:31.829 logd 468 468 W auditd : type=2000 audit(0.0:1): initialized", 507 "02-18 04:26:33.783 logd 468 468 I auditd : type=1403 audit(0.0:2): policy loaded auid=4294967295 ses=4294967295", 508 "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", 509 "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: ANR in com.example.android.helloactivity (com.example.android.helloactivity/.HelloActivity)", 510 "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: PID: 7176", 511 "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.)", 512 "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: Load: 6.85 / 7.07 / 5.31", 513 "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):", 514 "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", 515 "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", 516 "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 ", 517 "06-12 16:45:47.426 1000 1050 1124 E ActivityManager: 5.3% 489/surfaceflinger: 2.9% user + 2.3% kernel / faults: 15 minor ", 518 "", 519 "------ VM TRACES AT LAST ANR (/data/anr/anr_4376042170248254515: 2017-06-12 16:45:47) ------", 520 "", 521 "----- pid 7176 at 2017-06-12 16:45:45 -----", 522 "Cmd line: com.example.android.helloactivity", 523 "", 524 "DALVIK THREADS:", 525 "(mutexes: tll=0 tsl=0 tscl=0 ghl=0)", 526 "", 527 "\"main\" daemon prio=5 tid=5 Waiting", 528 " | group=\"system\" sCount=1 dsCount=0 flags=1 obj=0x140805e8 self=0x7caf4bf400", 529 " | sysTid=7184 nice=4 cgrp=default sched=0/0 handle=0x7c9b4e44f0", 530 " | state=S schedstat=( 507031 579062 19 ) utm=0 stm=0 core=3 HZ=100", 531 " | stack=0x7c9b3e2000-0x7c9b3e4000 stackSize=1037KB", 532 " | held mutexes=", 533 " at java.lang.Object.wait(Native method)", 534 " - waiting on <0x0281f7b7> (a java.lang.Class<java.lang.ref.ReferenceQueue>)", 535 " at java.lang.Daemons$ReferenceQueueDaemon.runInternal(Daemons.java:178)", 536 " - locked <0x0281f7b7> (a java.lang.Class<java.lang.ref.ReferenceQueue>)", 537 " at java.lang.Daemons$Daemon.run(Daemons.java:103)", 538 " at java.lang.Thread.run(Thread.java:764)", 539 "", 540 "----- end 7176 -----"); 541 542 // NOTE: The parser only extracts the main thread from the traces. 543 List<String> expectedStack = 544 Arrays.asList( 545 "\"main\" daemon prio=5 tid=5 Waiting", 546 " | group=\"system\" sCount=1 dsCount=0 flags=1 obj=0x140805e8 self=0x7caf4bf400", 547 " | sysTid=7184 nice=4 cgrp=default sched=0/0 handle=0x7c9b4e44f0", 548 " | state=S schedstat=( 507031 579062 19 ) utm=0 stm=0 core=3 HZ=100", 549 " | stack=0x7c9b3e2000-0x7c9b3e4000 stackSize=1037KB", 550 " | held mutexes=", 551 " at java.lang.Object.wait(Native method)", 552 " - waiting on <0x0281f7b7> (a java.lang.Class<java.lang.ref.ReferenceQueue>)", 553 " at java.lang.Daemons$ReferenceQueueDaemon.runInternal(Daemons.java:178)", 554 " - locked <0x0281f7b7> (a java.lang.Class<java.lang.ref.ReferenceQueue>)", 555 " at java.lang.Daemons$Daemon.run(Daemons.java:103)", 556 " at java.lang.Thread.run(Thread.java:764)"); 557 558 BugreportItem bugreport = new BugreportParser().parse(lines); 559 assertNotNull(bugreport.getSystemLog()); 560 assertEquals(1, bugreport.getSystemLog().getAnrs().size()); 561 assertEquals( 562 ArrayUtil.join("\n", expectedStack), 563 bugreport.getSystemLog().getAnrs().get(0).getTrace()); 564 } 565 566 /** 567 * Test that missing sections in bugreport are set to {@code null}, not empty {@link IItem}s. 568 */ testNoSections()569 public void testNoSections() { 570 List<String> lines = Arrays.asList( 571 "========================================================", 572 "== dumpstate: 2012-04-25 20:45:10", 573 "========================================================"); 574 575 BugreportItem bugreport = new BugreportParser().parse(lines); 576 assertNotNull(bugreport); 577 assertNull(bugreport.getDumpsys()); 578 assertNull(bugreport.getKernelLog()); 579 assertNull(bugreport.getMemInfo()); 580 assertNull(bugreport.getProcrank()); 581 assertNull(bugreport.getSystemLog()); 582 assertNull(bugreport.getSystemProps()); 583 assertNull(bugreport.getTop()); 584 assertNotNull(bugreport.getLastKmsg()); 585 List<MiscKernelLogItem> events = bugreport.getLastKmsg().getMiscEvents( 586 KernelLogParser.KERNEL_RESET); 587 assertEquals(events.size(), 1); 588 assertEquals(events.get(0).getStack(), "Unknown reason"); 589 590 lines = Arrays.asList( 591 "========================================================", 592 "== dumpstate: 2012-04-25 20:45:10", 593 "========================================================", 594 "", 595 "------ DUMPSYS (dumpsys) ------", 596 "", 597 "------ KERNEL LOG (dmesg) ------", 598 "", 599 "------ LAST KMSG (/proc/last_kmsg) ------", 600 "", 601 "------ MEMORY INFO (/proc/meminfo) ------", 602 "", 603 "------ PROCRANK (procrank) ------", 604 "", 605 "------ SYSTEM LOG (logcat -v threadtime -d *:v) ------", 606 "", 607 "------ SYSTEM PROPERTIES ------", 608 "", 609 "------ CPU INFO (top -n 1 -d 1 -m 30 -t) ------", 610 ""); 611 612 bugreport = new BugreportParser().parse(lines); 613 assertNotNull(bugreport); 614 assertNotNull(bugreport.getDumpsys()); 615 assertNull(bugreport.getKernelLog()); 616 assertNull(bugreport.getMemInfo()); 617 assertNull(bugreport.getProcrank()); 618 assertNull(bugreport.getSystemLog()); 619 assertNull(bugreport.getSystemProps()); 620 assertNull(bugreport.getTop()); 621 assertNotNull(bugreport.getLastKmsg()); 622 events = bugreport.getLastKmsg().getMiscEvents(KernelLogParser.KERNEL_RESET); 623 assertEquals(events.size(), 1); 624 assertEquals(events.get(0).getStack(), "Unknown reason"); 625 } 626 627 /** 628 * Test that section headers are correctly parsed. 629 */ testSectionHeader()630 public void testSectionHeader() { 631 List<String> lines = 632 Arrays.asList( 633 "========================================================", 634 "== dumpstate: 2012-04-25 20:45:10", 635 "========================================================", 636 "------ DUMPSYS (dumpsys) ------", 637 "DUMP OF SERVICE SurfaceFlinger:", 638 "--DrmDisplayCompositor[0]: num_frames=1456 num_ms=475440 fps=3.06243", 639 "---- DrmDisplayCompositor Layers: num=3", 640 "------ DrmDisplayCompositor Layer: plane=17 crtc=20 crtc[x/y/w/h]=0/0/2560/1800", 641 "------ DrmDisplayCompositor Layer: plane=21 disabled", 642 "------ DrmDisplayCompositor Layer: plane=22 disabled", 643 "DUMP OF SERVICE batterystats:", 644 "Battery History (0% used, 1636 used of 256KB, 15 strings using 794):", 645 " 0 (15) RESET:TIME: 1970-01-10-06-23-28", 646 " +45s702ms (2) 001 80080000 volt=4187", 647 " +1m15s525ms (2) 001 80080000 temp=299 volt=4155", 648 "Statistics since last charged:", 649 " Time on battery: 1h 5m 2s 4ms (9%) realtime, 1h 5m 2s 4ms (9%) uptime", 650 " Time on battery screen off: 1h 4m 5s 8ms (9%) realtime, 1h 4m 5s 8ms (9%) uptime", 651 " All kernel wake locks:", 652 " Kernel Wake lock PowerManagerService.WakeLocks: 5m 10s 6ms (2 times) realtime", 653 " Kernel Wake lock msm_serial_hs_rx: 2m 13s 612ms (258 times) realtime", 654 "", 655 " All partial wake locks:", 656 " Wake lock 1001 ProxyController: 1h 4m 47s 565ms (4 times) realtime", 657 " Wake lock 1013 AudioMix: 1s 979ms (3 times) realtime", 658 "", 659 " All wakeup reasons:", 660 " Wakeup reason 2:bcmsdh_sdmmc:2:qcom,smd:2:msmgio: 1m 5s 4ms (2 times) realtime", 661 " Wakeup reason 2:qcom,smd-rpm:2:fc4c.qcom,spmi: 7m 1s 914ms (7 times) realtime", 662 "DUMP OF SERVICE package:", 663 "Package [com.google.android.calculator] (e075c9d):", 664 " use rId=10071", 665 " secondaryCpuAbi=null", 666 " versionCode=73000302 minSdk=10000 targetSdk=10000", 667 " versionName=7.3 (3821978)", 668 " splits=[base]", 669 "DUMP OF SERVICE procstats:", 670 "COMMITTED STATS FROM 2015-09-30-07-44-54:", 671 " * system / 1000 / v23:", 672 " TOTAL: 100% (118MB-118MB-118MB/71MB-71MB-71MB over 1)", 673 " Persistent: 100% (118MB-118MB-118MB/71MB-71MB-71MB over 1)", 674 " * com.android.phone / 1001 / v23:", 675 " TOTAL: 6.7%", 676 " Persistent: 6.7%", 677 ""); 678 BugreportItem bugreport = new BugreportParser().parse(lines); 679 assertNotNull(bugreport.getDumpsys()); 680 assertNotNull(bugreport.getDumpsys().getBatteryStats()); 681 assertNotNull(bugreport.getDumpsys().getPackageStats()); 682 assertNotNull(bugreport.getDumpsys().getProcStats()); 683 } 684 685 /** 686 * Test that an empty input returns {@code null}. 687 */ testEmptyInput()688 public void testEmptyInput() { 689 BugreportItem item = new BugreportParser().parse(Arrays.asList("")); 690 assertNull(item); 691 } 692 693 /** 694 * Test that app names from logcat events are populated by matching the logcat PIDs with the 695 * PIDs from the logcat. 696 */ testSetAppsFromProcrank()697 public void testSetAppsFromProcrank() { 698 List<String> lines = Arrays.asList( 699 "========================================================", 700 "== dumpstate: 2012-04-25 20:45:10", 701 "========================================================", 702 "------ PROCRANK (procrank) ------", 703 " PID Vss Rss Pss Uss cmdline", 704 " 3064 87136K 81684K 52829K 50012K com.android.package1", 705 " 3066 87136K 81684K 52829K 50012K com.android.package2", 706 " ------ ------ ------", 707 " 203624K 163604K TOTAL", 708 "RAM: 731448K total, 415804K free, 9016K buffers, 108548K cached", 709 "[procrank: 1.6s elapsed]", 710 "------ SYSTEM LOG (logcat -v threadtime -d *:v) ------", 711 "04-25 09:55:47.799 3064 3082 E AndroidRuntime: java.lang.Exception", 712 "04-25 09:55:47.799 3064 3082 E AndroidRuntime: \tat class.method1(Class.java:1)", 713 "04-25 09:55:47.799 3064 3082 E AndroidRuntime: \tat class.method2(Class.java:2)", 714 "04-25 09:55:47.799 3064 3082 E AndroidRuntime: \tat class.method3(Class.java:3)", 715 "04-25 09:55:47.799 3065 3083 E AndroidRuntime: java.lang.Exception", 716 "04-25 09:55:47.799 3065 3083 E AndroidRuntime: \tat class.method1(Class.java:1)", 717 "04-25 09:55:47.799 3065 3083 E AndroidRuntime: \tat class.method2(Class.java:2)", 718 "04-25 09:55:47.799 3065 3083 E AndroidRuntime: \tat class.method3(Class.java:3)", 719 "04-25 09:55:47.799 3065 3084 E AndroidRuntime: FATAL EXCEPTION: main", 720 "04-25 09:55:47.799 3066 3084 E AndroidRuntime: Process: com.android.package3, PID: 1234", 721 "04-25 09:55:47.799 3066 3084 E AndroidRuntime: java.lang.Exception", 722 "04-25 09:55:47.799 3066 3084 E AndroidRuntime: \tat class.method1(Class.java:1)", 723 "04-25 09:55:47.799 3066 3084 E AndroidRuntime: \tat class.method2(Class.java:2)", 724 "04-25 09:55:47.799 3066 3084 E AndroidRuntime: \tat class.method3(Class.java:3)"); 725 726 BugreportItem bugreport = new BugreportParser().parse(lines); 727 assertNotNull(bugreport.getSystemLog()); 728 assertEquals(3, bugreport.getSystemLog().getJavaCrashes().size()); 729 assertEquals("com.android.package1", 730 bugreport.getSystemLog().getJavaCrashes().get(0).getApp()); 731 assertNull(bugreport.getSystemLog().getJavaCrashes().get(1).getApp()); 732 assertEquals("com.android.package3", 733 bugreport.getSystemLog().getJavaCrashes().get(2).getApp()); 734 } 735 736 /** 737 * Some Android devices refer to SYSTEM LOG as MAIN LOG. Check that parser recognizes this 738 * alternate syntax. 739 */ testSystemLogAsMainLog()740 public void testSystemLogAsMainLog() { 741 List<String> lines = Arrays.asList( 742 "------ MAIN LOG (logcat -b main -b system -v threadtime -d *:v) ------", 743 "--------- beginning of /dev/log/system", 744 "12-11 19:48:07.945 1484 1508 D BatteryService: update start"); 745 BugreportItem bugreport = new BugreportParser().parse(lines); 746 assertNotNull(bugreport.getSystemLog()); 747 } 748 749 /** 750 * Some Android devices refer to SYSTEM LOG as MAIN AND SYSTEM LOG. Check that parser 751 * recognizes this alternate syntax. 752 */ testSystemAndMainLog()753 public void testSystemAndMainLog() { 754 List<String> lines = Arrays.asList( 755 "------ MAIN AND SYSTEM LOG (logcat -b main -b system -v threadtime -d *:v) ------", 756 "--------- beginning of /dev/log/system", 757 "12-17 15:15:12.877 1994 2019 D UiModeManager: updateConfigurationLocked: "); 758 BugreportItem bugreport = new BugreportParser().parse(lines); 759 assertNotNull(bugreport.getSystemLog()); 760 } 761 parseTime(String timeStr)762 private Date parseTime(String timeStr) throws ParseException { 763 DateFormat formatter = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS"); 764 return formatter.parse(timeStr); 765 } 766 } 767