/* * Copyright (C) 2016 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ package com.android.loganalysis.parser; 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.android.loganalysis.item.DmesgModuleInfoItem; import java.io.BufferedReader; import java.io.ByteArrayInputStream; import java.io.IOException; import java.io.InputStreamReader; import java.util.ArrayList; import java.util.Arrays; import java.util.HashMap; import java.util.List; import java.util.Map; import junit.framework.TestCase; /** * Unit tests for {@link DmesgParser}. */ public class DmesgParserTest extends TestCase { private static final String BOOT_ANIMATION = "bootanim"; private static final String NETD = "netd"; private static final String FOO = "foo"; private static final String BAR = "bar"; private static final String TOTAL_MODULE = "TOTAL_MODULE"; private static final String[] LINES = new String[] { "[ 0.370107] init: Loading module /lib/modules/foo.ko with args ''", "[ 0.372497] init: Loaded kernel module /lib/modules/foo.ko", "[ 0.372500] init: Loading module /lib/modules/bar.ko with args ''", "[ 1.115467] init: Loaded 198 kernel modules took 748 ms", "[ 2.471163] init: Wait for property 'apexd.status=ready' took 403ms", "[ 3.786943] ueventd: Coldboot took 0.701291 seconds", "[ 4.295667] init: Command 'mount_all --late' action=late-fs " + "/vendor/etc/init/hw/init.rc:347) took 250ms and succeeded", "[ 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 (:0)", "[ 47.240083] init: processing action (set_kptr_restrict) from (:0)", "[ 47.245778] init: processing action (keychord_init) from (:0)", "[ 52.361049] init: processing action (persist.sys.usb.config=* boot) from" + " (:0)", "[ 52.361108] init: processing action (enable_property_trigger) from (: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 EXPECTED_SERVICE_INFO_ITEMS = getExpectedServiceInfoItems(); private static final List EXPECTED_STAGE_INFO_ITEMS = getExpectedStageInfoItems(); private static final List EXPECTED_ACTION_INFO_ITEMS = getExpectedActionInfoItems(); private static final Map EXPECTED_MODULE_INFO_ITEMS = getExpectedModuleInfoItems(); /** * Test for empty dmesg logs passed to the DmesgParser */ public void testEmptyDmesgLog() throws IOException { String[] lines = new String[] {""}; try (BufferedReader bufferedReader = new BufferedReader(new InputStreamReader( new ByteArrayInputStream(String.join("\n", lines).getBytes())))) { DmesgParser dmesgParser = new DmesgParser(); dmesgParser.parseInfo(bufferedReader); assertEquals("Service info items list should be empty", 0, dmesgParser.getServiceInfoItems().size()); } } /** * Test for complete dmesg logs passed as list of strings */ public void testCompleteDmesgLog_passedAsList() { DmesgParser dmesgParser = new DmesgParser(); DmesgItem actualDmesgItem = dmesgParser.parse(Arrays.asList(LINES)); assertEquals("Service info items list size should be 2", 2, dmesgParser.getServiceInfoItems().size()); assertEquals( "Stage info items list size should be 4", 4, dmesgParser.getStageInfoItems().size()); assertEquals("Action info items list size should be 9",9, dmesgParser.getActionInfoItems().size()); assertEquals( "Module info items list size should be 3", 3, dmesgParser.getModuleInfoItems().size()); assertEquals(EXPECTED_SERVICE_INFO_ITEMS, actualDmesgItem.getServiceInfoItems()); assertEquals(EXPECTED_STAGE_INFO_ITEMS, actualDmesgItem.getStageInfoItems()); assertEquals(EXPECTED_ACTION_INFO_ITEMS, actualDmesgItem.getActionInfoItems()); assertEquals(EXPECTED_MODULE_INFO_ITEMS, actualDmesgItem.getModuleInfoItems()); } /** * Test for complete dmesg logs passed as buffered input */ public void testCompleteDmesgLog_passedAsBufferedInput() throws IOException { try (BufferedReader bufferedReader = new BufferedReader(new InputStreamReader( new ByteArrayInputStream(String.join("\n", LINES).getBytes())))) { DmesgParser dmesgParser = new DmesgParser(); dmesgParser.parseInfo(bufferedReader); assertEquals("Service info items list size should be 2", 2, dmesgParser.getServiceInfoItems().size()); assertEquals( "Stage info items list size should be 4", 4, dmesgParser.getStageInfoItems().size()); assertEquals("Action info items list size should be 9",9, dmesgParser.getActionInfoItems().size()); assertEquals( "Module info items list size should be 3", 3, dmesgParser.getModuleInfoItems().size()); } } /** * Test service which logs both the start and end time */ public void testCompleteServiceInfo() { DmesgParser dmesgParser = new DmesgParser(); for (String line : LINES) { dmesgParser.parseServiceInfo(line); } assertEquals("There should be two service infos", 2, dmesgParser.getServiceInfoItems().size()); assertEquals(EXPECTED_SERVICE_INFO_ITEMS, dmesgParser.getServiceInfoItems()); } /** * Test service which logs only the start time */ public void testStartServiceInfo() { DmesgParser dmesgParser = new DmesgParser(); for (String line : LINES) { dmesgParser.parseServiceInfo(line); } List serviceInfoItems = new ArrayList<>( dmesgParser.getServiceInfoItems().values()); assertEquals("There should be exactly two service infos", 2, serviceInfoItems.size()); assertEquals("Service name is not bootanim", BOOT_ANIMATION, serviceInfoItems.get(0).getServiceName()); assertEquals("Service name is not netd", NETD, serviceInfoItems.get(1).getServiceName()); } /** * Test multiple service info parsed correctly and stored in the same order logged in * the file. */ public void testMultipleServiceInfo() { DmesgParser dmesgParser = new DmesgParser(); for (String line : LINES) { dmesgParser.parseServiceInfo(line); } assertEquals("There should be exactly two service info", 2, dmesgParser.getServiceInfoItems().size()); assertEquals(EXPECTED_SERVICE_INFO_ITEMS, dmesgParser.getServiceInfoItems()); } /** * Test invalid patterns on the start and exit service logs */ public void testInvalidServiceLogs() { // Added space at the end of the start and exit of service logs to make it invalid String[] lines = new String[] { "[ 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 "}; DmesgParser dmesgParser = new DmesgParser(); for (String line : lines) { dmesgParser.parseServiceInfo(line); } List serviceInfoItems = new ArrayList<>( dmesgParser.getServiceInfoItems().values()); assertEquals("No service info should be available", 0, serviceInfoItems.size()); } public void testCompleteStageInfo_onKernel_5_15() { DmesgParser dmesgParser = new DmesgParser(); String[] lines = new String[] { "[ 0.370107] [@2 init][....] init: Loading module /lib/modules/foo.ko " + "with args ''", "[ 0.372497] [@2 init][....] init: Loaded kernel module /lib/modules/foo.ko", "[ 0.372500] [@2 init][....] init: Loading module /lib/modules/bar.ko " + "with args ''", "[ 1.115467] [@2 init][....] init: Loaded 198 kernel modules took 748 ms", "[ 2.471163] [@2 init][....] init: Wait for property 'apexd.status=ready' " + "took 403ms", "[ 3.786943] [@2 init][....] ueventd: Coldboot took 0.701291 seconds", "[ 4.295667] [@2 init][....] init: Command 'mount_all --late' action=late-fs" + " /vendor/etc/init/hw/init.rc:347) took 250ms and succeeded", "[ 41.665818] [@2 init][....] init: init first stage started!" }; for (String line : lines) { dmesgParser.parseStageInfo(line); } List stageInfoItems = dmesgParser.getStageInfoItems(); assertEquals(4, stageInfoItems.size()); assertEquals(EXPECTED_STAGE_INFO_ITEMS, stageInfoItems); } /** * Test init stages' start time logs */ public void testCompleteStageInfo() { DmesgParser dmesgParser = new DmesgParser(); for (String line : LINES) { dmesgParser.parseStageInfo(line); } List stageInfoItems = dmesgParser.getStageInfoItems(); assertEquals(4, stageInfoItems.size()); assertEquals(EXPECTED_STAGE_INFO_ITEMS, stageInfoItems); } /** Test processing action start time logs */ public void testCompleteActionInfo() { DmesgParser dmesgParser = new DmesgParser(); for (String line : LINES) { dmesgParser.parseActionInfo(line); } List actualActionInfoItems = dmesgParser.getActionInfoItems(); assertEquals(9, actualActionInfoItems.size()); assertEquals(EXPECTED_ACTION_INFO_ITEMS, actualActionInfoItems); } /** Test incomplete module loaded pattern */ public void testIncompleteModuleInfo() { DmesgParser dmesgParser = new DmesgParser(); for (String line : LINES) { dmesgParser.parseModuleInfo(line); } List actualModuleInfoItems = new ArrayList<>(dmesgParser.getModuleInfoItems().values()); assertEquals(EXPECTED_MODULE_INFO_ITEMS, dmesgParser.getModuleInfoItems()); assertEquals(3, actualModuleInfoItems.size()); assertEquals( "Duration should be -1L", Long.valueOf(-1L), actualModuleInfoItems.get(0).getModuleDuration()); } private static List getExpectedActionInfoItems() { return Arrays.asList( new DmesgActionInfoItem("/init.rc:13", "early-init", 44942L), new DmesgActionInfoItem(":0", "set_mmap_rnd_bits", 47233L), new DmesgActionInfoItem(":0", "set_kptr_restrict", 47240L), new DmesgActionInfoItem(":0", "keychord_init", 47245L), new DmesgActionInfoItem( ":0", "persist.sys.usb.config=* boot", 52361L), new DmesgActionInfoItem(":0", "enable_property_trigger", 52361L), new DmesgActionInfoItem("/init.rc:677", "security.perf_harden=1", 52361L), new DmesgActionInfoItem("/init.rc:700", "ro.debuggable=1", 52361L), new DmesgActionInfoItem(null, "sys.boot_completed=1", 58298L)); } private static List getExpectedStageInfoItems() { return Arrays.asList( new DmesgStageInfoItem("init_Wait for property 'apexd.status=ready'", null, 403L), new DmesgStageInfoItem("ueventd_Coldboot", null, 701L), new DmesgStageInfoItem("init_mount_all_late", null, 250L), new DmesgStageInfoItem("first", 41665L, null)); } private static Map getExpectedServiceInfoItems() { Map serviceInfoItemsMap = new HashMap<>(); DmesgServiceInfoItem bootanimServiceInfoItem = new DmesgServiceInfoItem(); bootanimServiceInfoItem.setServiceName(BOOT_ANIMATION); bootanimServiceInfoItem.setStartTime(22962L); bootanimServiceInfoItem.setEndTime(69855L); DmesgServiceInfoItem netdServiceInfoItem = new DmesgServiceInfoItem(); netdServiceInfoItem.setServiceName(NETD); netdServiceInfoItem.setStartTime(23252L); serviceInfoItemsMap.put(BOOT_ANIMATION, bootanimServiceInfoItem); serviceInfoItemsMap.put(NETD, netdServiceInfoItem); return serviceInfoItemsMap; } private static Map getExpectedModuleInfoItems() { Map moduleInfoItemsMap = new HashMap<>(); DmesgModuleInfoItem fooModuleInfo = new DmesgModuleInfoItem(); fooModuleInfo.setModuleName(FOO); fooModuleInfo.setStartTime(370L); fooModuleInfo.setEndTime(372L); DmesgModuleInfoItem barModuleInfo = new DmesgModuleInfoItem(); barModuleInfo.setModuleName(BAR); barModuleInfo.setStartTime(372L); DmesgModuleInfoItem totalInfoItem = new DmesgModuleInfoItem(); totalInfoItem.setModuleName(TOTAL_MODULE); totalInfoItem.setModuleCount("198"); totalInfoItem.setModuleDuration(748L); moduleInfoItemsMap.put(FOO, fooModuleInfo); moduleInfoItemsMap.put(BAR, barModuleInfo); moduleInfoItemsMap.put(TOTAL_MODULE, totalInfoItem); return moduleInfoItemsMap; } }