1# Lint as: python2, python3 2# Copyright (c) 2012 The Chromium OS Authors. All rights reserved. 3# Use of this source code is governed by a BSD-style license that can be 4# found in the LICENSE file. 5 6from __future__ import absolute_import 7from __future__ import division 8from __future__ import print_function 9 10import abc, logging, os, re, time 11from six.moves import range 12import subprocess 13 14import common 15 16from autotest_lib.client.bin import utils 17from autotest_lib.client.common_lib import error 18from autotest_lib.client.cros.constants import CLEANUP_LOGS_PAUSED_FILE 19 20 21def strip_timestamp(msg): 22 """ 23 Strips timestamps and PIDs from a syslog message to facilitate 24 failure reason aggregation when this message is used as an autotest 25 exception text. 26 """ 27 kernel = re.search(r' kernel: \[ *\d+.\d+\] (.*)$', msg) 28 if kernel: 29 return 'kernel: ' + kernel.group(1) 30 31 user = re.match(r'[^a-z]+ [^ ]* ([^\[ ]+)(?:\[.*\])?(: .*)$', msg) 32 if user: 33 return user.group(1) + user.group(2) 34 35 logging.warning('Could not parse syslog message: ' + msg) 36 return msg 37 38 39def extract_kernel_timestamp(msg): 40 """Extract a timestmap that appears in kernel log messages and looks 41 like this: 42 ... kernel: [78791.721832] ... 43 44 Returns: 45 The timestamp as float in seconds since last boot. 46 """ 47 48 match = re.search('\[\s*([0-9]+\.[0-9]+)\] ', msg) 49 if match: 50 return float(match.group(1)) 51 raise error.TestError('Could not extract timestamp from message: ' + msg) 52 53 54class AbstractLogReader(object): 55 56 def __init__(self): 57 self._start_line = 1 58 59 @abc.abstractmethod 60 def read_all_logs(self): 61 """Read all content from log files. 62 63 Generator function. 64 Return an iterator on the content of files. 65 66 This generator can peek a line once (and only once!) by using 67 .send(offset). Must iterate over the peeked line before you can 68 peek again. 69 """ 70 pass 71 72 def set_start_by_regexp(self, index, regexp): 73 """Set the start of logs based on a regular expression. 74 75 @param index: line matching regexp to start at, earliest log at 0. 76 Negative numbers indicate matches since end of log. 77 78 @return True if a matching line was found, false otherwise 79 """ 80 regexp_compiled = re.compile(regexp) 81 starts = [] 82 line_number = 1 83 self._start_line = 1 84 for line in self.read_all_logs(): 85 if regexp_compiled.search(line): 86 starts.append(line_number) 87 line_number += 1 88 if index < -len(starts): 89 self._start_line = 1 90 return False 91 elif index >= len(starts): 92 self._start_line = line_number 93 else: 94 self._start_line = starts[index] 95 return True 96 97 98 def set_start_by_reboot(self, index): 99 """ Set the start of logs (must be system log) based on reboot. 100 101 @param index: reboot to start at, earliest log at 0. Negative 102 numbers indicate reboots since end of log. 103 104 @return True if the boot message line was found, False otherwise 105 """ 106 # Include a 'kernel' tag to avoid matching boot messages logged by 107 # crosvm: https://crbug.com/817946 108 return self.set_start_by_regexp(index, 109 r'kernel:(.*000\])? Linux version \d') 110 111 112 def set_start_by_current(self, relative=0): 113 """ Set start of logs based on current last line. 114 115 @param relative: line relative to current to start at. 1 means 116 to start the log after this line. 117 """ 118 count = self._start_line + relative 119 for line in self.read_all_logs(): 120 count += 1 121 self._start_line = count 122 123 124 def get_logs(self): 125 """ Get logs since the start line. 126 127 Start line is set by set_start_* functions or 128 since the start of the file if none were called. 129 130 @return string of contents of file since start line. 131 """ 132 logs = [] 133 for line in self.read_all_logs(): 134 logs.append(line) 135 return ''.join(logs) 136 137 138 def can_find(self, string): 139 """ Try to find string in the logs. 140 141 @return boolean indicating if we found the string. 142 """ 143 return string in self.get_logs() 144 145 146 def get_last_msg(self, patterns, retries=0, sleep_seconds=0.2): 147 """Search the logs and return the latest occurrence of a message 148 matching one of the patterns. 149 150 Args: 151 patterns: A regexp or a list of regexps to search the logs with. 152 The function returns as soon as it finds any match to one of 153 the patters, it will not search for the other patterns. 154 retries: Number of times to retry if none of the patterns were 155 found. Default is one attempt. 156 sleep_seconds: Time to sleep between retries. 157 158 Returns: 159 The last occurrence of the first matching pattern. "None" if none 160 of the patterns matched. 161 """ 162 163 if not type(patterns) in (list, tuple): 164 patterns = [patterns] 165 166 for retry in range(retries + 1): 167 for pattern in patterns: 168 regexp_compiled = re.compile(pattern) 169 last_match = None 170 for line in self.read_all_logs(): 171 if regexp_compiled.search(line): 172 last_match = line 173 if last_match: 174 return last_match 175 time.sleep(sleep_seconds) 176 177 return None 178 179 180class LogRotationPauser(object): 181 """ 182 Class to control when logs are rotated from either server or client. 183 184 Assumes all setting of CLEANUP_LOGS_PAUSED_FILE is done by this class 185 and that all calls to begin and end are properly 186 nested. For instance, [ a.begin(), b.begin(), b.end(), a.end() ] is 187 supported, but [ a.begin(), b.begin(), a.end(), b.end() ] is not. 188 We do support redundant calls to the same class, such as 189 [ a.begin(), a.begin(), a.end() ]. 190 """ 191 def __init__(self, host=None): 192 self._host = host 193 self._begun = False 194 self._is_nested = True 195 196 197 def _run(self, command, *args, **dargs): 198 if self._host: 199 return self._host.run(command, *args, **dargs).exit_status 200 else: 201 return utils.system(command, *args, **dargs) 202 203 204 def begin(self): 205 """Make sure that log rotation is disabled.""" 206 if self._begun: 207 return 208 self._is_nested = (self._run(('[ -r %s ]' % 209 CLEANUP_LOGS_PAUSED_FILE), 210 ignore_status=True) == 0) 211 if self._is_nested: 212 logging.info('File %s was already present' % 213 CLEANUP_LOGS_PAUSED_FILE) 214 else: 215 self._run('touch ' + CLEANUP_LOGS_PAUSED_FILE) 216 self._begun = True 217 218 219 def end(self): 220 assert self._begun 221 if not self._is_nested: 222 self._run('rm -f ' + CLEANUP_LOGS_PAUSED_FILE) 223 else: 224 logging.info('Leaving existing %s file' % CLEANUP_LOGS_PAUSED_FILE) 225 self._begun = False 226 227 228class LogReader(AbstractLogReader): 229 """Class to read traditional text log files. 230 231 Be default reads all logs from /var/log/messages. 232 """ 233 234 def __init__(self, filename='/var/log/messages', include_rotated_logs=True): 235 AbstractLogReader.__init__(self) 236 self._filename = filename 237 self._include_rotated_logs = include_rotated_logs 238 if not os.path.exists(CLEANUP_LOGS_PAUSED_FILE): 239 raise error.TestError('LogReader created without ' + 240 CLEANUP_LOGS_PAUSED_FILE) 241 242 def read_all_logs(self): 243 log_files = [] 244 line_number = 0 245 if self._include_rotated_logs: 246 log_files.extend(utils.system_output( 247 'ls -tr1 %s.*' % self._filename, 248 ignore_status=True).splitlines()) 249 log_files.append(self._filename) 250 for log_file in log_files: 251 f = open(log_file) 252 for line in f: 253 line_number += 1 254 if line_number < self._start_line: 255 continue 256 peek = yield line 257 if peek: 258 buf = [next(f) for _ in range(peek)] 259 yield buf[-1] 260 while buf: 261 yield buf.pop(0) 262 f.close() 263 264 265class SystemLogReader(AbstractLogReader): 266 """A class to read logs stored in plaintexts using croslog command 267 """ 268 269 def read_all_logs(self): 270 proc = subprocess.Popen(['croslog'], stdout=subprocess.PIPE) 271 line_number = 0 272 for line in proc.stdout: 273 line_number += 1 274 if line_number < self._start_line: 275 continue 276 yield line 277 proc.terminate() 278 279 280class JournalLogReader(AbstractLogReader): 281 """A class to read logs stored by systemd-journald. 282 """ 283 284 def read_all_logs(self): 285 proc = subprocess.Popen(['journalctl'], stdout=subprocess.PIPE) 286 line_number = 0 287 for line in proc.stdout: 288 line_number += 1 289 if line_number < self._start_line: 290 continue 291 yield line 292 proc.terminate() 293 294 295class ContinuousLogReader(AbstractLogReader): 296 """Reads log file from where it left over last time. 297 298 Useful when reading a growing log file. 299 """ 300 def __init__(self, filename): 301 self._filename = filename 302 # Keeps file offset of last read. 303 self._last_pos = 0 304 305 def read_all_logs(self): 306 try: 307 with open(self._filename, 'r') as f: 308 f.seek(self._last_pos) 309 for line in f: 310 yield line 311 # Notice that _last_pos is recorded only if all lines in the file is 312 # read up. Maybe put this into a context manager so it's always 313 # recorded if needed. 314 self._last_pos = f.tell() 315 except IOError: 316 logging.error('Could not read log file %s', self._filename) 317 318 319def make_system_log_reader(): 320 """Create a system log reader. 321 322 This will create SystemLogReader(). JournalLogReader() or LogReader() depending on 323 whether the system is configured with systemd. 324 """ 325 if os.path.exists("/usr/sbin/croslog"): 326 return SystemLogReader() 327 elif os.path.exists("/var/log/journal"): 328 return JournalLogReader() 329 else: 330 return LogReader() 331