Project

General

Profile

Actions
Copy link

Bug #3518

closed

Rapid SETUP followed DISC results in lingering B-leg

Added by keith about 5 years ago. Updated almost 2 years ago.

Status:
Closed
Priority:
Low
Assignee:
keith
Target version:
-
Start date:
09/04/2018
Due date:
% Done:

60%

Resolution:
Spec Reference:

Description

This is 100% reproducible at the moment.

First log output is from correct behaviour, (slighty longer before pressing END on UE)

Second log output shows some clue of what's happening..

A race condition?

Tue Sep  4 17:30:22 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_SETUP_IND
Tue Sep  4 17:30:22 2018 DMNCC <0001> mncc.c:466 Created call(5018) with MNCC leg(2147483734) IMSI(262423203000396)
Tue Sep  4 17:30:22 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_RTP_CREATE
Tue Sep  4 17:30:22 2018 DMNCC <0001> mncc.c:391 RTP cnt leg(2147483734) ip(172.16.0.15), port(16536) pt(98) ptm(771)
Tue Sep  4 17:30:22 2018 DMNCC <0001> mncc.c:81 Got response(0x204), stopping timer on leg(2147483734)
Tue Sep  4 17:30:22 2018 DSIP <0000> sip.c:223 SIP event(7) status(0) phrase(INVITE sent) 0x1476e50
Tue Sep  4 17:30:22 2018 DSIP <0000> sip.c:290 nua_callback() did nothing with event(7), status(0)
Tue Sep  4 17:30:22 2018 DSIP <0000> sip.c:223 SIP event(1) status(100) phrase(Trying) (nil)
Tue Sep  4 17:30:22 2018 DSIP <0000> sip.c:89 Incoming call handle(0x147fb10)
Tue Sep  4 17:30:22 2018 DSIP <0000> sip.c:223 SIP event(7) status(100) phrase(Trying) 0x1487b30
Tue Sep  4 17:30:22 2018 DSIP <0000> sip.c:290 nua_callback() did nothing with event(7), status(100)
Tue Sep  4 17:30:23 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_DISC_IND
Tue Sep  4 17:30:23 2018 DMNCC <0001> mncc.c:511 Rcvd MNCC_DISC_IND, Cause: NORM_CALL_CLEAR
Tue Sep  4 17:30:23 2018 DMNCC <0001> mncc.c:513 leg(2147483734) was disconnected. Releasing
Tue Sep  4 17:30:23 2018 DSIP <0000> sip.c:332 sip_release_call(): Release with MNCC cause(NORM_CALL_CLEAR)
Tue Sep  4 17:30:23 2018 DSIP <0000> sip.c:304 cause2status(): Mapping cause(NORM_CALL_CLEAR) to status(200)
Tue Sep  4 17:30:23 2018 DSIP <0000> sip.c:338 Canceling leg(0x1476e50) in int state
Tue Sep  4 17:30:23 2018 DSIP <0000> :0 nta_outgoing_tcancel: trying to cancel cancelled request
Tue Sep  4 17:30:23 2018 DSIP <0000> sip.c:223 SIP event(2) status(200) phrase(OK) 0x1487b30
Tue Sep  4 17:30:23 2018 DSIP <0000> sip.c:280 Canceled on leg(0x1487b30)
Tue Sep  4 17:30:23 2018 DMNCC <0001> mncc.c:253 Releasing call in initial-state leg(5019)
Tue Sep  4 17:30:23 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_REL_CNF
Tue Sep  4 17:30:23 2018 DMNCC <0001> mncc.c:81 Got response(0x112), stopping timer on leg(5019)
Tue Sep  4 17:30:23 2018 DMNCC <0001> mncc.c:560 leg(5019) was cnf released.
Tue Sep  4 17:30:23 2018 DAPP <0002> call.c:88 call(5019) released.
Tue Sep  4 17:30:23 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_REL_CNF
Tue Sep  4 17:30:23 2018 DMNCC <0001> mncc.c:81 Got response(0x112), stopping timer on leg(2147483734)
Tue Sep  4 17:30:23 2018 DMNCC <0001> mncc.c:560 leg(2147483734) was cnf released.
Tue Sep  4 17:30:23 2018 DAPP <0002> call.c:88 call(5018) released.

Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_SETUP_IND
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:466 Created call(5020) with MNCC leg(2147483735) IMSI(262423203000396)
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_DISC_IND
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:511 Rcvd MNCC_DISC_IND, Cause: NORM_CALL_CLEAR
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:513 leg(2147483735) was disconnected. Releasing
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_RTP_CREATE
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:391 RTP cnt leg(2147483735) ip(172.16.0.15), port(16538) pt(98) ptm(771)
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:75 Wanted rsp(274) but got(516) for leg(2147483735)
Tue Sep  4 17:30:27 2018 DSIP <0000> sip.c:223 SIP event(7) status(0) phrase(INVITE sent) 0x148b950
Tue Sep  4 17:30:27 2018 DSIP <0000> sip.c:290 nua_callback() did nothing with event(7), status(0)
Tue Sep  4 17:30:27 2018 DSIP <0000> sip.c:223 SIP event(1) status(100) phrase(Trying) (nil)
Tue Sep  4 17:30:27 2018 DSIP <0000> sip.c:89 Incoming call handle(0x1489690)
Tue Sep  4 17:30:27 2018 DSIP <0000> sip.c:223 SIP event(7) status(100) phrase(Trying) 0x148e950
Tue Sep  4 17:30:27 2018 DSIP <0000> sip.c:290 nua_callback() did nothing with event(7), status(100)
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_REL_CNF
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:81 Got response(0x112), stopping timer on leg(2147483735)
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:560 leg(2147483735) was cnf released.
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_CALL_CONF_IND
Tue Sep  4 17:30:27 2018 DMNCC <0001> mncc.c:609 leg(5021) confirmend. creating RTP socket.
Tue Sep  4 17:30:28 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_RTP_CREATE
Tue Sep  4 17:30:28 2018 DMNCC <0001> mncc.c:391 RTP cnt leg(5021) ip(172.16.0.15), port(16540) pt(3) ptm(768)
Tue Sep  4 17:30:28 2018 DMNCC <0001> mncc.c:81 Got response(0x204), stopping timer on leg(5021)
Tue Sep  4 17:30:28 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_ALERT_IND
Tue Sep  4 17:30:28 2018 DMNCC <0001> mncc.c:626 leg(5021) is alerting.
Tue Sep  4 17:30:28 2018 DSIP <0000> sip.c:223 SIP event(7) status(180) phrase(Ringing) 0x148e950
Tue Sep  4 17:30:28 2018 DSIP <0000> sip.c:290 nua_callback() did nothing with event(7), status(180)
Tue Sep  4 17:30:28 2018 DSIP <0000> sip.c:223 SIP event(31) status(183) phrase(Session Progress) 0x148b950
Tue Sep  4 17:30:28 2018 DSIP <0000> sip.c:223 SIP event(7) status(183) phrase(Session Progress) 0x148b950
Tue Sep  4 17:30:28 2018 DSIP <0000> sip.c:290 nua_callback() did nothing with event(7), status(183)
Tue Sep  4 17:30:30 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_DISC_IND
Tue Sep  4 17:30:30 2018 DMNCC <0001> mncc.c:511 Rcvd MNCC_DISC_IND, Cause: USER_BUSY
Tue Sep  4 17:30:30 2018 DMNCC <0001> mncc.c:513 leg(5021) was disconnected. Releasing
Tue Sep  4 17:30:30 2018 DSIP <0000> sip.c:332 sip_release_call(): Release with MNCC cause(USER_BUSY)
Tue Sep  4 17:30:30 2018 DSIP <0000> sip.c:304 cause2status(): Mapping cause(USER_BUSY) to status(486)
Tue Sep  4 17:30:30 2018 DSIP <0000> sip.c:343 Canceling leg(0x148e950) in cnfd state
Tue Sep  4 17:30:30 2018 DMNCC <0001> mncc.c:845 MNCC rcvd message type: MNCC_REL_CNF
Tue Sep  4 17:30:30 2018 DMNCC <0001> mncc.c:81 Got response(0x112), stopping timer on leg(5021)
Tue Sep  4 17:30:30 2018 DMNCC <0001> mncc.c:560 leg(5021) was cnf released.
Tue Sep  4 17:30:30 2018 DAPP <0002> call.c:88 call(5021) released.
Tue Sep  4 17:30:37 2018 DSIP <0000> sip.c:223 SIP event(31) status(486) phrase(Busy Here) 0x148b950
Tue Sep  4 17:30:37 2018 DSIP <0000> sip.c:242 leg(0x148b950) unknown SIP status(486), releasing.
Tue Sep  4 17:30:37 2018 DAPP <0002> call.c:88 call(5020) released.
Actions
Copy link
 #1

Updated by fixeria about 5 years ago

It would be great to have some protocol traces (*.pcap) and some logs of the other MNCC side (i.e. OsmoMSC or OpenBSC) attached.

Actions
Copy link
 #2

Updated by keith about 5 years ago

Hi Vadim!

Yes. traces, of course would be useful.
[EDIT: On seconds thoughts, possibly not so useful, at least not for anyone familiar with what's happening on the other side of the MNCC socket (nitb/msc) ]

Unfortunately, I have to divert attention to something else right now, but rather than let the noted issue leak out of my (grey-matter) memory I made this note of the problem.

Seeing as how (as I said), it is 100% reproducible, maybe somebody else might get around to adding said trace. ;-)

That said, I have a sneaky feeling that the problem is probably visible even with static analysis.

Actions
Copy link
 #3

Updated by keith almost 5 years ago

Static Analysis:

It appears we are getting MNCC_RTP_CREATE after MNCC_DISC_IND (this was observed with osmo-nitb)

On receipt of MNCC_RTP_CREATE, check_rtp_create() calls stop_cmd_timer() which complains and returns, and then we go ahead with continue_call() anyway, ultimateley resulting in the setup of the B-leg, even though the A leg is gone.

So we need to check someplace for the continuing validity of the A-leg.

Also this would appear to reveal a bug on the MSC side, in that somehow we are getting this MNCC_RTP_CREATE from the MNCC socket (in this case, I repeat, osmo-nitb) after we got the MNCC_DISC_IND.

Note to self: Maybe that's because we didn't send back some response to MNCC_DISC_IND yet?

Actions
Copy link
 #4

Updated by laforge almost 5 years ago

Actions
Copy link
 #7

Updated by keith almost 5 years ago

Adding link to possible workaround patch here:

https://gerrit.osmocom.org/#/c/osmo-sip-connector/+/11194/

Actions
Copy link
 #8

Updated by rafael2k over 4 years ago

keith wrote:

Adding link to possible workaround patch here:

https://gerrit.osmocom.org/#/c/osmo-sip-connector/+/11194/

Another possible fix here, in libmsc:
https://gerrit.osmocom.org/#/c/openbsc/+/13703/

ps: I plan to do the same with osmo-msc's libmsc.

Actions
Copy link
 #9

Updated by laforge over 4 years ago

Can we please have a regression test case in SIP_Tests.ttcn which reproduces
the problem? It should be as simple as to send three messages to MNCC, right?

This way we can avoid the problem from ever re-appearing again.

I do believe that the fix in osmo-sip-connector published in
https://gerrit.osmocom.org/#/c/osmo-sip-connector/+/11194/
is correct. There's no use of accepting any other commands for a given call
after we received a DISC_IND.

Having said this, it's of course also wrong for the MSC/NITB to send such messages
in the first place. The use of proper state machines should prevent something like
that, and I wonder if neels/ho (which introduces lots more osmo_fsm into the MSC)
already adresses this "by accident"

Actions
Copy link
 #10

Updated by laforge over 4 years ago

  • Status changed from New to In Progress
Actions
Copy link
 #11

Updated by keith over 4 years ago

  • % Done changed from 0 to 60

Patch to osmo-sip-connector to deal with the case is now merged. Lingering B leg not possible anymore.

@rafael2k's patch to legacy openbsc is also merged, so nitb should no longer cause this error (might be nice for anybody still running nitb/lcr)

TODO: Verify if the osmo-msc still exhibits this behaviour, now that the code there hardly resembles legacy libmsc.

Actions
Copy link
 #12

Updated by keith almost 2 years ago

  • Status changed from In Progress to Closed
  • Priority changed from Normal to Low

Closing as too old.

Actions
Copy link

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)