# Copyright (c) 2012 The Chromium OS Authors. All rights reserved. # Use of this source code is governed by a BSD-style license that can be # found in the LICENSE file. import abc, logging, os, re, time import subprocess import common from autotest_lib.client.bin import utils from autotest_lib.client.common_lib import error from constants import CLEANUP_LOGS_PAUSED_FILE def strip_timestamp(msg): """ Strips timestamps and PIDs from a syslog message to facilitate failure reason aggregation when this message is used as an autotest exception text. """ kernel = re.search(r' kernel: \[ *\d+.\d+\] (.*)$', msg) if kernel: return 'kernel: ' + kernel.group(1) user = re.match(r'[^a-z]+ [^ ]* ([^\[ ]+)(?:\[.*\])?(: .*)$', msg) if user: return user.group(1) + user.group(2) logging.warning('Could not parse syslog message: ' + msg) return msg def extract_kernel_timestamp(msg): """Extract a timestmap that appears in kernel log messages and looks like this: ... kernel: [78791.721832] ... Returns: The timestamp as float in seconds since last boot. """ match = re.search('\[\s*([0-9]+\.[0-9]+)\] ', msg) if match: return float(match.group(1)) raise error.TestError('Could not extract timestamp from message: ' + msg) class AbstractLogReader(object): def __init__(self): self._start_line = 1 @abc.abstractmethod def read_all_logs(self): """Read all content from log files. Generator function. Return an iterator on the content of files. This generator can peek a line once (and only once!) by using .send(offset). Must iterate over the peeked line before you can peek again. """ pass def set_start_by_regexp(self, index, regexp): """Set the start of logs based on a regular expression. @param index: line matching regexp to start at, earliest log at 0. Negative numbers indicate matches since end of log. """ regexp_compiled = re.compile(regexp) starts = [] line_number = 1 self._start_line = 1 for line in self.read_all_logs(): if regexp_compiled.match(line): starts.append(line_number) line_number += 1 if index < -len(starts): self._start_line = 1 elif index >= len(starts): self._start_line = line_number else: self._start_line = starts[index] def set_start_by_reboot(self, index): """ Set the start of logs (must be system log) based on reboot. @param index: reboot to start at, earliest log at 0. Negative numbers indicate reboots since end of log. """ # Include a 'kernel' tag to avoid matching boot messages logged by # crosvm: https://crbug.com/817946 return self.set_start_by_regexp(index, r'kernel:.*000\] Linux version \d') def set_start_by_current(self, relative=0): """ Set start of logs based on current last line. @param relative: line relative to current to start at. 1 means to start the log after this line. """ count = self._start_line + relative for line in self.read_all_logs(): count += 1 self._start_line = count def get_logs(self): """ Get logs since the start line. Start line is set by set_start_* functions or since the start of the file if none were called. @return string of contents of file since start line. """ logs = [] for line in self.read_all_logs(): logs.append(line) return ''.join(logs) def can_find(self, string): """ Try to find string in the logs. @return boolean indicating if we found the string. """ return string in self.get_logs() def get_last_msg(self, patterns, retries=0, sleep_seconds=0.2): """Search the logs and return the latest occurrence of a message matching one of the patterns. Args: patterns: A regexp or a list of regexps to search the logs with. The function returns as soon as it finds any match to one of the patters, it will not search for the other patterns. retries: Number of times to retry if none of the patterns were found. Default is one attempt. sleep_seconds: Time to sleep between retries. Returns: The last occurrence of the first matching pattern. "None" if none of the patterns matched. """ if not type(patterns) in (list, tuple): patterns = [patterns] for retry in xrange(retries + 1): for pattern in patterns: regexp_compiled = re.compile(pattern) last_match = None for line in self.read_all_logs(): if regexp_compiled.search(line): last_match = line if last_match: return last_match time.sleep(sleep_seconds) return None class LogRotationPauser(object): """ Class to control when logs are rotated from either server or client. Assumes all setting of CLEANUP_LOGS_PAUSED_FILE is done by this class and that all calls to begin and end are properly nested. For instance, [ a.begin(), b.begin(), b.end(), a.end() ] is supported, but [ a.begin(), b.begin(), a.end(), b.end() ] is not. We do support redundant calls to the same class, such as [ a.begin(), a.begin(), a.end() ]. """ def __init__(self, host=None): self._host = host self._begun = False self._is_nested = True def _run(self, command, *args, **dargs): if self._host: return self._host.run(command, *args, **dargs).exit_status else: return utils.system(command, *args, **dargs) def begin(self): """Make sure that log rotation is disabled.""" if self._begun: return self._is_nested = (self._run(('[ -r %s ]' % CLEANUP_LOGS_PAUSED_FILE), ignore_status=True) == 0) if self._is_nested: logging.info('File %s was already present' % CLEANUP_LOGS_PAUSED_FILE) else: self._run('touch ' + CLEANUP_LOGS_PAUSED_FILE) self._begun = True def end(self): assert self._begun if not self._is_nested: self._run('rm -f ' + CLEANUP_LOGS_PAUSED_FILE) else: logging.info('Leaving existing %s file' % CLEANUP_LOGS_PAUSED_FILE) self._begun = False class LogReader(AbstractLogReader): """Class to read traditional text log files. Be default reads all logs from /var/log/messages. """ def __init__(self, filename='/var/log/messages', include_rotated_logs=True): AbstractLogReader.__init__(self) self._filename = filename self._include_rotated_logs = include_rotated_logs if not os.path.exists(CLEANUP_LOGS_PAUSED_FILE): raise error.TestError('LogReader created without ' + CLEANUP_LOGS_PAUSED_FILE) def read_all_logs(self): log_files = [] line_number = 0 if self._include_rotated_logs: log_files.extend(utils.system_output( 'ls -tr1 %s.*' % self._filename, ignore_status=True).splitlines()) log_files.append(self._filename) for log_file in log_files: f = open(log_file) for line in f: line_number += 1 if line_number < self._start_line: continue peek = yield line if peek: buf = [f.next() for _ in xrange(peek)] yield buf[-1] while buf: yield buf.pop(0) f.close() class JournalLogReader(AbstractLogReader): """A class to read logs stored by systemd-journald. """ def read_all_logs(self): proc = subprocess.Popen(['journalctl'], stdout=subprocess.PIPE) line_number = 0 for line in proc.stdout: line_number += 1 if line_number < self._start_line: continue yield line proc.terminate() class ContinuousLogReader(AbstractLogReader): """Reads log file from where it left over last time. Useful when reading a growing log file. """ def __init__(self, filename): self._filename = filename # Keeps file offset of last read. self._last_pos = 0 def read_all_logs(self): try: with open(self._filename, 'r') as f: f.seek(self._last_pos) for line in f: yield line # Notice that _last_pos is recorded only if all lines in the file is # read up. Maybe put this into a context manager so it's always # recorded if needed. self._last_pos = f.tell() except IOError: logging.error('Could not read log file %s', self._filename) def make_system_log_reader(): """Create a system log reader. This will create JournalLogReader() or LogReader() depending on whether the system is configured with systemd. """ if os.path.exists("/var/log/journal"): return JournalLogReader() else: return LogReader()