Cellular Network Infrastructure

I downloaded a PCAP collected during a successful test and compared it with the failing one:

Successful¶

  565   3.147020 172.18.2.203 → 172.18.2.20  RSL 91 ESTablish INDication (DTAP) (GCC) 
  582   3.147277  172.18.2.20 → 172.18.2.203 GSMTAP 197 Received SCCP User Primitive (N-CONNECT.request) 
  583   3.147288  172.18.2.20 → 172.18.2.203 GSMTAP 195 SCCP-SCOC(15)[0x55f15dd6d7d0]{IDLE}: Allocated 
  584   3.147296  172.18.2.20 → 172.18.2.203 GSMTAP 214 SCCP-SCOC(15)[0x55f15dd6d7d0]{IDLE}: Received Event N-CONNECT.req 
  599   3.147449  172.18.2.20 → 172.18.2.203 GSMTAP 228 SCCP-SCOC(15)[0x55f15dd6d7d0]{IDLE}: State change to CONN_PEND_OUT (no timeout) 
  606   3.150207 172.18.2.203 → 172.18.2.20  RSL 82 CONNection FAILure
  616   3.150388  172.18.2.20 → 172.18.2.203 GSMTAP 188 Received CO:COAK for local reference 15 
  617   3.150395  172.18.2.20 → 172.18.2.203 GSMTAP 234 SCCP-SCOC(15)[0x55f15dd6d7d0]{CONN_PEND_OUT}: Received Event RCOC-CONNECT_CONFIRM.ind 
  618   3.150404  172.18.2.20 → 172.18.2.203 GSMTAP 230 SCCP-SCOC(15)[0x55f15dd6d7d0]{CONN_PEND_OUT}: State change to ACTIVE (no timeout) 
  619   3.150413  172.18.2.20 → 172.18.2.203 GSMTAP 198 Delivering N-CONNECT.confirm to SCCP User 'msc-0' 
  631   3.150553  172.18.2.20 → 172.18.2.203 GSMTAP 194 Received SCCP User Primitive (N-DATA.request) 
  632   3.150563  172.18.2.20 → 172.18.2.203 GSMTAP 213 SCCP-SCOC(15)[0x55f15dd6d7d0]{ACTIVE}: Received Event N-DATA.req 
  651   3.152214  172.18.2.20 → 172.18.2.203 GSMTAP 188 Received CO:CODT for local reference 15 
  652   3.152223  172.18.2.20 → 172.18.2.203 GSMTAP 215 SCCP-SCOC(15)[0x55f15dd6d7d0]{ACTIVE}: Received Event RCOC-DT1.ind 
  653   3.152233  172.18.2.20 → 172.18.2.203 GSMTAP 198 Delivering N-DATA.indication to SCCP User 'msc-0' 
  661   3.152313  172.18.2.20 → 172.18.2.203 GSMTAP 194 Received SCCP User Primitive (N-DATA.request) 
  662   3.152321  172.18.2.20 → 172.18.2.203 GSMTAP 213 SCCP-SCOC(15)[0x55f15dd6d7d0]{ACTIVE}: Received Event N-DATA.req 
  678   3.152514  172.18.2.20 → 172.18.2.203 RSL 87 DATA REQuest (DTAP) (RR) Channel Release

Failing¶

  565   3.067967 172.18.2.203 → 172.18.2.20  RSL 91 ESTablish INDication (DTAP) (GCC) 
  582   3.068220  172.18.2.20 → 172.18.2.203 GSMTAP 197 Received SCCP User Primitive (N-CONNECT.request) 
  583   3.068231  172.18.2.20 → 172.18.2.203 GSMTAP 195 SCCP-SCOC(15)[0x55725960a7b0]{IDLE}: Allocated 
  584   3.068239  172.18.2.20 → 172.18.2.203 GSMTAP 214 SCCP-SCOC(15)[0x55725960a7b0]{IDLE}: Received Event N-CONNECT.req 
  599   3.068390  172.18.2.20 → 172.18.2.203 GSMTAP 228 SCCP-SCOC(15)[0x55725960a7b0]{IDLE}: State change to CONN_PEND_OUT (no timeout) 
  605   3.071071 172.18.2.203 → 172.18.2.20  RSL 82 CONNection FAILure 
  616   3.071276  172.18.2.20 → 172.18.2.203 GSMTAP 194 Received SCCP User Primitive (N-DATA.request) 
  617   3.071285  172.18.2.20 → 172.18.2.203 GSMTAP 220 SCCP-SCOC(15)[0x55725960a7b0]{CONN_PEND_OUT}: Received Event N-DATA.req 
  618   3.071317  172.18.2.20 → 172.18.2.203 GSMTAP 225 SCCP-SCOC(15)[0x55725960a7b0]{CONN_PEND_OUT}: Event N-DATA.req not permitted 
  623   3.071390  172.18.2.20 → 172.18.2.203 GSMTAP 194 Received SCCP User Primitive (N-DATA.request) 
  624   3.071399  172.18.2.20 → 172.18.2.203 GSMTAP 220 SCCP-SCOC(15)[0x55725960a7b0]{CONN_PEND_OUT}: Received Event N-DATA.req 
  625   3.071413  172.18.2.20 → 172.18.2.203 GSMTAP 225 SCCP-SCOC(15)[0x55725960a7b0]{CONN_PEND_OUT}: Event N-DATA.req not permitted 
  642   3.071571  172.18.2.20 → 172.18.2.203 GSMTAP 200 Received SCCP User Primitive (N-DISCONNECT.request) 
  643   3.071579  172.18.2.20 → 172.18.2.203 GSMTAP 226 SCCP-SCOC(15)[0x55725960a7b0]{CONN_PEND_OUT}: Received Event N-DISCONNECT.req 
  644   3.071588  172.18.2.20 → 172.18.2.203 GSMTAP 238 SCCP-SCOC(15)[0x55725960a7b0]{CONN_PEND_OUT}: State change to WAIT_CONN_CONF (no timeout) 
  655   3.071705  172.18.2.20 → 172.18.2.203 GSMTAP 188 Received CO:COAK for local reference 15 
  656   3.071714  172.18.2.20 → 172.18.2.203 GSMTAP 235 SCCP-SCOC(15)[0x55725960a7b0]{WAIT_CONN_CONF}: Received Event RCOC-CONNECT_CONFIRM.ind 
  658   3.071743  172.18.2.20 → 172.18.2.203 GSMTAP 202 MTP-TRANSFER.req from SCCP without DPC?!? called=RI=0 
  659   3.071759  172.18.2.20 → 172.18.2.203 GSMTAP 243 SCCP-SCOC(15)[0x55725960a7b0]{WAIT_CONN_CONF}: transition to state DISCONN_PEND not permitted! 
  661   3.071806  172.18.2.20 → 172.18.2.203 RSL 87 DATA REQuest (DTAP) (RR) Channel Release 
  664   3.071843  172.18.2.20 → 172.18.2.203 RSL 79 DEACTIVATE SACCH 
  684   5.071572  172.18.2.20 → 172.18.2.203 RSL 79 RF CHANnel RELease

Analysis¶

As can be seen, the both RSL CONNection FAILure and RCOC-CONNECT_CONFIRM.ind are received almost at the same time, so the outcome depends on which of them is handled by osmo-bsc first. Basically a race condition.

https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/30591 BSC_Tests: fix a race condition in TC_chan_rel_conn_fail [NEW]

Applied in changeset core-testing-infra:osmo-ttcn3-hacks|01d0a90b681ca3e6fcf5c77d786cd27288471c41.