Project

General

Profile

Actions
Copy link

Bug #4824

closed

vty comand "show sndcp" can cause SEGV in vty_dump_sne()

Added by keith over 3 years ago. Updated over 2 years ago.

Status:
Resolved
Priority:
High
Assignee:
osmith
Category:
-
Target version:
-
Start date:
10/21/2020
Due date:
% Done:

100%

Spec Reference:

Description

(gdb) bt
#0  vty_dump_sne (vty=0x558339e52010, sne=0x558339e57360) at gprs_sndcp_vty.c:44
#1  0x000055833916afb7 in show_sndcp (self=0x55833939aac0 <show_sndcp_cmd>, vty=0x558339e52010, argc=0, argv=0x7ffcb165cf50) at gprs_sndcp_vty.c:60
Actions
Copy link
 #1

Updated by keith over 3 years ago 

static void vty_dump_sne(struct vty *vty, struct gprs_sndcp_entity *sne)
{
    vty_out(vty, " TLLI %08x SAPI=%u NSAPI=%u:%s",
        sne->lle->llme->tlli, sne->lle->sapi, sne->nsapi, VTY_NEWLINE);
    vty_out(vty, "  Defrag: npdu=%u highest_seg=%u seg_have=0x%08x tot_len=%u%s",
        sne->defrag.npdu, sne->defrag.highest_seg, sne->defrag.seg_have,
        sne->defrag.tot_len, VTY_NEWLINE);
}

(gdb) p sne->lle->llme
$6 = (struct gprs_llc_llme *) 0x0
Actions
Copy link
 #2

Updated by keith over 3 years ago

Can anyone shed any light on if this is an expected condition, and should be fixed by simply checking before access, of it it betrays an underlying bug?

Actions
Copy link
 #3

Updated by laforge over 3 years ago

I don't think this is expected. The LLME is the LLC Management Entity. So you have LLC Enties with out its related management.

I can currently only find code that sets lle->llme during lle_init(), but I cannot find any other place (which would set it to NULL)

Actions
Copy link
 #4

Updated by laforge over 3 years ago

maybe the entire 'lle' is gone, and the reference from the sne (sndcp entity) is already problematic? Can you print the lle in the debugger?

Actions
Copy link
 #5

Updated by laforge over 3 years ago

also, the lle are an array inside the llme. So it's impossible that a LLE has no LLME. The back-pointer is not written to anywhere, so I think indeed the sne->lle pointer may be stale, or the entire sne.

Actions
Copy link
 #6

Updated by laforge over 3 years ago

so the SNE is free'd via sndcp_sm_deactivate_ind(), which happens at PDP context termination.

the LLME with all its LLEs is free'd via gprs_llgmm_assign(..., new_tlli=TLLI_UNASSIGNED)

maybe there are other situations in whihc the LLME is freed, where the SNE is not free'd before? As all the gprs_llgmm_assign() calls originate from gprs_gmm, it may be in the path for GGSN side PDP context termination from sgsn_libgtp.c -> sndcp_sm_deactivate_ind() where the SNDCP entity is not free'd.

I'll drop looking at it further here.

Actions
Copy link
 #7

Updated by lynxis over 3 years ago

The rc3 setup has the same problem. But not always. maybe only when the llme was gone.

Actions
Copy link
 #8

Updated by lynxis over 3 years ago 

(gdb) bt
#0  vty_dump_sne (vty=0x55e91d42e840, sne=0x55e91d43a590) at ../../../../src/osmo-sgsn/src/sgsn/gprs_sndcp_vty.c:44
#1  0x000055e91c3e1302 in show_sndcp (self=0x55e91c414b60 <show_sndcp_cmd>, vty=0x55e91d42e840, argc=0, argv=0x7ffc22507bf0)
    at ../../../../src/osmo-sgsn/src/sgsn/gprs_sndcp_vty.c:60
#2  0x00007f6194d335b9 in cmd_execute_command_real (vty=vty@entry=0x55e91d42e840, cmd=cmd@entry=0x0, vline=<optimized out>, vline=<optimized out>)
    at ../../../../src/libosmocore/src/vty/command.c:2602
#3  0x00007f6194d354ce in cmd_execute_command (vline=vline@entry=0x55e91d440600, vty=vty@entry=0x55e91d42e840, cmd=cmd@entry=0x0, vtysh=vtysh@entry=0)
    at ../../../../src/libosmocore/src/vty/command.c:2654
#4  0x00007f6194d37c1a in vty_command (vty=0x55e91d42e840) at ../../../../src/libosmocore/src/vty/vty.c:438
#5  vty_execute (vty=0x55e91d42e840) at ../../../../src/libosmocore/src/vty/vty.c:702
#6  vty_read (vty=<optimized out>) at ../../../../src/libosmocore/src/vty/vty.c:1428
#7  0x00007f6194d39ced in client_data (fd=0x55e91d433e98, what=1) at ../../../../src/libosmocore/src/vty/telnet_interface.c:154
#8  0x00007f6194d01add in poll_disp_fds (n_fd=<optimized out>) at ../../../src/libosmocore/src/select.c:350
#9  _osmo_select_main (polling=<optimized out>) at ../../../src/libosmocore/src/select.c:378
#10 0x00007f6194d01b56 in osmo_select_main (polling=<optimized out>) at ../../../src/libosmocore/src/select.c:417
#11 0x000055e91c3e6b38 in main (argc=3, argv=0x7ffc22508838) at ../../../../src/osmo-sgsn/src/sgsn/sgsn_main.c:532
(gdb) frame 0 
#0  vty_dump_sne (vty=0x55e91d42e840, sne=0x55e91d43a590) at ../../../../src/osmo-sgsn/src/sgsn/gprs_sndcp_vty.c:44
44              vty_out(vty, " TLLI %08x SAPI=%u NSAPI=%u:%s",
(gdb) p locals
No symbol "locals" in current context.
(gdb) info locals
No locals.
(gdb) info local
No locals.
(gdb) info locals 
No locals.
(gdb) p *sne 
$1 = {list = {next = 0x55e91c414b40 <gprs_sndcp_entities>, prev = 0x55e91d4348e0}, ra_id = {mcc = 262, mnc = 42, mnc_3_digits = false, lac = 23, rac = 0 '\000'}, 
  lle = 0x55e91d43b988, nsapi = 5 '\005', tx_npdu_nr = 195, rx_state = SNDCP_RX_S_FIRST, defrag = {npdu = 197, highest_seg = 2 '\002', seg_have = 7, no_more = 1, 
    tot_len = 1159, frag_list = {next = 0x55e91d43a5d0, prev = 0x55e91d43a5d0}, timer = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, 
        prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x55e91d43a590}, pcomp = 0 '\000', dcomp = 0 '\000', proto = 0x55e91d439800, 
    data = 0x55e91d435840}}

(gdb) p *sne->lle
$3 = {list = {next = 0x0, prev = 0x0}, sapi = 0, llme = 0x0, state = 0, t200 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, 
      prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0}, t201 = {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {
      next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0, data = 0x0}, v_sent = 0, v_ack = 0, v_recv = 0, vu_send = 0, vu_recv = 0, 
  vu_recv_last = 0, vu_recv_duplicates = 0, oc_i_send = 0, oc_i_recv = 0, oc_ui_send = 0, oc_ui_recv = 0, retrans_ctr = 0, params = {iov_i_exp = 0, t200_201 = 0, n200 = 0, 
    n201_u = 0, n201_i = 0, mD = 0, mU = 0, kD = 0, kU = 0}, xid = 0x0}
Actions
Copy link
 #9

Updated by lynxis over 3 years ago

it happens when moving from 2G to 3G!

Actions
Copy link
 #10

Updated by keith over 2 years ago

  • Assignee set to 118
  • Priority changed from Normal to High

Given this bug still exists in the latest release, and causes an SGSN crash from a simple vty command, I'm bumping priority.

Actions
Copy link
 #11

Updated by keith over 2 years ago

While observing an MS that appears to "think" it has a PDP context, that is to say "mobile data" status is "connected" and apps attempt data connection.

On the SGSN side, this is happening:

20211206042155100 DLLC NOTICE LLME(ffffffff/94653e86){UNASSIGNED} LLC RX: unknown TLLI 0x94653e86, creating LLME on the fly (gprs_llc.c:542)
20211206042155100 DLLC NOTICE LLME(ffffffff/94653e86){UNASSIGNED} LLGM Assign pre (94653e86 => cf536b1a) (gprs_llc.c:1068)
20211206042155100 DLLC NOTICE LLME(94653e86/cf536b1a){ASSIGNED} LLGM Assign post (94653e86 => cf536b1a) (gprs_llc.c:1114)
20211206042155778 DGPRS INFO SUBSCR(334070000000968) subscriber data is not available (gprs_subscriber.c:820)
20211206042155778 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 04 01 08 33 04 07 00 00 00 69 f8 28 01 01 2a 01 01  (gprs_subscriber.c:213)
20211206042155781 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gprs_subscriber.c:726)
20211206042155781 DGPRS INFO SUBSCR(334070000000968) Will set PDP info, context id = 1, APN = 01 2a  (gprs_subscriber.c:371)
20211206042155781 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 12 01 08 33 04 07 00 00 00 69 f8 28 01 01  (gprs_subscriber.c:213)
20211206042155781 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT (gprs_subscriber.c:726)
20211206042156498 DLLC NOTICE LLME(94653e86/cf536b1a){ASSIGNED} LLGM Assign pre (ffffffff => cf536b1a) (gprs_llc.c:1068)
20211206042156498 DLLC NOTICE LLME(ffffffff/cf536b1a){ASSIGNED} LLGM Assign post (ffffffff => cf536b1a) (gprs_llc.c:1114)
20211206042156498 DGPRS INFO PDP(334070000000968/0) <- ACTIVATE PDP CONTEXT ACK (gprs_sm.c:188)
20211206042156499 DLLC NOTICE Sending XID type NULL (8 bytes) request to MS... (gprs_llc.c:354)
20211206042157339 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206042157339 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206042158100 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206042158100 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)

OsmoSGSN# show mm-context all pdp 
MM Context for IMSI 334070000000968, IMEI 357292075895950, P-TMSI cf536b1a
  MSISDN: 57057174747, TLLI: cf536b1a HLR: 
  GMM State: Registered.NORMAL, Routeing Area: 334-07-101-21, Cell ID: 0
  MM State: Ready, RAN Type: GPRS/EDGE via Gb
  SGSN MM Context Statistics:
   Signalling Messages ( In):       18 (0/s 6/m 15/h 0/d)
   Signalling Messages (Out):       23 (0/s 6/m 20/h 0/d)
   User Data  Messages ( In):     1965 (0/s 0/m 1965/h 0/d)
   User Data  Messages (Out):     1732 (0/s 30/m 1732/h 0/d)
   User Data  Bytes    ( In):   265372 (0/s 0/m 265372/h 0/d)
   User Data  Bytes    (Out):   534831 (0/s 2520/m 534831/h 0/d)
   PDP Context Activations  :        2 (0/s 0/m 2/h 0/d)
   SUSPEND Count            :        0 (0/s 0/m 0/h 0/d)
   Paging Packet Switched   :        0 (0/s 0/m 0/h 0/d)
   Paging Circuit Switched  :        0 (0/s 0/m 0/h 0/d)
   Routing Area Update      :        0 (0/s 0/m 0/h 0/d)
  PDP Context IMSI: 334070000000968, SAPI: 3, NSAPI: 5, TI: 0
    APN: internet
    PDP Address: IPv4 172.22.222.23
    GTPv1 Local Control(10.23.100.51 / TEIC: 0x00000001) Data(10.23.100.51 / TEID: 0x00000001)
    GTPv1 Remote Control(10.23.0.4 / TEIC: 0x00000003) Data(10.23.0.4 / TEID: 0x00000003)
 SGSN PDP Context Statistics:
  User Data  Messages ( In):       53 (0/s 0/m 53/h 0/d)
  User Data  Messages (Out):      100 (0/s 30/m 100/h 0/d)
  User Data  Bytes    ( In):     4153 (0/s 0/m 4153/h 0/d)
  User Data  Bytes    (Out):     8094 (0/s 2520/m 8094/h 0/d)
OsmoSGSN# 
OsmoSGSN# 20211206042205719 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206042205739 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206042205757 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206042205757 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)

OsmoSGSN# show sndcp              
State of SNDCP Entities
 TLLI c2abc586 SAPI=3 NSAPI=5:
  Defrag: npdu=6 highest_seg=1 seg_have=0x00000003 tot_len=569

PCU:


OsmoPCU# show ms all 
MS TLLI=cf536b1a, IMSI=334070000000968
[....]

After some short time....

20211206043058316 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043103296 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043107538 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043108318 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043110058 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043110099 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb8718, TLLI=cf536b1a, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043129439 DLLC NOTICE LLME(ffffffff/8f536b1a){UNASSIGNED} LLC RX: unknown TLLI 0x8f536b1a, creating LLME on the fly (gprs_llc.c:542)
20211206043129439 DLLC NOTICE LLME(ffffffff/8f536b1a){UNASSIGNED} LLGM Assign pre (8f536b1a => f3730fb9) (gprs_llc.c:1068)
20211206043129439 DLLC NOTICE LLME(8f536b1a/f3730fb9){ASSIGNED} LLGM Assign post (8f536b1a => f3730fb9) (gprs_llc.c:1114)
20211206043130117 DGPRS INFO SUBSCR(334070000000968) subscriber data is not available (gprs_subscriber.c:820)
20211206043130117 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 04 01 08 33 04 07 00 00 00 69 f8 28 01 01 2a 01 01  (gprs_subscriber.c:213)
20211206043130119 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gprs_subscriber.c:726)
20211206043130119 DGPRS INFO SUBSCR(334070000000968) Will set PDP info, context id = 1, APN = 01 2a  (gprs_subscriber.c:371)
20211206043130119 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 12 01 08 33 04 07 00 00 00 69 f8 28 01 01  (gprs_subscriber.c:213)
20211206043130120 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT (gprs_subscriber.c:726)
20211206043130837 DLLC NOTICE LLME(8f536b1a/f3730fb9){ASSIGNED} LLGM Assign pre (ffffffff => f3730fb9) (gprs_llc.c:1068)
20211206043130837 DLLC NOTICE LLME(ffffffff/f3730fb9){ASSIGNED} LLGM Assign post (ffffffff => f3730fb9) (gprs_llc.c:1114)
20211206043130838 DGPRS INFO PDP(334070000000968/0) <- ACTIVATE PDP CONTEXT ACK (gprs_sm.c:188)
20211206043130838 DLLC NOTICE Sending XID type NULL (8 bytes) request to MS... (gprs_llc.c:354)
20211206043131700 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043131701 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043131701 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043131701 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043131701 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043132559 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043132559 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043132560 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043132560 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043132560 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043132560 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043135217 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043135218 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043135218 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043136757 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043136777 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043137197 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043137238 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eb9858, TLLI=f3730fb9, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043156979 DLLC NOTICE LLME(ffffffff/b3730fb9){UNASSIGNED} LLC RX: unknown TLLI 0xb3730fb9, creating LLME on the fly (gprs_llc.c:542)
20211206043156979 DLLC NOTICE LLME(ffffffff/b3730fb9){UNASSIGNED} LLGM Assign pre (b3730fb9 => d2af1c03) (gprs_llc.c:1068)
20211206043156979 DLLC NOTICE LLME(b3730fb9/d2af1c03){ASSIGNED} LLGM Assign post (b3730fb9 => d2af1c03) (gprs_llc.c:1114)
20211206043157657 DGPRS INFO SUBSCR(334070000000968) subscriber data is not available (gprs_subscriber.c:820)
20211206043157657 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 04 01 08 33 04 07 00 00 00 69 f8 28 01 01 2a 01 01  (gprs_subscriber.c:213)
20211206043157659 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gprs_subscriber.c:726)
20211206043157659 DGPRS INFO SUBSCR(334070000000968) Will set PDP info, context id = 1, APN = 01 2a  (gprs_subscriber.c:371)
20211206043157659 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 12 01 08 33 04 07 00 00 00 69 f8 28 01 01  (gprs_subscriber.c:213)
20211206043157660 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT (gprs_subscriber.c:726)
20211206043157999 DLLC NOTICE LLME(b3730fb9/d2af1c03){ASSIGNED} LLGM Assign pre (ffffffff => d2af1c03) (gprs_llc.c:1068)
20211206043157999 DLLC NOTICE LLME(ffffffff/d2af1c03){ASSIGNED} LLGM Assign post (ffffffff => d2af1c03) (gprs_llc.c:1114)
20211206043158460 DGPRS INFO PDP(334070000000968/0) <- ACTIVATE PDP CONTEXT ACK (gprs_sm.c:188)
20211206043158460 DLLC NOTICE Sending XID type NULL (8 bytes) request to MS... (gprs_llc.c:354)
20211206043159199 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043159199 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043159199 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043159199 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043159200 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043159559 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043159979 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043159979 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043159979 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043159979 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043159980 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043202901 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043202901 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043202901 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043204519 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043204539 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043204557 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043204880 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043204917 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043206038 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043206080 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043206099 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043209020 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043209039 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043209379 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043209836 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043209879 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043210219 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043211138 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043211180 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043211199 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043212158 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043212200 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043213137 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043213999 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043214019 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14eba998, TLLI=d2af1c03, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043233477 DLLC NOTICE LLME(ffffffff/92af1c03){UNASSIGNED} LLC RX: unknown TLLI 0x92af1c03, creating LLME on the fly (gprs_llc.c:542)
20211206043233477 DLLC NOTICE LLME(ffffffff/92af1c03){UNASSIGNED} LLGM Assign pre (92af1c03 => c5d5b15b) (gprs_llc.c:1068)
20211206043233477 DLLC NOTICE LLME(92af1c03/c5d5b15b){ASSIGNED} LLGM Assign post (92af1c03 => c5d5b15b) (gprs_llc.c:1114)
20211206043234017 DGPRS INFO SUBSCR(334070000000968) subscriber data is not available (gprs_subscriber.c:820)
20211206043234017 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 04 01 08 33 04 07 00 00 00 69 f8 28 01 01 2a 01 01  (gprs_subscriber.c:213)
20211206043234024 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gprs_subscriber.c:726)
20211206043234024 DGPRS INFO SUBSCR(334070000000968) Will set PDP info, context id = 1, APN = 01 2a  (gprs_subscriber.c:371)
20211206043234024 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 12 01 08 33 04 07 00 00 00 69 f8 28 01 01  (gprs_subscriber.c:213)
20211206043234025 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT (gprs_subscriber.c:726)
20211206043234359 DLLC NOTICE LLME(92af1c03/c5d5b15b){ASSIGNED} LLGM Assign pre (ffffffff => c5d5b15b) (gprs_llc.c:1068)
20211206043234359 DLLC NOTICE LLME(ffffffff/c5d5b15b){ASSIGNED} LLGM Assign post (ffffffff => c5d5b15b) (gprs_llc.c:1114)
20211206043234718 DGPRS INFO PDP(334070000000968/0) <- ACTIVATE PDP CONTEXT ACK (gprs_sm.c:188)
20211206043234718 DLLC NOTICE Sending XID type NULL (8 bytes) request to MS... (gprs_llc.c:354)
20211206043235337 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ebbad8, TLLI=c5d5b15b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043235337 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ebbad8, TLLI=c5d5b15b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043235337 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ebbad8, TLLI=c5d5b15b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043235338 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ebbad8, TLLI=c5d5b15b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043235338 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ebbad8, TLLI=c5d5b15b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043235338 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ebbad8, TLLI=c5d5b15b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043235339 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ebbad8, TLLI=c5d5b15b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043235757 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ebbad8, TLLI=c5d5b15b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043236158 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ebbad8, TLLI=c5d5b15b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206043236159 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ebbad8, TLLI=c5d5b15b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)

This Appears to be going on for ever....

Actions
Copy link
 #12

Updated by keith over 2 years ago

Oh. And then this happens:

20211206043516753 DGPRS INFO Inactivity timeout for TLLI 0xc2abc586, age 900 (gprs_sgsn.c:1026)
20211206043516753 DGPRS INFO Deleting orphaned LLME, TLLI 0xc2abc586 (gprs_sgsn.c:997)
20211206043516753 DLLC NOTICE LLME(ffffffff/c2abc586){ASSIGNED} LLGM Assign pre (c2abc586 => ffffffff) (gprs_llc.c:1068)
20211206043516753 DLLC NOTICE LLME(00000000/00000000){UNASSIGNED} LLGM Assign post (c2abc586 => ffffffff) (gprs_llc.c:1114)
20211206043533297 DLLC NOTICE LLME(ffffffff/b77f072f){UNASSIGNED} LLC RX: unknown TLLI 0xb77f072f, creating LLME on the fly (gprs_llc.c:542)
20211206043533297 DLLC NOTICE LLME(ffffffff/b77f072f){UNASSIGNED} LLGM Assign pre (b77f072f => f10cbd10) (gprs_llc.c:1068)
20211206043533297 DLLC NOTICE LLME(b77f072f/f10cbd10){ASSIGNED} LLGM Assign post (b77f072f => f10cbd10) (gprs_llc.c:1114)
20211206043533740 DGPRS INFO SUBSCR(334070000000968) subscriber data is not available (gprs_subscriber.c:820)
20211206043533740 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 04 01 08 33 04 07 00 00 00 69 f8 28 01 01 2a 01 01  (gprs_subscriber.c:213)
20211206043533751 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gprs_subscriber.c:726)
20211206043533751 DGPRS INFO SUBSCR(334070000000968) Will set PDP info, context id = 1, APN = 01 2a  (gprs_subscriber.c:371)
20211206043533751 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 12 01 08 33 04 07 00 00 00 69 f8 28 01 01  (gprs_subscriber.c:213)
20211206043533752 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT (gprs_subscriber.c:726)
20211206043534197 DLLC NOTICE LLME(b77f072f/f10cbd10){ASSIGNED} LLGM Assign pre (ffffffff => f10cbd10) (gprs_llc.c:1068)
20211206043534197 DLLC NOTICE LLME(ffffffff/f10cbd10){ASSIGNED} LLGM Assign post (ffffffff => f10cbd10) (gprs_llc.c:1114)
20211206043534580 DGPRS INFO PDP(334070000000968/0) <- ACTIVATE PDP CONTEXT ACK (gprs_sm.c:188)
20211206043534580 DLLC NOTICE Sending XID type NULL (8 bytes) request to MS... (gprs_llc.c:354)
20211206043546753 DGPRS INFO Inactivity timeout for TLLI 0xdf2195e7, age 900 (gprs_sgsn.c:1026)
20211206043546753 DGPRS INFO Deleting orphaned LLME, TLLI 0xdf2195e7 (gprs_sgsn.c:997)
20211206043546753 DLLC NOTICE LLME(ffffffff/df2195e7){ASSIGNED} LLGM Assign pre (df2195e7 => ffffffff) (gprs_llc.c:1068)
20211206043546753 DLLC NOTICE LLME(00000000/00000000){UNASSIGNED} LLGM Assign post (df2195e7 => ffffffff) (gprs_llc.c:1114)
20211206043616753 DGPRS INFO Inactivity timeout for TLLI 0xd7730e5f, age 900 (gprs_sgsn.c:1026)
20211206043616753 DGPRS INFO Deleting orphaned LLME, TLLI 0xd7730e5f (gprs_sgsn.c:997)
20211206043616753 DLLC NOTICE LLME(ffffffff/d7730e5f){ASSIGNED} LLGM Assign pre (d7730e5f => ffffffff) (gprs_llc.c:1068)
20211206043616753 DLLC NOTICE LLME(00000000/00000000){UNASSIGNED} LLGM Assign post (d7730e5f => ffffffff) (gprs_llc.c:1114)

OsmoSGSN# show sndcp 
State of SNDCP Entities
 TLLI f10cbd10 SAPI=3 NSAPI=5:
  Defrag: npdu=300 highest_seg=1 seg_have=0x00000003 tot_len=776
OsmoSGSN# show mm-context all pdp 
MM Context for IMSI 334070000000968, IMEI 357292075895950, P-TMSI f10cbd10
Actions
Copy link
 #13

Updated by keith over 2 years ago

While in the PCU shortly after a RACH:

DLBSSGP <0023> ../../git/src/gprs_bssgp_pcu.c:181 LLC [SGSN -> PCU] = TLLI: 0x89a522e6 IMSI: 334070000000968 len: 9
DTBF <0008> ../../git/src/tbf_dl.cpp:308 There is a new MS object for the same MS: (0xc9a522e6, '334070000000968') -> (0x89a522e6, '')
DRLCMAC <0002> ../../git/src/gprs_ms.c:386 MS(TLLI=0xc9a522e6, IMSI=334070000000968, TA=2, 12/12,) Clearing MS object
DRLCMAC <0002> ../../git/src/gprs_ms.c:150 MS(TLLI=0xffffffff, IMSI=, TA=2, 12/12,) Destroying MS object
DRLCMAC <0002> ../../git/src/gprs_ms.c:475 Modifying MS object, TLLI: 0x89a522e6 confirmed

meanwhile:

20211206045747439 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ec5e98, TLLI=c9a522e6, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206045747439 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ec5e98, TLLI=c9a522e6, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206045748956 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ec5e98, TLLI=c9a522e6, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206045748979 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ec5e98, TLLI=c9a522e6, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)

OsmoSGSN# 20211206045808180 DLLC NOTICE LLME(ffffffff/89a522e6){UNASSIGNED} LLC RX: unknown TLLI 0x89a522e6, creating LLME on the fly (gprs_llc.c:542)
20211206045808180 DLLC NOTICE LLME(ffffffff/89a522e6){UNASSIGNED} LLGM Assign pre (89a522e6 => c240827b) (gprs_llc.c:1068)
20211206045808180 DLLC NOTICE LLME(89a522e6/c240827b){ASSIGNED} LLGM Assign post (89a522e6 => c240827b) (gprs_llc.c:1114)
20211206045808960 DGPRS INFO SUBSCR(334070000000968) subscriber data is not available (gprs_subscriber.c:820)
20211206045808960 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 04 01 08 33 04 07 00 00 00 69 f8 28 01 01 2a 01 01  (gprs_subscriber.c:213)
20211206045808963 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_INSERT_DATA_REQUEST (gprs_subscriber.c:726)
20211206045808963 DGPRS INFO SUBSCR(334070000000968) Will set PDP info, context id = 1, APN = 01 2a  (gprs_subscriber.c:371)
20211206045808963 DGPRS INFO SUBSCR(334070000000968) Sending GSUP, will send: 12 01 08 33 04 07 00 00 00 69 f8 28 01 01  (gprs_subscriber.c:213)
20211206045808963 DGPRS INFO SUBSCR(334070000000968) Received GSUP message OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT (gprs_subscriber.c:726)
20211206045809298 DLLC NOTICE LLME(89a522e6/c240827b){ASSIGNED} LLGM Assign pre (ffffffff => c240827b) (gprs_llc.c:1068)
20211206045809298 DLLC NOTICE LLME(ffffffff/c240827b){ASSIGNED} LLGM Assign post (ffffffff => c240827b) (gprs_llc.c:1114)
20211206045813239 DGPRS INFO PDP(334070000000968/0) <- ACTIVATE PDP CONTEXT ACK (gprs_sm.c:188)
20211206045813239 DLLC NOTICE Sending XID type NULL (8 bytes) request to MS... (gprs_llc.c:354)
20211206045814139 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ec6fd8, TLLI=c240827b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)
20211206045814140 DSNDCP ERROR Message for non-existing SNDCP Entity (lle=0x55bb14ec6fd8, TLLI=c240827b, SAPI=3, NSAPI=5) (gprs_sndcp.c:798)

I do not understand this.

Actions
Copy link
 #14

Updated by laforge over 2 years ago

  • Assignee changed from 118 to osmith
Actions
Copy link
 #15

Updated by osmith over 2 years ago

  • Status changed from New to In Progress
  • % Done changed from 0 to 90

laforge wrote in #note-6:

so the SNE is free'd via sndcp_sm_deactivate_ind(), which happens at PDP context termination.

the LLME with all its LLEs is free'd via gprs_llgmm_assign(..., new_tlli=TLLI_UNASSIGNED)

maybe there are other situations in whihc the LLME is freed, where the SNE is not free'd before? As all the gprs_llgmm_assign() calls originate from gprs_gmm, it may be in the path for GGSN side PDP context termination from sgsn_libgtp.c -> sndcp_sm_deactivate_ind() where the SNDCP entity is not free'd.

There are a whole lot of code paths, that potentially lead to LLME getting freed:

- gprs_llc.c:llme_free()
-- gprs_llc.c:gprs_llgmm_assign(), old_tlli != UNASSIGNED && new_tlli == UNASSIGNED
--- gprs_gmm.c:gsm48_rx_gmm_att_req()
--- gprs_gmm.c:gsm48_rx_gmm_att_compl()
--- gprs_gmm.c:gsm48_rx_gmm_ra_upd_req()
--- gprs_gmm.c:gsm48_rx_gmm_ra_upd_compl()
--- // gprs_gmm.c:gsm48_rx_gmm_ptmsi_reall_compl()
--- gprs_llc.c:gprs_llgmm_unassign()
---- gprs_gmm.c:gsm48_rx_gmm_att_req()
---- gprs_gmm.c:gsm48_rx_gmm_ra_upd_req()
---- gprs_gmm.c:gsm0408_rcv_gmm()
---- gprs_mm_state_gb_fsm.c:st_mm_idle_on_enter()
---- gprs_sgsn.c:sgsn_mm_ctx_cleanup_free()
---- gprs_sgsn.c:sgsn_llme_cleanup_free()

I'm not very familiar with the OsmoSGSN codebase, but it seems that the most feasible way to fix this is, right before freeing LLME, it should also free all SNE pointing to any of the LLME's LLEs.

Prepared a patch: https://gerrit.osmocom.org/c/osmo-sgsn/+/26462

I've verified that the existing ttcn3, regression and vty tests work the same with this patch, but did not do further testing. It would be good if somebody who is more familiar with the code has a look.

Actions
Copy link
 #16

Updated by osmith over 2 years ago

  • Status changed from In Progress to Resolved
  • % Done changed from 90 to 100
Actions
Copy link
 #17

Updated by keith over 2 years ago

It's my fault for hijacking this issue to describe another one, but none of what I described in notes 11 to 13 has been dealt with here.
Opening #5349

Actions
Copy link

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)