blob: 07ef59efeb49c5110fa6f707819106095c8317db [file] [log] [blame]
andrewonlab2a6c9342014-10-16 13:40:15 -04001#TopoPerfNext
2#
3#Topology Performance test for ONOS-next
4#
5#andrew@onlab.us
6
7import time
8import sys
9import os
10import re
11
12class TopoPerfNext:
13 def __init__(self):
14 self.default = ''
15
16 def CASE1(self, main):
17 '''
18 ONOS startup sequence
19 '''
andrewonlabe9fb6722014-10-24 12:20:35 -040020 import time
21
andrewonlab2a6c9342014-10-16 13:40:15 -040022 cell_name = main.params['ENV']['cellName']
23
24 git_pull = main.params['GIT']['autoPull']
25 checkout_branch = main.params['GIT']['checkout']
26
27 ONOS1_ip = main.params['CTRL']['ip1']
andrewonlabba44bcf2014-10-16 16:54:41 -040028 ONOS2_ip = main.params['CTRL']['ip2']
29 ONOS3_ip = main.params['CTRL']['ip3']
andrewonlab2a6c9342014-10-16 13:40:15 -040030 MN1_ip = main.params['MN']['ip1']
31 BENCH_ip = main.params['BENCH']['ip']
32
33 main.case("Setting up test environment")
34
35 main.step("Creating cell file")
36 cell_file_result = main.ONOSbench.create_cell_file(
andrewonlabe6745342014-10-17 14:29:13 -040037 BENCH_ip, cell_name, MN1_ip, "onos-core",
andrewonlabba44bcf2014-10-16 16:54:41 -040038 ONOS1_ip, ONOS2_ip, ONOS3_ip)
andrewonlab2a6c9342014-10-16 13:40:15 -040039
40 main.step("Applying cell file to environment")
41 cell_apply_result = main.ONOSbench.set_cell(cell_name)
42 verify_cell_result = main.ONOSbench.verify_cell()
43
44 main.step("Git checkout and pull "+checkout_branch)
45 if git_pull == 'on':
46 checkout_result = \
47 main.ONOSbench.git_checkout(checkout_branch)
48 pull_result = main.ONOSbench.git_pull()
49 else:
50 checkout_result = main.TRUE
51 pull_result = main.TRUE
52 main.log.info("Skipped git checkout and pull")
53
54 main.step("Using mvn clean & install")
andrewonlab8d29f122014-10-22 17:15:04 -040055 #mvn_result = main.ONOSbench.clean_install()
56 mvn_result = main.TRUE
andrewonlab2a6c9342014-10-16 13:40:15 -040057
andrewonlabb1998c52014-11-10 13:31:43 -050058 main.step("Set cell for ONOS cli env")
59 main.ONOS1cli.set_cell(cell_name)
60 main.ONOS2cli.set_cell(cell_name)
61 main.ONOS3cli.set_cell(cell_name)
62
andrewonlab2a6c9342014-10-16 13:40:15 -040063 main.step("Creating ONOS package")
64 package_result = main.ONOSbench.onos_package()
65
66 main.step("Installing ONOS package")
andrewonlabe9fb6722014-10-24 12:20:35 -040067 install1_result = main.ONOSbench.onos_install(node=ONOS1_ip)
68 install2_result = main.ONOSbench.onos_install(node=ONOS2_ip)
69 install3_result = main.ONOSbench.onos_install(node=ONOS3_ip)
andrewonlab2a6c9342014-10-16 13:40:15 -040070
andrewonlabe9fb6722014-10-24 12:20:35 -040071 time.sleep(10)
72
andrewonlab867212a2014-10-22 20:13:38 -040073 main.step("Start onos cli")
andrewonlabe9fb6722014-10-24 12:20:35 -040074 cli1 = main.ONOS1cli.start_onos_cli(ONOS1_ip)
75 cli2 = main.ONOS2cli.start_onos_cli(ONOS2_ip)
76 cli3 = main.ONOS3cli.start_onos_cli(ONOS3_ip)
77
andrewonlab867212a2014-10-22 20:13:38 -040078 main.step("Enable metrics feature")
andrewonlabb1998c52014-11-10 13:31:43 -050079 main.ONOS1cli.feature_install("onos-app-metrics")
80 main.ONOS2cli.feature_install("onos-app-metrics")
81 main.ONOS3cli.feature_install("onos-app-metrics")
andrewonlab867212a2014-10-22 20:13:38 -040082
andrewonlab2a6c9342014-10-16 13:40:15 -040083 utilities.assert_equals(expect=main.TRUE,
84 actual= cell_file_result and cell_apply_result and\
85 verify_cell_result and checkout_result and\
86 pull_result and mvn_result and\
andrewonlabe9fb6722014-10-24 12:20:35 -040087 install1_result and install2_result and\
88 install3_result,
andrewonlab8d29f122014-10-22 17:15:04 -040089 onpass="ONOS started successfully",
90 onfail="Failed to start ONOS")
andrewonlab2a6c9342014-10-16 13:40:15 -040091
andrewonlabba44bcf2014-10-16 16:54:41 -040092 def CASE2(self, main):
93 '''
94 Assign s1 to ONOS1 and measure latency
andrewonlab3a7c3c72014-10-24 17:21:03 -040095
96 There are 4 levels of latency measurements to this test:
97 1) End-to-end measurement: Complete end-to-end measurement
98 from TCP (SYN/ACK) handshake to Graph change
99 2) OFP-to-graph measurement: 'ONOS processing' snippet of
100 measurement from OFP Vendor message to Graph change
101 3) OFP-to-device measurement: 'ONOS processing without
102 graph change' snippet of measurement from OFP vendor
103 message to Device change timestamp
104 4) T0-to-device measurement: Measurement that includes
105 the switch handshake to devices timestamp without
106 the graph view change. (TCP handshake -> Device
107 change)
andrewonlabba44bcf2014-10-16 16:54:41 -0400108 '''
109 import time
andrewonlabe6745342014-10-17 14:29:13 -0400110 import subprocess
111 import json
112 import requests
113 import os
andrewonlabba44bcf2014-10-16 16:54:41 -0400114
115 ONOS1_ip = main.params['CTRL']['ip1']
116 ONOS2_ip = main.params['CTRL']['ip2']
117 ONOS3_ip = main.params['CTRL']['ip3']
andrewonlabe6745342014-10-17 14:29:13 -0400118 ONOS_user = main.params['CTRL']['user']
119
andrewonlabba44bcf2014-10-16 16:54:41 -0400120 default_sw_port = main.params['CTRL']['port1']
121
122 #Number of iterations of case
123 num_iter = main.params['TEST']['numIter']
124
andrewonlab226024e2014-10-24 16:01:32 -0400125 #Timestamp 'keys' for json metrics output.
126 #These are subject to change, hence moved into params
127 deviceTimestamp = main.params['JSON']['deviceTimestamp']
128 graphTimestamp = main.params['JSON']['graphTimestamp']
129
andrewonlab58f7d702014-11-07 13:21:19 -0500130 debug_mode = main.params['TEST']['debugMode']
andrewonlabb1998c52014-11-10 13:31:43 -0500131 onos_log = main.params['TEST']['onosLogFile']
andrewonlab58f7d702014-11-07 13:21:19 -0500132
andrewonlabe5bcef92014-11-06 17:53:20 -0500133 #Threshold for the test
134 threshold_str = main.params['TEST']['singleSwThreshold']
135 threshold_obj = threshold_str.split(",")
136 threshold_min = int(threshold_obj[0])
137 threshold_max = int(threshold_obj[1])
138
andrewonlab226024e2014-10-24 16:01:32 -0400139 #List of switch add latency collected from
140 #all iterations
141 latency_end_to_end_list = []
142 latency_ofp_to_graph_list = []
143 latency_ofp_to_device_list = []
144 latency_t0_to_device_list = []
145
andrewonlabba44bcf2014-10-16 16:54:41 -0400146 #Directory/file to store tshark results
147 tshark_of_output = "/tmp/tshark_of_topo.txt"
148 tshark_tcp_output = "/tmp/tshark_tcp_topo.txt"
149
150 #String to grep in tshark output
151 tshark_tcp_string = "TCP 74 "+default_sw_port
152 tshark_of_string = "OFP 86 Vendor"
andrewonlabe6745342014-10-17 14:29:13 -0400153
154 #Initialize assertion to TRUE
155 assertion = main.TRUE
andrewonlab58f7d702014-11-07 13:21:19 -0500156
157 local_time = time.strftime('%x %X')
andrewonlabb1998c52014-11-10 13:31:43 -0500158 local_time = local_time.replace("/","")
159 local_time = local_time.replace(" ","_")
160 local_time = local_time.replace(":","")
andrewonlab58f7d702014-11-07 13:21:19 -0500161 if debug_mode == 'on':
162 main.ONOS1.tshark_pcap("eth0",
andrewonlabb1998c52014-11-10 13:31:43 -0500163 "/tmp/single_sw_lat_pcap_"+local_time)
164
165 main.log.info("TEST")
andrewonlab58f7d702014-11-07 13:21:19 -0500166
andrewonlabba44bcf2014-10-16 16:54:41 -0400167 main.log.report("Latency of adding one switch")
168
169 for i in range(0, int(num_iter)):
170 main.log.info("Starting tshark capture")
171
172 #* TCP [ACK, SYN] is used as t0_a, the
173 # very first "exchange" between ONOS and
174 # the switch for end-to-end measurement
175 #* OFP [Stats Reply] is used for t0_b
176 # the very last OFP message between ONOS
177 # and the switch for ONOS measurement
178 main.ONOS1.tshark_grep(tshark_tcp_string,
179 tshark_tcp_output)
180 main.ONOS1.tshark_grep(tshark_of_string,
181 tshark_of_output)
182
183 #Wait and ensure tshark is started and
184 #capturing
185 time.sleep(10)
186
187 main.log.info("Assigning s1 to controller")
188
189 main.Mininet1.assign_sw_controller(sw="1",
190 ip1=ONOS1_ip, port1=default_sw_port)
191
192 #Wait and ensure switch is assigned
193 #before stopping tshark
andrewonlab867212a2014-10-22 20:13:38 -0400194 time.sleep(30)
andrewonlab226024e2014-10-24 16:01:32 -0400195
196 main.log.info("Stopping all Tshark processes")
andrewonlabba44bcf2014-10-16 16:54:41 -0400197 main.ONOS1.stop_tshark()
198
andrewonlabe6745342014-10-17 14:29:13 -0400199 #tshark output is saved in ONOS. Use subprocess
200 #to copy over files to TestON for parsing
201 main.log.info("Copying over tshark files")
202
203 #TCP CAPTURE ****
andrewonlab8d29f122014-10-22 17:15:04 -0400204 #Copy the tshark output from ONOS machine to
205 #TestON machine in tshark_tcp_output directory>file
206 os.system("scp "+ONOS_user+"@"+ONOS1_ip+":"+
207 tshark_tcp_output+" /tmp/")
208 tcp_file = open(tshark_tcp_output, 'r')
209 temp_text = tcp_file.readline()
andrewonlabe6745342014-10-17 14:29:13 -0400210 temp_text = temp_text.split(" ")
andrewonlabba44bcf2014-10-16 16:54:41 -0400211
andrewonlabe6745342014-10-17 14:29:13 -0400212 main.log.info("Object read in from TCP capture: "+
213 str(temp_text))
andrewonlab867212a2014-10-22 20:13:38 -0400214 if len(temp_text) > 1:
andrewonlab3a7c3c72014-10-24 17:21:03 -0400215 t0_tcp = float(temp_text[1])*1000.0
andrewonlabe6745342014-10-17 14:29:13 -0400216 else:
217 main.log.error("Tshark output file for TCP"+
218 " returned unexpected results")
219 t0_tcp = 0
220 assertion = main.FALSE
andrewonlab8d29f122014-10-22 17:15:04 -0400221
222 tcp_file.close()
andrewonlabe6745342014-10-17 14:29:13 -0400223 #****************
andrewonlabba44bcf2014-10-16 16:54:41 -0400224
andrewonlabe6745342014-10-17 14:29:13 -0400225 #OF CAPTURE ****
andrewonlab8d29f122014-10-22 17:15:04 -0400226 os.system("scp "+ONOS_user+"@"+ONOS1_ip+":"+
227 tshark_of_output+" /tmp/")
228 of_file = open(tshark_of_output, 'r')
229
230 line_ofp = ""
andrewonlab226024e2014-10-24 16:01:32 -0400231 #Read until last line of file
andrewonlabe6745342014-10-17 14:29:13 -0400232 while True:
andrewonlab8d29f122014-10-22 17:15:04 -0400233 temp_text = of_file.readline()
234 if temp_text !='':
andrewonlabe6745342014-10-17 14:29:13 -0400235 line_ofp = temp_text
236 else:
237 break
238 obj = line_ofp.split(" ")
239
240 main.log.info("Object read in from OFP capture: "+
241 str(line_ofp))
242
andrewonlab867212a2014-10-22 20:13:38 -0400243 if len(line_ofp) > 1:
andrewonlab3a7c3c72014-10-24 17:21:03 -0400244 t0_ofp = float(obj[1])*1000.0
andrewonlabe6745342014-10-17 14:29:13 -0400245 else:
246 main.log.error("Tshark output file for OFP"+
247 " returned unexpected results")
248 t0_ofp = 0
249 assertion = main.FALSE
andrewonlab8d29f122014-10-22 17:15:04 -0400250
251 of_file.close()
andrewonlabe6745342014-10-17 14:29:13 -0400252 #****************
253
andrewonlab867212a2014-10-22 20:13:38 -0400254 json_str_1 = main.ONOS1cli.topology_events_metrics()
255 json_str_2 = main.ONOS2cli.topology_events_metrics()
256 json_str_3 = main.ONOS3cli.topology_events_metrics()
andrewonlab867212a2014-10-22 20:13:38 -0400257
258 json_obj_1 = json.loads(json_str_1)
259 json_obj_2 = json.loads(json_str_2)
260 json_obj_3 = json.loads(json_str_3)
261
andrewonlab226024e2014-10-24 16:01:32 -0400262 #Obtain graph timestamp. This timestsamp captures
263 #the epoch time at which the topology graph was updated.
264 graph_timestamp_1 = \
265 json_obj_1[graphTimestamp]['value']
266 graph_timestamp_2 = \
267 json_obj_2[graphTimestamp]['value']
268 graph_timestamp_3 = \
269 json_obj_3[graphTimestamp]['value']
andrewonlab867212a2014-10-22 20:13:38 -0400270
andrewonlab226024e2014-10-24 16:01:32 -0400271 #Obtain device timestamp. This timestamp captures
272 #the epoch time at which the device event happened
273 device_timestamp_1 = \
274 json_obj_1[deviceTimestamp]['value']
275 device_timestamp_2 = \
276 json_obj_2[deviceTimestamp]['value']
277 device_timestamp_3 = \
278 json_obj_3[deviceTimestamp]['value']
andrewonlabe9fb6722014-10-24 12:20:35 -0400279
andrewonlab226024e2014-10-24 16:01:32 -0400280 #t0 to device processing latency
281 delta_device_1 = int(device_timestamp_1) - int(t0_tcp)
282 delta_device_2 = int(device_timestamp_2) - int(t0_tcp)
283 delta_device_3 = int(device_timestamp_3) - int(t0_tcp)
284
285 #Get average of delta from all instances
286 avg_delta_device = \
287 (int(delta_device_1)+\
288 int(delta_device_2)+\
289 int(delta_device_3)) / 3
andrewonlabba44bcf2014-10-16 16:54:41 -0400290
andrewonlab226024e2014-10-24 16:01:32 -0400291 #Ensure avg delta meets the threshold before appending
292 if avg_delta_device > 0.0 and avg_delta_device < 10000:
293 latency_t0_to_device_list.append(avg_delta_device)
andrewonlabee4efeb2014-10-24 16:44:51 -0400294 else:
andrewonlab09d973e2014-10-24 18:56:58 -0400295 main.log.info("Results for t0-to-device ignored"+\
296 "due to excess in threshold")
andrewonlabee4efeb2014-10-24 16:44:51 -0400297
andrewonlab226024e2014-10-24 16:01:32 -0400298 #t0 to graph processing latency (end-to-end)
299 delta_graph_1 = int(graph_timestamp_1) - int(t0_tcp)
300 delta_graph_2 = int(graph_timestamp_2) - int(t0_tcp)
301 delta_graph_3 = int(graph_timestamp_3) - int(t0_tcp)
302
303 #Get average of delta from all instances
304 avg_delta_graph = \
305 (int(delta_graph_1)+\
306 int(delta_graph_2)+\
307 int(delta_graph_3)) / 3
308
andrewonlab226024e2014-10-24 16:01:32 -0400309 #Ensure avg delta meets the threshold before appending
310 if avg_delta_graph > 0.0 and avg_delta_graph < 10000:
andrewonlab09d973e2014-10-24 18:56:58 -0400311 latency_end_to_end_list.append(avg_delta_graph)
andrewonlabee4efeb2014-10-24 16:44:51 -0400312 else:
andrewonlab09d973e2014-10-24 18:56:58 -0400313 main.log.info("Results for end-to-end ignored"+\
314 "due to excess in threshold")
andrewonlab226024e2014-10-24 16:01:32 -0400315
316 #ofp to graph processing latency (ONOS processing)
317 delta_ofp_graph_1 = int(graph_timestamp_1) - int(t0_ofp)
318 delta_ofp_graph_2 = int(graph_timestamp_2) - int(t0_ofp)
319 delta_ofp_graph_3 = int(graph_timestamp_3) - int(t0_ofp)
320
321 avg_delta_ofp_graph = \
322 (int(delta_ofp_graph_1)+\
323 int(delta_ofp_graph_2)+\
324 int(delta_ofp_graph_3)) / 3
325
andrewonlabe5bcef92014-11-06 17:53:20 -0500326 if avg_delta_ofp_graph > threshold_min \
327 and avg_delta_ofp_graph < threshold_max:
andrewonlab226024e2014-10-24 16:01:32 -0400328 latency_ofp_to_graph_list.append(avg_delta_ofp_graph)
andrewonlabee4efeb2014-10-24 16:44:51 -0400329 else:
andrewonlab09d973e2014-10-24 18:56:58 -0400330 main.log.info("Results for ofp-to-graph "+\
331 "ignored due to excess in threshold")
andrewonlabee4efeb2014-10-24 16:44:51 -0400332
andrewonlab226024e2014-10-24 16:01:32 -0400333 #ofp to device processing latency (ONOS processing)
andrewonlabee4efeb2014-10-24 16:44:51 -0400334 delta_ofp_device_1 = float(device_timestamp_1) - float(t0_ofp)
335 delta_ofp_device_2 = float(device_timestamp_2) - float(t0_ofp)
336 delta_ofp_device_3 = float(device_timestamp_3) - float(t0_ofp)
andrewonlab226024e2014-10-24 16:01:32 -0400337
338 avg_delta_ofp_device = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400339 (float(delta_ofp_device_1)+\
340 float(delta_ofp_device_2)+\
341 float(delta_ofp_device_3)) / 3.0
andrewonlab226024e2014-10-24 16:01:32 -0400342
andrewonlabf47993a2014-10-24 17:56:01 -0400343 #NOTE: ofp - delta measurements are occasionally negative
344 # due to system time misalignment.
andrewonlabf47993a2014-10-24 17:56:01 -0400345 latency_ofp_to_device_list.append(avg_delta_ofp_device)
andrewonlabba44bcf2014-10-16 16:54:41 -0400346
andrewonlabe6745342014-10-17 14:29:13 -0400347 #TODO:
348 #Fetch logs upon threshold excess
andrewonlabba44bcf2014-10-16 16:54:41 -0400349
andrewonlab226024e2014-10-24 16:01:32 -0400350 main.log.info("ONOS1 delta end-to-end: "+
andrewonlab09d973e2014-10-24 18:56:58 -0400351 str(delta_graph_1) + " ms")
andrewonlab226024e2014-10-24 16:01:32 -0400352 main.log.info("ONOS2 delta end-to-end: "+
andrewonlab09d973e2014-10-24 18:56:58 -0400353 str(delta_graph_2) + " ms")
354 main.log.info("ONOS3 delta end-to-end: "+
355 str(delta_graph_3) + " ms")
andrewonlabba44bcf2014-10-16 16:54:41 -0400356
andrewonlab226024e2014-10-24 16:01:32 -0400357 main.log.info("ONOS1 delta OFP - graph: "+
andrewonlab09d973e2014-10-24 18:56:58 -0400358 str(delta_ofp_graph_1) + " ms")
andrewonlab226024e2014-10-24 16:01:32 -0400359 main.log.info("ONOS2 delta OFP - graph: "+
andrewonlab09d973e2014-10-24 18:56:58 -0400360 str(delta_ofp_graph_2) + " ms")
andrewonlab226024e2014-10-24 16:01:32 -0400361 main.log.info("ONOS3 delta OFP - graph: "+
andrewonlab09d973e2014-10-24 18:56:58 -0400362 str(delta_ofp_graph_3) + " ms")
andrewonlabe6745342014-10-17 14:29:13 -0400363
andrewonlab226024e2014-10-24 16:01:32 -0400364 main.log.info("ONOS1 delta device - t0: "+
andrewonlab09d973e2014-10-24 18:56:58 -0400365 str(delta_device_1) + " ms")
andrewonlab226024e2014-10-24 16:01:32 -0400366 main.log.info("ONOS2 delta device - t0: "+
andrewonlab09d973e2014-10-24 18:56:58 -0400367 str(delta_device_2) + " ms")
andrewonlab226024e2014-10-24 16:01:32 -0400368 main.log.info("ONOS3 delta device - t0: "+
andrewonlab09d973e2014-10-24 18:56:58 -0400369 str(delta_device_3) + " ms")
andrewonlab226024e2014-10-24 16:01:32 -0400370
andrewonlab8790abb2014-11-06 13:51:54 -0500371 #main.log.info("ONOS1 delta OFP - device: "+
372 # str(delta_ofp_device_1) + " ms")
373 #main.log.info("ONOS2 delta OFP - device: "+
374 # str(delta_ofp_device_2) + " ms")
375 #main.log.info("ONOS3 delta OFP - device: "+
376 # str(delta_ofp_device_3) + " ms")
andrewonlab226024e2014-10-24 16:01:32 -0400377
andrewonlab8d29f122014-10-22 17:15:04 -0400378 main.step("Remove switch from controller")
379 main.Mininet1.delete_sw_controller("s1")
andrewonlabba44bcf2014-10-16 16:54:41 -0400380
andrewonlab8d29f122014-10-22 17:15:04 -0400381 time.sleep(5)
andrewonlabba44bcf2014-10-16 16:54:41 -0400382
andrewonlab09d973e2014-10-24 18:56:58 -0400383 #END of for loop iteration
andrewonlabf47993a2014-10-24 17:56:01 -0400384
andrewonlabee4efeb2014-10-24 16:44:51 -0400385 #If there is at least 1 element in each list,
andrewonlabc15c9582014-10-24 16:35:52 -0400386 #pass the test case
387 if len(latency_end_to_end_list) > 0 and\
388 len(latency_ofp_to_graph_list) > 0 and\
389 len(latency_ofp_to_device_list) > 0 and\
390 len(latency_t0_to_device_list) > 0:
391 assertion = main.TRUE
andrewonlabf47993a2014-10-24 17:56:01 -0400392 elif len(latency_end_to_end_list) == 0:
393 #The appending of 0 here is to prevent
394 #the min,max,sum functions from failing
395 #below
396 latency_end_to_end_list.append(0)
397 assertion = main.FALSE
398 elif len(latency_ofp_to_graph_list) == 0:
399 latency_ofp_to_graph_list.append(0)
400 assertion = main.FALSE
401 elif len(latency_ofp_to_device_list) == 0:
402 latency_ofp_to_device_list.append(0)
403 assertion = main.FALSE
404 elif len(latency_t0_to_device_list) == 0:
405 latency_t0_to_device_list.append(0)
406 assertion = main.FALSE
andrewonlabc15c9582014-10-24 16:35:52 -0400407
408 #Calculate min, max, avg of latency lists
409 latency_end_to_end_max = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400410 int(max(latency_end_to_end_list))
andrewonlabc15c9582014-10-24 16:35:52 -0400411 latency_end_to_end_min = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400412 int(min(latency_end_to_end_list))
andrewonlabc15c9582014-10-24 16:35:52 -0400413 latency_end_to_end_avg = \
andrewonlabc90667c2014-10-24 16:48:28 -0400414 (int(sum(latency_end_to_end_list)) / \
andrewonlabc15c9582014-10-24 16:35:52 -0400415 len(latency_end_to_end_list))
416
417 latency_ofp_to_graph_max = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400418 int(max(latency_ofp_to_graph_list))
andrewonlabc15c9582014-10-24 16:35:52 -0400419 latency_ofp_to_graph_min = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400420 int(min(latency_ofp_to_graph_list))
andrewonlabc15c9582014-10-24 16:35:52 -0400421 latency_ofp_to_graph_avg = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400422 (int(sum(latency_ofp_to_graph_list)) / \
andrewonlabc15c9582014-10-24 16:35:52 -0400423 len(latency_ofp_to_graph_list))
424
425 latency_ofp_to_device_max = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400426 int(max(latency_ofp_to_device_list))
andrewonlabc15c9582014-10-24 16:35:52 -0400427 latency_ofp_to_device_min = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400428 int(min(latency_ofp_to_device_list))
andrewonlabc15c9582014-10-24 16:35:52 -0400429 latency_ofp_to_device_avg = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400430 (int(sum(latency_ofp_to_device_list)) / \
andrewonlabc15c9582014-10-24 16:35:52 -0400431 len(latency_ofp_to_device_list))
432
433 latency_t0_to_device_max = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400434 float(max(latency_t0_to_device_list))
andrewonlabc15c9582014-10-24 16:35:52 -0400435 latency_t0_to_device_min = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400436 float(min(latency_t0_to_device_list))
andrewonlabc15c9582014-10-24 16:35:52 -0400437 latency_t0_to_device_avg = \
andrewonlabee4efeb2014-10-24 16:44:51 -0400438 (float(sum(latency_t0_to_device_list)) / \
andrewonlabc15c9582014-10-24 16:35:52 -0400439 len(latency_ofp_to_device_list))
440
441 main.log.report("Switch add - End-to-end latency: \n"+\
andrewonlab58f7d702014-11-07 13:21:19 -0500442 "Min: "+str(latency_end_to_end_min)+" mx\n"+\
443 "Max: "+str(latency_end_to_end_max)+" ms\n"+\
444 "Avg: "+str(latency_end_to_end_avg)+" ms")
andrewonlabc15c9582014-10-24 16:35:52 -0400445 main.log.report("Switch add - OFP-to-Graph latency: \n"+\
andrewonlab58f7d702014-11-07 13:21:19 -0500446 "Min: "+str(latency_ofp_to_graph_min)+" ms \n"+\
447 "Max: "+str(latency_ofp_to_graph_max)+" ms\n"+\
448 "Avg: "+str(latency_ofp_to_graph_avg)+" ms")
andrewonlabc15c9582014-10-24 16:35:52 -0400449 main.log.report("Switch add - t0-to-Device latency: \n"+\
andrewonlab58f7d702014-11-07 13:21:19 -0500450 "Min: "+str(latency_t0_to_device_min)+" ms\n"+\
451 "Max: "+str(latency_t0_to_device_max)+" ms\n"+\
452 "Avg: "+str(latency_t0_to_device_avg)+" ms")
andrewonlab226024e2014-10-24 16:01:32 -0400453
andrewonlabb1998c52014-11-10 13:31:43 -0500454 if debug_mode == 'on':
455 main.ONOS1.cp_logs_to_dir("/opt/onos/log/karaf.log",
456 "/tmp/", copy_file_name="sw_lat_karaf")
457
andrewonlab8d29f122014-10-22 17:15:04 -0400458 utilities.assert_equals(expect=main.TRUE, actual=assertion,
459 onpass="Switch latency test successful",
460 onfail="Switch latency test failed")
andrewonlabba44bcf2014-10-16 16:54:41 -0400461
andrewonlab8d29f122014-10-22 17:15:04 -0400462 def CASE3(self, main):
463 '''
464 Bring port up / down and measure latency.
465 Port enable / disable is simulated by ifconfig up / down
andrewonlab393531a2014-10-27 18:36:26 -0400466
467 In ONOS-next, we must ensure that the port we are
468 manipulating is connected to another switch with a valid
469 connection. Otherwise, graph view will not be updated.
andrewonlab8d29f122014-10-22 17:15:04 -0400470 '''
471 import time
472 import subprocess
473 import os
474 import requests
475 import json
andrewonlab2a6c9342014-10-16 13:40:15 -0400476
andrewonlab8d29f122014-10-22 17:15:04 -0400477 ONOS1_ip = main.params['CTRL']['ip1']
andrewonlab393531a2014-10-27 18:36:26 -0400478 ONOS2_ip = main.params['CTRL']['ip2']
479 ONOS3_ip = main.params['CTRL']['ip3']
andrewonlab8d29f122014-10-22 17:15:04 -0400480 ONOS_user = main.params['CTRL']['user']
andrewonlab8d29f122014-10-22 17:15:04 -0400481
andrewonlab393531a2014-10-27 18:36:26 -0400482 default_sw_port = main.params['CTRL']['port1']
andrewonlab8790abb2014-11-06 13:51:54 -0500483
484 assertion = main.TRUE
andrewonlab393531a2014-10-27 18:36:26 -0400485 #Number of iterations of case
486 num_iter = main.params['TEST']['numIter']
487
488 #Timestamp 'keys' for json metrics output.
489 #These are subject to change, hence moved into params
490 deviceTimestamp = main.params['JSON']['deviceTimestamp']
491 graphTimestamp = main.params['JSON']['graphTimestamp']
andrewonlab58f7d702014-11-07 13:21:19 -0500492
493 debug_mode = main.params['TEST']['debugMode']
494
495 local_time = time.strftime('%x %X')
andrewonlabb1998c52014-11-10 13:31:43 -0500496 local_time = local_time.replace("/","")
497 local_time = local_time.replace(" ","_")
498 local_time = local_time.replace(":","")
andrewonlab58f7d702014-11-07 13:21:19 -0500499 if debug_mode == 'on':
500 main.ONOS1.tshark_pcap("eth0",
andrewonlabb1998c52014-11-10 13:31:43 -0500501 "/tmp/port_lat_pcap_"+local_time)
andrewonlab393531a2014-10-27 18:36:26 -0400502
andrewonlabe5bcef92014-11-06 17:53:20 -0500503 #Threshold for this test case
504 up_threshold_str = main.params['TEST']['portUpThreshold']
505 down_threshold_str = main.params['TEST']['portDownThreshold']
andrewonlabb1998c52014-11-10 13:31:43 -0500506
andrewonlabe5bcef92014-11-06 17:53:20 -0500507 up_threshold_obj = up_threshold_str.split(",")
508 down_threshold_obj = down_threshold_str.split(",")
509
510 up_threshold_min = int(up_threshold_obj[0])
511 up_threshold_max = int(up_threshold_obj[1])
512
513 down_threshold_min = int(down_threshold_obj[0])
514 down_threshold_max = int(down_threshold_obj[1])
515
andrewonlab393531a2014-10-27 18:36:26 -0400516 #NOTE: Some hardcoded variables you may need to configure
517 # besides the params
518
andrewonlab8d29f122014-10-22 17:15:04 -0400519 tshark_port_status = "OFP 130 Port Status"
520
521 tshark_port_up = "/tmp/tshark_port_up.txt"
522 tshark_port_down = "/tmp/tshark_port_down.txt"
andrewonlab393531a2014-10-27 18:36:26 -0400523 interface_config = "s1-eth1"
andrewonlab8d29f122014-10-22 17:15:04 -0400524
525 main.log.report("Port enable / disable latency")
526
andrewonlab393531a2014-10-27 18:36:26 -0400527 main.step("Assign switches s1 and s2 to controller 1")
andrewonlab8d29f122014-10-22 17:15:04 -0400528 main.Mininet1.assign_sw_controller(sw="1",ip1=ONOS1_ip,
529 port1=default_sw_port)
andrewonlab393531a2014-10-27 18:36:26 -0400530 main.Mininet1.assign_sw_controller(sw="2",ip1=ONOS1_ip,
531 port1=default_sw_port)
andrewonlab8d29f122014-10-22 17:15:04 -0400532
andrewonlab8790abb2014-11-06 13:51:54 -0500533 #Give enough time for metrics to propagate the
534 #assign controller event. Otherwise, these events may
535 #carry over to our measurements
andrewonlabb1998c52014-11-10 13:31:43 -0500536 time.sleep(15)
andrewonlab8d29f122014-10-22 17:15:04 -0400537
andrewonlab393531a2014-10-27 18:36:26 -0400538 port_up_device_to_ofp_list = []
539 port_up_graph_to_ofp_list = []
540 port_down_device_to_ofp_list = []
541 port_down_graph_to_ofp_list = []
542
andrewonlab8d29f122014-10-22 17:15:04 -0400543 for i in range(0, int(num_iter)):
544 main.step("Starting wireshark capture for port status down")
545 main.ONOS1.tshark_grep(tshark_port_status,
546 tshark_port_down)
547
andrewonlabb1998c52014-11-10 13:31:43 -0500548 time.sleep(5)
andrewonlab8d29f122014-10-22 17:15:04 -0400549
andrewonlab393531a2014-10-27 18:36:26 -0400550 #Disable interface that is connected to switch 2
551 main.step("Disable port: "+interface_config)
andrewonlabb1998c52014-11-10 13:31:43 -0500552 main.Mininet1.handle.sendline("sh ifconfig "+
andrewonlab393531a2014-10-27 18:36:26 -0400553 interface_config+" down")
andrewonlabb1998c52014-11-10 13:31:43 -0500554 main.Mininet1.handle.expect("mininet>")
andrewonlab8d29f122014-10-22 17:15:04 -0400555
andrewonlabb1998c52014-11-10 13:31:43 -0500556 time.sleep(3)
andrewonlab8d29f122014-10-22 17:15:04 -0400557 main.ONOS1.tshark_stop()
andrewonlabb1998c52014-11-10 13:31:43 -0500558
559 main.step("Obtain t1 by metrics call")
560 json_str_up_1 = main.ONOS1cli.topology_events_metrics()
561 json_str_up_2 = main.ONOS2cli.topology_events_metrics()
562 json_str_up_3 = main.ONOS3cli.topology_events_metrics()
563
564 json_obj_1 = json.loads(json_str_up_1)
565 json_obj_2 = json.loads(json_str_up_2)
566 json_obj_3 = json.loads(json_str_up_3)
andrewonlab8d29f122014-10-22 17:15:04 -0400567
568 #Copy tshark output file from ONOS to TestON instance
569 #/tmp directory
570 os.system("scp "+ONOS_user+"@"+ONOS1_ip+":"+
571 tshark_port_down+" /tmp/")
572
573 f_port_down = open(tshark_port_down, 'r')
andrewonlab393531a2014-10-27 18:36:26 -0400574 #Get first line of port down event from tshark
andrewonlab8d29f122014-10-22 17:15:04 -0400575 f_line = f_port_down.readline()
576 obj_down = f_line.split(" ")
577 if len(f_line) > 0:
andrewonlabb1998c52014-11-10 13:31:43 -0500578 timestamp_begin_pt_down = int(float(obj_down[1])*1000)
andrewonlab393531a2014-10-27 18:36:26 -0400579 main.log.info("Port down begin timestamp: "+
580 str(timestamp_begin_pt_down))
andrewonlab8d29f122014-10-22 17:15:04 -0400581 else:
582 main.log.info("Tshark output file returned unexpected"+
andrewonlab393531a2014-10-27 18:36:26 -0400583 " results: "+str(obj_down))
andrewonlab8d29f122014-10-22 17:15:04 -0400584 timestamp_begin_pt_down = 0
andrewonlab393531a2014-10-27 18:36:26 -0400585
586 f_port_down.close()
andrewonlab8d29f122014-10-22 17:15:04 -0400587
andrewonlab4e124482014-11-04 13:37:25 -0500588 main.log.info("TEST tshark obj: "+str(obj_down))
589
andrewonlabb1998c52014-11-10 13:31:43 -0500590 time.sleep(3)
andrewonlab393531a2014-10-27 18:36:26 -0400591
592 #Obtain graph timestamp. This timestsamp captures
593 #the epoch time at which the topology graph was updated.
594 graph_timestamp_1 = \
595 json_obj_1[graphTimestamp]['value']
596 graph_timestamp_2 = \
597 json_obj_2[graphTimestamp]['value']
598 graph_timestamp_3 = \
599 json_obj_3[graphTimestamp]['value']
600
andrewonlabb1998c52014-11-10 13:31:43 -0500601 main.log.info("TEST graph timestamp ONOS1: "+
602 str(graph_timestamp_1))
603
andrewonlab393531a2014-10-27 18:36:26 -0400604 #Obtain device timestamp. This timestamp captures
605 #the epoch time at which the device event happened
606 device_timestamp_1 = \
607 json_obj_1[deviceTimestamp]['value']
608 device_timestamp_2 = \
609 json_obj_2[deviceTimestamp]['value']
610 device_timestamp_3 = \
611 json_obj_3[deviceTimestamp]['value']
andrewonlab393531a2014-10-27 18:36:26 -0400612
613 #Get delta between graph event and OFP
614 pt_down_graph_to_ofp_1 = int(graph_timestamp_1) -\
615 int(timestamp_begin_pt_down)
616 pt_down_graph_to_ofp_2 = int(graph_timestamp_2) -\
617 int(timestamp_begin_pt_down)
618 pt_down_graph_to_ofp_3 = int(graph_timestamp_3) -\
619 int(timestamp_begin_pt_down)
620
621 #Get delta between device event and OFP
622 pt_down_device_to_ofp_1 = int(device_timestamp_1) -\
623 int(timestamp_begin_pt_down)
624 pt_down_device_to_ofp_2 = int(device_timestamp_2) -\
625 int(timestamp_begin_pt_down)
626 pt_down_device_to_ofp_3 = int(device_timestamp_3) -\
627 int(timestamp_begin_pt_down)
628
629 #Caluclate average across clusters
630 pt_down_graph_to_ofp_avg =\
631 (int(pt_down_graph_to_ofp_1) +
632 int(pt_down_graph_to_ofp_2) +
andrewonlab8790abb2014-11-06 13:51:54 -0500633 int(pt_down_graph_to_ofp_3)) / 3.0
andrewonlab393531a2014-10-27 18:36:26 -0400634 pt_down_device_to_ofp_avg = \
635 (int(pt_down_device_to_ofp_1) +
636 int(pt_down_device_to_ofp_2) +
andrewonlab8790abb2014-11-06 13:51:54 -0500637 int(pt_down_device_to_ofp_3)) / 3.0
andrewonlab393531a2014-10-27 18:36:26 -0400638
andrewonlabb1998c52014-11-10 13:31:43 -0500639 if pt_down_graph_to_ofp_avg > down_threshold_min and \
640 pt_down_graph_to_ofp_avg < down_threshold_max:
andrewonlab393531a2014-10-27 18:36:26 -0400641 port_down_graph_to_ofp_list.append(
andrewonlababb11c32014-11-04 15:03:24 -0500642 pt_down_graph_to_ofp_avg)
643 main.log.info("Port down: graph to ofp avg: "+
644 str(pt_down_graph_to_ofp_avg) + " ms")
andrewonlab393531a2014-10-27 18:36:26 -0400645 else:
646 main.log.info("Average port down graph-to-ofp result" +
647 " exceeded the threshold: "+
648 str(pt_down_graph_to_ofp_avg))
649
andrewonlab3622beb2014-10-28 16:07:56 -0400650 if pt_down_device_to_ofp_avg > 0 and \
651 pt_down_device_to_ofp_avg < 1000:
652 port_down_device_to_ofp_list.append(
andrewonlababb11c32014-11-04 15:03:24 -0500653 pt_down_device_to_ofp_avg)
654 main.log.info("Port down: device to ofp avg: "+
655 str(pt_down_device_to_ofp_avg) + " ms")
andrewonlab3622beb2014-10-28 16:07:56 -0400656 else:
657 main.log.info("Average port down device-to-ofp result" +
658 " exceeded the threshold: "+
659 str(pt_down_device_to_ofp_avg))
660
andrewonlab8d29f122014-10-22 17:15:04 -0400661 #Port up events
662 main.step("Enable port and obtain timestamp")
663 main.step("Starting wireshark capture for port status up")
andrewonlabb1998c52014-11-10 13:31:43 -0500664 main.ONOS1.tshark_grep(tshark_port_status, tshark_port_up)
andrewonlab8790abb2014-11-06 13:51:54 -0500665 time.sleep(5)
andrewonlab8d29f122014-10-22 17:15:04 -0400666
andrewonlabb1998c52014-11-10 13:31:43 -0500667 main.Mininet1.handle.sendline("sh ifconfig "+
andrewonlab393531a2014-10-27 18:36:26 -0400668 interface_config+" up")
andrewonlabb1998c52014-11-10 13:31:43 -0500669 main.Mininet1.handle.expect("mininet>")
andrewonlab8790abb2014-11-06 13:51:54 -0500670
andrewonlabb1998c52014-11-10 13:31:43 -0500671 #Allow time for tshark to capture event
672 time.sleep(3)
andrewonlab8790abb2014-11-06 13:51:54 -0500673 main.ONOS1.tshark_stop()
andrewonlab8d29f122014-10-22 17:15:04 -0400674
andrewonlabb1998c52014-11-10 13:31:43 -0500675 #Obtain metrics shortly afterwards
676 #This timestsamp captures
677 #the epoch time at which the topology graph was updated.
678 main.step("Obtain t1 by REST call")
679 json_str_up_1 = main.ONOS1cli.topology_events_metrics()
680 json_str_up_2 = main.ONOS2cli.topology_events_metrics()
681 json_str_up_3 = main.ONOS3cli.topology_events_metrics()
682
683 json_obj_1 = json.loads(json_str_up_1)
684 json_obj_2 = json.loads(json_str_up_2)
685 json_obj_3 = json.loads(json_str_up_3)
686
andrewonlab8d29f122014-10-22 17:15:04 -0400687 os.system("scp "+ONOS_user+"@"+ONOS1_ip+":"+
688 tshark_port_up+" /tmp/")
689
690 f_port_up = open(tshark_port_up, 'r')
andrewonlab393531a2014-10-27 18:36:26 -0400691 f_line = f_port_up.readline()
andrewonlab8d29f122014-10-22 17:15:04 -0400692 obj_up = f_line.split(" ")
693 if len(f_line) > 0:
andrewonlabb1998c52014-11-10 13:31:43 -0500694 timestamp_begin_pt_up = int(float(obj_up[1])*1000)
andrewonlab393531a2014-10-27 18:36:26 -0400695 main.log.info("Port up begin timestamp: "+
696 str(timestamp_begin_pt_up))
andrewonlab8d29f122014-10-22 17:15:04 -0400697 else:
698 main.log.info("Tshark output file returned unexpected"+
699 " results.")
700 timestamp_begin_pt_up = 0
701
andrewonlab393531a2014-10-27 18:36:26 -0400702 f_port_up.close()
703
andrewonlab393531a2014-10-27 18:36:26 -0400704 graph_timestamp_1 = \
705 json_obj_1[graphTimestamp]['value']
706 graph_timestamp_2 = \
707 json_obj_2[graphTimestamp]['value']
708 graph_timestamp_3 = \
709 json_obj_3[graphTimestamp]['value']
710
711 #Obtain device timestamp. This timestamp captures
712 #the epoch time at which the device event happened
713 device_timestamp_1 = \
714 json_obj_1[deviceTimestamp]['value']
715 device_timestamp_2 = \
716 json_obj_2[deviceTimestamp]['value']
717 device_timestamp_3 = \
718 json_obj_3[deviceTimestamp]['value']
719
720 #Get delta between graph event and OFP
721 pt_up_graph_to_ofp_1 = int(graph_timestamp_1) -\
andrewonlab8d29f122014-10-22 17:15:04 -0400722 int(timestamp_begin_pt_up)
andrewonlab393531a2014-10-27 18:36:26 -0400723 pt_up_graph_to_ofp_2 = int(graph_timestamp_2) -\
andrewonlab8d29f122014-10-22 17:15:04 -0400724 int(timestamp_begin_pt_up)
andrewonlab393531a2014-10-27 18:36:26 -0400725 pt_up_graph_to_ofp_3 = int(graph_timestamp_3) -\
726 int(timestamp_begin_pt_up)
727
728 #Get delta between device event and OFP
729 pt_up_device_to_ofp_1 = int(device_timestamp_1) -\
730 int(timestamp_begin_pt_up)
731 pt_up_device_to_ofp_2 = int(device_timestamp_2) -\
732 int(timestamp_begin_pt_up)
733 pt_up_device_to_ofp_3 = int(device_timestamp_3) -\
andrewonlab8d29f122014-10-22 17:15:04 -0400734 int(timestamp_begin_pt_up)
andrewonlab3622beb2014-10-28 16:07:56 -0400735
andrewonlabb1998c52014-11-10 13:31:43 -0500736 main.log.info("ONOS1 delta G2O: "+str(pt_up_graph_to_ofp_1))
737 main.log.info("ONOS2 delta G2O: "+str(pt_up_graph_to_ofp_2))
738 main.log.info("ONOS3 delta G2O: "+str(pt_up_graph_to_ofp_3))
739
740 main.log.info("ONOS1 delta D2O: "+str(pt_up_device_to_ofp_1))
741 main.log.info("ONOS2 delta D2O: "+str(pt_up_device_to_ofp_2))
742 main.log.info("ONOS3 delta D2O: "+str(pt_up_device_to_ofp_3))
743
andrewonlab3622beb2014-10-28 16:07:56 -0400744 pt_up_graph_to_ofp_avg = \
745 (float(pt_up_graph_to_ofp_1) +
746 float(pt_up_graph_to_ofp_2) +
747 float(pt_up_graph_to_ofp_3)) / 3
748
749 pt_up_device_to_ofp_avg = \
750 (float(pt_up_device_to_ofp_1) +
751 float(pt_up_device_to_ofp_2) +
752 float(pt_up_device_to_ofp_3)) / 3
753
andrewonlabe5bcef92014-11-06 17:53:20 -0500754 if pt_up_graph_to_ofp_avg > up_threshold_min and \
755 pt_up_graph_to_ofp_avg < up_threshold_max:
andrewonlab3622beb2014-10-28 16:07:56 -0400756 port_up_graph_to_ofp_list.append(
757 pt_up_graph_to_ofp_avg)
andrewonlababb11c32014-11-04 15:03:24 -0500758 main.log.info("Port down: graph to ofp avg: "+
759 str(pt_up_graph_to_ofp_avg) + " ms")
andrewonlab3622beb2014-10-28 16:07:56 -0400760 else:
761 main.log.info("Average port up graph-to-ofp result"+
762 " exceeded the threshold: "+
763 str(pt_up_graph_to_ofp_avg))
764
andrewonlabe5bcef92014-11-06 17:53:20 -0500765 if pt_up_device_to_ofp_avg > up_threshold_min and \
766 pt_up_device_to_ofp_avg < up_threshold_max:
andrewonlab3622beb2014-10-28 16:07:56 -0400767 port_up_device_to_ofp_list.append(
768 pt_up_device_to_ofp_avg)
andrewonlababb11c32014-11-04 15:03:24 -0500769 main.log.info("Port up: device to ofp avg: "+
770 str(pt_up_device_to_ofp_avg) + " ms")
andrewonlab3622beb2014-10-28 16:07:56 -0400771 else:
andrewonlababb11c32014-11-04 15:03:24 -0500772 main.log.info("Average port up device-to-ofp result"+
andrewonlab3622beb2014-10-28 16:07:56 -0400773 " exceeded the threshold: "+
774 str(pt_up_device_to_ofp_avg))
andrewonlab8d29f122014-10-22 17:15:04 -0400775
andrewonlab3622beb2014-10-28 16:07:56 -0400776 #END ITERATION FOR LOOP
andrewonlab8790abb2014-11-06 13:51:54 -0500777
778 #Check all list for latency existence and set assertion
779 if (port_down_graph_to_ofp_list and port_down_device_to_ofp_list\
780 and port_up_graph_to_ofp_list and port_up_device_to_ofp_list):
781 assertion = main.TRUE
782
andrewonlababb11c32014-11-04 15:03:24 -0500783 #Calculate and report latency measurements
andrewonlab3622beb2014-10-28 16:07:56 -0400784 port_down_graph_to_ofp_min = min(port_down_graph_to_ofp_list)
785 port_down_graph_to_ofp_max = max(port_down_graph_to_ofp_list)
786 port_down_graph_to_ofp_avg = \
787 (sum(port_down_graph_to_ofp_list) /
788 len(port_down_graph_to_ofp_list))
789
andrewonlab58f7d702014-11-07 13:21:19 -0500790 main.log.report("Port down graph-to-ofp \nMin: "+
791 str(port_down_graph_to_ofp_min)+" ms \nMax: "+
792 str(port_down_graph_to_ofp_max)+" ms \nAvg: "+
793 str(port_down_graph_to_ofp_avg)+" ms")
andrewonlababb11c32014-11-04 15:03:24 -0500794
795 port_down_device_to_ofp_min = min(port_down_device_to_ofp_list)
796 port_down_device_to_ofp_max = max(port_down_device_to_ofp_list)
797 port_down_device_to_ofp_avg = \
798 (sum(port_down_device_to_ofp_list) /\
799 len(port_down_device_to_ofp_list))
800
andrewonlab58f7d702014-11-07 13:21:19 -0500801 main.log.report("Port down device-to-ofp \nMin: "+
802 str(port_down_device_to_ofp_min)+" ms \nMax: "+
803 str(port_down_device_to_ofp_max)+" ms \nAvg: "+
804 str(port_down_device_to_ofp_avg)+" ms")
andrewonlababb11c32014-11-04 15:03:24 -0500805
806 port_up_graph_to_ofp_min = min(port_up_graph_to_ofp_list)
807 port_up_graph_to_ofp_max = max(port_up_graph_to_ofp_list)
808 port_up_graph_to_ofp_avg = \
809 (sum(port_up_graph_to_ofp_list) /\
810 len(port_up_graph_to_ofp_list))
andrewonlab8790abb2014-11-06 13:51:54 -0500811
andrewonlab58f7d702014-11-07 13:21:19 -0500812 main.log.report("Port up graph-to-ofp \nMin: "+
813 str(port_up_graph_to_ofp_min)+" ms \nMax: "+
814 str(port_up_graph_to_ofp_max)+" ms \nAvg: "+
815 str(port_up_graph_to_ofp_avg)+" ms")
andrewonlab8790abb2014-11-06 13:51:54 -0500816
817 port_up_device_to_ofp_min = min(port_up_device_to_ofp_list)
818 port_up_device_to_ofp_max = max(port_up_device_to_ofp_list)
819 port_up_device_to_ofp_avg = \
820 (sum(port_up_device_to_ofp_list) /\
821 len(port_up_device_to_ofp_list))
822
andrewonlab58f7d702014-11-07 13:21:19 -0500823 main.log.report("Port up device-to-ofp \nMin: "+
824 str(port_up_device_to_ofp_min)+" ms \nMax: "+
825 str(port_up_device_to_ofp_max)+" ms \nAvg: "+
826 str(port_up_device_to_ofp_avg)+" ms")
andrewonlab8790abb2014-11-06 13:51:54 -0500827
828 utilities.assert_equals(expect=main.TRUE, actual=assertion,
829 onpass="Port discovery latency calculation successful",
830 onfail="Port discovery test failed")
andrewonlababb11c32014-11-04 15:03:24 -0500831
andrewonlab3622beb2014-10-28 16:07:56 -0400832 def CASE4(self, main):
833 '''
834 Link down event using loss rate 100%
andrewonlab53b641c2014-10-31 19:44:44 -0400835
836 Important:
837 Use a simple 2 switch topology with 1 link between
838 the two switches. Ensure that mac addresses of the
839 switches are 1 / 2 respectively
andrewonlab3622beb2014-10-28 16:07:56 -0400840 '''
841 import time
842 import subprocess
843 import os
844 import requests
845 import json
846
847 ONOS1_ip = main.params['CTRL']['ip1']
848 ONOS2_ip = main.params['CTRL']['ip2']
849 ONOS3_ip = main.params['CTRL']['ip3']
850 ONOS_user = main.params['CTRL']['user']
851
852 default_sw_port = main.params['CTRL']['port1']
853
854 #Number of iterations of case
855 num_iter = main.params['TEST']['numIter']
856
857 #Timestamp 'keys' for json metrics output.
858 #These are subject to change, hence moved into params
859 deviceTimestamp = main.params['JSON']['deviceTimestamp']
860 linkTimestamp = main.params['JSON']['linkTimestamp']
andrewonlab53b641c2014-10-31 19:44:44 -0400861 graphTimestamp = main.params['JSON']['graphTimestamp']
andrewonlab58f7d702014-11-07 13:21:19 -0500862
863 debug_mode = main.params['TEST']['debugMode']
864
865 local_time = time.strftime('%x %X')
andrewonlabb1998c52014-11-10 13:31:43 -0500866 local_time = local_time.replace("/","")
867 local_time = local_time.replace(" ","_")
868 local_time = local_time.replace(":","")
andrewonlab58f7d702014-11-07 13:21:19 -0500869 if debug_mode == 'on':
870 main.ONOS1.tshark_pcap("eth0",
andrewonlabb1998c52014-11-10 13:31:43 -0500871 "/tmp/link_lat_pcap_"+local_time)
andrewonlab53b641c2014-10-31 19:44:44 -0400872
andrewonlabe5bcef92014-11-06 17:53:20 -0500873 #Threshold for this test case
874 up_threshold_str = main.params['TEST']['linkUpThreshold']
875 down_threshold_str = main.params['TEST']['linkDownThreshold']
876
877 up_threshold_obj = up_threshold_str.split(",")
878 down_threshold_obj = down_threshold_str.split(",")
879
880 up_threshold_min = int(up_threshold_obj[0])
881 up_threshold_max = int(up_threshold_obj[1])
882
883 down_threshold_min = int(down_threshold_obj[0])
884 down_threshold_max = int(down_threshold_obj[1])
885
andrewonlab3622beb2014-10-28 16:07:56 -0400886 assertion = main.TRUE
887 #Link event timestamp to system time list
888 link_down_link_to_system_list = []
889 link_up_link_to_system_list = []
890 #Graph event timestamp to system time list
891 link_down_graph_to_system_list = []
892 link_up_graph_to_system_list = []
893
894 main.log.report("Add / remove link latency between "+
895 "two switches")
896
897 main.step("Assign all switches")
898 main.Mininet1.assign_sw_controller(sw="1",
899 ip1=ONOS1_ip, port1=default_sw_port)
900 main.Mininet1.assign_sw_controller(sw="2",
901 ip1=ONOS1_ip, port1=default_sw_port)
902
903 main.step("Verifying switch assignment")
904 result_s1 = main.Mininet1.get_sw_controller(sw="s1")
905 result_s2 = main.Mininet1.get_sw_controller(sw="s2")
andrewonlab3622beb2014-10-28 16:07:56 -0400906
907 #Allow time for events to finish before taking measurements
908 time.sleep(10)
909
andrewonlababb11c32014-11-04 15:03:24 -0500910 link_down1 = False
911 link_down2 = False
912 link_down3 = False
andrewonlab3622beb2014-10-28 16:07:56 -0400913 #Start iteration of link event test
914 for i in range(0, int(num_iter)):
915 main.step("Getting initial system time as t0")
andrewonlab8d29f122014-10-22 17:15:04 -0400916
andrewonlab3622beb2014-10-28 16:07:56 -0400917 timestamp_link_down_t0 = time.time() * 1000
918 #Link down is simulated by 100% loss rate using traffic
919 #control command
920 main.Mininet1.handle.sendline(
921 "sh tc qdisc add dev s1-eth1 root netem loss 100%")
922
andrewonlab53b641c2014-10-31 19:44:44 -0400923 #TODO: Iterate through 'links' command to verify that
andrewonlababb11c32014-11-04 15:03:24 -0500924 # link s1 -> s2 went down (loop timeout 30 seconds)
925 # on all 3 ONOS instances
andrewonlab53b641c2014-10-31 19:44:44 -0400926 main.log.info("Checking ONOS for link update")
927 loop_count = 0
andrewonlababb11c32014-11-04 15:03:24 -0500928 while( not (link_down1 and link_down2 and link_down3)\
929 and loop_count < 30 ):
930 json_str1 = main.ONOS1cli.links()
931 json_str2 = main.ONOS2cli.links()
932 json_str3 = main.ONOS3cli.links()
933
934 if not (json_str1 and json_str2 and json_str3):
935 main.log.error("CLI command returned error ")
andrewonlab53b641c2014-10-31 19:44:44 -0400936 break
937 else:
andrewonlababb11c32014-11-04 15:03:24 -0500938 json_obj1 = json.loads(json_str1)
939 json_obj2 = json.loads(json_str2)
940 json_obj3 = json.loads(json_str3)
941 for obj1 in json_obj1:
942 if '01' not in obj1['src']['device']:
943 link_down1 = True
andrewonlab53b641c2014-10-31 19:44:44 -0400944 main.log.report("Link down from "+
andrewonlababb11c32014-11-04 15:03:24 -0500945 "s1 -> s2 on ONOS1 detected")
946 for obj2 in json_obj2:
947 if '01' not in obj2['src']['device']:
948 link_down2 = True
949 main.log.report("Link down from "+
950 "s1 -> s2 on ONOS2 detected")
951 for obj3 in json_obj3:
952 if '01' not in obj3['src']['device']:
953 link_down3 = True
954 main.log.report("Link down from "+
955 "s1 -> s2 on ONOS3 detected")
956
andrewonlab53b641c2014-10-31 19:44:44 -0400957 loop_count += 1
andrewonlababb11c32014-11-04 15:03:24 -0500958 #If CLI doesn't like the continuous requests
959 #and exits in this loop, increase the sleep here.
960 #Consequently, while loop timeout will increase
andrewonlab53b641c2014-10-31 19:44:44 -0400961 time.sleep(1)
962
963 #Give time for metrics measurement to catch up
andrewonlababb11c32014-11-04 15:03:24 -0500964 #NOTE: May need to be configured more accurately
andrewonlab53b641c2014-10-31 19:44:44 -0400965 time.sleep(10)
andrewonlababb11c32014-11-04 15:03:24 -0500966 #If we exited the while loop and link down 1,2,3 are still
andrewonlab53b641c2014-10-31 19:44:44 -0400967 #false, then ONOS has failed to discover link down event
andrewonlababb11c32014-11-04 15:03:24 -0500968 if not (link_down1 and link_down2 and link_down3):
andrewonlab53b641c2014-10-31 19:44:44 -0400969 main.log.info("Link down discovery failed")
970
971 link_down_lat_graph1 = 0
972 link_down_lat_graph2 = 0
973 link_down_lat_graph3 = 0
974 link_down_lat_device1 = 0
975 link_down_lat_device2 = 0
976 link_down_lat_device3 = 0
977
978 assertion = main.FALSE
979 else:
980 json_topo_metrics_1 =\
981 main.ONOS1cli.topology_events_metrics()
982 json_topo_metrics_2 =\
983 main.ONOS2cli.topology_events_metrics()
984 json_topo_metrics_3 =\
985 main.ONOS3cli.topology_events_metrics()
986 json_topo_metrics_1 = json.loads(json_topo_metrics_1)
987 json_topo_metrics_2 = json.loads(json_topo_metrics_2)
988 json_topo_metrics_3 = json.loads(json_topo_metrics_3)
989
990 main.log.info("Obtaining graph and device timestamp")
991 graph_timestamp_1 = \
992 json_topo_metrics_1[graphTimestamp]['value']
993 graph_timestamp_2 = \
994 json_topo_metrics_2[graphTimestamp]['value']
995 graph_timestamp_3 = \
996 json_topo_metrics_3[graphTimestamp]['value']
997
998 link_timestamp_1 = \
999 json_topo_metrics_1[linkTimestamp]['value']
1000 link_timestamp_2 = \
1001 json_topo_metrics_2[linkTimestamp]['value']
1002 link_timestamp_3 = \
1003 json_topo_metrics_3[linkTimestamp]['value']
1004
1005 if graph_timestamp_1 and graph_timestamp_2 and\
1006 graph_timestamp_3 and link_timestamp_1 and\
1007 link_timestamp_2 and link_timestamp_3:
1008 link_down_lat_graph1 = int(graph_timestamp_1) -\
1009 timestamp_link_down_t0
1010 link_down_lat_graph2 = int(graph_timestamp_2) -\
1011 timestamp_link_down_t0
1012 link_down_lat_graph3 = int(graph_timestamp_3) -\
1013 timestamp_link_down_t0
1014
1015 link_down_lat_link1 = int(link_timestamp_1) -\
1016 timestamp_link_down_t0
1017 link_down_lat_link2 = int(link_timestamp_2) -\
1018 timestamp_link_down_t0
1019 link_down_lat_link3 = int(link_timestamp_3) -\
1020 timestamp_link_down_t0
1021 else:
1022 main.log.error("There was an error calculating"+
1023 " the delta for link down event")
1024 link_down_lat_graph1 = 0
1025 link_down_lat_graph2 = 0
1026 link_down_lat_graph3 = 0
1027
1028 link_down_lat_device1 = 0
1029 link_down_lat_device2 = 0
1030 link_down_lat_device3 = 0
1031
andrewonlab4e124482014-11-04 13:37:25 -05001032 main.log.report("Link down latency ONOS1 iteration "+
1033 str(i)+" (end-to-end): "+
andrewonlababb11c32014-11-04 15:03:24 -05001034 str(link_down_lat_graph1)+" ms")
andrewonlab4e124482014-11-04 13:37:25 -05001035 main.log.report("Link down latency ONOS2 iteration "+
1036 str(i)+" (end-to-end): "+
andrewonlababb11c32014-11-04 15:03:24 -05001037 str(link_down_lat_graph2)+" ms")
andrewonlab4e124482014-11-04 13:37:25 -05001038 main.log.report("Link down latency ONOS3 iteration "+
1039 str(i)+" (end-to-end): "+
andrewonlababb11c32014-11-04 15:03:24 -05001040 str(link_down_lat_graph3)+" ms")
andrewonlab4e124482014-11-04 13:37:25 -05001041
1042 main.log.report("Link down latency ONOS1 iteration "+
1043 str(i)+" (link-event-to-system-timestamp): "+
andrewonlababb11c32014-11-04 15:03:24 -05001044 str(link_down_lat_link1)+" ms")
andrewonlab4e124482014-11-04 13:37:25 -05001045 main.log.report("Link down latency ONOS2 iteration "+
1046 str(i)+" (link-event-to-system-timestamp): "+
andrewonlababb11c32014-11-04 15:03:24 -05001047 str(link_down_lat_link2)+" ms")
andrewonlab4e124482014-11-04 13:37:25 -05001048 main.log.report("Link down latency ONOS3 iteration "+
1049 str(i)+" (link-event-to-system-timestamp): "+
1050 str(link_down_lat_link3))
1051
1052 #Calculate avg of node calculations
1053 link_down_lat_graph_avg =\
andrewonlababb11c32014-11-04 15:03:24 -05001054 (link_down_lat_graph1 +
1055 link_down_lat_graph2 +
1056 link_down_lat_graph3) / 3.0
andrewonlab4e124482014-11-04 13:37:25 -05001057 link_down_lat_link_avg =\
andrewonlababb11c32014-11-04 15:03:24 -05001058 (link_down_lat_link1 +
1059 link_down_lat_link2 +
1060 link_down_lat_link3) / 3.0
andrewonlab53b641c2014-10-31 19:44:44 -04001061
andrewonlab4e124482014-11-04 13:37:25 -05001062 #Set threshold and append latency to list
andrewonlabe5bcef92014-11-06 17:53:20 -05001063 if link_down_lat_graph_avg > down_threshold_min and\
1064 link_down_lat_graph_avg < down_threshold_max:
andrewonlab4e124482014-11-04 13:37:25 -05001065 link_down_graph_to_system_list.append(
1066 link_down_lat_graph_avg)
andrewonlab8790abb2014-11-06 13:51:54 -05001067 else:
1068 main.log.info("Link down latency exceeded threshold")
1069 main.log.info("Results for iteration "+str(i)+
1070 "have been omitted")
andrewonlabe5bcef92014-11-06 17:53:20 -05001071 if link_down_lat_link_avg > down_threshold_min and\
1072 link_down_lat_link_avg < down_threshold_max:
andrewonlab4e124482014-11-04 13:37:25 -05001073 link_down_link_to_system_list.append(
1074 link_down_lat_link_avg)
andrewonlab8790abb2014-11-06 13:51:54 -05001075 else:
1076 main.log.info("Link down latency exceeded threshold")
1077 main.log.info("Results for iteration "+str(i)+
1078 "have been omitted")
andrewonlab53b641c2014-10-31 19:44:44 -04001079
1080 #NOTE: To remove loss rate and measure latency:
1081 # 'sh tc qdisc del dev s1-eth1 root'
andrewonlababb11c32014-11-04 15:03:24 -05001082 timestamp_link_up_t0 = time.time() * 1000
andrewonlab53b641c2014-10-31 19:44:44 -04001083 main.Mininet1.handle.sendline("sh tc qdisc del dev "+
1084 "s1-eth1 root")
1085 main.Mininet1.handle.expect("mininet>")
andrewonlababb11c32014-11-04 15:03:24 -05001086
1087 main.log.info("Checking ONOS for link update")
1088
1089 link_down1 = True
1090 link_down2 = True
1091 link_down3 = True
1092 loop_count = 0
1093 while( (link_down1 and link_down2 and link_down3)\
1094 and loop_count < 30 ):
1095 json_str1 = main.ONOS1cli.links()
1096 json_str2 = main.ONOS2cli.links()
1097 json_str3 = main.ONOS3cli.links()
1098 if not (json_str1 and json_str2 and json_str3):
1099 main.log.error("CLI command returned error ")
1100 break
1101 else:
1102 json_obj1 = json.loads(json_str1)
1103 json_obj2 = json.loads(json_str2)
1104 json_obj3 = json.loads(json_str3)
1105
1106 for obj1 in json_obj1:
1107 if '01' in obj1['src']['device']:
1108 link_down1 = False
1109 main.log.report("Link up from "+
1110 "s1 -> s2 on ONOS1 detected")
1111 for obj2 in json_obj2:
1112 if '01' in obj2['src']['device']:
1113 link_down2 = False
1114 main.log.report("Link up from "+
1115 "s1 -> s2 on ONOS2 detected")
1116 for obj3 in json_obj3:
1117 if '01' in obj3['src']['device']:
1118 link_down3 = False
1119 main.log.report("Link up from "+
1120 "s1 -> s2 on ONOS3 detected")
1121
1122 loop_count += 1
1123 time.sleep(1)
1124
1125 if (link_down1 and link_down2 and link_down3):
1126 main.log.info("Link up discovery failed")
1127
1128 link_up_lat_graph1 = 0
1129 link_up_lat_graph2 = 0
1130 link_up_lat_graph3 = 0
1131 link_up_lat_device1 = 0
1132 link_up_lat_device2 = 0
1133 link_up_lat_device3 = 0
1134
1135 assertion = main.FALSE
1136 else:
1137 json_topo_metrics_1 =\
1138 main.ONOS1cli.topology_events_metrics()
1139 json_topo_metrics_2 =\
1140 main.ONOS2cli.topology_events_metrics()
1141 json_topo_metrics_3 =\
1142 main.ONOS3cli.topology_events_metrics()
1143 json_topo_metrics_1 = json.loads(json_topo_metrics_1)
1144 json_topo_metrics_2 = json.loads(json_topo_metrics_2)
1145 json_topo_metrics_3 = json.loads(json_topo_metrics_3)
1146
1147 main.log.info("Obtaining graph and device timestamp")
1148 graph_timestamp_1 = \
1149 json_topo_metrics_1[graphTimestamp]['value']
1150 graph_timestamp_2 = \
1151 json_topo_metrics_2[graphTimestamp]['value']
1152 graph_timestamp_3 = \
1153 json_topo_metrics_3[graphTimestamp]['value']
1154
1155 link_timestamp_1 = \
1156 json_topo_metrics_1[linkTimestamp]['value']
1157 link_timestamp_2 = \
1158 json_topo_metrics_2[linkTimestamp]['value']
1159 link_timestamp_3 = \
1160 json_topo_metrics_3[linkTimestamp]['value']
1161
1162 if graph_timestamp_1 and graph_timestamp_2 and\
1163 graph_timestamp_3 and link_timestamp_1 and\
1164 link_timestamp_2 and link_timestamp_3:
1165 link_up_lat_graph1 = int(graph_timestamp_1) -\
1166 timestamp_link_up_t0
1167 link_up_lat_graph2 = int(graph_timestamp_2) -\
1168 timestamp_link_up_t0
1169 link_up_lat_graph3 = int(graph_timestamp_3) -\
1170 timestamp_link_up_t0
1171
1172 link_up_lat_link1 = int(link_timestamp_1) -\
1173 timestamp_link_up_t0
1174 link_up_lat_link2 = int(link_timestamp_2) -\
1175 timestamp_link_up_t0
1176 link_up_lat_link3 = int(link_timestamp_3) -\
1177 timestamp_link_up_t0
1178 else:
1179 main.log.error("There was an error calculating"+
1180 " the delta for link down event")
1181 link_up_lat_graph1 = 0
1182 link_up_lat_graph2 = 0
1183 link_up_lat_graph3 = 0
1184
1185 link_up_lat_device1 = 0
1186 link_up_lat_device2 = 0
1187 link_up_lat_device3 = 0
andrewonlab58f7d702014-11-07 13:21:19 -05001188
1189 if debug_mode == 'on':
1190 main.log.info("Link up latency ONOS1 iteration "+
andrewonlababb11c32014-11-04 15:03:24 -05001191 str(i)+" (end-to-end): "+
1192 str(link_up_lat_graph1)+" ms")
andrewonlab58f7d702014-11-07 13:21:19 -05001193 main.log.info("Link up latency ONOS2 iteration "+
andrewonlababb11c32014-11-04 15:03:24 -05001194 str(i)+" (end-to-end): "+
1195 str(link_up_lat_graph2)+" ms")
andrewonlab58f7d702014-11-07 13:21:19 -05001196 main.log.info("Link up latency ONOS3 iteration "+
andrewonlababb11c32014-11-04 15:03:24 -05001197 str(i)+" (end-to-end): "+
1198 str(link_up_lat_graph3)+" ms")
1199
andrewonlab58f7d702014-11-07 13:21:19 -05001200 main.log.info("Link up latency ONOS1 iteration "+
andrewonlababb11c32014-11-04 15:03:24 -05001201 str(i)+" (link-event-to-system-timestamp): "+
1202 str(link_up_lat_link1)+" ms")
andrewonlab58f7d702014-11-07 13:21:19 -05001203 main.log.info("Link up latency ONOS2 iteration "+
andrewonlababb11c32014-11-04 15:03:24 -05001204 str(i)+" (link-event-to-system-timestamp): "+
1205 str(link_up_lat_link2)+" ms")
andrewonlab58f7d702014-11-07 13:21:19 -05001206 main.log.info("Link up latency ONOS3 iteration "+
andrewonlababb11c32014-11-04 15:03:24 -05001207 str(i)+" (link-event-to-system-timestamp): "+
1208 str(link_up_lat_link3))
1209
1210 #Calculate avg of node calculations
1211 link_up_lat_graph_avg =\
1212 (link_up_lat_graph1 +
1213 link_up_lat_graph2 +
1214 link_up_lat_graph3) / 3.0
1215 link_up_lat_link_avg =\
1216 (link_up_lat_link1 +
1217 link_up_lat_link2 +
1218 link_up_lat_link3) / 3.0
1219
1220 #Set threshold and append latency to list
andrewonlabe5bcef92014-11-06 17:53:20 -05001221 if link_up_lat_graph_avg > up_threshold_min and\
1222 link_up_lat_graph_avg < up_threshold_max:
andrewonlababb11c32014-11-04 15:03:24 -05001223 link_up_graph_to_system_list.append(
1224 link_up_lat_graph_avg)
andrewonlab8790abb2014-11-06 13:51:54 -05001225 else:
1226 main.log.info("Link up latency exceeded threshold")
1227 main.log.info("Results for iteration "+str(i)+
1228 "have been omitted")
andrewonlabe5bcef92014-11-06 17:53:20 -05001229 if link_up_lat_link_avg > up_threshold_min and\
1230 link_up_lat_link_avg < up_threshold_max:
andrewonlababb11c32014-11-04 15:03:24 -05001231 link_up_link_to_system_list.append(
1232 link_up_lat_link_avg)
andrewonlab8790abb2014-11-06 13:51:54 -05001233 else:
1234 main.log.info("Link up latency exceeded threshold")
1235 main.log.info("Results for iteration "+str(i)+
1236 "have been omitted")
andrewonlab53b641c2014-10-31 19:44:44 -04001237
andrewonlab4e124482014-11-04 13:37:25 -05001238 #Calculate min, max, avg of list and report
1239 link_down_min = min(link_down_graph_to_system_list)
1240 link_down_max = max(link_down_graph_to_system_list)
1241 link_down_avg = sum(link_down_graph_to_system_list) / \
1242 len(link_down_graph_to_system_list)
andrewonlababb11c32014-11-04 15:03:24 -05001243 link_up_min = min(link_up_graph_to_system_list)
1244 link_up_max = max(link_up_graph_to_system_list)
1245 link_up_avg = sum(link_up_graph_to_system_list) / \
1246 len(link_up_graph_to_system_list)
1247
andrewonlab58f7d702014-11-07 13:21:19 -05001248 main.log.report("Link down latency - \nMin: "+
1249 str(link_down_min)+" ms \nMax: "+
1250 str(link_down_max)+" ms \nAvg: "+
1251 str(link_down_avg)+" ms")
1252 main.log.report("Link up latency - \nMin: "+
1253 str(link_up_min)+" ms \nMax: "+
1254 str(link_up_max)+" ms \nAvg: "+
1255 str(link_up_avg)+" ms")
andrewonlab4e124482014-11-04 13:37:25 -05001256
andrewonlab8790abb2014-11-06 13:51:54 -05001257 utilities.assert_equals(expect=main.TRUE, actual=assertion,
1258 onpass="Link discovery latency calculation successful",
1259 onfail="Link discovery latency case failed")
1260
andrewonlabb54b85b2014-10-28 18:43:57 -04001261 def CASE5(self, main):
1262 '''
1263 100 Switch discovery latency
1264
1265 Important:
andrewonlab16ce4852014-10-30 13:41:09 -04001266 This test case can be potentially dangerous if
1267 your machine has previously set iptables rules.
1268 One of the steps of the test case will flush
1269 all existing iptables rules.
andrewonlab8790abb2014-11-06 13:51:54 -05001270 Note:
1271 You can specify the number of switches in the
1272 params file to adjust the switch discovery size
1273 (and specify the corresponding topology in Mininet1
1274 .topo file)
andrewonlabb54b85b2014-10-28 18:43:57 -04001275 '''
1276 import time
1277 import subprocess
1278 import os
1279 import requests
1280 import json
1281
1282 ONOS1_ip = main.params['CTRL']['ip1']
1283 ONOS2_ip = main.params['CTRL']['ip2']
1284 ONOS3_ip = main.params['CTRL']['ip3']
1285 MN1_ip = main.params['MN']['ip1']
1286 ONOS_user = main.params['CTRL']['user']
1287
1288 default_sw_port = main.params['CTRL']['port1']
1289
1290 #Number of iterations of case
1291 num_iter = main.params['TEST']['numIter']
andrewonlab16ce4852014-10-30 13:41:09 -04001292 num_sw = main.params['TEST']['numSwitch']
1293
andrewonlabb54b85b2014-10-28 18:43:57 -04001294 #Timestamp 'keys' for json metrics output.
1295 #These are subject to change, hence moved into params
1296 deviceTimestamp = main.params['JSON']['deviceTimestamp']
andrewonlab16ce4852014-10-30 13:41:09 -04001297 graphTimestamp = main.params['JSON']['graphTimestamp']
andrewonlab58f7d702014-11-07 13:21:19 -05001298
1299 debug_mode = main.params['TEST']['debugMode']
1300
andrewonlabb1998c52014-11-10 13:31:43 -05001301 local_time = time.strftime('%X')
1302 local_time = local_time.replace("/","")
1303 local_time = local_time.replace(" ","_")
1304 local_time = local_time.replace(":","")
andrewonlab58f7d702014-11-07 13:21:19 -05001305 if debug_mode == 'on':
1306 main.ONOS1.tshark_pcap("eth0",
andrewonlabb1998c52014-11-10 13:31:43 -05001307 "/tmp/100_sw_lat_pcap_"+local_time)
andrewonlabe5bcef92014-11-06 17:53:20 -05001308
1309 #Threshold for this test case
1310 sw_disc_threshold_str = main.params['TEST']['swDisc100Threshold']
1311 sw_disc_threshold_obj = sw_disc_threshold_str.split(",")
1312 sw_disc_threshold_min = int(sw_disc_threshold_obj[0])
1313 sw_disc_threshold_max = int(sw_disc_threshold_obj[1])
1314
andrewonlab53b641c2014-10-31 19:44:44 -04001315 tshark_ofp_output = "/tmp/tshark_ofp_"+num_sw+"sw.txt"
1316 tshark_tcp_output = "/tmp/tshark_tcp_"+num_sw+"sw.txt"
1317
1318 tshark_ofp_result_list = []
1319 tshark_tcp_result_list = []
andrewonlabb54b85b2014-10-28 18:43:57 -04001320
andrewonlabe5bcef92014-11-06 17:53:20 -05001321 sw_discovery_lat_list = []
1322
andrewonlab16ce4852014-10-30 13:41:09 -04001323 main.case(num_sw+" Switch discovery latency")
andrewonlabb54b85b2014-10-28 18:43:57 -04001324 main.step("Assigning all switches to ONOS1")
andrewonlab16ce4852014-10-30 13:41:09 -04001325 for i in range(1, int(num_sw)+1):
andrewonlabb54b85b2014-10-28 18:43:57 -04001326 main.Mininet1.assign_sw_controller(
1327 sw=str(i),
1328 ip1=ONOS1_ip,
1329 port1=default_sw_port)
andrewonlab16ce4852014-10-30 13:41:09 -04001330
andrewonlabb54b85b2014-10-28 18:43:57 -04001331 #Ensure that nodes are configured with ptpd
andrewonlab16ce4852014-10-30 13:41:09 -04001332 #Just a warning message
1333 main.log.info("Please check ptpd configuration to ensure"+\
1334 " All nodes' system times are in sync")
1335 time.sleep(5)
andrewonlabb54b85b2014-10-28 18:43:57 -04001336
1337 for i in range(0, int(num_iter)):
andrewonlab8d29f122014-10-22 17:15:04 -04001338
andrewonlabb54b85b2014-10-28 18:43:57 -04001339 main.step("Set iptables rule to block incoming sw connections")
1340 #Set iptables rule to block incoming switch connections
andrewonlab53b641c2014-10-31 19:44:44 -04001341 #The rule description is as follows:
1342 # Append to INPUT rule,
1343 # behavior DROP that matches following:
1344 # * packet type: tcp
1345 # * source IP: MN1_ip
1346 # * destination PORT: 6633
andrewonlabb54b85b2014-10-28 18:43:57 -04001347 main.ONOS1.handle.sendline(
andrewonlab16ce4852014-10-30 13:41:09 -04001348 "sudo iptables -A INPUT -p tcp -s "+MN1_ip+
andrewonlabb54b85b2014-10-28 18:43:57 -04001349 " --dport "+default_sw_port+" -j DROP")
1350 main.ONOS1.handle.expect("\$")
andrewonlab53b641c2014-10-31 19:44:44 -04001351 # Append to OUTPUT rule,
1352 # behavior DROP that matches following:
1353 # * packet type: tcp
1354 # * source IP: MN1_ip
1355 # * destination PORT: 6633
1356 main.ONOS1.handle.sendline(
1357 "sudo iptables -A OUTPUT -p tcp -s "+MN1_ip+
1358 " --dport "+default_sw_port+" -j DROP")
1359 main.ONOS1.handle.expect("\$")
andrewonlabb54b85b2014-10-28 18:43:57 -04001360 #Give time to allow rule to take effect
andrewonlab8790abb2014-11-06 13:51:54 -05001361 #NOTE: Sleep period may need to be configured
1362 # based on the number of switches in the topology
andrewonlab16ce4852014-10-30 13:41:09 -04001363 main.log.info("Please wait for switch connection to "+
1364 "time out")
1365 time.sleep(60)
1366
1367 #Gather vendor OFP with tshark
1368 main.ONOS1.tshark_grep("OFP 86 Vendor",
1369 tshark_ofp_output)
andrewonlab53b641c2014-10-31 19:44:44 -04001370 main.ONOS1.tshark_grep("TCP 74 ",
1371 tshark_tcp_output)
andrewonlabb54b85b2014-10-28 18:43:57 -04001372
andrewonlab16ce4852014-10-30 13:41:09 -04001373 #NOTE: Remove all iptables rule quickly (flush)
andrewonlabb54b85b2014-10-28 18:43:57 -04001374 # Before removal, obtain TestON timestamp at which
andrewonlab16ce4852014-10-30 13:41:09 -04001375 # removal took place
1376 # (ensuring nodes are configured via ptp)
andrewonlabb54b85b2014-10-28 18:43:57 -04001377 # sudo iptables -F
andrewonlab16ce4852014-10-30 13:41:09 -04001378
1379 t0_system = time.time() * 1000
1380 main.ONOS1.handle.sendline(
1381 "sudo iptables -F")
andrewonlabb54b85b2014-10-28 18:43:57 -04001382
andrewonlab16ce4852014-10-30 13:41:09 -04001383 #Counter to track loop count
1384 counter_loop = 0
1385 counter_avail1 = 0
1386 counter_avail2 = 0
1387 counter_avail3 = 0
1388 onos1_dev = False
1389 onos2_dev = False
1390 onos3_dev = False
1391 while counter_loop < 60:
1392 #Continue to check devices for all device
1393 #availability. When all devices in all 3
1394 #ONOS instances indicate that devices are available
1395 #obtain graph event timestamp for t1.
1396 device_str_obj1 = main.ONOS1cli.devices()
1397 device_str_obj2 = main.ONOS2cli.devices()
1398 device_str_obj3 = main.ONOS3cli.devices()
1399
1400 device_json1 = json.loads(device_str_obj1)
1401 device_json2 = json.loads(device_str_obj2)
1402 device_json3 = json.loads(device_str_obj3)
1403
1404 for device1 in device_json1:
1405 if device1['available'] == True:
1406 counter_avail1 += 1
1407 if counter_avail1 == int(num_sw):
1408 onos1_dev = True
1409 main.log.info("All devices have been "+
1410 "discovered on ONOS1")
1411 else:
1412 counter_avail1 = 0
1413 for device2 in device_json2:
1414 if device2['available'] == True:
1415 counter_avail2 += 1
1416 if counter_avail2 == int(num_sw):
1417 onos2_dev = True
1418 main.log.info("All devices have been "+
1419 "discovered on ONOS2")
1420 else:
1421 counter_avail2 = 0
1422 for device3 in device_json3:
1423 if device3['available'] == True:
1424 counter_avail3 += 1
1425 if counter_avail3 == int(num_sw):
1426 onos3_dev = True
1427 main.log.info("All devices have been "+
1428 "discovered on ONOS3")
1429 else:
1430 counter_avail3 = 0
1431
1432 if onos1_dev and onos2_dev and onos3_dev:
1433 main.log.info("All devices have been discovered "+
1434 "on all ONOS instances")
1435 json_str_topology_metrics_1 =\
1436 main.ONOS1cli.topology_events_metrics()
1437 json_str_topology_metrics_2 =\
1438 main.ONOS2cli.topology_events_metrics()
1439 json_str_topology_metrics_3 =\
1440 main.ONOS3cli.topology_events_metrics()
andrewonlab53b641c2014-10-31 19:44:44 -04001441
1442 #Exit while loop if all devices discovered
andrewonlab16ce4852014-10-30 13:41:09 -04001443 break
1444
1445 counter_loop += 1
1446 #Give some time in between CLI calls
1447 #(will not affect measurement)
1448 time.sleep(3)
1449
1450 main.ONOS1.tshark_stop()
1451
1452 os.system("scp "+ONOS_user+"@"+ONOS1_ip+":"+
1453 tshark_ofp_output+" /tmp/")
andrewonlab53b641c2014-10-31 19:44:44 -04001454 os.system("scp "+ONOS_user+"@"+ONOS1_ip+":"+
1455 tshark_tcp_output+" /tmp/")
andrewonlab16ce4852014-10-30 13:41:09 -04001456
andrewonlab16ce4852014-10-30 13:41:09 -04001457 #TODO: Automate OFP output analysis
andrewonlab58f7d702014-11-07 13:21:19 -05001458 #Debug mode - print out packets captured at runtime
1459 if debug_mode == 'on':
1460 ofp_file = open(tshark_ofp_output, 'r')
1461 main.log.info("Tshark OFP Vendor output: ")
1462 for line in ofp_file:
1463 tshark_ofp_result_list.append(line)
andrewonlabe5bcef92014-11-06 17:53:20 -05001464 main.log.info(line)
andrewonlab58f7d702014-11-07 13:21:19 -05001465 ofp_file.close()
andrewonlab16ce4852014-10-30 13:41:09 -04001466
andrewonlab58f7d702014-11-07 13:21:19 -05001467 tcp_file = open(tshark_tcp_output, 'r')
1468 main.log.info("Tshark TCP 74 output: ")
1469 for line in tcp_file:
1470 tshark_tcp_result_list.append(line)
andrewonlabe5bcef92014-11-06 17:53:20 -05001471 main.log.info(line)
andrewonlab58f7d702014-11-07 13:21:19 -05001472 tcp_file.close()
andrewonlab53b641c2014-10-31 19:44:44 -04001473
andrewonlab16ce4852014-10-30 13:41:09 -04001474 json_obj_1 = json.loads(json_str_topology_metrics_1)
1475 json_obj_2 = json.loads(json_str_topology_metrics_2)
1476 json_obj_3 = json.loads(json_str_topology_metrics_3)
1477
1478 graph_timestamp_1 = \
1479 json_obj_1[graphTimestamp]['value']
1480 graph_timestamp_2 = \
1481 json_obj_2[graphTimestamp]['value']
1482 graph_timestamp_3 = \
1483 json_obj_3[graphTimestamp]['value']
1484
andrewonlabe5bcef92014-11-06 17:53:20 -05001485 graph_lat_1 = int(graph_timestamp_1) - int(t0_system)
1486 graph_lat_2 = int(graph_timestamp_2) - int(t0_system)
1487 graph_lat_3 = int(graph_timestamp_3) - int(t0_system)
andrewonlab16ce4852014-10-30 13:41:09 -04001488
andrewonlabe5bcef92014-11-06 17:53:20 -05001489 avg_graph_lat = \
1490 (int(graph_lat_1) +\
1491 int(graph_lat_2) +\
1492 int(graph_lat_3)) / 3
1493
1494 if avg_graph_lat > sw_disc_threshold_min \
1495 and avg_graph_lat < sw_disc_threshold_max:
1496 sw_discovery_lat_list.append(
1497 avg_graph_lat)
1498 else:
1499 main.log.info("100 Switch discovery latency "+
1500 "exceeded the threshold.")
1501
1502 #END ITERATION FOR LOOP
andrewonlab16ce4852014-10-30 13:41:09 -04001503
andrewonlabe5bcef92014-11-06 17:53:20 -05001504 sw_lat_min = min(sw_discovery_lat_list)
1505 sw_lat_max = max(sw_discovery_lat_list)
1506 sw_lat_avg = sum(sw_discovery_lat_list) /\
1507 len(sw_discovery_lat_list)
andrewonlab16ce4852014-10-30 13:41:09 -04001508
andrewonlabe5bcef92014-11-06 17:53:20 -05001509 main.log.report("100 Switch discovery lat - \n"+\
1510 "Min: "+str(sw_lat_min)+" ms\n"+\
1511 "Max: "+str(sw_lat_max)+" ms\n"+\
1512 "Avg: "+str(sw_lat_avg)+" ms\n")
andrewonlab16ce4852014-10-30 13:41:09 -04001513
andrewonlabb54b85b2014-10-28 18:43:57 -04001514