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
9To test, call './adb_logcat_printer.py <base_dir>' where
10<base_dir> contains 'adb logcat -v threadtime' files named as
11logcat_<deviceID>_<sequenceNum>
12
13The script will print the files to out, and will combine multiple
14logcats from a single device if there is overlap.
15
16Additionally, if a <base_dir>/LOGCAT_MONITOR_PID exists, the script
17will attempt to terminate the contained PID by sending a SIGINT and
18monitoring for the deletion of the aforementioned file.
19"""
20# pylint: disable=W0702
21
22import cStringIO
23import logging
24import optparse
25import os
26import re
27import signal
28import sys
29import time
30
31
32# Set this to debug for more verbose output
33LOG_LEVEL = logging.INFO
34
35
36def 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
72def 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_(\w+)_(\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
99def 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
127def 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
154def 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
212if __name__ == '__main__':
213  sys.exit(main(sys.argv[1:]))
214