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