Newer
Older
1001
1002
1003
1004
1005
1006
1007
1008
1009
1010
1011
1012
1013
1014
1015
1016
1017
1018
1019
1020
1021
1022
1023
1024
1025
1026
1027
1028
1029
1030
1031
1032
1033
1034
1035
1036
1037
1038
1039
1040
1041
1042
1043
1044
1045
1046
1047
1048
1049
1050
1051
1052
1053
1054
1055
1056
1057
1058
1059
1060
1061
1062
1063
1064
1065
1066
1067
1068
1069
1070
1071
1072
1073
1074
1075
1076
1077
1078
1079
1080
1081
1082
1083
1084
1085
1086
1087
1088
1089
1090
1091
1092
1093
1094
1095
1096
1097
1098
1099
1100
1101
1102
1103
1104
1105
1106
1107
1108
1109
1110
1111
1112
1113
1114
1115
1116
1117
1118
1119
1120
1121
1122
1123
1124
1125
1126
1127
1128
1129
1130
1131
1132
1133
1134
1135
1136
1137
1138
1139
1140
1141
1142
1143
1144
1145
1146
1147
1148
1149
1150
1151
1152
1153
1154
1155
1156
1157
1158
1159
1160
1161
1162
1163
1164
1165
1166
1167
1168
1169
1170
1171
1172
1173
1174
1175
1176
1177
1178
1179
1180
1181
1182
1183
1184
1185
1186
1187
1188
1189
1190
1191
1192
1193
1194
1195
1196
1197
1198
1199
1200
1201
1202
1203
1204
1205
1206
1207
1208
1209
1210
1211
1212
1213
1214
1215
1216
1217
1218
1219
1220
1221
1222
1223
1224
1225
1226
1227
1228
1229
1230
1231
1232
1233
1234
1235
1236
1237
1238
1239
1240
1241
1242
1243
1244
1245
1246
1247
1248
1249
1250
1251
1252
1253
1254
1255
1256
1257
1258
1259
1260
1261
1262
1263
1264
1265
1266
1267
1268
1269
1270
1271
1272
1273
1274
1275
1276
1277
1278
1279
1280
1281
1282
1283
1284
1285
1286
1287
1288
1289
1290
1291
1292
1293
1294
1295
1296
1297
1298
1299
1300
1301
1302
1303
1304
1305
1306
1307
1308
1309
1310
1311
1312
1313
1314
1315
1316
1317
1318
1319
1320
1321
1322
1323
1324
1325
1326
1327
1328
1329
1330
1331
1332
1333
1334
1335
1336
1337
1338
1339
1340
1341
1342
1343
1344
1345
1346
1347
1348
1349
1350
1351
1352
1353
1354
logging.error(f'did not find RNTI while matching key {k}')
continue
rnti = result.group(1)
#remove 1- all useless char before relevant info (ulsch or dlsch) 2- trailing char
if not rnti in dlsch_ulsch_stats: dlsch_ulsch_stats[rnti] = {}
dlsch_ulsch_stats[rnti][k]=re.sub(r'^.*\]\s+', r'' , line.rstrip())
result = re.search('Received NR_RRCReconfigurationComplete from UE', str(line))
if result is not None:
nrRrcRcfgComplete += 1
result = re.search('HARQ feedback is in the past', str(line))
if result is not None:
harqFeedbackPast += 1
#count "problem receiving samples" msg
result = re.search('\[PHY\]\s+problem receiving samples', str(line))
if result is not None:
pb_receiving_samples_cnt += 1
#count "Removing UE" msg
result = re.search('\[MAC\]\s+Removing UE', str(line))
if result is not None:
removing_ue += 1
#count "X2AP-PDU"
result = re.search('X2AP-PDU', str(line))
if result is not None:
x2ap_pdu += 1
#gnb markers logging
for k in gnb_markers:
result = re.search(k, line)
if result is not None:
gnb_markers[k].append(line_cnt)
# check whether e/gNB log finishes with "Bye." message
showedByeMsg |= re.search(r'^Bye.\n', str(line), re.MULTILINE) is not None
enb_log_file.close()
#the following part takes the *_stats.log files as source (not the stdout log file)
#the datalog config file has to be loaded
datalog_rt_stats_file=self.datalog_rt_stats_file
if (os.path.isfile(datalog_rt_stats_file)):
yaml_file=datalog_rt_stats_file
elif (os.path.isfile('ci-scripts/'+datalog_rt_stats_file)):
yaml_file='ci-scripts/'+datalog_rt_stats_file
else:
logging.error("Datalog RT stats yaml file cannot be found")
sys.exit("Datalog RT stats yaml file cannot be found")
with open(yaml_file,'r') as f:
datalog_rt_stats = yaml.load(f,Loader=yaml.FullLoader)
rt_keys = datalog_rt_stats['Ref'] #we use the keys from the Ref field
if os.path.isfile('./nrL1_stats.log') and os.path.isfile('./nrMAC_stats.log'):
# don't use CI-nrL1_stats.log, as this will increase the processing time for
# no reason, we just need the last occurence
nrL1_stats = open('./nrL1_stats.log', 'r')
nrMAC_stats = open('./nrMAC_stats.log', 'r')
for line in nrL1_stats.readlines():
for k in rt_keys:
result = re.search(k, line)
if result is not None:
#remove 1- all useless char before relevant info 2- trailing char
tmp=re.match(rf'^.*?(\b{k}\b.*)',line.rstrip()) #from python 3.6 we can use literal string interpolation for the variable k, using rf' in the regex
if tmp!=None:
real_time_stats[k]=tmp.group(1)
for line in nrMAC_stats.readlines():
for k in rt_keys:
result = re.search(k, line)
if result is not None:
#remove 1- all useless char before relevant info 2- trailing char
tmp=re.match(rf'^.*?(\b{k}\b.*)',line.rstrip()) #from python 3.6 we can use literal string interpolation for the variable k, using rf' in the regex
if tmp!=None:
real_time_stats[k]=tmp.group(1)
nrL1_stats.close()
nrMAC_stats.close()
else:
logging.debug("NR Stats files for RT analysis not found")
#stdout log file and stat log files analysis completed
logging.debug(' File analysis (stdout, stats) completed')
#post processing depending on the node type
if not nodeB_prefix_found:
if self.air_interface[self.eNB_instance] == 'lte-softmodem':
nodeB_prefix = 'e'
else:
nodeB_prefix = 'g'
if nodeB_prefix == 'g':
if ulschReceiveOK > 0:
statMsg = nodeB_prefix + 'NB showed ' + str(ulschReceiveOK) + ' "ULSCH received ok" message(s)'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
if gnbRxTxWakeUpFailure > 0:
statMsg = nodeB_prefix + 'NB showed ' + str(gnbRxTxWakeUpFailure) + ' "could not wakeup gNB rxtx process" message(s)'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
if gnbTxWriteThreadEnabled:
statMsg = nodeB_prefix + 'NB ran with TX Write thread enabled'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
if nrRrcRcfgComplete > 0:
statMsg = nodeB_prefix + 'NB showed ' + str(nrRrcRcfgComplete) + ' "Received NR_RRCReconfigurationComplete from UE" message(s)'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
if harqFeedbackPast > 0:
statMsg = nodeB_prefix + 'NB showed ' + str(harqFeedbackPast) + ' "HARQ feedback is in the past" message(s)'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
#FR1 NSA test : add new markers to make sure gNB is used
if NSA_RAPROC_PUSCH_check:
statMsg = '[RAPROC] PUSCH with TC_RNTI message check for ' + nodeB_prefix + 'NB : PASS '
htmlMsg = statMsg+'\n'
else:
statMsg = '[RAPROC] PUSCH with TC_RNTI message check for ' + nodeB_prefix + 'NB : FAIL or not relevant'
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
#problem receiving samples log
statMsg = '[PHY] problem receiving samples msg count = '+str(pb_receiving_samples_cnt)
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
#gnb markers
statMsg = 'logfile line count = ' + str(line_cnt)
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
if len(gnb_markers['SgNBReleaseRequestAcknowledge'])!=0:
statMsg = 'SgNBReleaseRequestAcknowledge = ' + str(len(gnb_markers['SgNBReleaseRequestAcknowledge'])) + ' occurences , starting line ' + str(gnb_markers['SgNBReleaseRequestAcknowledge'][0])
else:
statMsg = 'SgNBReleaseRequestAcknowledge = ' + str(len(gnb_markers['SgNBReleaseRequestAcknowledge'])) + ' occurences'
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
statMsg = 'FAILURE = ' + str(len(gnb_markers['FAILURE'])) + ' occurences'
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
statMsg = 'Detected UL Failure on PUSCH = ' + str(len(gnb_markers['Detected UL Failure on PUSCH'])) + ' occurences'
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
#ulsch and dlsch statistics and checkers
for ue in dlsch_ulsch_stats:
dlulstat = dlsch_ulsch_stats[ue]
#print statistics into html
statMsg=''
for key in dlulstat:
statMsg += dlulstat[key] + '\n'
logging.debug(dlulstat[key])
htmleNBFailureMsg += statMsg
retx_status[ue] = {}
dlcheckers = [] if 'd_retx_th' not in checkers else checkers['d_retx_th']
retx_status[ue]['dl'] = self._analyzeUeRetx(dlulstat['dlsch_rounds'], dlcheckers, r'^.*dlsch_rounds\s+(\d+)\/(\d+)\/(\d+)\/(\d+),\s+dlsch_errors\s+(\d+)')
ulcheckers = [] if 'u_retx_th' not in checkers else checkers['u_retx_th']
retx_status[ue]['ul'] = self._analyzeUeRetx(dlulstat['ulsch_rounds'], ulcheckers, r'^.*ulsch_rounds\s+(\d+)\/(\d+)\/(\d+)\/(\d+),\s+.*,\s+ulsch_errors\s+(\d+)')
#real time statistics
datalog_rt_stats['Data']={}
if len(real_time_stats)!=0: #check if dictionary is not empty
for k in real_time_stats:
tmp=re.match(r'^(?P<metric>.*):\s+(?P<avg>\d+\.\d+) us;\s+(?P<count>\d+);\s+(?P<max>\d+\.\d+) us;',real_time_stats[k])
if tmp is not None:
metric=tmp.group('metric')
avg=float(tmp.group('avg'))
max=float(tmp.group('max'))
count=int(tmp.group('count'))
datalog_rt_stats['Data'][metric]=["{:.0f}".format(avg),"{:.0f}".format(max),"{:d}".format(count),"{:.2f}".format(avg/datalog_rt_stats['Ref'][metric])]
#once all metrics are collected, store the data as a class attribute to build a dedicated HTML table afterward
self.datalog_rt_stats=datalog_rt_stats
#check if there is a fail => will render the test as failed
for k in datalog_rt_stats['Data']:
if float(datalog_rt_stats['Data'][k][3])> datalog_rt_stats['Threshold'][k]: #condition for fail : avg/ref is greater than the fixed threshold
logging.debug('\u001B[1;30;43m datalog_rt_stats metric ' + k + '=' + datalog_rt_stats['Data'][k][3] + ' > threshold ' + str(datalog_rt_stats['Threshold'][k]) + ' \u001B[0m')
RealTimeProcessingIssue = True
else:
statMsg = 'No real time stats found in the log file\n'
logging.debug('No real time stats found in the log file')
htmleNBFailureMsg += statMsg
if not showedByeMsg:
logging.debug('\u001B[1;37;41m ' + nodeB_prefix + 'NB did not show "Bye." message at end, it likely did not stop properly! \u001B[0m')
htmleNBFailureMsg += 'No Bye. message found, did not stop properly\n'
global_status = CONST.ENB_SHUTDOWN_NO_BYE
else:
logging.debug('"Bye." message found at end.')
else:
#Removing UE log
statMsg = '[MAC] Removing UE msg count = '+str(removing_ue)
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
#X2AP-PDU log
statMsg = 'X2AP-PDU msg count = '+str(x2ap_pdu)
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
#nsa markers
statMsg = 'logfile line count = ' + str(line_cnt)
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
if len(gnb_markers['SgNBReleaseRequest'])!=0:
statMsg = 'SgNBReleaseRequest = ' + str(len(gnb_markers['SgNBReleaseRequest'])) + ' occurences , starting line ' + str(gnb_markers['SgNBReleaseRequest'][0])
else:
statMsg = 'SgNBReleaseRequest = ' + str(len(gnb_markers['SgNBReleaseRequest'])) + ' occurences'
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
statMsg = 'scgFailureInformationNR-r15 = ' + str(len(gnb_markers['scgFailureInformationNR-r15'])) + ' occurences'
htmlMsg = statMsg+'\n'
logging.debug(statMsg)
htmleNBFailureMsg += htmlMsg
for ue in retx_status:
msg = f"retransmissions for UE {ue}: DL {retx_status[ue]['dl']} UL {retx_status[ue]['ul']}"
if False in retx_status[ue]['dl'] or False in retx_status[ue]['ul']:
msg = 'Failure: ' + msg
logging.error(f'\u001B[1;37;41m {msg}\u001B[0m')
htmleNBFailureMsg += f'{msg}\n'
global_status = CONST.ENB_RETX_ISSUE
else:
logging.debug(msg)
if RealTimeProcessingIssue:
logging.debug('\u001B[1;37;41m ' + nodeB_prefix + 'NB ended with real time processing issue! \u001B[0m')
htmleNBFailureMsg += 'Fail due to real time processing issue\n'
global_status = CONST.ENB_REAL_TIME_PROCESSING_ISSUE
if uciStatMsgCount > 0:
statMsg = nodeB_prefix + 'NB showed ' + str(uciStatMsgCount) + ' "uci->stat" message(s)'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
if pdcpFailure > 0:
statMsg = nodeB_prefix + 'NB showed ' + str(pdcpFailure) + ' "PDCP Out of Resources" message(s)'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
if ulschFailure > 0:
statMsg = nodeB_prefix + 'NB showed ' + str(ulschFailure) + ' "ULSCH in error in round" message(s)'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
if ulschAllocateCCEerror > 0:
statMsg = nodeB_prefix + 'NB showed ' + str(ulschAllocateCCEerror) + ' "eNB_dlsch_ulsch_scheduler(); ERROR ALLOCATING CCEs" message(s)'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
if uplinkSegmentsAborted > 0:
statMsg = nodeB_prefix + 'NB showed ' + str(uplinkSegmentsAborted) + ' "uplink segment error 0/2, aborted * segments" message(s)'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
if dropNotEnoughRBs > 0:
statMsg = 'eNB showed ' + str(dropNotEnoughRBs) + ' "dropping, not enough RBs" message(s)'
logging.debug('\u001B[1;30;43m ' + statMsg + ' \u001B[0m')
htmleNBFailureMsg += statMsg + '\n'
if rrcSetupComplete > 0:
rrcMsg = nodeB_prefix + 'NB completed ' + str(rrcSetupComplete) + ' RRC Connection Setup(s)'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
rrcMsg = ' -- ' + str(rrcSetupComplete) + ' were completed'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
if rrcReleaseRequest > 0:
rrcMsg = nodeB_prefix + 'NB requested ' + str(rrcReleaseRequest) + ' RRC Connection Release(s)'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
if rrcReconfigRequest > 0 or rrcReconfigComplete > 0:
rrcMsg = nodeB_prefix + 'NB requested ' + str(rrcReconfigRequest) + ' RRC Connection Reconfiguration(s)'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
rrcMsg = ' -- ' + str(rrcReconfigComplete) + ' were completed'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
if rrcReestablishRequest > 0 or rrcReestablishComplete > 0 or rrcReestablishReject > 0:
rrcMsg = nodeB_prefix + 'NB requested ' + str(rrcReestablishRequest) + ' RRC Connection Reestablishment(s)'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
rrcMsg = ' -- ' + str(rrcReestablishComplete) + ' were completed'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
rrcMsg = ' -- ' + str(rrcReestablishReject) + ' were rejected'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
if self.eNBmbmsEnables[int(self.eNB_instance)]:
if mbmsRequestMsg > 0:
rrcMsg = 'eNB requested ' + str(mbmsRequestMsg) + ' times the RLC for MBMS USER-PLANE'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
if X2HO_inNbProcedures > 0:
rrcMsg = 'eNB completed ' + str(X2HO_inNbProcedures) + ' X2 Handover Connection procedure(s)'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
if X2HO_outNbProcedures > 0:
rrcMsg = 'eNB completed ' + str(X2HO_outNbProcedures) + ' X2 Handover Release procedure(s)'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
if self.eNBOptions[int(self.eNB_instance)] != '':
res1 = re.search('drx_Config_present prSetup', self.eNBOptions[int(self.eNB_instance)])
if res1 is not None:
if cdrxActivationMessageCount > 0:
rrcMsg = 'eNB activated the CDRX Configuration for ' + str(cdrxActivationMessageCount) + ' time(s)'
logging.debug('\u001B[1;30;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
else:
rrcMsg = 'eNB did NOT ACTIVATE the CDRX Configuration'
logging.debug('\u001B[1;37;43m ' + rrcMsg + ' \u001B[0m')
htmleNBFailureMsg += rrcMsg + '\n'
if rachCanceledProcedure > 0:
rachMsg = nodeB_prefix + 'NB cancelled ' + str(rachCanceledProcedure) + ' RA procedure(s)'
logging.debug('\u001B[1;30;43m ' + rachMsg + ' \u001B[0m')
htmleNBFailureMsg += rachMsg + '\n'
if isRRU:
if isSlave:
if slaveReceivesFrameResyncCmd:
rruMsg = 'Slave RRU received the RRU_frame_resynch command from RAU'
logging.debug('\u001B[1;30;43m ' + rruMsg + ' \u001B[0m')
htmleNBFailureMsg += rruMsg + '\n'
else:
rruMsg = 'Slave RRU DID NOT receive the RRU_frame_resynch command from RAU'
logging.debug('\u001B[1;37;41m ' + rruMsg + ' \u001B[0m')
htmleNBFailureMsg += rruMsg + '\n'
self.prematureExit = True
global_status = CONST.ENB_PROCESS_SLAVE_RRU_NOT_SYNCED
if foundSegFault:
logging.debug('\u001B[1;37;41m ' + nodeB_prefix + 'NB ended with a Segmentation Fault! \u001B[0m')
global_status = CONST.ENB_PROCESS_SEG_FAULT
if foundAssertion:
logging.debug('\u001B[1;37;41m ' + nodeB_prefix + 'NB ended with an assertion! \u001B[0m')
htmleNBFailureMsg += msgAssertion
global_status = CONST.ENB_PROCESS_ASSERTION
if foundRealTimeIssue:
logging.debug('\u001B[1;37;41m ' + nodeB_prefix + 'NB faced real time issues! \u001B[0m')
htmleNBFailureMsg += nodeB_prefix + 'NB faced real time issues! COUNT = '+ str(foundRealTimeIssue_cnt) +' lines\n'
if rlcDiscardBuffer > 0:
rlcMsg = nodeB_prefix + 'NB RLC discarded ' + str(rlcDiscardBuffer) + ' buffer(s)'
logging.debug('\u001B[1;37;41m ' + rlcMsg + ' \u001B[0m')
htmleNBFailureMsg += rlcMsg + '\n'
global_status = CONST.ENB_PROCESS_REALTIME_ISSUE
HTML.htmleNBFailureMsg=htmleNBFailureMsg
# Runtime statistics for console output and HTML
if runTime != '':
logging.debug(runTime)
logging.debug(userTime)
logging.debug(systemTime)
logging.debug(maxPhyMemUsage)
logging.debug(nbContextSwitches)
self.runtime_stats='<pre>'+runTime + '\n'+ userTime + '\n' + systemTime + '\n' + maxPhyMemUsage + '\n' + nbContextSwitches+'</pre>'
return global_status