1# Lint as: python2, python3 2# Copyright (c) 2014 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 6import collections 7import logging 8import os 9import re 10import six 11 12IW_REMOTE_EVENT_LOG_FILE_NAME = 'iw_event.log' 13 14LogEntry = collections.namedtuple('LogEntry', ['timestamp', 15 'interface', 16 'message']) 17 18class IwEventLogger(object): 19 """Context enclosing the use of iw event logger.""" 20 def __init__(self, host, command_iw, local_file): 21 self._host = host 22 self._command_iw = command_iw 23 self._iw_event_log_path = os.path.join(self._host.get_tmp_dir(), 24 IW_REMOTE_EVENT_LOG_FILE_NAME) 25 self._local_file = local_file 26 self._pid = None 27 self._start_time = 0 28 29 30 def __enter__(self): 31 return self 32 33 34 def __exit__(self, exception, value, traceback): 35 self.stop() 36 37 38 def _check_message_for_disconnect(self, message): 39 """Check log message for disconnect event. 40 41 This function checks log messages for signs the connection was 42 terminated. 43 44 @param: message String message to check for disconnect event. 45 46 @returns True if the log message is a disconnect event, false otherwise. 47 48 """ 49 return (message.startswith('disconnected') or 50 message.startswith('Deauthenticated') or 51 message == 'Previous authentication no longer valid') 52 53 54 @property 55 def local_file(self): 56 """@return string local host path for log file.""" 57 return self._local_file 58 59 60 def start(self): 61 """Start event logger. 62 63 This function will start iw event process in remote host, and redirect 64 output to a temporary file in remote host. 65 66 """ 67 command = 'nohup %s event -t </dev/null >%s 2>&1 & echo $!' % ( 68 self._command_iw, self._iw_event_log_path) 69 command += ';date +%s' 70 out_lines = self._host.run(command).stdout.splitlines() 71 self._pid = int(out_lines[0]) 72 self._start_time = float(out_lines[1]) 73 74 75 def stop(self): 76 """Stop event logger. 77 78 This function will kill iw event process, and copy the log file from 79 remote to local. 80 81 """ 82 if self._pid is None: 83 return 84 # Kill iw event process 85 self._host.run('kill %d' % self._pid, ignore_status=True) 86 self._pid = None 87 # Copy iw event log file from remote host 88 self._host.get_file(self._iw_event_log_path, self._local_file) 89 logging.info('iw event log saved to %s', self._local_file) 90 91 92 def get_log_entries(self): 93 """Parse local log file and yield LogEntry named tuples. 94 95 This function will parse the iw event log and return individual 96 LogEntry tuples for each parsed line. 97 Here are example of lines to be parsed: 98 1393961008.058711: wlan0 (phy #0): scan started 99 1393961019.758599: wlan0 (phy #0): connected to 04:f0:21:03:7d:bd 100 101 @yields LogEntry tuples for each log entry. 102 103 """ 104 iw_log = self._host.run('cat %s' % self._iw_event_log_path).stdout 105 iw_log_file = six.StringIO(iw_log) 106 for line in iw_log_file.readlines(): 107 parse_line = re.match('\s*(\d+).(\d+): (\w[^:]*): (\w.*)', line) 108 if parse_line: 109 time_integer = parse_line.group(1) 110 time_decimal = parse_line.group(2) 111 timestamp = float('%s.%s' % (time_integer, time_decimal)) 112 yield LogEntry(timestamp=timestamp, 113 interface=parse_line.group(3), 114 message=parse_line.group(4)) 115 116 117 def get_reassociation_time(self): 118 """Return reassociation time. 119 120 This function will search the iw event log to determine the time it 121 takes from start of reassociation request to being connected. Start of 122 reassociation request could be either an attempt to scan or to 123 disconnect. Assume the one that appeared in the log first is the start 124 of the reassociation request. 125 126 @returns float number of seconds it take from start of reassociation 127 request to being connected. Return None if unable to determine 128 the time based on the log. 129 130 """ 131 start_time = None 132 end_time = None 133 # Figure out the time when reassociation process started and the time 134 # when client is connected. 135 for entry in self.get_log_entries(): 136 if (entry.message.startswith('scan started') and 137 start_time is None): 138 start_time = entry.timestamp 139 # Newer wpa_supplicant would attempt to disconnect then reconnect 140 # without scanning. So if no scan event is detected before the 141 # disconnect attempt, we'll assume the disconnect attempt is the 142 # beginning of the reassociate attempt. 143 if (self._check_message_for_disconnect(entry.message) and 144 start_time is None): 145 start_time = entry.timestamp 146 if entry.message.startswith('connected'): 147 if start_time is None: 148 return None 149 end_time = entry.timestamp 150 break; 151 else: 152 return None 153 return end_time - start_time 154 155 156 def get_disconnect_count(self): 157 """Return number of times the system disconnected during the log. 158 159 This function will search the iw event log to determine how many 160 times the "disconnect" and "Deauthenticated" messages appear. 161 162 @returns int number of times the system disconnected in the logs. 163 164 """ 165 count = 0 166 for entry in self.get_log_entries(): 167 if self._check_message_for_disconnect(entry.message): 168 count += 1 169 return count 170 171 172 def get_time_to_disconnected(self): 173 """Return disconnect time. 174 175 This function will search the iw event log to determine the number of 176 seconds between the time iw event logger is started to the time the 177 first "disconnected" or "Deauthenticated" event is received. 178 179 @return float number of seconds between the time iw event logger is 180 started to the time "disconnected" or "Deauthenticated" event 181 is received. Return None if no "disconnected" or 182 "Deauthenticated" event is detected in the iw event log. 183 """ 184 for entry in self.get_log_entries(): 185 if self._check_message_for_disconnect(entry.message): 186 return entry.timestamp - self._start_time 187 return None 188