Bug #5532: Assert failed osmo_use_count_get_put() - OsmoMSC - Open Source Mobile Communications

Actions

Copy link

Bug #5532

closed

Assert failed osmo_use_count_get_put()

Added by keith about 2 years ago. Updated almost 2 years ago.

Status:

Resolved

Priority:

Normal

Assignee:

neels

Category:

Target version:

Start date:

04/17/2022

Due date:

% Done:

100%

Resolution:

Spec Reference:

Description

Apr 16 20:41:30 huautla-bsc osmo-msc[17647]: DMSC ERROR msc_a.c:1685 (IMSI-334020349750006:MSISDN-69610126097:TMSI-0x30156FAD) Cannot tx event to MSC-I, no such role defined
Apr 16 20:41:30 huautla-bsc osmo-msc[17647]: DBSSAP ERROR msc_a.c:881 msc_a(IMSI-334020162777078:MSISDN-69610141108:TMSI-0x4ADE6C87:GERAN-A-112952:CM_SERVICE_REQ)[0x56363376a020]{MSC_A_ST_AUTHENTICATED}: Deallocating active transactions failed
Apr 16 20:41:30 huautla-bsc osmo-msc[17647]: DBSSAP ERROR msc_a.c:881 msc_a(IMSI-334020501994454:MSISDN-69610124271:TMSI-0xB068C7BB:GERAN-A-112949:CM_SERVICE_REQ)[0x5636358a43b0]{MSC_A_ST_AUTHENTICATED}: Deallocating active transactions failed
Apr 16 20:41:30 huautla-bsc osmo-msc[17647]: DBSSAP ERROR msc_a.c:881 msc_a(IMSI-334020547509057:MSISDN-69610143481:TMSI-0x3E52487F:GERAN-A-112942:CM_SERVICE_REQ)[0x563638968e20]{MSC_A_ST_AUTHENTICATED}: Deallocating active transactions failed
Apr 16 20:41:30 huautla-bsc osmo-msc[17647]: DVLR ERROR vlr.c:916 SUBSCR(IMSI-334030256923813:MSISDN-69610142437:TMSI-0x9189A257) Rx GSUP LU Result without LU in progress
Apr 16 20:41:35 huautla-bsc osmo-msc[17647]: DBSSAP ERROR msub.c:360 msc_a(TMSI-0xA8049D6D:GERAN-A-112959:CM_SERVICE_REQ)[0x563635db18d0]{MSC_A_ST_VALIDATE_L3}: Cannot associate with VLR subscr, another connection is already active at IMSI-334020544609239:MSISDN-69610133008:TMSI-0xA8049D6D:GERAN-A-112944:CM_SERVICE_REQ
Apr 16 20:41:35 huautla-bsc osmo-msc[17647]: DBSSAP ERROR msub.c:362 msc_a(IMSI-334020544609239:MSISDN-69610133008:TMSI-0xA8049D6D:GERAN-A-112944:CM_SERVICE_REQ)[0x56363471c6f0]{MSC_A_ST_AUTHENTICATED}: Attempt to associate a second subscriber connection at TMSI-0xA8049D6D:GERAN-A-112959:CM_SERVICE_REQ
Apr 16 20:41:35 huautla-bsc osmo-msc[17647]: DBSSAP ERROR gsm_04_08.c:817 msc_a(TMSI-0xA8049D6D:GERAN-A-112959:CM_SERVICE_REQ)[0x563635db18d0]{MSC_A_ST_RELEASING}: subscriber not allowed to do a CM Service Request
Apr 16 20:41:35 huautla-bsc osmo-msc[17647]: DBSSAP ERROR msc_a.c:1630 msc_a(TMSI-0xA8049D6D:GERAN-A-112959:CM_SERVICE_REQ)[0x563635db18d0]{MSC_A_ST_RELEASING}: RAN decode error (rc=-5) for COMPL_L3 from MSC-I
Apr 16 20:41:36 huautla-bsc osmo-msc[17647]: DMM ERROR gsm_04_08.c:696 msc_a(TMSI-0x3FD0B53C:GERAN-A-112960:CM_SERVICE_REQ)[0x56363689ab60]{MSC_A_ST_COMMUNICATING}: CM Service Request with mismatching mobile identity: TMSI-0x3FD0B53C
Apr 16 20:41:36 huautla-bsc osmo-msc[17647]: Assert failed osmo_use_count_get_put(&msc_a->use_count, msc_a_cm_service_type_to_use(cm_service_type), -1) == 0 gsm_04_08.c:1516

Possibly related to problems arising from #5530
Of course, It would be nice to recover from whatever this is without a restart of the MSC, as that is quite disruptive.

Actions

Copy link

Updated by laforge about 2 years ago

Assignee set to neels

Actions

Copy link

Updated by neels about 2 years ago

crash avoided by https://gerrit.osmocom.org/c/osmo-msc/+/27916

However, keith, there is quite a number of disturbing error messages for such a short log.
There are N subscribers catching seemingly as many weird errors that i would never want to see.
Should we work on that some more?

Actions

Copy link

Updated by keith about 2 years ago

This:

mscpool:subscr:no_msc: 2673 Complete Layer 3 requests lost because no connected MSC is found available

from osmo-bsc show statistics, seems to be of concern.

Looking at the MSC log at a time that osmo-bsc is logging no MSC, I can see it stopped logging for almost 3 minutes!

I guess a suspect might be the sms queue code blocking?

Apr 24 08:35:45 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smc.c:142 SMC(0) new CP state IDLE -> MM_CONN_PENDING

The next line is:

Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS NOTICE gsm_04_11.c:806 trans(SMS IMSI-334020154053674:MSISDN-69610124122:TMSI-0x0CC1BB7D:GERAN-A-201030:PAGING_RESP callref-0x40023
aa7 tid-0) id:18858742 sub:000 dlvrd:000 submit date:YYMMDDhhmm done date:YYMMDDhhmm stat:DELIVRD err:000 text:

Followed by:

Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS NOTICE gsm_04_11.c:831 trans(SMS IMSI-334020154053674:MSISDN-69610124122:TMSI-0x0CC1BB7D:GERAN-A-201030:PAGING_RESP callref-0x40023aa7 tid-0) Status report has been sent
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smc.c:475 SMC(0) message MNSMS-REL-REQ received in state MM_ESTABLISHED
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smc.c:142 SMC(0) new CP state MM_ESTABLISHED -> IDLE
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smr.c:99 SMR(0) clearing SMR instance
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smc.c:103 SMC(0) clearing instance
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smc.c:475 SMC(0) message MNSMS-ABORT-REQ received in state MM_CONN_PENDING
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smc.c:142 SMC(0) new CP state MM_CONN_PENDING -> IDLE
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DMSC ERROR msc_a.c:1668 Attempt to send DTAP to NULL MSC-A, dropping message: SMS SMS:0x10
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smr.c:99 SMR(0) clearing SMR instance
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smc.c:103 SMC(0) clearing instance
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS ERROR gsm_04_11.c:1350 trans(SMS IMSI-334020535468910:MSISDN-69610134819:TMSI-0x13668131 callref-0x40023aa9 tid-0,PAGING) Freeing transaction that still contains an SMS -- discarding
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS NOTICE sms_queue.c:158 Sending SMS 18858724 failed 1 times.
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smc.c:475 SMC(0) message MNSMS-ABORT-REQ received in state MM_CONN_PENDING
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smc.c:142 SMC(0) new CP state MM_CONN_PENDING -> IDLE
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DMSC ERROR msc_a.c:1668 Attempt to send DTAP to NULL MSC-A, dropping message: SMS SMS:0x10
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smr.c:99 SMR(0) clearing SMR instance
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO gsm0411_smc.c:103 SMC(0) clearing instance
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS ERROR gsm_04_11.c:1350 trans(SMS IMSI-334020543397131:MSISDN-69610127938:TMSI-0x806C650D:TMSInew-0x7D46436A callref-0x40023aa8 tid-0,PAGING) Freeing transaction that still contains an SMS -- discarding
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS NOTICE sms_queue.c:158 Sending SMS 18858695 failed 1 times.
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msc_a.c:1247 msc_a(IMSI-334020154053674:MSISDN-69610124122:TMSI-0x0CC1BB7D:GERAN-A-201030:PAGING_RESP)[0x55d5fcfe6ba0]{MSC_A_ST_RELEASING}: Message not permitted for initial conn: SMS:0x01
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msc_a.c:1630 msc_a(IMSI-334020154053674:MSISDN-69610124122:TMSI-0x0CC1BB7D:GERAN-A-201030:PAGING_RESP)[0x55d5fcfe6ba0]{MSC_A_ST_RELEASING}: RAN decode error (rc=-13) for DTAP from MSC-I
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DSMPP INFO smpp_smsc.c:736 [OSMPP] Rx SUBMIT-SM (69610133113/3/1)
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO db.c:774 Stored SMS id=18858743 in DB
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DLSMS INFO smpp_openbsc.c:297 SMPP SUBMIT-SM: Stored in DB
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DVLR ERROR vlr_access_req_fsm.c:371 Process_Access_Request_VLR(TMSI-0x9E052506:GERAN-A-201036:CM_SERVICE_REQ)[0x55d5fe0ece30]{PR_ARQ_S_INIT}: Another proc_arq_fsm is already associated with subscr IMSI-334020162582924:MSISDN-69610133113:TMSI-0x9E052506, terminating the other FSM.
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DVLR ERROR vlr_access_req_fsm.c:103 Process_Access_Request_VLR(IMSI-334020162582924:MSISDN-69610133113:TMSI-0x9E052506:GERAN-A-201032:CM_SERVICE_REQ)[0x55d60199f7e0]{PR_ARQ_S_DONE}: transition to state PR_ARQ_S_DONE not permitted!
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msub.c:360 msc_a(TMSI-0x9E052506:GERAN-A-201036:CM_SERVICE_REQ)[0x55d5f9df4f80]{MSC_A_ST_VALIDATE_L3}: Cannot associate with VLR subscr, another connection is already active at IMSI-334020162582924:MSISDN-69610133113:TMSI-0x9E052506:GERAN-A-201032:CM_SERVICE_REQ
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msub.c:362 msc_a(IMSI-334020162582924:MSISDN-69610133113:TMSI-0x9E052506:GERAN-A-201032:CM_SERVICE_REQ)[0x55d5fc415a40]{MSC_A_ST_AUTHENTICATED}: Attempt to associate a second subscriber connection at TMSI-0x9E052506:GERAN-A-201036:CM_SERVICE_REQ
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR gsm_04_08.c:817 msc_a(TMSI-0x9E052506:GERAN-A-201036:CM_SERVICE_REQ)[0x55d5f9df4f80]{MSC_A_ST_RELEASING}: subscriber not allowed to do a CM Service Request
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msc_a.c:1630 msc_a(TMSI-0x9E052506:GERAN-A-201036:CM_SERVICE_REQ)[0x55d5f9df4f80]{MSC_A_ST_RELEASING}: RAN decode error (rc=-5) for COMPL_L3 from MSC-I
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DSMPP INFO smpp_smsc.c:706 [OSMPP] Rx DELIVER-SM RESP (No Error)
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DVLR ERROR vlr_access_req_fsm.c:371 Process_Access_Request_VLR(TMSI-0x1D648D30:GERAN-A-201040:CM_SERVICE_REQ)[0x55d6026c4000]{PR_ARQ_S_INIT}: Another proc_arq_fsm is already associated with subscr IMSI-334020492933126:MSISDN-69610147400:TMSI-0x1D648D30, terminating the other FSM.
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DVLR ERROR vlr_access_req_fsm.c:103 Process_Access_Request_VLR(IMSI-334020492933126:MSISDN-69610147400:TMSI-0x1D648D30:GERAN-A-201034:CM_SERVICE_REQ)[0x55d6031fce30]{PR_ARQ_S_DONE}: transition to state PR_ARQ_S_DONE not permitted!
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msub.c:360 msc_a(TMSI-0x1D648D30:GERAN-A-201040:CM_SERVICE_REQ)[0x55d5fb63dfe0]{MSC_A_ST_VALIDATE_L3}: Cannot associate with VLR subscr, another connection is already active at IMSI-334020492933126:MSISDN-69610147400:TMSI-0x1D648D30:GERAN-A-201034:CM_SERVICE_REQ
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msub.c:362 msc_a(IMSI-334020492933126:MSISDN-69610147400:TMSI-0x1D648D30:GERAN-A-201034:CM_SERVICE_REQ)[0x55d5fb4a2e40]{MSC_A_ST_AUTHENTICATED}: Attempt to associate a second subscriber connection at TMSI-0x1D648D30:GERAN-A-201040:CM_SERVICE_REQ
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR gsm_04_08.c:817 msc_a(TMSI-0x1D648D30:GERAN-A-201040:CM_SERVICE_REQ)[0x55d5fb63dfe0]{MSC_A_ST_RELEASING}: subscriber not allowed to do a CM Service Request
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msc_a.c:1630 msc_a(TMSI-0x1D648D30:GERAN-A-201040:CM_SERVICE_REQ)[0x55d5fb63dfe0]{MSC_A_ST_RELEASING}: RAN decode error (rc=-5) for COMPL_L3 from MSC-I
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DMSC ERROR msc_a.c:1433 msc_a(IMSI-334020154053674:MSISDN-69610124122:TMSI-0x0CC1BB7D:GERAN-A-201030:PAGING_RESP)[0x55d5fcfe6ba0]{MSC_A_ST_RELEASING}: Event MSC_A_EV_MO_CLOSE not permitted
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msc_a.c:1630 msc_a(IMSI-334020154053674:MSISDN-69610124122:TMSI-0x0CC1BB7D:GERAN-A-201030:PAGING_RESP)[0x55d5fcfe6ba0]{MSC_A_ST_RELEASING}: RAN decode error (rc=-1) for CLEAR_REQUEST from MSC-I
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DMSC ERROR msc_a.c:1685 (IMSI-334020349284655:MSISDN-69610145466:TMSI-0x58080331) Cannot tx event to MSC-I, no such role defined
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DMSC ERROR msc_a.c:1685 (IMSI-334050065100887:MSISDN-69610133733:TMSI-0x009E27C2) Cannot tx event to MSC-I, no such role defined
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DMSC ERROR msc_a.c:1685 (IMSI-334030310764079:MSISDN-69610147297:TMSI-0x8A57E8B5) Cannot tx event to MSC-I, no such role defined
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DMSC ERROR msc_a.c:1685 (IMSI-334020434290129:MSISDN-69610129638:TMSI-0x171C9B78) Cannot tx event to MSC-I, no such role defined
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msc_a.c:881 msc_a(IMSI-334020345281495:MSISDN-69610141078:TMSI-0x0B40C5BB:GERAN-A-201039:CM_SERVICE_REQ)[0x55d5fa44dd00]{MSC_A_ST_AUTHENTICATED}: Deallocating active transactions failed
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msc_a.c:881 msc_a(IMSI-334020162582924:MSISDN-69610133113:TMSI-0x9E052506:GERAN-A-201032:CM_SERVICE_REQ)[0x55d5fc415a40]{MSC_A_ST_AUTHENTICATED}: Deallocating active transactions failed
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DMSC ERROR msc_a.c:1685 (IMSI-334020167279618:MSISDN-69610122328:TMSI-0x3827D686) Cannot tx event to MSC-I, no such role defined
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DMSC ERROR msc_a.c:1685 (IMSI-334020162823590:MSISDN-69610134503:TMSI-0x8AFA14FF) Cannot tx event to MSC-I, no such role defined
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DCC ERROR gsm_04_08_cc.c:1901 trans(NULL NULL callref-0x0 tid-0) Unknown call reference for MNCC_REL_REQ
Apr 24 08:38:38 huautla-bsc osmo-msc[17564]: DBSSAP ERROR msc_a.c:881 msc_a(IMSI-334020492933126:MSISDN-69610147400:TMSI-0x1D648D30:GERAN-A-201034:CM_SERVICE_REQ)[0x55d5fb4a2e40]{MSC_A_ST_AUTHENTICATED}: Deallocating active transactions failed

Actions

Copy link