1 /* 2 * Copyright (C) 2016 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 17 package com.android.loganalysis.parser; 18 19 import com.android.loganalysis.item.DmesgActionInfoItem; 20 import com.android.loganalysis.item.DmesgItem; 21 import com.android.loganalysis.item.DmesgServiceInfoItem; 22 import com.android.loganalysis.item.DmesgStageInfoItem; 23 import java.io.BufferedReader; 24 import java.io.ByteArrayInputStream; 25 import java.io.IOException; 26 import java.io.InputStreamReader; 27 import java.util.ArrayList; 28 import java.util.Arrays; 29 import java.util.HashMap; 30 import java.util.List; 31 import java.util.Map; 32 import junit.framework.TestCase; 33 34 /** 35 * Unit tests for {@link DmesgParser}. 36 */ 37 public class DmesgParserTest extends TestCase { 38 39 private static final String BOOT_ANIMATION = "bootanim"; 40 private static final String NETD = "netd"; 41 private static final String[] LINES = 42 new String[] { 43 "[ 2.471163] init: Wait for property 'apexd.status=ready' took 403ms", 44 "[ 3.786943] ueventd: Coldboot took 0.701291 seconds", 45 "[ 22.962730] init: starting service 'bootanim'...", 46 "[ 23.252321] init: starting service 'netd'...", 47 "[ 29.331069] ipa-wan ipa_wwan_ioctl:1428 dev(rmnet_data0) register to IPA", 48 "[ 32.182592] ueventd: fixup /sys/devices/virtual/input/poll_delay 0 1004 660", 49 "[ 35.642666] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts", 50 "[ 39.855818] init: Service 'bootanim' (pid 588) exited with status 0", 51 "[ 41.665818] init: init first stage started!", 52 "[ 44.942872] init: processing action (early-init) from (/init.rc:13)", 53 "[ 47.233446] init: processing action (set_mmap_rnd_bits) from (<Builtin Action>:0)", 54 "[ 47.240083] init: processing action (set_kptr_restrict) from (<Builtin Action>:0)", 55 "[ 47.245778] init: processing action (keychord_init) from (<Builtin Action>:0)", 56 "[ 52.361049] init: processing action (persist.sys.usb.config=* boot) from (<Builtin Action>:0)", 57 "[ 52.361108] init: processing action (enable_property_trigger) from (<Builtin Action>:0)", 58 "[ 52.361313] init: processing action (security.perf_harden=1) from (/init.rc:677)", 59 "[ 52.361495] init: processing action (ro.debuggable=1) from (/init.rc:700)", 60 "[ 58.298293] init: processing action (sys.boot_completed=1)", 61 "[ 59.331069] ipa-wan ipa_wwan_ioctl:1428 dev(rmnet_data0) register to IPA", 62 "[ 62.182592] ueventd: fixup /sys/devices/virtual/input/poll_delay 0 1004 660", 63 "[ 65.642666] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts", 64 "[ 69.855818] init: Service 'bootanim' (pid 588) exited with status 0" 65 }; 66 67 private static final Map<String, DmesgServiceInfoItem> EXPECTED_SERVICE_INFO_ITEMS = 68 getExpectedServiceInfoItems(); 69 70 private static final List<DmesgStageInfoItem> EXPECTED_STAGE_INFO_ITEMS = 71 getExpectedStageInfoItems(); 72 73 private static final List<DmesgActionInfoItem> EXPECTED_ACTION_INFO_ITEMS = 74 getExpectedActionInfoItems(); 75 76 /** 77 * Test for empty dmesg logs passed to the DmesgParser 78 */ testEmptyDmesgLog()79 public void testEmptyDmesgLog() throws IOException { 80 String[] lines = new String[] {""}; 81 try (BufferedReader bufferedReader = new BufferedReader(new InputStreamReader( 82 new ByteArrayInputStream(String.join("\n", lines).getBytes())))) { 83 DmesgParser dmesgParser = new DmesgParser(); 84 dmesgParser.parseInfo(bufferedReader); 85 assertEquals("Service info items list should be empty", 0, 86 dmesgParser.getServiceInfoItems().size()); 87 } 88 } 89 90 /** 91 * Test for complete dmesg logs passed as list of strings 92 */ testCompleteDmesgLog_passedAsList()93 public void testCompleteDmesgLog_passedAsList() { 94 95 DmesgParser dmesgParser = new DmesgParser(); 96 DmesgItem actualDmesgItem = dmesgParser.parse(Arrays.asList(LINES)); 97 98 assertEquals("Service info items list size should be 2", 2, 99 dmesgParser.getServiceInfoItems().size()); 100 assertEquals("Stage info items list size should be 3",3, 101 dmesgParser.getStageInfoItems().size()); 102 assertEquals("Action info items list size should be 9",9, 103 dmesgParser.getActionInfoItems().size()); 104 105 assertEquals(EXPECTED_SERVICE_INFO_ITEMS, actualDmesgItem.getServiceInfoItems()); 106 assertEquals(EXPECTED_STAGE_INFO_ITEMS, actualDmesgItem.getStageInfoItems()); 107 assertEquals(EXPECTED_ACTION_INFO_ITEMS, actualDmesgItem.getActionInfoItems()); 108 } 109 110 /** 111 * Test for complete dmesg logs passed as buffered input 112 */ testCompleteDmesgLog_passedAsBufferedInput()113 public void testCompleteDmesgLog_passedAsBufferedInput() throws IOException { 114 try (BufferedReader bufferedReader = new BufferedReader(new InputStreamReader( 115 new ByteArrayInputStream(String.join("\n", LINES).getBytes())))) { 116 DmesgParser dmesgParser = new DmesgParser(); 117 dmesgParser.parseInfo(bufferedReader); 118 assertEquals("Service info items list size should be 2", 2, 119 dmesgParser.getServiceInfoItems().size()); 120 assertEquals("Stage info items list size should be 3", 3, 121 dmesgParser.getStageInfoItems().size()); 122 assertEquals("Action info items list size should be 9",9, 123 dmesgParser.getActionInfoItems().size()); 124 } 125 } 126 127 /** 128 * Test service which logs both the start and end time 129 */ testCompleteServiceInfo()130 public void testCompleteServiceInfo() { 131 DmesgParser dmesgParser = new DmesgParser(); 132 for (String line : LINES) { 133 dmesgParser.parseServiceInfo(line); 134 } 135 136 assertEquals("There should be two service infos", 2, 137 dmesgParser.getServiceInfoItems().size()); 138 assertEquals(EXPECTED_SERVICE_INFO_ITEMS, dmesgParser.getServiceInfoItems()); 139 } 140 141 /** 142 * Test service which logs only the start time 143 */ testStartServiceInfo()144 public void testStartServiceInfo() { 145 DmesgParser dmesgParser = new DmesgParser(); 146 for (String line : LINES) { 147 dmesgParser.parseServiceInfo(line); 148 } 149 List<DmesgServiceInfoItem> serviceInfoItems = new ArrayList<>( 150 dmesgParser.getServiceInfoItems().values()); 151 assertEquals("There should be exactly two service infos", 2, serviceInfoItems.size()); 152 assertEquals("Service name is not bootanim", BOOT_ANIMATION, 153 serviceInfoItems.get(0).getServiceName()); 154 assertEquals("Service name is not netd", NETD, serviceInfoItems.get(1).getServiceName()); 155 } 156 157 /** 158 * Test multiple service info parsed correctly and stored in the same order logged in 159 * the file. 160 */ testMultipleServiceInfo()161 public void testMultipleServiceInfo() { 162 DmesgParser dmesgParser = new DmesgParser(); 163 for (String line : LINES) { 164 dmesgParser.parseServiceInfo(line); 165 } 166 assertEquals("There should be exactly two service info", 2, 167 dmesgParser.getServiceInfoItems().size()); 168 assertEquals(EXPECTED_SERVICE_INFO_ITEMS, dmesgParser.getServiceInfoItems()); 169 } 170 171 /** 172 * Test invalid patterns on the start and exit service logs 173 */ testInvalidServiceLogs()174 public void testInvalidServiceLogs() { 175 // Added space at the end of the start and exit of service logs to make it invalid 176 String[] lines = new String[] { 177 "[ 22.962730] init: starting service 'bootanim'... ", 178 "[ 23.252321] init: starting service 'netd'... ", 179 "[ 29.331069] ipa-wan ipa_wwan_ioctl:1428 dev(rmnet_data0) register to IPA", 180 "[ 32.182592] ueventd: fixup /sys/devices/virtual/input/poll_delay 0 1004 660", 181 "[ 35.642666] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts", 182 "[ 39.855818] init: Service 'bootanim' (pid 588) exited with status 0 "}; 183 DmesgParser dmesgParser = new DmesgParser(); 184 for (String line : lines) { 185 dmesgParser.parseServiceInfo(line); 186 } 187 List<DmesgServiceInfoItem> serviceInfoItems = new ArrayList<>( 188 dmesgParser.getServiceInfoItems().values()); 189 assertEquals("No service info should be available", 0, serviceInfoItems.size()); 190 } 191 192 /** 193 * Test init stages' start time logs 194 */ testCompleteStageInfo()195 public void testCompleteStageInfo() { 196 DmesgParser dmesgParser = new DmesgParser(); 197 for (String line : LINES) { 198 dmesgParser.parseStageInfo(line); 199 } 200 List<DmesgStageInfoItem> stageInfoItems = dmesgParser.getStageInfoItems(); 201 assertEquals(3, stageInfoItems.size()); 202 assertEquals(EXPECTED_STAGE_INFO_ITEMS, stageInfoItems); 203 } 204 205 /** Test processing action start time logs */ testCompleteActionInfo()206 public void testCompleteActionInfo() { 207 DmesgParser dmesgParser = new DmesgParser(); 208 for (String line : LINES) { 209 dmesgParser.parseActionInfo(line); 210 } 211 List<DmesgActionInfoItem> actualActionInfoItems = dmesgParser.getActionInfoItems(); 212 assertEquals(9, actualActionInfoItems.size()); 213 assertEquals(EXPECTED_ACTION_INFO_ITEMS, actualActionInfoItems); 214 } 215 getExpectedActionInfoItems()216 private static List<DmesgActionInfoItem> getExpectedActionInfoItems() { 217 return Arrays.asList( 218 new DmesgActionInfoItem("early-init", (long) (Double.parseDouble("44942.872"))), 219 new DmesgActionInfoItem( 220 "set_mmap_rnd_bits", (long) (Double.parseDouble("47233.446"))), 221 new DmesgActionInfoItem( 222 "set_kptr_restrict", (long) (Double.parseDouble("47240.083"))), 223 new DmesgActionInfoItem("keychord_init", (long) (Double.parseDouble("47245.778"))), 224 new DmesgActionInfoItem( 225 "persist.sys.usb.config=* boot", (long) (Double.parseDouble("52361.049"))), 226 new DmesgActionInfoItem( 227 "enable_property_trigger", (long) (Double.parseDouble("52361.108"))), 228 new DmesgActionInfoItem( 229 "security.perf_harden=1", (long) (Double.parseDouble("52361.313"))), 230 new DmesgActionInfoItem( 231 "ro.debuggable=1", (long) (Double.parseDouble("52361.495"))), 232 new DmesgActionInfoItem( 233 "sys.boot_completed=1", (long) (Double.parseDouble("58298.293")))); 234 } 235 getExpectedStageInfoItems()236 private static List<DmesgStageInfoItem> getExpectedStageInfoItems() { 237 return Arrays.asList( 238 new DmesgStageInfoItem("init_Wait for property 'apexd.status=ready'", null, 403L), 239 new DmesgStageInfoItem("ueventd_Coldboot", null, 701L), 240 new DmesgStageInfoItem("first", 41665L, null)); 241 } 242 getExpectedServiceInfoItems()243 private static Map<String, DmesgServiceInfoItem> getExpectedServiceInfoItems() { 244 Map<String, DmesgServiceInfoItem> serviceInfoItemsMap = new HashMap<>(); 245 DmesgServiceInfoItem bootanimServiceInfoItem = new DmesgServiceInfoItem(); 246 bootanimServiceInfoItem.setServiceName(BOOT_ANIMATION); 247 bootanimServiceInfoItem.setStartTime(22962L); 248 bootanimServiceInfoItem.setEndTime(69855L); 249 250 DmesgServiceInfoItem netdServiceInfoItem = new DmesgServiceInfoItem(); 251 netdServiceInfoItem.setServiceName(NETD); 252 netdServiceInfoItem.setStartTime(23252L); 253 254 serviceInfoItemsMap.put(BOOT_ANIMATION, bootanimServiceInfoItem); 255 serviceInfoItemsMap.put(NETD, netdServiceInfoItem); 256 257 return serviceInfoItemsMap; 258 } 259 260 } 261