Client asks for session timers. server doesn't confirm in OK. Client sends one anyway. But one only. A later assert abort results when in-dialog reinvite arrived for the call

[elbow]

Hi Dave,

In this issue the client phone asked for session-timers. Didn't get them agreed in the OK, but did actually send one UPDATE as if it was doing timers.

But after sending one it didn't send any more.

Later an in-dialog reinvite arrived from the client for the call, but triggered an assert error in PendingRequestController::processNewRequest:

assert(sip->sip_request->rq_method != sip_method_invite || NULL == sip->sip_to->a_tag ) ; //new INVITEs only

Call was started with this INVITE:

I did compare with the RFC4028 and it is weird that it has Session-Expires header but nothing in the Supported: header (ie no "timer").

2020-04-01 02:34:45.182850 recv 1660 bytes from wss/[cli.ent.ipa.ddr]:14794 at 02:34:45.182454:
INVITE sip:0800368368@rtc.telviva.com SIP/2.0
Via: SIP/2.0/WSS 7672pqiuuogb.invalid;branch=z9hG4bK3163995
Max-Forwards: 69
To: <sip:0800368368@rtc.telviva.com>
From: "clientaccount" <sip:clientaccount@rtc.telviva.com>;tag=hv7l6bk92a
Call-ID: tsve1ol6cro2udrdj6pl
CSeq: 9734 INVITE
Contact: <sip:tuq9k1nr@7672pqiuuogb.invalid;transport=ws;ob>
Content-Type: application/sdp
Session-Expires: 90
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO
Supported:
User-Agent: TelvivaMobile ios 1.3.0 79
Content-Length: 1129

There is no Session-Expires header returned to the client in the 2xx response:

2020-04-01 02:34:49.037453 send 1388 bytes to wss/[cli.ent.ipa.ddr]:14794 at 02:34:49.037051:
SIP/2.0 200 OK
Via: SIP/2.0/WSS 7672pqiuuogb.invalid;branch=z9hG4bK7123285;received=cli.ent.ipa.ddr;rport=14794
From: "clientaccount" <sip:clientaccount@rtc.telviva.com>;tag=hv7l6bk92a
To: <sip:0800368368@rtc.telviva.com>;tag=Z9633ZHNHejUm
Call-ID: tsve1ol6cro2udrdj6pl
CSeq: 9735 INVITE
Contact: <sips:AAA.BBB.250.156:4433;transport=wss>
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE, INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE, INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Content-Type: application/sdp
Content-Length: 738

So in my book session timers were not agreed.

Nevertheless, later the client sends an UPDATE. It seems like it thinks it must refresh timers. Drachtio forwards that to my rtcproxy client and an OK is returned:

2020-04-01 02:35:55.107601 recv 538 bytes from wss/[cli.ent.ipa.ddr]:14794 at 02:35:55.107391:
UPDATE sips:AAA.BBB.250.156:4433;transport=wss SIP/2.0
Via: SIP/2.0/WSS 7672pqiuuogb.invalid;branch=z9hG4bK7406714
Max-Forwards: 69
To: <sip:0800368368@rtc.telviva.com>;tag=Z9633ZHNHejUm
From: "clientaccount" <sip:clientaccount@rtc.telviva.com>;tag=hv7l6bk92a
Call-ID: tsve1ol6cro2udrdj6pl
CSeq: 9736 UPDATE
Contact: <sip:tuq9k1nr@7672pqiuuogb.invalid;transport=ws;ob>
Session-Expires: 90;refresher=uac
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO
Supported:
User-Agent: TelvivaMobile ios 1.3.0 79
Content-Length: 0

2020-04-01 02:35:55.107816 SipDialogController::addIncomingRequestTransaction - adding transactionId 34b7eb3c-879a-41b8-bb3c-fbea581a80b1 for irq:0x11d94f00
2020-04-01 02:35:55.111072 send 303 bytes to wss/[cli.ent.ipa.ddr]:14794 at 02:35:55.110873:
SIP/2.0 200 OK
Via: SIP/2.0/WSS 7672pqiuuogb.invalid;branch=z9hG4bK7406714;received=cli.ent.ipa.ddr;rport=14794
From: "clientaccount" <sip:clientaccount@rtc.telviva.com>;tag=hv7l6bk92a
To: <sip:0800368368@rtc.telviva.com>;tag=Z9633ZHNHejUm
Call-ID: tsve1ol6cro2udrdj6pl
CSeq: 9736 UPDATE
Content-Length: 0

For this update I see it is received in the client and the OK returned.

Now its only at 02:40:21 that we get another update.

According to the drachtio-server logs it is just dropped:

2020-04-01 02:40:21.765019 recv 538 bytes from wss/[cli.ent.ipa.ddr]:14794 at 02:40:21.764784:
UPDATE sips:AAA.BBB.250.156:4433;transport=wss SIP/2.0
Via: SIP/2.0/WSS 7672pqiuuogb.invalid;branch=z9hG4bK3705069
Max-Forwards: 69
To: <sip:0800368368@rtc.telviva.com>;tag=Z9633ZHNHejUm
From: "clientaccount" <sip:clientaccount@rtc.telviva.com>;tag=hv7l6bk92a
Call-ID: tsve1ol6cro2udrdj6pl
CSeq: 9737 UPDATE
Contact: <sip:tuq9k1nr@7672pqiuuogb.invalid;transport=ws;ob>
Session-Expires: 90;refresher=uac
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO
Supported:
User-Agent: TelvivaMobile ios 1.3.0 79
Content-Length: 0

Just after than a re-INVITE (hold) arrives from the client and

2020-04-01 02:40:33.314649 recv 3870 bytes from wss/[cli.ent.ipa.ddr]:14794 at 02:40:33.312845:
INVITE sips:AAA.BBB.250.156:4433;transport=wss SIP/2.0
...
a=sendonly

This triggers the assert. But to keep my drachtio-server up, I modified my drachtio code and replaced the assert with code that logs and returns a 500:

2020-04-01 02:40:33.315572 processNewRequest - not expecting an in-dialog INVITE here
2020-04-01 02:40:33.316068 send 321 bytes to wss/[cli.ent.ipa.ddr]:14794 at 02:40:33.315756:
SIP/2.0 500 Internal Server Error
Via: SIP/2.0/WSS 7672pqiuuogb.invalid;branch=z9hG4bK937262;received=cli.ent.ipa.ddr;rport=14794
From: "clientaccount" <sip:clientaccount@rtc.telviva.com>;tag=hv7l6bk92a
To: <sip:0800368368@rtc.telviva.com>;tag=Z9633ZHNHejUm
Call-ID: tsve1ol6cro2udrdj6pl
CSeq: 9738 INVITE
Content-Length: 0

So with this mod drachtio server stays up but returning the 500 does cause the hold to fail and in fact kills the call.

So it is funky of the client to send an UPDATE apparently as a session refresher. We have logs from the app on the client phone but it doesn't log the details of the JSSIP activity but we will go looking for this issue in the client code

Still, UPDATEs are a legit message for a client to send.

Why did drachtio drop the second update and not pass to the client?

And if drachtio had decided that session timers had been agreed why was there no BYE generated. (Followup would be: whose job is it to do the bye? drachtio-server, drachtio-srf or our code?)

Is an assert and associated abort a prudent thing to do when a client sends something unexpected? Weird stuff does happen, and malicious actors could certainly exploit to DDOS services.

Thanks, Steve

[davehorton]

assertions are useful to detect when something you (/me, the programmer) believe to be true, is somehow not true. They are compiled out of production builds by the NDEBUG flag.

In this case, the sofia stack has received an INVITE that it does not match to an existing dialog, and yet it has a tag in the To header, indicating that it is not a new INVITE. That is a worthy assertion, actually, since something is wrong.

I'll need the full log to look further into it.

Note: this could happen after the drachtio server restarted, but I cannot think of another case where it should be expected

[davehorton]

There are a couple of issues here, but the main one seems to be on the client side. When the client sends the first UPDATE with Session-expires: 90 and the drachtio server returns 200 OK, there is now an expectation that the client will refresh the session within 90 seconds. In fact, this time expires without a refresh. So at that point the drachtio server closes the dialog (get back to that in a second). So when the second INVITE comes in -- almost 5 minutes after the first -- this is treated as an out-of-dialog UPDATE request. Since your app is not handling this no response is sent. Later, a reINVITE comes in, but due to the elapsed session timer the drachtio server has flushed that dialog and treats it as a new one. Thus the assert.

Now, when the drachtio server expired the session, it should have sent a BYE. I see an error in the logs that indicates it may have tried to, but failed for some reason.

Here is the timeline:

02:34:54 Call established 02:35:55. UPDATE with session timer 90 02:37:25 Session expires 02:40:21 UPDATE arrives, but session is expired 02:40:33 re-INVITE arrives but session is expired

at 02:37:25 when the session expires, I see this message which indicates that the drachtio server had a porblem sending a BYE.

2020-04-01 02:37:25.108437 nta.c:10220 outgoing_resolve() nta(0x127efe50): transport ws is not supported

So the best way to resolve this issue is to address the client issue where it is not refreshing the session in accordance with the session expires value it provided.