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)