sdk/platform-tools/systrace/catapult/devil/devil/android/logcat_monitor.py

   1 # Copyright 2015 The Chromium Authors. All rights reserved.
   2 # Use of this source code is governed by a BSD-style license that can be
   3 # found in the LICENSE file.
   4
   5 # pylint: disable=unused-argument
   6
   7 import errno
   8 import logging
   9 import os
  10 import re
  11 import shutil
  12 import tempfile
  13 import threading
  14 import time
  15
  16 from devil.android import decorators
  17 from devil.android import device_errors
  18 from devil.android.sdk import adb_wrapper
  19 from devil.utils import reraiser_thread
  20
  21 logger = logging.getLogger(__name__)
  22
  23
  24 class LogcatMonitor(object):
  25
  26   _RECORD_ITER_TIMEOUT = 2.0
  27   _RECORD_THREAD_JOIN_WAIT = 5.0
  28   _WAIT_TIME = 0.2
  29   _THREADTIME_RE_FORMAT = (
  30       r'(?P<date>\S*) +(?P<time>\S*) +(?P<proc_id>%s) +(?P<thread_id>%s) +'
  31       r'(?P<log_level>%s) +(?P<component>%s) *: +(?P<message>%s)$')
  32
  33   def __init__(self, adb, clear=True, filter_specs=None, output_file=None):
  34     """Create a LogcatMonitor instance.
  35
  36     Args:
  37       adb: An instance of adb_wrapper.AdbWrapper.
  38       clear: If True, clear the logcat when monitoring starts.
  39       filter_specs: An optional list of '<tag>[:priority]' strings.
  40       output_file: File path to save recorded logcat.
  41     """
  42     if isinstance(adb, adb_wrapper.AdbWrapper):
  43       self._adb = adb
  44     else:
  45       raise ValueError('Unsupported type passed for argument "device"')
  46     self._clear = clear
  47     self._filter_specs = filter_specs
  48     self._output_file = output_file
  49     self._record_file = None
  50     self._record_file_lock = threading.Lock()
  51     self._record_thread = None
  52     self._stop_recording_event = threading.Event()
  53
  54   @property
  55   def output_file(self):
  56     return self._output_file
  57
  58   @decorators.WithTimeoutAndRetriesDefaults(10, 0)
  59   def WaitFor(self, success_regex, failure_regex=None, timeout=None,
  60               retries=None):
  61     """Wait for a matching logcat line or until a timeout occurs.
  62
  63     This will attempt to match lines in the logcat against both |success_regex|
  64     and |failure_regex| (if provided). Note that this calls re.search on each
  65     logcat line, not re.match, so the provided regular expressions don't have
  66     to match an entire line.
  67
  68     Args:
  69       success_regex: The regular expression to search for.
  70       failure_regex: An optional regular expression that, if hit, causes this
  71         to stop looking for a match. Can be None.
  72       timeout: timeout in seconds
  73       retries: number of retries
  74
  75     Returns:
  76       A match object if |success_regex| matches a part of a logcat line, or
  77       None if |failure_regex| matches a part of a logcat line.
  78     Raises:
  79       CommandFailedError on logcat failure (NOT on a |failure_regex| match).
  80       CommandTimeoutError if no logcat line matching either |success_regex| or
  81         |failure_regex| is found in |timeout| seconds.
  82       DeviceUnreachableError if the device becomes unreachable.
  83       LogcatMonitorCommandError when calling |WaitFor| while not recording
  84         logcat.
  85     """
  86     if self._record_thread is None:
  87       raise LogcatMonitorCommandError(
  88           'Must be recording logcat when calling |WaitFor|',
  89           device_serial=str(self._adb))
  90     if isinstance(success_regex, basestring):
  91       success_regex = re.compile(success_regex)
  92     if isinstance(failure_regex, basestring):
  93       failure_regex = re.compile(failure_regex)
  94
  95     logger.debug('Waiting %d seconds for "%s"', timeout, success_regex.pattern)
  96
  97     # NOTE This will continue looping until:
  98     #  - success_regex matches a line, in which case the match object is
  99     #    returned.
 100     #  - failure_regex matches a line, in which case None is returned
 101     #  - the timeout is hit, in which case a CommandTimeoutError is raised.
 102     with open(self._record_file.name, 'r') as f:
 103       while True:
 104         line = f.readline()
 105         if line:
 106           m = success_regex.search(line)
 107           if m:
 108             return m
 109           if failure_regex and failure_regex.search(line):
 110             return None
 111         else:
 112           time.sleep(self._WAIT_TIME)
 113
 114   def FindAll(self, message_regex, proc_id=None, thread_id=None, log_level=None,
 115               component=None):
 116     """Finds all lines in the logcat that match the provided constraints.
 117
 118     Args:
 119       message_regex: The regular expression that the <message> section must
 120         match.
 121       proc_id: The process ID to match. If None, matches any process ID.
 122       thread_id: The thread ID to match. If None, matches any thread ID.
 123       log_level: The log level to match. If None, matches any log level.
 124       component: The component to match. If None, matches any component.
 125
 126     Raises:
 127       LogcatMonitorCommandError when calling |FindAll| before recording logcat.
 128
 129     Yields:
 130       A match object for each matching line in the logcat. The match object
 131       will always contain, in addition to groups defined in |message_regex|,
 132       the following named groups: 'date', 'time', 'proc_id', 'thread_id',
 133       'log_level', 'component', and 'message'.
 134     """
 135     if self._record_file is None:
 136       raise LogcatMonitorCommandError(
 137           'Must have recorded or be recording a logcat to call |FindAll|',
 138           device_serial=str(self._adb))
 139     if proc_id is None:
 140       proc_id = r'\d+'
 141     if thread_id is None:
 142       thread_id = r'\d+'
 143     if log_level is None:
 144       log_level = r'[VDIWEF]'
 145     if component is None:
 146       component = r'[^\s:]+'
 147     # pylint: disable=protected-access
 148     threadtime_re = re.compile(
 149         type(self)._THREADTIME_RE_FORMAT % (
 150             proc_id, thread_id, log_level, component, message_regex))
 151
 152     with open(self._record_file.name, 'r') as f:
 153       for line in f:
 154         m = re.match(threadtime_re, line)
 155         if m:
 156           yield m
 157
 158   def _StartRecording(self):
 159     """Starts recording logcat to file.
 160
 161     Function spawns a thread that records logcat to file and will not die
 162     until |StopRecording| is called.
 163     """
 164     def record_to_file():
 165       # Write the log with line buffering so the consumer sees each individual
 166       # line.
 167       for data in self._adb.Logcat(filter_specs=self._filter_specs,
 168                                    logcat_format='threadtime',
 169                                    iter_timeout=self._RECORD_ITER_TIMEOUT):
 170         if self._stop_recording_event.isSet():
 171           return
 172
 173         if data is None:
 174           # Logcat can yield None if the iter_timeout is hit.
 175           continue
 176
 177         with self._record_file_lock:
 178           if self._record_file and not self._record_file.closed:
 179             self._record_file.write(data + '\n')
 180
 181     self._stop_recording_event.clear()
 182     if not self._record_thread:
 183       self._record_thread = reraiser_thread.ReraiserThread(record_to_file)
 184       self._record_thread.start()
 185
 186   def _StopRecording(self):
 187     """Finish recording logcat."""
 188     if self._record_thread:
 189       self._stop_recording_event.set()
 190       self._record_thread.join(timeout=self._RECORD_THREAD_JOIN_WAIT)
 191       self._record_thread.ReraiseIfException()
 192       self._record_thread = None
 193
 194   def Start(self):
 195     """Starts the logcat monitor.
 196
 197     Clears the logcat if |clear| was set in |__init__|.
 198     """
 199     if self._clear:
 200       self._adb.Logcat(clear=True)
 201     if not self._record_file:
 202       self._record_file = tempfile.NamedTemporaryFile(mode='a', bufsize=1)
 203     self._StartRecording()
 204
 205   def Stop(self):
 206     """Stops the logcat monitor.
 207
 208     Stops recording the logcat. Copies currently recorded logcat to
 209     |self._output_file|.
 210     """
 211     self._StopRecording()
 212     with self._record_file_lock:
 213       if self._record_file and self._output_file:
 214         try:
 215           os.makedirs(os.path.dirname(self._output_file))
 216         except OSError as e:
 217           if e.errno != errno.EEXIST:
 218             raise
 219         shutil.copy(self._record_file.name, self._output_file)
 220
 221   def Close(self):
 222     """Closes logcat recording file.
 223
 224     Should be called when finished using the logcat monitor.
 225     """
 226     with self._record_file_lock:
 227       if self._record_file:
 228         self._record_file.close()
 229         self._record_file = None
 230
 231   def __enter__(self):
 232     """Starts the logcat monitor."""
 233     self.Start()
 234     return self
 235
 236   def __exit__(self, exc_type, exc_val, exc_tb):
 237     """Stops the logcat monitor."""
 238     self.Stop()
 239
 240   def __del__(self):
 241     """Closes logcat recording file in case |Close| was never called."""
 242     with self._record_file_lock:
 243       if self._record_file:
 244         logger.warning(
 245             'Need to call |Close| on the logcat monitor when done!')
 246         self._record_file.close()
 247
 248   @property
 249   def adb(self):
 250     return self._adb
 251
 252
 253 class LogcatMonitorCommandError(device_errors.CommandFailedError):
 254   """Exception for errors with logcat monitor commands."""
 255   pass