1 /*
2  * Copyright (C) 2011 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.LogcatItem;
19 import com.android.loganalysis.item.MiscLogcatItem;
20 import com.android.loganalysis.util.ArrayUtil;
21 import com.android.loganalysis.util.LogPatternUtil;
22 import com.android.loganalysis.util.LogTailUtil;
23 
24 import java.io.BufferedReader;
25 import java.io.IOException;
26 import java.text.DateFormat;
27 import java.text.ParseException;
28 import java.text.SimpleDateFormat;
29 import java.util.ArrayList;
30 import java.util.Date;
31 import java.util.HashMap;
32 import java.util.LinkedList;
33 import java.util.List;
34 import java.util.Map;
35 import java.util.regex.Matcher;
36 import java.util.regex.Pattern;
37 
38 /**
39  * An {@link IParser} to handle logcat.  The parser can handle the time and threadtime logcat
40  * formats.
41  * <p>
42  * Since the timestamps in the logcat do not have a year, the year can be set manually when the
43  * parser is created or through {@link #setYear(String)}.  If a year is not set, the current year
44  * will be used.
45  * </p>
46  */
47 public class LogcatParser implements IParser {
48     public static final String ANR = "ANR";
49     public static final String JAVA_CRASH = "JAVA_CRASH";
50     public static final String NATIVE_CRASH = "NATIVE_CRASH";
51     public static final String HIGH_CPU_USAGE = "HIGH_CPU_USAGE";
52     public static final String HIGH_MEMORY_USAGE = "HIGH_MEMORY_USAGE";
53     public static final String RUNTIME_RESTART = "RUNTIME_RESTART";
54 
55     /**
56      * Match a single line of `logcat -v threadtime`, such as:
57      *
58      * <pre>05-26 11:02:36.886 5689 5689 D AndroidRuntime: CheckJNI is OFF.</pre>
59      */
60     private static final Pattern THREADTIME_LINE =
61             // UID was added to logcat. It could either be a number or a string.
62             Pattern.compile(
63                     // timestamp[1]
64                     "^(\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2}.\\d{3})"
65                             // pid/tid and log level [2-4]
66                             + "(?:\\s+[0-9A-Za-z]+)?\\s+(\\d+)\\s+(\\d+)\\s+([A-Z])\\s+"
67                             // tag and message [5-6]
68                             + "(.+?)\\s*: (.*)$");
69 
70     /**
71      * Match a single line of `logcat -v time`, such as:
72      * 06-04 02:32:14.002 D/dalvikvm(  236): GC_CONCURRENT freed 580K, 51% free [...]
73      */
74     private static final Pattern TIME_LINE = Pattern.compile(
75             "^(\\d{2}-\\d{2} \\d{2}:\\d{2}:\\d{2}.\\d{3})\\s+" +  /* timestamp [1] */
76                 "(\\w)/(.+?)\\(\\s*(\\d+)\\): (.*)$");  /* level, tag, pid, msg [2-5] */
77 
78     /**
79      * Match: "*** FATAL EXCEPTION IN SYSTEM PROCESS: message"
80      */
81     private static final Pattern SYSTEM_SERVER_CRASH = Pattern.compile(
82             "\\*\\*\\* FATAL EXCEPTION IN SYSTEM PROCESS:.*");
83     /**
84      * Match "Process: com.android.package, PID: 123" or "PID: 123"
85      */
86     private static final Pattern JAVA_CRASH_PROCESS_PID = Pattern.compile(
87             "^(Process: (\\S+), )?PID: (\\d+)$");
88 
89 
90     /**
91      * Match a line thats printed when a non app java process starts.
92      */
93     private static final Pattern JAVA_PROC_START = Pattern.compile("Calling main entry (.+)");
94 
95     /**
96      * Class for storing logcat meta data for a particular grouped list of lines.
97      */
98     private class LogcatData {
99         public Integer mPid = null;
100         public Integer mTid = null;
101         public Date mTime = null;
102         public String mLevel = null;
103         public String mTag = null;
104         public String mLastPreamble = null;
105         public String mProcPreamble = null;
106         public List<String> mLines = new LinkedList<String>();
107 
LogcatData(Integer pid, Integer tid, Date time, String level, String tag, String lastPreamble, String procPreamble)108         public LogcatData(Integer pid, Integer tid, Date time, String level, String tag,
109                 String lastPreamble, String procPreamble) {
110             mPid = pid;
111             mTid = tid;
112             mTime = time;
113             mLevel = level;
114             mTag = tag;
115             mLastPreamble = lastPreamble;
116             mProcPreamble = procPreamble;
117         }
118     }
119 
120     private LogPatternUtil mPatternUtil = new LogPatternUtil();
121     private LogTailUtil mPreambleUtil = new LogTailUtil();
122 
123     private String mYear = null;
124 
125     LogcatItem mLogcat = null;
126 
127     Map<String, LogcatData> mDataMap = new HashMap<String, LogcatData>();
128     List<LogcatData> mDataList = new LinkedList<LogcatData>();
129 
130     private Date mStartTime = null;
131     private Date mStopTime = null;
132 
133     private boolean mIsParsing = true;
134 
135     private Map<Integer, String> mPids = new HashMap<Integer, String>();
136 
137     private List<CrashTag> mJavaCrashTags = new ArrayList<>();
138     private List<CrashTag> mNativeCrashTags = new ArrayList<>();
139 
140     /**
141      * Constructor for {@link LogcatParser}.
142      */
LogcatParser()143     public LogcatParser() {
144         // Add default tag for java crash
145         addJavaCrashTag("E", "AndroidRuntime", JAVA_CRASH);
146         addNativeCrashTag("I", "DEBUG");
147         addNativeCrashTag("F", "DEBUG");
148         initPatterns();
149     }
150 
151     /**
152      * Constructor for {@link LogcatParser}.
153      *
154      * @param year The year as a string.
155      */
LogcatParser(String year)156     public LogcatParser(String year) {
157         this();
158         setYear(year);
159     }
160 
161     /**
162      * Sets the year for {@link LogcatParser}.
163      *
164      * @param year The year as a string.
165      */
setYear(String year)166     public void setYear(String year) {
167         mYear = year;
168     }
169 
170     /**
171      * Parse a logcat from a {@link BufferedReader} into an {@link LogcatItem} object.
172      *
173      * @param input a {@link BufferedReader}.
174      * @return The {@link LogcatItem}.
175      * @see #parse(List)
176      */
parse(BufferedReader input)177     public LogcatItem parse(BufferedReader input) throws IOException {
178         String line;
179         while ((line = input.readLine()) != null) {
180             parseLine(line);
181         }
182         commit();
183 
184         return mLogcat;
185     }
186 
187     /**
188      * {@inheritDoc}
189      *
190      * @return The {@link LogcatItem}.
191      */
192     @Override
parse(List<String> lines)193     public LogcatItem parse(List<String> lines) {
194         for (String line : lines) {
195             if (line == null) {
196                 continue;
197             }
198             parseLine(line);
199         }
200         commit();
201 
202         return mLogcat;
203     }
204 
205     /**
206      * Clear the existing {@link LogcatItem}. The next parse will create a new one.
207      */
clear()208     public void clear() {
209         mLogcat = null;
210         mDataList.clear();
211         mDataMap.clear();
212     }
213 
214     /**
215      * Parse a line of input.
216      *
217      * @param line The line to parse
218      */
parseLine(String line)219     private void parseLine(String line) {
220         if ("".equals(line.trim())) {
221             return;
222         }
223         if (mLogcat == null) {
224             mLogcat = new LogcatItem();
225         }
226         Integer pid = null;
227         Integer tid = null;
228         Date time = null;
229         String level = null;
230         String tag = null;
231         String msg = null;
232 
233         Matcher m = THREADTIME_LINE.matcher(line);
234         Matcher tm = TIME_LINE.matcher(line);
235         if (m.matches()) {
236             time = parseTime(m.group(1));
237             pid = Integer.parseInt(m.group(2));
238             tid = Integer.parseInt(m.group(3));
239             level = m.group(4);
240             tag = m.group(5);
241             msg = m.group(6);
242         } else if (tm.matches()) {
243             time = parseTime(tm.group(1));
244             level = tm.group(2);
245             tag = tm.group(3);
246             pid = Integer.parseInt(tm.group(4));
247             msg = tm.group(5);
248         }
249 
250         if (time != null) {
251             if (mStartTime == null) {
252                 mStartTime = time;
253             }
254             mStopTime = time;
255         }
256 
257         // Don't parse any lines after device begins reboot until a new log is detected.
258         if ("I".equals(level) && "ShutdownThread".equals(tag) &&
259                 Pattern.matches("Rebooting, reason: .*", msg)) {
260             mIsParsing = false;
261         }
262         if (Pattern.matches(".*--------- beginning of .*", line)) {
263             mIsParsing = true;
264         }
265 
266         if (!mIsParsing || !(m.matches() || tm.matches())) {
267             return;
268         }
269 
270 
271         // When a non app java process starts add its pid to the map
272         Matcher pidMatcher = JAVA_PROC_START.matcher(msg);
273         if (pidMatcher.matches()) {
274             String name = pidMatcher.group(1);
275             mPids.put(pid, name);
276         }
277 
278         // ANRs are separated either by different PID/TIDs or when AnrParser.START matches a line.
279         // The newest entry is kept in the dataMap for quick lookup while all entries are added to
280         // the list.
281         if ("E".equals(level) && "ActivityManager".equals(tag)) {
282             String key = encodeLine(pid, tid, level, tag);
283             LogcatData data;
284             if (!mDataMap.containsKey(key) || AnrParser.START.matcher(msg).matches()) {
285                 data = new LogcatData(pid, tid, time, level, tag, mPreambleUtil.getLastTail(),
286                         mPreambleUtil.getIdTail(pid));
287                 mDataMap.put(key, data);
288                 mDataList.add(data);
289             } else {
290                 data = mDataMap.get(key);
291             }
292             data.mLines.add(msg);
293         }
294 
295         // Native crashes are separated either by different PID/TIDs or when
296         // NativeCrashParser.FINGERPRINT matches a line.  The newest entry is kept in the dataMap
297         // for quick lookup while all entries are added to the list.
298         if (anyNativeCrashTagMatches(level, tag)) {
299             String key = encodeLine(pid, tid, level, tag);
300             LogcatData data;
301             if (!mDataMap.containsKey(key) || NativeCrashParser.FINGERPRINT.matcher(msg).matches()) {
302                 data = new LogcatData(pid, tid, time, level, tag, mPreambleUtil.getLastTail(),
303                         mPreambleUtil.getIdTail(pid));
304                 mDataMap.put(key, data);
305                 mDataList.add(data);
306             } else {
307                 data = mDataMap.get(key);
308             }
309             data.mLines.add(msg);
310         }
311 
312         // PID and TID are enough to separate Java crashes.
313         if (anyJavaCrashTagMatches(level, tag)) {
314             String key = encodeLine(pid, tid, level, tag);
315             LogcatData data;
316             if (!mDataMap.containsKey(key)) {
317                 data = new LogcatData(pid, tid, time, level, tag, mPreambleUtil.getLastTail(),
318                         mPreambleUtil.getIdTail(pid));
319                 mDataMap.put(key, data);
320                 mDataList.add(data);
321             } else {
322                 data = mDataMap.get(key);
323             }
324             data.mLines.add(msg);
325         }
326 
327         // Check the message here but add it in commit()
328         if (mPatternUtil.checkMessage(msg, new ExtrasPattern(level, tag)) != null) {
329             LogcatData data = new LogcatData(pid, tid, time, level, tag,
330                     mPreambleUtil.getLastTail(), mPreambleUtil.getIdTail(pid));
331             data.mLines.add(msg);
332             mDataList.add(data);
333         }
334 
335         // After parsing the line, add it the the buffer for the preambles.
336         mPreambleUtil.addLine(pid, line);
337     }
338 
339     /**
340      * Signal that the input has finished.
341      */
commit()342     private void commit() {
343         if (mLogcat == null) {
344             return;
345         }
346         for (LogcatData data : mDataList) {
347             MiscLogcatItem item = null;
348             if ("E".equals(data.mLevel) && "ActivityManager".equals(data.mTag)) {
349                 item = new AnrParser().parse(data.mLines);
350             } else if (anyJavaCrashTagMatches(data.mLevel, data.mTag)) {
351                 // Get the process name/PID from the Java crash, then pass the rest of the lines to
352                 // the parser.
353                 Integer pid = null;
354                 String app = null;
355                 for (int i = 0; i < data.mLines.size(); i++) {
356                     String line = data.mLines.get(i);
357                     Matcher m = JAVA_CRASH_PROCESS_PID.matcher(line);
358                     if (m.matches()) {
359                         app = m.group(2);
360                         pid = Integer.valueOf(m.group(3));
361                         data.mLines = data.mLines.subList(i + 1, data.mLines.size());
362                         break;
363                     }
364                     m = SYSTEM_SERVER_CRASH.matcher(line);
365                     if (m.matches()) {
366                         app = mPids.get(data.mPid);
367                         if (app == null) {
368                             app = "system_server";
369                         }
370                         data.mLines = data.mLines.subList(i + 1, data.mLines.size());
371                         break;
372                     }
373                 }
374                 item = new JavaCrashParser().parse(data.mLines);
375                 if (item != null) {
376                     item.setApp(app);
377                     item.setPid(pid);
378                     item.setCategory(getJavaCrashCategory(data.mLevel, data.mTag));
379                 }
380             } else if (anyNativeCrashTagMatches(data.mLevel, data.mTag)) {
381                 // CLog.v("Parsing native crash: %s", data.mLines);
382                 item = new NativeCrashParser().parse(data.mLines);
383             } else {
384                 String msg = ArrayUtil.join("\n", data.mLines);
385                 String category = mPatternUtil.checkMessage(msg, new ExtrasPattern(
386                         data.mLevel, data.mTag));
387                 if (category != null) {
388                     MiscLogcatItem logcatItem = new MiscLogcatItem();
389                     logcatItem.setCategory(category);
390                     logcatItem.setStack(msg);
391                     item = logcatItem;
392                 }
393             }
394             if (item != null) {
395                 item.setEventTime(data.mTime);
396                 if (item.getPid() == null) {
397                     item.setPid(data.mPid);
398                     item.setTid(data.mTid);
399                 }
400                 item.setLastPreamble(data.mLastPreamble);
401                 item.setProcessPreamble(data.mProcPreamble);
402                 item.setTag(data.mTag);
403                 mLogcat.addEvent(item);
404             }
405         }
406 
407         mLogcat.setStartTime(mStartTime);
408         mLogcat.setStopTime(mStopTime);
409     }
410 
411     /**
412      * Create an identifier that "should" be unique for a given logcat. In practice, we do use it as
413      * a unique identifier.
414      */
encodeLine(Integer pid, Integer tid, String level, String tag)415     private static String encodeLine(Integer pid, Integer tid, String level, String tag) {
416         if (tid == null) {
417             return String.format("%d|%s|%s", pid, level, tag);
418         }
419         return String.format("%d|%d|%s|%s", pid, tid, level, tag);
420     }
421 
422     /**
423      * Parse the timestamp and return a {@link Date}.  If year is not set, the current year will be
424      * used.
425      *
426      * @param timeStr The timestamp in the format {@code MM-dd HH:mm:ss.SSS}.
427      * @return The {@link Date}.
428      */
parseTime(String timeStr)429     private Date parseTime(String timeStr) {
430         // If year is null, just use the current year.
431         if (mYear == null) {
432             DateFormat yearFormatter = new SimpleDateFormat("yyyy");
433             mYear = yearFormatter.format(new Date());
434         }
435 
436         DateFormat formatter = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
437         try {
438             return formatter.parse(String.format("%s-%s", mYear, timeStr));
439         } catch (ParseException e) {
440             // CLog.e("Could not parse time string %s", timeStr);
441             return null;
442         }
443     }
444 
initPatterns()445     private void initPatterns() {
446         // High CPU usage
447         mPatternUtil.addPattern(Pattern.compile(".* timed out \\(is the CPU pegged\\?\\).*"),
448                 HIGH_CPU_USAGE);
449 
450         // High memory usage
451         mPatternUtil.addPattern(Pattern.compile(
452                 "GetBufferLock timed out for thread \\d+ buffer .*"), HIGH_MEMORY_USAGE);
453 
454         // Runtime restarts
455         mPatternUtil.addPattern(Pattern.compile("\\*\\*\\* WATCHDOG KILLING SYSTEM PROCESS.*"),
456                 RUNTIME_RESTART);
457     }
458 
459     /**
460      * Adds a custom, more complex pattern to LogcatParser for parsing out of logcat events.
461      * Any matched events are then assigned to the category name provided, and can be grabbed
462      * via LogcatParser's .getMiscEvents("yourCustomCategoryName") method.
463      * Considers null messages, levels, or tags to be wildcards.
464      *
465      * @param pattern The regex representing the pattern to match for, or null for wildcard.
466      * @param level The name of the level to match for, or null for wildcard.
467      * @param tag The name of the tag to match for, or null for wildcard.
468      * @param category Assign any matching logcat events to this category name, for later retrieval
469      */
addPattern(Pattern pattern, String level, String tag, String category)470     public void addPattern(Pattern pattern, String level, String tag, String category) {
471         /* count null message as wildcard */
472         if (pattern == null) {
473             pattern = Pattern.compile(".*");
474         }
475         mPatternUtil.addPattern(pattern, new ExtrasPattern(level, tag), category);
476     }
477 
478     /**
479      * Used internally for bundling up extra pattern criteria for more advanced pattern matching.
480      */
481     private class ExtrasPattern {
482         public String mLevel;
483         public String mTag;
484 
ExtrasPattern(String level, String tag)485         public ExtrasPattern(String level, String tag) {
486             mLevel = level;
487             mTag = tag;
488         }
489 
490         /**
491          * Override Object.equals to match based on the level & tag patterns,
492          * while also counting null level & tag patterns as wildcards.
493          *
494          * @param otherObj the object we're matching the level & tag patterns to.
495          * @return true if otherObj's extras match, false otherwise
496          */
497         @Override
equals(Object otherObj)498         public boolean equals(Object otherObj) {
499             if (otherObj instanceof ExtrasPattern) {
500                 // Treat objects as equal only if the obj's level and tag match.
501                 // Treat null as a wildcard.
502                 ExtrasPattern other = (ExtrasPattern) otherObj;
503                 if ((mLevel == null || other.mLevel == null || mLevel.equals(other.mLevel)) &&
504                         (mTag == null || other.mTag == null || mTag.equals(other.mTag))) {
505                     return true;
506                 }
507             }
508             return false;
509         }
510 
511         /** {@inheritdoc} */
512         @Override
hashCode()513         public int hashCode() {
514             // Since both mLevel and mTag can be wild cards, we can't actually use them to generate
515             // a hashcode without potentially violating the hashcode contract. That doesn't leave
516             // us with anything to actually use to generate the hashcode, so just return a random
517             // static int.
518             return 145800969;
519         }
520     }
521 
522     /**
523      * Allows Java crashes to be parsed from multiple log levels and tags. Normally the crashes
524      * are error level messages from AndroidRuntime, but they could also be from other sources.
525      * Use this method to parse java crashes from those other sources.
526      *
527      * @param level log level on which to look for java crashes
528      * @param tag log tag where to look for java crashes
529      */
addJavaCrashTag(String level, String tag, String category)530     public void addJavaCrashTag(String level, String tag, String category) {
531         mJavaCrashTags.add(new CrashTag(level, tag, category));
532     }
533 
534     /**
535      * Allows native crashes to be parsed from multiple log levels and tags.  The default levels
536      * are "I DEBUG" and "F DEBUG".
537      *
538      * @param level log level on which to look for native crashes
539      * @param tag log tag where to look for native crashes
540      */
addNativeCrashTag(String level, String tag)541     private void addNativeCrashTag(String level, String tag) {
542         mNativeCrashTags.add(new CrashTag(level, tag, NATIVE_CRASH));
543     }
544 
545     /**
546      * Determines if any of the Java crash tags is matching a logcat line.
547      *
548      * @param level log level of the logcat line
549      * @param tag tag of the logcat line
550      * @return True if any Java crash tag matches the current level and tag. False otherwise.
551      */
anyJavaCrashTagMatches(String level, String tag)552     private boolean anyJavaCrashTagMatches(String level, String tag) {
553         return findCrashTag(mJavaCrashTags, level, tag) != null;
554     }
555 
556     /**
557      * Determines if any of the native crash tags is matching a logcat line.
558      *
559      * @param level log level of the logcat line
560      * @param tag tag of the logcat line
561      * @return True if any native crash tag matches the current level and tag. False otherwise.
562      */
anyNativeCrashTagMatches(String level, String tag)563     private boolean anyNativeCrashTagMatches(String level, String tag) {
564         return findCrashTag(mNativeCrashTags, level, tag) != null;
565     }
566 
567     /**
568      * Finds the {@link CrashTag} matching given level and tag.
569      *
570      * @param level level to find
571      * @param tag tag to find
572      * @return the matching {@link CrashTag} or null if no matches exist.
573      */
findCrashTag(List<CrashTag> crashTags, String level, String tag)574     private CrashTag findCrashTag(List<CrashTag> crashTags, String level, String tag) {
575         for (CrashTag t : crashTags) {
576             if (t.matches(level, tag)) {
577                 return t;
578             }
579         }
580         return null;
581     }
582 
583     /**
584      * Returns category for a given {@link CrashTag}.
585      *
586      * @param level level of the {@link CrashTag}
587      * @param tag tag of the {@link CrashTag}
588      * @return category of the {@link CrashTag}, matching search criteria. If nothing was found
589      * returns {@code JAVA_CRASH}.
590      */
getJavaCrashCategory(String level, String tag)591     private String getJavaCrashCategory(String level, String tag) {
592         CrashTag crashTag = findCrashTag(mJavaCrashTags, level, tag);
593         if (crashTag == null) {
594             return JAVA_CRASH;
595         }
596         return crashTag.getCategory();
597     }
598 
599     /**
600      * Class to encapsulate the tags that indicate which crashes should be parsed.
601      */
602     private class CrashTag {
603         private String mLevel;
604         private String mTag;
605         private String mCategory;
606 
CrashTag(String level, String tag, String category)607         public CrashTag(String level, String tag, String category) {
608             mLevel = level;
609             mTag = tag;
610             mCategory = category;
611         }
612 
matches(String level, String tag)613         public boolean matches(String level, String tag) {
614             return mLevel.equals(level) && mTag.equals(tag);
615         }
616 
getCategory()617         public String getCategory() {
618             return mCategory;
619         }
620     }
621 }
622