Bug #4022
closedTTCN3: "MSC_Tests.TC_ho_inter_bsc" sometimes causes the whole ttcn3-msc-test{,-latest} job to hang
0%
Description
From time to time, "MSC_Tests.TC_ho_inter_bsc" hangs here:
------ MSC_Tests.TC_ho_inter_bsc ------ Wed May 22 03:29:39 UTC 2019 Waiting for packet dumper to start... 0 MTC@e12ba6715163: External command `../ttcn3-tcpdump-start.sh MSC_Tests.TC_ho_inter_bsc' was executed successfully (exit status: 0). MTC@e12ba6715163: Test case TC_ho_inter_bsc started. MTC@e12ba6715163: Connecting BSSAP RAN_Emulation to SCCP_SP_PORT MTC@e12ba6715163: Starting RAN_Emulation MSC_Test_0-M3UA(1006)@e12ba6715163: ************************************************* MSC_Test_0-M3UA(1006)@e12ba6715163: M3UA emulation initiated, the test can be started MSC_Test_0-M3UA(1006)@e12ba6715163: ************************************************* MSC_Test_0-SCCP(1004)@e12ba6715163: v_sccp_pdu_maxlen:268 MTC@e12ba6715163: Connecting BSSAP RAN_Emulation to SCCP_SP_PORT MTC@e12ba6715163: Starting RAN_Emulation MSC_Test_1-M3UA(1009)@e12ba6715163: ************************************************* MSC_Test_1-M3UA(1009)@e12ba6715163: M3UA emulation initiated, the test can be started MSC_Test_1-M3UA(1009)@e12ba6715163: ************************************************* MSC_Test_1-SCCP(1007)@e12ba6715163: v_sccp_pdu_maxlen:268 MSC_Test-MNCC(1011)@e12ba6715163: Ignoring MNCC { msg_type := MNCC_SOCKET_HELLO (1024), u := { hello := { version := 5, mncc_size := 836, data_frame_size := 8, called_offset := 104, signal_offset := 796, emergency_offset := 812, lchan_type_offset := 832 } } } MSC_Test_0-M3UA(1006)@e12ba6715163: Warning: The maximum number of open file descriptors (1048576) is greater than FD_SETSIZE (1024). Ensure that Test Ports using Install_Handler do not try to wait for events of file descriptors with values greater than FD_SETSIZE (1024). (Current caller of Install_Handler is "SCTP_PORT") MSC_Test_0-M3UA(1006)@e12ba6715163: SCTP_ConnectResult -> connection established from: "172.18.1.103":23906 to server: "172.18.1.200":2905 association #8 MSC_Test_0-M3UA(1006)@e12ba6715163: Association #8 state changed to aSP_Down_sCTP_Associate_done (2) MSC_Test_0-M3UA(1006)@e12ba6715163: Association #8 state changed to: aSP_Down_commUP_Received (3) MSC_Test_0-M3UA(1006)@e12ba6715163: M3UA_ASPUP sent MSC_Test_0-M3UA(1006)@e12ba6715163: Association #8 state changed to: aSP_Down_ASPUP_Sent (4) MSC_Test_0-M3UA(1006)@e12ba6715163: Message received on association #8 MSC_Test_0-M3UA(1006)@e12ba6715163: M3UA_ASPUP_Ack received -> send M3UA_ASPAC MSC_Test_0-M3UA(1006)@e12ba6715163: Association #8 state changed to: aSP_Inactive (5) MSC_Test_0-M3UA(1006)@e12ba6715163: Association #8 state changed to: aSP_Inact_ASPAC_Sent (6) MSC_Test_0-M3UA(1006)@e12ba6715163: Message received on association #8 MSC_Test_0-M3UA(1006)@e12ba6715163: Received M3UA_NOTIFY -> discard MSC_Test_0-M3UA(1006)@e12ba6715163: Message received on association #8 MSC_Test_0-M3UA(1006)@e12ba6715163: ASPAC_Ack received for association #8 MSC_Test_0-M3UA(1006)@e12ba6715163: Association #8 state changed to: aSP_Active (7) MSC_Test_0-M3UA(1006)@e12ba6715163: Message received on association #8 MSC_Test_0-M3UA(1006)@e12ba6715163: Received M3UA_NOTIFY -> discard MSC_Test_1-M3UA(1009)@e12ba6715163: Warning: The maximum number of open file descriptors (1048576) is greater than FD_SETSIZE (1024). Ensure that Test Ports using Install_Handler do not try to wait for events of file descriptors with values greater than FD_SETSIZE (1024). (Current caller of Install_Handler is "SCTP_PORT") MSC_Test_1-M3UA(1009)@e12ba6715163: SCTP_ConnectResult -> connection established from: "172.18.1.103":23907 to server: "172.18.1.200":2905 association #8 MSC_Test_1-M3UA(1009)@e12ba6715163: Association #8 state changed to aSP_Down_sCTP_Associate_done (2) MSC_Test_1-M3UA(1009)@e12ba6715163: Association #8 state changed to: aSP_Down_commUP_Received (3) MSC_Test_1-M3UA(1009)@e12ba6715163: M3UA_ASPUP sent MSC_Test_1-M3UA(1009)@e12ba6715163: Association #8 state changed to: aSP_Down_ASPUP_Sent (4) MSC_Test_1-M3UA(1009)@e12ba6715163: Message received on association #8 MSC_Test_1-M3UA(1009)@e12ba6715163: M3UA_ASPUP_Ack received -> send M3UA_ASPAC MSC_Test_1-M3UA(1009)@e12ba6715163: Association #8 state changed to: aSP_Inactive (5) MSC_Test_1-M3UA(1009)@e12ba6715163: Association #8 state changed to: aSP_Inact_ASPAC_Sent (6) MSC_Test_1-M3UA(1009)@e12ba6715163: Message received on association #8 MSC_Test_1-M3UA(1009)@e12ba6715163: Received M3UA_NOTIFY -> discard MSC_Test_1-M3UA(1009)@e12ba6715163: Message received on association #8 MSC_Test_1-M3UA(1009)@e12ba6715163: ASPAC_Ack received for association #8 MSC_Test_1-M3UA(1009)@e12ba6715163: Association #8 state changed to: aSP_Active (7) MSC_Test_1-M3UA(1009)@e12ba6715163: Message received on association #8 MSC_Test_1-M3UA(1009)@e12ba6715163: Received M3UA_NOTIFY -> discard MSC_Test-GSUP-IPA(1013)@e12ba6715163: IPA: Connected MSC_Test-GSUP-IPA(1013)@e12ba6715163: CCM Tx:{ msg_type := IPAC_MSGT_ID_GET (4), u := { get := { { len := 1, tag := IPAC_IDTAG_UNITNAME (1) } } } } MSC_Test-GSUP-IPA(1013)@e12ba6715163: CCM Rx:{ msg_type := IPAC_MSGT_PING (0), u := omit } MSC_Test-GSUP-IPA(1013)@e12ba6715163: CCM Tx:{ msg_type := IPAC_MSGT_PONG (1), u := omit } MSC_Test-GSUP-IPA(1013)@e12ba6715163: CCM Rx:{ msg_type := IPAC_MSGT_ID_RESP (5), u := { resp := { { len := 23, tag := IPAC_IDTAG_UNITNAME (1), data := '4D53432D30302D30302D30302D30302D30302D303000'O } } } } MSC_Test-GSUP-IPA(1013)@e12ba6715163: IPA ID RESP: { { len := 23, tag := IPAC_IDTAG_UNITNAME (1), data := '4D53432D30302D30302D30302D30302D30302D303000'O } } MSC_Test-GSUP-IPA(1013)@e12ba6715163: CCM Tx:{ msg_type := IPAC_MSGT_ID_ACK (6), u := omit } MSC_Test-GSUP-IPA(1013)@e12ba6715163: CCM Rx:{ msg_type := IPAC_MSGT_ID_ACK (6), u := omit } TC_ho_inter_bsc0(1016)@e12ba6715163: failVTY: Unknown Command TC_ho_inter_bsc0(1016)@e12ba6715163: Dynamic test case error: testcase.stop MSC_Test_0-RAN(1005)@e12ba6715163: Dynamic test case error: Performing a valueof or send operation on a non-specific template of type @BSSAP_Types.BSSMAP_IE_Osmo_OsmuxSupport. MSC_Test_1-RAN(1008)@e12ba6715163: Dynamic test case error: Performing a valueof or send operation on a non-specific template of type @BSSAP_Types.BSSMAP_IE_Osmo_OsmuxSupport. MSC_Test-GSUP-IPA(1013)@e12ba6715163: CCM Rx:{ msg_type := IPAC_MSGT_PING (0), u := omit } MSC_Test-GSUP-IPA(1013)@e12ba6715163: CCM Tx:{ msg_type := IPAC_MSGT_PONG (1), u := omit } MSC_Test-GSUP-IPA(1013)@e12ba6715163: CCM Rx:{ msg_type := IPAC_MSGT_PING (0), u := omit } MSC_Test-GSUP-IPA(1013)@e12ba6715163: CCM Tx:{ msg_type := IPAC_MSGT_PONG (1), u := omit } ...
(Ping, pong goes on forever.)
Recent examples of that failure:
https://jenkins.osmocom.org/jenkins/job/ttcn3-msc-test-latest/224
https://jenkins.osmocom.org/jenkins/job/ttcn3-msc-test-latest/223
https://jenkins.osmocom.org/jenkins/job/ttcn3-msc-test/549
When it runs successfully, instead of the "failVTY: Unknown Command" line and everything below, it says:
MSC_Test-GSUP(12)@9b613c80c993: Created GsupExpect[0] for "262420000000001" to be handled at TC_lu_imsi_noauth_tmsi0(14) TC_lu_imsi_noauth_tmsi0(14)@9b613c80c993: Sending COMPL L3: { discriminator := '0000'B, tiOrSkip := { skipIndicator := '0000'B }, msgs := { mm := { locationUpdateRequest := { messageType := '001000'B, nsd := '00'B, locationUpdatingType := { lut := '10'B, spare1_1 := '0'B, fop := '0'B }, cipheringKeySequenceNumber := { keySequence := '000'B, spare := '0'B }, locationAreaIdentification := { mcc_mnc := '62F220'O, lac := '9999'O }, mobileStationClassmark1 := { rf_PowerCapability := '010'B, a5_1 := '0'B, esind := '1'B, revisionLevel := '10'B, spare1_1 := '0'B }, mobileIdentityLV := { lengthIndicator := 0, mobileIdentityV := { typeOfIdentity := '001'B, oddEvenInd_identity := { imsi := { oddevenIndicator := '1'B, digits := '262420000000001'H, fillerDigit := omit } } } }, classmarkInformationType2_forUMTS := omit, additionalUpdateParameterTV := omit, deviceProperties := omit, mS_NetworkFeatureSupport := omit } } } } MSC_Test_0-M3UA(7)@9b613c80c993: MTP3_SP_PORT: ASP_MTP3_TRANSFERreq received -> message sent via SCTP
I can not reproduce this locally. In MSC_Tests.ttcn, I found that there is a Tguard timeout for other test cases. Maybe we can add it to this test case, too?
Can somebody take a look at this, or tell me roughly how to go about fixing this/how to add the timeout in the right place?
Is there an easy way to reproduce this locally (e.g. by adjusting the test case to always run into the ping-pong sequence that goes on forever)?