# 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()