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:
*273@timeconditions-: Custom:TC3 State:Idle Presence:not_set Watchers 0
deactivated:
*273@timeconditions-: 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 1000@from-inter Idle dialog-info+xml 000600
10.30.0.106 1006 2fde2e4acd8fe00 *280@from-inter Idle dialog-info+xml 000605
10.30.0.106 1006 1d0ef5194d0386e 1002@from-inter Idle dialog-info+xml 000600
10.30.0.106 1006 87865fd87a1551c 1001@from-inter InUse dialog-info+xml 000592
10.30.0.106 1006 5475775f0dbc059 *273@from-inter Idle dialog-info+xml 000611
10.30.0.106 1006 704be09f369e566 1004@from-inter 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
00401@ext-local : SCCP/00401&Custom:DN State:Idle Presence:not_set Watchers 0
_46XXXXX30002@ext: Queue:${EXTEN:10}_pa State:Unavailable Presence: Watchers 0
_45XXXXXXXX@ext-qu: 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
> E..4zX..@...
> ..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`..c...@..?
> ..
> ..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
> E..4.9..@...
> ..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`..c...@...
> ..
> ..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: 0I 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 1000@from-inter Idle dialog-info+xml <none> 000590
10.30.0.111 1004 fca4edce8f87f2e 1001@from-inter Idle dialog-info+xml <none> 000601
10.30.0.106 1006 fc41bda531749aa 1000@from-inter Idle dialog-info+xml <none> 000589
10.30.0.106 1006 1bf156abdb9bb20 *273@from-inter Idle dialog-info+xml <none> 000594
10.30.0.111 1004 2531fc00f3456af *273@from-inter Idle dialog-info+xml <none> 000610
10.30.0.106 1006 6cded5b7ef50173 1002@from-inter Idle dialog-info+xml <none> 000607
10.30.0.111 1004 c1269b395212639 1002@from-inter Idle dialog-info+xml <none> 000592
10.30.0.113 1013 [email protected] -- <none> mwi 1013@devic 003600
10.30.0.111 1004 1f2e8f841f5b679 *280@from-inter Idle dialog-info+xml <none> 000597
10.30.0.106 1006 0798a0ef36c7eeb 1001@from-inter Idle dialog-info+xml <none> 000609
10.30.0.106 1006 93e6e430aab575d *280@from-inter Idle dialog-info+xml <none> 000595
10.30.0.106 1006 74631fd2417ddee 1004@from-inter Idle dialog-info+xml <none> 000594
10.30.0.111 1004 55d703eb74342af 1006@from-inter 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.