BLF lights continue to be a problem?

Hello,

With recent versions of FreePBX (currently FreePBX 13.0.189) and using all 6757i phones. Restarting the phones seems to fix it for awhile, but then it will stop working again in a day or two?

Any suggestions on debugging strategies?

-jr

If rebooting the phone fixes it then its a issue in the phone. I would start with aastra on that since rebooting the phone does not make the PBX change something.

Thanks Tony. I suspect that the Endpoint Manager upgraded firmware on the phones? Never had this problem until a few months ago when we upgraded.

I don’t think Aastra supports these phones anymore… Hate to have to buy all new phones just for this issue…

-jr

EPM does not upgrade firmware do you. You control 100% in the Firmware section of EPM what firmware the phone uses and we NEVER change those on EPM upgrading. You manually have to control that and drag out and in firmware versions.

Thank you Tony…

I’d like to try and debug this further. I really do not think it is the Aastra phones. I am seeing this in the logs when I activate the time condition via button on the phone.

In my case, I have a button which does *273 to activate/deactivate the time condition…

2016-11-22 09:39:27] WARNING[16138][C-00000001]: ast_expr2.fl:470 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected ‘>’, expecting $end; Input:

0
^
[2016-11-22 09:39:27] WARNING[16138][C-00000001]: ast_expr2.fl:474 ast_yyerror: If you have questions, please refer to https://wiki.asterisk.org/wiki/display/AST/Channel+Variables
[2016-11-22 09:39:36] WARNING[16160][C-00000002]: ast_expr2.fl:470 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected ‘>’, expecting $end; Input:
0
^
[2016-11-22 09:39:36] WARNING[16160][C-00000002]: ast_expr2.fl:474 ast_yyerror: If you have questions, please refer to https://wiki.asterisk.org/wiki/display/AST/Channel+Variables
[2016-11-22 09:40:01] WARNING[16201][C-00000003]: ast_expr2.fl:470 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected ‘>’, expecting $end; Input:
0
^
[2016-11-22 09:40:01] WARNING[16201][C-00000003]: ast_expr2.fl:474 ast_yyerror: If you have questions, please refer to https://wiki.asterisk.org/wiki/display/AST/Channel+Variables
[2016-11-22 09:40:05] WARNING[16203][C-00000004]: ast_expr2.fl:470 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected ‘>’, expecting $end; Input:
0
^
[2016-11-22 09:40:05] WARNING[16203][C-00000004]: ast_expr2.fl:474 ast_yyerror: If you have questions, please refer to https://wiki.asterisk.org/wiki/display/AST/Channel+Variables
[2016-11-22 09:40:24] NOTICE[16224][C-00000005]: func_audiohookinherit.c:64 func_inheritance_write: AUDIOHOOK_INHERIT is deprecated and now does nothing.

core show hints is showing that the state is changing…

activated:

*[email protected]: Custom:TC3 State:Idle Presence:not_set Watchers 0

deactivated:

*[email protected]: Custom:TC3 State:InUse Presence:not_set Watchers 0

When the BLFs aren’t working I have zero subscriptions… When I reboot a phone I get subscriptions again and the device works.

Peer User Call ID Extension Last state Type Mailbox Expiry
10.30.0.106 1006 76399b134258773 [email protected] Idle dialog-info+xml 000600
10.30.0.106 1006 2fde2e4acd8fe00 *[email protected] Idle dialog-info+xml 000605
10.30.0.106 1006 1d0ef5194d0386e [email protected] Idle dialog-info+xml 000600
10.30.0.106 1006 87865fd87a1551c [email protected] InUse dialog-info+xml 000592
10.30.0.106 1006 5475775f0dbc059 *[email protected] Idle dialog-info+xml 000611
10.30.0.106 1006 704be09f369e566 [email protected] InUse dialog-info+xml 000591
6 active SIP subscriptions

Any other thoughts or debugging directions?

Exactly

The phone has to do the subscription to Asterisk and tell it that it wants to subscribe. Those are only lost in Asterisk if you restart Asterisk and Aastra only does a subscribe on boot so if after you boot the phone and you restart asterisk then your subscriptions are lost with aastra phones.

Ok, Tony understood.

How can I watch the subscriptions via console (and not having to wireshark it) to see what the phone is actually doing?

This all used to work just fine in previous versions of FreePBX. I don’t know why it stopped working, but I’m committed to trying to figure it out. I now do I have an application sitting on AMI for some screen pop stuff, don’t know if that could have impacted it somehow, but I doubt it…

I’ve upgraded one phone to a later firmware using EPM, so I’m going to see how this works… If the theory is correct of the phones not re-subscribing then they should fail fast in about 5 minutes or so?

-jr

No you missed what I wrote. I said when you restart asterisk your subscriptions are lost. Asterisk has always done this. So if the phone is booted and lights are working. Restart Asterisk because you upgrade or whatever reason Asterisk no longer has the subscription. Aastra phones only subscribe on boot where most other phones resubscribe when they re-register to make sure all the hints are their.

Ok, thank you for clarifying. I understand now. So, perhaps Asterisk is getting restarted for updates and that is when the subscription loss is happening.

I’ve run some tcpdumps on the asterisk machine and been watching the SUBSCRIPTIONS and it is subscribing multiple times over a period of time. This is on the phone with the newer firmware image I just updated. Perhaps the issue has been fixed. There is also the "sip blf subscription period: “600"” option in the configuration which would be configuration option for these re-subscriptions.

Also – the reason why it might not have been happening with older installations is they weren’t being updated or restarted.

I appreciate the dialog. At least now I know what seems to be happening so I can further troubleshoot it… Perhaps upgrading the firmware has fixed it.

-jr

It bears repeating that this hint is incomplete. It’s too long to be displayed in Asterisk - the only way I’ve ever found to get the entire text was groveling through the time conditions source code.

I submitted a ticket about shortening this hint about a million years ago and was told “No”.

I was wondering the same, it seems my hints are too long to be displayed as well and I am unable to find where the full string is located.

_96X.@ext-cf-hints : Custom:DEVCF${EXTEN: State:Unavailable Presence: Watchers 0
[email protected] : SCCP/00401&Custom:DN State:Idle Presence:not_set Watchers 0
_46XXXXX
[email protected]: Queue:${EXTEN:10}_pa State:Unavailable Presence: Watchers 0
_45XXX[email protected]: Custom:QUEUE${EXTEN: State:Unavailable Presence: Watchers 0

So, I am seeing the phone issue the SUBSCRIBE for the hint every couple minutes as expected. Doesn’t this disprove the idea that the phone is only subscribing once at startup?

First @ 14:25… Then @ 14:33

> 2016-11-22 14:25:48.936138 IP 10.30.0.104.sip > 10.30.0.10.sip: UDP, length 792
> [email protected]
> ..h
> ..
> ..... z.SUBSCRIBE sip:*[email protected]:5060 SIP/2.0
> Accept: application/dialog-info+xml
> Via: SIP/2.0/UDP 10.30.0.104;branch=z9hG4bK7e9957be945d8bd28
> Max-Forwards: 70
> From: "1000" <sip:[email protected]:5060>;tag=94f7f775ec
> To: <sip:*[email protected]:5060>;tag=as2643f534
> Call-ID: d79c4b5a38893610
> CSeq: 2100 SUBSCRIBE
> Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO
> Allow-Events: aastra-xml, talk, hold, conference, LocalModeStatus
> Authorization: Digest username="1000",realm="asterisk",nonce="09e0d1ad",uri="sip:*[email protected]:5060",response="88411cdf418351eac9c60f20ce3b719c",algorithm=MD5
> Contact: "1000" <sip:[email protected]:5060;transport=udp>
> Event: dialog
> Expires: 600
> Supported: path
> User-Agent: Aastra 57i/3.2.2.2063
> Content-Length: 0


> 2016-11-22 14:25:48.936396 IP 10.30.0.10.sip > 10.30.0.104.sip: UDP, length 499
> E`[email protected]?
> ..

> ..h........SIP/2.0 200 OK
> Via: SIP/2.0/UDP 10.30.0.104;branch=z9hG4bK7e9957be945d8bd28;received=10.30.0.104;rport=5060
> From: "1000" <sip:[email protected]:5060>;tag=94f7f775ec
> To: <sip:*[email protected]:5060>;tag=as2643f534
> Call-ID: d79c4b5a38893610
> CSeq: 2100 SUBSCRIBE
> Server: FPBX-13.0.190.2(13.7.0)
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
> Supported: replaces, timer
> Expires: 600
> Contact: <sip:*[email protected]:5060>;expires=600
> Content-Length: 0





> 2016-11-22 14:33:49.089258 IP 10.30.0.104.sip > 10.30.0.10.sip: UDP, length 792
> [email protected]
> ..h
> ..
> ..... ..SUBSCRIBE sip:*[email protected]:5060 SIP/2.0
> Accept: application/dialog-info+xml
> Via: SIP/2.0/UDP 10.30.0.104;branch=z9hG4bK9326d6ce3592fbd9d
> Max-Forwards: 70
> From: "1000" <sip:[email protected]:5060>;tag=94f7f775ec
> To: <sip:*[email protected]:5060>;tag=as2643f534
> Call-ID: d79c4b5a38893610
> CSeq: 2102 SUBSCRIBE
> Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO
> Allow-Events: aastra-xml, talk, hold, conference, LocalModeStatus
> Authorization: Digest username="1000",realm="asterisk",nonce="6712f293",uri="sip:*[email protected]:5060",response="5afee33cad2afa5bf255068d1bd04edb",algorithm=MD5
> Contact: "1000" <sip:[email protected]:5060;transport=udp>
> Event: dialog
> Expires: 600
> Supported: path
> User-Agent: Aastra 57i/3.2.2.2063
> Content-Length: 0


> 2016-11-22 14:33:49.089568 IP 10.30.0.10.sip > 10.30.0.104.sip: UDP, length 499
> E`[email protected]
> ..

> ..h........SIP/2.0 200 OK
> Via: SIP/2.0/UDP 10.30.0.104;branch=z9hG4bK9326d6ce3592fbd9d;received=10.30.0.104;rport=5060
> From: "1000" <sip:[email protected]:5060>;tag=94f7f775ec
> To: <sip:*[email protected]:5060>;tag=as2643f534
> Call-ID: d79c4b5a38893610
> CSeq: 2102 SUBSCRIBE
> Server: FPBX-13.0.190.2(13.7.0)
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
> Supported: replaces, timer
> Expires: 600
> Contact: <sip:*[email protected]:5060>;expires=600
> Content-Length: 0

I have not used Aastra in a 2 plus years but they historically only subscribed on boot.

Ok, thanks for your help Tony… I’m just trying to figure it out. Perhaps they are subscribing now, but over time they stop. At least at this point I have the tools to troubleshoot a bit further and figure out what is happening either way…

I’ll continue to monitor and report back. The next time it occurs, I’l look for the lack of subscriptions and then do some packet monitoring to see if the SUBSCRIBE messages are still coming in…

So, this morning. I came in to find the two 57i phones I upgraded to 3.3.1.4358 to still have subscriptions, but the other phones to have not have them… The system did not reboot last night…

Tony – any thoughts on why they lost the subscriptions? It was my understanding that they were lost on a restart of Asterisk or do they fall off after a period of time? What is the Expiry column on the show subscriptions?

asterisk*CLI> sip show subscriptions
Peer             User             Call ID          Extension        Last state     Type            Mailbox    Expiry
10.30.0.111      1004             fa5ff5ba32824bd  [email protected]  Idle           dialog-info+xml <none>     000590
10.30.0.111      1004             fca4edce8f87f2e  [email protected]  Idle           dialog-info+xml <none>     000601
10.30.0.106      1006             fc41bda531749aa  [email protected]  Idle           dialog-info+xml <none>     000589
10.30.0.106      1006             1bf156abdb9bb20  *[email protected]  Idle           dialog-info+xml <none>     000594
10.30.0.111      1004             2531fc00f3456af  *[email protected]  Idle           dialog-info+xml <none>     000610
10.30.0.106      1006             6cded5b7ef50173  [email protected]  Idle           dialog-info+xml <none>     000607
10.30.0.111      1004             c1269b395212639  [email protected]  Idle           dialog-info+xml <none>     000592
10.30.0.113      1013             [email protected]  --               <none>         mwi             [email protected] 003600
10.30.0.111      1004             1f2e8f841f5b679  *[email protected]  Idle           dialog-info+xml <none>     000597
10.30.0.106      1006             0798a0ef36c7eeb  [email protected]  Idle           dialog-info+xml <none>     000609
10.30.0.106      1006             93e6e430aab575d  *[email protected]  Idle           dialog-info+xml <none>     000595
10.30.0.106      1006             74631fd2417ddee  [email protected]  Idle           dialog-info+xml <none>     000594
10.30.0.111      1004             55d703eb74342af  [email protected]  Idle           dialog-info+xml <none>     000604
13 active SIP subscriptions
asterisk*CLI> core show uptime
System uptime: 22 hours, 59 minutes, 26 seconds
Last reload: 15 hours, 8 minutes, 8 seconds
asterisk*CLI> 

I’m going to upgrade the other phones and see what happens…

thanks,

-jr

Well if the two you upgraded firmware on are still working that should answer your question. Upgrade your phone firmware.

I have upgraded them.

However, my question was do the Subscriptions expire on the Asterisk end if not renewed? Also, what does the Expiry column represent in the subscription listing.

-jr

Google is your friend for these answers but the expiry comes from your phone telling asterisk how long its good for.

Thanks Tony. I tried to google it, but really couldn’t find an answer. I welcome a link if you have one which explains it.

So, does the expiry value represent how much time is left before the subscription expires? If so, I would expect them to be changing every second or so as I refresh the listing? Also, I would expect them to be all the same value and not +/- 10 around a value of 600.

Happy Thanksgiving Tony. I appreciate the dialog.

-jr

No its from when it sent the last subscribe.