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
5import collections
6import logging
7import os
8import re
9import StringIO
10
11IW_REMOTE_EVENT_LOG_FILE_NAME = 'iw_event.log'
12
13LogEntry = collections.namedtuple('LogEntry', ['timestamp',
14                                               'interface',
15                                               'message'])
16
17class 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