summaryrefslogtreecommitdiffstats
path: root/build/android/adb_logcat_printer.py
blob: 55176ab9201333745d63f878bcdcb68118efe95a (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
#!/usr/bin/env python
#
# Copyright (c) 2012 The Chromium Authors. All rights reserved.
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.

"""Shutdown adb_logcat_monitor and print accumulated logs.

To test, call './adb_logcat_printer.py <base_dir>' where
<base_dir> contains 'adb logcat -v threadtime' files named as
logcat_<deviceID>_<sequenceNum>

The script will print the files to out, and will combine multiple
logcats from a single device if there is overlap.

Additionally, if a <base_dir>/LOGCAT_MONITOR_PID exists, the script
will attempt to terminate the contained PID by sending a SIGINT and
monitoring for the deletion of the aforementioned file.
"""
# pylint: disable=W0702

import cStringIO
import logging
import optparse
import os
import re
import signal
import sys
import time


# Set this to debug for more verbose output
LOG_LEVEL = logging.INFO


def CombineLogFiles(list_of_lists, logger):
  """Splices together multiple logcats from the same device.

  Args:
    list_of_lists: list of pairs (filename, list of timestamped lines)
    logger: handler to log events

  Returns:
    list of lines with duplicates removed
  """
  cur_device_log = ['']
  for cur_file, cur_file_lines in list_of_lists:
    # Ignore files with just the logcat header
    if len(cur_file_lines) < 2:
      continue
    common_index = 0
    # Skip this step if list just has empty string
    if len(cur_device_log) > 1:
      try:
        line = cur_device_log[-1]
        # Used to make sure we only splice on a timestamped line
        if re.match(r'^\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{3} ', line):
          common_index = cur_file_lines.index(line)
        else:
          logger.warning('splice error - no timestamp in "%s"?', line.strip())
      except ValueError:
        # The last line was valid but wasn't found in the next file
        cur_device_log += ['***** POSSIBLE INCOMPLETE LOGCAT *****']
        logger.info('Unable to splice %s. Incomplete logcat?', cur_file)

    cur_device_log += ['*'*30 + '  %s' % cur_file]
    cur_device_log.extend(cur_file_lines[common_index:])

  return cur_device_log


def FindLogFiles(base_dir):
  """Search a directory for logcat files.

  Args:
    base_dir: directory to search

  Returns:
    Mapping of device_id to a sorted list of file paths for a given device
  """
  logcat_filter = re.compile(r'^logcat_(\S+)_(\d+)$')
  # list of tuples (<device_id>, <seq num>, <full file path>)
  filtered_list = []
  for cur_file in os.listdir(base_dir):
    matcher = logcat_filter.match(cur_file)
    if matcher:
      filtered_list += [(matcher.group(1), int(matcher.group(2)),
                         os.path.join(base_dir, cur_file))]
  filtered_list.sort()
  file_map = {}
  for device_id, _, cur_file in filtered_list:
    if device_id not in file_map:
      file_map[device_id] = []

    file_map[device_id] += [cur_file]
  return file_map


def GetDeviceLogs(log_filenames, logger):
  """Read log files, combine and format.

  Args:
    log_filenames: mapping of device_id to sorted list of file paths
    logger: logger handle for logging events

  Returns:
    list of formatted device logs, one for each device.
  """
  device_logs = []

  for device, device_files in log_filenames.iteritems():
    logger.debug('%s: %s', device, str(device_files))
    device_file_lines = []
    for cur_file in device_files:
      with open(cur_file) as f:
        device_file_lines += [(cur_file, f.read().splitlines())]
    combined_lines = CombineLogFiles(device_file_lines, logger)
    # Prepend each line with a short unique ID so it's easy to see
    # when the device changes.  We don't use the start of the device
    # ID because it can be the same among devices.  Example lines:
    # AB324:  foo
    # AB324:  blah
    device_logs += [('\n' + device[-5:] + ':  ').join(combined_lines)]
  return device_logs


def ShutdownLogcatMonitor(base_dir, logger):
  """Attempts to shutdown adb_logcat_monitor and blocks while waiting."""
  try:
    monitor_pid_path = os.path.join(base_dir, 'LOGCAT_MONITOR_PID')
    with open(monitor_pid_path) as f:
      monitor_pid = int(f.readline())

    logger.info('Sending SIGTERM to %d', monitor_pid)
    os.kill(monitor_pid, signal.SIGTERM)
    i = 0
    while True:
      time.sleep(.2)
      if not os.path.exists(monitor_pid_path):
        return
      if not os.path.exists('/proc/%d' % monitor_pid):
        logger.warning('Monitor (pid %d) terminated uncleanly?', monitor_pid)
        return
      logger.info('Waiting for logcat process to terminate.')
      i += 1
      if i >= 10:
        logger.warning('Monitor pid did not terminate. Continuing anyway.')
        return

  except (ValueError, IOError, OSError):
    logger.exception('Error signaling logcat monitor - continuing')


def main(argv):
  parser = optparse.OptionParser(usage='Usage: %prog [options] <log dir>')
  parser.add_option('--output-path',
                    help='Output file path (if unspecified, prints to stdout)')
  options, args = parser.parse_args(argv)
  if len(args) != 1:
    parser.error('Wrong number of unparsed args')
  base_dir = args[0]
  if options.output_path:
    output_file = open(options.output_path, 'w')
  else:
    output_file = sys.stdout

  log_stringio = cStringIO.StringIO()
  logger = logging.getLogger('LogcatPrinter')
  logger.setLevel(LOG_LEVEL)
  sh = logging.StreamHandler(log_stringio)
  sh.setFormatter(logging.Formatter('%(asctime)-2s %(levelname)-8s'
                                    ' %(message)s'))
  logger.addHandler(sh)

  try:
    # Wait at least 5 seconds after base_dir is created before printing.
    #
    # The idea is that 'adb logcat > file' output consists of 2 phases:
    #  1 Dump all the saved logs to the file
    #  2 Stream log messages as they are generated
    #
    # We want to give enough time for phase 1 to complete.  There's no
    # good method to tell how long to wait, but it usually only takes a
    # second.  On most bots, this code path won't occur at all, since
    # adb_logcat_monitor.py command will have spawned more than 5 seconds
    # prior to called this shell script.
    try:
      sleep_time = 5 - (time.time() - os.path.getctime(base_dir))
    except OSError:
      sleep_time = 5
    if sleep_time > 0:
      logger.warning('Monitor just started? Sleeping %.1fs', sleep_time)
      time.sleep(sleep_time)

    assert os.path.exists(base_dir), '%s does not exist' % base_dir
    ShutdownLogcatMonitor(base_dir, logger)
    separator = '\n' + '*' * 80 + '\n\n'
    for log in GetDeviceLogs(FindLogFiles(base_dir), logger):
      output_file.write(log)
      output_file.write(separator)
    with open(os.path.join(base_dir, 'eventlog')) as f:
      output_file.write('\nLogcat Monitor Event Log\n')
      output_file.write(f.read())
  except:
    logger.exception('Unexpected exception')

  logger.info('Done.')
  sh.flush()
  output_file.write('\nLogcat Printer Event Log\n')
  output_file.write(log_stringio.getvalue())

if __name__ == '__main__':
  sys.exit(main(sys.argv[1:]))