Bug #4792
closedTLV parsing problem during SNS-ADD / SNS-DEL
100%
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)
Files
Updated by laforge over 3 years ago
- File sns-add.png sns-add.png added
- File TC_sns_add.pcap TC_sns_add.pcap added
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.
Updated by laforge over 3 years 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.
Updated by lynxis over 3 years 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.
Updated by lynxis over 3 years ago
- Status changed from In Progress to Feedback
- % Done changed from 0 to 100
Updated by lynxis over 3 years ago
https://gerrit.osmocom.org/c/libosmocore/+/20568 gprs_ns2: fix empty prefix in TLV Parse error
Updated by laforge over 3 years ago
- Status changed from Feedback to Resolved
all three patches merged, marking as resolved.