Project

General

Profile

Actions
Copy link

Bug #6484

closed

use-after-free segfault at end of ttcn3 tests, in map_sccp_wait_cc_action()

Added by neels 24 days ago. Updated 20 days ago.

Status:
Resolved
Priority:
Normal
Assignee:
-
Target version:
-
Start date:
06/06/2024
Due date:
% Done:

100%

Spec Reference:

Description

I am running ttcn3 tests to verify that https://gerrit.osmocom.org/c/osmo-hnbgw/+/36894 (hnb_persistent disconnected timeout) has no adverse effects.
Long after the new ttcn3 test has run and succeeded, and after a lot of other tests ran and succeeded, I get below segfault.
I doubt that it is caused by above patch, so far just recording the segfault in case it isn't reproducible:

20240606070047642 DCN DEBUG N-PCSTATE ind: affected_pc=185 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:557)
20240606070047642 DCN NOTICE (sgsn-0) now unreachable: N-PCSTATE ind: pc=185 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:620)
20240606070047642 DRANAP NOTICE cnlink(sgsn-0)[0x512000005020]{DISCONNECTED}: link lost (cnlink.c:118)
20240606070047642 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070047642 DCN DEBUG N-PCSTATE ind: affected_pc=10 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:557)
20240606070047642 DCN NOTICE (sgsn-1) now unreachable: N-PCSTATE ind: pc=10 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:620)
20240606070047642 DRANAP NOTICE cnlink(sgsn-1)[0x512000005320]{DISCONNECTED}: link lost (cnlink.c:118)
20240606070047642 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070047642 DCN DEBUG N-PCSTATE ind: affected_pc=2 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:557)
20240606070047642 DCN NOTICE (msc-1) now unreachable: N-PCSTATE ind: pc=2 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:620)
20240606070047642 DRANAP NOTICE cnlink(msc-1)[0x512000004720]{DISCONNECTED}: link lost (cnlink.c:118)
20240606070047642 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-37)[0x51200001af20]{connected}: Received Event MAP_SCCP_EV_RAN_LINK_LOST (context_map.c:189)
20240606070047642 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-37)[0x51200001af20]{connected}: State change to disconnected (X31, 5s) (context_map_sccp.c:382)
20240606070047643 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-12599569)[0x51200001ada0]{connected}: Received Event MAP_RUA_EV_CN_DISC (context_map_sccp.c:465)
20240606070047643 DHNB INFO map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-12599569)[0x51200001ada0]{connected}: Tx RUA Disconnect (context_map_rua.c:262)
20240606070047643 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-12599569)[0x51200001ada0]{connected}: State change to disrupted (X31, 5s) (context_map_rua.c:305)
20240606070047643 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-12599569)[0x51200001ada0]{disrupted}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:202)
20240606070047643 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-12599569)[0x51200001ada0]{disrupted}: Freeing instance (context_map.c:202)
20240606070047643 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-12599569)[0x51200001ada0]{disrupted}: Deallocated (fsm.c:568)
20240606070047643 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-37)[0x51200001af20]{disconnected}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:206)
20240606070047643 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-37)[0x51200001af20]{disconnected}: Freeing instance (context_map.c:206)
20240606070047643 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-37)[0x51200001af20]{disconnected}: Deallocated (fsm.c:568)
20240606070047643 DMAIN INFO (127.0.1.1:9999 TTCN3-HNB-0) RUA-12599569 SCCP-37 msc-1 MI=TMSI-0x42400023: Deallocating (context_map.c:225)
20240606070047643 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-38)[0x51200001b3a0]{connected}: Received Event MAP_SCCP_EV_RAN_LINK_LOST (context_map.c:189)
20240606070047643 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-38)[0x51200001b3a0]{connected}: State change to disconnected (X31, 5s) (context_map_sccp.c:382)
20240606070047643 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-4010700)[0x51200001b220]{connected}: Received Event MAP_RUA_EV_CN_DISC (context_map_sccp.c:465)
20240606070047643 DHNB INFO map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-4010700)[0x51200001b220]{connected}: Tx RUA Disconnect (context_map_rua.c:262)
20240606070047643 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-4010700)[0x51200001b220]{connected}: State change to disrupted (X31, 5s) (context_map_rua.c:305)
20240606070047643 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-4010700)[0x51200001b220]{disrupted}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:202)
20240606070047643 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-4010700)[0x51200001b220]{disrupted}: Freeing instance (context_map.c:202)
20240606070047643 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-4010700)[0x51200001b220]{disrupted}: Deallocated (fsm.c:568)
20240606070047643 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-38)[0x51200001b3a0]{disconnected}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:206)
20240606070047643 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-38)[0x51200001b3a0]{disconnected}: Freeing instance (context_map.c:206)
20240606070047643 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-38)[0x51200001b3a0]{disconnected}: Deallocated (fsm.c:568)
20240606070047644 DMAIN INFO (127.0.1.1:9999 TTCN3-HNB-0) RUA-4010700 SCCP-38 msc-1 MI=TMSI-0x42410023: Deallocating (context_map.c:225)
20240606070047644 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-39)[0x51200001b820]{connected}: Received Event MAP_SCCP_EV_RAN_LINK_LOST (context_map.c:189)
20240606070047644 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-39)[0x51200001b820]{connected}: State change to disconnected (X31, 5s) (context_map_sccp.c:382)
20240606070047644 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-9583615)[0x51200001b6a0]{connected}: Received Event MAP_RUA_EV_CN_DISC (context_map_sccp.c:465)
20240606070047644 DHNB INFO map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-9583615)[0x51200001b6a0]{connected}: Tx RUA Disconnect (context_map_rua.c:262)
20240606070047644 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-9583615)[0x51200001b6a0]{connected}: State change to disrupted (X31, 5s) (context_map_rua.c:305)
20240606070047644 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-9583615)[0x51200001b6a0]{disrupted}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:202)
20240606070047644 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-9583615)[0x51200001b6a0]{disrupted}: Freeing instance (context_map.c:202)
20240606070047644 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-9583615)[0x51200001b6a0]{disrupted}: Deallocated (fsm.c:568)
20240606070047644 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-39)[0x51200001b820]{disconnected}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:206)
20240606070047644 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-39)[0x51200001b820]{disconnected}: Freeing instance (context_map.c:206)
20240606070047644 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-39)[0x51200001b820]{disconnected}: Deallocated (fsm.c:568)
20240606070047644 DMAIN INFO (127.0.1.1:9999 TTCN3-HNB-0) RUA-9583615 SCCP-39 msc-1 MI=TMSI-0x427FC023: Deallocating (context_map.c:225)
20240606070047644 DMAIN NOTICE (127.0.1.1:9999 TTCN3-HNB-0) sctp_recvmsg(r=127.0.1.1:9999<->l=127.0.0.1:29169) = SCTP_SHUTDOWN_EVENT, closing conn (hnbgw.c:793)
20240606070047644 DMAIN INFO (disconnected TTCN3-HNB-0) Releasing HNB context (hnbgw.c:351)
20240606070047654 DLGLOBAL INFO Closing telnet connection r=127.0.0.1:40206<->l=127.0.0.1:4261 (telnet_interface.c:138)
20240606070047987 DLGLOBAL INFO Accept()ed new telnet connection r=127.0.0.1:40232<->l=127.0.0.1:4261 (telnet_interface.c:192)
20240606070048210 DMAIN INFO New HNB SCTP connection r=127.0.1.1:9999<->l=127.0.0.1:29169 (hnbgw.c:873)
20240606070048617 DLGLOBAL INFO Accept()ed new telnet connection r=127.0.0.1:53964<->l=127.0.0.1:4261 (telnet_interface.c:192)
20240606070048694 DMAIN INFO New HNB SCTP connection r=127.0.1.2:36753<->l=127.0.0.1:29169 (hnbgw.c:873)
20240606070048848 DLCTRL INFO accept()ed new CTRL connection from (r=127.0.0.1:37943<->l=127.0.0.1:4262) (control_if.c:570)
20240606070048938 DCN NOTICE (msc-0) VTY requests BSSMAP RESET (hnbgw_vty.c:789)
20240606070048940 DCN NOTICE (msc-1) VTY requests BSSMAP RESET (hnbgw_vty.c:789)
20240606070048948 DCN NOTICE (msc-2) VTY requests BSSMAP RESET (hnbgw_vty.c:789)
20240606070048951 DCN NOTICE (msc-3) VTY requests BSSMAP RESET (hnbgw_vty.c:789)
20240606070049870 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070049870 DCN DEBUG N-PCSTATE ind: affected_pc=188 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:557)
20240606070049870 DCN NOTICE (msc-0) now available: N-PCSTATE ind: pc=188 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:628)
20240606070050321 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070050321 DCN DEBUG N-PCSTATE ind: affected_pc=2 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:557)
20240606070050321 DCN NOTICE (msc-1) now available: N-PCSTATE ind: pc=2 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:628)
20240606070050385 DCN NOTICE (sgsn-0) VTY requests BSSMAP RESET (hnbgw_vty.c:789)
20240606070050404 DCN NOTICE (sgsn-1) VTY requests BSSMAP RESET (hnbgw_vty.c:789)
20240606070050409 DCN NOTICE (sgsn-2) VTY requests BSSMAP RESET (hnbgw_vty.c:789)
20240606070050430 DCN NOTICE (sgsn-3) VTY requests BSSMAP RESET (hnbgw_vty.c:789)
20240606070050511 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070050511 DCN DEBUG N-PCSTATE ind: affected_pc=3 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:557)
20240606070050511 DCN NOTICE (msc-2) now available: N-PCSTATE ind: pc=3 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:628)
20240606070050928 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070050928 DRANAP NOTICE (msc-0) Tx RANAP RESET ACK IuCS RI=SSN_PC,PC=0.23.5,SSN=RANAP --> RI=SSN_PC,PC=0.23.4,SSN=RANAP (cnlink.c:197)
20240606070050928 DRANAP NOTICE cnlink(msc-0)[0x512000004420]{CONNECTED}: link up (cnlink.c:111)
20240606070050946 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070050946 DRANAP INFO cnlink(msc-0)[0x512000004420]{CONNECTED}: Link is already up, ignoring RESET ACK (cnlink.c:282)
20240606070051234 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070051235 DRANAP NOTICE (msc-1) Tx RANAP RESET ACK IuCS RI=SSN_PC,PC=0.23.5,SSN=RANAP --> RI=SSN_PC,PC=0.0.2,SSN=RANAP (cnlink.c:197)
20240606070051235 DRANAP NOTICE cnlink(msc-1)[0x512000004720]{CONNECTED}: link up (cnlink.c:111)
20240606070051260 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070051260 DCN DEBUG N-PCSTATE ind: affected_pc=185 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:557)
20240606070051260 DCN NOTICE (sgsn-0) now available: N-PCSTATE ind: pc=185 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:628)
20240606070051359 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070051362 DRANAP INFO cnlink(msc-1)[0x512000004720]{CONNECTED}: Link is already up, ignoring RESET ACK (cnlink.c:282)
20240606070051630 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070051630 DRANAP NOTICE (msc-2) Tx RANAP RESET ACK IuCS RI=SSN_PC,PC=0.23.5,SSN=RANAP --> RI=SSN_PC,PC=0.0.3,SSN=RANAP (cnlink.c:197)
20240606070051630 DRANAP NOTICE cnlink(msc-2)[0x512000004a20]{CONNECTED}: link up (cnlink.c:111)
20240606070051701 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070051701 DRANAP INFO cnlink(msc-2)[0x512000004a20]{CONNECTED}: Link is already up, ignoring RESET ACK (cnlink.c:282)
20240606070051898 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070051901 DCN DEBUG N-PCSTATE ind: affected_pc=10 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:557)
20240606070051901 DCN NOTICE (sgsn-1) now available: N-PCSTATE ind: pc=10 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:628)
20240606070051929 DMAIN DEBUG Decoding message HNBAP_HNBRegisterRequestIEs (hnbap_decoder.c:22) (hnbap_decoder.c:22)
20240606070051929 DHNBAP DEBUG (127.0.1.1:9999 TTCN3-HNB-0) HNB-REGISTER-REQ TTCN3-HNB-0 001-01-L2342-R0-S55-C1 (hnbgw_hnbap.c:561)
20240606070051930 DHNBAP NOTICE (127.0.1.1:9999 TTCN3-HNB-0) HNB (re)connecting, discarding all previous UE state (hnbgw_hnbap.c:567)
20240606070051930 DHNBAP NOTICE (127.0.1.1:9999 TTCN3-HNB-0) Accepting HNB-REGISTER-REQ (hnbgw_hnbap.c:168)
20240606070051999 DMAIN DEBUG Decoding message HNBAP_HNBRegisterRequestIEs (hnbap_decoder.c:22) (hnbap_decoder.c:22)
20240606070051999 DHNBAP DEBUG (127.0.1.2:36753 TTCN3-HNB-1) HNB-REGISTER-REQ TTCN3-HNB-1 001-01-L2343-R0-S55-C2 (hnbgw_hnbap.c:561)
20240606070052005 DHNBAP NOTICE (127.0.1.2:36753 TTCN3-HNB-1) HNB (re)connecting, discarding all previous UE state (hnbgw_hnbap.c:567)
20240606070052005 DHNBAP NOTICE (127.0.1.2:36753 TTCN3-HNB-1) Accepting HNB-REGISTER-REQ (hnbgw_hnbap.c:168)
20240606070052023 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070052023 DCN DEBUG N-PCSTATE ind: affected_pc=11 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:557)
20240606070052023 DCN NOTICE (sgsn-2) now available: N-PCSTATE ind: pc=11 sp_status=ACCESSIBLE remote_sccp_status=AVAILABLE (hnbgw_cn.c:628)
20240606070052204 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070052205 DRANAP NOTICE (sgsn-0) Tx RANAP RESET ACK IuPS RI=SSN_PC,PC=0.23.5,SSN=RANAP --> RI=SSN_PC,PC=0.23.1,SSN=RANAP (cnlink.c:197)
20240606070052205 DRANAP NOTICE cnlink(sgsn-0)[0x512000005020]{CONNECTED}: link up (cnlink.c:111)
20240606070052334 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070052334 DRANAP INFO cnlink(sgsn-0)[0x512000005020]{CONNECTED}: Link is already up, ignoring RESET ACK (cnlink.c:282)
20240606070052550 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070052550 DRANAP NOTICE (sgsn-1) Tx RANAP RESET ACK IuPS RI=SSN_PC,PC=0.23.5,SSN=RANAP --> RI=SSN_PC,PC=0.1.2,SSN=RANAP (cnlink.c:197)
20240606070052550 DRANAP NOTICE cnlink(sgsn-1)[0x512000005320]{CONNECTED}: link up (cnlink.c:111)
20240606070052560 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070052561 DRANAP INFO cnlink(sgsn-1)[0x512000005320]{CONNECTED}: Link is already up, ignoring RESET ACK (cnlink.c:282)
20240606070052919 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070052919 DRANAP NOTICE (sgsn-2) Tx RANAP RESET ACK IuPS RI=SSN_PC,PC=0.23.5,SSN=RANAP --> RI=SSN_PC,PC=0.1.3,SSN=RANAP (cnlink.c:197)
20240606070052919 DRANAP NOTICE cnlink(sgsn-2)[0x512000005620]{CONNECTED}: link up (cnlink.c:111)
20240606070052942 DCN DEBUG sccp_sap_up(N-UNITDATA.indication) (hnbgw_cn.c:647)
20240606070052942 DRANAP INFO cnlink(sgsn-2)[0x512000005620]{CONNECTED}: Link is already up, ignoring RESET ACK (cnlink.c:282)
20240606070054064 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:new (control_cmd.c:428)
20240606070054082 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:known (control_cmd.c:428)
20240606070054088 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:reattach (control_cmd.c:428)
20240606070054095 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070054100 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:paged (control_cmd.c:428)
20240606070054106 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:new (control_cmd.c:428)
20240606070054111 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:known (control_cmd.c:428)
20240606070054115 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:reattach (control_cmd.c:428)
20240606070054120 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070054124 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:paged (control_cmd.c:428)
20240606070054128 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:new (control_cmd.c:428)
20240606070054131 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:known (control_cmd.c:428)
20240606070054136 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:reattach (control_cmd.c:428)
20240606070054140 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070054143 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:paged (control_cmd.c:428)
20240606070054147 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:new (control_cmd.c:428)
20240606070054151 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:known (control_cmd.c:428)
20240606070054156 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:reattach (control_cmd.c:428)
20240606070054159 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070054161 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:paged (control_cmd.c:428)
20240606070054202 DLGLOBAL INFO Accept()ed new telnet connection r=127.0.0.1:53970<->l=127.0.0.1:4261 (telnet_interface.c:192)
20240606070055273 DMAIN DEBUG Decoding message RUA_ConnectIEs (rua_decoder.c:22) (rua_decoder.c:22)
20240606070055273 DHNB DEBUG map_rua[0x51200001bb20]{init}: Allocated (fsm.c:456)
20240606070055273 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-7994758)[0x51200001bb20]{init}: State change to init (X31, 5s) (context_map_rua.c:85)
20240606070055274 DCN INFO (127.0.1.1:9999 TTCN3-HNB-0) RUA-7994758 SCCP-0 CS MI=TMSI-0x42800023: TMSI-0x42800023 NRI(10bit)=0x200=512: NRI match selects msc 2 (hnbgw_cn.c:1067)
20240606070055274 DCN DEBUG map_sccp[0x51200001bca0]{init}: Allocated (fsm.c:456)
20240606070055274 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-40)[0x51200001bca0]{init}: State change to init (X31, 5s) (context_map_sccp.c:93)
20240606070055274 DRUA NOTICE New conn: r=127.0.1.1:9999<->l=127.0.0.1:29169 '127.0.1.1:9999 TTCN3-HNB-0' RUA-7994758 <-> SCCP-40 msc-2 msc-two cs7-0.sccp l=0.23.5<->r=0.0.3 (context_map.c:128)
20240606070055274 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-7994758)[0x51200001bb20]{init}: Received Event MAP_RUA_EV_RX_CONNECT (hnbgw_rua.c:299)
20240606070055274 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-7994758)[0x51200001bb20]{init}: rx from RUA: RANAP Initial UE Message (context_map_rua.c:166)
20240606070055274 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-40)[0x51200001bca0]{init}: Received Event MAP_SCCP_EV_TX_DATA_REQUEST (context_map_rua.c:194)
20240606070055274 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-40)[0x51200001bca0]{init}: State change to wait_cc (X31, 5s) (context_map_sccp.c:272)
20240606070055274 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-7994758)[0x51200001bb20]{init}: State change to connected (no timeout) (context_map_rua.c:224)
20240606070055291 DCN DEBUG sccp_sap_up(N-CONNECT.confirm) (hnbgw_cn.c:647)
20240606070055291 DCN DEBUG handle_cn_conn_conf() conn_id=40, addrs: called=RI=SSN_PC,PC=0.0.3,SSN=RANAP calling=RI=SSN_PC,PC=0.23.5,SSN=RANAP responding=RI=NONE (hnbgw_cn.c:483)
20240606070055291 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-40)[0x51200001bca0]{wait_cc}: Received Event MAP_SCCP_EV_RX_CONNECTION_CONFIRM (hnbgw_cn.c:489)
20240606070055291 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-40)[0x51200001bca0]{wait_cc}: State change to connected (no timeout) (context_map_sccp.c:304)
20240606070055293 DLGLOBAL INFO Closing telnet connection r=127.0.0.1:53970<->l=127.0.0.1:4261 (telnet_interface.c:138)
20240606070055295 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:new (control_cmd.c:428)
20240606070055297 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:known (control_cmd.c:428)
20240606070055299 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:reattach (control_cmd.c:428)
20240606070055301 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070055303 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:paged (control_cmd.c:428)
20240606070055305 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:new (control_cmd.c:428)
20240606070055307 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:known (control_cmd.c:428)
20240606070055309 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:reattach (control_cmd.c:428)
20240606070055311 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070055312 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:paged (control_cmd.c:428)
20240606070055314 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:new (control_cmd.c:428)
20240606070055316 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:known (control_cmd.c:428)
20240606070055318 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:reattach (control_cmd.c:428)
20240606070055320 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070055322 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:paged (control_cmd.c:428)
20240606070055324 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:new (control_cmd.c:428)
20240606070055326 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:known (control_cmd.c:428)
20240606070055327 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:reattach (control_cmd.c:428)
20240606070055329 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070055331 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:paged (control_cmd.c:428)
20240606070055382 DLGLOBAL INFO Accept()ed new telnet connection r=127.0.0.1:53974<->l=127.0.0.1:4261 (telnet_interface.c:192)
20240606070056418 DMAIN DEBUG Decoding message RUA_ConnectIEs (rua_decoder.c:22) (rua_decoder.c:22)
20240606070056419 DHNB DEBUG map_rua[0x512000020020]{init}: Allocated (fsm.c:456)
20240606070056419 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-291557)[0x512000020020]{init}: State change to init (X31, 5s) (context_map_rua.c:85)
20240606070056419 DCN INFO (127.0.1.1:9999 TTCN3-HNB-0) RUA-291557 SCCP-0 CS MI=TMSI-0x42A98023: TMSI-0x42A98023 NRI(10bit)=0x2a6=678: NRI match selects msc 2 (hnbgw_cn.c:1067)
20240606070056419 DCN DEBUG map_sccp[0x5120000201a0]{init}: Allocated (fsm.c:456)
20240606070056419 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-41)[0x5120000201a0]{init}: State change to init (X31, 5s) (context_map_sccp.c:93)
20240606070056419 DRUA NOTICE New conn: r=127.0.1.1:9999<->l=127.0.0.1:29169 '127.0.1.1:9999 TTCN3-HNB-0' RUA-291557 <-> SCCP-41 msc-2 msc-two cs7-0.sccp l=0.23.5<->r=0.0.3 (context_map.c:128)
20240606070056419 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-291557)[0x512000020020]{init}: Received Event MAP_RUA_EV_RX_CONNECT (hnbgw_rua.c:299)
20240606070056419 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-291557)[0x512000020020]{init}: rx from RUA: RANAP Initial UE Message (context_map_rua.c:166)
20240606070056420 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-41)[0x5120000201a0]{init}: Received Event MAP_SCCP_EV_TX_DATA_REQUEST (context_map_rua.c:194)
20240606070056420 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-41)[0x5120000201a0]{init}: State change to wait_cc (X31, 5s) (context_map_sccp.c:272)
20240606070056420 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-291557)[0x512000020020]{init}: State change to connected (no timeout) (context_map_rua.c:224)
20240606070056427 DCN DEBUG sccp_sap_up(N-CONNECT.confirm) (hnbgw_cn.c:647)
20240606070056427 DCN DEBUG handle_cn_conn_conf() conn_id=41, addrs: called=RI=SSN_PC,PC=0.0.3,SSN=RANAP calling=RI=SSN_PC,PC=0.23.5,SSN=RANAP responding=RI=NONE (hnbgw_cn.c:483)
20240606070056427 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-41)[0x5120000201a0]{wait_cc}: Received Event MAP_SCCP_EV_RX_CONNECTION_CONFIRM (hnbgw_cn.c:489)
20240606070056427 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-41)[0x5120000201a0]{wait_cc}: State change to connected (no timeout) (context_map_sccp.c:304)
20240606070056434 DLGLOBAL INFO Closing telnet connection r=127.0.0.1:53974<->l=127.0.0.1:4261 (telnet_interface.c:138)
20240606070056436 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:new (control_cmd.c:428)
20240606070056439 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:known (control_cmd.c:428)
20240606070056442 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:reattach (control_cmd.c:428)
20240606070056444 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070056447 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:paged (control_cmd.c:428)
20240606070056451 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:new (control_cmd.c:428)
20240606070056454 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:known (control_cmd.c:428)
20240606070056457 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:reattach (control_cmd.c:428)
20240606070056459 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070056462 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:paged (control_cmd.c:428)
20240606070056465 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:new (control_cmd.c:428)
20240606070056468 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:known (control_cmd.c:428)
20240606070056470 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:reattach (control_cmd.c:428)
20240606070056473 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070056477 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:paged (control_cmd.c:428)
20240606070056480 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:new (control_cmd.c:428)
20240606070056484 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:known (control_cmd.c:428)
20240606070056488 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:reattach (control_cmd.c:428)
20240606070056491 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070056494 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:paged (control_cmd.c:428)
20240606070056584 DLGLOBAL INFO Accept()ed new telnet connection r=127.0.0.1:53976<->l=127.0.0.1:4261 (telnet_interface.c:192)
20240606070057626 DMAIN DEBUG Decoding message RUA_ConnectIEs (rua_decoder.c:22) (rua_decoder.c:22)
20240606070057626 DHNB DEBUG map_rua[0x5120000204a0]{init}: Allocated (fsm.c:456)
20240606070057626 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-15282514)[0x5120000204a0]{init}: State change to init (X31, 5s) (context_map_rua.c:85)
20240606070057626 DCN INFO (127.0.1.1:9999 TTCN3-HNB-0) RUA-15282514 SCCP-0 CS MI=IMSI-262420000000001: CN link round-robin selects msc 1 (hnbgw_cn.c:1114)
20240606070057626 DCN DEBUG map_sccp[0x512000020620]{init}: Allocated (fsm.c:456)
20240606070057626 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-42)[0x512000020620]{init}: State change to init (X31, 5s) (context_map_sccp.c:93)
20240606070057626 DRUA NOTICE New conn: r=127.0.1.1:9999<->l=127.0.0.1:29169 '127.0.1.1:9999 TTCN3-HNB-0' RUA-15282514 <-> SCCP-42 msc-1 msc-one cs7-0.sccp l=0.23.5<->r=0.0.2 (context_map.c:128)
20240606070057626 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-15282514)[0x5120000204a0]{init}: Received Event MAP_RUA_EV_RX_CONNECT (hnbgw_rua.c:299)
20240606070057627 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-15282514)[0x5120000204a0]{init}: rx from RUA: RANAP Initial UE Message (context_map_rua.c:166)
20240606070057627 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-42)[0x512000020620]{init}: Received Event MAP_SCCP_EV_TX_DATA_REQUEST (context_map_rua.c:194)
20240606070057627 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-42)[0x512000020620]{init}: State change to wait_cc (X31, 5s) (context_map_sccp.c:272)
20240606070057627 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-15282514)[0x5120000204a0]{init}: State change to connected (no timeout) (context_map_rua.c:224)
20240606070057658 DLGLOBAL INFO Closing telnet connection r=127.0.0.1:53976<->l=127.0.0.1:4261 (telnet_interface.c:138)
20240606070057660 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:new (control_cmd.c:428)
20240606070057668 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:known (control_cmd.c:428)
20240606070057672 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:reattach (control_cmd.c:428)
20240606070057676 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070057678 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.0.cnpool:subscr:paged (control_cmd.c:428)
20240606070057683 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:new (control_cmd.c:428)
20240606070057690 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:known (control_cmd.c:428)
20240606070057697 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:reattach (control_cmd.c:428)
20240606070057700 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070057704 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.1.cnpool:subscr:paged (control_cmd.c:428)
20240606070057706 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:new (control_cmd.c:428)
20240606070057708 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:known (control_cmd.c:428)
20240606070057710 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:reattach (control_cmd.c:428)
20240606070057712 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070057714 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.2.cnpool:subscr:paged (control_cmd.c:428)
20240606070057717 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:new (control_cmd.c:428)
20240606070057720 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:known (control_cmd.c:428)
20240606070057722 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:reattach (control_cmd.c:428)
20240606070057724 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:attach_lost (control_cmd.c:428)
20240606070057726 DLCTRL DEBUG Command: GET rate_ctr.abs.msc.3.cnpool:subscr:paged (control_cmd.c:428)
20240606070057735 DLGLOBAL INFO Closing telnet connection r=127.0.0.1:40232<->l=127.0.0.1:4261 (telnet_interface.c:138)
20240606070057752 DMAIN NOTICE (127.0.1.2:36753 TTCN3-HNB-1) sctp_recvmsg(r=127.0.1.2:36753<->l=127.0.0.1:29169) = SCTP_SHUTDOWN_EVENT, closing conn (hnbgw.c:793)
20240606070057752 DMAIN INFO (disconnected TTCN3-HNB-1) Releasing HNB context (hnbgw.c:351)
20240606070057752 DLCTRL INFO close()d CTRL connection (r=127.0.0.1:37943<->l=127.0.0.1:4262) (control_if.c:193)
20240606070057769 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070057769 DCN DEBUG N-PCSTATE ind: affected_pc=188 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:557)
20240606070057769 DCN NOTICE (msc-0) now unreachable: N-PCSTATE ind: pc=188 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:620)
20240606070057769 DRANAP NOTICE cnlink(msc-0)[0x512000004420]{DISCONNECTED}: link lost (cnlink.c:118)
20240606070057769 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070057769 DCN DEBUG N-PCSTATE ind: affected_pc=3 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:557)
20240606070057769 DCN NOTICE (msc-2) now unreachable: N-PCSTATE ind: pc=3 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:620)
20240606070057769 DRANAP NOTICE cnlink(msc-2)[0x512000004a20]{DISCONNECTED}: link lost (cnlink.c:118)
20240606070057769 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-40)[0x51200001bca0]{connected}: Received Event MAP_SCCP_EV_RAN_LINK_LOST (context_map.c:189)
20240606070057769 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-40)[0x51200001bca0]{connected}: State change to disconnected (X31, 5s) (context_map_sccp.c:382)
20240606070057769 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-7994758)[0x51200001bb20]{connected}: Received Event MAP_RUA_EV_CN_DISC (context_map_sccp.c:465)
20240606070057769 DHNB INFO map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-7994758)[0x51200001bb20]{connected}: Tx RUA Disconnect (context_map_rua.c:262)
20240606070057769 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-7994758)[0x51200001bb20]{connected}: State change to disrupted (X31, 5s) (context_map_rua.c:305)
20240606070057769 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-7994758)[0x51200001bb20]{disrupted}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:202)
20240606070057769 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-7994758)[0x51200001bb20]{disrupted}: Freeing instance (context_map.c:202)
20240606070057769 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-7994758)[0x51200001bb20]{disrupted}: Deallocated (fsm.c:568)
20240606070057769 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-40)[0x51200001bca0]{disconnected}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:206)
20240606070057769 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-40)[0x51200001bca0]{disconnected}: Freeing instance (context_map.c:206)
20240606070057769 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-40)[0x51200001bca0]{disconnected}: Deallocated (fsm.c:568)
20240606070057770 DMAIN INFO (127.0.1.1:9999 TTCN3-HNB-0) RUA-7994758 SCCP-40 msc-2 MI=TMSI-0x42800023: Deallocating (context_map.c:225)
20240606070057770 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-41)[0x5120000201a0]{connected}: Received Event MAP_SCCP_EV_RAN_LINK_LOST (context_map.c:189)
20240606070057770 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-41)[0x5120000201a0]{connected}: State change to disconnected (X31, 5s) (context_map_sccp.c:382)
20240606070057770 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-291557)[0x512000020020]{connected}: Received Event MAP_RUA_EV_CN_DISC (context_map_sccp.c:465)
20240606070057770 DHNB INFO map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-291557)[0x512000020020]{connected}: Tx RUA Disconnect (context_map_rua.c:262)
20240606070057770 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-291557)[0x512000020020]{connected}: State change to disrupted (X31, 5s) (context_map_rua.c:305)
20240606070057770 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-291557)[0x512000020020]{disrupted}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:202)
20240606070057771 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-291557)[0x512000020020]{disrupted}: Freeing instance (context_map.c:202)
20240606070057771 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-291557)[0x512000020020]{disrupted}: Deallocated (fsm.c:568)
20240606070057771 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-41)[0x5120000201a0]{disconnected}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:206)
20240606070057771 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-41)[0x5120000201a0]{disconnected}: Freeing instance (context_map.c:206)
20240606070057771 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-2-SCCP-41)[0x5120000201a0]{disconnected}: Deallocated (fsm.c:568)
20240606070057771 DMAIN INFO (127.0.1.1:9999 TTCN3-HNB-0) RUA-291557 SCCP-41 msc-2 MI=TMSI-0x42A98023: Deallocating (context_map.c:225)
20240606070057771 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070057771 DCN DEBUG N-PCSTATE ind: affected_pc=185 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:557)
20240606070057771 DCN NOTICE (sgsn-0) now unreachable: N-PCSTATE ind: pc=185 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:620)
20240606070057771 DRANAP NOTICE cnlink(sgsn-0)[0x512000005020]{DISCONNECTED}: link lost (cnlink.c:118)
20240606070057771 DCN DEBUG sccp_sap_up(N-PCSTATE.indication) (hnbgw_cn.c:647)
20240606070057771 DCN DEBUG N-PCSTATE ind: affected_pc=10 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:557)
20240606070057771 DCN NOTICE (sgsn-1) now unreachable: N-PCSTATE ind: pc=10 sp_status=INACCESSIBLE remote_sccp_status=UNAVAILABLE_UNKNOWN (hnbgw_cn.c:620)
20240606070057771 DRANAP NOTICE cnlink(sgsn-1)[0x512000005320]{DISCONNECTED}: link lost (cnlink.c:118)
20240606070057771 DMAIN NOTICE (127.0.1.1:9999 TTCN3-HNB-0) sctp_recvmsg(r=127.0.1.1:9999<->l=127.0.0.1:29169) = SCTP_SHUTDOWN_EVENT, closing conn (hnbgw.c:793)
20240606070057772 DMAIN INFO (disconnected TTCN3-HNB-0) Releasing HNB context (hnbgw.c:351)
20240606070057772 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-15282514)[0x5120000204a0]{connected}: Received Event MAP_RUA_EV_HNB_LINK_LOST (context_map.c:184)
20240606070057772 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-15282514)[0x5120000204a0]{connected}: State change to disrupted (X31, 5s) (context_map_rua.c:298)
20240606070057772 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-42)[0x512000020620]{wait_cc}: Received Event MAP_SCCP_EV_RAN_LINK_LOST (context_map_rua.c:319)
20240606070057832 DCN DEBUG sccp_sap_up(N-CONNECT.confirm) (hnbgw_cn.c:647)
20240606070057832 DCN DEBUG handle_cn_conn_conf() conn_id=42, addrs: called=RI=SSN_PC,PC=0.0.2,SSN=RANAP calling=RI=SSN_PC,PC=0.23.5,SSN=RANAP responding=RI=NONE (hnbgw_cn.c:483)
20240606070057832 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-42)[0x512000020620]{wait_cc}: Received Event MAP_SCCP_EV_RX_CONNECTION_CONFIRM (hnbgw_cn.c:489)
20240606070057834 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-42)[0x512000020620]{wait_cc}: State change to connected (no timeout) (context_map_sccp.c:304)
20240606070057834 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-42)[0x512000020620]{connected}: State change to disconnected (X31, 5s) (context_map_sccp.c:342)
20240606070057834 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-15282514)[0x5120000204a0]{disrupted}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:202)
20240606070057834 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-15282514)[0x5120000204a0]{disrupted}: Freeing instance (context_map.c:202)
20240606070057834 DHNB DEBUG map_rua(127-0-1-1:9999-TTCN3-HNB-0-CS-RUA-15282514)[0x5120000204a0]{disrupted}: Deallocated (fsm.c:568)
20240606070057834 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-42)[0x512000020620]{disconnected}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (context_map.c:206)
20240606070057834 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-42)[0x512000020620]{disconnected}: Freeing instance (context_map.c:206)
20240606070057834 DCN DEBUG map_sccp(127-0-1-1:9999-TTCN3-HNB-0-msc-1-SCCP-42)[0x512000020620]{disconnected}: Deallocated (fsm.c:568)
20240606070057834 DMAIN INFO (NULL) RUA-15282514 SCCP-42 msc-1 MI=IMSI-262420000000001: Deallocating (context_map.c:225)
=================================================================
==571587==ERROR: AddressSanitizer: heap-use-after-free on address 0x512000020648 at pc 0x55f8b2009974 bp 0x7fff87231280 sp 0x7fff87231278
READ of size 8 at 0x512000020648 thread T0
    #0 0x55f8b2009973 in handle_rx_sccp ../../../../src/osmo-hnbgw/src/osmo-hnbgw/context_map_sccp.c:198
    #1 0x55f8b200b889 in map_sccp_wait_cc_action ../../../../src/osmo-hnbgw/src/osmo-hnbgw/context_map_sccp.c:306
    #2 0x7f9580db6ec6 in _osmo_fsm_inst_dispatch ../../../../src/libosmocore/src/core/fsm.c:875
    #3 0x55f8b1ffe26f in _map_sccp_dispatch ../../../../src/osmo-hnbgw/src/osmo-hnbgw/context_map.c:163
    #4 0x55f8b2016bcc in handle_cn_conn_conf ../../../../src/osmo-hnbgw/src/osmo-hnbgw/hnbgw_cn.c:489
    #5 0x55f8b2019606 in sccp_sap_up ../../../../src/osmo-hnbgw/src/osmo-hnbgw/hnbgw_cn.c:671
    #6 0x7f9582a0a6fd in sccp_user_prim_up ../../../src/libosmo-sccp/src/sccp_user.c:178
    #7 0x7f9582a006ff in scu_gen_encode_and_send ../../../src/libosmo-sccp/src/sccp_scoc.c:942
    #8 0x7f9582a0212e in scoc_fsm_conn_pend_out ../../../src/libosmo-sccp/src/sccp_scoc.c:1135
    #9 0x7f9580db6ec6 in _osmo_fsm_inst_dispatch ../../../../src/libosmocore/src/core/fsm.c:875
    #10 0x7f9582a06bf0 in sccp_scoc_rx_from_scrc ../../../src/libosmo-sccp/src/sccp_scoc.c:1857
    #11 0x7f95829f43bc in scrc_rx_mtp_xfer_ind_xua ../../../src/libosmo-sccp/src/sccp_scrc.c:479
    #12 0x7f9582a0acd0 in mtp_user_prim_cb ../../../src/libosmo-sccp/src/sccp_user.c:203
    #13 0x7f95829a42d6 in deliver_to_mtp_user ../../../src/libosmo-sccp/src/osmo_ss7_hmrt.c:95
    #14 0x7f95829a4966 in hmdt_message_for_distribution ../../../src/libosmo-sccp/src/osmo_ss7_hmrt.c:134
    #15 0x7f95829a64bd in m3ua_hmdc_rx_from_l2 ../../../src/libosmo-sccp/src/osmo_ss7_hmrt.c:284
    #16 0x7f95829751c4 in m3ua_rx_xfer ../../../src/libosmo-sccp/src/m3ua.c:576
    #17 0x7f9582977090 in m3ua_rx_msg ../../../src/libosmo-sccp/src/m3ua.c:731
    #18 0x7f958299d045 in xua_cli_read_cb ../../../src/libosmo-sccp/src/osmo_ss7_asp.c:1066
    #19 0x7f9583119f03 in stream_cli_iofd_recvmsg_cb ../../../src/libosmo-netif/src/stream_cli.c:530
    #20 0x7f9580e0064a in iofd_handle_recv ../../../../src/libosmocore/src/core/osmo_io.c:368
    #21 0x7f9580e07f6b in iofd_poll_ofd_cb_recvmsg_sendmsg ../../../../src/libosmocore/src/core/osmo_io_poll.c:77
    #22 0x7f9580e08832 in iofd_poll_ofd_cb_dispatch ../../../../src/libosmocore/src/core/osmo_io_poll.c:115
    #23 0x7f9580e17775 in poll_disp_fds ../../../../src/libosmocore/src/core/select.c:419
    #24 0x7f9580e17902 in _osmo_select_main ../../../../src/libosmocore/src/core/select.c:457
    #25 0x7f9580e179e5 in osmo_select_main_ctx ../../../../src/libosmocore/src/core/select.c:513
    #26 0x55f8b1fc1825 in main ../../../../src/osmo-hnbgw/src/osmo-hnbgw/osmo_hnbgw_main.c:364
    #27 0x7f9580a42c89  (/lib/x86_64-linux-gnu/libc.so.6+0x27c89) (BuildId: 3264bbfd8d6151ee14beb5444dc47c60bc1ff1f4)
    #28 0x7f9580a42d44 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x27d44) (BuildId: 3264bbfd8d6151ee14beb5444dc47c60bc1ff1f4)
    #29 0x55f8b1fbf770 in _start (/usr/local/bin/osmo-hnbgw+0x133770) (BuildId: 3acb0cb6b1b55caeb26a4fa95949d003b9ed5d80)

0x512000020648 is located 136 bytes inside of 296-byte region [0x5120000205c0,0x5120000206e8)
freed by thread T0 here:
    #0 0x7f95840f2868 in free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:52
    #1 0x7f95827f65e1  (/lib/x86_64-linux-gnu/libtalloc.so.2+0x45e1) (BuildId: 75c550e5dc091c77e1159c52b284f34d0c4d92cd)
    #2 0x7f9580dafbc7 in osmo_fsm_inst_free ../../../../src/libosmocore/src/core/fsm.c:569
    #3 0x7f9580dbb129 in _osmo_fsm_inst_term ../../../../src/libosmocore/src/core/fsm.c:957
    #4 0x55f8b1fff490 in context_map_free ../../../../src/osmo-hnbgw/src/osmo-hnbgw/context_map.c:206
    #5 0x55f8b200db81 in map_sccp_disconnected_onenter ../../../../src/osmo-hnbgw/src/osmo-hnbgw/context_map_sccp.c:467
    #6 0x7f9580db439f in state_chg ../../../../src/libosmocore/src/core/fsm.c:697
    #7 0x7f9580db44ac in _osmo_fsm_inst_state_chg_ms ../../../../src/libosmocore/src/core/fsm.c:752
    #8 0x7f9580e5143b in _osmo_tdef_fsm_inst_state_chg ../../../../src/libosmocore/src/core/tdef.c:370
    #9 0x55f8b200c5b4 in map_sccp_connected_onenter ../../../../src/osmo-hnbgw/src/osmo-hnbgw/context_map_sccp.c:342
    #10 0x7f9580db439f in state_chg ../../../../src/libosmocore/src/core/fsm.c:697
    #11 0x7f9580db4458 in _osmo_fsm_inst_state_chg ../../../../src/libosmocore/src/core/fsm.c:746
    #12 0x7f9580e50ed0 in _osmo_tdef_fsm_inst_state_chg ../../../../src/libosmocore/src/core/tdef.c:344
    #13 0x55f8b200b833 in map_sccp_wait_cc_action ../../../../src/osmo-hnbgw/src/osmo-hnbgw/context_map_sccp.c:304
    #14 0x7f9580db6ec6 in _osmo_fsm_inst_dispatch ../../../../src/libosmocore/src/core/fsm.c:875
    #15 0x55f8b1ffe26f in _map_sccp_dispatch ../../../../src/osmo-hnbgw/src/osmo-hnbgw/context_map.c:163
    #16 0x55f8b2016bcc in handle_cn_conn_conf ../../../../src/osmo-hnbgw/src/osmo-hnbgw/hnbgw_cn.c:489
    #17 0x55f8b2019606 in sccp_sap_up ../../../../src/osmo-hnbgw/src/osmo-hnbgw/hnbgw_cn.c:671
    #18 0x7f9582a0a6fd in sccp_user_prim_up ../../../src/libosmo-sccp/src/sccp_user.c:178
    #19 0x7f9582a006ff in scu_gen_encode_and_send ../../../src/libosmo-sccp/src/sccp_scoc.c:942
    #20 0x7f9582a0212e in scoc_fsm_conn_pend_out ../../../src/libosmo-sccp/src/sccp_scoc.c:1135
    #21 0x7f9580db6ec6 in _osmo_fsm_inst_dispatch ../../../../src/libosmocore/src/core/fsm.c:875
    #22 0x7f9582a06bf0 in sccp_scoc_rx_from_scrc ../../../src/libosmo-sccp/src/sccp_scoc.c:1857
    #23 0x7f95829f43bc in scrc_rx_mtp_xfer_ind_xua ../../../src/libosmo-sccp/src/sccp_scrc.c:479
    #24 0x7f9582a0acd0 in mtp_user_prim_cb ../../../src/libosmo-sccp/src/sccp_user.c:203
    #25 0x7f95829a42d6 in deliver_to_mtp_user ../../../src/libosmo-sccp/src/osmo_ss7_hmrt.c:95
    #26 0x7f95829a4966 in hmdt_message_for_distribution ../../../src/libosmo-sccp/src/osmo_ss7_hmrt.c:134
    #27 0x7f95829a64bd in m3ua_hmdc_rx_from_l2 ../../../src/libosmo-sccp/src/osmo_ss7_hmrt.c:284
    #28 0x7f95829751c4 in m3ua_rx_xfer ../../../src/libosmo-sccp/src/m3ua.c:576
    #29 0x7f9582977090 in m3ua_rx_msg ../../../src/libosmo-sccp/src/m3ua.c:731

previously allocated by thread T0 here:
    #0 0x7f95840f3bc7 in malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:69
    #1 0x7f95827f7e73  (/lib/x86_64-linux-gnu/libtalloc.so.2+0x5e73) (BuildId: 75c550e5dc091c77e1159c52b284f34d0c4d92cd)

SUMMARY: AddressSanitizer: heap-use-after-free ../../../../src/osmo-hnbgw/src/osmo-hnbgw/context_map_sccp.c:198 in handle_rx_sccp
Shadow bytes around the buggy address:
  0x512000020380: 00 00 00 00 00 00 00 00 00 00 00 00 00 fa fa fa
  0x512000020400: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
  0x512000020480: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x512000020500: fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa
  0x512000020580: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
=>0x512000020600: fd fd fd fd fd fd fd fd fd[fd]fd fd fd fd fd fd
  0x512000020680: fd fd fd fd fd fd fd fd fd fd fd fd fd fa fa fa
  0x512000020700: fa fa fa fa fa fa fa fa 00 00 00 00 00 00 00 00
  0x512000020780: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x512000020800: 00 00 00 00 00 00 00 00 00 00 00 00 00 fa fa fa
  0x512000020880: fa fa fa fa fa fa fa 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
==571587==ABORTING

Related issues

Related to OsmoHNBGW - Feature #6085: context_map_sccp.c parrots states/events that the SCCP-SCOC FSM already handlesNewneels07/04/2023

Actions
Actions
Copy link
 #1

Updated by neels 24 days ago 

pass HNBGW_Tests.TC_hnb_register
pass HNBGW_Tests.TC_hnb_register_duplicate
pass HNBGW_Tests.TC_hnb_register_duplicate_reuse_sctp_assoc
pass HNBGW_Tests.TC_ue_register
pass HNBGW_Tests.TC_ue_register_tmsi_lai
pass HNBGW_Tests.TC_ue_register_before_hnb_register
pass HNBGW_Tests.TC_rab_release_abnormal
pass HNBGW_Tests.TC_ranap_cs_initial_ue
pass HNBGW_Tests.TC_ranap_ps_initial_ue
pass HNBGW_Tests.TC_ranap_cs_initial_ue_empty_cr
pass HNBGW_Tests.TC_ranap_ps_initial_ue_empty_cr
pass HNBGW_Tests.TC_ranap_cs_bidir
pass HNBGW_Tests.TC_ranap_ps_bidir
pass HNBGW_Tests.TC_rab_assignment
pass HNBGW_Tests.TC_rab_release
pass HNBGW_Tests.TC_rab_release_abnormal
pass HNBGW_Tests.TC_rab_assign_fail
pass HNBGW_Tests.TC_rab_assign_mgcp_to
pass HNBGW_Tests.TC_rab_assign_mgw_iuup_addr_chg
pass HNBGW_Tests.TC_ranap_cs_mo_disconnect
pass HNBGW_Tests.TC_ranap_ps_mo_disconnect
pass HNBGW_Tests.TC_ps_rab_assignment_without_pfcp
pass HNBGW_Tests.TC_mscpool_L3Compl_on_1_cnlink
pass HNBGW_Tests.TC_mscpool_L3Complete_by_imsi_round_robin
pass HNBGW_Tests.TC_mscpool_LU_by_tmsi_null_nri_0_round_robin
pass HNBGW_Tests.TC_mscpool_LU_by_tmsi_null_nri_1_round_robin
pass HNBGW_Tests.TC_mscpool_L3Complete_by_tmsi_unassigned_nri_round_robin
pass HNBGW_Tests.TC_mscpool_L3Complete_by_tmsi_valid_nri_msc_not_connected_round_robin
pass HNBGW_Tests.TC_mscpool_L3Complete_by_tmsi_valid_nri_1
pass HNBGW_Tests.TC_mscpool_L3Complete_by_tmsi_valid_nri_2
pass->FAIL HNBGW_Tests.TC_mscpool_LU_by_tmsi_from_other_PLMN
NEW: PASS HNBGW_Tests.TC_hnb_register2
NEW: PASS HNBGW_Tests.TC_hnb_disconnected_timeout
NEW: PASS HNBGW_Tests.TC_hnbap_cs_hnb_disconnect
NEW: PASS HNBGW_Tests.TC_hnbap_ps_hnb_disconnect

Summary:
  pass->FAIL: 1
  pass: 30
  NEW: PASS: 4
  skip: 16

HNBGW_Tests.TC_mscpool_LU_by_tmsi_from_other_PLMN was run last, not sure if the segfault happened before or during this test.

Actions
Copy link
 #2

Updated by neels 21 days ago

I couldn't reproduce the problem again, but I figured out how the segfault came about:

The CN link was lost while the map_sccp_fsm is still waiting for the SCCP connection confirmation.
Hence osmo-hnbgw sets map->please_disconnect = true, to still receive a pending CC or CREF in the right place.
Then, an SCCP CC is received and this code happens:

        case MAP_SCCP_EV_RX_CONNECTION_CONFIRM:
                map_sccp_fsm_state_chg(MAP_SCCP_ST_CONNECTED);
                /* Usually doesn't but if the SCCP CC contained data, forward it to RUA */
                handle_rx_sccp(fi, ranap_msg);
                return;

We change the state, then dispatch a contained RANAP msg, if any.
However, since please_disconnect == true, the FSM is terminated during the state change:

static void map_sccp_connected_onenter(struct osmo_fsm_inst *fi, uint32_t prev_state)
{
        struct hnbgw_context_map *map = fi->priv;
        if (map->please_disconnect) {
                /* SCCP has already been asked to disconnect, so disconnect now that the CC has been received. Send RLSD
                 * to SCCP (without RANAP data) */
                tx_sccp_rlsd(fi);
                map_sccp_fsm_state_chg(MAP_SCCP_ST_DISCONNECTED);
        }
}

So after the state change, the FSM is deallocated, and attempting to do

                handle_rx_sccp(fi, ranap_msg);

causes a use-after-free.

This use-after-free is a general problem for FSM design. For this, we created osmo_fsm_set_dealloc_ctx(ctx):
When an FSM is terminated, it gets moved to a separate talloc context, instead of being deallocated.
Hence it is still safe to query the FSM's state after termination.

So to solve the problem, I will

  • set osmo_fsm_set_dealloc_ctx(OTC_SELECT) in osmo-hnbgw's main().
    This way we possibly pre-empt similar crashes that we haven't hit yet.
  • In the event handler, dispatch RANAP only when the FSM's state is still ST_CONNECTED after the state change.
Actions
Copy link
 #3

Updated by neels 21 days ago

neels wrote in #note-2:

The CN link was lost

Actually I meant to say, the Iuh link (RUA to the hNodeB) was lost, while the CN link (SCCP to the MSC) was waiting for SCCP CC or CREF.

Actions
Copy link
 #4

Updated by neels 21 days ago

  • Related to Feature #6085: context_map_sccp.c parrots states/events that the SCCP-SCOC FSM already handles added
Actions
Copy link
 #5

Updated by neels 21 days ago

Looking at #6484: probably the issue could also be fixed by entirely cutting out the wait-for-CC behavior, which is already implemented in the SCCP-SCOC FSM, and not actually needed; i.e. remove all of the please_disconnect related code and just dispatch a DISCONN prim to SCCP-SCOC.

Actions
Copy link
 #6

Updated by neels 21 days ago

The first fix (stability against terminated FSM instances) is https://gerrit.osmocom.org/c/osmo-hnbgw/+/37147
This stability improvement does make sense in general, independently from this particular use-after-free case.

We should still solve #6085, but after merging the above patch, it is not particularly urgent anymore.

There obviously is no TTCN3 test for this case.
IIRC it is hard to test this, because our TTCN3 SCCP layer always responds with CC implicitly.
Would be worth a try, also for #6085.

Actions
Copy link
 #7

Updated by neels 21 days ago

  • % Done changed from 0 to 90
Actions
Copy link
 #8

Updated by neels 20 days ago

  • Status changed from New to Resolved
  • % Done changed from 90 to 100
Actions
Copy link

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)