registration expired reached

236 views
Skip to first unread message

conrad.ja...@gmail.com

unread,
May 25, 2016, 6:59:39 AM5/25/16
to SIP.js
I'm getting a "registration expired" warning.

This is the behavior i'm experiencing...

1) I get a warning: "Wed May 25 2016 11:45:18 GMT+0200 | sip.registercontext | registration expired"

2) Just after that Asterisk displays the warning:
Peer '102' is now UNREACHABLE! Last qualify: 61
Peer '102' is now Reachable. (67ms / 2000ms)

I think there is something wrong with the expires and timers, im just not sure how to fix it. I do specify registerExpires: 1800 in the SIP.UA, but it never seem to reach that timeout. I have debugged Asterisk SIP messaging and what I can see is that:

Every 60 seconds Asterisk sends an OPTIONS message in order to keep the connection alive and to determine if the extension is available.

However after every now and again, the OPTION message is transmitted during the time that the extension is somehow expired (or the peer connection is closed).

A second or so after that this registration timeout kicks in and the SIPjs re-registers the extension, and the extension goes back online again.

Sometimes the re-register manages to complete while Asterisk is re-transmitting the OPTIONS message, so the first 2 or 3 tries will fail, but the last one succeeds - this causes Asterisk to consider the extension "lagged"

This is what the Chrome Warning log looks like:

Wed May 25 2016 11:45:18 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 11:47:26 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 11:51:32 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 11:53:35 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 11:55:43 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 11:59:44 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 12:03:50 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 12:09:49 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 12:13:55 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 12:16:03 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 12:24:00 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 12:28:01 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 12:32:02 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 12:34:05 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 12:36:08 GMT+0200 | sip.registercontext | registration expired
Wed May 25 2016 12:40:09 GMT+0200 | sip.registercontext | registration expired

While this is what the asterisk server looks like:

[2016-05-25 11:51:15] NOTICE: Peer '102' is now Reachable. (46ms / 2000ms)
[2016-05-25 11:53:19] NOTICE: Peer '102' is now UNREACHABLE! Last qualify: 86
[2016-05-25 11:53:24] NOTICE: Peer '102' is now Reachable. (71ms / 2000ms)
[2016-05-25 11:55:26] NOTICE: Peer '102' is now Lagged. (2311ms / 2000ms)
[2016-05-25 11:55:26] NOTICE: Peer '102' is now Reachable. (59ms / 2000ms)
[2016-05-25 11:59:28] NOTICE: Peer '102' is now UNREACHABLE! Last qualify: 91
[2016-05-25 11:59:32] NOTICE: Peer '102' is now Reachable. (71ms / 2000ms)
[2016-05-25 12:03:33] NOTICE: Peer '102' is now Lagged. (2962ms / 2000ms)
[2016-05-25 12:03:33] NOTICE: Peer '102' is now Reachable. (55ms / 2000ms)
[2016-05-25 12:09:32] NOTICE: Peer '102' is now Lagged. (2612ms / 2000ms)
[2016-05-25 12:09:37] NOTICE: Peer '102' is now Reachable. (59ms / 2000ms)
[2016-05-25 12:13:39] NOTICE: Peer '102' is now UNREACHABLE! Last qualify: 91
[2016-05-25 12:13:43] NOTICE: Peer '102' is now Reachable. (54ms / 2000ms)
[2016-05-25 12:15:46] NOTICE: Peer '102' is now Lagged. (2828ms / 2000ms)
[2016-05-25 12:15:46] NOTICE: Peer '102' is now Reachable. (42ms / 2000ms)
[2016-05-25 12:27:44] NOTICE: Peer '102' is now Lagged. (2819ms / 2000ms)
[2016-05-25 12:27:44] NOTICE: Peer '102' is now Reachable. (60ms / 2000ms)
[2016-05-25 12:31:45] NOTICE: Peer '102' is now Lagged. (2436ms / 2000ms)
[2016-05-25 12:31:45] NOTICE: Peer '102' is now Reachable. (53ms / 2000ms)
[2016-05-25 12:33:48] NOTICE: Peer '102' is now Lagged. (2781ms / 2000ms)
[2016-05-25 12:33:48] NOTICE: Peer '102' is now Reachable. (65ms / 2000ms)
[2016-05-25 12:35:52] NOTICE: Peer '102' is now Lagged. (2985ms / 2000ms)
[2016-05-25 12:35:52] NOTICE: Peer '102' is now Reachable. (74ms / 2000ms)
[2016-05-25 12:39:54] NOTICE: Peer '102' is now UNREACHABLE! Last qualify: 55
[2016-05-25 12:39:57] NOTICE: Peer '102' is now Reachable. (55ms / 2000ms)
[2016-05-25 12:42:00] NOTICE: Peer '102' is now Lagged. (2773ms / 2000ms)
[2016-05-25 12:42:05] NOTICE: Peer '102' is now Reachable. (78ms / 2000ms)

James Criscuolo

unread,
May 25, 2016, 9:36:14 AM5/25/16
to SIP.js, conrad.ja...@gmail.com
Hi conrad.james.de.wet,
  I'm not entirely sure what the cause of this is, but I would enable traceSip to see the actual REGISTER message go out and see what happens. SIP.js should re-register a few seconds before registration expires (I looked briefly, it looked like 3 seconds, I'm sure there's a standard we should be following on that).

It's rare that I see that log message, so I'm guessing some weird signaling is occurring, but traceSip (preferably with output pasted in a gist) should be helpful here.

- James
Reply all
Reply to author
Forward
0 new messages