Bug #5823
closed
ttcn3-bsc-test: BSC_Tests.TC_chan_rel_conn_fail sporadically fails
Added by fixeria over 1 year ago.
Updated over 1 year ago.
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
- Status changed from New to In Progress
- % 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.
- Status changed from In Progress to Feedback
- % Done changed from 50 to 100
- Status changed from Feedback to Resolved
Also available in: Atom
PDF
