Initial code for log analysis

- we agreed to basically throw away the old log checker (as it is
  unmaintainable)
- now: provide list of analysis to do
  * all checkers in cls_log_analysis, can be unit tested (see also next
    commit)
  * looked up dynamically to simplify adding of new tests + config
  * configured with

      <analysis>
        <services>DESCRIPTION [DESCRIPTION...]</services>
        <service>DESCRIPTION</service>
        ...
      </analysis>

    where DESCRIPTION follows service=func[=options]:
    - service is name of service to check
    - func is function to call, which receives filename
    - option are arbitary options to pass to func
    <services> is whitespace delimited (so can take multiple service
    analysis definitions)
    <service> exists to allow service definitions with whitespace
    changes that would not work in <services>
- I initially planned to check return code, but most softmodems actually
  exit with non-zero return code, so this is still TODO
- Default analyzer (checking for assertions, ...) is always run if a
  service is listed
- checks for file size
- add unit tests

ci-scripts/cls_analysis.py

@@ -24,10 +24,13 @@ import re
 import os
 import logging
 import yaml
+import signal
 
 import xml.etree.ElementTree as ET
 import json
 
+import importlib, inspect
+
 class Analysis():
 
 	def _get_test_description(properties):
@@ -147,3 +150,98 @@ class Analysis():
 				logging.debug(f'\u001B[1;30;43m normalized metric {k}={valnorm} deviates by more than {dev}\u001B[0m')
 				success = False
 		return success, datalog_rt_stats
+
+
+# returns tuple of (service, analyzer, option string)
+def _lookupServiceAnalyzerOpt(s, analyzers):
+	res = s.split("=", 2)
+	name = res[0]
+	if len(res) == 1:
+		return res[0], analyzers["Default"], None
+	opt = res[2] if len(res) > 2 else None
+	func = res[1]
+	a = analyzers[func] if func in analyzers else None
+	return name, a, opt
+
+# groups requested service analysis (service=func[=option]) on per service
+# basis and looks up analyzer func. If log analysis is requested, will always
+# run Default log analysis
+def _groupServices(to_analyze):
+	req_analysis = {}
+	# get content of cls_loganalysis module, then get all analyzers (classes) in this module
+	mod = importlib.import_module("cls_loganalysis")
+	analyzers = {name:cl for name, cl in inspect.getmembers(mod, inspect.isclass)}
+	for req in to_analyze:
+		s, func, opt = _lookupServiceAnalyzerOpt(req, analyzers)
+		logging.debug(f"requested check '{req}' => service {s}, function {func.__name__}, options '{opt}'")
+		# always put default analyzer first
+		l = req_analysis[s] if s in req_analysis else [(analyzers["Default"], None, "default")]
+		if func is not analyzers["Default"]:
+			l.append((func, opt, req))
+		req_analysis[s] = l
+	return req_analysis
+
+def _describe_exit_code(code):
+	if code > 128:
+		sig = code - 128
+		try:
+			return f"terminated by signal {sig} ({signal.Signals(sig).name})"
+		except ValueError:
+			return f"terminated by unknown signal {sig}"
+	else:
+		return f"custom exit code"
+
+def AnalyzeServices(HTML, service_desc, to_analyze):
+	success = True
+	# hack: we want to give as a description "log analysis", but the description
+	# is set outside, so retain what was set before
+	orig_html_desc = HTML.desc
+	# group analysis on a per-service basis, then iterate
+	for serv, list_analysis in _groupServices(to_analyze).items():
+		HTML.desc = f"Log analysis for service {serv}"
+		if serv not in service_desc:
+			success = False
+			logging.error(f"requested service {serv} not in list of services")
+			HTML.CreateHtmlTestRowQueue("N/A", 'KO', ["service not detected"])
+			continue
+		# pre-initialize with return code
+		rc = service_desc[serv]["returncode"]
+		logging.info(f"analyze service {serv}: return code {rc}")
+		service_success = True # TODO rc == 0: too many functions (eNB, lteUE, RIC, nrUE) fail non-zero
+		logs = []
+		if rc != 0:
+			logs.append(f"=> return code {rc}, likely " + _describe_exit_code(rc) + " [ignored by CI]")
+		# skip if the file is too big
+		logfile = service_desc[serv]["logfile"]
+		filename = os.path.basename(logfile)
+		b = os.path.getsize(logfile)
+		logging.debug(f"using logfile {logfile} of size {b} bytes")
+		if b > 10 * 1024 * 1024:
+			success = False
+			logs.append(f"logfile too big (>10MB)")
+			logging.error(logs)
+			HTML.CreateHtmlTestRowQueue(filename, 'KO', ["\n".join(logs)])
+			continue
+		# run each analyzer with its options on the logfile
+		for (func, opt, desc) in list_analysis:
+			if func is None:
+				service_success = False
+				logging.error(f"request analysis function for desc {desc} not found")
+				HTML.CreateHtmlTestRowQueue(serv, 'KO', [f"no analysis function for {desc}"])
+				continue
+			result, l = func.run(logfile, opt)
+			logging.info(f"service {serv}: analysis with func {func}, result {result}, logs '{l}'")
+			service_success = service_success and result
+			if not result:
+				logs.append(f"=> {func.__name__} check (options '{opt}') FAILED")
+				logs.append(l)
+		logs = '\n'.join(logs)
+		if not service_success:
+			logging.error(l)
+		else:
+			logging.info(l)
+		all_funcs = ", ".join([f.__name__ for (f, _, _) in list_analysis])
+		HTML.CreateHtmlTestRowQueue(f"Check {all_funcs} on {filename}", 'OK' if service_success else 'KO', [logs])
+		success = success and service_success
+	HTML.desc = orig_html_desc
+	return success

ci-scripts/cls_containerize.py

@@ -46,6 +46,7 @@ import cls_cmd
 import helpreadme as HELP
 import constants as CONST
 import cls_oaicitest
+import cls_analysis
 from cls_ci_helper import archiveArtifact
 from collections import deque
 
@@ -808,7 +809,7 @@ class Containerize():
 			HTML.CreateHtmlTestRowQueue(self.services, 'KO', [f'Failed stopping {" ".join(fail)}, succeeded {" ".join(success)}'])
 		return success
 
-	def UndeployObject(self, ctx, node, HTML, RAN):
+	def UndeployObject(self, ctx, node, HTML, to_analyze):
 		lSourcePath = self.eNBSourceCodePath
 		logging.info(f'\u001B[1m Undeploying all objects from server {node}\u001B[0m')
 		yaml = self.yamlPath.strip('/')
@@ -817,21 +818,27 @@ class Containerize():
 		with cls_cmd.getConnection(node) as ssh:
 			ExistEnvFilePrint(ssh, wd)
 			services = GetDeployedServices(ssh, wd_yaml)
-			copyin_res = None
+			all_logs = True
 			ssh.run(f'docker compose -f {wd_yaml} stop')
 			if services is not None:
-				copyin_res = [CopyinServiceLog(ssh, lSourcePath, s, wd_yaml, ctx) for s, _ in services]
+				service_desc = {}
+				for s, c in services:
+					ret = ssh.run(f'docker inspect {c} --format="{{{{.State.ExitCode}}}}"')
+					rc = int(ret.stdout.strip())
+					f = CopyinServiceLog(ssh, lSourcePath, s, wd_yaml, ctx)
+					all_logs = all_logs and f is not None
+					service_desc[s] = {'returncode': rc, 'logfile': f}
 			else:
 				logging.warning('could not identify services to stop => no log file')
 			ssh.run(f'docker compose -f {wd_yaml} down -v')
+			HTML.CreateHtmlTestRowQueue(node, 'OK', ['Undeployment successful'])
 			ssh.run(f'rm {wd}/.env')
-		if not copyin_res:
+		if not all_logs:
 			HTML.CreateHtmlTestRowQueue('N/A', 'KO', ['Could not copy logfile(s)'])
-			logging.error(f"could not copy all files: {copyin_res=} {services=}")
+			logging.error(f"could not copy all files: {all_logs=} {services=}")
 			success = False
 		else:
-			log_results = [CheckLogs(self, f, HTML, RAN) for f in copyin_res]
+			success = cls_analysis.AnalyzeServices(HTML, service_desc, to_analyze)
-			success = all(log_results)
 		if success:
 			logging.info('\u001B[1m Undeploying objects Pass\u001B[0m')
 		else:

ci-scripts/cls_loganalysis.py

@@ -0,0 +1,40 @@
+#/*
+# * Licensed to the OpenAirInterface (OAI) Software Alliance under one or more
+# * contributor license agreements.  See the NOTICE file distributed with
+# * this work for additional information regarding copyright ownership.
+# * The OpenAirInterface Software Alliance licenses this file to You under
+# * the OAI Public License, Version 1.1  (the "License"); you may not use this file
+# * except in compliance with the License.
+# * You may obtain a copy of the License at
+# *
+# *	  http://www.openairinterface.org/?page_id=698
+# *
+# * Unless required by applicable law or agreed to in writing, software
+# * distributed under the License is distributed on an "AS IS" BASIS,
+# * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# * See the License for the specific language governing permissions and
+# * limitations under the License.
+# *-------------------------------------------------------------------------------
+# * For more information about the OpenAirInterface (OAI) Software Alliance:
+# *	  contact@openairinterface.org
+# */
+#---------------------------------------------------------------------
+
+import re
+import os
+import logging
+
+class Default:
+	def run(file, opt=None):
+		# TODO add check on assertions, etc
+		if not os.path.exists(file):
+			return False, f"cannot find file {file}"
+		return True, ""
+
+class ContainsString:
+	def run(file, needle):
+		with open(file, "r") as f:
+			for line in f.readlines():
+				if re.search(needle, line):
+					return True, ""
+		return False, f"could not find '{needle}' in logs"

ci-scripts/main.py

@@ -115,7 +115,14 @@ def ExecuteActionWithParam(action, ctx, node):
 		string_field=test.findtext('u_retx_th')
 		if (string_field is not None):
 			RAN.ran_checkers['u_retx_th'] = [float(x) for x in string_field.split(',')]
-		success = RAN.TerminateeNB(ctx, node, HTML)
+		services = []
+		analysis = test.find("analysis")
+		if analysis is not None:
+			# services: multiple services to analyse, separated by whitespace
+			services = analysis.findtext("services", default="").split()
+			# service: individual services to analyze, in case they have whitespace
+			services = services + [s.text for s in analysis.findall("service")]
+		success = RAN.TerminateeNB(ctx, node, HTML, services)
 
 	elif action == 'Initialize_UE' or action == 'Attach_UE' or action == 'Detach_UE' or action == 'Terminate_UE' or action == 'CheckStatusUE' or action == 'DataEnable_UE' or action == 'DataDisable_UE':
 		CiTestObj.ue_ids = test.findtext('id').split(' ')
@@ -188,12 +195,6 @@ def ExecuteActionWithParam(action, ctx, node):
 
 	elif action == 'Deploy_Object' or action == 'Undeploy_Object' or action == "Create_Workspace" or action == "Stop_Object":
 		CONTAINERS.yamlPath = test.findtext('yaml_path')
-		string_field=test.findtext('d_retx_th')
-		if (string_field is not None):
-			CONTAINERS.ran_checkers['d_retx_th'] = [float(x) for x in string_field.split(',')]
-		string_field=test.findtext('u_retx_th')
-		if (string_field is not None):
-			CONTAINERS.ran_checkers['u_retx_th'] = [float(x) for x in string_field.split(',')]
 		CONTAINERS.services = test.findtext('services')
 		CONTAINERS.num_attempts = int(test.findtext('num_attempts') or 1)
 		CONTAINERS.deploymentTag = cls_containerize.CreateTag(CONTAINERS.ranCommitID, CONTAINERS.ranBranch, CONTAINERS.ranAllowMerge)
@@ -202,7 +203,14 @@ def ExecuteActionWithParam(action, ctx, node):
 		elif action == 'Stop_Object':
 			success = CONTAINERS.StopObject(ctx, node, HTML)
 		elif action == 'Undeploy_Object':
-			success = CONTAINERS.UndeployObject(ctx, node, HTML, RAN)
+			analysis = test.find("analysis")
+			services = []
+			if analysis is not None:
+				# services: multiple services to analyse, separated by whitespace
+				services = analysis.findtext("services", default="").split()
+				# service: individual services to analyze, in case they have whitespace
+				services = services + [s.text for s in analysis.findall("service")]
+			success = CONTAINERS.UndeployObject(ctx, node, HTML, services)
 		elif action == 'Create_Workspace':
 			if force_local:
 				# Do not create a working directory when running locally. Current repo directory will be used

ci-scripts/ran.py

@@ -127,7 +127,7 @@ class RANManagement():
 
 		return enbDidSync
 
-	def TerminateeNB(self, ctx, node, HTML):
+	def TerminateeNB(self, ctx, node, HTML, to_analyze):
 		logging.debug('Stopping eNB/gNB on server: ' + node)
 		lSourcePath = self.eNBSourceCodePath
 		cmd = cls_cmd.getConnection(node)
@@ -142,6 +142,7 @@ class RANManagement():
 		if result is not None:
 			cmd.run('sudo -S killall --signal SIGKILL -r .*-softmodem')
 			time.sleep(5)
+		HTML.CreateHtmlTestRowQueue(node, 'OK', ['Undeployment successful'])
 
 		# see InitializeeNB()
 		logfile = f'{lSourcePath}/cmake_targets/enb.log'
@@ -156,13 +157,10 @@ class RANManagement():
 			return False
 
 		logging.debug('\u001B[1m Analyzing xNB logfile \u001B[0m ' + file)
-		logStatus = self.AnalyzeLogFile_eNB(file, HTML, self.ran_checkers)
+		service_desc = {}
-		if logStatus < 0:
+		service_desc["nr-softmodem"] = {'returncode': 0, 'logfile': file}
-			HTML.CreateHtmlTestRow('N/A', 'KO', logStatus)
+		success = cls_analysis.AnalyzeServices(HTML, service_desc, to_analyze)
-		else:
+		return success
-			HTML.CreateHtmlTestRow(self.runtime_stats, 'OK', CONST.ALL_PROCESSES_OK)
-
-		return logStatus >= 0
 
 	def AnalyzeRTStats(self, HTML, node, ctx, thresholds):
 		logging.info(f'Analyzing realtime stats from server: {node}')

ci-scripts/tests/README.md

@@ -16,6 +16,7 @@ To run individual unit tests, start them like so:
     python tests/corenetwork.py -v
     python tests/deployment.py -v
     python tests/iperf-analysis.py -v
+    python tests/log-analysis.py -v
     python tests/ping-iperf.py -v
     python tests/pull-clean-int-registry.py -v
 

ci-scripts/tests/analysis.py

@@ -53,5 +53,19 @@ class TestAnalysis(unittest.TestCase):
 		# TODO this one is not found, the CI does not recover this??
 		#self.assertEqual(s['Data']['DL & UL scheduling timing'], ['17', '97', '159371', '1.14'])
 
+	def test_analze_services_no_service(self):
+		service_desc = {} # nothing to analyze
+		to_analyze = ["testserv"] # some service requested to be analyze that does not exist
+		status = cls_analysis.AnalyzeServices(self.html, service_desc, to_analyze)
+		self.assertFalse(status)
+
+	# TODO this does not work: we don't evaluate return codes yet
+	#def test_analze_service_exit_nonnull(self):
+	#	service_desc = {}
+	#	service_desc["testserv"] = {'returncode': 129, 'logfile': 'tests/log-analysis/empty.log'}
+	#	to_analyze = ["testserv"] # some service requested to be analyze that does not exist
+	#	status = cls_analysis.AnalyzeServices(self.html, service_desc, to_analyze)
+	#	self.assertFalse(status)
+
 if __name__ == '__main__':
 	unittest.main()

ci-scripts/tests/deployment.py

@@ -16,7 +16,6 @@ import cls_oai_html
 import cls_oaicitest
 import cls_containerize
 from cls_ci_helper import TestCaseCtx
-import ran
 import cls_cmd
 
 class TestDeploymentMethods(unittest.TestCase):
@@ -39,7 +38,6 @@ class TestDeploymentMethods(unittest.TestCase):
 		self.html.testCaseId = "000000"
 		self.ci = cls_oaicitest.OaiCiTest()
 		self.cont = cls_containerize.Containerize()
-		self.ran = ran.RANManagement()
 		self.cont.yamlPath = ''
 		self.cont.ranAllowMerge = True
 		self.cont.ranBranch = ''
@@ -56,7 +54,7 @@ class TestDeploymentMethods(unittest.TestCase):
 		self.cont.yamlPath = 'tests/simple-dep/'
 		self.cont.deploymentTag = "noble"
 		deploy = self.cont.DeployObject(self.ctx, self.node, self.html)
-		undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, self.ran)
+		undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, [])
 		self.assertTrue(deploy)
 		self.assertTrue(undeploy)
 
@@ -79,7 +77,7 @@ class TestDeploymentMethods(unittest.TestCase):
 		stopB = self.cont.StopObject(self.ctx, self.node, self.html)
 		# should not undeploy anything (everything already stopped)
 		self.cont.services = None
-		undeployAll = self.cont.UndeployObject(self.ctx, self.node, self.html, self.ran)
+		undeployAll = self.cont.UndeployObject(self.ctx, self.node, self.html, [])
 		self.assertTrue(deploy)
 		self.assertFalse(stopC)
 		self.assertTrue(stopA)
@@ -92,7 +90,7 @@ class TestDeploymentMethods(unittest.TestCase):
 		old = self.cont.yamlPath
 		self.cont.yamlPath = 'tests/simple-fail/'
 		deploy = self.cont.DeployObject(self.ctx, self.node, self.html)
-		self.cont.UndeployObject(self.ctx, self.node, self.html, self.ran)
+		self.cont.UndeployObject(self.ctx, self.node, self.html, [])
 		self.assertFalse(deploy)
 		self.cont.yamlPath = old
 
@@ -101,7 +99,7 @@ class TestDeploymentMethods(unittest.TestCase):
 		old = self.cont.yamlPath
 		self.cont.yamlPath = 'tests/simple-fail-2svc/'
 		deploy = self.cont.DeployObject(self.ctx, self.node, self.html)
-		self.cont.UndeployObject(self.ctx, self.node, self.html, self.ran)
+		self.cont.UndeployObject(self.ctx, self.node, self.html, [])
 		self.assertFalse(deploy)
 		self.cont.yamlPath = old
 
@@ -110,7 +108,7 @@ class TestDeploymentMethods(unittest.TestCase):
 		self.cont.services = "oai-gnb"
 		self.cont.deploymentTag = 'develop-12345678'
 		deploy = self.cont.DeployObject(self.ctx, self.node, self.html)
-		undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, self.ran)
+		undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, [])
 		self.assertTrue(deploy)
 		self.assertTrue(undeploy)
 
@@ -119,7 +117,7 @@ class TestDeploymentMethods(unittest.TestCase):
 		self.cont.services = "oai-gnb oai-nr-ue"
 		self.cont.deploymentTag = 'develop-12345678'
 		deploy = self.cont.DeployObject(self.ctx, self.node, self.html)
-		undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, self.ran)
+		undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, [])
 		self.assertTrue(deploy)
 		self.assertTrue(undeploy)
 
@@ -130,7 +128,7 @@ class TestDeploymentMethods(unittest.TestCase):
 		deploy1 = self.cont.DeployObject(self.ctx, self.node, self.html)
 		self.cont.services = "oai-nr-ue"
 		deploy2 = self.cont.DeployObject(self.ctx, self.node, self.html)
-		undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, self.ran)
+		undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, [])
 		self.assertTrue(deploy1)
 		self.assertTrue(deploy2)
 		self.assertTrue(undeploy)
@@ -145,5 +143,37 @@ class TestDeploymentMethods(unittest.TestCase):
 			cmd.run(f"rm -rf {self.cont.eNBSourceCodePath}")
 		self.assertTrue(ws)
 
+	def test_undeploy_loganalysis(self):
+		self.cont.yamlPath = 'yaml_files/5g_rfsimulator_tdd_dora'
+		self.cont.services = "oai-gnb"
+		self.cont.deploymentTag = 'develop-12345678'
+		deploy = self.cont.DeployObject(self.ctx, self.node, self.html)
+		analyze = ["oai-gnb"]
+		undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, analyze)
+		self.assertTrue(deploy)
+		self.assertTrue(undeploy)
+
+	def test_undeploy_multi_loganalysis(self):
+		self.cont.yamlPath = 'yaml_files/5g_rfsimulator_tdd_dora'
+		self.cont.services = "oai-gnb"
+		self.cont.deploymentTag = 'develop-12345678'
+		deploy = self.cont.DeployObject(self.ctx, self.node, self.html)
+		analyze = ["oai-gnb", "oai-gnb=ContainsString=NOTFOUND"]
+		undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, analyze)
+		self.assertTrue(deploy)
+		self.assertFalse(undeploy)
+
+	# TODO this does not work: we don't evaluate return codes yet
+	#def test_undeploy_rc_nonnull(self):
+	#	# fails reliably
+	#	old = self.cont.yamlPath
+	#	self.cont.yamlPath = 'tests/simple-fail/'
+	#	deploy = self.cont.DeployObject(self.ctx, self.node, self.html)
+	#	# should be false because wrong exit code
+	#	undeploy = self.cont.UndeployObject(self.ctx, self.node, self.html, ["test"])
+	#	self.assertFalse(deploy)
+	#	self.assertFalse(undeploy)
+	#	self.cont.yamlPath = old
+
 if __name__ == '__main__':
 	unittest.main()

ci-scripts/tests/log-analysis.py

@@ -0,0 +1,26 @@
+import sys
+import logging
+logging.basicConfig(
+	level=logging.DEBUG,
+	stream=sys.stdout,
+	format="[%(asctime)s] %(levelname)8s: %(message)s"
+)
+import os
+import unittest
+
+sys.path.append('./') # to find OAI imports below
+import cls_loganalysis
+
+class TestLogAnalysis(unittest.TestCase):
+    def test_no_file(self):
+        f = "/total/fantasy/path/file.log"
+        result, _ = cls_loganalysis.Default.run(f, None)
+        self.assertFalse(result)
+
+    def test_no_error(self):
+        f = "tests/log-analysis/empty.log"
+        result, _ = cls_loganalysis.Default.run(f, None)
+        self.assertTrue(result)
+
+if __name__ == '__main__':
+	unittest.main()

ci-scripts/xml_files/gnb_phytest_rfemulator_run_100_2x2.xml

@@ -59,6 +59,9 @@
     <node>caracal</node>
     <always_exec>true</always_exec>
     <desc>Terminate gNB</desc>
+    <analysis>
+      <service>nr-softmodem=ContainsString=Bye.</service>
+    </analysis>
   </testCase>
 
   <testCase>