1# Lint as: python2, python3 2# Copyright 2021 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"""Helper class to manage bluetooth logs""" 6 7from datetime import datetime 8import logging 9import os 10import re 11import subprocess 12import time 13 14 15SYSLOG_PATH = '/var/log/messages' 16 17 18class LogManager(object): 19 """The LogManager class helps to collect logs without a listening thread""" 20 21 DEFAULT_ENCODING = 'utf-8' 22 23 class LoggingException(Exception): 24 """A stub exception class for LogManager class.""" 25 pass 26 27 def __init__(self, log_path=SYSLOG_PATH, raise_missing=False): 28 """Initialize log manager object 29 30 @param log_path: string path to log file to manage 31 @param raise_missing: raise an exception if the log file is missing 32 33 @raises: LogManager.LoggingException on non-existent log file 34 """ 35 if not os.path.isfile(log_path): 36 msg = 'Requested log file {} does not exist'.format(log_path) 37 if raise_missing: 38 raise LogManager.LoggingException(msg) 39 else: 40 self._LogErrorToSyslog(msg) 41 42 self.log_path = log_path 43 44 self.ResetLogMarker() 45 self._bin_log_contents = [] 46 47 def _LogErrorToSyslog(self, message): 48 """Create a new syslog file and add a message to syslog.""" 49 subprocess.call(['reload', 'syslog']) 50 subprocess.call(['logger', message]) 51 52 def _GetSize(self): 53 """Get the size of the log""" 54 try: 55 return os.path.getsize(self.log_path) 56 except Exception as e: 57 logging.error('Failed to get log size: {}'.format(e)) 58 return 0 59 60 def ResetLogMarker(self, now_size=None): 61 """Reset the start-of-log marker for later comparison""" 62 if now_size is None: 63 now_size = self._GetSize() 64 self.initial_log_size = now_size 65 66 def StartRecording(self): 67 """Mark initial log size for later comparison""" 68 69 self._bin_log_contents = [] 70 71 def StopRecording(self): 72 """Gather the logs since StartRecording was called 73 74 @raises: LogManager.LoggingException if: 75 - Log file disappeared since StartRecording was called 76 - Log file is smaller than when logging began 77 - StartRecording was never called 78 """ 79 initial_size = self.initial_log_size 80 now_size = self._GetSize() 81 82 if not os.path.isfile(self.log_path): 83 msg = 'File {} disappeared unexpectedly'.format(self.log_path) 84 raise LogManager.LoggingException(msg) 85 86 if now_size < initial_size: 87 msg = 'Log became smaller unexpectedly' 88 raise LogManager.LoggingException(msg) 89 90 with open(self.log_path, 'rb') as mf: 91 # Skip to the point where we started recording 92 mf.seek(self.initial_log_size) 93 94 readsize = now_size - self.initial_log_size 95 self._bin_log_contents = mf.read(readsize).split(b'\n') 96 97 # Re-set start of log marker 98 self.ResetLogMarker(now_size) 99 100 def LogContains(self, search_str): 101 """Performs simple string checking on each line from the collected log 102 103 @param search_str: string to be located within log contents. This arg 104 is expected to not span between lines in the logs 105 106 @returns: True if search_str was located in the collected log contents, 107 False otherwise 108 """ 109 pattern = re.compile(search_str.encode(self.DEFAULT_ENCODING)) 110 for line in self._bin_log_contents: 111 if pattern.search(line): 112 return True 113 114 return False 115 116 def FilterOut(self, rm_reg_exp): 117 """Remove lines with specified pattern from the log file 118 119 @param rm_reg_exp: regular expression of the lines to be removed 120 """ 121 # If log_path doesn't exist, there's nothing to do 122 if not os.path.isfile(self.log_path): 123 return 124 125 rm_line_cnt = 0 126 initial_size = self._GetSize() 127 rm_pattern = re.compile(rm_reg_exp.encode(self.DEFAULT_ENCODING)) 128 129 with open(self.log_path, 'rb+') as mf: 130 lines = mf.readlines() 131 mf.seek(0) 132 for line in lines: 133 if rm_pattern.search(line): 134 rm_line_cnt += 1 135 else: 136 mf.write(line) 137 mf.truncate() 138 139 # Some tracebacks point out here causing /var/log/messages missing but 140 # we don't have many clues. Adding a check and logs here. 141 if not os.path.isfile(self.log_path): 142 msg = '{} does not exist after FilterOut'.format(self.log_path) 143 logging.warning(msg) 144 self._LogErrorToSyslog(msg) 145 146 new_size = self._GetSize() 147 rm_byte = initial_size - new_size 148 logging.info('Removed number of line: %d, Reduced log size: %d byte', 149 rm_line_cnt, rm_byte) 150 151 # Note the new size of the log 152 self.ResetLogMarker(new_size) 153 154 155class InterleaveLogger(LogManager): 156 """LogManager class that focus on interleave scan""" 157 158 # Example bluetooth kernel log: 159 # "2020-11-23T07:52:31.395941Z DEBUG kernel: [ 6469.811135] Bluetooth: " 160 # "cancel_interleave_scan() hci0: cancelling interleave scan" 161 KERNEL_LOG_PATTERN = ('([^ ]+) DEBUG kernel: \[.*\] Bluetooth: ' 162 '{FUNCTION}\(\) hci0: {LOG_STR}') 163 STATE_PATTERN = KERNEL_LOG_PATTERN.format( 164 FUNCTION='hci_req_add_le_interleaved_scan', 165 LOG_STR='next state: (.+)') 166 CANCEL_PATTERN = KERNEL_LOG_PATTERN.format( 167 FUNCTION='cancel_interleave_scan', 168 LOG_STR='cancelling interleave scan') 169 SYSTIME_LENGTH = len('2020-12-18T00:11:22.345678') 170 171 def __init__(self): 172 """ Initialize object 173 """ 174 self.reset() 175 self.state_pattern = re.compile( 176 self.STATE_PATTERN.encode(self.DEFAULT_ENCODING)) 177 self.cancel_pattern = re.compile( 178 self.CANCEL_PATTERN.encode(self.DEFAULT_ENCODING)) 179 super(InterleaveLogger, self).__init__() 180 181 def reset(self): 182 """ Clear data between each log collection attempt 183 """ 184 self.records = [] 185 self.cancel_events = [] 186 187 def StartRecording(self): 188 """ Reset the previous data and start recording. 189 """ 190 self.reset() 191 super(InterleaveLogger, self).ResetLogMarker() 192 super(InterleaveLogger, self).StartRecording() 193 194 def StopRecording(self): 195 """ Stop recording and parse logs 196 The following data will be set after this call 197 198 - self.records: a dictionary where each item is a record of 199 interleave |state| and the |time| the state starts. 200 |state| could be {'no filter', 'allowlist'} 201 |time| is system time in sec 202 203 - self.cancel_events: a list of |time| when a interleave cancel 204 event log was found 205 |time| is system time in sec 206 207 @returns: True if StopRecording success, False otherwise 208 209 """ 210 try: 211 super(InterleaveLogger, self).StopRecording() 212 except Exception as e: 213 logging.error(e) 214 return False 215 216 success = True 217 218 def sys_time_to_timestamp(time_str): 219 """ Return timestamp of time_str """ 220 221 # This is to remove the suffix of time string, in some cases the 222 # time string ends with an extra 'Z', in other cases, the string 223 # ends with time zone (ex. '+08:00') 224 time_str = time_str[:self.SYSTIME_LENGTH] 225 226 try: 227 dt = datetime.strptime(time_str, "%Y-%m-%dT%H:%M:%S.%f") 228 except Exception as e: 229 logging.error(e) 230 success = False 231 return 0 232 233 return time.mktime(dt.timetuple()) + dt.microsecond * (10**-6) 234 235 for line in self._bin_log_contents: 236 line = line.strip().replace(b'\\r\\n', b'') 237 state_pattern = self.state_pattern.search(line) 238 cancel_pattern = self.cancel_pattern.search(line) 239 240 if cancel_pattern: 241 time_str = cancel_pattern.groups()[0].decode( 242 self.DEFAULT_ENCODING) 243 time_sec = sys_time_to_timestamp(time_str) 244 self.cancel_events.append(time_sec) 245 246 if state_pattern: 247 time_str, state = [ 248 x.decode(self.DEFAULT_ENCODING) 249 for x in state_pattern.groups() 250 ] 251 time_sec = sys_time_to_timestamp(time_str) 252 self.records.append({'time': time_sec, 'state': state}) 253 254 return success 255