logcat_monitor.py revision a0e5c0de428e9dea6d07dd57c5594fb1f1c17c20 
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
7import errno
8import logging
9import os
10import re
11import shutil
12import tempfile
13import threading
14import time
15
16from devil.android import decorators
17from devil.android import device_errors
18from devil.android.sdk import adb_wrapper
19from devil.utils import reraiser_thread
20
21logger = logging.getLogger(__name__)
22
23
24class 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
253class LogcatMonitorCommandError(device_errors.CommandFailedError):
254  """Exception for errors with logcat monitor commands."""
255  pass
256