Project

General

Profile

Bug #4022

TTCN3: "MSC_Tests.TC_ho_inter_bsc" sometimes causes the whole ttcn3-msc-test{,-latest} job to hang

Added by osmith about 2 months ago. Updated 26 days ago.

Status:
Closed
Priority:
Normal
Assignee:
sysmocom
Category:
-
Target version:
-
Start date:
05/24/2019
Due date:
% Done:

0%

Resolution:

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)?

History

#1 Updated by osmith 26 days ago

  • Status changed from New to Closed

This issue has not happened within the last month.

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)