Some extensions remain with idle state, BLF trouble

Hello everyone, im new to asterisks!

Downloaded and installed FreePBX distro 6.12.65 with aster11, configured it, all working fine! :airplane:
Upgraded it with scripts as described in wiki

[code][[email protected] ~]# cat /etc/schmooze/pbx-version
6.12.65-31
[[email protected] ~]# asterisk -rvvvvvvv
Asterisk 11.20.0, Copyright © 1999 - 2013 Digium, Inc. and others.

[/code]

Having trouble with BLF hints and sip presence for a couple of extensions.
All extensions are advertising states for other subscribed softphones fine, but a couple of them remain with hints IDLE and not changing to UNAVAILABLE when i terminate softphones (extensions get state from OK to UNKNOWN in ‘sip show peers’)

Output of ‘sip show peers’, with disconnected extensions:

FreePBX-FSI*CLI> sip show peers
Name/username             Host                                    Dyn Forcerport Comedia    ACL Port     Status      Description
401/401                   (Unspecified)                            D  Auto (No)  Auto (No)   A  0        UNKNOWN
402/402                   (Unspecified)                            D  Auto (No)  Auto (No)   A  0        UNKNOWN
403                       (Unspecified)                            D  Auto (No)  Auto (No)   A  0        UNKNOWN
404                       (Unspecified)                            D  No         No          A  0        UNKNOWN
405/405                   172.16.50.221                            D  No         No          A  5060     OK (1 ms)
406                       (Unspecified)                            D  No         No          A  0        UNKNOWN
407                       (Unspecified)                            D  Auto (No)  Auto (No)   A  0        UNKNOWN
408                       (Unspecified)                            D  Auto (No)  Auto (No)   A  0        UNKNOWN

The extensions 401 and 403 are the problematic ones
405 is subscribed to monitor other extensions (MicroSIP, but doesnt matter, Eyebeam shows same result)

Output of ‘sip show subscriptions’ :

Peer             User             Call ID          Extension        Last state     Type            Mailbox    Expiry
172.16.50.221    405              c26d6f0c2fcf400  [email protected]  Idle           pidf+xml        <none>     000600
172.16.50.221    405              28d09e3062e7432  [email protected]  Idle           pidf+xml        <none>     000600
172.16.50.221    405              f5ceca197e7f4e5  *46*[email protected]  Idle           pidf+xml        <none>     000600
172.16.50.221    405              fd58110296024eb  [email protected]  Unavailable    pidf+xml        <none>     000600
172.16.50.221    405              98b212e2f89247c  *46*[email protected]  Idle           pidf+xml        <none>     000600
172.16.50.221    405              f7fca66ebaf846d  *46*[email protected]  Idle           pidf+xml        <none>     000600
172.16.50.221    405              68a9a137fc85437  [email protected]  Unavailable    pidf+xml        <none>     000600
172.16.50.221    405              fa51bdf2c3f140e  [email protected]  Idle           pidf+xml        <none>     000600
172.16.50.221    405              6a5a6a4a45d04a9  [email protected]  Unavailable    pidf+xml        <none>     000600
172.16.50.221    405              52d50cabc863414  [email protected]  Unavailable    pidf+xml        <none>     000600
172.16.50.221    405              e225561ffca94a9  [email protected]  Unavailable    pidf+xml        <none>     000600
172.16.50.221    405              51d52e679d2146c  *46*[email protected]  Idle           pidf+xml        <none>     000600
12 active SIP subscriptions

(Yes, i also monitor ‘queue pause’ states)

As you can see [email protected] and [email protected] remain idle even with no connected peers.
When i connect 401 or 403 they notify Ringing, In Use and other states (Except UNAVAILABLE) just normal as it must be.

So, for now, I tried removing those extensions and re-creating them - no effect.
Restarts, reloads - no effect.
The trouble was before i upgraded freepbx - so upgrading also didnt solve the problem.

‘core show hints’ output:

[email protected]           : SIP/401&Custom:DND40  State:Idle            Watchers  1
[email protected]           : SIP/403&Custom:DND40  State:Idle            Watchers  1
[email protected]           : SIP/402&Custom:DND40  State:Unavailable     Watchers  1
[email protected]ext-local           : SIP/405&Custom:DND40  State:Idle            Watchers  1
[email protected]           : SIP/404&Custom:DND40  State:Unavailable     Watchers  1
[email protected]           : SIP/407&Custom:DND40  State:Unavailable     Watchers  1
[email protected]           : SIP/406&Custom:DND40  State:Unavailable     Watchers  1
[email protected]           : SIP/408&Custom:DND40  State:Unavailable     Watchers  1

I dont understand why this is happening, because i tried to make configuration of pbx clean as possible, from GUI. New extensions which i create don’t have such problem, only those two 401 and 403.

Any help will be apreciated, thank you!

Debugs: Here i connect 401 (bad) and 402 (good)

  -- Registered SIP '401' at 172.16.50.221:5453
[2015-11-17 10:28:08] NOTICE[2164]: chan_sip.c:23739 handle_response_peerpoke: Peer '401' is now Reachable. (51ms / 2000ms)
    -- Registered SIP '402' at 172.16.50.221:50934
  == Extension Changed 402[ext-local] new state Idle for Notify User 405
[2015-11-17 10:28:14] NOTICE[2164]: chan_sip.c:23739 handle_response_peerpoke: Peer '402' is now Reachable. (106ms / 2000ms)
[2015-11-17 10:28:14] NOTICE[2164]: chan_sip.c:28112 handle_request_subscribe: Received SIP subscribe for peer without mailbox: 402

As you can see 401 not changed state for notify user 405!

Im newbie in asterisks and dont really know what info to extract from debugs.
Here is output of ‘sip set debug peer 401’, when i terminate softphone:

FreePBX-FSI*CLI> sip set debug peer 401
SIP Debugging Enabled for IP: 172.16.50.221

<--- SIP read from UDP:172.16.50.221:5453 --->
REGISTER sip:172.16.1.241 SIP/2.0
Via: SIP/2.0/UDP 172.16.50.221:5453;branch=z9hG4bK-524287-1---8d78073b1527d84f;rport
Max-Forwards: 70
Contact: <sip:[email protected]:5453>;+sip.instance="<urn:uuid:2BC7C79F-94CB-F846-D74A-773A8D15BB19>";expires=0
To: <sip:[email protected]>
From: <sip:[email protected]>;tag=e1260a03
Call-ID: vm3ZyPp-wcZbfHWdlP227A..
CSeq: 3 REGISTER
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, REGISTER, SUBSCRIBE, INFO
Supported: replaces
User-Agent: PortGo v11.2.2, Build 08102015
Authorization: Digest username="401",realm="asterisk",nonce="2cd09a02",uri="sip:172.16.1.241",response="2dd5bb0dc1b2f510c26d27ffe3e037fd",algorithm=MD5
Content-Length: 0

<------------->
--- (13 headers 0 lines) ---
Sending to 172.16.50.221:5453 (NAT)
Sending to 172.16.50.221:5453 (NAT)

<--- Transmitting (no NAT) to 172.16.50.221:5453 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 172.16.50.221:5453;branch=z9hG4bK-524287-1---8d78073b1527d84f;received=172.16.50.221;rport=5453
From: <sip:[email protected]>;tag=e1260a03
To: <sip:[email protected]>;tag=as17cb9f84
Call-ID: vm3ZyPp-wcZbfHWdlP227A..
CSeq: 3 REGISTER
Server: FPBX-12.0.76.2(11.20.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="12743c58"
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog 'vm3ZyPp-wcZbfHWdlP227A..' in 32000 ms (Method: REGISTER)

<--- SIP read from UDP:172.16.50.221:5453 --->
REGISTER sip:172.16.1.241 SIP/2.0
Via: SIP/2.0/UDP 172.16.50.221:5453;branch=z9hG4bK-524287-1---6f758b7eb055ea25;rport
Max-Forwards: 70
Contact: <sip:[email protected]:5453>;+sip.instance="<urn:uuid:2BC7C79F-94CB-F846-D74A-773A8D15BB19>";expires=0
To: <sip:[email protected]>
From: <sip:[email protected]>;tag=e1260a03
Call-ID: vm3ZyPp-wcZbfHWdlP227A..
CSeq: 4 REGISTER
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, REGISTER, SUBSCRIBE, INFO
Supported: replaces
User-Agent: PortGo v11.2.2, Build 08102015
Authorization: Digest username="401",realm="asterisk",nonce="12743c58",uri="sip:172.16.1.241",response="f245a712512257a3f6e22c43aeb2c16f",algorithm=MD5
Content-Length: 0

<------------->
--- (13 headers 0 lines) ---
Sending to 172.16.50.221:5453 (no NAT)
    -- Unregistered SIP '401'

<--- Transmitting (no NAT) to 172.16.50.221:5453 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.50.221:5453;branch=z9hG4bK-524287-1---6f758b7eb055ea25;received=172.16.50.221;rport=5453
From: <sip:[email protected]>;tag=e1260a03
To: <sip:[email protected]>;tag=as17cb9f84
Call-ID: vm3ZyPp-wcZbfHWdlP227A..
CSeq: 4 REGISTER
Server: FPBX-12.0.76.2(11.20.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 0
Date: Tue, 17 Nov 2015 08:29:03 GMT
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog 'vm3ZyPp-wcZbfHWdlP227A..' in 32000 ms (Method: REGISTER)

And here is when i terminate 402:

FreePBX-FSI*CLI> sip set debug peer 402
SIP Debugging Enabled for IP: 172.16.50.221

<--- SIP read from UDP:172.16.50.221:50934 --->
REGISTER sip:172.16.1.241:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.50.221:50934;branch=z9hG4bK-d8754z-2e6bab00bd63bc7c-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:[email protected]:50934;rinstance=15aada7883483cb6>;expires=0
To: "402"<sip:[email protected]:5060>
From: "402"<sip:[email protected]:5060>;tag=e514d312
Call-ID: ZmNjNzE5ZjcwNTFlNTQ5OWEyMTg0NWI3ODkzNzliYjA.
CSeq: 3 REGISTER
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Supported: replaces
User-Agent: 3CXPhone 6.0.26523.0
Authorization: Digest username="402",realm="asterisk",nonce="61fde888",uri="sip:172.16.1.241:5060",response="45c3e446e0964ab2f1b5c80343cfdd24",algorithm=MD5
Content-Length: 0

<------------->
--- (13 headers 0 lines) ---
Sending to 172.16.50.221:50934 (NAT)
Sending to 172.16.50.221:50934 (NAT)

<--- Transmitting (no NAT) to 172.16.50.221:50934 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 172.16.50.221:50934;branch=z9hG4bK-d8754z-2e6bab00bd63bc7c-1---d8754z-;received=172.16.50.221;rport=50934
From: "402"<sip:[email protected]:5060>;tag=e514d312
To: "402"<sip:[email protected]:5060>;tag=as71d81869
Call-ID: ZmNjNzE5ZjcwNTFlNTQ5OWEyMTg0NWI3ODkzNzliYjA.
CSeq: 3 REGISTER
Server: FPBX-12.0.76.2(11.20.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="42075cbf"
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog 'ZmNjNzE5ZjcwNTFlNTQ5OWEyMTg0NWI3ODkzNzliYjA.' in 32000 ms (Method: REGISTER)

<--- SIP read from UDP:172.16.50.221:50934 --->
REGISTER sip:172.16.1.241:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.50.221:50934;branch=z9hG4bK-d8754z-4a13e96e64602c01-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:[email protected]:50934;rinstance=15aada7883483cb6>;expires=0
To: "402"<sip:[email protected]:5060>
From: "402"<sip:[email protected]:5060>;tag=e514d312
Call-ID: ZmNjNzE5ZjcwNTFlNTQ5OWEyMTg0NWI3ODkzNzliYjA.
CSeq: 4 REGISTER
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Supported: replaces
User-Agent: 3CXPhone 6.0.26523.0
Authorization: Digest username="402",realm="asterisk",nonce="42075cbf",uri="sip:172.16.1.241:5060",response="05f485334d5eb4b30a744d5a2a1f5845",algorithm=MD5
Content-Length: 0

<------------->
--- (13 headers 0 lines) ---
Sending to 172.16.50.221:50934 (no NAT)
    -- Unregistered SIP '402'

<--- Transmitting (no NAT) to 172.16.50.221:50934 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.50.221:50934;branch=z9hG4bK-d8754z-4a13e96e64602c01-1---d8754z-;received=172.16.50.221;rport=50934
From: "402"<sip:[email protected]:5060>;tag=e514d312
To: "402"<sip:[email protected]:5060>;tag=as71d81869
Call-ID: ZmNjNzE5ZjcwNTFlNTQ5OWEyMTg0NWI3ODkzNzliYjA.
CSeq: 4 REGISTER
Server: FPBX-12.0.76.2(11.20.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 0
Date: Tue, 17 Nov 2015 08:29:23 GMT
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog 'ZmNjNzE5ZjcwNTFlNTQ5OWEyMTg0NWI3ODkzNzliYjA.' in 32000 ms (Method: REGISTER)
  == Extension Changed 402[ext-local] new state Unavailable for Notify User 405
Really destroying SIP dialog 'ZmNjNzE5ZjcwNTFlNTQ5OWEyMTg0NWI3ODkzNzliYjA.' Method: REGISTER

AND one more thing i observed:

 -- Registered SIP '401' at 172.16.50.221:8881
       > Saved useragent "PortGo v11.2.2, Build 08102015" for peer 401
[2015-11-17 10:25:13] NOTICE[2164]: chan_sip.c:23739 handle_response_peerpoke: Peer '401' is now Reachable. (50ms / 2000ms)
[2015-11-17 10:25:28] NOTICE[2164]: chan_sip.c:16582 check_auth: Correct auth, but based on stale nonce received from '<sip:[email protected]>;tag=2449bf72'
    -- Unregistered SIP '401'
[2015-11-17 10:25:28] NOTICE[2164]: chan_sip.c:16582 check_auth: Correct auth, but based on stale nonce received from '<sip:[email protected]>;tag=3a657b5a'
[2015-11-17 10:25:28] NOTICE[2164]: chan_sip.c:16582 check_auth: Correct auth, but based on stale nonce received from '<sip:[email protected]>;tag=52407443'
    -- Registered SIP '401' at 172.16.50.221:8946
[2015-11-17 10:25:35] NOTICE[2164]: chan_sip.c:16582 check_auth: Correct auth, but based on stale nonce received from '<sip:[email protected]>;tag=033df212'
    -- Unregistered SIP '401'

18.11.2015 - since no responses, i think this is hard to solve… sad.

.
Tried to add in [from internal] the include => ext-local = No effect.

By default at the extension creation the context field in filled with ‘from-internal’

In ‘subscribecontext’ for peer 405 = nothing, it uses the default context info (from-internal)
In softphone 405 i just add number in contact list and tick the ‘presence subscription’. MicroSIP and Eyebeam.
Tried to change context to ext-local for 401 - no effect.
Tried to change context to ext-local for 405 - no effect, in that case subscription were from ext-local and queue pause hint were no more monitored by softphone.

Can’t understand why other extensions tell about their ‘Unavailable’ state , but those 401 and 403 - no, while other states ‘ringing, In use’… working just normal…

Was just having the same problem with some Yealink phones. Found out on some of the ones that were not working, it has the “SIP Server Type” set to Broadsoft instead of Default. Switching it to Default fixed them.

On the others, the “BLF LED Mode” needed to be changed back to 0.