Bug #5823
closedttcn3-bsc-test: BSC_Tests.TC_chan_rel_conn_fail sporadically fails
100%
Description
Starting from build https://jenkins.osmocom.org/jenkins/view/TTCN3/job/ttcn3-bsc-test/1951/, I see sporadic failures of BSC_Tests.TC_chan_rel_conn_fail
.
Timeout of T_guard BSC_Tests.ttcn:12102 BSC_Tests control part BSC_Tests.ttcn:1984 TC_chan_rel_conn_fail testcase
As can be seen from the attached PCAP file, osmo-bsc fails to deliver BSSMAP Clear Request/Complete
messages:
614 3.071251 172.18.2.20 → 172.18.2.203 GSMTAP 178 Tx MSC: BSSMAP: CLEAR REQUEST 615 3.071265 172.18.2.20 → 172.18.2.203 GSMTAP 248 Sending connection (id=15) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (00 04 22 04 01 01 ) 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 619 3.071346 172.18.2.20 → 172.18.2.203 GSMTAP 253 SUBSCR_CONN(msc0-conn15)[0x55725960a2b0]{WAIT_CLEAR_CMD}: Unable to deliver BSSMAP Clear Request message 620 3.071356 172.18.2.20 → 172.18.2.203 GSMTAP 247 SUBSCR_CONN(msc0-conn15)[0x55725960a2b0]{WAIT_CLEAR_CMD}: State change to WAIT_SCCP_RLSD (X4, 60s) 621 3.071368 172.18.2.20 → 172.18.2.203 GSMTAP 179 Tx MSC: BSSMAP: CLEAR COMPLETE 622 3.071380 172.18.2.20 → 172.18.2.203 GSMTAP 239 Sending connection (id=15) oriented data to MSC: RI=SSN_PC,PC=0.23.1,SSN=BSSAP (00 01 21 ) 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 626 3.071427 172.18.2.20 → 172.18.2.203 GSMTAP 237 SUBSCR_CONN(msc0-conn15)[0x55725960a2b0]{WAIT_SCCP_RLSD}: Unable to deliver SCCP message
Files
Updated by fixeria over 1 year ago
- % Done changed from 0 to 50
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.
Updated by fixeria over 1 year ago
- Status changed from In Progress to Feedback
- % Done changed from 50 to 100
https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/30591 BSC_Tests: fix a race condition in TC_chan_rel_conn_fail [NEW]
Updated by fixeria over 1 year ago
- Status changed from Feedback to Resolved
Applied in changeset core-testing-infra:osmo-ttcn3-hacks|01d0a90b681ca3e6fcf5c77d786cd27288471c41.