Project

General

Profile

Bug #4959

Problems on NS-VC recovery

Added by laforge about 1 month ago. Updated 12 days 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)New05/01/2020

Associated revisions

Revision 2f8f7b62 (diff)
Added by lynxis 23 days ago

gprs_ns2_vc_fsm: reset ALIVE N counter when restarting the test procedure.

Otherwise a NS-VC would flap between ALIVE and UNBLOCKED state.

Related: OS#4959
Change-Id: Id98629bd65f92103e0e571ec388c58b02cb2ccb5

History

#1 Updated by laforge about 1 month ago

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

#2 Updated by laforge about 1 month ago

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

#3 Updated by laforge 26 days ago

ping?

#4 Updated by lynxis 23 days ago

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

#5 Updated by lynxis 12 days ago

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

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)