1 /* 2 * Copyright (C) 2013 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.KernelLogItem; 19 import com.android.loganalysis.item.LowMemoryKillerItem; 20 import com.android.loganalysis.item.MiscKernelLogItem; 21 import com.android.loganalysis.item.PageAllocationFailureItem; 22 import com.android.loganalysis.item.SELinuxItem; 23 import com.android.loganalysis.util.LogPatternUtil; 24 25 import junit.framework.TestCase; 26 27 import java.util.Arrays; 28 import java.util.List; 29 30 /** 31 * Unit tests for {@link KernelLogParser}. 32 */ 33 public class KernelLogParserTest extends TestCase { 34 /** 35 * Test that log lines formatted by last kmsg are able to be parsed. 36 */ testParseLastKmsg()37 public void testParseLastKmsg() { 38 List<String> lines = Arrays.asList( 39 "[ 0.000000] Start", 40 "[ 1.000000] Kernel panic", 41 "[ 2.000000] End"); 42 43 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 44 assertNotNull(kernelLog); 45 assertEquals(0.0, kernelLog.getStartTime(), 0.0000005); 46 assertEquals(2.0, kernelLog.getStopTime(), 0.0000005); 47 assertEquals(1, kernelLog.getEvents().size()); 48 assertEquals(1, kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).size()); 49 50 MiscKernelLogItem item = kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).get(0); 51 assertEquals(1.0, item.getEventTime(), 0.0000005); 52 assertEquals("[ 0.000000] Start", item.getPreamble()); 53 assertEquals("Kernel panic", item.getStack()); 54 } 55 56 /** 57 * Test that log lines formatted by dmsg are able to be parsed. 58 */ testParseDmesg()59 public void testParseDmesg() { 60 List<String> lines = Arrays.asList( 61 "<1>[ 0.000000] Start", 62 "<1>[ 1.000000] Kernel panic", 63 "<1>[ 2.000000] End"); 64 65 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 66 assertNotNull(kernelLog); 67 assertEquals(0.0, kernelLog.getStartTime(), 0.0000005); 68 assertEquals(2.0, kernelLog.getStopTime(), 0.0000005); 69 assertEquals(1, kernelLog.getEvents().size()); 70 assertEquals(1, kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).size()); 71 72 MiscKernelLogItem item = kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).get(0); 73 assertEquals(1.0, item.getEventTime(), 0.0000005); 74 assertEquals("<1>[ 0.000000] Start", item.getPreamble()); 75 assertEquals("Kernel panic", item.getStack()); 76 } 77 78 /** 79 * Test that last boot reasons are parsed. 80 */ testParseLastMessage()81 public void testParseLastMessage() { 82 List<String> lines = Arrays.asList( 83 "[ 0.000000] Start", 84 "[ 2.000000] End", 85 "Last boot reason: hw_reset"); 86 87 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 88 assertNotNull(kernelLog); 89 assertEquals(0.0, kernelLog.getStartTime(), 0.0000005); 90 assertEquals(2.0, kernelLog.getStopTime(), 0.0000005); 91 assertEquals(1, kernelLog.getEvents().size()); 92 assertEquals(1, kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).size()); 93 94 MiscKernelLogItem item = kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).get(0); 95 assertEquals(2.0, item.getEventTime(), 0.0000005); 96 assertEquals("[ 0.000000] Start\n[ 2.000000] End", item.getPreamble()); 97 assertEquals("Last boot reason: hw_reset", item.getStack()); 98 } 99 100 /** 101 * Test that unknown last boot reasons are parsed. 102 */ testParseUnknownLastMessage()103 public void testParseUnknownLastMessage() { 104 List<String> lines = Arrays.asList( 105 "[ 0.000000] Start", 106 "[ 2.000000] End", 107 "Last boot reason: unknown failure"); 108 109 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 110 assertNotNull(kernelLog); 111 assertEquals(0.0, kernelLog.getStartTime(), 0.0000005); 112 assertEquals(2.0, kernelLog.getStopTime(), 0.0000005); 113 assertEquals(1, kernelLog.getEvents().size()); 114 assertEquals(1, kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).size()); 115 116 MiscKernelLogItem item = kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).get(0); 117 assertEquals(2.0, item.getEventTime(), 0.0000005); 118 assertEquals("[ 0.000000] Start\n[ 2.000000] End", item.getPreamble()); 119 assertNotNull(item.getStack()); 120 } 121 testParseKnownGoodLastMessage()122 public void testParseKnownGoodLastMessage() { 123 List<String> lines = Arrays.asList( 124 "[ 0.000000] Start", 125 "[ 2.000000] End", 126 "Last boot reason: reboot"); 127 128 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 129 assertNotNull(kernelLog); 130 assertEquals(0.0, kernelLog.getStartTime(), 0.0000005); 131 assertEquals(2.0, kernelLog.getStopTime(), 0.0000005); 132 assertEquals(0, kernelLog.getEvents().size()); 133 } 134 135 /** 136 * Test that reset reasons don't crash if times are set. 137 */ testNoPreviousLogs()138 public void testNoPreviousLogs() { 139 List<String> lines = Arrays.asList( 140 "Last boot reason: hw_reset"); 141 142 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 143 assertNotNull(kernelLog); 144 assertNull(kernelLog.getStartTime()); 145 assertNull(kernelLog.getStopTime()); 146 assertEquals(1, kernelLog.getEvents().size()); 147 assertEquals(1, kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).size()); 148 149 MiscKernelLogItem item = kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).get(0); 150 assertNull(item.getEventTime()); 151 assertEquals("", item.getPreamble()); 152 assertEquals("Last boot reason: hw_reset", item.getStack()); 153 } 154 155 /** 156 * Test that an empty input returns {@code null}. 157 */ testEmptyInput()158 public void testEmptyInput() { 159 KernelLogItem item = new KernelLogParser().parse(Arrays.asList("")); 160 assertNull(item); 161 } 162 163 /** 164 * Test that kernel patterns are matched. 165 */ testPatterns()166 public void testPatterns() { 167 List<String> kernelResetPatterns = Arrays.asList( 168 "smem: DIAG", 169 "smsm: AMSS FATAL ERROR", 170 "kernel BUG at ", 171 "PVR_K:(Fatal): Debug assertion failed! []", 172 "Kernel panic", 173 "BP panicked", 174 "WROTE DSP RAMDUMP", 175 "tegra_wdt: last reset due to watchdog timeout", 176 "tegra_wdt tegra_wdt.0: last reset is due to watchdog timeout.", 177 "Last reset was MPU Watchdog Timer reset", 178 "[MODEM_IF] CRASH", 179 "Last boot reason: kernel_panic", 180 "Last boot reason: rpm_err", 181 "Last boot reason: hw_reset", 182 "Last boot reason: wdog_", 183 "Last boot reason: tz_err", 184 "Last boot reason: adsp_err", 185 "Last boot reason: modem_err", 186 "Last boot reason: mba_err", 187 "Last boot reason: watchdog", 188 "Last boot reason: watchdogr", 189 "Last boot reason: Watchdog", 190 "Last boot reason: Panic", 191 "Last reset was system watchdog timer reset"); 192 193 LogPatternUtil patternUtil = new KernelLogParser().getLogPatternUtil(); 194 195 for (String pattern : kernelResetPatterns) { 196 assertEquals(String.format("Message \"%s\" was not matched.", pattern), 197 KernelLogParser.KERNEL_RESET, patternUtil.checkMessage(pattern)); 198 } 199 200 assertEquals(KernelLogParser.KERNEL_ERROR, patternUtil.checkMessage("Internal error:")); 201 assertEquals(KernelLogParser.SELINUX_DENIAL, patternUtil.checkMessage( 202 "avc: denied scontext=0:0:domain:0 ")); 203 } 204 205 /** 206 * Test that an SELinux Denial can be parsed out of a list of log lines. 207 */ testSelinuxDenialParse()208 public void testSelinuxDenialParse() { 209 final String SELINUX_DENIAL_STACK = "type=1400 audit(1384544483.730:10): avc: denied " + 210 "{ getattr } for pid=797 comm=\"Binder_5\" path=\"/dev/pts/1\" + " + 211 "dev=devpts ino=4 scontext=u:r:system_server:s0 " + 212 "tcontext=u:object_r:devpts:s0 tclass=chr_file"; 213 List<String> lines = Arrays.asList( 214 "<4>[ 0.000000] Memory policy: ECC disabled, Data cache writealloc", 215 "<7>[ 7.896355] SELinux: initialized (dev cgroup, type cgroup)" + 216 ", uses genfs_contexts", 217 "<5>[ 43.399164] " + SELINUX_DENIAL_STACK); 218 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 219 220 assertNotNull(kernelLog); 221 assertEquals(0.0, kernelLog.getStartTime(), 0.0000005); 222 assertEquals(43.399164, kernelLog.getStopTime(), 0.0000005); 223 assertEquals(2, kernelLog.getEvents().size()); 224 assertEquals(1, kernelLog.getMiscEvents(KernelLogParser.SELINUX_DENIAL).size()); 225 assertEquals(1, kernelLog.getSELinuxEvents().size()); 226 227 MiscKernelLogItem item = kernelLog.getMiscEvents(KernelLogParser.SELINUX_DENIAL).get(0); 228 assertEquals(43.399164, item.getEventTime(), 0.0000005); 229 assertEquals(KernelLogParser.SELINUX_DENIAL, item.getCategory()); 230 assertEquals(SELINUX_DENIAL_STACK, item.getStack()); 231 232 SELinuxItem selinuxItem = kernelLog.getSELinuxEvents().get(0); 233 assertEquals("system_server", selinuxItem.getSContext()); 234 assertEquals(43.399164, selinuxItem.getEventTime(), 0.0000005); 235 assertEquals(KernelLogParser.SELINUX_DENIAL, selinuxItem.getCategory()); 236 assertEquals(SELINUX_DENIAL_STACK, selinuxItem.getStack()); 237 } 238 239 /** 240 * Test that an LowMemoryKiller event can be parsed out of a list of log lines. 241 */ testLowMemoryKillerParse()242 public void testLowMemoryKillerParse() { 243 final String LMK_MESSAGE = "Killing '.qcrilmsgtunnel' (3699), adj 100,"; 244 List<String> lines = Arrays.asList( 245 "<4>[ 0.000000] Memory policy: ECC disabled, Data cache writealloc", 246 "<7>[ 7.896355] SELinux: initialized (dev cgroup, type cgroup)" + 247 ", uses genfs_contexts", 248 "<3>[ 43.399164] " + LMK_MESSAGE); 249 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 250 251 assertNotNull(kernelLog); 252 assertEquals(0.0, kernelLog.getStartTime(), 0.0000005); 253 assertEquals(43.399164, kernelLog.getStopTime(), 0.0000005); 254 assertEquals(2, kernelLog.getEvents().size()); 255 assertEquals(1, kernelLog.getMiscEvents(KernelLogParser.LOW_MEMORY_KILLER).size()); 256 assertEquals(1, kernelLog.getLowMemoryKillerEvents().size()); 257 258 MiscKernelLogItem miscItem = kernelLog.getMiscEvents(KernelLogParser.LOW_MEMORY_KILLER) 259 .get(0); 260 assertEquals(43.399164, miscItem.getEventTime(), 0.0000005); 261 assertEquals(KernelLogParser.LOW_MEMORY_KILLER, miscItem.getCategory()); 262 assertEquals(LMK_MESSAGE, miscItem.getStack()); 263 264 LowMemoryKillerItem lmkItem = kernelLog.getLowMemoryKillerEvents().get(0); 265 assertEquals(KernelLogParser.LOW_MEMORY_KILLER, lmkItem.getCategory()); 266 assertEquals(3699, lmkItem.getPid()); 267 assertEquals(".qcrilmsgtunnel", lmkItem.getProcessName()); 268 assertEquals(100, lmkItem.getAdjustment()); 269 assertEquals(LMK_MESSAGE, lmkItem.getStack()); 270 } 271 272 /** 273 * Test that page allocation failures can be parsed out of a list of log lines. 274 */ testPageAllocationFailureParse()275 public void testPageAllocationFailureParse() { 276 final String ALLOC_FAILURE = "page allocation failure: order:3, mode:0x10c0d0"; 277 List<String> lines = Arrays.asList( 278 "<4>[ 0.000000] Memory policy: ECC disabled, Data cache writealloc", 279 "<7>[ 7.896355] SELinux: initialized (dev cgroup, type cgroup)" + 280 ", uses genfs_contexts", 281 "<3>[ 43.399164] " + ALLOC_FAILURE); 282 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 283 284 assertNotNull(kernelLog); 285 assertEquals(0.0, kernelLog.getStartTime(), 0.0000005); 286 assertEquals(43.399164, kernelLog.getStopTime(), 0.0000005); 287 assertEquals(2, kernelLog.getEvents().size()); 288 assertEquals(1, kernelLog.getMiscEvents(KernelLogParser.PAGE_ALLOC_FAILURE).size()); 289 assertEquals(1, kernelLog.getPageAllocationFailureEvents().size()); 290 291 MiscKernelLogItem miscItem = kernelLog.getMiscEvents(KernelLogParser.PAGE_ALLOC_FAILURE) 292 .get(0); 293 assertEquals(43.399164, miscItem.getEventTime(), 0.0000005); 294 assertEquals(KernelLogParser.PAGE_ALLOC_FAILURE, miscItem.getCategory()); 295 assertEquals(ALLOC_FAILURE, miscItem.getStack()); 296 297 PageAllocationFailureItem failItem = kernelLog.getPageAllocationFailureEvents().get(0); 298 assertEquals(KernelLogParser.PAGE_ALLOC_FAILURE, failItem.getCategory()); 299 assertEquals(3, failItem.getOrder()); 300 assertEquals(ALLOC_FAILURE, failItem.getStack()); 301 } 302 testMantaReset()303 public void testMantaReset() { 304 final List<String> lines = Arrays.asList("[ 3281.347296] ---fimc_is_ischain_close(0)", 305 "[ 3281.432055] fimc_is_scalerc_video_close", 306 "[ 3281.432270] fimc_is_scalerp_video_close", 307 "[ 3287.688303] wm8994-codec wm8994-codec: FIFO error", 308 "", 309 "No errors detected", 310 "Last reset was system watchdog timer reset (RST_STAT=0x100000)"); 311 312 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 313 assertEquals(1, kernelLog.getEvents().size()); 314 assertEquals(1, kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).size()); 315 } 316 317 /** 318 * Test that only the first kernel reset is taken but other signatures can have multiple 319 */ testMultipleKernelResets()320 public void testMultipleKernelResets() { 321 final String SELINUX_DENIAL_STACK = "type=1400 audit(1384544483.730:10): avc: denied " + 322 "{ getattr } for pid=797 comm=\"Binder_5\" path=\"/dev/pts/1\" + " + 323 "dev=devpts ino=4 scontext=u:r:system_server:s0 " + 324 "tcontext=u:object_r:devpts:s0 tclass=chr_file"; 325 final List<String> lines = Arrays.asList( 326 "[ 0.000000] Kernel panic", 327 "[ 0.000000] Internal error:", 328 "[ 0.000000] " + SELINUX_DENIAL_STACK, 329 "[ 1.000000] Kernel panic", 330 "[ 1.000000] Internal error:", 331 "[ 1.000000] " + SELINUX_DENIAL_STACK, 332 "[ 2.000000] Kernel panic", 333 "[ 2.000000] Internal error:", 334 "[ 2.000000] " + SELINUX_DENIAL_STACK); 335 336 KernelLogItem kernelLog = new KernelLogParser().parse(lines); 337 assertEquals(7, kernelLog.getEvents().size()); 338 assertEquals(1, kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).size()); 339 assertEquals(0.0, 340 kernelLog.getMiscEvents(KernelLogParser.KERNEL_RESET).get(0).getEventTime()); 341 } 342 } 343