From 9d8cb31234b78b03f7044e78526053cb7e1050ea Mon Sep 17 00:00:00 2001 From: Christian Holler Date: Wed, 9 May 2012 16:16:26 +0200 Subject: [PATCH] Implement detection and triage of non-fatal assertions through logfilter --- adbfuzz.py | 111 ++++++++++++++++++++++++++++++++++++--------------- logfilter.py | 75 ++++++++++++++++++++++++++++++++++ mail.py | 14 ++++--- triage.py | 44 ++++++++++++-------- 4 files changed, 190 insertions(+), 54 deletions(-) create mode 100644 logfilter.py diff --git a/adbfuzz.py b/adbfuzz.py index f86dc5f..95b7879 100644 --- a/adbfuzz.py +++ b/adbfuzz.py @@ -23,6 +23,7 @@ import signal import sys import traceback import random +import uuid from ConfigParser import SafeConfigParser from mozdevice import DeviceManagerADB @@ -30,6 +31,7 @@ from mozdevice import DeviceManagerADB from adbfuzzconfig import ADBFuzzConfig from triage import Triager from minidump import Minidump +from logfilter import LogFilter def usage(): print "" @@ -84,6 +86,7 @@ class ADBFuzz: self.HTTPProcess = None self.logProcesses = [] + self.logThreads = [] self.remoteInitialized = None self.triager = Triager(self.config) @@ -207,7 +210,7 @@ class ADBFuzz: logSize = 0 hangDetected = False forceRestart = False - while(self.isFennecRunning()): + while(self.isFennecRunning() and not self.checkLoggingThreads()): time.sleep(self.config.runTimeout) if not os.path.exists(self.logFile): @@ -231,36 +234,57 @@ class ADBFuzz: print "Hang detected or running too long, restarting..." else: try: - # Fennec died + # Fennec died or a logger found something + checkCrashDump = True + crashUUID = None + minidump = None + + # If Fennec is still running, stop it now + if self.isFennecRunning(): + checkCrashDump = False + self.stopFennec() # Terminate our logging processes first self.stopLoggers() - dumps = self.getMinidumps() - if (len(dumps) > 1): - raise Exception("Multiple dumps detected!") + if checkCrashDump: + dumps = self.getMinidumps() + if (len(dumps) > 1): + raise Exception("Multiple dumps detected!") + + if (len(dumps) < 1): + raise Exception("No crash dump detected!") + + if not self.fetchMinidump(dumps[0]): + raise Exception("Failed to fetch minidump with UUID " + dumps[0]) + + crashUUID = dumps[0] + + # Copy logfiles + shutil.copy2(self.syslogFile, dumps[0] + ".syslog") + shutil.copy2(self.logFile, dumps[0] + ".log") + + minidump = Minidump(dumps[0] + ".dmp", self.config.libDir) + else: + # We need to generate an arbitrary ID here + crashUUID = str(uuid.uuid4()) - if (len(dumps) < 1): - raise Exception("No crash dump detected!") + # Copy logfiles + shutil.copy2(self.syslogFile, crashUUID + ".syslog") + shutil.copy2(self.logFile, crashUUID + ".log") - if not self.fetchMinidump(dumps[0]): - raise Exception("Failed to fetch minidump with UUID " + dumps[0]) + print "Crash detected. Reproduction logfile stored at: " + crashUUID + ".log" + if checkCrashDump: + crashTrace = minidump.getCrashTrace() + crashType = minidump.getCrashType() + print "Crash type: " + crashType + print "Crash backtrace:" + print "" + print crashTrace + else: + print "Crash type: Abnormal behavior (e.g. Assertion violation)" - # Copy logfiles - shutil.copy2(self.syslogFile, dumps[0] + ".syslog") - shutil.copy2(self.logFile, dumps[0] + ".log") - - minidump = Minidump(dumps[0] + ".dmp", self.config.libDir) - - print "Crash detected. Reproduction logfile stored at: " + dumps[0] + ".log" - crashTrace = minidump.getCrashTrace() - crashType = minidump.getCrashType() - print "Crash type: " + crashType - print "Crash backtrace:" - print "" - print crashTrace - - self.triager.process(minidump, dumps[0] + ".syslog", dumps[0] + ".log") + self.triager.process(crashUUID, minidump, crashUUID + ".syslog", crashUUID + ".log") except Exception, e: print "Error during crash processing: " print traceback.format_exc() @@ -290,7 +314,7 @@ class ADBFuzz: startTime = time.time() - while(self.isFennecRunning()): + while(self.isFennecRunning() and not self.checkLoggingThreads()): time.sleep(1) if ((time.time() - startTime) > self.config.runTimeout): self.stopFennec() @@ -298,6 +322,11 @@ class ADBFuzz: self.stopLoggers() print "[TIMEOUT]" return False + + abortedByLogThread = False + if self.isFennecRunning(): + abortedByLogThread = True + self.stopFennec() self.HTTPProcess.terminate() self.stopLoggers() @@ -307,8 +336,11 @@ class ADBFuzz: if (len(dumps) > 0): print "[Crash reproduced successfully]" return True + elif abortedByLogThread: + print "[Abort reproduced successfully]" + return True else: - # Fennec exited, but no crash + # Fennec exited, but no crash/abort print "[Exit without Crash]" return False @@ -367,6 +399,20 @@ class ADBFuzz: # Terminate our logging processes while (len(self.logProcesses) > 0): self.logProcesses.pop().terminate() + + while (len(self.logThreads) > 0): + logThread = self.logThreads.pop() + logThread.terminate() + logThread.join() + + def checkLoggingThreads(self): + for logThread in self.logThreads: + # Check if the thread aborted but did not hit EOF. + # That means we hit something interesting. + if not logThread.isAlive() and not logThread.eof: + return True + + return False def startNewDeviceLog(self, toStdout=False): # Clear the log first @@ -375,16 +421,17 @@ class ADBFuzz: logCmd = ["adb", "logcat", "-s", "Gecko:v", "GeckoDump:v", "GeckoConsole:v", "MOZ_Assert:v"] if toStdout: - logProcess = subprocess.Popen(logCmd) + logFile = None else: # Logfile self.syslogFile = 'device.log' + logFile = self.syslogFile - # Start logging - logFile = open(self.syslogFile, 'w') - logProcess = subprocess.Popen(logCmd, stdout=logFile) - - self.logProcesses.append(logProcess) + # Start logging thread + logThread = LogFilter(self.config, self.triager, logCmd, logFile) + logThread.start() + + self.logThreads.append(logThread) def startNewWebSocketLog(self): self.logFile = 'websock.log' diff --git a/logfilter.py b/logfilter.py new file mode 100644 index 0000000..df68d08 --- /dev/null +++ b/logfilter.py @@ -0,0 +1,75 @@ +# ***** BEGIN LICENSE BLOCK ***** +# Version: MPL 2.0 +# +# This Source Code Form is subject to the terms of the Mozilla Public +# License, v. 2.0. If a copy of the MPL was not distributed with this +# file, You can obtain one at http://mozilla.org/MPL/2.0/. +# +# The Original Code is ADBFuzz. +# +# The Initial Developer of the Original Code is Christian Holler (decoder). +# +# Contributors: +# Christian Holler (Original Developer) +# +# ***** END LICENSE BLOCK ***** + +import threading +import subprocess + +class LogFilter(threading.Thread): + def __init__(self, config, triager, logCmd, logFile): + self.config = config + self.triager = triager + self.logCmd = logCmd + self.logFile = logFile + self.eof = False + + # Thread initialization stuff + self.stdout = None + self.stderr = None + threading.Thread.__init__(self) + + # We need this to know when to terminate + self._stop = threading.Event() + + def run(self): + + if self.logFile == None: + logFileFd = None + else: + logFileFd = open(self.logFile, 'w') + + logProcess = subprocess.Popen(self.logCmd, shell=False, stdout=subprocess.PIPE, stderr=None) + + # Loop until we get aborted, hit EOF or find something interesting + while not self._stop.isSet(): + line = logProcess.stdout.readline() + if (len(line) == 0): + self.eof = True + break + + if logFileFd == None: + # Output to stdout + print line + else: + # Store to file first + logFileFd.write(line) + + # Now check if it has something interesting (e.g. assertion) + line = line.strip() + if self.triager.checkLine(line): + break + + logProcess.terminate() + + if logFileFd != None: + logFileFd.close() + + return + + def terminate(self): + self._stop.set() + +if __name__ == "__main__": + raise Exception("This module cannot run standalone, but is used by ADBFuzz") diff --git a/mail.py b/mail.py index a12ae30..42f59e8 100644 --- a/mail.py +++ b/mail.py @@ -20,19 +20,21 @@ class Mailer: def __init__(self, config): self.config = config - def notify(self, miniDump, issueDesc): + def notify(self, issueUUID, issueDesc, miniDump): msg = ("From: %s\r\nTo: %s\r\n" % (self.config.mailFrom, self.config.mailTo)) msg = msg + "Subject: [ADBFuzz] Issue report: " + issueDesc + "\r\n\r\n" - msg = msg + "Crash dump: " + miniDump.getFilename() + "\r\n" + msg = msg + "Crash UUID: " + issueUUID + "\r\n" msg = msg + "Instance identifier: " + self.config.id + "\r\n" msg = msg + "\r\n" - msg = msg + "Crash trace:" + "\r\n" - crashTrace = miniDump.getSymbolizedCrashTrace() + if miniDump != None: + msg = msg + "Crash trace:" + "\r\n" - for (frameNum, frameAddr, frameFile) in crashTrace: - msg = msg + " " + frameNum + " " + frameAddr + " " + frameFile + "\r\n" + crashTrace = miniDump.getSymbolizedCrashTrace() + + for (frameNum, frameAddr, frameFile) in crashTrace: + msg = msg + " " + frameNum + " " + frameAddr + " " + frameFile + "\r\n" server = smtplib.SMTP(self.config.SMTPHost) server.set_debuglevel(1) diff --git a/triage.py b/triage.py index b6bb212..5754ec3 100644 --- a/triage.py +++ b/triage.py @@ -34,8 +34,10 @@ class Triager: self.assertDetector = AssertionDetector(self.config.knownPath) self.crashDetector = CrashDetector(self.config.knownPath) + + self.androidLogLinefilter = lambda x: re.sub('^[^:]+: ', '', x) - def process(self, miniDump, systemLog, websockLog): + def process(self, issueUUID, miniDump, systemLog, websockLog): print "Triaging crash..." # Read Android system log @@ -45,7 +47,7 @@ class Triager: aborted = self.assertDetector.hasFatalAssertion( systemLogFile, verbose=True, - lineFilter=lambda x: re.sub('^[^:]+: ', '', x) + lineFilter=self.androidLogLinefilter ) # Reopen file @@ -58,27 +60,32 @@ class Triager: systemLogFile, verbose=True, ignoreKnownAssertions=True, - lineFilter=lambda x: re.sub('^[^:]+: ', '', x) + lineFilter=self.androidLogLinefilter ) hasNewAssertion = len(assertions) > 0 systemLogFile.close() - # Obtain symbolized crash trace to check crash signature - trace = miniDump.getSymbolizedCrashTrace() - - isNewCrash = True + if miniDump == None and not hasNewAssertion: + print "Error: No minidump available but also no assertions detected!" + return + + isNewCrash = (miniDump != None) crashFunction = "Unknown" issueDesc = "Unknown" - if (len(trace) > 0): - crashFunction = trace[0][1] - issueDesc = "Crashed at " + crashFunction - isNewCrash = not self.crashDetector.isKnownCrashSignature(crashFunction) - # Also check first frame (some functions are blacklisted here) - if (isNewCrash and len(trace) > 1): - isNewCrash = not self.crashDetector.isKnownCrashSignature(trace[1][1]) + if miniDump != None: + # Obtain symbolized crash trace to check crash signature + trace = miniDump.getSymbolizedCrashTrace() + + if (len(trace) > 0): + crashFunction = trace[0][1] + issueDesc = "Crashed at " + crashFunction + isNewCrash = not self.crashDetector.isKnownCrashSignature(crashFunction) + # Also check first frame (some functions are blacklisted here) + if (isNewCrash and len(trace) > 1): + isNewCrash = not self.crashDetector.isKnownCrashSignature(trace[1][1]) # Use the last assertion as issue description if hasNewAssertion: @@ -89,15 +96,20 @@ class Triager: if hasNewAssertion or (not aborted and isNewCrash): print "Found new issue, check " + websockLog + " to reproduce" if self.config.useMail: - self.mailer.notify(miniDump, issueDesc) + self.mailer.notify(issueUUID, issueDesc, miniDump) else: # Delete files if not in debug mode if not self.config.debug: - miniDump.cleanup() + if miniDump != None: + miniDump.cleanup() os.remove(systemLog) os.remove(websockLog) return + + def checkLine(self, line): + return self.assertDetector.scanLineAssertions(self.androidLogLinefilter(line)) + if __name__ == "__main__": raise Exception("This module cannot run standalone, but is used by ADBFuzz")