Project

General

Profile

Actions

Bug #3152

closed

OsmoMSC heap-use-after-free during processing of RP-ACK in MT-SMS

Added by laforge almost 6 years ago. Updated almost 6 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
SMS
Target version:
-
Start date:
04/09/2018
Due date:
% Done:

100%

Resolution:
Spec Reference:

Description

Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface_bssap.c:68 (subscr unknown, conn_id 1) A-Interface subscriber connection successfully allocated!
Mon Apr  9 19:53:22 2018 DMM <0002> fsm.c:272 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_INIT}: Allocated
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:339 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:59 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:405 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP
Mon Apr  9 19:53:22 2018 DVLR <000e> fsm.c:272 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: Allocated
Mon Apr  9 19:53:22 2018 DVLR <000e> fsm.c:302 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: is child of Subscr_Conn(36223918)[0x612000016420]
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:704 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: rev=R99 net=GERAN (no Auth)
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:730 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:337 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:289 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:255 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:227 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:212 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:196 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:174 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:187 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:109 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
Mon Apr  9 19:53:22 2018 DVLR <000e> vlr_access_req_fsm.c:119 Process_Access_Request_VLR(36223918)[0x6120000165a0]{PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Mon Apr  9 19:53:22 2018 DMM <0002> vlr_access_req_fsm.c:158 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:71 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Mon Apr  9 19:53:22 2018 DMSC <0006> sms_queue.c:422 Pending paging while subscriber 262420000000043 attached.
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:1092 paging_cb_send_sms(hooknum=1, event=0, msg=(nil),conn=0x6140000018a0, sms=0x6170000023e0/id: 4)
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:1013 gsm411_send_sms()
Mon Apr  9 19:53:22 2018 DCC <0001> transaction.c:96 (ti 00 sub MSISDN:491230000043 callref 40000001) New transaction
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:95 SMC(4) instance created for network
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smr.c:91 SMR(4) instance created for network.
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:1073 TX: SMS DELIVER
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smr.c:421 SMR(4) message SM-RL-DATA_REQ received in state IDLE
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smr.c:221 SMR(4) TX SMS RP-DATA
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smr.c:145 SMR(4) new RP state IDLE -> WAIT_FOR_RP_ACK
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:474 SMC(4) message MNSMS-EST-REQ received in state IDLE
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:141 SMC(4) new CP state IDLE -> MM_CONN_PENDING
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:574 SMC(4) message MMSMS-EST-CNF received in state MM_CONN_PENDING
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:188 SMC(4) send CP data
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:141 SMC(4) new CP state MM_CONN_PENDING -> WAIT_CP_ACK
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:142 sending CP message (trans=0)
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:125 GSM4.11 TX 09 01 23 01 00 07 91 44 77 58 10 06 50 00 17 00 04 80 32 24 00 00 81 40 90 91 35 22 80 09 c8 32 9b fd 06 4d 9b 53 
Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface.c:154 (subscr MSISDN:491230000043, conn_id 1) Passing DTAP message (DLCI=0x03) from MSC to BSC
Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface.c:168 (subscr MSISDN:491230000043, conn_id 1) N-DATA.req([])
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:119 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:152 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Mon Apr  9 19:53:22 2018 DMM <0002> osmo_msc.c:100 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:152 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface.c:564 N-DATA.ind(1, 01 03 02 89 04 )
Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface_bssap.c:88 (subscr MSISDN:491230000043, conn_id 1) Found A subscriber for conn_id 1
Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface_bssap.c:620 (subscr MSISDN:491230000043, conn_id 1) Rx DTAP 01 03 02 89 04 
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:920 receiving data (trans_id=0, msg_type=SMS:0x04)
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:364 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:170 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:574 SMC(4) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:263 SMC(4) received CP-ACK
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:141 SMC(4) new CP state WAIT_CP_ACK -> MM_ESTABLISHED
Mon Apr  9 19:53:22 2018 DMM <0002> osmo_msc.c:100 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:152 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface.c:564 N-DATA.ind(1, 01 03 05 89 01 02 02 00 )
Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface_bssap.c:88 (subscr MSISDN:491230000043, conn_id 1) Found A subscriber for conn_id 1
Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface_bssap.c:620 (subscr MSISDN:491230000043, conn_id 1) Rx DTAP 01 03 05 89 01 02 02 00 
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:920 receiving data (trans_id=0, msg_type=SMS:0x01)
Mon Apr  9 19:53:22 2018 DMM <0002> subscr_conn.c:364 Subscr_Conn(36223918)[0x612000016420]{SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:574 SMC(4) message MMSMS-DATA-IND (CP DATA) received in state MM_ESTABLISHED
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smc.c:291 SMC(4) received CP-DATA
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:142 sending CP message (trans=0)
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:125 GSM4.11 TX 09 04 
Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface.c:154 (subscr MSISDN:491230000043, conn_id 1) Passing DTAP message (DLCI=0x03) from MSC to BSC
Mon Apr  9 19:53:22 2018 DBSSAP <0010> a_iface.c:168 (subscr MSISDN:491230000043, conn_id 1) N-DATA.req([])
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:883 MNSMS-DATA/EST-IND
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smr.c:488 SMR(4) message MNSMS-DATA-IND received in state WAIT_FOR_RP_ACK
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smr.c:314 SMR(4) RX SMS RP-ACK
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm0411_smr.c:145 SMR(4) new RP state WAIT_FOR_RP_ACK -> IDLE
Mon Apr  9 19:53:22 2018 DLSMS <0017> gsm_04_11.c:826 RX SMS RP-ACK (MO)
=================================================================
==23190==ERROR: AddressSanitizer: heap-use-after-free on address 0x60d00001c7b8 at pc 0x556b19afebb3 bp 0x7fff6ab0c730 sp 0x7fff6ab0c728
READ of size 8 at 0x60d00001c7b8 thread T0
    #0 0x556b19afebb2 in sms_sms_cb /home/laforge/projects/git/osmo-msc/src/libmsc/sms_queue.c:484
    #1 0x7f29c614104b in osmo_signal_dispatch /home/laforge/projects/git/libosmocore/src/signal.c:111
    #2 0x556b19ada782 in send_signal /home/laforge/projects/git/osmo-msc/src/libmsc/gsm_04_11.c:120
    #3 0x556b19ada782 in gsm411_rx_rp_ack /home/laforge/projects/git/osmo-msc/src/libmsc/gsm_04_11.c:721
    #4 0x556b19ada782 in gsm411_rx_rl_report /home/laforge/projects/git/osmo-msc/src/libmsc/gsm_04_11.c:827
    #5 0x556b19ada782 in gsm411_rl_recv /home/laforge/projects/git/osmo-msc/src/libmsc/gsm_04_11.c:859
    #6 0x7f29c637cab4 in gsm411_mnsms_data_ind_tx /home/laforge/projects/git/libosmocore/src/gsm/gsm0411_smr.c:324
    #7 0x7f29c637bbeb in gsm411_mmsms_cp_data /home/laforge/projects/git/libosmocore/src/gsm/gsm0411_smc.c:303
    #8 0x556b19adc08c in gsm0411_rcv_sms /home/laforge/projects/git/osmo-msc/src/libmsc/gsm_04_11.c:983
    #9 0x556b19ad3082 in gsm0408_dispatch /home/laforge/projects/git/osmo-msc/src/libmsc/gsm_04_08.c:3497
    #10 0x556b19b0456c in msc_dtap /home/laforge/projects/git/osmo-msc/src/libmsc/osmo_msc.c:143
    #11 0x556b19a9e51c in rx_dtap /home/laforge/projects/git/osmo-msc/src/libmsc/a_iface_bssap.c:627
    #12 0x556b19a9e51c in a_sccp_rx_dt /home/laforge/projects/git/osmo-msc/src/libmsc/a_iface_bssap.c:649
    #13 0x556b19a98079 in sccp_sap_up /home/laforge/projects/git/osmo-msc/src/libmsc/a_iface.c:565
    #14 0x7f29c614435e in _osmo_fsm_inst_dispatch /home/laforge/projects/git/libosmocore/src/fsm.c:517
    #15 0x7f29c5ab0984 in sccp_scoc_rx_from_scrc /home/laforge/projects/git/libosmo-sccp/src/sccp_scoc.c:1581
    #16 0x7f29c5aae67a in scrc_rx_mtp_xfer_ind_xua /home/laforge/projects/git/libosmo-sccp/src/sccp_scrc.c:449
    #17 0x7f29c5ab1554 in mtp_user_prim_cb /home/laforge/projects/git/libosmo-sccp/src/sccp_user.c:176
    #18 0x7f29c5aa9392 in m3ua_rx_xfer /home/laforge/projects/git/libosmo-sccp/src/m3ua.c:586
    #19 0x7f29c5aa9392 in m3ua_rx_msg /home/laforge/projects/git/libosmo-sccp/src/m3ua.c:738
    #20 0x7f29c5ab4552 in xua_cli_read_cb /home/laforge/projects/git/libosmo-sccp/src/osmo_ss7.c:1592
    #21 0x7f29c2d6b1fa in osmo_stream_cli_read /home/laforge/projects/git/libosmo-netif/src/stream.c:192
    #22 0x7f29c2d6b1fa in osmo_stream_cli_fd_cb /home/laforge/projects/git/libosmo-netif/src/stream.c:276
    #23 0x7f29c6140df0 in osmo_fd_disp_fds /home/laforge/projects/git/libosmocore/src/select.c:216
    #24 0x7f29c6140df0 in osmo_select_main /home/laforge/projects/git/libosmocore/src/select.c:256
    #25 0x556b19a9259b in main /home/laforge/projects/git/osmo-msc/src/osmo-msc/msc_main.c:694
    #26 0x7f29c4258a86 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x21a86)
    #27 0x556b19a93319 in _start (/space/home/laforge/projects/git/osmo-msc/src/osmo-msc/osmo-msc+0xf8319)

0x60d00001c7b8 is located 120 bytes inside of 136-byte region [0x60d00001c740,0x60d00001c7c8)
freed by thread T0 here:
    #0 0x7f29c6cc48c8 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xd98c8)
    #1 0x7f29c67bae82 in _talloc_free (/usr/lib/x86_64-linux-gnu/libtalloc.so.2+0x3e82)

previously allocated by thread T0 here:
    #0 0x7f29c6cc4c20 in __interceptor_malloc (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xd9c20)
    #1 0x7f29c67bd150 in _talloc_zero (/usr/lib/x86_64-linux-gnu/libtalloc.so.2+0x6150)

SUMMARY: AddressSanitizer: heap-use-after-free /home/laforge/projects/git/osmo-msc/src/libmsc/sms_queue.c:484 in sms_sms_cb
Shadow bytes around the buggy address:
  0x0c1a7fffb8a0: fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa fa
  0x0c1a7fffb8b0: fa fa fa fa fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c1a7fffb8c0: fd fd fd fd fd fd fa fa fa fa fa fa fa fa fd fd
  0x0c1a7fffb8d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c1a7fffb8e0: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
=>0x0c1a7fffb8f0: fd fd fd fd fd fd fd[fd]fd fa fa fa fa fa fa fa
  0x0c1a7fffb900: fa fa fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c1a7fffb910: fd fd fd fa fa fa fa fa fa fa fa fa fd fd fd fd
  0x0c1a7fffb920: fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa
  0x0c1a7fffb930: fa fa fa fa fa fa fd fd fd fd fd fd fd fd fd fd
  0x0c1a7fffb940: fd fd fd fd fd fd fd fa fa fa fa fa fa fa fa fa
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==23190==ABORTING

Files

Actions #1

Updated by laforge almost 6 years ago

  • Subject changed from OsmoMSCheap-use-after-free during processing of RP-ACK in MT-SMS to OsmoMSC heap-use-after-free during processing of RP-ACK in MT-SMS
Actions #2

Updated by laforge almost 6 years ago

this is likely the cause of why MSC_Tests.TC_lu_and_mt_sms is currently failing

Actions #3

Updated by laforge almost 6 years ago

  • Status changed from New to In Progress
  • Assignee changed from 4368 to laforge
  • % Done changed from 0 to 80

pretty straight forward what's wrong here:

               sms_pending_free(pending);
               db_sms_delete_sent_message_by_id(pending->sms_id);

patch proposed as https://gerrit.osmocom.org/7796

Actions #4

Updated by laforge almost 6 years ago

pespin: I'm surprised we don't catch this in osmo-gsm-tester.

It's MT SMS delivery in non-transactional mode, i.e. via the queue.

Are we not testing with asan enabled in osmo-gsm-tester?

Actions #5

Updated by laforge almost 6 years ago

  • Status changed from In Progress to Resolved
  • % Done changed from 80 to 100
Actions #6

Updated by pespin almost 6 years ago

I think we don't have it enabled, I'll create a task to enable it.

Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)