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 com.android.loganalysis.item.DmesgModuleInfoItem;
24 
25 import com.google.common.annotations.VisibleForTesting;
26 
27 import java.io.BufferedReader;
28 import java.io.IOException;
29 import java.util.List;
30 import java.util.Map;
31 import java.util.regex.Matcher;
32 import java.util.regex.Pattern;
33 
34 
35 /**
36  * Parse the dmesg logs. </p>
37  */
38 public class DmesgParser implements IParser {
39 
40     private static final String SERVICENAME = "SERVICENAME";
41     private static final String TIMESTAMP = "TIMESTAMP";
42     private static final String STAGE = "STAGE";
43     private static final String ACTION = "ACTION";
44     private static final String SOURCE = "SOURCE";
45     private static final String DURATION = "DURATION";
46     private static final String UEVENTD = "ueventd";
47     private static final String INIT = "init";
48     private static final String WAIT_PROPERTY = "Wait for property ";
49     private static final String TOTAL_MODULE = "TOTAL_MODULE";
50     private static final String MOUNT_ALL = "mount_all";
51 
52     private static final String TIMESTAMP_PATTERN =
53             String.format("\\[\\s+(?<%s>[\\d.]+)]", TIMESTAMP);
54 
55     // This is optionally present in dmesg output on some kernels
56     // Matches possibly repeated pairs of square brackets enclosing arbitrary text
57     // An example is [   10.258464] [@3 insmod][....] aml dvb init
58     private static final String CPU_INFO_PATTERN = "(\\[[^]]+])+";
59 
60     // Matches: [ 14.822691] init:
61     private static final String SERVICE_PREFIX =
62             String.format("^%s( %s)? init:\\s+", TIMESTAMP_PATTERN, CPU_INFO_PATTERN);
63     // Matches: [    3.791635] ueventd:
64     private static final String UEVENTD_PREFIX =
65             String.format("^%s( %s)? ueventd:\\s+", TIMESTAMP_PATTERN, CPU_INFO_PATTERN);
66 
67     // Matches: starting service 'ueventd'...
68     private static final String START_SERVICE_SUFFIX = String.format("starting service "
69             + "\\'(?<%s>.*)\\'...", SERVICENAME);
70     // Matches: Service 'ueventd' (pid 439) exited with status 0
71     private static final String EXIT_SERVICE_SUFFIX = String.format("Service \\'(?<%s>.*)\\'\\s+"
72             + "\\((?<PID>.*)\\) exited with status 0.*", SERVICENAME);
73 
74     private static final Pattern START_SERVICE = Pattern.compile(
75             String.format("%s%s", SERVICE_PREFIX, START_SERVICE_SUFFIX));
76     private static final Pattern EXIT_SERVICE = Pattern.compile(
77             String.format("%s%s", SERVICE_PREFIX, EXIT_SERVICE_SUFFIX));
78 
79     // Matches: init first stage started!
80     // Matches: init second stage started!
81     private static final String START_STAGE_PREFIX = String.format("init (?<%s>.*) stage started!",
82             STAGE);
83 
84     // Matches: [   13.647997] init: init first stage started!
85     private static final Pattern START_STAGE = Pattern.compile(
86             String.format("%s%s", SERVICE_PREFIX, START_STAGE_PREFIX));
87 
88     // Matches: init: processing action (early-init) from (/init.rc:14)
89     private static final String START_PROCESSING_ACTION_PREFIX =
90             String.format("processing action \\((?<%s>[^)]*)\\)( from \\((?<%s>.*)\\)|.*)$",
91                     ACTION, SOURCE);
92 
93     // Matches: init: processing action (early-init) from (/init.rc:14)
94     private static final Pattern START_PROCESSING_ACTION =
95             Pattern.compile(String.format("%s%s", SERVICE_PREFIX, START_PROCESSING_ACTION_PREFIX));
96 
97     // Matches: [    1.175984] [    T1] init: Loaded 198 kernel modules took 808 ms
98     private static final Pattern MODULES_INFO =
99             Pattern.compile(
100                     String.format(
101                             "%sLoaded (?<count>\\d+) kernel modules took (?<%s>\\d+) ms.*$",
102                             SERVICE_PREFIX, DURATION));
103 
104     // Matches: [    0.503853] [    T1] init: Loading module /lib/modules/exynos_dit.ko with args ''
105     private static final Pattern MODULE_LOADING =
106             Pattern.compile(
107                     String.format(
108                             "%sLoading module \\S+\\/(?<koname>\\S+)\\.ko with args.*",
109                             SERVICE_PREFIX));
110 
111     // Matches: [    0.503803] [    T1] init: Loaded kernel module /lib/modules/boot_device_spi.ko
112     private static final Pattern MODULE_LOADED =
113             Pattern.compile(
114                     String.format(
115                             "%sLoaded kernel module \\S+\\/(?<koname>\\S+)\\.ko", SERVICE_PREFIX));
116 
117     // Matches: [    3.791635] ueventd: Coldboot took 0.695055 seconds
118     private static final String STAGE_SUFFIX =
119             String.format("(?<%s>.*)\\s+took\\s+(?<%s>.*)\\s+seconds$", STAGE, DURATION);
120     private static final Pattern UEVENTD_STAGE_INFO = Pattern.compile(
121             String.format("%s%s", UEVENTD_PREFIX, STAGE_SUFFIX));
122 
123     private static final String PROPERTY_SUFFIX =
124             String.format("Wait for property\\s(?<%s>.*)\\s+took\\s+(?<%s>.*)ms$", STAGE, DURATION);
125     // Matches [    7.270487] init: Wait for property 'apexd.status=ready' took 230ms
126     private static final Pattern WAIT_FOR_PROPERTY_INFO = Pattern.compile(
127             String.format("%s%s", SERVICE_PREFIX, PROPERTY_SUFFIX));
128 
129     // Matches: [    2.295667] init: Command 'mount_all --late' action=late-fs
130     // (/vendor/etc/init/init.rc:347) took 250ms and succeeded
131     private static final String MOUNT_SUFFIX =
132             String.format(
133                     "Command 'mount_all (?<%s>/\\S+|.*)?--(?<%s>.+)'.* took (?<%s>\\d+)ms.*",
134                     SOURCE, STAGE, DURATION);
135     private static final Pattern MOUNT_STAGE_INFO =
136             Pattern.compile(String.format("%s%s", SERVICE_PREFIX, MOUNT_SUFFIX));
137 
138     private DmesgItem mDmesgItem = new DmesgItem();
139 
140     /**
141      * {@inheritDoc}
142      */
143     @Override
parse(List<String> lines)144     public DmesgItem parse(List<String> lines) {
145         for (String line : lines) {
146             parse(line);
147         }
148 
149         return mDmesgItem;
150     }
151 
152     /**
153      * Parse the kernel log till EOF to retrieve the duration of the service calls, start times of
154      * different boot stages and actions taken. Besides, while parsing these informations are stored
155      * in the intermediate {@link DmesgServiceInfoItem}, {@link DmesgStageInfoItem} and {@link
156      * DmesgActionInfoItem} objects
157      *
158      * @param bufferedLog dmesg log
159      * @throws IOException
160      */
parseInfo(BufferedReader bufferedLog)161     public DmesgItem parseInfo(BufferedReader bufferedLog) throws IOException {
162         String line;
163         while ((line = bufferedLog.readLine()) != null) {
164             parse(line);
165         }
166 
167         return mDmesgItem;
168     }
169 
170     /**
171      * <p>
172      * Parse single line of the dmesg log to retrieve the duration of the service calls or start
173      * times of different boot stages or start times of actions taken based on the info contained in
174      * the line.
175      * </p>
176      * <p>
177      * Besides, while parsing these informations are stored in the intermediate
178      * {@link DmesgServiceInfoItem}, {@link DmesgStageInfoItem} and {@link DmesgActionInfoItem}
179      * objects
180      * </p>
181      *
182      * @param line individual line of the dmesg log
183      */
parse(String line)184     private void parse(String line) {
185 
186         if (parseServiceInfo(line)) {
187             return;
188         }
189         if (parseStageInfo(line)) {
190             return;
191         }
192         if (parseActionInfo(line)) {
193             return;
194         }
195         if (parseModuleInfo(line)) {
196             return;
197         }
198     }
199 
200     /**
201      * Parse init services {@code start time} and {@code end time} from each {@code line} of dmesg
202      * log and store the {@code duration} it took to complete the service if the end time stamp is
203      * available in {@link DmesgServiceInfoItem}.
204      *
205      * @param line individual line of the dmesg log
206      * @return {@code true}, if the {@code line} indicates start or end of a service, {@code false},
207      *     otherwise
208      */
209     @VisibleForTesting
parseServiceInfo(String line)210     boolean parseServiceInfo(String line) {
211         Matcher match = null;
212         if ((match = matches(START_SERVICE, line)) != null) {
213             DmesgServiceInfoItem serviceItem = new DmesgServiceInfoItem();
214             serviceItem.setServiceName(match.group(SERVICENAME));
215             serviceItem.setStartTime((long) (Double.parseDouble(
216                     match.group(TIMESTAMP)) * 1000));
217             getServiceInfoItems().put(match.group(SERVICENAME), serviceItem);
218             return true;
219         } else if ((match = matches(EXIT_SERVICE, line)) != null) {
220             if (getServiceInfoItems().containsKey(match.group(SERVICENAME))) {
221                 DmesgServiceInfoItem serviceItem = getServiceInfoItems().get(
222                         match.group(SERVICENAME));
223                 serviceItem.setEndTime((long) (Double.parseDouble(
224                         match.group(TIMESTAMP)) * 1000));
225             }
226             return true;
227         }
228         return false;
229     }
230 
231     /**
232      * Parse init stages log from each {@code line} of dmesg log and store the stage name, start
233      * time and duration if available in a {@link DmesgStageInfoItem} object
234      *
235      * @param line individual line of the dmesg log
236      * @return {@code true}, if the {@code line} indicates start of a boot stage, {@code false},
237      *     otherwise
238      */
239     @VisibleForTesting
parseStageInfo(String line)240     boolean parseStageInfo(String line) {
241         Matcher match = null;
242         if ((match = matches(START_STAGE, line)) != null) {
243             DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
244             stageInfoItem.setStageName(match.group(STAGE));
245             stageInfoItem.setStartTime((long) (Double.parseDouble(
246                     match.group(TIMESTAMP)) * 1000));
247             mDmesgItem.addStageInfoItem(stageInfoItem);
248             return true;
249         }
250         if((match = matches(UEVENTD_STAGE_INFO, line)) != null) {
251             DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
252             stageInfoItem.setStageName(String.format("%s_%s", UEVENTD, match.group(STAGE)));
253             stageInfoItem.setDuration((long) (Double.parseDouble(
254                     match.group(DURATION)) * 1000));
255             mDmesgItem.addStageInfoItem(stageInfoItem);
256             return true;
257         }
258         if((match = matches(WAIT_FOR_PROPERTY_INFO, line)) != null) {
259             DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
260             stageInfoItem.setStageName(
261                     String.format("%s_%s%s", INIT, WAIT_PROPERTY, match.group(STAGE)));
262             stageInfoItem.setDuration((long) Double.parseDouble(match.group(DURATION)));
263             mDmesgItem.addStageInfoItem(stageInfoItem);
264             return true;
265         }
266         if ((match = matches(MOUNT_STAGE_INFO, line)) != null) {
267             DmesgStageInfoItem stageInfoItem = new DmesgStageInfoItem();
268             if (match.group(SOURCE).isEmpty()) {
269                 stageInfoItem.setStageName(
270                         String.format("%s_%s_%s", INIT, MOUNT_ALL, match.group(STAGE)));
271             } else {
272                 stageInfoItem.setStageName(
273                         String.format(
274                                 "%s_%s_%s_%s",
275                                 INIT, MOUNT_ALL, match.group(STAGE), match.group(SOURCE).trim()));
276             }
277             stageInfoItem.setDuration((long) Double.parseDouble(match.group(DURATION)));
278             mDmesgItem.addStageInfoItem(stageInfoItem);
279             return true;
280         }
281         return false;
282     }
283 
284     /**
285      * Parse action from each {@code line} of dmesg log and store the action name and start time in
286      * {@link DmesgActionInfoItem} object
287      *
288      * @param line individual {@code line} of the dmesg log
289      * @return {@code true}, if {@code line} indicates starting of processing of action {@code
290      *     false}, otherwise
291      */
292     @VisibleForTesting
parseActionInfo(String line)293     boolean parseActionInfo(String line) {
294         Matcher match = null;
295         if ((match = matches(START_PROCESSING_ACTION, line)) != null) {
296             DmesgActionInfoItem actionInfoItem = new DmesgActionInfoItem();
297             if (match.group(SOURCE) != null) {
298                 actionInfoItem.setSourceName(match.group(SOURCE));
299             }
300             actionInfoItem.setActionName(match.group(ACTION));
301             actionInfoItem.setStartTime((long) (Double.parseDouble(
302                     match.group(TIMESTAMP)) * 1000));
303             mDmesgItem.addActionInfoItem(actionInfoItem);
304             return true;
305         }
306         return false;
307     }
308 
309     /**
310      * Parse modules from each {@code line} of dmesg log and store the module name and loading time
311      * in {@link DmesgModuleInfoItem} object
312      *
313      * @param line individual {@code line} of the dmesg log
314      * @return {@code true}, if {@code line} indicates start, end of a module loading or the summary
315      *     {@code false}, otherwise
316      */
317     @VisibleForTesting
parseModuleInfo(String line)318     boolean parseModuleInfo(String line) {
319         Matcher match = null;
320         if ((match = matches(MODULES_INFO, line)) != null) {
321             DmesgModuleInfoItem moduleInfoItem = new DmesgModuleInfoItem();
322             moduleInfoItem.setModuleName(TOTAL_MODULE);
323             moduleInfoItem.setModuleDuration((long) Double.parseDouble(match.group(DURATION)));
324             moduleInfoItem.setModuleCount(match.group("count"));
325             mDmesgItem.addModuleInfoItem(TOTAL_MODULE, moduleInfoItem);
326             return true;
327         }
328 
329         if ((match = matches(MODULE_LOADING, line)) != null) {
330             DmesgModuleInfoItem moduleInfoItem = new DmesgModuleInfoItem();
331             moduleInfoItem.setModuleName(match.group("koname"));
332             moduleInfoItem.setStartTime((long) (Double.parseDouble(match.group(TIMESTAMP)) * 1000));
333             mDmesgItem.addModuleInfoItem(match.group("koname"), moduleInfoItem);
334             return true;
335         } else if ((match = matches(MODULE_LOADED, line)) != null) {
336             if (getModuleInfoItems().containsKey(match.group("koname"))) {
337                 DmesgModuleInfoItem moduleInfoItem =
338                         getModuleInfoItems().get(match.group("koname"));
339                 moduleInfoItem.setEndTime(
340                         (long) (Double.parseDouble(match.group(TIMESTAMP)) * 1000));
341             }
342             return true;
343         }
344         return false;
345     }
346 
347     /**
348      * Checks whether {@code line} matches the given {@link Pattern}.
349      *
350      * @return The resulting {@link Matcher} obtained by matching the {@code line} against
351      *         {@code pattern}, or null if the {@code line} does not match.
352      */
matches(Pattern pattern, String line)353     private static Matcher matches(Pattern pattern, String line) {
354         Matcher ret = pattern.matcher(line);
355         return ret.matches() ? ret : null;
356     }
357 
getServiceInfoItems()358     public Map<String, DmesgServiceInfoItem> getServiceInfoItems() {
359         return mDmesgItem.getServiceInfoItems();
360     }
361 
setServiceInfoItems(Map<String, DmesgServiceInfoItem> serviceInfoItems)362     public void setServiceInfoItems(Map<String, DmesgServiceInfoItem> serviceInfoItems) {
363         for(String key : serviceInfoItems.keySet()) {
364             mDmesgItem.addServiceInfoItem(key, serviceInfoItems.get(key));
365         }
366     }
367 
getStageInfoItems()368     public List<DmesgStageInfoItem> getStageInfoItems() {
369         return mDmesgItem.getStageInfoItems();
370     }
371 
getActionInfoItems()372     public List<DmesgActionInfoItem> getActionInfoItems() {
373         return mDmesgItem.getActionInfoItems();
374     }
375 
getModuleInfoItems()376     public Map<String, DmesgModuleInfoItem> getModuleInfoItems() {
377         return mDmesgItem.getModuleInfoItems();
378     }
379 }