Actions
Bug #3152
closedOsmoMSC heap-use-after-free during processing of RP-ACK in MT-SMS
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