diff --git a/ci-scripts/cls_containerize.py b/ci-scripts/cls_containerize.py index dff5b418c0..07bc90dd02 100644 --- a/ci-scripts/cls_containerize.py +++ b/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[0-9\.]+)(?P[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[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[0-9\.]+) +sec +[0-9\.]+ [KMG]Bytes +(?P[0-9\.]+) (?P[KMG])bits\/sec +(?P[0-9\.]+) ms +(\d+\/ ..\d+) +(\((?P[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) + 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 - - # Computing the requested bandwidth in float - result = re.search('-b (?P[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[0-9\.]+ [KMG]bits\/sec) +(?P[0-9\.]+ ms) +(\d+\/ ..\d+) +(\((?P[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[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()