Statistics
| Branch: | Revision:

iof-tools / log_parser.py @ 3d8e3339

History | View | Annotate | Download (8.41 KB)

1
#!/usr/bin/env python3
2
import argparse
3
import datetime
4
import re
5
from collections import defaultdict, Counter
6

    
7

    
8
log_types = ['FATAL', 'RECONF']
9

    
10

    
11
class WrongLogLine(Exception):
12
    pass
13

    
14

    
15
class WrongFileName(Exception):
16
    pass
17

    
18

    
19
args = None
20
resolution = 1
21

    
22
def print_in_columns(data, width=15, separator=','):
23
    print(separator.join([str(d).ljust(width) for d in data]))
24

    
25

    
26
def to_unixtime(t):
27
    """ note that this does not work if all timestamps are not from the same time zone """
28
    return int((t - datetime.datetime(1970, 1, 1)).total_seconds()*resolution)
29

    
30

    
31
def parse_args():
32
    global args
33
    global resolution
34
    parser = argparse.ArgumentParser()
35
    parser.add_argument('-f', help='the log file', required=True, nargs='*')
36
    parser.add_argument('-v', help='be more verbose', default=False,
37
                        action='store_true')
38
    parser.add_argument('-c', help='Compute convergence delay', default=False,
39
                        action='store_true')
40
    parser.add_argument('-t', help='compute the number of updates generated',
41
                        default=False, action='store_true')
42
    parser.add_argument('-T', help='time resolution (s/decimal/cent/milli)',
43
                        default='SEC',
44
                        choices=['SECS', 'DSEC', 'CSEC', 'MSEC'])
45
    args = parser.parse_args()
46
    if args.T == 'DSEC':
47
        resolution = 10
48
    elif args.T == 'CSEC':
49
        resolution = 100
50
    elif args.T == 'MSEC':
51
        resolution = 1000
52

    
53

    
54
def parse_line(line, verb):
55
    split_line = line.split()
56
    try:
57
        date_time = split_line[0] + " " + split_line[1]
58
        log_time = to_unixtime(datetime.datetime.strptime(date_time, '%Y-%m-%d %H:%M:%S.%f'))
59
    except (ValueError, IndexError):
60
        if verb:
61
            print("Ignoring this log line:", line)
62
        raise WrongLogLine
63
    log_type = ''.join(split_line[2][1:-1])
64
    if log_type not in log_types:
65
        if verb:
66
            print("Ignoring this log line:", line)
67
        raise WrongLogLine
68
    try:
69
        log_body = line.split('{')[1].split('}')[0]
70
    except IndexError:
71
        if verb:
72
            print("Ignoring this log line:", line)
73
        raise WrongLogLine
74
    log_fields = log_body.split(',')
75
    log_dict = {}
76
    for k, v in [x.split(':') for x in log_fields]:
77
        log_dict[k.strip()] = v.strip()
78
    if log_dict['type'] == 'RECONF':
79
        return log_time, log_dict, True
80
    return log_time, log_dict, False
81

    
82

    
83
def parse_file(fname):
84
    try:
85
        AS_number = int(fname.split('_')[2][:-4]) + 1
86
    except (ValueError, ):
87
        print('Invalid file name:', fname)
88
        print('I expect a file name of the form log_h_X.log '
89
              'where X is an AS number')
90
        exit()
91
    data = []
92
    reconf_time = None
93
    with open(fname, 'r') as f:
94
        for line in f:
95
            try:
96
                t, d, reconf = parse_line(line, args.v)
97
                if reconf:
98
                    reconf_time = t
99
            except WrongLogLine:
100
                continue
101
            data.append([t, d])
102
    return AS_number, data, reconf_time
103

    
104

    
105
def compute_convergence_time(data):
106
    convergence_time = ''
107
    best_path = ''
108
    first_log = None
109
    for (t, d) in data:
110
        if not first_log:
111
            first_log = t
112
        if 'processing' in d and d['processing'] == 'NEW_BEST_PATH':
113
            convergence_time = t
114
            best_path = d['actual_best_path']
115
        if 'processing' in d and (d['processing'] == 'REMOVED_REPLACED_PATH'
116
                                  or d['processing'] == 'NEW_PATH'):
117
            if d['actual_best_path'] == 'NONE':
118
                convergence_time = ''
119
                best_path = ''
120
            elif d['actual_best_path'] != best_path:
121
                best_path = d['actual_best_path']
122
                convergence_time = t
123
        if args.v and 'processing' in d:
124
            print(t, d)
125
    if convergence_time:
126
        return convergence_time, first_log
127
    return None, None
128

    
129

    
130
def compute_updates_number(data):
131
    updates = Counter()
132
    min_secs = data[0][0]
133
    max_secs = data[-1][0]
134
    for (t, d) in data:
135
        if d['type'] == 'UPDATE_TX':
136
            updates[t] += 1
137
    return updates, min_secs, max_secs
138

    
139

    
140
def main():
141
    parse_args()
142
    AS_data = defaultdict(dict)
143
    reconf_time = None
144
    last_reconf = None
145
    for fname in args.f:
146
        AS_number, data, reconf_temp = parse_file(fname)
147
        if reconf_temp:
148
            reconf_time = reconf_temp
149
        if args.c:
150
            convergence_time, first_log = compute_convergence_time(data)
151
            AS_data[AS_number]['convergence_time'] = convergence_time
152
            AS_data[AS_number]['first_log'] = first_log
153
        if args.t:
154
            updates, min_secs, max_secs = compute_updates_number(data)
155
            AS_data[AS_number]['updates'] = updates
156
            AS_data[AS_number]['min_secs'] = min_secs
157
            AS_data[AS_number]['max_secs'] = max_secs
158

    
159
    if args.c:
160
        print_in_columns(['AS', 'convergence_time'])
161
        for AS_number, c_data in sorted(AS_data.items()):
162
            if c_data['convergence_time']:
163
                print_line = []
164
                if reconf_time:
165
                    print_line = [AS_number, (c_data['convergence_time'] -
166
                                  reconf_time)]
167
                else:
168
                    print_line = [AS_number, (c_data['convergence_time'] -
169
                                  c_data['first_log'])]
170
                    # there can be negative value for convergence, that
171
                    # happen when a node is not affected by the change
172
                    # (it converged before the RECONF)
173
            else:
174
                print_line = [AS_number, 1000000]  # a big number to show that
175
                                                   # it did not converge
176
            print_in_columns(print_line)
177
        print('\n\n')
178

    
179
        print_in_columns(['time', 'converged_ASes', 'non_converged_ASes', 'total_nodes'])
180
        convergence_time = []
181
        never_converged_ASes = 0
182
        non_reconfigured_ASes = 0
183
        last_reconf = 0
184
        for AS_number, c_data in sorted(AS_data.items()):
185
            if c_data['convergence_time']:
186
                if reconf_time:
187
                    # convergence_time is a relative time
188
                    conv_time = (c_data['convergence_time'] - reconf_time)
189
                else:
190
                    conv_time = (c_data['convergence_time'] - c_data['first_log'])
191
                if conv_time >= 0:
192
                    convergence_time.append((AS_number, conv_time))
193
                    if c_data['convergence_time'] > last_reconf:
194
                        last_reconf = c_data['convergence_time']
195
                else:
196
                    non_reconfigured_ASes += 1
197
            else:
198
                never_converged_ASes += 1
199
        tot_nodes = len(AS_data)
200
        max_time = max([x[1] for x in convergence_time])
201
        for i in range(max_time + 1):
202
            conv_ASes = 0
203
            for (AS, t) in convergence_time:
204
                if i >= t:
205
                    conv_ASes += 1
206
            print_in_columns([i, conv_ASes + non_reconfigured_ASes,
207
                              tot_nodes - conv_ASes - non_reconfigured_ASes,
208
                              tot_nodes])
209
        print('\n\n')
210

    
211

    
212
    if args.t:
213
        # here seconds are in unix time
214
        if reconf_time:
215
            reconf_secs = reconf_time
216
        else:
217
            reconf_secs = min([AS_data[x]['min_secs'] for x in AS_data])
218

    
219
        if last_reconf:
220
            end_secs = last_reconf
221
        else:
222
            end_secs = max([AS_data[x]['max_secs'] for x in AS_data])
223

    
224
        print_in_columns(['time'] + ['sum'] + sorted(AS_data.keys()), width=4)
225
        # just a check that we are not leving any number behind
226
        control_total = 0
227
        for i in range(reconf_time, end_secs+1):
228
            print_list = []
229
            tot_udp = 0
230
            for (AS_number, c_data) in sorted(AS_data.items()):
231
                upd = c_data['updates'].get(i, 0)
232
                tot_udp += upd
233
                print_list.append(str(upd))
234
            print_list.insert(0, tot_udp)
235
            print_list.insert(0, str(i-reconf_secs))
236
            print_in_columns(print_list, width=4)
237
            control_total += tot_udp
238
        tot_updates = 0
239
        for (AS_number, c_data) in sorted(AS_data.items()):
240
            for k,v in c_data['updates'].items():
241
                if k >= reconf_time and k < last_reconf + 1:
242
                    tot_updates += v
243
        if (tot_updates != control_total):
244
            print("Error in counting updates")
245

    
246
main()