Project

General

Profile

Bug #3824

transactions like SMS may trigger while a RAN connection is already in release and cause a heap-use-after-free

Added by neels 17 days ago. Updated 17 days ago.

Status:
In Progress
Priority:
Normal
Assignee:
Category:
-
Target version:
-
Start date:
03/07/2019
Due date:
% Done:

100%

Resolution:

Description

In current osmo-msc master, when a RAN conn goes into release, it first off cleans up its transactions.
It then sends a Clear Command and continues to exist until a Clear Complete -- or a timeout.
If during this time e.g. a periodic SMS queue calls connection_for_subscr(), this connection will actually be returned and used.
The result is that a new transaction is added to a connection that is already in release.
Upon the final Clear Complete or timeout, the conn then deallocates, assuming that its list of transactions is still empty.
If then the transaction fires some async action, like a timeout, the access to its conn pointer becomes a use-after-free.

A log transcript follows.

History

#1 Updated by neels 17 days ago

This log transcript of a ttcn3-msc-test run shows a conn that is in RELEASING state.
When the SMS queue then triggers, this conn is used and causes a use-after-free after it is deallocated and SMS retry triggers.

Wed Mar  6 21:31:35 2019 DLSMS INFO SMC(0) new CP state MM_ESTABLISHED -> IDLE (gsm0411_smc.c:141)
Wed Mar  6 21:31:35 2019 DLSMS DEBUG Got MMSMS_REL_REQ, destroying transaction. (gsm_04_11.c:246)
Wed Mar  6 21:31:35 2019 DLSMS INFO SMR(0) clearing SMR instance (gsm0411_smr.c:98)
Wed Mar  6 21:31:35 2019 DLSMS INFO SMC(0) clearing instance (gsm0411_smc.c:102)
Wed Mar  6 21:31:35 2019 DREF DEBUG VLR subscr IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E usage decreases to: 2 (transaction.c:
168)
Wed Mar  6 21:31:35 2019 DREF DEBUG IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E: MSC conn use - trans_sms == 1 (0x2: dtap) (tran
saction.c:178)
Wed Mar  6 21:31:35 2019 DREF DEBUG IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E: MSC conn use - dtap == 0 (0x0: ) (osmo_msc.c:11
4)
Wed Mar  6 21:31:35 2019 DMM DEBUG RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a0]
{RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_UNUSED (ran_conn.c:904)
Wed Mar  6 21:31:35 2019 DMM DEBUG RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a0]
{RAN_CONN_S_COMMUNICATING}: state_chg to RAN_CONN_S_RELEASING (ran_conn.c:317)
Wed Mar  6 21:31:35 2019 DREF DEBUG IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E: MSC conn use + release == 1 (0x100: release) (r
an_conn.c:353)
Wed Mar  6 21:31:35 2019 DREF DEBUG VLR subscr IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E usage increases to: 3 (vlr.c:304)
Wed Mar  6 21:31:35 2019 DREF DEBUG VLR subscr IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E usage decreases to: 2 (vlr.c:309)
Wed Mar  6 21:31:35 2019 DBSSAP INFO RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a
0]{RAN_CONN_S_RELEASING}: Tx BSSMAP CLEAR COMMAND to BSC (a_iface.c:426)
Wed Mar  6 21:31:35 2019 DBSSAP DEBUG RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2
a0]{RAN_CONN_S_RELEASING}: N-DATA.req(00 04 20 04 01 09 ) (a_iface.c:150)
Wed Mar  6 21:31:36 2019 DVLR DEBUG GSUP rx 53: 28010862420200000090f14001ff41070294210300001942070394210300001943100006802143650000811132813
0858200450102 (vlr.c:1084)
Wed Mar  6 21:31:36 2019 DREF DEBUG VLR subscr IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E usage increases to: 3 (vlr.c:1105)
Wed Mar  6 21:31:36 2019 DMSC DEBUG Routed to GSM 04.11 MT handler (gsm_04_08.c:1837)
Wed Mar  6 21:31:36 2019 DLSMS DEBUG RX MT-forwardSM-Req (gsm_04_11_gsup.c:257)
Wed Mar  6 21:31:36 2019 DLSMS INFO Going to send a MT SMS (gsm_04_11.c:1064)
Wed Mar  6 21:31:36 2019 DCC DEBUG (ti 00 sub IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E callref 40000037) New transaction (tra
nsaction.c:118)
Wed Mar  6 21:31:36 2019 DREF DEBUG VLR subscr IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E usage increases to: 4 (transaction.c:
124)
Wed Mar  6 21:31:36 2019 DLSMS INFO SMC(0) instance created for network (gsm0411_smc.c:95)
Wed Mar  6 21:31:36 2019 DLSMS INFO SMR(0) instance created for network. (gsm0411_smr.c:91)
Wed Mar  6 21:31:36 2019 DREF DEBUG IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E: MSC conn use + trans_sms == 2 (0x120: trans_sms
,release) (gsm_04_11.c:1028)
Wed Mar  6 21:31:36 2019 DLSMS INFO SMR(0) message SM-RL-DATA_REQ received in state IDLE (gsm0411_smr.c:421)
Wed Mar  6 21:31:36 2019 DLSMS DEBUG SMR(0) TX SMS RP-DATA (gsm0411_smr.c:221)
Wed Mar  6 21:31:36 2019 DLSMS INFO SMR(0) new RP state IDLE -> WAIT_FOR_RP_ACK (gsm0411_smr.c:145)
Wed Mar  6 21:31:36 2019 DLSMS INFO SMC(0) message MNSMS-EST-REQ received in state IDLE (gsm0411_smc.c:474)
Wed Mar  6 21:31:36 2019 DLSMS INFO SMC(0) new CP state IDLE -> MM_CONN_PENDING (gsm0411_smc.c:141)
Wed Mar  6 21:31:36 2019 DLSMS DEBUG Using an existing connection for IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E (gsm_04_11.c:1
87)
Wed Mar  6 21:31:36 2019 DLSMS INFO SMC(0) message MMSMS-EST-CNF received in state MM_CONN_PENDING (gsm0411_smc.c:574)
Wed Mar  6 21:31:36 2019 DLSMS INFO SMC(0) send CP data (gsm0411_smc.c:188)
Wed Mar  6 21:31:36 2019 DLSMS INFO SMC(0) new CP state MM_CONN_PENDING -> WAIT_CP_ACK (gsm0411_smc.c:141)
Wed Mar  6 21:31:36 2019 DLSMS DEBUG sending CP message (trans=0) (gsm_04_11.c:224)
Wed Mar  6 21:31:36 2019 DLSMS DEBUG GSM4.11 TX 09 01 1b 01 00 06 94 21 03 00 00 19 00 10 00 06 80 21 43 65 00 00 81 11 32 81 30 85 82 00  (g
sm_04_11.c:124)
Wed Mar  6 21:31:36 2019 DMSC DEBUG msc_tx 30 bytes to IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E via GERAN-A (msc_ifaces.c:54)
Wed Mar  6 21:31:36 2019 DBSSAP DEBUG RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2
a0]{RAN_CONN_S_RELEASING}: Passing DTAP message (DLCI=0x03) from MSC to BSC (a_iface.c:165)
Wed Mar  6 21:31:36 2019 DBSSAP DEBUG RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2
a0]{RAN_CONN_S_RELEASING}: N-DATA.req(01 03 1e 09 01 1b 01 00 06 94 21 03 00 00 19 00 10 00 06 80 21 43 65 00 00 81 11 32 81 30 85 82 00 ) (a
_iface.c:150)
Wed Mar  6 21:31:36 2019 DREF DEBUG VLR subscr IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E usage decreases to: 3 (vlr.c:1153)
Wed Mar  6 21:31:40 2019 DMM DEBUG RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a0]{RAN_CONN_S_RELEASING}: Timeout of T0 (fsm.c:210)
Wed Mar  6 21:31:40 2019 DMM ERROR RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a0]{RAN_CONN_S_RELEASING}: Timeout while releasing, discarding right now (ran_conn.c:329)
Wed Mar  6 21:31:40 2019 DMM DEBUG RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a0]{RAN_CONN_S_RELEASING}: Terminating (cause = OSMO_FSM_TERM_TIMEOUT) (ran_conn.c:330)
Wed Mar  6 21:31:40 2019 DVLR DEBUG Process_Access_Request_VLR(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f120]{PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) (ran_conn.c:330)
Wed Mar  6 21:31:40 2019 DVLR DEBUG Process_Access_Request_VLR(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f120]{PR_ARQ_S_DONE}: Removing from parent RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a0] (ran_conn.c:330)
Wed Mar  6 21:31:40 2019 DVLR DEBUG Process_Access_Request_VLR(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f120]{PR_ARQ_S_DONE}: Freeing instance (ran_conn.c:330)
Wed Mar  6 21:31:40 2019 DVLR DEBUG Process_Access_Request_VLR(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f120]{PR_ARQ_S_DONE}: Deallocated (fsm.c:402)
Wed Mar  6 21:31:40 2019 DMM DEBUG RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a0]{RAN_CONN_S_RELEASING}: ran_conn_fsm_has_active_transactions: connection still has active transaction: SMS (ran_conn.c:257)
Wed Mar  6 21:31:40 2019 DMM ERROR RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a0]{RAN_CONN_S_RELEASING}: Deallocating despite active transactions (ran_conn.c:542)
Wed Mar  6 21:31:40 2019 DRLL DEBUG IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E: Freeing RAN connection (ran_conn.c:550)
Wed Mar  6 21:31:40 2019 DREF DEBUG VLR subscr IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E usage decreases to: 2 (ran_conn.c:553)
Wed Mar  6 21:31:40 2019 DMM DEBUG RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a0]{RAN_CONN_S_RELEASING}: Freeing instance (ran_conn.c:330)
Wed Mar  6 21:31:40 2019 DMM DEBUG RAN_conn(IMSI-262420000000091:MSISDN-491230000091:TMSI-0x158A208E:GERAN-A-135:PAGING_RESP)[0x61200031f2a0]{RAN_CONN_S_RELEASING}: Deallocated (fsm.c:402)
Wed Mar  6 21:31:42 2019 DPAG DEBUG Paging failure for IMSI-262420000011827:MSISDN-491230011827:TMSI-0x986A1B2C (event=1) (gsm_subscriber.c:73)
Wed Mar  6 21:31:42 2019 DPAG DEBUG Paging can stop for IMSI-262420000011827:MSISDN-491230011827:TMSI-0x986A1B2C (osmo_msc.c:225)
Wed Mar  6 21:31:42 2019 DPAG DEBUG Paging without action. (gsm_subscriber.c:103)
Wed Mar  6 21:31:42 2019 DPAG DEBUG Paging without action. (gsm_subscriber.c:103)
Wed Mar  6 21:31:42 2019 DREF DEBUG VLR subscr IMSI-262420000011827:MSISDN-491230011827:TMSI-0x986A1B2C usage decreases to: 3 (gsm_subscriber.c:109)
Wed Mar  6 21:31:46 2019 DLSMS INFO SMC(0) TC1* timeout, retrying... (gsm0411_smc.c:249)
Wed Mar  6 21:31:46 2019 DLSMS INFO SMC(0) send CP data (gsm0411_smc.c:188)
Wed Mar  6 21:31:46 2019 DLSMS INFO SMC(0) new CP state WAIT_CP_ACK -> WAIT_CP_ACK (gsm0411_smc.c:141)
Wed Mar  6 21:31:46 2019 DLSMS DEBUG sending CP message (trans=0) (gsm_04_11.c:224)
Wed Mar  6 21:31:46 2019 DLSMS DEBUG GSM4.11 TX 09 01 1b 01 00 06 94 21 03 00 00 19 00 10 00 06 80 21 43 65 00 00 81 11 32 81 30 85 82 00  (gsm_04_11.c:124)

Address Sanitizer hits here, output lost because it is not written to the log file.
All I remember is that it hits in the osmo_timers trigger for an SMS transaction, at
msc_ifaces.c:52 in msc_tx().

#2 Updated by neels 17 days ago

  • Status changed from New to In Progress
  • Assignee set to neels
  • % Done changed from 0 to 100

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)