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