Looking at the attached logs of OsmoMSC, I also noticed that the RAN connection, that was used for Location Updating, was not reused for MT SMS delivery. Instead, the Paging procedure was initiated (despite there was an active connection):
### Final part of Location Updating procedure
DMM gsm_04_08.c:1126 TMSI Reallocation Completed. Subscriber: IMSI-901700000009031:MSISDN-2014:TMSI-0x46C2D4D8:TMSInew-0xA3B74039
DMM ran_conn.c:735 RAN_conn(IMSI-901700000009031:MSISDN-2014:TMSI-0xA3B74039:GERAN-A-0:LU)[0x61200001f720]{RAN_CONN_S_AUTH_CIPH}: Updated ID
DMM vlr_lu_fsm.c:741 RAN_conn(IMSI-901700000009031:MSISDN-2014:TMSI-0xA3B74039:GERAN-A-0:LU)[0x61200001f720]{RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
### Here we inform ESME that subscriber is available
DSMPP smpp_smsc.c:653 [esme-2013] Tx ALERT_NOTIFICATION (2014/3/1): Available
### Here we allocate a new transaction for MT SMS
DLSMS gsm_04_11.c:1064 Going to send a MT SMS
DCC transaction.c:118 (ti 00 sub IMSI-901700000009031:MSISDN-2014:TMSI-0xA3B74039 callref 40000001) New transaction
DREF transaction.c:124 VLR subscr IMSI-901700000009031:MSISDN-2014:TMSI-0xA3B74039 usage increases to: 4
DLSMS gsm0411_smc.c:95 SMC(0) instance created for network
DLSMS gsm0411_smr.c:91 SMR(0) instance created for network.
DLSMS gsm0411_smr.c:421 SMR(0) message SM-RL-DATA_REQ received in state IDLE
DLSMS gsm0411_smr.c:221 SMR(0) TX SMS RP-DATA
DLSMS gsm0411_smr.c:145 SMR(0) new RP state IDLE -> WAIT_FOR_RP_ACK
DLSMS gsm0411_smc.c:474 SMC(0) message MNSMS-EST-REQ received in state IDLE
DLSMS gsm0411_smc.c:141 SMC(0) new CP state IDLE -> MM_CONN_PENDING
### Despite we still have an active connection, OsmoMSC initiates the Paging procedure
DLSMS gsm_04_11.c:194 Initiating Paging procedure for IMSI-901700000009031:MSISDN-2014:TMSI-0xA3B74039 due to MMSMS_EST_REQ
DMM gsm_subscriber.c:163 Subscriber IMSI-901700000009031:MSISDN-2014:TMSI-0xA3B74039 not paged yet, start paging.
### And now the existing connection becomes available for SMS delivery, but it's too late :/
DMM ran_conn.c:146 RAN_conn(IMSI-901700000009031:MSISDN-2014:TMSI-0xA3B74039:GERAN-A-0:LU)[0x61200001f720]{RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
DREF osmo_msc.c:114 IMSI-901700000009031:MSISDN-2014:TMSI-0xA3B74039: MSC conn use - dtap == 0 (0x0: )
DMM ran_conn.c:906 RAN_conn(IMSI-901700000009031:MSISDN-2014:TMSI-0xA3B74039:GERAN-A-0:LU)[0x61200001f720]{RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED
DMM ran_conn.c:297 RAN_conn(IMSI-901700000009031:MSISDN-2014:TMSI-0xA3B74039:GERAN-A-0:LU)[0x61200001f720]{RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING
After a short investigation, I found the reason why it was working before, and why doesn't work now:
struct ran_conn *connection_for_subscr(struct vlr_subscr *vsub)
{
struct gsm_network *net = vsub->vlr->user_ctx;
struct ran_conn *conn;
llist_for_each_entry(conn, &net->ran_conns, entry) {
if (conn->vsub != vsub)
continue;
/* Found a conn, but is it in a usable state? Must not add transactions to a conn that is in release,
* and must not start transactions for an unauthenticated subscriber. There will obviously be only one
* conn for this vsub, so return NULL right away. */
if (!ran_conn_is_accepted(conn))
return NULL;
return conn;
}
return NULL;
}
At the moment we trigger the SMS queue, the existing RAN connection is still in state RAN_CONN_S_AUTH_CIPH!
