Status 180 occasionally not received by caller

Asterisk Asterisk Support
1

Hi,

I’m hoping for some ideas of where to look in order to try solving an intermittent SIP problem we have.

The server is a Positron PBX. The caller is a Windows “kiosk PC” application (our own, which uses the PortSIP SDK) on a wired connection. The callee is an Android tablet app (again, our own, using the PortSIP SDK) on a wifi connection. One possible fly in the ointment here is that the PortSIP SDK (I am led to believe ?) has only been tested against 3COM 3CX, not Asterisk, but I don’t know how true that is, and I simply ask you to read on into the problem before you pass judgment!

For 4 out of 5 calls, everything is fine (i.e. we see all the expected SIP messages, audio and video pass both ways, the call starts up and shuts down cleanly, etc). The following extract is a merging of two different log files, one of them created by my kiosk app, the other created by the PortSIP SDK. The merging is mine - done sequentially by timestamp - so may not quite reflect the actual sequence of callbacks between the SDK and my program – but I think it is clear enough.

Below are two sequences. The first is the typical sequence for a good call – a pattern of callbacks that we always see and which we can rely on. The second sequence shows a sample of a failed call.

The nub of the issue seems to be that the failed call cannot progress because the SDK never received a status 180. The finger seems to point at the server (or the network), but I don’t know enough about these matters to know where to look. Unfortunately we don’t have a log from the PBX which adds any further evidence - we know this would be a useful tool - but in the meantime, can anyone suggest why we might be seeing this behaviour and where we should look ? Could it even be just an intermittently flaky Ethernet which is occasionally losing packets at a crucial moment ?

Any help very much appreciated. Thanks.

===== SUCCESSFUL CALL STARTS =====
INFO | 20150326-125740.119 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipResp: 407 tid=c641220959277f74 cseq=1 INVITE / 1 from(wire)

INFO | 20150326-125740.169 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipResp: 100 tid=aa7329300a75ab44 cseq=2 INVITE contact=205@192.168.0.20 / 2 from(wire)

INFO | 20150326-125740.219 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipResp: 183 tid=aa7329300a75ab44 cseq=2 INVITE contact=205@192.168.0.20 / 2 from(wire)

INFO | 20150326-125740.219 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | InviteSession.cxx:2754 | Transition UAC_Start -> UAC_Early

INFO | 20150326-125740.219 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | ClientInviteSession.cxx:357 | UAC_Early: startStaleCallTimer
3/26/2015 12:57:40 PM : startCall() for: 205
3/26/2015 12:57:40 PM : About to set remote video window
3/26/2015 12:57:40 PM : Result of setRemoteVideoWindow(): 0
3/26/2015 12:57:40 PM : onInviteTrying
INFO | 20150326-125741.070 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipResp: 180 tid=aa7329300a75ab44 cseq=2 INVITE contact=205@192.168.0.20 / 2 from(wire)

INFO | 20150326-125741.070 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | InviteSession.cxx:2754 | Transition UAC_Early -> UAC_Early

INFO | 20150326-125741.070 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | ClientInviteSession.cxx:357 | UAC_Early: startStaleCallTimer

3/26/2015 12:57:41 PM : onInviteSessionProgress: codecs = pcma#pcmu#telephone-event, h263, early media = True, audio = True, video = True
3/26/2015 12:57:41 PM : onInviteSessionProgress: send video regardless of early media
3/26/2015 12:57:41 PM : onInviteRinging: pbxProvidesRingtone = False

INFO | 20150326-125748.372 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipResp: 200 tid=aa7329300a75ab44 cseq=2 INVITE contact=205@192.168.0.20 / 2 from(wire)
INFO | 20150326-125748.372 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | InviteSession.cxx:2754 | Transition UAC_Early -> InviteSession::Connected

INFO | 20150326-125748.372 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | InviteSession.cxx:3098 | Sending SipReq:  ACK 205@192.168.0.20 tid=7e78f857d849aa0a cseq=2 ACK contact=103 / 2 from(tu)
3/26/2015 12:57:48 PM : onInviteAnswered by callee sip:205@192.168.0.20
3/26/2015 12:57:48 PM : onInviteAnswered - codecs: pcma#pcmu#telephone-event and h263
3/26/2015 12:57:48 PM : onInviteAnswered - video exists
3/26/2015 12:57:48 PM : onInviteAnswered - send video regardless of early media
3/26/2015 12:57:48 PM : onInviteAnswered - audio exists
3/26/2015 12:57:48 PM : Session established
3/26/2015 12:57:48 PM : onInviteConnected
3/26/2015 12:57:51 PM : hangupCall()
3/26/2015 12:57:51 PM : hangupCall(), _sdkLib.hangUp() with reset, return = 0

INFO | 20150326-125752.070 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 6088 | ClientInviteSession.cxx:208 | InviteSession::Connected: end

INFO | 20150326-125752.070 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 6088 | InviteSession.cxx:3121 | "103"<sip:103@192.168.0.20>;tag=4127e453 Sending BYE 

INFO | 20150326-125752.070 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 6088 | InviteSession.cxx:2754 | Transition InviteSession::Connected -> InviteSession::Terminated

INFO | 20150326-125752.071 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipReq:  INVITE 103@192.168.0.23:8535 tid=586acdff cseq=102 INVITE contact=205@192.168.0.20 / 102 from(wire)

INFO | 20150326-125752.071 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:2017 | Handling in-dialog request: SipReq:  INVITE 103@192.168.0.23:8535 tid=586acdff cseq=102 INVITE contact=205@192.168.0.20 / 102 from(wire)

INFO | 20150326-125752.071 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | InviteSession.cxx:2009 | InviteSession::dispatchTerminated SipReq:  INVITE 103@192.168.0.23:8535 tid=586acdff cseq=102 INVITE contact=205@192.168.0.20 / 102 from(wire)

INFO | 20150326-125752.121 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipResp: 200 tid=35274c16782ee81b cseq=3 BYE / 3 from(wire)

INFO | 20150326-125752.121 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | InviteSession.cxx:2009 | InviteSession::dispatchTerminated SipResp: 200 tid=35274c16782ee81b cseq=3 BYE / 3 from(wire)

===== CALL ENDS =====

However, the occasional bad call manifests itself as follows. Notice how we never receive the crucial status code 180 which allows the call to proceed further.

===== FAILED CALL STARTS =====

3/26/2015 2:52:22 PM : startCall() for: 205
3/26/2015 2:52:22 PM : About to set remote video window
3/26/2015 2:52:22 PM : Result of setRemoteVideoWindow(): 0
INFO | 20150326-145222.414 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipResp: 407 tid=8e6a6f2eae638d43 cseq=1 INVITE / 1 from(wire)

INFO | 20150326-145222.464 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipResp: 100 tid=541d5157a62a073e cseq=2 INVITE contact=205@192.168.0.20 / 2 from(wire)

INFO | 20150326-145222.514 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipResp: 183 tid=541d5157a62a073e cseq=2 INVITE contact=205@192.168.0.20 / 2 from(wire)

INFO | 20150326-145222.514 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | InviteSession.cxx:2754 | Transition UAC_Start -> UAC_Early

INFO | 20150326-145222.514 | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | ClientInviteSession.cxx:357 | UAC_Early: startStaleCallTimer

3/26/2015 2:52:22 PM : onInviteTrying
***** Here's the point where things go wrong
***** After onInviteTrying callback, we should have received a status 180 (like any successful call) but we didn't

***** We SHOULD have seen something like the following 3 lines in the PortSIP log, but they never occurred !!

***** INFO | <timestamp> | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | DialogUsageManager.cxx:1599 | Got: SipResp: 180 tid=541d5157a62a073e cseq=2 INVITE contact=250@192.168.0.20 / 2 from(wire)

***** INFO | <timestamp> | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | InviteSession.cxx:2754 | Transition UAC_Early -> UAC_Early

***** INFO | <timestamp> | PortSIP VoIP SDK 11.2 | RESIP:DUM | 2108 | ClientInviteSession.cxx:357 | UAC_Early: startStaleCallTimer
2

There is no requirement in the SIP protocol to send any 1xx response. The only partial requirement is that there should be a 100 if nothing better can be sent within the initial timeout.

1xx responses are transmitted unreliably, so the initiating system should be able to tolerate their being lost.

Whether Asterisk generates a 180 will depend on details of its dialplan, which you have not provided, and what is happening on the outgoing leg, although, as noted, the fact that it has sent one doesn’t mean the upstream system will receive it.

3

Thanks @david55.

I wonder if I could just ask you to expand on your answer a little, although I will understand if you can’t given the lack of evidence I’ve provided (e.g. dialplan, etc., and the fact that you probably won’t know the innards of the SDK we are using!!). I am nowhere near being a SIP guru but I do understand the underlying HTTP principles, so I appreciate your comment about 1xx messages being unreliable.

I know you say that that there’s no guarantee we would receive a 180, but if I were to tell you that we are in control of the dialplan and that it never changes, then how would you react to my assumption that a ‘good’ call between the two stated devices on the same network always shows a 180 receipt ? My logic says to me that only one situation is likely to upset this pattern – a network glitch – but is my logic flawed ?

We are starting to wonder if there is an intermittent lower-level networking issue on the connection from caller to server, or server to callee, but the trouble we have is (a) proving it and (b) not knowing whether (and how) the SDK reacts to missing the receipt of the 180. Indeed, the SDK may not even care, and we need to quiz the supplier more to find out if it is simply our responsibility (as the client using the SDK) to handle the loss (e.g. I’ve just started a call, so I will create a 3-second timer, and if the timer elapses without receiving the 180, I will either reset the call or retry it).

Any thoughts you can give me on the above ?

Thanks

4

UDP doesn’t guarantee delivery, or even order of delivery.

If you explicitly call Ringing, you should get 180, but you shouldn’t get the 183 before it.