Project

General

Profile

Bug #4245

osmo-sgsn hitting assert during osmo-gsm-tester ping.py test

Added by pespin about 1 month ago. Updated 16 days ago.

Status:
Resolved
Priority:
High
Assignee:
Category:
Gb interface
Target version:
-
Start date:
10/31/2019
Due date:
% Done:

100%

Spec Reference:

Description

20191030225436564 DNS <000f> gprs_ns.c:321 NSVCI=65535 Creating NS-VC
20191030225436564 DNS <000f> gprs_ns.c:332 NSEI 0 (NS-VCI=65535) setting state [DEAD,UNBLOCKED,UNRESET] -> [DEAD,BLOCKED,UNRESET]
20191030225436564 DLGLOBAL <0020> rate_ctr.c:88 validating counter group 0x7feea7871240(ns:nsvc) with 12 counters
20191030225436565 DNS <000f> gprs_ns.c:1698 Creating NS-VC for BSS at 10.42.42.114:23020
20191030225436565 DNS <000f> gprs_ns.c:1248 NSVCI=65535(invalid) Rx NS RESET (NSEI=358, NSVCI=358, cause=O&M intervention)
20191030225436565 DNS <000f> gprs_ns.c:1297 NSEI 0 (NS-VCI=65535) setting state [DEAD,BLOCKED,UNRESET] -> [ALIVE,BLOCKED,UNRESET]
20191030225436565 DNS <000f> gprs_ns.c:865 NSEI=358 Tx NS RESET ACK (NSVCI=358)
20191030225436565 DNS <000f> gprs_ns.c:717 NSEI=358 Tx NS ALIVE (NSVCI=358)
20191030225436565 DNS <000f> gprs_ns.c:756 NSEI=358 Starting timer in mode tns-test (30 seconds)
20191030225436568 DNS <000f> gprs_ns.c:730 NSEI=358 Tx NS ALIVE_ACK (NSVCI=358)
20191030225436569 DNS <000f> gprs_ns.c:1764 NSEI 358 (NS-VCI=358) setting state [ALIVE,BLOCKED,UNRESET] -> [ALIVE,BLOCKED,UNRESET]
20191030225436569 DNS <000f> gprs_ns.c:756 NSEI=358 Starting timer in mode tns-test (30 seconds)
20191030225436578 DNS <000f> gprs_ns.c:1791 NSEI=358 Rx NS UNBLOCK
20191030225436578 DNS <000f> gprs_ns.c:1792 NSEI 358 (NS-VCI=358) setting state [ALIVE,BLOCKED,UNRESET] -> [ALIVE,UNBLOCKED,UNRESET]
20191030225436588 DBSSGP <0010> gprs_bssgp.c:270 BSSGP BVCI=0 Rx RESET cause=O&M intervention
20191030225436588 DLGLOBAL <0020> rate_ctr.c:88 validating counter group 0x7feea78715e0(bssgp:bss_ctx) with 7 counters
20191030225436590 DBSSGP <0010> gprs_bssgp.c:270 BSSGP BVCI=358 Rx RESET cause=O&M intervention
20191030225436590 DLGLOBAL <0020> rate_ctr.c:88 validating counter group 0x7feea78715e0(bssgp:bss_ctx) with 7 counters
20191030225436591 DBSSGP <0010> gprs_bssgp.c:292 Cell 901-70-357-102 CI 357 on BVCI 358
20191030225436593 DBSSGP <0010> gprs_bssgp.c:364 BSSGP BVCI=358 Rx BVC-UNBLOCK
20191030225436595 DBSSGP <0010> gprs_bssgp.c:812 BSSGP BVCI=358 Rx Flow Control BVC
20191030225436595 DBSSGP <0010> gprs_bssgp.c:845 BSS instructs us to MS default bucket leak rate != 0, restarting DL GPRS!
20191030225437582 DLINP <0022> stream.c:666 [CONNECTING] cli_timer_cb(): reconnecting.
20191030225437583 DLINP <0022> stream.c:183 [      NONE] osmo_stream_cli_reconnect(): retrying in 5 seconds...
20191030225442584 DLINP <0022> stream.c:666 [CONNECTING] cli_timer_cb(): reconnecting.
20191030225442585 DLINP <0022> stream.c:183 [      NONE] osmo_stream_cli_reconnect(): retrying in 5 seconds...
20191030225446596 DBSSGP <0010> gprs_bssgp.c:812 BSSGP BVCI=358 Rx Flow Control BVC
20191030225447500 DGPRS <000e> gprs_sgsn.c:1013 Checking for inactive LLMEs, time = 192373
20191030225447573 DLGSUP <002a> gsup_client.c:237 GSUP ping callback (connected, got PONG)
20191030225447573 DLGSUP <002a> gsup_client.c:257 GSUP sending PING
20191030225447573 DLINP <0022> input/ipa.c:139 10.42.42.2:4222 connected write
20191030225447573 DLINP <0022> input/ipa.c:89 10.42.42.2:4222 sending data
20191030225447574 DLINP <0022> input/ipa.c:139 10.42.42.2:4222 connected write
20191030225447574 DLINP <0022> input/ipa.c:89 10.42.42.2:4222 sending data
20191030225447574 DLINP <0022> input/ipa.c:135 10.42.42.2:4222 connected read
20191030225447574 DLINP <0022> input/ipa.c:56 10.42.42.2:4222 message received
20191030225447575 DLMI <0024> ipa.c:509 PONG!
20191030225447575 DLGSUP <002a> gsup_client.c:194 GSUP receiving PONG
20191030225447585 DLINP <0022> stream.c:666 [CONNECTING] cli_timer_cb(): reconnecting.
20191030225447585 DLINP <0022> stream.c:183 [      NONE] osmo_stream_cli_reconnect(): retrying in 5 seconds...
20191030225452586 DLINP <0022> stream.c:666 [CONNECTING] cli_timer_cb(): reconnecting.
20191030225452587 DLINP <0022> stream.c:183 [      NONE] osmo_stream_cli_reconnect(): retrying in 5 seconds...
20191030225456596 DBSSGP <0010> gprs_bssgp.c:812 BSSGP BVCI=358 Rx Flow Control BVC
20191030225457587 DLINP <0022> stream.c:666 [CONNECTING] cli_timer_cb(): reconnecting.
20191030225457588 DLINP <0022> stream.c:183 [      NONE] osmo_stream_cli_reconnect(): retrying in 5 seconds...
20191030225502588 DLINP <0022> stream.c:666 [CONNECTING] cli_timer_cb(): reconnecting.
20191030225502589 DLINP <0022> stream.c:183 [      NONE] osmo_stream_cli_reconnect(): retrying in 5 seconds...
20191030225504251 DBSSGP <0010> gprs_bssgp.c:396 BSSGP TLLI=0xbffe776d Rx UPLINK-UNITDATA
20191030225504251 DLLC <0011> gprs_llc.c:532 LLC RX: unknown TLLI 0xbffe776d, creating LLME on the fly
20191030225504251 DLLC <0011> gprs_llc_parse.c:81 LLC SAPI=1 C   U GEA0 IOV-UI=0x000000 FCS=0x62c662 CMD=UI DATA
20191030225504251 DMM <0002> gprs_gmm.c:1117 MM(---/ffffffff) -> GMM ATTACH REQUEST MI(4294866797) type="GPRS attach" 
20191030225504252 DLGLOBAL <0020> rate_ctr.c:88 validating counter group 0x55f0bd820f40(sgsn:mmctx) with 11 counters
20191030225504252 DMM <0002> fsm.c:461 GMM(gmm_fsm)[0x6120000087a0]{Deregistered}: Allocated
20191030225504252 DMM <0002> fsm.c:461 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000008620]{Init}: Allocated
20191030225504252 DMM <0002> fsm.c:461 MM_STATE_Gb[0x6120000084a0]{Idle}: Allocated
20191030225504252 DMM <0002> fsm.c:461 MM_STATE_Iu[0x612000008320]{Detached}: Allocated
20191030225504252 DMM <0002> gprs_sgsn.c:300 MM(/00000000) Allocated with GEA0 cipher.
20191030225504252 DMM <0002> gprs_gmm.c:1099 GMM(gmm_fsm)[0x6120000087a0]{Deregistered}: Received Event E_GMM_COMMON_PROC_INIT_REQ
20191030225504253 DMM <0002> gprs_gmm_fsm.c:25 GMM(gmm_fsm)[0x6120000087a0]{Deregistered}: state_chg to CommonProcedureInitiated
20191030225504253 DMM <0002> gprs_gmm.c:1270 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000008620]{Init}: Received Event E_ATTACH_REQ_RECV
20191030225504253 DMM <0002> gprs_gmm_attach.c:50 GMM_ATTACH_REQ_FSM(gb_gmm_req)[0x612000008620]{Init}: state_chg to CheckIdentity
20191030225504253 DMM <0002> gprs_gmm.c:409 MM(/e9867183) <- GPRS IDENTITY REQUEST: mi_type=IMEI
20191030225505454 DBSSGP <0010> gprs_bssgp.c:439 BSSGP BVCI=0 TLLI=0xbffe776d Rx SUSPEND
20191030225505454 DMM <0002> gprs_gmm.c:2143 SUSPEND request for unknown TLLI=bffe776d
20191030225505456 DBSSGP <0010> gprs_bssgp.c:556 BSSGP BVCI=0 Rx BVC STATUS, cause=Unknown BVCI
20191030225505456 DBSSGP <0010> gprs_bssgp.c:563 BSSGP BVCI=0 Rx STATUS cause=Unknown BVCI missing conditional BVCI IE
20191030225506570 DNS <000f> gprs_ns.c:784 NSEI=358 Timer expired in mode tns-test (30 seconds)
20191030225506570 DNS <000f> gprs_ns.c:717 NSEI=358 Tx NS ALIVE (NSVCI=358)
20191030225506570 DNS <000f> gprs_ns.c:756 NSEI=358 Starting timer in mode tns-alive (3 seconds)
20191030225506571 DNS <000f> gprs_ns.c:1764 NSEI 358 (NS-VCI=358) setting state [ALIVE,UNBLOCKED,UNRESET] -> [ALIVE,UNBLOCKED,UNRESET]
20191030225506571 DNS <000f> gprs_ns.c:756 NSEI=358 Starting timer in mode tns-test (30 seconds)
20191030225506579 DNS <000f> gprs_ns.c:730 NSEI=358 Tx NS ALIVE_ACK (NSVCI=358)
20191030225506591 DBSSGP <0010> gprs_bssgp.c:396 BSSGP TLLI=0xbffe776d Rx UPLINK-UNITDATA
20191030225506591 DLLC <0011> gprs_llc_parse.c:81 LLC SAPI=1 C   U GEA0 IOV-UI=0x000000 FCS=0x210d46 CMD=UI DATA
20191030225506591 DMM <0002> gprs_gb.c:40 MM_STATE_Gb(3221124973)[0x6120000084a0]{Idle}: Received Event E_MM_PDU_RECEPTION
20191030225506592 DMM <0002> gprs_gmm.c:1531 MM(/e9867183) -> GMM RA UPDATE REQUEST type="RA updating" 
20191030225506592 DMM <0002> gprs_gmm.c:1615 MM(/e9867183) The MM context cannot be used, RA: 901-70-357-102
Assert failed mmctx->gb.llme == NULL gprs_gmm.c:1620
talloc report on 'vty' (total 158164 bytes in 8394 blocks)
    Configure SCCP timer values, see ITU-T Q.714
Waiting for connection confirm message, 1 to 2 minutes (default: 60)
Send keep-alive: on an idle connection, delay before sending an Idle Timer message, 5 to 10 minutes (default: 420)
Receive keep-alive: on an idle connection, delay until considering a connection as stale, 11 to 21 minutes (default: 900)
Waiting for release complete message, 10 to 20 seconds (default: 10)
Waiting for release complete message; or to repeat sending released message after the initial expiry, 10 to 20 seconds (default: 10)
Waiting for release complete message; or to release connection resources, freeze the LRN and alert a maintenance function after the initial expiry, extending to 1 minute (default: 60)
ping.tar.gz ping.tar.gz 109 KB pespin, 10/31/2019 03:11 PM

Related issues

Related to OsmoPCU - Bug #4111: BSSGP SUSPEND ACK with unknown BVCI=0Resolved07/17/2019

Related to OsmoSGSN - Bug #3957: ABORT from gprs_sndcp_comp_free()Feedback04/24/2019

History

#1 Updated by pespin about 1 month ago

  • Priority changed from Normal to High

#2 Updated by pespin about 1 month ago

  • Related to Bug #4111: BSSGP SUSPEND ACK with unknown BVCI=0 added

#3 Updated by pespin about 1 month ago

  • Related to Bug #3957: ABORT from gprs_sndcp_comp_free() added

#4 Updated by pespin about 1 month ago

  • Status changed from New to Feedback
  • % Done changed from 0 to 90

Should be fixed by:
https://gerrit.osmocom.org/c/osmo-sgsn/+/16015 gmm: Fix assertion hit during RA UPD REQ before completting gmm attach

And TTCN3 test triggering the issue:
https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/16016 sgsn: Introduce test TC_attach_req_id_req_ra_update

#5 Updated by pespin 21 days ago

I added following commit: https://gerrit.osmocom.org/c/osmo-sgsn/+/16151
since TTCN3 test I added to reproduce the issue showed different (new PTMSI based) TLLI being used during XID reset message.

#6 Updated by pespin 16 days ago

  • Status changed from Feedback to Resolved
  • % Done changed from 90 to 100

Merged, closing.

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)