ioftools / 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(ireconf_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() 