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