build/android/adb_logcat_printer.py

   1 #!/usr/bin/env python
   2 #
   3 # Copyright (c) 2012 The Chromium Authors. All rights reserved.
   4 # Use of this source code is governed by a BSD-style license that can be
   5 # found in the LICENSE file.
   6
   7 """Shutdown adb_logcat_monitor and print accumulated logs.
   8
   9 To test, call './adb_logcat_printer.py <base_dir>' where
  10 <base_dir> contains 'adb logcat -v threadtime' files named as
  11 logcat_<deviceID>_<sequenceNum>
  12
  13 The script will print the files to out, and will combine multiple
  14 logcats from a single device if there is overlap.
  15
  16 Additionally, if a <base_dir>/LOGCAT_MONITOR_PID exists, the script
  17 will attempt to terminate the contained PID by sending a SIGINT and
  18 monitoring for the deletion of the aforementioned file.
  19 """
  20 # pylint: disable=W0702
  21
  22 import cStringIO
  23 import logging
  24 import optparse
  25 import os
  26 import re
  27 import signal
  28 import sys
  29 import time
  30
  31
  32 # Set this to debug for more verbose output
  33 LOG_LEVEL = logging.INFO
  34
  35
  36 def CombineLogFiles(list_of_lists, logger):
  37   """Splices together multiple logcats from the same device.
  38
  39   Args:
  40     list_of_lists: list of pairs (filename, list of timestamped lines)
  41     logger: handler to log events
  42
  43   Returns:
  44     list of lines with duplicates removed
  45   """
  46   cur_device_log = ['']
  47   for cur_file, cur_file_lines in list_of_lists:
  48     # Ignore files with just the logcat header
  49     if len(cur_file_lines) < 2:
  50       continue
  51     common_index = 0
  52     # Skip this step if list just has empty string
  53     if len(cur_device_log) > 1:
  54       try:
  55         line = cur_device_log[-1]
  56         # Used to make sure we only splice on a timestamped line
  57         if re.match(r'^\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{3} ', line):
  58           common_index = cur_file_lines.index(line)
  59         else:
  60           logger.warning('splice error - no timestamp in "%s"?', line.strip())
  61       except ValueError:
  62         # The last line was valid but wasn't found in the next file
  63         cur_device_log += ['***** POSSIBLE INCOMPLETE LOGCAT *****']
  64         logger.info('Unable to splice %s. Incomplete logcat?', cur_file)
  65
  66     cur_device_log += ['*'*30 + '  %s' % cur_file]
  67     cur_device_log.extend(cur_file_lines[common_index:])
  68
  69   return cur_device_log
  70
  71
  72 def FindLogFiles(base_dir):
  73   """Search a directory for logcat files.
  74
  75   Args:
  76     base_dir: directory to search
  77
  78   Returns:
  79     Mapping of device_id to a sorted list of file paths for a given device
  80   """
  81   logcat_filter = re.compile(r'^logcat_(\S+)_(\d+)$')
  82   # list of tuples (<device_id>, <seq num>, <full file path>)
  83   filtered_list = []
  84   for cur_file in os.listdir(base_dir):
  85     matcher = logcat_filter.match(cur_file)
  86     if matcher:
  87       filtered_list += [(matcher.group(1), int(matcher.group(2)),
  88                          os.path.join(base_dir, cur_file))]
  89   filtered_list.sort()
  90   file_map = {}
  91   for device_id, _, cur_file in filtered_list:
  92     if device_id not in file_map:
  93       file_map[device_id] = []
  94
  95     file_map[device_id] += [cur_file]
  96   return file_map
  97
  98
  99 def GetDeviceLogs(log_filenames, logger):
 100   """Read log files, combine and format.
 101
 102   Args:
 103     log_filenames: mapping of device_id to sorted list of file paths
 104     logger: logger handle for logging events
 105
 106   Returns:
 107     list of formatted device logs, one for each device.
 108   """
 109   device_logs = []
 110
 111   for device, device_files in log_filenames.iteritems():
 112     logger.debug('%s: %s', device, str(device_files))
 113     device_file_lines = []
 114     for cur_file in device_files:
 115       with open(cur_file) as f:
 116         device_file_lines += [(cur_file, f.read().splitlines())]
 117     combined_lines = CombineLogFiles(device_file_lines, logger)
 118     # Prepend each line with a short unique ID so it's easy to see
 119     # when the device changes.  We don't use the start of the device
 120     # ID because it can be the same among devices.  Example lines:
 121     # AB324:  foo
 122     # AB324:  blah
 123     device_logs += [('\n' + device[-5:] + ':  ').join(combined_lines)]
 124   return device_logs
 125
 126
 127 def ShutdownLogcatMonitor(base_dir, logger):
 128   """Attempts to shutdown adb_logcat_monitor and blocks while waiting."""
 129   try:
 130     monitor_pid_path = os.path.join(base_dir, 'LOGCAT_MONITOR_PID')
 131     with open(monitor_pid_path) as f:
 132       monitor_pid = int(f.readline())
 133
 134     logger.info('Sending SIGTERM to %d', monitor_pid)
 135     os.kill(monitor_pid, signal.SIGTERM)
 136     i = 0
 137     while True:
 138       time.sleep(.2)
 139       if not os.path.exists(monitor_pid_path):
 140         return
 141       if not os.path.exists('/proc/%d' % monitor_pid):
 142         logger.warning('Monitor (pid %d) terminated uncleanly?', monitor_pid)
 143         return
 144       logger.info('Waiting for logcat process to terminate.')
 145       i += 1
 146       if i >= 10:
 147         logger.warning('Monitor pid did not terminate. Continuing anyway.')
 148         return
 149
 150   except (ValueError, IOError, OSError):
 151     logger.exception('Error signaling logcat monitor - continuing')
 152
 153
 154 def main(argv):
 155   parser = optparse.OptionParser(usage='Usage: %prog [options] <log dir>')
 156   parser.add_option('--output-path',
 157                     help='Output file path (if unspecified, prints to stdout)')
 158   options, args = parser.parse_args(argv)
 159   if len(args) != 1:
 160     parser.error('Wrong number of unparsed args')
 161   base_dir = args[0]
 162   if options.output_path:
 163     output_file = open(options.output_path, 'w')
 164   else:
 165     output_file = sys.stdout
 166
 167   log_stringio = cStringIO.StringIO()
 168   logger = logging.getLogger('LogcatPrinter')
 169   logger.setLevel(LOG_LEVEL)
 170   sh = logging.StreamHandler(log_stringio)
 171   sh.setFormatter(logging.Formatter('%(asctime)-2s %(levelname)-8s'
 172                                     ' %(message)s'))
 173   logger.addHandler(sh)
 174
 175   try:
 176     # Wait at least 5 seconds after base_dir is created before printing.
 177     #
 178     # The idea is that 'adb logcat > file' output consists of 2 phases:
 179     #  1 Dump all the saved logs to the file
 180     #  2 Stream log messages as they are generated
 181     #
 182     # We want to give enough time for phase 1 to complete.  There's no
 183     # good method to tell how long to wait, but it usually only takes a
 184     # second.  On most bots, this code path won't occur at all, since
 185     # adb_logcat_monitor.py command will have spawned more than 5 seconds
 186     # prior to called this shell script.
 187     try:
 188       sleep_time = 5 - (time.time() - os.path.getctime(base_dir))
 189     except OSError:
 190       sleep_time = 5
 191     if sleep_time > 0:
 192       logger.warning('Monitor just started? Sleeping %.1fs', sleep_time)
 193       time.sleep(sleep_time)
 194
 195     assert os.path.exists(base_dir), '%s does not exist' % base_dir
 196     ShutdownLogcatMonitor(base_dir, logger)
 197     separator = '\n' + '*' * 80 + '\n\n'
 198     for log in GetDeviceLogs(FindLogFiles(base_dir), logger):
 199       output_file.write(log)
 200       output_file.write(separator)
 201     with open(os.path.join(base_dir, 'eventlog')) as f:
 202       output_file.write('\nLogcat Monitor Event Log\n')
 203       output_file.write(f.read())
 204   except:
 205     logger.exception('Unexpected exception')
 206
 207   logger.info('Done.')
 208   sh.flush()
 209   output_file.write('\nLogcat Printer Event Log\n')
 210   output_file.write(log_stringio.getvalue())
 211
 212 if __name__ == '__main__':
 213   sys.exit(main(sys.argv[1:]))