IperfFromContainer: handle unidirectional iperfs

- Refactor iperf analysis into IperfAnalyze function
- IperfAnalyze uses server report, or uses last client report (for MBMS
  case)
- Additional check: duration as recognized in server/client report is
  according to command line

ci-scripts/cls_containerize.py

@@ -151,6 +151,97 @@ def AnalyzeBuildLogs(buildRoot, images, globalStatus):
 		collectInfo[image] = files
 	return collectInfo
 
+def AnalyzeIperf(cliOptions, clientReport, serverReport):
+	req_bw = 1.0 # default iperf throughput, in Mbps
+	result = re.search('-b *(?P<iperf_bandwidth>[0-9\.]+)(?P<magnitude>[KMG])', cliOptions)
+	if result is not None:
+		req_bw = float(result.group('iperf_bandwidth'))
+		magn = result.group('magnitude')
+		if magn == "K":
+			req_bw /= 1000
+		elif magn == "G":
+			req_bw *= 1000
+	req_dur = 10 # default iperf send duration
+	result = re.search('-t *(?P<duration>[0-9]+)', cliOptions)
+	if result is not None:
+		req_dur = int(result.group('duration'))
+
+	reportLine = None
+	# find server report in client status
+	clientReportLines = clientReport.split('\n')
+	for l in range(len(clientReportLines)):
+		res = re.search('read failed: Connection refused', clientReportLines[l])
+		if res is not None:
+			message = 'iperf connection refused by server!'
+			logging.error(f'\u001B[1;37;41mIperf Test FAIL: {message}\u001B[0m')
+			return (False, message)
+		res = re.search('Server Report:', clientReportLines[l])
+		if res is not None and l + 1 < len(clientReportLines):
+			reportLine = clientReportLines[l+1]
+			logging.debug(f'found server report: "{reportLine}"')
+
+	statusTemplate = '(?:|\[ *\d+\].*) +0\.0-(?P<duration>[0-9\.]+) +sec +[0-9\.]+ [KMG]Bytes +(?P<bitrate>[0-9\.]+) (?P<magnitude>[KMG])bits\/sec +(?P<jitter>[0-9\.]+) ms +(\d+\/ ..\d+) +(\((?P<packetloss>[0-9\.]+)%\))'
+	# if we do not find a server report in the client logs, check the server logs
+	# and use the last line which is typically close/identical to server report
+	if reportLine is None:
+		for l in serverReport.split('\n'):
+			res = re.search(statusTemplate, l)
+			if res is not None:
+				reportLine = l
+		if reportLine is None:
+			logging.warning('no report in server status found!')
+			return (False, 'could not parse iperf logs')
+		logging.debug(f'found client status: {reportLine}')
+
+	result = re.search(statusTemplate, reportLine)
+	if result is None:
+		logging.error('could not analyze report from statusTemplate')
+		return (False, 'could not parse iperf logs')
+
+	duration = float(result.group('duration'))
+	bitrate = float(result.group('bitrate'))
+	magn = result.group('magnitude')
+	if magn == "K":
+		bitrate *= 1000
+	elif magn == "G": # we assume bitrate in Mbps, therefore it must be G now
+		bitrate /= 1000
+	jitter = float(result.group('jitter'))
+	packetloss = float(result.group('packetloss'))
+
+	logging.debug('\u001B[1;37;44m iperf result \u001B[0m')
+	msg = f'Req Bitrate: {req_bw}'
+	logging.debug(f'\u001B[1;34m{msg}\u001B[0m')
+
+	br_loss = bitrate/req_bw
+	bmsg = f'Bitrate    : {bitrate} (perf {br_loss})'
+	logging.debug(f'\u001B[1;34m{bmsg}\u001B[0m')
+	msg += '\n' + bmsg
+	if br_loss < 0.9:
+		msg += '\nBitrate performance too low (<90%)'
+		logging.debug(f'\u001B[1;37;41mBitrate performance too low (<90%)\u001B[0m')
+		return (False, msg)
+
+	plmsg = f'Packet Loss: {packetloss}%'
+	logging.debug(f'\u001B[1;34m{plmsg}\u001B[0m')
+	msg += '\n' + plmsg
+	if packetloss > 5.0:
+		msg += '\nPacket Loss too high!'
+		logging.debug(f'\u001B[1;37;41mPacket Loss too high \u001B[0m')
+		return (False, msg)
+
+	dmsg = f'Duration   : {duration} (req {req_dur})'
+	logging.debug(f'\u001B[1;34m{dmsg}\u001B[0m')
+	msg += '\n' + dmsg
+	if duration < float(req_dur):
+		msg += '\nDuration of iperf too short!'
+		logging.debug(f'\u001B[1;37;41mDuration of iperf too short\u001B[0m')
+		return (False, msg)
+
+	jmsg = f'Jitter     : {jitter}'
+	logging.debug(f'\u001B[1;34m{jmsg}\u001B[0m')
+	msg += '\n' + jmsg
+	return (True, msg)
+
 #-----------------------------------------------------------
 # Class Declaration
 #-----------------------------------------------------------
@@ -1354,110 +1445,36 @@ class Containerize():
 		logStatus = subprocess.check_output(cmd, shell=True, stderr=subprocess.STDOUT, universal_newlines=True, timeout=10)
 
 		# Start the server process
-		cmd = 'docker exec -d ' + self.svrContName + ' /bin/bash -c "nohup iperf ' + self.svrOptions + ' > /tmp/iperf_server.log 2>&1" || true'
+		cmd = f'docker exec -d {self.svrContName} /bin/bash -c "nohup iperf {self.svrOptions} > /tmp/iperf_server.log 2>&1"'
 		logging.info(cmd)
-		serverStatus = subprocess.check_output(cmd, shell=True, stderr=subprocess.STDOUT, universal_newlines=True, timeout=10)
-		time.sleep(5)
+		subprocess.check_output(cmd, shell=True, stderr=subprocess.STDOUT, universal_newlines=True, timeout=10)
+		time.sleep(3)
 
 		# Start the client process
-
-		cmd = 'docker exec ' + self.cliContName + ' /bin/bash -c "iperf ' + self.cliOptions + '" 2>&1 | tee '+ logPath + '/iperf_client_' + HTML.testCase_id + '.log || true'
+		cmd = f'docker exec {self.cliContName} /bin/bash -c "iperf {self.cliOptions}" 2>&1 | tee {logPath}/iperf_client_{HTML.testCase_id}.log'
 		logging.info(cmd)
 		clientStatus = subprocess.check_output(cmd, shell=True, stderr=subprocess.STDOUT, universal_newlines=True, timeout=100)
 
 		# Stop the server process
-		cmd = 'docker exec ' + self.svrContName + ' /bin/bash -c "pkill iperf" || true'
+		cmd = f'docker exec {self.svrContName} /bin/bash -c "pkill iperf"'
 		logging.info(cmd)
-		serverStatus = subprocess.check_output(cmd, shell=True, stderr=subprocess.STDOUT, universal_newlines=True, timeout=10)
-		time.sleep(5)
-		cmd = 'docker cp ' + self.svrContName + ':/tmp/iperf_server.log '+ logPath + '/iperf_server_' + HTML.testCase_id + '.log'
+		subprocess.check_output(cmd, shell=True, stderr=subprocess.STDOUT, universal_newlines=True, timeout=10)
+		time.sleep(3)
+		serverStatusFilename = f'{logPath}/iperf_server_{HTML.testCase_id}.log'
+		cmd = f'docker cp {self.svrContName}:/tmp/iperf_server.log {serverStatusFilename}'
 		logging.info(cmd)
-		serverStatus = subprocess.check_output(cmd, shell=True, stderr=subprocess.STDOUT, universal_newlines=True, timeout=30)
-
-		# Analyze client output
-		result = re.search('Server Report:', clientStatus)
-		if result is None:
-			result = re.search('read failed: Connection refused', clientStatus)
-			if result is not None:
-				message = 'Could not connect to iperf server!'
-			else:
-				message = 'Server Report and Connection refused Not Found!'
-			self.IperfExit(HTML, RAN, UE, False, message)
-			logging.error('\u001B[1;37;41m Iperf Test FAIL\u001B[0m')
-			return
+		subprocess.check_output(cmd, shell=True, stderr=subprocess.STDOUT, universal_newlines=True, timeout=30)
 
-		# Computing the requested bandwidth in float
-		result = re.search('-b (?P<iperf_bandwidth>[0-9\.]+)[KMG]', self.cliOptions)
-		if result is not None:
-			req_bandwidth = result.group('iperf_bandwidth')
-			req_bw = float(req_bandwidth)
-			result = re.search('-b [0-9\.]+K', self.cliOptions)
-			if result is not None:
-				req_bandwidth = '%.1f Kbits/sec' % req_bw
-				req_bw = req_bw * 1000
-			result = re.search('-b [0-9\.]+M', self.cliOptions)
-			if result is not None:
-				req_bandwidth = '%.1f Mbits/sec' % req_bw
-				req_bw = req_bw * 1000000
-
-		reportLine = None
-		reportLineFound = False
-		for iLine in clientStatus.split('\n'):
-			if reportLineFound:
-				reportLine = iLine
-				reportLineFound = False
-			res = re.search('Server Report:', iLine)
-			if res is not None:
-				reportLineFound = True
-		result = None
-		if reportLine is not None:
-			result = re.search('(?:|\[ *\d+\].*) (?P<bitrate>[0-9\.]+ [KMG]bits\/sec) +(?P<jitter>[0-9\.]+ ms) +(\d+\/ ..\d+) +(\((?P<packetloss>[0-9\.]+)%\))', reportLine)
-		iperfStatus = True
-		if result is not None:
-			bitrate = result.group('bitrate')
-			packetloss = result.group('packetloss')
-			jitter = result.group('jitter')
-			logging.debug('\u001B[1;37;44m iperf result \u001B[0m')
-			iperfStatus = True
-			msg = 'Req Bitrate : ' + req_bandwidth + '\n'
-			logging.debug('\u001B[1;34m    Req Bitrate : ' + req_bandwidth + '\u001B[0m')
-			if bitrate is not None:
-				msg += 'Bitrate     : ' + bitrate + '\n'
-				logging.debug('\u001B[1;34m    Bitrate     : ' + bitrate + '\u001B[0m')
-				result = re.search('(?P<real_bw>[0-9\.]+) [KMG]bits/sec', str(bitrate))
-				if result is not None:
-					actual_bw = float(str(result.group('real_bw')))
-					result = re.search('[0-9\.]+ K', bitrate)
-					if result is not None:
-						actual_bw = actual_bw * 1000
-					result = re.search('[0-9\.]+ M', bitrate)
-					if result is not None:
-						actual_bw = actual_bw * 1000000
-					br_loss = 100 * actual_bw / req_bw
-					if br_loss < 90:
-						iperfStatus = False
-					bitperf = '%.2f ' % br_loss
-					msg += 'Bitrate Perf: ' + bitperf + '%\n'
-					logging.debug('\u001B[1;34m    Bitrate Perf: ' + bitperf + '%\u001B[0m')
-			if packetloss is not None:
-				msg += 'Packet Loss : ' + packetloss + '%\n'
-				logging.debug('\u001B[1;34m    Packet Loss : ' + packetloss + '%\u001B[0m')
-				if float(packetloss) > float(5):
-					msg += 'Packet Loss too high!\n'
-					logging.debug('\u001B[1;37;41m Packet Loss too high \u001B[0m')
-					iperfStatus = False
-			if jitter is not None:
-				msg += 'Jitter      : ' + jitter + '\n'
-				logging.debug('\u001B[1;34m    Jitter      : ' + jitter + '\u001B[0m')
-			self.IperfExit(HTML, RAN, UE, iperfStatus, msg)
-		else:
-			iperfStatus = False
-			logging.error('problem?')
-			self.IperfExit(HTML, RAN, UE, iperfStatus, 'problem?')
+		# clientStatus was retrieved above. The serverStatus was
+		# written in the background, then copied to the local machine
+		with open(serverStatusFilename, 'r') as f:
+			serverStatus = f.read()
+		(iperfStatus, msg) = AnalyzeIperf(self.cliOptions, clientStatus, serverStatus)
 		if iperfStatus:
 			logging.info('\u001B[1m Iperf Test PASS\u001B[0m')
 		else:
 			logging.error('\u001B[1;37;41m Iperf Test FAIL\u001B[0m')
+		self.IperfExit(HTML, RAN, UE, iperfStatus, msg)
 
 	def IperfExit(self, HTML, RAN, UE, status, message):
 		html_queue = SimpleQueue()