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