Project

General

Profile

Bug #4792

TLV parsing problem during SNS-ADD / SNS-DEL

Added by laforge 6 months ago. Updated 6 months ago.

Status:
Resolved
Priority:
Urgent
Assignee:
Category:
libosmogb
Target version:
-
Start date:
10/09/2020
Due date:
% Done:

100%

Spec Reference:

Description

While executing PCU_Tests_SNS.TC_sns_add or TC_sns_del, we are seeing the following error message on stderr of osmo-pcu (using gprs_ns2):

Error during TLV Parse in [L2]> 0d 04 82 04 d2 17 05 88 7f 00 00 01 59 da 00 01  (gprs_ns2.c:881)
Error during TLV Parse in [L2]> 11 04 82 04 d2 18 05 88 7f 00 00 01 59 d9 00 01  (gprs_ns2.c:881)
Error during TLV Parse in [L2]> 0e 04 82 04 d2 19 05 88 7f 00 00 01 59 d9 00 c8  (gprs_ns2.c:881)

First of all, the question is whether those errors are errors in NS2 or erors in our TTCN3 tests.

Secondly, why are those TLV parsing errors written to stderr without any prefix? There's no subssystem/level/... printed in frot. Look at this example:

20201009144947177 DLNS DEBUG GPRS-NS2-VC[0x5634298c0e40]{UNBLOCKED}: Received Event UNITDATA (gprs_ns2_vc_fsm.c:647)
20201009144947177 DBSSGP DEBUG rx BVCI_PTP=1234 gprs_bssgp_rx_ptp (gprs_bssgp_pcu.cpp:483)
20201009144947177 DBSSGP DEBUG Rx BSSGP BVCI=1234 (PTP) FLOW-CONTROL-BVC-ACK (gprs_bssgp_pcu.cpp:279)
Error during TLV Parse in [L2]> 0d 04 82 04 d2 17 05 88 7f 00 00 01 59 da 00 01  (gprs_ns2.c:881)
20201009144957174 DBSSGP DEBUG Sending flow control info on BVCI 1234 (gprs_bssgp_pcu.cpp:917)
20201009144957175 DBSSGP DEBUG Computed BVC leak rate = 20000, num_pdch = 8, cs = CS-4 (gprs_bssgp_pcu.cpp:825)

sns-add.png View sns-add.png 51.3 KB laforge, 10/09/2020 01:28 PM
TC_sns_add.pcap TC_sns_add.pcap 1.32 KB laforge, 10/09/2020 01:30 PM
4306

Associated revisions

Revision c068d860 (diff)
Added by lynxis 6 months ago

gprs_ns2: fix SNS_ADD for IPv4

The remote must be initialized because the osmo_sockaddr_cmp is using a memcmp() and might fail
on spare bytes in the struct. The same was already done for IPv6.

Related: OS#4792
Change-Id: Iefeef969bb2b5ae4d5db6a6358293ef9eeda858a

Revision bb0a53ba (diff)
Added by lynxis 6 months ago

gprs_ns2: fix empty prefix in TLV Parse error

Those messages were printed without any prefix because
LOGPC was used. LOGPC means continue a log line.
This must happened while copying this part of code over
from ns1 where has been a LOGP in this function.

Related: OS#4792
Change-Id: I2672ea0e34d19ea6172cb3458b8ff98d9700b2d0

Revision 8ebc1acb (diff)
Added by lynxis 6 months ago

gprs_ns2: Partial revert 48f63867 allow to create NS_ALIVE NSVC

NS_ALIVE can't create new NS-VC. Those NS-VC can be only created
by SNS or by vty.
Also fixes a crash because the TLV parser tried to retrieve NSEI TLV
which doesn't exist on NS_ALIVE PDUs.

Related: OS#4792
Change-Id: I16b9d7b2eb7544a83ce871d894887c4b30605b34

History

#1 Updated by laforge 6 months ago

4306

The SNS-ADD PDU is in my opinion correct. Wireshark also has no trouble decoding it:

I'm attaching a related pcap file for reference.

I'm a bit surprised this was not detected during local testing before submitting the patch for merge, given that we do have multiple existing test cases that trigger the problem.

#2 Updated by laforge 6 months ago

See https://gerrit.osmocom.org/c/libosmocore/+/20509 - this code could never have been tested even once.

Even with the patch applied, there's now a segfault:

20201009153944364 DLNS DEBUG NSEI=1234 Rx SNS PDU type SNS-ADD (gprs_ns2_sns.c:1370)
20201009153944364 DLNS DEBUG GPRS-NS2-SNS-BSS[0x555555643c30]{CONFIGURED}: Received Event ADD (gprs_ns2_sns.c:1393)
20201009153944364 DLGLOBAL DEBUG validating counter group 0x7ffff7f87780(ns:nsvc) with 12 counters (rate_ctr.c:87)
20201009153944364 DLNS DEBUG GPRS-NS2-VC[0x5555556f4690]{UNCONFIGURED}: Allocated (fsm.c:461)
20201009153944364 DLNS DEBUG GPRS-NS2-VC[0x5555556f4690]{UNCONFIGURED}: Received Event START (gprs_ns2_vc_fsm.c:595)
20201009153944364 DLNS DEBUG GPRS-NS2-VC[0x5555556f4690]{UNCONFIGURED}: state_chg to ALIVE (gprs_ns2_vc_fsm.c:223)
20201009153944364 DLNS DEBUG NSEI=1234 Tx NS ALIVE (NSVCI=0) (gprs_ns2_message.c:372)
20201009153944367 DLNS INFO Ignoring NS ALIVE ACK from newconnection for non-existing NS-VC (gprs_ns2.c:640)

Program received signal SIGSEGV, Segmentation fault.
ns2_create_vc (bind=bind@entry=0x5555556eff90, msg=msg@entry=0x5555556f2e20, logname=logname@entry=0x7ffff7f7f167 "newconnection", 
    reject=reject@entry=0x7fffffffdd68, success=success@entry=0x7fffffffdd60) at gprs_ns2.c:698
698             nse = gprs_ns2_nse_by_nsei(bind->nsi, nsei);
(gdb) bt full
#0  ns2_create_vc (bind=bind@entry=0x5555556eff90, msg=msg@entry=0x5555556f2e20, logname=logname@entry=0x7ffff7f7f167 "newconnection", 
    reject=reject@entry=0x7fffffffdd68, success=success@entry=0x7fffffffdd60) at gprs_ns2.c:698
        nsh = <optimized out>
        tp = {lv = {{len = 0, val = 0x0} <repeats 256 times>}}
        nsvc = <optimized out>
        nse = <optimized out>
        nsvci = <optimized out>
        nsei = <error reading variable nsei (Cannot access memory at address 0x0)>
        rc = <optimized out>
#1  0x00007ffff7f710c4 in handle_nsip_read (bfd=0x55555565e680) at gprs_ns2_udp.c:223
        nsvc = 0x0
        msg = 0x5555556f2e20
        rc = <optimized out>
        error = <optimized out>
        bind = 0x5555556eff90
        saddr = {u = {sa = {sa_family = 2, sa_data = "Y\332\177\000\000\001\000\000\000\000\000\000\000"}, sas = {ss_family = 2, 
              __ss_padding = "Y\332\177\000\000\001\000\000\000\000\000\000\000\000\036\000\000\000\000\000\000\000(>\347\367\377\177\000\000 h\200_\000\000\000\000\345\377\004\000\000\000\000\000\350\354^UUU\000\000\340\335\377\377\377\177\000\000\001\000\000\000\000\000\000\000i\b\375\367\377\177\000\000 h\200_\000\000\000\000i\b\375\367\377\177\000\000h\367\223\367\377\177\000\000\300\336\377\377\377\177\000\000\000\336\377\377\377\177\000", 
              __ss_align = 140737352515625}, sin = {sin_family = 2, sin_port = 55897, sin_addr = {s_addr = 16777343}, 
              sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 55897, sin6_flowinfo = 16777343, sin6_addr = {__in6_u = {
                  __u6_addr8 = "\000\000\000\000\000\000\000\000\036\000\000\000\000\000\000", __u6_addr16 = {0, 0, 0, 0, 30, 0, 0, 0}, __u6_addr32 = {0, 0, 
                    30, 0}}}, sin6_scope_id = 4159127080}}}
        reject = 0x10
        rc = <optimized out>
        error = <optimized out>
        bind = <optimized out>
        saddr = <optimized out>
        nsvc = <optimized out>
        msg = <optimized out>
        reject = <optimized out>

I'm stopping here. please fix.

#3 Updated by lynxis 6 months ago

  • Status changed from New to In Progress

I've found the crash and reverted the commit.
The crash was only a side track. The root problem is the NS2 code can't find the correct NS-VC for the just added NS-VC.

#4 Updated by lynxis 6 months ago

  • Status changed from In Progress to Feedback
  • % Done changed from 0 to 100

#5 Updated by lynxis 6 months ago

https://gerrit.osmocom.org/c/libosmocore/+/20568 gprs_ns2: fix empty prefix in TLV Parse error

#6 Updated by laforge 6 months ago

  • Status changed from Feedback to Resolved

all three patches merged, marking as resolved.

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)