Project

General

Profile

Actions

Bug #4959

closed

Problems on NS-VC recovery

Added by laforge about 3 years ago. Updated about 3 years ago.

Status:
Resolved
Priority:
High
Assignee:
Target version:
-
Start date:
01/19/2021
Due date:
% Done:

100%

Spec Reference:

Description

I have a test that first brings up all NS-VC / BVC as usual in our GBProxy_Tests.ttcn f_init().

It then
  • disables NSVC 101
  • waits for 60s
  • re-enables NSVC 101
  • waits for another 30s

In the osmo-gbproxy log we can see about 50s after the NS-VC is disabled:

Tue Jan 19 18:32:33 2021 DLNS gprs_ns2_vc_fsm.c:209 GPRS-NS2-VC(UDP-NSE00101-remote-127_0_0_10:7777)[0x612000002aa0]{UNBLOCKED}: State change to ALIVE (T0, 3s)
Tue Jan 19 18:32:33 2021 DGPRS gb_proxy.c:1348 NS-NSE 101 became unavailable

Furthermore, we can see that after the NS-VC is re-enabled in the tester:

Tue Jan 19 18:33:03 2021 DLNS gprs_ns2_vc_fsm.c:353 GPRS-NS2-VC(UDP-NSE00101-remote-127_0_0_10:7777)[0x612000002aa0]{ALIVE}: State change to UNBLOCKED (no timeout)
Tue Jan 19 18:33:03 2021 DGPRS gb_proxy.c:1314 NS-NSE 101 became available

so great, the unavailability / availability is detected correctly by NS2, and osmo-gproxy also understands those events. Furthermore, this triggers a BVC-RESET of the signaling BVC, as expected:

ue Jan 19 18:33:03 2021 DLBSSGP gb_proxy.c:1320 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{UNBLOCKED}: Received Event REQ-RESET
Tue Jan 19 18:33:03 2021 DLBSSGP bssgp_bvc_fsm.c:173 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{UNBLOCKED}: Tx BSSGP BVC-RESET
Tue Jan 19 18:33:03 2021 DLBSSGP bssgp_bvc_fsm.c:514 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{UNBLOCKED}: State change to WAIT_RESET_ACK (no timeout)
Tue Jan 19 18:33:03 2021 DGPRS gb_proxy.c:1351 NS: Unknown NS-STATUS.ind cause=NSVC recovery from NS
Tue Jan 19 18:33:03 2021 DLNS gprs_ns2_vc_fsm.c:707 GPRS-NS2-VC(UDP-NSE00101-remote-127_0_0_10:7777)[0x612000002aa0]{UNBLOCKED}: Received Event UNITDATA
Tue Jan 19 18:33:03 2021 DGPRS gb_proxy.c:1087 NSE(00101/SGSN)-BVC(00000/??) Rx BVC-RESET-ACK
Tue Jan 19 18:33:03 2021 DLBSSGP gb_proxy.c:1127 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{WAIT_RESET_ACK}: Received Event RX-BVC-RESET-ACK
Tue Jan 19 18:33:03 2021 DLBSSGP bssgp_bvc_fsm.c:264 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{WAIT_RESET_ACK}: Updating features: Advertised 0x0000, Received 0x0000, Negotiated 0x0000
Tue Jan 19 18:33:03 2021 DLBSSGP bssgp_bvc_fsm.c:392 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{WAIT_RESET_ACK}: State change to UNBLOCKED (no timeout)

However, now it gets interesting, as a second outage is detected where there is none:

Tue Jan 19 18:33:06 2021 DLNS gprs_ns2_vc_fsm.c:209 GPRS-NS2-VC(UDP-NSE00101-remote-127_0_0_10:7777)[0x612000002aa0]{UNBLOCKED}: State change to ALIVE (T0, 3s)
Tue Jan 19 18:33:06 2021 DLNS gprs_ns2_message.c:381 NSEI=101 Tx NS ALIVE (NSVCI=0)
Tue Jan 19 18:33:06 2021 DGPRS gb_proxy.c:1348 NS-NSE 101 became unavailable
Tue Jan 19 18:33:06 2021 DLNS gprs_ns2_vc_fsm.c:703 GPRS-NS2-VC(UDP-NSE00101-remote-127_0_0_10:7777)[0x612000002aa0]{ALIVE}: Received Event ALIVE_ACK
Tue Jan 19 18:33:06 2021 DLNS gprs_ns2_vc_fsm.c:353 GPRS-NS2-VC(UDP-NSE00101-remote-127_0_0_10:7777)[0x612000002aa0]{ALIVE}: State change to UNBLOCKED (no timeout)
Tue Jan 19 18:33:06 2021 DGPRS gb_proxy.c:1314 NS-NSE 101 became available

which in turn of course generates another BVC-RESET:

Tue Jan 19 18:33:06 2021 DLBSSGP gb_proxy.c:1320 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{UNBLOCKED}: Received Event REQ-RESET
Tue Jan 19 18:33:06 2021 DLBSSGP bssgp_bvc_fsm.c:173 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{UNBLOCKED}: Tx BSSGP BVC-RESET
Tue Jan 19 18:33:06 2021 DLBSSGP bssgp_bvc_fsm.c:514 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{UNBLOCKED}: State change to WAIT_RESET_ACK (no timeout)
Tue Jan 19 18:33:06 2021 DGPRS gb_proxy.c:1351 NS: Unknown NS-STATUS.ind cause=NSVC recovery from NS
Tue Jan 19 18:33:06 2021 DLNS gprs_ns2_vc_fsm.c:707 GPRS-NS2-VC(UDP-NSE00101-remote-127_0_0_10:7777)[0x612000002aa0]{UNBLOCKED}: Received Event UNITDATA
Tue Jan 19 18:33:06 2021 DGPRS gb_proxy.c:1087 NSE(00101/SGSN)-BVC(00000/??) Rx BVC-RESET-ACK
Tue Jan 19 18:33:06 2021 DLBSSGP gb_proxy.c:1127 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{WAIT_RESET_ACK}: Received Event RX-BVC-RESET-ACK
Tue Jan 19 18:33:06 2021 DLBSSGP bssgp_bvc_fsm.c:264 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{WAIT_RESET_ACK}: Updating features: Advertised 0x0000, Received 0x0000, Negotiated 0x0000
Tue Jan 19 18:33:06 2021 DLBSSGP bssgp_bvc_fsm.c:392 BSSGP-BVC(NSE00101-BVC00000)[0x612000001120]{WAIT_RESET_ACK}: State change to UNBLOCKED (no timeout)

where does that second NS-VC unavailable come from? Line 209 of gprs_ns2_vc_fsm.c points to a timeout. However, I don't understand why? Maybe the timer state is not properly cleared on recovery?


Related issues

Related to osmo-gbproxy - Feature #4521: gbproxy: Redundancy between NS-VCs (SGSN Side)Newlaforge05/01/2020

Actions
Actions #1

Updated by laforge about 3 years ago

Testcase TC_nsvc_loss is available in osmo-ttcn3-hacks.git branch laforge/os4959

Actions #2

Updated by laforge about 3 years ago

  • Related to Feature #4521: gbproxy: Redundancy between NS-VCs (SGSN Side) added
Actions #3

Updated by laforge about 3 years ago

ping?

Actions #4

Updated by lynxis about 3 years ago

  • Status changed from New to Feedback
  • % Done changed from 0 to 90
Actions #5

Updated by lynxis about 3 years ago

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

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)