Actions
Bug #1978
closedOsmoMSC: IuCS: segfault
Start date:
03/09/2017
Due date:
% Done:
100%
Resolution:
Spec Reference:
Description
testing IuCS with the current sysmocom/iu + vlr branch, I get a SIGABRT upon msgb_alloc().
Details follow.
Updated by neels about 7 years ago
branch head revision d3d62f4d40bfe204adebb646375da41ccf04ced7
OsmoMSC log:
GNU gdb (Debian 7.7.1+dfsg-5) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/local/bin/osmo-msc...done.
Starting program: /usr/local/bin/osmo-msc
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
20170309174921430 DMNCC <0006> ../../../src/osmo-msc/msc_main.c:397 Using internal MNCC handler.
20170309174921431 DLGLOBAL <001f> ../../../src/vty/telnet_interface.c:95 telnet at 127.0.0.1 4254
20170309174921431 DSMPP <0017> ../../../src/libmsc/smpp_smsc.c:978 SMPP at 0.0.0.0 2775
20170309174921438 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:76 GSUP connecting to 127.0.0.1:2222
20170309174921446 DLSMS <0025> ../../../src/libmsc/sms_queue.c:252 Attempting to send 20 SMS
20170309174921447 DLSMS <0025> ../../../src/libmsc/sms_queue.c:236 SMS queue: no SMS to be sent
20170309174921447 DLSMS <0025> ../../../src/libmsc/sms_queue.c:263 Sending SMS done (0 attempted)
20170309174921447 DLSMS <0025> ../../../src/libmsc/sms_queue.c:319 SMSqueue added 0 messages in 0 rounds
20170309174921447 DMGCP <000b> ../../../src/libmgcp/mgcpgw_client.c:369 MGCP GW connection: 0.0.0.0:0 -> 192.168.0.132:2427
20170309174921447 DLINP <0021> ../../src/input/ipa.c:129 connection done.
20170309174921447 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:134 GSUP link to 127.0.0.1:2222 UP
20170309174921447 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:265 GSUP sending PING
20170309174921447 DLINP <0021> ../../src/input/ipa.c:136 connected read
20170309174921447 DLINP <0021> ../../src/input/ipa.c:54 message received
20170309174921447 DLINP <0021> ../../src/input/ipaccess.c:706 received ID get
20170309174921447 DLINP <0021> ../../src/input/ipaccess.c:641 tag 8: 0/0/0
20170309174921447 DLINP <0021> ../../src/input/ipaccess.c:641 tag 7: 00:00:00:00:00:00
20170309174921447 DLINP <0021> ../../src/input/ipaccess.c:641 tag 2: 00:00:00:00:00:00
20170309174921447 DLINP <0021> ../../src/input/ipaccess.c:641 tag 3: 00:00:00:00:00:00
20170309174921447 DLINP <0021> ../../src/input/ipaccess.c:641 tag 4: 00:00:00:00:00:00
20170309174921447 DLINP <0021> ../../src/input/ipaccess.c:641 tag 5: 00:00:00:00:00:00
20170309174921447 DLINP <0021> ../../src/input/ipaccess.c:641 tag 1: MSC-00-00-00-00-00-00
20170309174921447 DLINP <0021> ../../src/input/ipaccess.c:641 tag 0: MSC-00-00-00-00-00-00
20170309174921447 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309174921447 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309174921447 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309174921447 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309174921447 DLINP <0021> ../../src/input/ipa.c:136 connected read
20170309174921447 DLINP <0021> ../../src/input/ipa.c:54 message received
20170309174921486 DLINP <0021> ../../src/input/ipa.c:136 connected read
20170309174921486 DLINP <0021> ../../src/input/ipa.c:54 message received
20170309174921486 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:201 GSUP receiving PONG
20170309174923454 DLINP <0021> ../../src/stream.c:389 accept()ed new link from 127.0.0.1 to port 14001
20170309174923454 DSUA <001b> ../../src/sua.c:1437 New SCTP connection accepted
20170309174923454 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309174923454 DLINP <0021> ../../src/stream.c:509 message received
20170309174923454 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 12
20170309174923454 DSUA <001b> ../../src/sua.c:1322 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SCTP NOTIFICATION 32777 flags=0x0
20170309174923454 DSUA <001b> ../../src/sua.c:1335 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SENDER_DRY_EVENT
20170309174925306 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309174925306 DLINP <0021> ../../src/stream.c:509 message received
20170309174925306 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 148
20170309174925306 DSUA <001b> ../../src/sua.c:1322 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SCTP NOTIFICATION 32770 flags=0x0
20170309174925306 DSUA <001b> ../../src/sua.c:1335 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV PEER_ADDR_CHANGE
20170309174926042 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309174926042 DLINP <0021> ../../src/stream.c:509 message received
20170309174926042 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 148
20170309174926042 DSUA <001b> ../../src/sua.c:1322 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SCTP NOTIFICATION 32770 flags=0x0
20170309174926042 DSUA <001b> ../../src/sua.c:1335 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV PEER_ADDR_CHANGE
20170309174926322 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309174926322 DLINP <0021> ../../src/stream.c:509 message received
20170309174926322 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 148
20170309174926322 DSUA <001b> ../../src/sua.c:1322 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SCTP NOTIFICATION 32770 flags=0x0
20170309174926322 DSUA <001b> ../../src/sua.c:1335 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV PEER_ADDR_CHANGE
20170309174926962 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309174926962 DLINP <0021> ../../src/stream.c:509 message received
20170309174926962 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 148
20170309174926962 DSUA <001b> ../../src/sua.c:1322 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SCTP NOTIFICATION 32770 flags=0x0
20170309174926962 DSUA <001b> ../../src/sua.c:1335 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV PEER_ADDR_CHANGE
20170309174941452 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:244 GSUP ping callback (connected, got PONG)
20170309174941452 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:265 GSUP sending PING
20170309174941452 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309174941452 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309174941452 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309174941452 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309174941452 DLINP <0021> ../../src/input/ipa.c:136 connected read
20170309174941452 DLINP <0021> ../../src/input/ipa.c:54 message received
20170309174941452 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:201 GSUP receiving PONG
20170309175001453 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:244 GSUP ping callback (connected, got PONG)
20170309175001454 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:265 GSUP sending PING
20170309175001454 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309175001454 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309175001454 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309175001454 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309175001454 DLINP <0021> ../../src/input/ipa.c:136 connected read
20170309175001454 DLINP <0021> ../../src/input/ipa.c:54 message received
20170309175001454 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:201 GSUP receiving PONG
20170309175021459 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:244 GSUP ping callback (connected, got PONG)
20170309175021459 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:265 GSUP sending PING
20170309175021459 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309175021460 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309175021460 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309175021460 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309175021460 DLINP <0021> ../../src/input/ipa.c:136 connected read
20170309175021460 DLINP <0021> ../../src/input/ipa.c:54 message received
20170309175021460 DLGSUP <0029> ../../../src/libcommon/gsup_client.c:201 GSUP receiving PONG
20170309175033425 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175033425 DLINP <0021> ../../src/stream.c:509 message received
20170309175033425 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 128
20170309175033425 DSUA <001b> ../../src/sua.c:1232 Received SUA Message (8:1)
20170309175033425 DSUA <001b> ../../src/sua.c:745 sua_parse_addr(IEI=259) (4) 00 02 00 07
20170309175033425 DSUA <001b> ../../src/sua.c:340 (0) state chg IDLE->CONN_PEND_IN
20170309175033425 DRANAP <001a> ../../../src/libiu/iu.c:721 sccp_sap_up(N-CONNECTindication)
20170309175033425 DRANAP <001a> ../../../src/libiu/iu.c:730 N-CONNECT.ind(X->0)
20170309175033425 DSUA <001b> ../../src/sua.c:592 Received SCCP User Primitive (N-CONNECTresponse)
20170309175033425 DSUA <001b> ../../src/sua.c:340 (0) state chg CONN_PEND_IN->ACTIVE
20170309175033425 DSUA <001b> ../../src/sua.c:246 sua_link_send(01 00 08 02 00 00 00 30 00 06 00 08 00 00 00 00 01 15 00 08 00 00 00 02 01 05 00 08 00 00 03 e8 01 04 00 08 00 00 00 00 01 16 00 08 00 00 00 00 )
20170309175033425 DRSL <0004> ../../src/ranap_common_cn.c:43 Rx CO IM (Initial UE Message)
20170309175033425 DRLL <0000> ranap_decoder.c:2641 Decoding message RANAP_InitialUE_MessageIEs (ranap_decoder.c:2641)
20170309175033425 DRANAP <001a> ../../../src/libiu/iu.c:468 handle_co(dir=1, proc=19)
20170309175033425 DRANAP <001a> ../../../src/libiu/iu.c:143 New RNC 23 (LAC=10422 RAC=0)
20170309175033426 DIUCS <001e> ../../../src/osmo-msc/msc_main.c:321 got IuCS message 20 bytes: 05 08 22 09 f1 89 28 b6 57 05 f4 93 59 d2 23 33 03 57 58 86
20170309175033426 DIUCS <001e> ../../../src/osmo-msc/msc_main.c:325 got IuCS message on MNC 98 MCC 901 LAC 10422 RAC 0
20170309175033426 DIUCS <001e> ../../../src/libmsc/iucs.c:113 Looking for IuCS subscriber: link_id 0x700740, conn_id 0
20170309175033426 DIUCS <001e> ../../../src/libmsc/iucs.c:101 subscribers registered: 0
20170309175033426 DIUCS <001e> ../../../src/libmsc/iucs.c:126 No IuCS subscriber found for link_id 0x700740, conn_id 0
20170309175033426 DIUCS <001e> ../../../src/libmsc/iucs.c:44 Allocating IuCS subscriber conn: lac 10422, link_id 0x700740, conn_id 0
20170309175033426 DRLL <0000> ../../../src/libmsc/gsm_04_08.c:3618 Dispatching 04.08 message, pdisc=5
20170309175033426 DVLR <001d> ../../src/fsm.c:204 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_INIT}: Allocated
20170309175033426 DVLR <001d> ../../../src/libmsc/subscr_conn.c:353 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
20170309175033426 DVLR <001d> ../../../src/libmsc/subscr_conn.c:66 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
20170309175033426 DMM <0002> ../../../src/libmsc/gsm_04_08.c:369 LOCATION UPDATING REQUEST: MI(TMSI)=2472137251 type=IMSI ATTACH
20170309175033426 DMM <0002> ../../../src/libmsc/gsm_04_08.c:414 LU/new-LAC: 10422/10422
20170309175033426 DVLR <001d> ../../src/fsm.c:204 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_IDLE}: Allocated
20170309175033426 DVLR <001d> ../../src/fsm.c:234 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_IDLE}: is child of Subscr_Conn(2472137251)[0x7184c0]
20170309175033426 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:1409 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
20170309175033426 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:1415 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
20170309175033426 DVLR <001d> ../../../src/libvlr/vlr.c:362 New subscr, TMSI: 0x9359d223
20170309175033426 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:861 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_IDLE}: vlr_loc_upd_want_imsi()
20170309175033426 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:867 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_IMSI
20170309175033426 DMSC <000a> ../../../src/libmsc/msc_ifaces.c:44 msc_tx 3 bytes to TMSI:0x9359d223 via RAN_UTRAN_IU
20170309175033426 DRANAP <001a> ../../../src/libiu/iu.c:391 Transmitting L3 Message as RANAP DT (SUA link 0x700740 conn_id 0)
20170309175033426 DSUA <001b> ../../src/sua.c:592 Received SCCP User Primitive (N-DATArequest)
20170309175033426 DSUA <001b> ../../src/sua.c:246 sua_link_send(01 00 08 08 00 00 00 30 00 06 00 08 00 00 00 00 01 05 00 08 00 00 03 e8 01 0b 00 18 00 14 00 10 00 00 02 00 10 40 04 03 05 18 01 00 3b 40 01 00 )
20170309175033426 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175033426 DLINP <0021> ../../src/stream.c:526 sending data
20170309175033426 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175033426 DLINP <0021> ../../src/stream.c:509 message received
20170309175033426 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 12
20170309175033426 DSUA <001b> ../../src/sua.c:1322 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SCTP NOTIFICATION 32777 flags=0x0
20170309175033426 DSUA <001b> ../../src/sua.c:1335 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SENDER_DRY_EVENT
20170309175033426 DLINP <0021> ../../src/stream.c:526 sending data
20170309175033426 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175033426 DLINP <0021> ../../src/stream.c:526 sending data
20170309175033433 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175033433 DLINP <0021> ../../src/stream.c:509 message received
20170309175033433 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 12
20170309175033433 DSUA <001b> ../../src/sua.c:1322 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SCTP NOTIFICATION 32777 flags=0x0
20170309175033433 DSUA <001b> ../../src/sua.c:1335 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SENDER_DRY_EVENT
20170309175033433 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175033433 DLINP <0021> ../../src/stream.c:509 message received
20170309175033433 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 44
20170309175033433 DSUA <001b> ../../src/sua.c:1232 Received SUA Message (8:8)
20170309175033433 DRANAP <001a> ../../../src/libiu/iu.c:721 sccp_sap_up(N-DATAindication)
20170309175033433 DRANAP <001a> ../../../src/libiu/iu.c:754 N-DATA.ind(0, 00 14 40 0a 00 00 01 00 10 40 03 02 05 70 )
20170309175033433 DRSL <0004> ../../src/ranap_common_cn.c:43 Rx CO IM (Direct Transfer)
20170309175033433 DRLL <0000> ranap_decoder.c:3197 Decoding message RANAP_DirectTransferIEs (ranap_decoder.c:3197)
20170309175033433 DRANAP <001a> ../../../src/libiu/iu.c:468 handle_co(dir=1, proc=20)
20170309175033433 DIUCS <001e> ../../../src/osmo-msc/msc_main.c:321 got IuCS message 2 bytes: 05 70
20170309175033433 DIUCS <001e> ../../../src/libmsc/iucs.c:113 Looking for IuCS subscriber: link_id 0x700740, conn_id 0
20170309175033433 DIUCS <001e> ../../../src/libmsc/iucs.c:76 0: TMSI:0x9359d223 Iu link 0x700740, conn_id 0
20170309175033433 DIUCS <001e> ../../../src/libmsc/iucs.c:101 subscribers registered: 1
20170309175033433 DIUCS <001e> ../../../src/libmsc/iucs.c:122 Found IuCS subscriber for link_id 0x700740, conn_id 0
20170309175033433 DRLL <0000> ../../../src/libmsc/gsm_04_08.c:3618 Dispatching 04.08 message, pdisc=5
20170309175033433 DRLL <0000> ../../../src/libmsc/gsm_04_08.c:3625 subscr TMSI:0x9359d223: Message not permitted for initial conn: pdisc=0x05 msg_type=0x70
20170309175033653 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175033653 DLINP <0021> ../../src/stream.c:509 message received
20170309175033653 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 52
20170309175033653 DSUA <001b> ../../src/sua.c:1232 Received SUA Message (8:8)
20170309175033653 DRANAP <001a> ../../../src/libiu/iu.c:721 sccp_sap_up(N-DATAindication)
20170309175033653 DRANAP <001a> ../../../src/libiu/iu.c:754 N-DATA.ind(0, 00 14 40 13 00 00 01 00 10 40 0c 0b 05 99 08 99 10 07 00 00 10 74 20 )
20170309175033654 DRSL <0004> ../../src/ranap_common_cn.c:43 Rx CO IM (Direct Transfer)
20170309175033654 DRLL <0000> ranap_decoder.c:3197 Decoding message RANAP_DirectTransferIEs (ranap_decoder.c:3197)
20170309175033654 DRANAP <001a> ../../../src/libiu/iu.c:468 handle_co(dir=1, proc=20)
20170309175033654 DIUCS <001e> ../../../src/osmo-msc/msc_main.c:321 got IuCS message 11 bytes: 05 99 08 99 10 07 00 00 10 74 20
20170309175033654 DIUCS <001e> ../../../src/libmsc/iucs.c:113 Looking for IuCS subscriber: link_id 0x700740, conn_id 0
20170309175033654 DIUCS <001e> ../../../src/libmsc/iucs.c:76 0: TMSI:0x9359d223 Iu link 0x700740, conn_id 0
20170309175033654 DIUCS <001e> ../../../src/libmsc/iucs.c:101 subscribers registered: 1
20170309175033654 DIUCS <001e> ../../../src/libmsc/iucs.c:122 Found IuCS subscriber for link_id 0x700740, conn_id 0
20170309175033654 DRLL <0000> ../../../src/libmsc/gsm_04_08.c:3618 Dispatching 04.08 message, pdisc=5
20170309175033654 DMM <0002> ../../../src/libmsc/gsm_04_08.c:320 IDENTITY RESPONSE: MI(IMSI)=901700000014702
20170309175033654 DVLR <001d> ../../../src/libvlr/vlr.c:375 set IMSI on subscriber; IMSI=901700000014702 id=901700000014702
20170309175033654 DVLR <001d> ../../../src/libvlr/vlr.c:884 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_IMSI}: Received Event VLR_ULA_E_ID_IMSI
20170309175033654 DVLR <001d> ../../../src/libvlr/vlr.c:375 set IMSI on subscriber; IMSI=901700000014702 id=901700000014702
20170309175033654 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:838 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_IMSI}: vlr_loc_upd_node1()
20170309175033654 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:845 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_IMSI}: state_chg to VLR_ULA_S_WAIT_AUTH
20170309175033654 DVLR <001d> ../../src/fsm.c:204 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_NEEDS_AUTH}: Allocated
20170309175033654 DVLR <001d> ../../src/fsm.c:234 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(2472137251)[0x7192a0]
20170309175033654 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:601 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
20170309175033654 DVLR <001d> ../../../src/libvlr/vlr.c:145 GSUP tx: 08010809710000004107f2
20170309175033654 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:296 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
20170309175033654 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309175033654 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309175033654 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309175033654 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309175033660 DLINP <0021> ../../src/input/ipa.c:136 connected read
20170309175033660 DLINP <0021> ../../src/input/ipa.c:54 message received
20170309175033660 DVLR <001d> ../../../src/libvlr/vlr.c:767 GSUP rx 511: 0a010809710000004107f203622010c1008163884f87bf25044e5684b20f90210441ab761f220877bf2279ecf7d6fa23103dbb84021f1bf99ee50168c3eaa01f3624109c8fd06a6cc5ab82338a1ed275899bd02510368e7a3ea1f0000022b606cffddc41cb2708157d7f2554d6093a03622010b1acdb9b00207df263cdd7c43d8ede1d2104936f4e922208cc948230287fe1ad231041131cbe254dbfb1c06af5fbcb7213c32410fb2c4fc75fdd44fab6c124b2999d0925251086fad570358f0000ca15f61dd0bdd4882708c134cefe525b806c0362201007bad8c8050456f8b382a3af53dfbd11210489e309802208428016bb92c9711c23107753de78edc6262b4ea581bd3a4a936d241023e1261383982a6658976f6dc6ddee3c25102f295d54762500005cc33aa4902228892708ebd3cc116230c591036220100238ec1f80b7c0ce428e5f4cc3812ec32104514443312208b247fc86d72c7edf2310b44e8cc5300ce62beba7c8d41ef100d92410219acbb2fd201613cc34732504f18e3e2510a8b946cce0dd00006e9e98b0d08c856a2708b8b68b75e9f2c844036220109fb3f3b3e25c9f959195a6fd6db53be62104b15aa0832208cbc47c4eff6adab12310a8f30fdec61b43d5d37e1785e7ac8e1624103f0114c1c910a9da8f4870d417cdbea825106cfedbd19c420000b50b10b632995e3a27081c2fad59ad750dda
20170309175033661 DVLR <001d> ../../../src/libvlr/vlr.c:585 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
20170309175033661 DVLR <001d> ../../../src/libvlr/vlr.c:565 SUBSCR(IMSI:901700000014702) Received 5 auth tuples
20170309175033661 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:352 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
20170309175033661 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:263 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
20170309175033661 DMM <0002> ../../../src/libmsc/gsm_04_08.c:621 -> AUTH REQ (rand = c1008163884f87bf25044e5684b20f90)
20170309175033661 DMM <0002> ../../../src/libmsc/gsm_04_08.c:623 AUTH REQ (autn = 368e7a3ea1f0000022b606cffddc41cb)
20170309175033661 DMSC <000a> ../../../src/libmsc/msc_ifaces.c:44 msc_tx 37 bytes to IMSI:901700000014702 via RAN_UTRAN_IU
20170309175033661 DRANAP <001a> ../../../src/libiu/iu.c:391 Transmitting L3 Message as RANAP DT (SUA link 0x700740 conn_id 0)
20170309175033661 DSUA <001b> ../../src/sua.c:592 Received SCCP User Primitive (N-DATArequest)
20170309175033661 DSUA <001b> ../../src/sua.c:246 sua_link_send(01 00 08 08 00 00 00 54 00 06 00 08 00 00 00 00 01 05 00 08 00 00 03 e8 01 0b 00 3a 00 14 00 32 00 00 02 00 10 40 26 25 05 12 00 c1 00 81 63 88 4f 87 bf 25 04 4e 56 84 b2 0f 90 20 10 36 8e 7a 3e a1 f0 00 00 22 b6 06 cf fd dc 41 cb 00 3b 40 01 00 00 00 )
20170309175033661 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175033661 DLINP <0021> ../../src/stream.c:526 sending data
20170309175033661 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175033661 DLINP <0021> ../../src/stream.c:526 sending data
20170309175033858 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175033858 DLINP <0021> ../../src/stream.c:509 message received
20170309175033858 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 12
20170309175033858 DSUA <001b> ../../src/sua.c:1322 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SCTP NOTIFICATION 32777 flags=0x0
20170309175033858 DSUA <001b> ../../src/sua.c:1335 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SENDER_DRY_EVENT
20170309175034814 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175034814 DLINP <0021> ../../src/stream.c:509 message received
20170309175034814 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 52
20170309175034814 DSUA <001b> ../../src/sua.c:1232 Received SUA Message (8:8)
20170309175034814 DRANAP <001a> ../../../src/libiu/iu.c:721 sccp_sap_up(N-DATAindication)
20170309175034814 DRANAP <001a> ../../../src/libiu/iu.c:754 N-DATA.ind(0, 00 14 40 14 00 00 01 00 10 40 0d 0c 05 d4 15 7d 7f 25 21 04 54 d6 09 3a )
20170309175034814 DRSL <0004> ../../src/ranap_common_cn.c:43 Rx CO IM (Direct Transfer)
20170309175034814 DRLL <0000> ranap_decoder.c:3197 Decoding message RANAP_DirectTransferIEs (ranap_decoder.c:3197)
20170309175034814 DRANAP <001a> ../../../src/libiu/iu.c:468 handle_co(dir=1, proc=20)
20170309175034814 DIUCS <001e> ../../../src/osmo-msc/msc_main.c:321 got IuCS message 12 bytes: 05 d4 15 7d 7f 25 21 04 54 d6 09 3a
20170309175034814 DIUCS <001e> ../../../src/libmsc/iucs.c:113 Looking for IuCS subscriber: link_id 0x700740, conn_id 0
20170309175034814 DIUCS <001e> ../../../src/libmsc/iucs.c:76 0: IMSI:901700000014702 Iu link 0x700740, conn_id 0
20170309175034814 DIUCS <001e> ../../../src/libmsc/iucs.c:101 subscribers registered: 1
20170309175034814 DIUCS <001e> ../../../src/libmsc/iucs.c:122 Found IuCS subscriber for link_id 0x700740, conn_id 0
20170309175034814 DRLL <0000> ../../../src/libmsc/gsm_04_08.c:3618 Dispatching 04.08 message, pdisc=5
20170309175034814 DMM <0002> ../../../src/libmsc/gsm_04_08.c:923 IMSI:901700000014702: MM R99 AUTHENTICATION RESPONSE (res = 157d7f2554d6093a)
20170309175034814 DVLR <001d> ../../../src/libvlr/vlr.c:1019 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
20170309175034814 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:142 SUBSCR(IMSI:901700000014702) received res: 15 7d 7f 25 54 d6 09 3a
20170309175034814 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:179 SUBSCR(IMSI:901700000014702) AUTH established UMTS security context
20170309175034814 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:231 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
20170309175034814 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:235 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
20170309175034814 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:240 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
20170309175034814 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:240 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(2472137251)[0x7192a0]
20170309175034814 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:240 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_AUTHENTICATED}: Freeing instance
20170309175034814 DVLR <001d> ../../src/fsm.c:248 VLR_Authenticate(2472137251)[0x6fd860]{VLR_SUB_AS_AUTHENTICATED}: Deallocated
20170309175034814 DVLR <001d> ../../../src/libvlr/vlr_auth_fsm.c:240 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
20170309175034814 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:812 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
20170309175034815 DSUA <001b> ../../src/sua.c:592 Received SCCP User Primitive (N-DATArequest)
20170309175034815 DSUA <001b> ../../src/sua.c:246 sua_link_send(01 00 08 08 00 00 00 40 00 06 00 08 00 00 00 00 01 05 00 08 00 00 03 e8 01 0b 00 26 00 06 00 1e 00 00 02 00 0c 00 12 08 08 3d bb 84 02 1f 1b f9 9e e5 01 68 c3 ea a0 1f 36 00 4b 00 01 40 00 00 )
20170309175034815 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:830 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
20170309175034815 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175034815 DLINP <0021> ../../src/stream.c:526 sending data
20170309175034815 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175034815 DLINP <0021> ../../src/stream.c:526 sending data
20170309175035014 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175035014 DLINP <0021> ../../src/stream.c:509 message received
20170309175035014 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 12
20170309175035014 DSUA <001b> ../../src/sua.c:1322 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SCTP NOTIFICATION 32777 flags=0x0
20170309175035014 DSUA <001b> ../../src/sua.c:1335 (127.0.0.1:52559<->127.0.0.1:14001) SUA SRV SENDER_DRY_EVENT
20170309175035062 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175035063 DLINP <0021> ../../src/stream.c:509 message received
20170309175035063 DSUA <001b> ../../src/sua.c:1360 sua_srv_conn_cb(): sctp_recvmsg() returned 40
20170309175035063 DSUA <001b> ../../src/sua.c:1232 Received SUA Message (8:8)
20170309175035063 DRANAP <001a> ../../../src/libiu/iu.c:721 sccp_sap_up(N-DATAindication)
20170309175035063 DRANAP <001a> ../../../src/libiu/iu.c:754 N-DATA.ind(0, 20 06 00 08 00 00 01 00 06 00 01 00 )
20170309175035063 DRSL <0004> ../../src/ranap_common_cn.c:137 Rx CO SO (Security Mode Control)
20170309175035063 DRLL <0000> ranap_decoder.c:4315 Decoding message RANAP_SecurityModeCompleteIEs (ranap_decoder.c:4315)
20170309175035063 DRANAP <001a> ../../../src/libiu/iu.c:468 handle_co(dir=2, proc=6)
20170309175035063 DIUCS <001e> ../../../src/osmo-msc/msc_main.c:335 got IuCS event 1: IU_EVENT_SECURITY_MODE_COMPLETE
20170309175035063 DIUCS <001e> ../../../src/libmsc/iucs.c:113 Looking for IuCS subscriber: link_id 0x700740, conn_id 0
20170309175035063 DIUCS <001e> ../../../src/libmsc/iucs.c:76 0: IMSI:901700000014702 Iu link 0x700740, conn_id 0
20170309175035063 DIUCS <001e> ../../../src/libmsc/iucs.c:101 subscribers registered: 1
20170309175035063 DIUCS <001e> ../../../src/libmsc/iucs.c:122 Found IuCS subscriber for link_id 0x700740, conn_id 0
20170309175035063 DIUCS <001e> ../../../src/libmsc/iucs_ranap.c:97 IuCS security mode complete for IMSI:901700000014702
20170309175035063 DVLR <001d> ../../../src/libvlr/vlr.c:1028 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
20170309175035063 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:780 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
20170309175035063 DIUCS <001e> ../../../src/libmsc/msc_ifaces.c:114 IMSI:901700000014702: tx CommonID 901700000014702
20170309175035063 DRANAP <001a> ../../../src/libiu/iu.c:258 Transmitting RANAP CommonID (SUA link 0x700740 conn_id 0)
20170309175035063 DSUA <001b> ../../src/sua.c:592 Received SCCP User Primitive (N-DATArequest)
20170309175035063 DSUA <001b> ../../src/sua.c:246 sua_link_send(01 00 08 08 00 00 00 30 00 06 00 08 00 00 00 00 01 05 00 08 00 00 03 e8 01 0b 00 18 00 0f 40 10 00 00 01 00 17 40 09 50 09 71 00 00 00 41 07 f2 )
20170309175035063 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:743 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
20170309175035063 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:752 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
20170309175035063 DVLR <001d> ../../src/fsm.c:204 upd_hlr_vlr_fsm(2472137251)[0x700850]{UPD_HLR_VLR_S_INIT}: Allocated
20170309175035063 DVLR <001d> ../../src/fsm.c:234 upd_hlr_vlr_fsm(2472137251)[0x700850]{UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(2472137251)[0x7192a0]
20170309175035063 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:164 upd_hlr_vlr_fsm(2472137251)[0x700850]{UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
20170309175035063 DVLR <001d> ../../../src/libvlr/vlr.c:145 GSUP tx: 04010809710000004107f2
20170309175035063 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:81 upd_hlr_vlr_fsm(2472137251)[0x700850]{UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
20170309175035063 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309175035063 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309175035063 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175035063 DLINP <0021> ../../src/stream.c:526 sending data
20170309175035063 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309175035063 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309175035063 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175035063 DLINP <0021> ../../src/stream.c:526 sending data
20170309175035064 DLINP <0021> ../../src/input/ipa.c:136 connected read
20170309175035064 DLINP <0021> ../../src/input/ipa.c:54 message received
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr.c:767 GSUP rx 16: 10010809710000004107f208030207f2
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr.c:623 IMSI:901700000014702 has MSISDN:702
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr.c:145 GSUP tx: 12010809710000004107f2
20170309175035064 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309175035064 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309175035064 DLINP <0021> ../../src/input/ipa.c:140 connected write
20170309175035064 DLINP <0021> ../../src/input/ipa.c:90 sending data
20170309175035064 DLINP <0021> ../../src/input/ipa.c:136 connected read
20170309175035064 DLINP <0021> ../../src/input/ipa.c:54 message received
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr.c:767 GSUP rx 11: 06010809710000004107f2
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr.c:713 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:1145 upd_hlr_vlr_fsm(2472137251)[0x700850]{UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:103 upd_hlr_vlr_fsm(2472137251)[0x700850]{UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:104 upd_hlr_vlr_fsm(2472137251)[0x700850]{UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:104 upd_hlr_vlr_fsm(2472137251)[0x700850]{UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(2472137251)[0x7192a0]
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:104 upd_hlr_vlr_fsm(2472137251)[0x700850]{UPD_HLR_VLR_S_DONE}: Freeing instance
20170309175035064 DVLR <001d> ../../src/fsm.c:248 upd_hlr_vlr_fsm(2472137251)[0x700850]{UPD_HLR_VLR_S_DONE}: Deallocated
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:104 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:1153 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
20170309175035064 DVLR <001d> ../../src/fsm.c:204 lu_compl_vlr_fsm(2472137251)[0x71c4b0]{LU_COMPL_VLR_S_INIT}: Allocated
20170309175035064 DVLR <001d> ../../src/fsm.c:234 lu_compl_vlr_fsm(2472137251)[0x71c4b0]{LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(2472137251)[0x7192a0]
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:725 lu_compl_vlr_fsm(2472137251)[0x71c4b0]{LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:385 lu_compl_vlr_fsm(2472137251)[0x71c4b0]{LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
20170309175035064 DVLR <001d> ../../src/fsm.c:204 sub_pres_vlr_fsm(2472137251)[0x719150]{SUB_PRES_VLR_S_INIT}: Allocated
20170309175035064 DVLR <001d> ../../src/fsm.c:234 sub_pres_vlr_fsm(2472137251)[0x719150]{SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(2472137251)[0x71c4b0]
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:267 sub_pres_vlr_fsm(2472137251)[0x719150]{SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:200 sub_pres_vlr_fsm(2472137251)[0x719150]{SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:201 sub_pres_vlr_fsm(2472137251)[0x719150]{SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:201 sub_pres_vlr_fsm(2472137251)[0x719150]{SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(2472137251)[0x71c4b0]
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:201 sub_pres_vlr_fsm(2472137251)[0x719150]{SUB_PRES_VLR_S_DONE}: Freeing instance
20170309175035064 DVLR <001d> ../../src/fsm.c:248 sub_pres_vlr_fsm(2472137251)[0x719150]{SUB_PRES_VLR_S_DONE}: Deallocated
20170309175035064 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:201 lu_compl_vlr_fsm(2472137251)[0x71c4b0]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
20170309175035065 DMM <0002> ../../../src/libmsc/gsm_04_08.c:270 -> MSISDN:702 LOCATION UPDATE ACCEPT
20170309175035065 DMSC <000a> ../../../src/libmsc/msc_ifaces.c:44 msc_tx 17 bytes to MSISDN:702 via RAN_UTRAN_IU
20170309175035065 DRANAP <001a> ../../../src/libiu/iu.c:391 Transmitting L3 Message as RANAP DT (SUA link 0x700740 conn_id 0)
20170309175035065 DSUA <001b> ../../src/sua.c:592 Received SCCP User Primitive (N-DATArequest)
20170309175035065 DSUA <001b> ../../src/sua.c:246 sua_link_send(01 00 08 08 00 00 00 40 00 06 00 08 00 00 00 00 01 05 00 08 00 00 03 e8 01 0b 00 26 00 14 00 1e 00 00 02 00 10 40 12 11 05 02 09 f1 89 28 b6 17 08 99 10 07 00 00 10 74 20 00 3b 40 01 00 00 00 )
20170309175035065 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:321 lu_compl_vlr_fsm(2472137251)[0x71c4b0]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
20170309175035065 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:355 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
20170309175035065 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:733 lu_compl_vlr_fsm(2472137251)[0x71c4b0]{LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
20170309175035065 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:733 lu_compl_vlr_fsm(2472137251)[0x71c4b0]{LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(2472137251)[0x7192a0]
20170309175035065 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:733 lu_compl_vlr_fsm(2472137251)[0x71c4b0]{LU_COMPL_VLR_S_DONE}: Freeing instance
20170309175035065 DVLR <001d> ../../src/fsm.c:248 lu_compl_vlr_fsm(2472137251)[0x71c4b0]{LU_COMPL_VLR_S_DONE}: Deallocated
20170309175035065 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:700 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
20170309175035065 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:692 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
20170309175035065 DVLR <001d> ../../../src/libmsc/subscr_conn.c:77 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
20170309175035065 DVLR <001d> ../../../src/libmsc/subscr_conn.c:83 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
20170309175035067 DVLR <001d> ../../../src/libmsc/subscr_conn.c:125 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
20170309175035067 DVLR <001d> ../../../src/libmsc/subscr_conn.c:171 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
20170309175035067 DVLR <001d> ../../../src/libmsc/subscr_conn.c:265 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
20170309175035067 DVLR <001d> ../../../src/libmsc/subscr_conn.c:265 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
20170309175035067 DVLR <001d> ../../../src/libmsc/subscr_conn.c:265 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(2472137251)[0x7184c0]
20170309175035067 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:1342 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
20170309175035067 DVLR <001d> ../../../src/libmsc/subscr_conn.c:265 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_DONE}: Freeing instance
20170309175035067 DVLR <001d> ../../src/fsm.c:248 vlr_lu_fsm(2472137251)[0x7192a0]{VLR_ULA_S_DONE}: Deallocated
20170309175035067 DSUA <001b> ../../src/sua.c:592 Received SCCP User Primitive (N-DATArequest)
20170309175035067 DSUA <001b> ../../src/sua.c:246 sua_link_send(01 00 08 08 00 00 00 2c 00 06 00 08 00 00 00 00 01 05 00 08 00 00 03 e8 01 0b 00 11 00 01 00 09 00 00 01 00 04 40 02 07 80 00 00 00 )
20170309175035067 DRLL <0000> ../../../src/libmsc/osmo_msc.c:190 subscr MSISDN:702: Freeing subscriber connection
20170309175035067 DVLR <001d> ../../../src/libmsc/subscr_conn.c:265 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_RELEASED}: Freeing instance
20170309175035067 DVLR <001d> ../../src/fsm.c:248 Subscr_Conn(2472137251)[0x7184c0]{SUBSCR_CONN_S_RELEASED}: Deallocated
20170309175035067 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175035067 DLINP <0021> ../../src/stream.c:526 sending data
20170309175035068 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175035068 DLINP <0021> ../../src/stream.c:526 sending data
20170309175035068 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175035068 DLINP <0021> ../../src/stream.c:526 sending data
20170309175035272 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309175035272 DLINP <0021> ../../src/stream.c:509 message received
*** Error in `/usr/local/bin/osmo-msc': corrupted double-linked list: 0x0000000000700aa0 ***
Program received signal SIGABRT, Aborted.
0x00007ffff5a95067 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0 0x00007ffff5a95067 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1 0x00007ffff5a96448 in __GI_abort () at abort.c:89
#2 0x00007ffff5ad31b4 in __libc_message (do_abort=do_abort@entry=1, fmt=fmt@entry=0x7ffff5bc8530 "*** Error in `%s': %s: 0x%s ***\n") at ../sysdeps/posix/libc_fatal.c:175
#3 0x00007ffff5ad898e in malloc_printerr (action=1, str=0x7ffff5bc460c "corrupted double-linked list", ptr=<optimized out>) at malloc.c:4996
#4 0x00007ffff5ad8c4c in malloc_consolidate (av=av@entry=0x7ffff5e05620 <main_arena>) at malloc.c:4165
#5 0x00007ffff5ad9e98 in _int_malloc (av=0x7ffff5e05620 <main_arena>, bytes=1732) at malloc.c:3423
#6 0x00007ffff5adc020 in __GI___libc_malloc (bytes=1732) at malloc.c:2891
#7 0x00007ffff7bcf631 in _talloc_zero () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#8 0x00007ffff777130f in msgb_alloc (size=<optimized out>, name=<optimized out>) at ../../src/msgb.c:53
#9 0x00007ffff5e0f1a1 in sua_srv_conn_cb (conn=0x6fdd60) at ../../src/sua.c:1347
#10 0x00007ffff502d8a1 in osmo_stream_srv_read (conn=0x6fdd60) at ../../src/stream.c:512
#11 osmo_stream_srv_cb (ofd=<optimized out>, what=1) at ../../src/stream.c:563
#12 0x00007ffff7771042 in osmo_fd_disp_fds (_eset=0x7fffffffe590, _wset=0x7fffffffe510, _rset=0x7fffffffe490) at ../../src/select.c:167
#13 osmo_select_main (polling=<optimized out>) at ../../src/select.c:207
#14 0x0000000000406254 in main (argc=1, argv=0x669560) at ../../../src/osmo-msc/msc_main.c:518
(gdb)
osmo-msc.cfg
! ! OpenMSC configuration saved from vty ! password foo ! line vty no login ! network network country code 901 mobile network code 98 short name OsmoMSC long name OsmoMSC auth policy closed location updating reject cause 13 encryption a5 0 rrlp mode none mm info 1 msc mgcpgw remote-ip 192.168.0.132 log stderr logging print extended-timestamp 1 logging level all debug logging filter all 1 logging print category 1 log file current_log/msc.log logging filter all 1 logging color 1 logging print category 1 logging timestamp 1 logging print extended-timestamp 1 logging level all debug
Updated by neels about 7 years ago
seems to not be reproducible...
IIRC it happened while I was entering and leaving flight mode on and off with two phones,
but according to the log I had just started OsmoMSC anew.
Updated by neels about 7 years ago
hmm, maybe it was a temporary stack corruption from incomplete rebuild.
I'll leave this open for now, but if the problem doesn't re-appear we can just reject this issue.
Updated by neels about 7 years ago
got a similar segfault again.
20170309232357424 DMM <0002> ../../../src/libmsc/gsm_04_08.c:269 -> MSISDN:701 LOCATION UPDATE ACCEPT
20170309232357424 DMSC <000a> ../../../src/libmsc/msc_ifaces.c:44 msc_tx 17 bytes to MSISDN:701 via RAN_UTRAN_IU
20170309232357424 DRANAP <001a> ../../../src/libiu/iu.c:391 Transmitting L3 Message as RANAP DT (SUA link 0x701740 conn_id 7)
20170309232357424 DSUA <001b> ../../src/sua.c:592 Received SCCP User Primitive (N-DATArequest)
20170309232357424 DSUA <001b> ../../src/sua.c:246 sua_link_send(01 00 08 08 00 00 00 40 00 06 00 08 00 00 00 00 01 05 00 08 00 00 03 e8 01 0b 00 26 00 14 00 1e 00 00 02 00 10 40 12 11 05 02 09 f1 89 28 b6 17 08 99 10 07 00 00 10 74 10 00 3b 40 01 00 00 00 )
20170309232357424 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:321 lu_compl_vlr_fsm(901700000014701)[0x6fe910]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
20170309232357424 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:355 vlr_lu_fsm(901700000014701)[0x71c310]{VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
20170309232357424 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:733 lu_compl_vlr_fsm(901700000014701)[0x6fe910]{LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
20170309232357424 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:733 lu_compl_vlr_fsm(901700000014701)[0x6fe910]{LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000014701)[0x71c310]
20170309232357424 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:733 lu_compl_vlr_fsm(901700000014701)[0x6fe910]{LU_COMPL_VLR_S_DONE}: Freeing instance
20170309232357424 DVLR <001d> ../../src/fsm.c:248 lu_compl_vlr_fsm(901700000014701)[0x6fe910]{LU_COMPL_VLR_S_DONE}: Deallocated
20170309232357424 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:700 vlr_lu_fsm(901700000014701)[0x71c310]{VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
20170309232357424 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:692 Subscr_Conn(901700000014701)[0x6fe7e0]{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
20170309232357424 DVLR <001d> ../../../src/libmsc/subscr_conn.c:77 Subscr_Conn(901700000014701)[0x6fe7e0]{SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
20170309232357424 DVLR <001d> ../../../src/libmsc/subscr_conn.c:83 Subscr_Conn(901700000014701)[0x6fe7e0]{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
20170309232357427 DVLR <001d> ../../../src/libmsc/subscr_conn.c:125 Subscr_Conn(901700000014701)[0x6fe7e0]{SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
20170309232357427 DVLR <001d> ../../../src/libmsc/subscr_conn.c:188 Subscr_Conn(901700000014701)[0x6fe7e0]{SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
20170309232357427 DVLR <001d> ../../../src/libmsc/subscr_conn.c:189 Subscr_Conn(901700000014701)[0x6fe7e0]{SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
20170309232357427 DVLR <001d> ../../../src/libmsc/subscr_conn.c:282 Subscr_Conn(901700000014701)[0x6fe7e0]{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
20170309232357427 DVLR <001d> ../../../src/libmsc/subscr_conn.c:282 vlr_lu_fsm(901700000014701)[0x71c310]{VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
20170309232357427 DVLR <001d> ../../../src/libmsc/subscr_conn.c:282 vlr_lu_fsm(901700000014701)[0x71c310]{VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000014701)[0x6fe7e0]
20170309232357427 DVLR <001d> ../../../src/libvlr/vlr_lu_fsm.c:1342 vlr_lu_fsm(901700000014701)[0x71c310]{VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
20170309232357427 DVLR <001d> ../../../src/libmsc/subscr_conn.c:282 vlr_lu_fsm(901700000014701)[0x71c310]{VLR_ULA_S_DONE}: Freeing instance
20170309232357427 DVLR <001d> ../../src/fsm.c:248 vlr_lu_fsm(901700000014701)[0x71c310]{VLR_ULA_S_DONE}: Deallocated
20170309232357427 DSUA <001b> ../../src/sua.c:592 Received SCCP User Primitive (N-DATArequest)
20170309232357427 DSUA <001b> ../../src/sua.c:246 sua_link_send(01 00 08 08 00 00 00 2c 00 06 00 08 00 00 00 00 01 05 00 08 00 00 03 e8 01 0b 00 11 00 01 00 09 00 00 01 00 04 40 02 07 80 00 00 00 )
20170309232357427 DRLL <0000> ../../../src/libmsc/osmo_msc.c:201 subscr MSISDN:701: Freeing subscriber connection
20170309232357427 DVLR <001d> ../../../src/libmsc/subscr_conn.c:282 Subscr_Conn(901700000014701)[0x6fe7e0]{SUBSCR_CONN_S_RELEASED}: Freeing instance
20170309232357427 DVLR <001d> ../../src/fsm.c:248 Subscr_Conn(901700000014701)[0x6fe7e0]{SUBSCR_CONN_S_RELEASED}: Deallocated
20170309232357427 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309232357427 DLINP <0021> ../../src/stream.c:526 sending data
20170309232357427 DLINP <0021> ../../src/stream.c:561 connected read/write
20170309232357427 DLINP <0021> ../../src/stream.c:526 sending data
*** Error in `/usr/local/bin/osmo-msc': corrupted double-linked list: 0x0000000000701aa0 ***
Program received signal SIGABRT, Aborted.
0x00007ffff5a95067 in __GI_raise (sig=sig@entry=6)
at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0 0x00007ffff5a95067 in __GI_raise (sig=sig@entry=6)
at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1 0x00007ffff5a96448 in __GI_abort () at abort.c:89
#2 0x00007ffff5ad31b4 in __libc_message (do_abort=do_abort@entry=1,
fmt=fmt@entry=0x7ffff5bc8530 "*** Error in `%s': %s: 0x%s ***\n")
at ../sysdeps/posix/libc_fatal.c:175
#3 0x00007ffff5ad898e in malloc_printerr (action=1,
str=0x7ffff5bc460c "corrupted double-linked list", ptr=<optimized out>)
at malloc.c:4996
#4 0x00007ffff5ad8c4c in malloc_consolidate (
av=av@entry=0x7ffff5e05620 <main_arena>) at malloc.c:4165
#5 0x00007ffff5ad9641 in _int_free (av=0x7ffff5e05620 <main_arena>,
p=<optimized out>, have_lock=0) at malloc.c:4057
#6 0x00007ffff7bcb523 in _talloc_free ()
from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#7 0x00007ffff777134c in msgb_free (m=<optimized out>) at ../../src/msgb.c:74
#8 0x00007ffff502d86a in osmo_stream_srv_write (conn=0x6fed60)
at ../../src/stream.c:554
#9 osmo_stream_srv_cb (ofd=<optimized out>, what=<optimized out>)
at ../../src/stream.c:565
#10 0x00007ffff7771042 in osmo_fd_disp_fds (_eset=0x7fffffffe590,
_wset=0x7fffffffe510, _rset=0x7fffffffe490) at ../../src/select.c:167
#11 osmo_select_main (polling=<optimized out>) at ../../src/select.c:207
#12 0x0000000000406294 in main (argc=1, argv=0x66a560)
at ../../../src/osmo-msc/msc_main.c:518
Carefully cleaning out all builds and /usr/local/ and rebuilding from scratch...
If I see it again this soon I have introduced a bug on my 3G + VLR branch.
Updated by neels about 7 years ago
Found and fixed a subscr conn allocation / deallocation issue.
I hope that was it.
Updated by neels about 7 years ago
- Status changed from New to Resolved
- % Done changed from 0 to 100
Actions
