Build failed in Jenkins: ttcn3-sgsn-test-asan #74

See https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/74/display/redirect?page=changes

Changes:

[lynxis] SGSN_Tests: add paging a whole routing area with multiple cells

[lynxis] SGSN_Tests: remove unused variable d

[lynxis] SGSN_Tests_NS: NS related tests: use the shutdown helper

[lynxis] SGSN_Tests_NS: TC_NS_connect_alive: set missing verdict

------------------------------------------ [...truncated 1.13 MB...] 20240816124634370 DLNSSIGNAL INFO NSE(00096)-NSVC(00097) Tx NS-ALIVE-ACK (gprs_ns2_message.c:193) 20240816124634370 DLNSSIGNAL INFO NSE(00096)-NSVC(00097) Rx NS-UNBLOCK (gprs_ns2.c:1309) 20240816124634370 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00096-NSVC00097-127_0_0_10:23000-127_0_0_103:21010)[0x612000004ba0]{BLOCKED}: Received Event RX-UNBLOCK (gprs_ns2_vc_fsm.c:951) 20240816124634370 DLNSSIGNAL INFO NSE(00096)-NSVC(00097) Tx NS-UNBLOCK-ACK (gprs_ns2_message.c:193) 20240816124634370 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00096-NSVC00097-127_0_0_10:23000-127_0_0_103:21010)[0x612000004ba0]{BLOCKED}: state_chg to UNBLOCKED (gprs_ns2_vc_fsm.c:414) 20240816124634370 DLNS NOTICE NSE(00096) NS-STATUS.ind(bvci=00000): cause=NSE recovery, transfer=100, first=0, mtu=65523 (gprs_ns2.c:575) 20240816124634370 DGPRS NOTICE NS-E 96 became available (gprs_ns.c:43) 20240816124634370 DLNS NOTICE NSE(00096)-NSVC(00097) NS-STATUS.ind(bvci=00000): cause=NSVC recovery, transfer=100, first=0, mtu=65523 (gprs_ns2.c:571) 20240816124634370 DGPRS NOTICE NS: indication Unknown prim 2 from NS (gprs_ns.c:57) 20240816124634370 DLNSSIGNAL INFO NSE(00096)-NSVC(00097) Rx NS-ALIVE-ACK (gprs_ns2.c:1309) -NSVCI97(350)@bb9044106d99: Rx NS-ALIVE-ACK: stopping Tns-alive; starting Tns-test 20240816124634370 DLNS DEBUG 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) -NSVCI97(350)@bb9044106d99: NSVC 97 State Transition: NSVC_S_ALIVE_BLOCKED (3) -> NSVC_S_ALIVE_UNBLOCKED (4) 20240816124634373 DLNS DEBUG 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) SGSN_Test-Gb0-BSSGP0(347)@bb9044106d99: BVCI(0) Rx BVC-RESET-ACK SGSN_Test-Gb0-BSSGP0(347)@bb9044106d99: BVCI(0) State Transition: BVC_S_WAIT_NS_ALIVE_UNBLOCKED (1) -> BVC_S_UNBLOCKED (3) SGSN_Test-Gb1-NS1(351)@bb9044106d99: Creating NSIP provider for "127.0.0.103":21011 20240816124634380 DLNS DEBUG 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) 20240816124634380 DLBSSGP NOTICE Cell 262-42-13135-0 CI 20960 on BVCI 196 (gprs_bssgp.c:400) TC_attach_check_complete_resend-BVCI196(349)@bb9044106d99: BVCI(196) State Transition: BVC_S_BLOCKED (2) -> BVC_S_UNBLOCKED (3) SGSN_Test-Gb1-BSSGP1(352)@bb9044106d99: BVCI(0) State Transition: BVC_S_WAIT_RESET (0) -> BVC_S_WAIT_NS_ALIVE_UNBLOCKED (1) SGSN_Test-Gb1-NS1(351)@bb9044106d99: Starting NSVC component for { provider := { ip := { address_family := AF_INET (2), local_udp_port := 21011, local_ip := "127.0.0.103", remote_udp_port := 23000, remote_ip := "127.0.0.10", data_weight := 1, signalling_weight := 1 } }, nsvci := 98 } -NSVCI98(355)@bb9044106d99: NSVC 98 State Transition: NSVC_S_DEAD_BLOCKED (1) -> NSVC_S_DEAD_BLOCKED (1) -NSVCI98(355)@bb9044106d99: Provider Link came up: sending NS-RESET 20240816124634402 DLNSSIGNAL INFO NSE(00097)-NSVC(00098) Rx NS-RESET (gprs_ns2.c:1309) 20240816124634402 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00097-NSVC00098-127_0_0_10:23000-127_0_0_103:21011)[0x612000004d20]{UNBLOCKED}: Received Event RX-RESET (gprs_ns2_vc_fsm.c:934) 20240816124634402 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00097-NSVC00098-127_0_0_10:23000-127_0_0_103:21011)[0x612000004d20]{UNBLOCKED}: state_chg to RESET (gprs_ns2_vc_fsm.c:657) 20240816124634402 DLNS NOTICE NSE(00097) NS-STATUS.ind(bvci=00000): cause=NSE failure, transfer=0, first=0, mtu=65523 (gprs_ns2.c:575) 20240816124634402 DGPRS NOTICE NS-E 97 became unavailable (gprs_ns.c:54) 20240816124634402 DLNSSIGNAL INFO NSE(00097)-NSVC(00098) Tx NS-RESET-ACK (gprs_ns2_message.c:331) 20240816124634403 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00097-NSVC00098-127_0_0_10:23000-127_0_0_103:21011)[0x612000004d20]{RESET}: state_chg to BLOCKED (gprs_ns2_vc_fsm.c:329) 20240816124634403 DLNSSIGNAL INFO NSE(00097)-NSVC(00098) Tx NS-ALIVE (gprs_ns2_message.c:193) 20240816124634403 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00097-NSVC00098-127_0_0_10:23000-127_0_0_103:21011)[0x612000004d20]{BLOCKED}: Starting Tns-alive of 3 seconds (gprs_ns2_vc_fsm.c:177) -NSVCI98(355)@bb9044106d99: NSVC 98 State Transition: NSVC_S_WAIT_RESET (2) -> NSVC_S_ALIVE_BLOCKED (3) 20240816124634404 DLNSSIGNAL INFO NSE(00097)-NSVC(00098) Rx NS-ALIVE (gprs_ns2.c:1309) 20240816124634404 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00097-NSVC00098-127_0_0_10:23000-127_0_0_103:21011)[0x612000004d20]{BLOCKED}: Received Event RX-ALIVE (gprs_ns2_vc_fsm.c:957) 20240816124634404 DLNSSIGNAL INFO NSE(00097)-NSVC(00098) Tx NS-ALIVE-ACK (gprs_ns2_message.c:193) 20240816124634404 DLNSSIGNAL INFO NSE(00097)-NSVC(00098) Rx NS-UNBLOCK (gprs_ns2.c:1309) 20240816124634404 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00097-NSVC00098-127_0_0_10:23000-127_0_0_103:21011)[0x612000004d20]{BLOCKED}: Received Event RX-UNBLOCK (gprs_ns2_vc_fsm.c:951) 20240816124634404 DLNSSIGNAL INFO NSE(00097)-NSVC(00098) Tx NS-UNBLOCK-ACK (gprs_ns2_message.c:193) 20240816124634404 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00097-NSVC00098-127_0_0_10:23000-127_0_0_103:21011)[0x612000004d20]{BLOCKED}: state_chg to UNBLOCKED (gprs_ns2_vc_fsm.c:414) 20240816124634404 DLNS NOTICE NSE(00097) NS-STATUS.ind(bvci=00000): cause=NSE recovery, transfer=100, first=0, mtu=65523 (gprs_ns2.c:575) 20240816124634404 DGPRS NOTICE NS-E 97 became available (gprs_ns.c:43) 20240816124634404 DLNS NOTICE NSE(00097)-NSVC(00098) NS-STATUS.ind(bvci=00000): cause=NSVC recovery, transfer=100, first=0, mtu=65523 (gprs_ns2.c:571) 20240816124634404 DGPRS NOTICE NS: indication Unknown prim 2 from NS (gprs_ns.c:57) 20240816124634404 DLNSSIGNAL INFO NSE(00097)-NSVC(00098) Rx NS-ALIVE-ACK (gprs_ns2.c:1309) 20240816124634404 DLNS DEBUG 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) -NSVCI98(355)@bb9044106d99: Rx NS-ALIVE-ACK: stopping Tns-alive; starting Tns-test -NSVCI98(355)@bb9044106d99: NSVC 98 State Transition: NSVC_S_ALIVE_BLOCKED (3) -> NSVC_S_ALIVE_UNBLOCKED (4) 20240816124634407 DLNS DEBUG 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) SGSN_Test-Gb1-BSSGP1(352)@bb9044106d99: BVCI(0) Rx BVC-RESET-ACK SGSN_Test-Gb1-BSSGP1(352)@bb9044106d99: BVCI(0) State Transition: BVC_S_WAIT_NS_ALIVE_UNBLOCKED (1) -> BVC_S_UNBLOCKED (3) SGSN_Test-Gb2-NS2(356)@bb9044106d99: Creating NSIP provider for "127.0.0.103":21012 20240816124634414 DLNS DEBUG 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) 20240816124634414 DLBSSGP NOTICE Cell 262-42-13200-0 CI 20961 on BVCI 210 (gprs_bssgp.c:400) TC_attach_check_complete_resend-BVCI210(354)@bb9044106d99: BVCI(210) State Transition: BVC_S_BLOCKED (2) -> BVC_S_UNBLOCKED (3) SGSN_Test-Gb2-BSSGP2(357)@bb9044106d99: BVCI(0) State Transition: BVC_S_WAIT_RESET (0) -> BVC_S_WAIT_NS_ALIVE_UNBLOCKED (1) SGSN_Test-Gb2-NS2(356)@bb9044106d99: Starting NSVC component for { provider := { ip := { address_family := AF_INET (2), local_udp_port := 21012, local_ip := "127.0.0.103", remote_udp_port := 23000, remote_ip := "127.0.0.10", data_weight := 1, signalling_weight := 1 } }, nsvci := 99 } -NSVCI99(360)@bb9044106d99: NSVC 99 State Transition: NSVC_S_DEAD_BLOCKED (1) -> NSVC_S_DEAD_BLOCKED (1) -NSVCI99(360)@bb9044106d99: Provider Link came up: sending NS-RESET 20240816124634439 DLNSSIGNAL INFO NSE(00098)-NSVC(00099) Rx NS-RESET (gprs_ns2.c:1309) 20240816124634439 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00098-NSVC00099-127_0_0_10:23000-127_0_0_103:21012)[0x612000004ea0]{UNBLOCKED}: Received Event RX-RESET (gprs_ns2_vc_fsm.c:934) 20240816124634439 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00098-NSVC00099-127_0_0_10:23000-127_0_0_103:21012)[0x612000004ea0]{UNBLOCKED}: state_chg to RESET (gprs_ns2_vc_fsm.c:657) 20240816124634440 DLNS NOTICE NSE(00098) NS-STATUS.ind(bvci=00000): cause=NSE failure, transfer=0, first=0, mtu=65523 (gprs_ns2.c:575) 20240816124634440 DGPRS NOTICE NS-E 98 became unavailable (gprs_ns.c:54) 20240816124634440 DLNSSIGNAL INFO NSE(00098)-NSVC(00099) Tx NS-RESET-ACK (gprs_ns2_message.c:331) 20240816124634440 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00098-NSVC00099-127_0_0_10:23000-127_0_0_103:21012)[0x612000004ea0]{RESET}: state_chg to BLOCKED (gprs_ns2_vc_fsm.c:329) 20240816124634440 DLNSSIGNAL INFO NSE(00098)-NSVC(00099) Tx NS-ALIVE (gprs_ns2_message.c:193) 20240816124634440 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00098-NSVC00099-127_0_0_10:23000-127_0_0_103:21012)[0x612000004ea0]{BLOCKED}: Starting Tns-alive of 3 seconds (gprs_ns2_vc_fsm.c:177) -NSVCI99(360)@bb9044106d99: NSVC 99 State Transition: NSVC_S_WAIT_RESET (2) -> NSVC_S_ALIVE_BLOCKED (3) 20240816124634441 DLNSSIGNAL INFO NSE(00098)-NSVC(00099) Rx NS-ALIVE (gprs_ns2.c:1309) 20240816124634441 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00098-NSVC00099-127_0_0_10:23000-127_0_0_103:21012)[0x612000004ea0]{BLOCKED}: Received Event RX-ALIVE (gprs_ns2_vc_fsm.c:957) 20240816124634441 DLNSSIGNAL INFO NSE(00098)-NSVC(00099) Tx NS-ALIVE-ACK (gprs_ns2_message.c:193) 20240816124634441 DLNSSIGNAL INFO NSE(00098)-NSVC(00099) Rx NS-UNBLOCK (gprs_ns2.c:1309) 20240816124634441 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00098-NSVC00099-127_0_0_10:23000-127_0_0_103:21012)[0x612000004ea0]{BLOCKED}: Received Event RX-UNBLOCK (gprs_ns2_vc_fsm.c:951) 20240816124634441 DLNSSIGNAL INFO NSE(00098)-NSVC(00099) Tx NS-UNBLOCK-ACK (gprs_ns2_message.c:193) 20240816124634441 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00098-NSVC00099-127_0_0_10:23000-127_0_0_103:21012)[0x612000004ea0]{BLOCKED}: state_chg to UNBLOCKED (gprs_ns2_vc_fsm.c:414) 20240816124634441 DLNS NOTICE NSE(00098) NS-STATUS.ind(bvci=00000): cause=NSE recovery, transfer=100, first=0, mtu=65523 (gprs_ns2.c:575) 20240816124634441 DGPRS NOTICE NS-E 98 became available (gprs_ns.c:43) 20240816124634441 DLNS NOTICE NSE(00098)-NSVC(00099) NS-STATUS.ind(bvci=00000): cause=NSVC recovery, transfer=100, first=0, mtu=65523 (gprs_ns2.c:571) 20240816124634441 DGPRS NOTICE NS: indication Unknown prim 2 from NS (gprs_ns.c:57) 20240816124634442 DLNSSIGNAL INFO NSE(00098)-NSVC(00099) Rx NS-ALIVE-ACK (gprs_ns2.c:1309) 20240816124634442 DLNS DEBUG 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) -NSVCI99(360)@bb9044106d99: Rx NS-ALIVE-ACK: stopping Tns-alive; starting Tns-test -NSVCI99(360)@bb9044106d99: NSVC 99 State Transition: NSVC_S_ALIVE_BLOCKED (3) -> NSVC_S_ALIVE_UNBLOCKED (4) 20240816124634444 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00098-NSVC00099-127_0_0_10:23000-127_0_0_103:21012)[0x612000004ea0]{UNBLOCKED}: Received Event RX-UNITDATA (gprs_ns2_vc_fsm.c:964) SGSN_Test-Gb2-BSSGP2(357)@bb9044106d99: BVCI(0) Rx BVC-RESET-ACK SGSN_Test-Gb2-BSSGP2(357)@bb9044106d99: BVCI(0) State Transition: BVC_S_WAIT_NS_ALIVE_UNBLOCKED (1) -> BVC_S_UNBLOCKED (3) 20240816124634451 DLNS DEBUG GPRS-NS2-VC(UDP-NSE00098-NSVC00099-127_0_0_10:23000-127_0_0_103:21012)[0x612000004ea0]{UNBLOCKED}: Received Event RX-UNITDATA (gprs_ns2_vc_fsm.c:964) 20240816124634452 DLBSSGP NOTICE Cell 262-42-13200-0 CI 20962 on BVCI 220 (gprs_bssgp.c:400) TC_attach_check_complete_resend-BVCI220(359)@bb9044106d99: BVCI(220) State Transition: BVC_S_BLOCKED (2) -> BVC_S_UNBLOCKED (3) 20240816124635195 DLGSUP NOTICE GSUP connecting to 127.0.0.103:4222 (gsup_client.c:74) 20240816124635195 DLINP NOTICE 127.0.0.103:4222 connection done (ipa.c:143) 20240816124635195 DLGSUP INFO GSUP link to 127.0.0.103:4222 UP (gsup_client.c:151) 20240816124635195 DLGSUP DEBUG GSUP sending PING (gsup_client.c:288) SGSN_Test-GSUP-IPA(361)@bb9044106d99: Established a new IPA connection (conn_id=2) SGSN_Test-GSUP-IPA(361)@bb9044106d99: CCM Tx:{ msg_type := IPAC_MSGT_ID_GET (4), u := { get := { { len := 1, tag := IPAC_IDTAG_UNITNAME (1) }, { len := 1, tag := IPAC_IDTAG_UNITID (8) } } } } 20240816124635198 DLINP NOTICE received ID_GET for unit ID 0/0/0 (ipaccess.c:897) SGSN_Test-GSUP-IPA(361)@bb9044106d99: CCM Rx:{ msg_type := IPAC_MSGT_PING (0), u := omit } SGSN_Test-GSUP-IPA(361)@bb9044106d99: CCM Tx:{ msg_type := IPAC_MSGT_PONG (1), u := omit } 20240816124635198 DLGSUP DEBUG GSUP receiving PONG (gsup_client.c:225) SGSN_Test-GSUP-IPA(361)@bb9044106d99: CCM Rx:{ msg_type := IPAC_MSGT_ID_RESP (5), u := { resp := { { len := 24, tag := IPAC_IDTAG_UNITNAME (1), data := '5347534E2D30302D30302D30302D30302D30302D303000'O }, { len := 7, tag := IPAC_IDTAG_UNITID (8), data := '302F302F3000'O } } } } SGSN_Test-GSUP-IPA(361)@bb9044106d99: IPA ID RESP: { { len := 24, tag := IPAC_IDTAG_UNITNAME (1), data := '5347534E2D30302D30302D30302D30302D30302D303000'O }, { len := 7, tag := IPAC_IDTAG_UNITID (8), data := '302F302F3000'O } } SGSN_Test-GSUP-IPA(361)@bb9044106d99: CCM Tx:{ msg_type := IPAC_MSGT_ID_ACK (6), u := omit } SGSN_Test-GSUP-IPA(361)@bb9044106d99: CCM Rx:{ msg_type := IPAC_MSGT_ID_ACK (6), u := omit } TC_attach_check_complete_resend-BVCI196(349)@bb9044106d99: Adding Client=TC_attach_check_complete_resend(364), IMSI='262420000000036'H, TLLI='CFF8BD92'O, index=0 SGSN_Test-GSUP(362)@bb9044106d99: Created GsupExpect[0] for "262420000000036" to be handled at TC_attach_check_complete_resend(364) TC_attach_check_complete_resend(364)@bb9044106d99: GSUP sends only 2G auth tuple{ tag := OSMO_GSUP_AUTH_TUPLE_IE (3), len := 0, val := { auth_tuple := { { tag := OSMO_GSUP_RAND_IE (32), len := 0, val := { rand := 'E8E74F960D6B1406DCC79399E1578473'O } }, { tag := OSMO_GSUP_SRES_IE (33), len := 0, val := { sres := 'FDB364BD'O } }, { tag := OSMO_GSUP_KC_IE (34), len := 0, val := { kc := '980F0C14A1B7E70D'O } } } } } 20240816124636244 DLNS DEBUG 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) 20240816124636244 DLLC NOTICE LLME(ffffffff/cff8bd92){UNASSIGNED} LLC RX: unknown TLLI 0xcff8bd92, creating LLME on the fly (gprs_llc.c:552) 20240816124636244 DLLC DEBUG LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0x24bf94 CMD=UI DATA (gprs_llc_parse.c:89) 20240816124636244 DMM INFO MM(---/ffffffff) -> GMM ATTACH REQUEST MI(IMSI-262420000000036) type="Combined GPRS/IMSI attach"  (gprs_gmm.c:1266) 20240816124636244 DMM DEBUG GMM(gmm_fsm)[0x6120000108a0]{Deregistered}: Allocated (fsm.c:456) 20240816124636244 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{Init}: Allocated (fsm.c:456) 20240816124636244 DMM DEBUG MM_STATE_Gb[0x612000010ba0]{Idle}: Allocated (fsm.c:456) 20240816124636244 DMM DEBUG MM_STATE_Iu[0x612000010d20]{Detached}: Allocated (fsm.c:456) 20240816124636244 DMM DEBUG GMM(gmm_fsm)[0x6120000108a0]{Deregistered}: Received Event E_GMM_COMMON_PROC_INIT_REQ (gprs_gmm.c:1144) 20240816124636244 DMM DEBUG GMM(gmm_fsm)[0x6120000108a0]{Deregistered}: state_chg to CommonProcedureInitiated (gprs_gmm_fsm.c:49) 20240816124636244 DLLC NOTICE LLME(ffffffff/cff8bd92){UNASSIGNED} LLGM Assign pre (cff8bd92 => e7e27a3f) (gprs_llc.c:1079) 20240816124636244 DLLC NOTICE LLME(cff8bd92/e7e27a3f){ASSIGNED} LLGM Assign post (cff8bd92 => e7e27a3f) (gprs_llc.c:1125) 20240816124636244 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{Init}: Received Event E_ATTACH_REQ_RECV (gprs_gmm.c:1370) 20240816124636244 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{Init}: state_chg to CheckIdentity (gprs_gmm_attach.c:52) 20240816124636245 DMM DEBUG MM(262420000000036/e7e27a3f) <- GMM IDENTITY REQUEST: mi_type=IMEI (gprs_gmm.c:431) 20240816124636255 DLNS DEBUG 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) 20240816124636255 DLLC DEBUG LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0x612fca CMD=UI DATA (gprs_llc_parse.c:89) 20240816124636255 DMM DEBUG MM_STATE_Gb(0)[0x612000010ba0]{Idle}: Received Event E_MM_PDU_RECEPTION (gprs_gmm.c:2333) 20240816124636255 DMM DEBUG MM(262420000000036/e7e27a3f) -> GMM IDENTITY RESPONSE: MI=IMEI-499990000000360 (gprs_gmm.c:1084) 20240816124636255 DMM NOTICE MM(262420000000036/e7e27a3f) Stopping *inactive* MM timer 3370 (gprs_gmm.c:115) 20240816124636255 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{CheckIdentity}: Received Event E_IDEN_RESP_RECV (gprs_gmm.c:1128) 20240816124636255 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{CheckIdentity}: state_chg to Authenticate (gprs_gmm_attach.c:115) 20240816124636255 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{Authenticate}: state_chg to AskVLR (gprs_gmm_attach.c:143) 20240816124636255 DMM DEBUG MM(262420000000036/e7e27a3f) Requesting authorization (sgsn_auth.c:160) 20240816124636256 DMM INFO MM(262420000000036/e7e27a3f) Requesting authentication tuples (sgsn_auth.c:184) 20240816124636256 DMM DEBUG MM(262420000000036/e7e27a3f) Requesting subscriber authentication info (gprs_subscriber.c:921) 20240816124636256 DGPRS INFO SUBSCR(262420000000036) requesting auth info (gprs_subscriber.c:805) 20240816124636256 DGPRS INFO SUBSCR(262420000000036) Sending GSUP, will send: 08 01 08 62 42 02 00 00 00 30 f6 28 01 01 (gprs_subscriber.c:210) SGSN_Test-GSUP(362)@bb9044106d99: Found GsupExpect[0] for "262420000000036" handled at TC_attach_check_complete_resend(364) SGSN_Test-GSUP(362)@bb9044106d99: Added IMSI table entry 0TC_attach_check_complete_resend(364)"262420000000036" 20240816124636258 DGPRS INFO SUBSCR(262420000000036) Received GSUP message OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT (gprs_subscriber.c:723) 20240816124636258 DGPRS INFO SUBSCR(262420000000036) Got SendAuthenticationInfoResult, num_auth_vectors = 1 (gprs_subscriber.c:242) 20240816124636258 DGPRS DEBUG SUBSCR(262420000000036) Adding auth tuple, cksn = 0 (gprs_subscriber.c:255) 20240816124636258 DGPRS DEBUG SUBSCR(262420000000036) Updating subscriber authentication info (gprs_subscriber.c:850) 20240816124636258 DMM INFO MM(262420000000036/e7e27a3f) Subscriber data update (mmctx.c:430) 20240816124636258 DMM DEBUG MM(262420000000036/e7e27a3f) Updating authorization (unknown -> authenticate) (sgsn_auth.c:217) 20240816124636259 DMM INFO MM(262420000000036/e7e27a3f) Got authorization update: state unknown -> authenticate (sgsn_auth.c:246) 20240816124636259 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{AskVLR}: Received Event E_VLR_ANSWERED (gprs_gmm.c:991) 20240816124636259 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{AskVLR}: state_chg to Authenticate (gprs_gmm_attach.c:253) 20240816124636259 DMM INFO MM(262420000000036/e7e27a3f) <- GMM AUTH AND CIPHERING REQ (rand = e8 e7 4f 96 0d 6b 14 06 dc c7 93 99 e1 57 84 73 , mmctx_is_r99=0, vec->auth_types=0x1) (gprs_gmm.c:486) 20240816124636264 DLNS DEBUG 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) 20240816124636264 DLLC DEBUG LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xe44d18 CMD=UI DATA (gprs_llc_parse.c:89) 20240816124636264 DMM DEBUG MM_STATE_Gb(0)[0x612000010ba0]{Idle}: Received Event E_MM_PDU_RECEPTION (gprs_gmm.c:2333) 20240816124636264 DMM INFO MM(262420000000036/e7e27a3f) -> GMM AUTH AND CIPH RESPONSE (gprs_gmm.c:620) 20240816124636264 DMM NOTICE MM(262420000000036/e7e27a3f) Stopping *inactive* MM timer 3360 (gprs_gmm.c:115) 20240816124636264 DMM DEBUG MM(262420000000036/e7e27a3f) checking auth: received GSM SRES = fd b3 64 bd (gprs_gmm.c:666) 20240816124636264 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{Authenticate}: Received Event E_AUTH_RESP_RECV_SUCCESS (gprs_gmm.c:681) 20240816124636264 DMM DEBUG MM(262420000000036/e7e27a3f) Requesting authorization (sgsn_auth.c:160) 20240816124636264 DMM INFO MM(262420000000036/e7e27a3f) Missing information, requesting subscriber data (sgsn_auth.c:195) 20240816124636264 DMM DEBUG MM(262420000000036/e7e27a3f) Requesting subscriber data update (gprs_subscriber.c:894) 20240816124636264 DGPRS INFO SUBSCR(262420000000036) subscriber data is not available (gprs_subscriber.c:818) 20240816124636264 DGPRS INFO SUBSCR(262420000000036) Sending GSUP, will send: 04 01 08 62 42 02 00 00 00 30 f6 28 01 01 2a 01 01 (gprs_subscriber.c:210) 20240816124636265 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{Authenticate}: state_chg to WaitAttachComplete (gprs_gmm_attach.c:181) 20240816124636265 DMM INFO MM(262420000000036/e7e27a3f) <- GMM ATTACH ACCEPT (new P-TMSI=0xe7e27a3f) (gprs_gmm.c:300) 20240816124636266 DGPRS INFO SUBSCR(262420000000036) Received GSUP message OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gprs_subscriber.c:723) 20240816124636266 DGPRS INFO SUBSCR(262420000000036) Will set PDP info, context id = 0, APN = 2a (gprs_subscriber.c:367) 20240816124636266 DGPRS DEBUG SUBSCR(262420000000036) Updating subscriber data (gprs_subscriber.c:839) 20240816124636266 DMM INFO MM(262420000000036/e7e27a3f) Subscriber data update (mmctx.c:430) 20240816124636266 DMM DEBUG MM(262420000000036/e7e27a3f) Updating authorization (authenticate -> accepted) (sgsn_auth.c:217) 20240816124636266 DMM INFO MM(262420000000036/e7e27a3f) Got authorization update: state authenticate -> accepted (sgsn_auth.c:246) 20240816124636266 DMM NOTICE MM(262420000000036/e7e27a3f) Authorized, continuing procedure, IMSI=262420000000036 (gprs_gmm.c:1000) 20240816124636266 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{WaitAttachComplete}: Received Event E_VLR_ANSWERED (gprs_gmm.c:1005) 20240816124636266 DMM NOTICE MM(262420000000036/e7e27a3f) Unusual event: if MS got no data connection, check that it has APN configured. (gprs_gmm_attach.c:217) 20240816124636266 DGPRS INFO SUBSCR(262420000000036) Sending GSUP, will send: 12 01 08 62 42 02 00 00 00 30 f6 28 01 01 (gprs_subscriber.c:210) 20240816124636266 DGPRS INFO SUBSCR(262420000000036) Received GSUP message OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT (gprs_subscriber.c:723) 20240816124636266 DGPRS DEBUG SUBSCR(262420000000036) Updating subscriber data (gprs_subscriber.c:839) 20240816124636266 DMM INFO MM(262420000000036/e7e27a3f) Subscriber data update (mmctx.c:430) 20240816124636266 DMM DEBUG MM(262420000000036/e7e27a3f) Updating authorization (accepted -> accepted) (sgsn_auth.c:217) TC_attach_check_complete_resend(364)@bb9044106d99: Warning: Re-starting timer T, which is already active (running or expired). 20240816124642265 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{WaitAttachComplete}: Timeout of T3350 (fsm.c:317) 20240816124642265 DMM INFO MM(262420000000036/e7e27a3f) <- GMM ATTACH ACCEPT (new P-TMSI=0xe7e27a3f) (gprs_gmm.c:300) TC_attach_check_complete_resend(364)@bb9044106d99: Warning: Re-starting timer T, which is already active (running or expired). 20240816124645596 DGPRS DEBUG Checking for inactive LLMEs, time = 5623139 (sgsn.c:131) 20240816124648266 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{WaitAttachComplete}: Timeout of T3350 (fsm.c:317) 20240816124648266 DMM INFO MM(262420000000036/e7e27a3f) <- GMM ATTACH ACCEPT (new P-TMSI=0xe7e27a3f) (gprs_gmm.c:300) TC_attach_check_complete_resend(364)@bb9044106d99: Warning: Re-starting timer T, which is already active (running or expired). 20240816124654267 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{WaitAttachComplete}: Timeout of T3350 (fsm.c:317) 20240816124654267 DMM INFO MM(262420000000036/e7e27a3f) <- GMM ATTACH ACCEPT (new P-TMSI=0xe7e27a3f) (gprs_gmm.c:300) TC_attach_check_complete_resend(364)@bb9044106d99: Warning: Re-starting timer T, which is already active (running or expired). 20240816124655196 DLGSUP INFO GSUP ping callback (connected, got PONG) (gsup_client.c:266) 20240816124655196 DLGSUP DEBUG GSUP sending PING (gsup_client.c:288) SGSN_Test-GSUP-IPA(361)@bb9044106d99: CCM Rx:{ msg_type := IPAC_MSGT_PING (0), u := omit } SGSN_Test-GSUP-IPA(361)@bb9044106d99: CCM Tx:{ msg_type := IPAC_MSGT_PONG (1), u := omit } 20240816124655197 DLGSUP DEBUG GSUP receiving PONG (gsup_client.c:225) 20240816124700268 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{WaitAttachComplete}: Timeout of T3350 (fsm.c:317) 20240816124700268 DMM INFO MM(262420000000036/e7e27a3f) <- GMM ATTACH ACCEPT (new P-TMSI=0xe7e27a3f) (gprs_gmm.c:300) TC_attach_check_complete_resend(364)@bb9044106d99: Warning: Re-starting timer T, which is already active (running or expired). 20240816124704371 DLNSSIGNAL INFO NSE(00096)-NSVC(00097) Tx NS-ALIVE (gprs_ns2_message.c:193) 20240816124704373 DLNSSIGNAL INFO NSE(00096)-NSVC(00097) Rx NS-ALIVE-ACK (gprs_ns2.c:1309) 20240816124704373 DLNS DEBUG 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) 20240816124704405 DLNSSIGNAL INFO NSE(00097)-NSVC(00098) Tx NS-ALIVE (gprs_ns2_message.c:193) 20240816124704406 DLNSSIGNAL INFO NSE(00097)-NSVC(00098) Rx NS-ALIVE-ACK (gprs_ns2.c:1309) 20240816124704406 DLNS DEBUG 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) 20240816124704442 DLNSSIGNAL INFO NSE(00098)-NSVC(00099) Tx NS-ALIVE (gprs_ns2_message.c:193) 20240816124704443 DLNSSIGNAL INFO NSE(00098)-NSVC(00099) Rx NS-ALIVE-ACK (gprs_ns2.c:1309) 20240816124704443 DLNS DEBUG 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) 20240816124706269 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{WaitAttachComplete}: Timeout of T3350 (fsm.c:317) 20240816124706269 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{WaitAttachComplete}: Received Event E_REJECT (gprs_gmm_attach.c:444) 20240816124706269 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{WaitAttachComplete}: state_chg to Reject (gprs_gmm_attach.c:397) 20240816124706269 DGPRS INFO SUBSCR(262420000000036) purging MS subscriber (gprs_subscriber.c:785) 20240816124706269 DGPRS INFO SUBSCR(262420000000036) Sending GSUP, will send: 0c 01 08 62 42 02 00 00 00 30 f6 09 00 28 01 01 (gprs_subscriber.c:210) 20240816124706269 DMM DEBUG GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000010a20]{Reject}: Deallocated (fsm.c:568) 20240816124706269 DMM DEBUG MM_STATE_Gb(0)[0x612000010ba0]{Idle}: Deallocated (fsm.c:568) 20240816124706270 DMM DEBUG MM_STATE_Iu[0x612000010d20]{Detached}: Deallocated (fsm.c:568) 20240816124706270 DMM DEBUG GMM(gmm_fsm)[0x6120000108a0]{CommonProcedureInitiated}: Deallocated (fsm.c:568) 20240816124706270 DLLC NOTICE LLME(cff8bd92/e7e27a3f){ASSIGNED} LLGM Assign pre (e7e27a3f => ffffffff) (gprs_llc.c:1079) 20240816124706270 DLLC NOTICE LLME(00000000/00000000){UNASSIGNED} LLGM Assign post (e7e27a3f => ffffffff) (gprs_llc.c:1125) [testenv][generic] Testsuite is done [testenv][generic] Stopping testsuite (180725) [testenv][generic] Merging log files [testenv][generic] + ['podman', 'exec', '-e', 'CCACHE_DIR=/home/osmocom-build/ccache/testenv', '-e', 'TESTENV_CACHE_DIR=https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache', '-e', 'TESTENV_SRC_DIR=/home/osmocom-build/jenkins/workspace', '-e', 'TERM=dumb', '-e', 'TESTENV_GIT_DIR=https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache/git', '-e', 'PATH=https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_testenv/data/scripts:https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/sgsn:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', '-e', 'HOME=/home/osmocom-build', '-t', '-w', 'https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/74/artifact/logs/testsuite', 'testenv-sgsn-generic-osmocom-nightly-asan-20240816-1242-e766b8ba', 'sh', '-c', 'https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/log_merge.sh SGSN_Tests --rm >/dev/null'] Error: container bb9044106d99740e0b73386982751f86cd521fbd5e9223776ed9026150a64a39 does not exist in database: no such container [testenv] podman container crashed! Error: no container with name or ID testenv-sgsn-generic-osmocom-nightly-asan-20240816-1242-e766b8ba found: no such container [testenv][generic] Command failed unexpectedly [testenv][generic] Command: ['podman', 'exec', '-e', 'CCACHE_DIR=/home/osmocom-build/ccache/testenv', '-e', 'TESTENV_CACHE_DIR=https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache', '-e', 'TESTENV_SRC_DIR=/home/osmocom-build/jenkins/workspace', '-e', 'TERM=dumb', '-e', 'TESTENV_GIT_DIR=https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache/git', '-e', 'PATH=https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_testenv/data/scripts:https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/sgsn:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', '-e', 'HOME=/home/osmocom-build', '-t', '-w', 'https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/74/artifact/logs/testsuite', 'testenv-sgsn-generic-osmocom-nightly-asan-20240816-1242-e766b8ba', 'sh', '-c', 'https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/log_merge.sh SGSN_Tests --rm >/dev/null'] [testenv][generic] Returncode: 125 Traceback (most recent call last): File "https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/./testenv.py", line 115, in <module> main() File "https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/./testenv.py", line 104, in main run() File "https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/./testenv.py", line 63, in run testenv.testsuite.run(cfg) File "https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_testenv/testenv/testsuite.py", line 199, in run merge_log_files(cfg) File "https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_testenv/testenv/testsuite.py", line 131, in merge_log_files testenv.cmd.run(cmd, cwd=cwd) File "https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_testenv/testenv/cmd.py", line 86, in run return testenv.podman.exec_cmd(cmd, check=check, env=env, *args, **kwargs) File "https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_testenv/testenv/podman.py", line 133, in exec_cmd testenv.cmd.run( File "https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_testenv/testenv/cmd.py", line 103, in run exit_error_cmd(p, "Command failed unexpectedly") File "https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/ws/_testenv/testenv/cmd.py", line 59, in exit_error_cmd raise RuntimeError("shell command related error, find details right above this python trace") RuntimeError: shell command related error, find details right above this python trace [testenv][generic] Logs saved to: https://jenkins.osmocom.org/jenkins/job/ttcn3-sgsn-test-asan/74/artifact/log...  Build step 'Execute shell' marked build as failure Recording test results [Checks API] No suitable checks publisher found.