Actions
Bug #4784
openwrong cause code (resources unavailable) in MO-to-MT call without response
Start date:
10/08/2020
Due date:
% Done:
0%
Resolution:
Spec Reference:
Description
if a MO-to-MT call is performed using osmo-msc with internal MNCC handler, and the call proceeds up to the "ALERTING" being sent by the MT-leg (but the call is never accepted by the MT side), the CC RELEASE is sent using cause value "resources unavailable, unspecified" (GSM48_CC_CAUSE_RESOURCE_UNAVAIL). This is quite misleading to users, and one is trying to find what kind of resources miight be exhausted. But there is no exhaustion, "B" just never responded the call from "A".
Files
Updated by laforge over 3 years ago
- File os4784-mt_noreply-cc_wrong_release_cause.pcap os4784-mt_noreply-cc_wrong_release_cause.pcap added
add pcap file showing the issue.
I've used a modified TC_lu_and_mt_call to generate this: Simply comment out the "CC CONNECT" line in f_mt_call_complete():
- BSSAP.send(ts_PDU_DTAP_MO(ts_ML3_MO_CC_CONNECT(cpars.transaction_id))); + //BSSAP.send(ts_PDU_DTAP_MO(ts_ML3_MO_CC_CONNECT(cpars.transaction_id)));
Updated by laforge over 3 years ago
What happens in the MSC is an X2 timeout:
1404523:RTP_TO_CN:CI-22222:no-remote-port:local-2-2-2-2-11000)[0x6120000186a0]{DISCARDING}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Thu Oct 8 16:20:52 2020 DCC <0001> rtp_stream.c:231 rtp_stream(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP:trans-0:call-1721404523:RTP_TO_CN:CI-22222:no-remote-port:local-2-2-2-2-11000)[0x6120000186a0]{DISCARDING}: Removing from parent call_leg(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000174a0]
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:647 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{IN_USE}: rtpbridge/1@mgw CI[1] RTP_TO_CN CI=22222: DLCX: notify=NULL
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:694 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{IN_USE}: rtpbridge/1@mgw CI[1] RTP_TO_CN CI=22222: DLCX: Scheduling
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:697 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{IN_USE}: State change to WAIT_MGW_RESPONSE (X2427, 4s)
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:772 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: rtpbridge/1@mgw CI[1] RTP_TO_CN CI=22222: Sending MGCP: DLCX 22222
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client.c:1037 Queued 56 bytes for MGCP GW
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:902 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: rtpbridge/1@mgw Sent messages: 1
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:828 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: rtpbridge/1@mgw CI[0] RTP_TO_RAN CI=11111: MDCX 9.8.7.6:9000: done (rtpbridge/1@mgw:1.1.1.1:10000)
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:846 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: rtpbridge/1@mgw CI in use: 1, waiting for response: 0
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:857 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: State change to IN_USE (no timeout)
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:828 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{IN_USE}: rtpbridge/1@mgw CI[0] RTP_TO_RAN CI=11111: MDCX 9.8.7.6:9000: done (rtpbridge/1@mgw:1.1.1.1:10000)
Thu Oct 8 16:20:52 2020 DCC <0001> rtp_stream.c:231 rtp_stream(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP:trans-0:call-1721404523:RTP_TO_CN:CI-22222:no-remote-port:local-2-2-2-2-11000)[0x6120000186a0]{DISCARDING}: Freeing instance
Thu Oct 8 16:20:52 2020 DCC <0001> fsm.c:573 rtp_stream(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP:trans-0:call-1721404523:RTP_TO_CN:CI-22222:no-remote-port:local-2-2-2-2-11000)[0x6120000186a0]{DISCARDING}: Deallocated
Thu Oct 8 16:20:52 2020 DCC <0001> rtp_stream.c:231 call_leg(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000174a0]{ESTABLISHING}: Received Event CALL_LEG_EV_RTP_STREAM_GONE
Thu Oct 8 16:20:52 2020 DCC <0001> call_leg.c:124 call_leg(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000174a0]{ESTABLISHING}: State change to RELEASING (X2, 30s)
Thu Oct 8 16:20:52 2020 DCC <0001> call_leg.c:189 call_leg(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000174a0]{RELEASING}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Thu Oct 8 16:20:52 2020 DCC <0001> call_leg.c:189 rtp_stream(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP:trans-0:call-1721404523:RTP_TO_RAN:CI-11111:local-1-1-1-1-10000:remote-9-8-7-6-9000)[0x6120000177a0]{ESTABLISHED}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Thu Oct 8 16:20:52 2020 DCC <0001> call_leg.c:189 rtp_stream(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP:trans-0:call-1721404523:RTP_TO_RAN:CI-11111:local-1-1-1-1-10000:remote-9-8-7-6-9000)[0x6120000177a0]{ESTABLISHED}: Removing from parent call_leg(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000174a0]
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:647 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{IN_USE}: rtpbridge/1@mgw CI[0] RTP_TO_RAN CI=11111: DLCX: notify=NULL
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:694 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{IN_USE}: rtpbridge/1@mgw CI[0] RTP_TO_RAN CI=11111: DLCX: Scheduling
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:697 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{IN_USE}: State change to WAIT_MGW_RESPONSE (X2427, 4s)
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:772 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: rtpbridge/1@mgw CI[0] RTP_TO_RAN CI=11111: Sending MGCP: DLCX 11111
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client.c:1037 Queued 56 bytes for MGCP GW
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:902 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: rtpbridge/1@mgw Sent messages: 1
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:846 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: rtpbridge/1@mgw CI in use: 0, waiting for response: 0
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:851 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:851 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: Removing from parent call_leg(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000174a0]
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client_endpoint_fsm.c:851 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: Freeing instance
Thu Oct 8 16:20:52 2020 DLMGCP <0023> fsm.c:573 mgw-endp(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000017620]{WAIT_MGW_RESPONSE}: Deallocated
Thu Oct 8 16:20:52 2020 DCC <0001> mgcp_client_endpoint_fsm.c:851 call_leg(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000174a0]{RELEASING}: FSM instance already terminating, not dispatching event CALL_LEG_EV_MGW_ENDPOINT_GONE
Thu Oct 8 16:20:52 2020 DCC <0001> call_leg.c:189 rtp_stream(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP:trans-0:call-1721404523:RTP_TO_RAN:CI-11111:local-1-1-1-1-10000:remote-9-8-7-6-9000)[0x6120000177a0]{ESTABLISHED}: Freeing instance
Thu Oct 8 16:20:52 2020 DCC <0001> fsm.c:573 rtp_stream(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP:trans-0:call-1721404523:RTP_TO_RAN:CI-11111:local-1-1-1-1-10000:remote-9-8-7-6-9000)[0x6120000177a0]{ESTABLISHED}: Deallocated
Thu Oct 8 16:20:52 2020 DCC <0001> call_leg.c:189 call_leg(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000174a0]{RELEASING}: Removing from parent msc_a(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000014f20]
Thu Oct 8 16:20:52 2020 DCC <0001> call_leg.c:189 call_leg(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000174a0]{RELEASING}: Freeing instance
Thu Oct 8 16:20:52 2020 DCC <0001> fsm.c:573 call_leg(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000174a0]{RELEASING}: Deallocated
Thu Oct 8 16:20:52 2020 DCC <0001> transaction.c:170 trans(CC:CALL_RECEIVED IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP callref-0x669a8c6b tid-0) Freeing transaction
Thu Oct 8 16:20:52 2020 DCC <0001> gsm_04_08_cc.c:223 trans(CC:CALL_RECEIVED IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP callref-0x669a8c6b tid-0) stopping pending timer T301
Thu Oct 8 16:20:52 2020 DCC <0001> gsm_04_08_cc.c:482 trans(CC:CALL_RECEIVED IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP callref-0x669a8c6b tid-0) starting timer T308 with 10 seconds
Thu Oct 8 16:20:52 2020 DCC <0001> gsm_04_08_cc.c:189 trans(CC:CALL_RECEIVED IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP callref-0x669a8c6b tid-0) new state CALL_RECEIVED -> RELEASE_REQ
Thu Oct 8 16:20:52 2020 DMNCC <0004> gsm_04_08_cc.c:235 trans(CC:RELEASE_REQ IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP callref-0x669a8c6b tid-0) tx MNCC_REL_CNF
Thu Oct 8 16:20:52 2020 DCC <0001> gsm_04_08_cc.c:223 trans(CC:RELEASE_REQ IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP callref-0x669a8c6b tid-0) stopping pending timer T308
Thu Oct 8 16:20:52 2020 DCC <0001> gsm_04_08_cc.c:189 trans(CC:RELEASE_REQ IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP callref-0x669a8c6b tid-0) new state RELEASE_REQ -> NULL
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client.c:737 Tx MGCP: r=127.0.0.1:2427<->l=127.0.0.1:2727: len=56 'DLCX 4 rtpbridge/1@mgw MGCP 1.0\r\nC: 669a8c'...
Thu Oct 8 16:20:52 2020 DLMGCP <0023> mgcp_client.c:737 Tx MGCP: r=127.0.0.1:2427<->l=127.0.0.1:2727: len=56 'DLCX 5 rtpbridge/1@mgw MGCP 1.0\r\nC: 669a8c'...
Thu Oct 8 16:20:56 2020 DLMGCP <0023> mgcp_client.c:1068 Canceled transaction 5
Thu Oct 8 16:20:56 2020 DRLL <0000> mgcp_client_fsm.c:526 MGCP_CONN(RTP_TO_RAN)[0x612000017aa0]{ST_DLCX_RESP}: MGW/DLCX: FSM termination with connections still present, sending unconditional DLCX...
Thu Oct 8 16:20:56 2020 DLMGCP <0023> mgcp_client.c:1037 Queued 56 bytes for MGCP GW
Thu Oct 8 16:20:56 2020 DLMGCP <0023> mgcp_client.c:1068 Canceled transaction 4
Thu Oct 8 16:20:56 2020 DRLL <0000> mgcp_client_fsm.c:526 MGCP_CONN(RTP_TO_CN)[0x612000018ca0]{ST_DLCX_RESP}: MGW/DLCX: FSM termination with connections still present, sending unconditional DLCX...
Thu Oct 8 16:20:56 2020 DLMGCP <0023> mgcp_client.c:1037 Queued 56 bytes for MGCP GW
Thu Oct 8 16:20:56 2020 DLMGCP <0023> mgcp_client.c:737 Tx MGCP: r=127.0.0.1:2427<->l=127.0.0.1:2727: len=56 'DLCX 6 rtpbridge/1@mgw MGCP 1.0\r\nC: 669a8c'...
Thu Oct 8 16:20:56 2020 DLMGCP <0023> mgcp_client.c:737 Tx MGCP: r=127.0.0.1:2427<->l=127.0.0.1:2727: len=56 'DLCX 7 rtpbridge/1@mgw MGCP 1.0\r\nC: 669a8c'...
Thu Oct 8 16:21:21 2020 DMNCC <0004> mncc_sock.c:76 MNCC Socket has LOST connection
Thu Oct 8 16:21:21 2020 DCC <0001> gsm_04_08.c:87 Clearing all currently active transactions!!!
Thu Oct 8 16:21:21 2020 DLCTRL <001a> control_if.c:188 close()d CTRL connection (r=127.0.0.1:36457<->l=127.0.0.1:4255)
Thu Oct 8 16:21:21 2020 DLCTRL <001a> control_if.c:188 close()d CTRL connection (r=127.0.0.1:36049<->l=127.0.0.1:4255)
Thu Oct 8 16:21:21 2020 DLINP <0015> input/ipa.c:65 127.0.0.1:4222 connection closed with server
Thu Oct 8 16:21:22 2020 DBSSAP <0010> msc_a.c:721 msc_a(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000014f20]{MSC_A_ST_RELEASING}: Timeout while releasing, discarding right now
Thu Oct 8 16:21:22 2020 DVLR <000e> msc_a.c:841 Process_Access_Request_VLR(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000150a0]{PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Thu Oct 8 16:21:22 2020 DVLR <000e> msc_a.c:841 Process_Access_Request_VLR(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000150a0]{PR_ARQ_S_DONE}: Removing from parent msc_a(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x612000014f20]
Thu Oct 8 16:21:22 2020 DVLR <000e> msc_a.c:841 Process_Access_Request_VLR(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000150a0]{PR_ARQ_S_DONE}: Freeing instance
Thu Oct 8 16:21:22 2020 DVLR <000e> fsm.c:573 Process_Access_Request_VLR(IMSI-262420000000039:MSISDN-491230000039:TMSI-0x9B62A951:GERAN-A-1:PAGING_RESP)[0x6120000150a0]{PR_ARQ_S_DONE}: Deallocated
Actions
