SIP Presence and BFL Problem, IDLE state when UNKNOWN peer

Hello Everyone!

What i Have:

[root@FreePBX-FSI ~]# cat /etc/schmooze/pbx-version 6.12.65-31 [root@FreePBX-FSI ~]# asterisk -rvvvvvvv Asterisk 11.20.0, Copyright (C) 1999 - 2013 Digium, Inc. and others.

FreePBX was upgraded from 6.12.65-29 (initial installation and configuration was on this, and upgraded to -31 via script as descripbed in freepbx wiki - all fine)

What is the problem:

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
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 403@from-intern Idle pidf+xml <none> 000600 172.16.50.221 405 28d09e3062e7432 405@from-intern Idle pidf+xml <none> 000600 172.16.50.221 405 f5ceca197e7f4e5 *46*402@from-in Idle pidf+xml <none> 000600 172.16.50.221 405 fd58110296024eb 402@from-intern Unavailable pidf+xml <none> 000600 172.16.50.221 405 98b212e2f89247c *46*403@from-in Idle pidf+xml <none> 000600 172.16.50.221 405 f7fca66ebaf846d *46*401@from-in Idle pidf+xml <none> 000600 172.16.50.221 405 68a9a137fc85437 408@from-intern Unavailable pidf+xml <none> 000600 172.16.50.221 405 fa51bdf2c3f140e 401@from-intern Idle pidf+xml <none> 000600 172.16.50.221 405 6a5a6a4a45d04a9 407@from-intern Unavailable pidf+xml <none> 000600 172.16.50.221 405 52d50cabc863414 404@from-intern Unavailable pidf+xml <none> 000600 172.16.50.221 405 e225561ffca94a9 406@from-intern Unavailable pidf+xml <none> 000600 172.16.50.221 405 51d52e679d2146c *46*404@from-in Idle pidf+xml <none> 000600 12 active SIP subscriptions

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

As you can see 403@ and 401@ 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:

401@ext-local : SIP/401&Custom:DND40 State:Idle Watchers 1 403@ext-local : SIP/403&Custom:DND40 State:Idle Watchers 1 402@ext-local : SIP/402&Custom:DND40 State:Unavailable Watchers 1 405@ext-local : SIP/405&Custom:DND40 State:Idle Watchers 1 404@ext-local : SIP/404&Custom:DND40 State:Unavailable Watchers 1 407@ext-local : SIP/407&Custom:DND40 State:Unavailable Watchers 1 406@ext-local : SIP/406&Custom:DND40 State:Unavailable Watchers 1 408@ext-local : 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 (didn’t touch settings i don’t know/don’t need). 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:401@172.16.50.221:5453>;+sip.instance="<urn:uuid:2BC7C79F-94CB-F846-D74A-773A8D15BB19>";expires=0 To: <sip:401@172.16.1.241> From: <sip:401@172.16.1.241>;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:401@172.16.1.241>;tag=e1260a03 To: <sip:401@172.16.1.241>;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:401@172.16.50.221:5453>;+sip.instance="<urn:uuid:2BC7C79F-94CB-F846-D74A-773A8D15BB19>";expires=0 To: <sip:401@172.16.1.241> From: <sip:401@172.16.1.241>;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:401@172.16.1.241>;tag=e1260a03 To: <sip:401@172.16.1.241>;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:402@172.16.50.221:50934;rinstance=15aada7883483cb6>;expires=0 To: "402"<sip:402@172.16.1.241:5060> From: "402"<sip:402@172.16.1.241: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:402@172.16.1.241:5060>;tag=e514d312 To: "402"<sip:402@172.16.1.241: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:402@172.16.50.221:50934;rinstance=15aada7883483cb6>;expires=0 To: "402"<sip:402@172.16.1.241:5060> From: "402"<sip:402@172.16.1.241: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:402@172.16.1.241:5060>;tag=e514d312 To: "402"<sip:402@172.16.1.241: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:401@172.16.1.241>;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:401@172.16.1.241>;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:401@172.16.1.241>;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:401@172.16.1.241>;tag=033df212' -- Unregistered SIP '401'

Pleaase help. :neutral_face:

I don’t know FreePBX, but is ext-local included in from-inter…?

[from-internal-sip] ;I assume
include => ext-local

[quote=“mkozusnik”]I don’t know FreePBX, but is ext-local included in from-inter…?

[from-internal-sip] ;I assume
include => ext-local[/quote]

included ext-local in [from-internal]
No change.

The interesting thing is that only those 2 extensions 401 and 403 don’t go in Unavailable state when sip show peers = UNKNOWN… other 402, 404,405 etc… anything OK with them, even if contexts differ.

But other states are advertising just normal (Ringing, In Use and so on…).

When i create extension from GUI, by default the Context field is filled with the ‘from-internal’…
I tried to change this to ext-local:
for 401 - the one with problem
for 405 - the one which subscribes to monitor states (in that case i dont more see the queue pause states)

Still no effect…