See https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/78/display/redirect?page=changes
Changes:
[Pau Espin Pedrol] ggsn: Split test and relax expectations testing gtpu access over ipv6
[Pau Espin Pedrol] sgsn: Fix running with testenv.py podman setup
[Pau Espin Pedrol] sgsn: Introduce test TC_attach_rau_a_b_wrong_old_ra
[Pau Espin Pedrol] deps/Makefile: Use upstream titan.TestPorts.SIPmsg
------------------------------------------ [...truncated 1.50 MB...] [1;33m20240820124814125 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m MM(262420000000039/cd638218) Updating authorization (authenticate -> accepted) (sgsn_auth.c:217)[0;m [1;33m20240820124814125 [1;32mDMM[0;m[1;33m [1;32mINFO[0;m[1;33m MM(262420000000039/cd638218) Got authorization update: state authenticate -> accepted (sgsn_auth.c:246)[0;m [1;33m20240820124814125 [1;33mDMM[0;m[1;33m [1;33mNOTICE[0;m[1;33m MM(262420000000039/cd638218) Authorized, continuing procedure, IMSI=262420000000039 (gprs_gmm.c:1000)[0;m [1;33m20240820124814125 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000012e20]{WaitAttachComplete}: Received Event E_VLR_ANSWERED (gprs_gmm.c:1005)[0;m [1;33m20240820124814125 [1;33mDMM[0;m[1;33m [1;33mNOTICE[0;m[1;33m MM(262420000000039/cd638218) Unusual event: if MS got no data connection, check that it has APN configured. (gprs_gmm_attach.c:217)[0;m 20240820124814125 [1;32mDGPRS[0;m [1;32mINFO[0;m SUBSCR(262420000000039) Sending GSUP, will send: 12 01 08 62 42 02 00 00 00 30 f9 28 01 01 (gprs_subscriber.c:210) 20240820124814126 [1;32mDGPRS[0;m [1;32mINFO[0;m SUBSCR(262420000000039) Received GSUP message OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT (gprs_subscriber.c:723) 20240820124814126 [1;34mDGPRS[0;m [1;34mDEBUG[0;m SUBSCR(262420000000039) Updating subscriber data (gprs_subscriber.c:839) [1;33m20240820124814126 [1;32mDMM[0;m[1;33m [1;32mINFO[0;m[1;33m MM(262420000000039/cd638218) Subscriber data update (mmctx.c:430)[0;m [1;33m20240820124814126 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m MM(262420000000039/cd638218) Updating authorization (accepted -> accepted) (sgsn_auth.c:217)[0;m [38;5;57m20240820124814130 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(UDP-NSE00096-NSVC00097-127_0_0_10:23000-127_0_0_103:21010)[0x612000004ba0]{UNBLOCKED}: Received Event RX-UNITDATA (gprs_ns2_vc_fsm.c:964)[0;m 20240820124814130 [1;34mDLLC[0;m [1;34mDEBUG[0;m LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xffae8e CMD=UI DATA (gprs_llc_parse.c:89) [1;33m20240820124814130 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m MM_STATE_Gb(0)[0x612000012fa0]{Idle}: Received Event E_MM_PDU_RECEPTION (gprs_gmm.c:2333)[0;m [1;33m20240820124814130 [1;32mDMM[0;m[1;33m [1;32mINFO[0;m[1;33m MM(262420000000039/cd638218) -> GMM ATTACH COMPLETE (gprs_gmm.c:1397)[0;m [1;33m20240820124814130 [1;33mDMM[0;m[1;33m [1;33mNOTICE[0;m[1;33m MM(262420000000039/cd638218) Stopping *inactive* MM timer 3350 (gprs_gmm.c:115)[0;m [1;33m20240820124814130 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM(gmm_fsm)[0x612000012ca0]{CommonProcedureInitiated}: Received Event E_GMM_ATTACH_SUCCESS (gprs_gmm.c:1409)[0;m [1;33m20240820124814130 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM(gmm_fsm)[0x612000012ca0]{CommonProcedureInitiated}: state_chg to Registered.NORMAL (gprs_gmm_fsm.c:72)[0;m 20240820124814130 [1;33mDLLC[0;m [1;33mNOTICE[0;m LLME(c3923305/cd638218){ASSIGNED} LLGM Assign pre (ffffffff => cd638218) (gprs_llc.c:1079) 20240820124814130 [1;33mDLLC[0;m [1;33mNOTICE[0;m LLME(ffffffff/cd638218){ASSIGNED} LLGM Assign post (ffffffff => cd638218) (gprs_llc.c:1125) [1;33m20240820124814130 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m MM_STATE_Gb(0)[0x612000012fa0]{Idle}: Received Event E_MM_GPRS_ATTACH (gprs_gmm.c:1420)[0;m [1;33m20240820124814130 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m MM_STATE_Gb(0)[0x612000012fa0]{Idle}: state_chg to Ready (gprs_mm_state_gb_fsm.c:60)[0;m [1;33m20240820124814130 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000012e20]{WaitAttachComplete}: Received Event E_ATTACH_COMPLETE_RECV (gprs_gmm.c:1424)[0;m [1;33m20240820124814130 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000012e20]{WaitAttachComplete}: state_chg to Init (gprs_gmm_attach.c:212)[0;m TC_attach_rau_a_b_wrong_old_ra(535)@204f4a9cdd34: setverdict(pass): none -> pass TC_attach_rau_a_b_wrong_old_ra(535)@204f4a9cdd34: attach complete sending rau [38;5;57m20240820124814181 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(UDP-NSE00096-NSVC00097-127_0_0_10:23000-127_0_0_103:21010)[0x612000004ba0]{UNBLOCKED}: Received Event RX-UNITDATA (gprs_ns2_vc_fsm.c:964)[0;m 20240820124814182 [1;34mDLLC[0;m [1;34mDEBUG[0;m LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xbcf888 CMD=UI DATA (gprs_llc_parse.c:89) [1;33m20240820124814182 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m MM_STATE_Gb(0)[0x612000012fa0]{Ready}: Received Event E_MM_PDU_RECEPTION (gprs_gmm.c:2333)[0;m [1;33m20240820124814182 [1;32mDMM[0;m[1;33m [1;32mINFO[0;m[1;33m MM(262420000000039/cd638218) -> GMM RA UPDATE REQUEST type="RA updating" (gprs_gmm.c:1641)[0;m [1;33m20240820124814182 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM(gmm_fsm)[0x612000012ca0]{Registered.NORMAL}: Received Event E_GMM_COMMON_PROC_INIT_REQ (gprs_gmm.c:1144)[0;m [1;33m20240820124814182 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM(gmm_fsm)[0x612000012ca0]{Registered.NORMAL}: state_chg to CommonProcedureInitiated (gprs_gmm_fsm.c:81)[0;m 20240820124814182 [1;33mDLLC[0;m [1;33mNOTICE[0;m LLME(ffffffff/cd638218){ASSIGNED} LLGM Assign pre (cd638218 => e15a1c05) (gprs_llc.c:1079) 20240820124814182 [1;33mDLLC[0;m [1;33mNOTICE[0;m LLME(cd638218/e15a1c05){ASSIGNED} LLGM Assign post (cd638218 => e15a1c05) (gprs_llc.c:1125) [1;33m20240820124814182 [1;32mDMM[0;m[1;33m [1;32mINFO[0;m[1;33m MM(262420000000039/e15a1c05) <- GMM ROUTING AREA UPDATE ACCEPT (gprs_gmm.c:1504)[0;m TC_attach_rau_a_b_wrong_old_ra(535)@204f4a9cdd34: setverdict(pass): pass -> pass, component reason not changed TC_attach_rau_a_b_wrong_old_ra(535)@204f4a9cdd34: setverdict(pass): pass -> pass, component reason not changed TC_attach_rau_a_b_wrong_old_ra(535)@204f4a9cdd34: rau complete unregistering TC_attach_rau_a_b_wrong_old_ra-BVCI196(520)@204f4a9cdd34: Removing Client IMSI='262420000000039'H, index=0 [38;5;57m20240820124814187 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(UDP-NSE00096-NSVC00097-127_0_0_10:23000-127_0_0_103:21010)[0x612000004ba0]{UNBLOCKED}: Received Event RX-UNITDATA (gprs_ns2_vc_fsm.c:964)[0;m 20240820124814187 [1;34mDLLC[0;m [1;34mDEBUG[0;m LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xb0b0ba CMD=UI DATA (gprs_llc_parse.c:89) [1;33m20240820124814187 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m MM_STATE_Gb(0)[0x612000012fa0]{Ready}: Received Event E_MM_PDU_RECEPTION (gprs_gmm.c:2333)[0;m [1;33m20240820124814187 [1;32mDMM[0;m[1;33m [1;32mINFO[0;m[1;33m MM(262420000000039/e15a1c05) -> ROUTING AREA UPDATE COMPLETE (gprs_gmm.c:1847)[0;m [1;33m20240820124814187 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM(gmm_fsm)[0x612000012ca0]{CommonProcedureInitiated}: Received Event E_GMM_COMMON_PROC_SUCCESS (gprs_gmm.c:1852)[0;m [1;33m20240820124814187 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM(gmm_fsm)[0x612000012ca0]{CommonProcedureInitiated}: state_chg to Registered.NORMAL (gprs_gmm_fsm.c:72)[0;m 20240820124814188 [1;33mDLLC[0;m [1;33mNOTICE[0;m LLME(cd638218/e15a1c05){ASSIGNED} LLGM Assign pre (ffffffff => e15a1c05) (gprs_llc.c:1079) 20240820124814188 [1;33mDLLC[0;m [1;33mNOTICE[0;m LLME(ffffffff/e15a1c05){ASSIGNED} LLGM Assign post (ffffffff => e15a1c05) (gprs_llc.c:1125) [1;33m20240820124814188 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m MM_STATE_Gb(0)[0x612000012fa0]{Ready}: Received Event E_MM_RA_UPDATE (gprs_gmm.c:1862)[0;m TC_attach_rau_a_b_wrong_old_ra-BVCI210(525)@204f4a9cdd34: Adding Client=TC_attach_rau_a_b_wrong_old_ra(535), IMSI='262420000000039'H, TLLI='E15A1C05'O, index=0 TC_attach_rau_a_b_wrong_old_ra(535)@204f4a9cdd34: sending second RAU via different RA with wrong Old RA [38;5;57m20240820124814191 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(UDP-NSE00097-NSVC00098-127_0_0_10:23000-127_0_0_103:21011)[0x612000004d20]{UNBLOCKED}: Received Event RX-UNITDATA (gprs_ns2_vc_fsm.c:964)[0;m 20240820124814191 [1;34mDLLC[0;m [1;34mDEBUG[0;m LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xfedba3 CMD=UI DATA (gprs_llc_parse.c:89) [1;33m20240820124814191 [1;32mDMM[0;m[1;33m [1;32mINFO[0;m[1;33m MM(---/ffffffff) -> GMM RA UPDATE REQUEST type="RA updating" (gprs_gmm.c:1641)[0;m [1;33m20240820124814191 [1;33mDMM[0;m[1;33m [1;33mNOTICE[0;m[1;33m LLME(ffffffff/e15a1c05){ASSIGNED} LLC XID RESET (gprs_gmm.c:1749)[0;m 20240820124814191 [1;33mDLLC[0;m [1;33mNOTICE[0;m LLME(ffffffff/e15a1c05){ASSIGNED} LLGM Reset (SAPI=1) (gprs_llc.c:1186) [1;33m20240820124814192 [1;31mDMM[0;m[1;33m [1;31mERROR[0;m[1;33m LLME(ffffffff/e15a1c05){ASSIGNED} Rejecting GMM RA Update Request: MS should GMM Attach first (gprs_gmm.c:1755)[0;m [1;33m20240820124814192 [1;33mDMM[0;m[1;33m [1;33mNOTICE[0;m[1;33m MM(---/ffffffff) Rejecting RA Update Request with cause 'Implicitly detached' (10) (gprs_gmm.c:1824)[0;m [1;33m20240820124814192 [1;33mDMM[0;m[1;33m [1;33mNOTICE[0;m[1;33m <- ROUTING AREA UPDATE REJECT (gprs_gmm.c:1558)[0;m 20240820124814192 [1;33mDLLC[0;m [1;33mNOTICE[0;m LLME(ffffffff/e15a1c05){ASSIGNED} LLGM Assign pre (e15a1c05 => ffffffff) (gprs_llc.c:1079) 20240820124814192 [1;33mDLLC[0;m [1;33mNOTICE[0;m LLME(00000000/00000000){UNASSIGNED} LLGM Assign post (e15a1c05 => ffffffff) (gprs_llc.c:1125) [38;5;57m20240820124814202 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(UDP-NSE00097-NSVC00098-127_0_0_10:23000-127_0_0_103:21011)[0x612000004d20]{UNBLOCKED}: Received Event RX-UNITDATA (gprs_ns2_vc_fsm.c:964)[0;m 20240820124814202 [1;33mDLLC[0;m [1;33mNOTICE[0;m LLME(ffffffff/e15a1c05){UNASSIGNED} LLC RX: unknown TLLI 0xe15a1c05, creating LLME on the fly (gprs_llc.c:552) 20240820124814202 [1;34mDLLC[0;m [1;34mDEBUG[0;m LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0x912c5c CMD=UI DATA (gprs_llc_parse.c:89) [1;33m20240820124814202 [1;33mDMM[0;m[1;33m [1;33mNOTICE[0;m[1;33m LLME(ffffffff/e15a1c05){UNASSIGNED} Cannot handle GMM for unknown MM CTX (gprs_gmm.c:2035)[0;m 20240820124818471 [1;34mDGPRS[0;m [1;34mDEBUG[0;m Checking for inactive LLMEs, time = 5968832 (sgsn.c:131) [38;5;39m20240820124833053 [1;32mDLGSUP[0;m[38;5;39m [1;32mINFO[0;m[38;5;39m GSUP ping callback (connected, got PONG) (gsup_client.c:266)[0;m [38;5;39m20240820124833053 [1;34mDLGSUP[0;m[38;5;39m [1;34mDEBUG[0;m[38;5;39m GSUP sending PING (gsup_client.c:288)[0;m SGSN_Test-GSUP-IPA(532)@204f4a9cdd34: CCM Rx:{ msg_type := IPAC_MSGT_PING (0), u := omit } SGSN_Test-GSUP-IPA(532)@204f4a9cdd34: CCM Tx:{ msg_type := IPAC_MSGT_PONG (1), u := omit } [38;5;39m20240820124833053 [1;34mDLGSUP[0;m[38;5;39m [1;34mDEBUG[0;m[38;5;39m GSUP receiving PONG (gsup_client.c:225)[0;m [38;5;63m20240820124842219 [1;32mDLNSSIGNAL[0;m[38;5;63m [1;32mINFO[0;m[38;5;63m NSE(00096)-NSVC(00097) Tx NS-ALIVE (gprs_ns2_message.c:193)[0;m [38;5;63m20240820124842220 [1;32mDLNSSIGNAL[0;m[38;5;63m [1;32mINFO[0;m[38;5;63m NSE(00096)-NSVC(00097) Rx NS-ALIVE-ACK (gprs_ns2.c:1309)[0;m [38;5;57m20240820124842220 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(UDP-NSE00096-NSVC00097-127_0_0_10:23000-127_0_0_103:21010)[0x612000004ba0]{UNBLOCKED}: Received Event RX-ALIVE_ACK (gprs_ns2_vc_fsm.c:960)[0;m [38;5;63m20240820124842255 [1;32mDLNSSIGNAL[0;m[38;5;63m [1;32mINFO[0;m[38;5;63m NSE(00097)-NSVC(00098) Tx NS-ALIVE (gprs_ns2_message.c:193)[0;m [38;5;63m20240820124842256 [1;32mDLNSSIGNAL[0;m[38;5;63m [1;32mINFO[0;m[38;5;63m NSE(00097)-NSVC(00098) Rx NS-ALIVE-ACK (gprs_ns2.c:1309)[0;m [38;5;57m20240820124842256 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(UDP-NSE00097-NSVC00098-127_0_0_10:23000-127_0_0_103:21011)[0x612000004d20]{UNBLOCKED}: Received Event RX-ALIVE_ACK (gprs_ns2_vc_fsm.c:960)[0;m [38;5;63m20240820124842289 [1;32mDLNSSIGNAL[0;m[38;5;63m [1;32mINFO[0;m[38;5;63m NSE(00098)-NSVC(00099) Tx NS-ALIVE (gprs_ns2_message.c:193)[0;m [38;5;63m20240820124842290 [1;32mDLNSSIGNAL[0;m[38;5;63m [1;32mINFO[0;m[38;5;63m NSE(00098)-NSVC(00099) Rx NS-ALIVE-ACK (gprs_ns2.c:1309)[0;m [38;5;57m20240820124842290 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(UDP-NSE00098-NSVC00099-127_0_0_10:23000-127_0_0_103:21012)[0x612000004ea0]{UNBLOCKED}: Received Event RX-ALIVE_ACK (gprs_ns2_vc_fsm.c:960)[0;m TC_attach_rau_a_b_wrong_old_ra(535)@204f4a9cdd34: setverdict(fail): pass -> fail reason: "Tguard timeout", new component reason: "Tguard timeout" MC@204f4a9cdd34: Test Component 535 has requested to stop MTC. Terminating current testcase execution. SGSN_Test-Gb0-BSSGP0(518)@204f4a9cdd34: Final verdict of PTC: none TC_attach_rau_a_b_wrong_old_ra-BVCI210(525)@204f4a9cdd34: Final verdict of PTC: none TC_attach_rau_a_b_wrong_old_ra-BVCI196(520)@204f4a9cdd34: Final verdict of PTC: none SGSN_Test-Gb0-NS0(517)@204f4a9cdd34: Final verdict of PTC: none SGSN_Test-Gb1-NS1(522)@204f4a9cdd34: Final verdict of PTC: none 20240820124844119 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Closing telnet connection r=127.0.0.1:45628<->l=127.0.0.10:4245 (telnet_interface.c:138) -NSVCI97(521)@204f4a9cdd34: Final verdict of PTC: none -NSVCI98(526)@204f4a9cdd34: Final verdict of PTC: none -NSVCI99(531)@204f4a9cdd34: Final verdict of PTC: none SGSN_Test-Gb2-NS2(527)@204f4a9cdd34: Final verdict of PTC: none TC_attach_rau_a_b_wrong_old_ra(535)@204f4a9cdd34: Final verdict of PTC: fail reason: "Tguard timeout" [38;5;23m20240820124844120 [1;31mDLINP[0;m[38;5;23m [1;31mERROR[0;m[38;5;23m 127.0.0.103:4222 connection closed with server (ipa.c:68)[0;m [38;5;39m20240820124844121 [1;32mDLGSUP[0;m[38;5;39m [1;32mINFO[0;m[38;5;39m GSUP link to 127.0.0.103:4222 DOWN (gsup_client.c:151)[0;m SGSN_Test-GGSN_GTP(534)@204f4a9cdd34: Final verdict of PTC: none SGSN_Test-Gb2-BSSGP2(528)@204f4a9cdd34: Final verdict of PTC: none -NSVCI98-provIP(524)@204f4a9cdd34: Final verdict of PTC: none -NSVCI97-provIP(519)@204f4a9cdd34: Final verdict of PTC: none TC_attach_rau_a_b_wrong_old_ra-BVCI220(530)@204f4a9cdd34: Final verdict of PTC: none SGSN_Test-GSUP(533)@204f4a9cdd34: Final verdict of PTC: none SGSN_Test-Gb1-BSSGP1(523)@204f4a9cdd34: Final verdict of PTC: none -NSVCI99-provIP(529)@204f4a9cdd34: Final verdict of PTC: none SGSN_Test-GSUP-IPA(532)@204f4a9cdd34: Final verdict of PTC: none MTC@204f4a9cdd34: Setting final verdict of the test case. MTC@204f4a9cdd34: Local verdict of MTC: none MTC@204f4a9cdd34: Local verdict of PTC SGSN_Test-Gb0-NS0(517): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC SGSN_Test-Gb0-BSSGP0(518): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC -NSVCI97-provIP(519): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC TC_attach_rau_a_b_wrong_old_ra-BVCI196(520): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC -NSVCI97(521): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC SGSN_Test-Gb1-NS1(522): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC SGSN_Test-Gb1-BSSGP1(523): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC -NSVCI98-provIP(524): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC TC_attach_rau_a_b_wrong_old_ra-BVCI210(525): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC -NSVCI98(526): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC SGSN_Test-Gb2-NS2(527): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC SGSN_Test-Gb2-BSSGP2(528): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC -NSVCI99-provIP(529): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC TC_attach_rau_a_b_wrong_old_ra-BVCI220(530): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC -NSVCI99(531): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC SGSN_Test-GSUP-IPA(532): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC SGSN_Test-GSUP(533): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC SGSN_Test-GGSN_GTP(534): none (none -> none) MTC@204f4a9cdd34: Local verdict of PTC TC_attach_rau_a_b_wrong_old_ra(535): fail (none -> fail) reason: "Tguard timeout" MTC@204f4a9cdd34: Test case TC_attach_rau_a_b_wrong_old_ra finished. Verdict: fail reason: Tguard timeout MTC@204f4a9cdd34: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-stop.sh SGSN_Tests.TC_attach_rau_a_b_wrong_old_ra fail'. Tue Aug 20 12:48:44 UTC 2024 [1;31m------ SGSN_Tests.TC_attach_rau_a_b_wrong_old_ra fail ------[0m
Waiting for packet dumper to finish... 0 (prev_count=-1, count=99872) [38;5;39m20240820124845122 [1;33mDLGSUP[0;m[38;5;39m [1;33mNOTICE[0;m[38;5;39m GSUP connecting to 127.0.0.103:4222 (gsup_client.c:74)[0;m [38;5;39m20240820124845122 [1;32mDLGSUP[0;m[38;5;39m [1;32mINFO[0;m[38;5;39m GSUP link to 127.0.0.103:4222 DOWN (gsup_client.c:151)[0;m Waiting for packet dumper to finish... 1 (prev_count=99872, count=101568) [38;5;39m20240820124846123 [1;33mDLGSUP[0;m[38;5;39m [1;33mNOTICE[0;m[38;5;39m GSUP connecting to 127.0.0.103:4222 (gsup_client.c:74)[0;m [38;5;39m20240820124846123 [1;32mDLGSUP[0;m[38;5;39m [1;32mINFO[0;m[38;5;39m GSUP link to 127.0.0.103:4222 DOWN (gsup_client.c:151)[0;m MTC@204f4a9cdd34: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-stop.sh SGSN_Tests.TC_attach_rau_a_b_wrong_old_ra fail' was executed successfully (exit status: 0). MTC@204f4a9cdd34: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-start.sh SGSN_Tests.TC_attach_usim_resync'. ------ SGSN_Tests.TC_attach_usim_resync ------ Tue Aug 20 12:48:46 UTC 2024 /usr/bin/dumpcap -q -s 1520 -n -i any -w "https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/78/artifact/logs/testsuite/SGSN_Tests.TC_attach_usim_resync.pcap" >https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/78/artifact/logs/testsuite/SGSN_Tests.TC_attach_usim_resync.pcap.stdout 2>/tmp/cmderr & Waiting for packet dumper to start... 0 [38;5;39m20240820124847124 [1;33mDLGSUP[0;m[38;5;39m [1;33mNOTICE[0;m[38;5;39m GSUP connecting to 127.0.0.103:4222 (gsup_client.c:74)[0;m [38;5;39m20240820124847124 [1;32mDLGSUP[0;m[38;5;39m [1;32mINFO[0;m[38;5;39m GSUP link to 127.0.0.103:4222 DOWN (gsup_client.c:151)[0;m MTC@204f4a9cdd34: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-start.sh SGSN_Tests.TC_attach_usim_resync' was executed successfully (exit status: 0). MTC@204f4a9cdd34: Test case TC_attach_usim_resync started. 20240820124847256 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Accept()ed new telnet connection r=127.0.0.1:49860<->l=127.0.0.10:4245 (telnet_interface.c:192) [1;33m20240820124847257 [1;32mDMM[0;m[1;33m [1;32mINFO[0;m[1;33m MM(262420000000039/e15a1c05) Cancelled, deleting context silently (gprs_gmm.c:1061)[0;m [1;33m20240820124847257 [1;32mDMM[0;m[1;33m [1;32mINFO[0;m[1;33m MM(262420000000039/e15a1c05) Cleaning MM context due to access cancelled (gprs_gmm.c:200)[0;m [1;33m20240820124847257 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM(gmm_fsm)[0x612000012ca0]{Registered.NORMAL}: Received Event E_GMM_CLEANUP (gprs_gmm.c:203)[0;m [1;33m20240820124847257 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m GMM(gmm_fsm)[0x612000012ca0]{Registered.NORMAL}: state_chg to Deregistered (gprs_gmm_fsm.c:223)[0;m [1;33m20240820124847257 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m MM_STATE_Gb(0)[0x612000012fa0]{Ready}: Received Event E_MM_GPRS_DETACH (gprs_gmm.c:210)[0;m [1;33m20240820124847257 [1;34mDMM[0;m[1;33m [1;34mDEBUG[0;m[1;33m MM_STATE_Gb(0)[0x612000012fa0]{Ready}: state_chg to Idle (gprs_mm_state_gb_fsm.c:76)[0;m ================================================================= ==7814==ERROR: AddressSanitizer: heap-use-after-free on address 0x621002a45574 at pc 0x564385c1ee5b bp 0x7fffc57395d0 sp 0x7fffc57395c8 READ of size 4 at 0x621002a45574 thread T0 #0 0x564385c1ee5a (/usr/bin/osmo-sgsn+0x221e5a) #1 0x564385ba5f4c (/usr/bin/osmo-sgsn+0x1a8f4c) #2 0x7f366417c9af (/lib/x86_64-linux-gnu/libosmocore.so.22+0x17c9af) #3 0x7f366417f0fb in _osmo_fsm_inst_state_chg (/lib/x86_64-linux-gnu/libosmocore.so.22+0x17f0fb) #4 0x564385ba5ce7 (/usr/bin/osmo-sgsn+0x1a8ce7) #5 0x7f366417f7db in _osmo_fsm_inst_dispatch (/lib/x86_64-linux-gnu/libosmocore.so.22+0x17f7db) #6 0x564385b7a73d (/usr/bin/osmo-sgsn+0x17d73d) #7 0x564385bf13ef (/usr/bin/osmo-sgsn+0x1f43ef) #8 0x7f3664f0198c (/lib/x86_64-linux-gnu/libosmovty.so.13+0xae98c) #9 0x7f3664f121e4 in vty_read (/lib/x86_64-linux-gnu/libosmovty.so.13+0xbf1e4) #10 0x7f3664f23a00 (/lib/x86_64-linux-gnu/libosmovty.so.13+0xd0a00) #11 0x7f36641d1245 (/lib/x86_64-linux-gnu/libosmocore.so.22+0x1d1245) #12 0x7f36641d16e8 in osmo_select_main (/lib/x86_64-linux-gnu/libosmocore.so.22+0x1d16e8) #13 0x564385b7399c (/usr/bin/osmo-sgsn+0x17699c) #14 0x7f3660e46249 (/lib/x86_64-linux-gnu/libc.so.6+0x27249) #15 0x7f3660e46304 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x27304) #16 0x564385b74630 (/usr/bin/osmo-sgsn+0x177630)
0x621002a45574 is located 116 bytes inside of 4408-byte region [0x621002a45500,0x621002a46638) freed by thread T0 here: #0 0x7f36656b76a8 in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:52 #1 0x7f3665cab5b1 (/lib/x86_64-linux-gnu/libtalloc.so.2+0x45b1)
previously allocated by thread T0 here: #0 0x7f36656b89cf in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:69 #1 0x7f3665cacd53 (/lib/x86_64-linux-gnu/libtalloc.so.2+0x5d53)
SUMMARY: AddressSanitizer: heap-use-after-free (/usr/bin/osmo-sgsn+0x221e5a) Shadow bytes around the buggy address: 0x0c4280540a50: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c4280540a60: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c4280540a70: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c4280540a80: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c4280540a90: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa =>0x0c4280540aa0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd[fd]fd 0x0c4280540ab0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd 0x0c4280540ac0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd 0x0c4280540ad0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd 0x0c4280540ae0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd 0x0c4280540af0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd Shadow byte legend (one shadow byte represents 8 application bytes): Addressable: 00 Partially addressable: 01 02 03 04 05 06 07 Heap left redzone: fa Freed heap region: fd Stack left redzone: f1 Stack mid redzone: f2 Stack right redzone: f3 Stack after return: f5 Stack use after scope: f8 Global redzone: f9 Global init order: f6 Poisoned by user: f7 Container overflow: fc Array cookie: ac Intra object redzone: bb ASan internal: fe Left alloca redzone: ca Right alloca redzone: cb ==7814==ABORTING [38;5;23m20240820124847295 [1;33mDLINP[0;m[38;5;23m [1;33mNOTICE[0;m[38;5;23m asp-dyn-1 NOTIFICATION SHUTDOWN_EVENT flags=0x0 (stream.c:265)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m 0: asp-asp-dyn-1: ss7_asp_xua_srv_conn_rx_cb(): sctp_recvmsg() returned 0 (flags=0x80) (osmo_ss7_asp.c:831)[0;m [38;5;43m20240820124847295 [1;32mDLSS7[0;m[38;5;43m [1;32mINFO[0;m[38;5;43m 0: asp-asp-dyn-1: xUA SRV SCTP NOTIFICATION 32773 flags=0x0 (osmo_ss7_asp.c:769)[0;m [38;5;43m20240820124847295 [1;33mDLSS7[0;m[38;5;43m [1;33mNOTICE[0;m[38;5;43m 0: asp-asp-dyn-1: xUA SRV SHUTDOWN_EVENT (osmo_ss7_asp.c:792)[0;m [38;5;23m20240820124847295 [1;33mDLINP[0;m[38;5;23m [1;33mNOTICE[0;m[38;5;23m asp-dyn-1 NOTIFICATION ASSOC_CHANGE flags=0x0 SHUTDOWN_COMP (stream.c:265)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m 0: asp-asp-dyn-1: ss7_asp_xua_srv_conn_rx_cb(): sctp_recvmsg() returned 0 (flags=0x80) (osmo_ss7_asp.c:831)[0;m [38;5;43m20240820124847295 [1;32mDLSS7[0;m[38;5;43m [1;32mINFO[0;m[38;5;43m 0: asp-asp-dyn-1: xUA SRV SCTP NOTIFICATION 32769 flags=0x0 (osmo_ss7_asp.c:769)[0;m [38;5;43m20240820124847295 [1;33mDLSS7[0;m[38;5;43m [1;33mNOTICE[0;m[38;5;43m 0: asp-asp-dyn-1: xUA SRV SCTP_ASSOC_CHANGE: SHUTDOWN_COMP (osmo_ss7_asp.c:777)[0;m [38;5;23m20240820124847295 [1;33mDLINP[0;m[38;5;23m [1;33mNOTICE[0;m[38;5;23m SRVCONN(asp-dyn-1,r=127.0.0.1:41752<->l=127.0.0.200:2905) connection closed with client (stream_srv.c:673)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m 0: asp-asp-dyn-1: ss7_asp_xua_srv_conn_rx_cb(): sctp_recvmsg() returned 0 (flags=0x0) (osmo_ss7_asp.c:831)[0;m [38;5;43m20240820124847295 [1;32mDLSS7[0;m[38;5;43m [1;32mINFO[0;m[38;5;43m asp-dyn-1: connection closed (osmo_ss7_asp.c:1079)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_ASP(asp-dyn-1){ASP_ACTIVE}: Received Event SCTP-COMM_DOWN.ind (osmo_ss7_asp.c:1085)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_ASP(asp-dyn-1){ASP_ACTIVE}: state_chg to ASP_DOWN (xua_asp_fsm.c:683)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_AS(as-rkm-3){AS_ACTIVE}: Received Event ASPAS-ASP_DOWN.ind (xua_asp_fsm.c:364)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_AS(as-rkm-3){AS_ACTIVE}: state_chg to AS_PENDING (xua_as_fsm.c:467)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_ASP(asp-dyn-1){ASP_DOWN}: No Layer Manager, dropping M-ASP_DOWN.indication (xua_asp_fsm.c:115)[0;m [38;5;43m20240820124847295 [1;32mDLSS7[0;m[38;5;43m [1;32mINFO[0;m[38;5;43m 0: as-as-rkm-3: Destroying AS (osmo_ss7_as.c:159)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_AS(as-rkm-3){AS_PENDING}: Terminating (cause = OSMO_FSM_TERM_REQUEST) (osmo_ss7_as.c:162)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_AS(as-rkm-3){AS_PENDING}: Freeing instance (osmo_ss7_as.c:162)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_AS(as-rkm-3){AS_PENDING}: Deallocated (fsm.c:568)[0;m [38;5;43m20240820124847295 [1;32mDLSS7[0;m[38;5;43m [1;32mINFO[0;m[38;5;43m 0: Destroying route: pc=188=0.23.4 mask=0x3fff via linkset/ASP 'as-rkm-3' (osmo_ss7.c:797)[0;m [38;5;43m20240820124847295 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_ASP(asp-dyn-1){ASP_DOWN}: No Layer Manager, dropping M-SCTP_RELEASE.indication (xua_asp_fsm.c:115)[0;m [38;5;43m20240820124847295 [1;32mDLSS7[0;m[38;5;43m [1;32mINFO[0;m[38;5;43m 0: asp-asp-dyn-1: Destroying ASP (osmo_ss7_asp.c:578)[0;m [38;5;43m20240820124847296 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_ASP(asp-dyn-1){ASP_DOWN}: Terminating (cause = OSMO_FSM_TERM_REQUEST) (osmo_ss7_asp.c:585)[0;m [38;5;43m20240820124847296 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_ASP(asp-dyn-1){ASP_DOWN}: Freeing instance (osmo_ss7_asp.c:585)[0;m [38;5;43m20240820124847296 [1;34mDLSS7[0;m[38;5;43m [1;34mDEBUG[0;m[38;5;43m XUA_ASP(asp-dyn-1){ASP_DOWN}: Deallocated (fsm.c:568)[0;m [1;91m[testenv][generic] sgsn crashed![0m [1;34m[testenv][generic] Stopping podman container[0m [0;94m[testenv][generic] + ['podman', 'kill', 'testenv-sgsn-generic-osmocom-nightly-asan-20240820-1242-b8f3e599'][0m 204f4a9cdd34d6d11ae79dd00b8abbad30f3d80d65701070f7621831dd9fd413 [1;34m[testenv][generic] Stopping testsuite (3822254)[0m [1;34m[testenv][generic] Logs saved to: https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/78/artifact/log... [0m Build step 'Execute shell' marked build as failure Recording test results [Checks API] No suitable checks publisher found.