Digium Phone Provisioning Hangs at fetching user list

Commercial Products and Partners Digium
1

Hello, I am running FreePBX 2.11 with the DPMA version 1.6.0. Phone Provision was working fine but I went to configure a new phone last week and the phone now hangs at “Fetching User List”, I tried other phones with the same result. I tried watching the Asterisk console during the process however I get no errors or anything to suggest any thing is wrong. Phones that have already been configured work fine and I am able to reconfigure them without issue.

I’ve opened a ticket with digium however, they have been pretty unresponsive lately. So far based on digiums suggestions, I’ve updated said phones firmware to 1.4.2 and I’ve updated DPMA to 2.1.0. to my knowledge nothing has changed on the server or the network that would cause this.

My biggest problem at this point is that I just don’t know where else to look for problems or indicators to identify the problem. I’ve run packet captures but I don’t exactly know what I’m looking at or for. I can’t find any other logs and it seems that the syslog client on the phone is not yet running when the phone is provisioning.

Please Someone Help!

2

Does the multicast address provided by the DPMA configuration match the actual SIP address that the phone would use to contact the server?

3

Yes, and for what its worth we aren’t using multicast. The phones are on a separate subnet than the server and we aren’t using DHCP option 66 so the phones are manually pointed at FreePBX.

4

There’s nothing that’s changed between 1.6 and 2.1 in the basic handling of communications between DPMA + Asterisk and the phone. I’d make sure that your license is still valid:

https://wiki.asterisk.org/wiki/display/DIGIUM/DPMA+and+the+Asterisk+CLI#DPMAandtheAsteriskCLI-CheckingLicenseStatus

Then I’d look to see if you see SIP MESSAGE traffic from the phone on the Asterisk CLI, and I’d look to see if the response packets are going back to the phone, or not. Perhaps there’s a new router in the middle that’s gobbling SIP MESSAGE traffic with a “smart” ALG capability.

I’d make sure that the Network (https://wiki.asterisk.org/wiki/display/DIGIUM/DPMA+Configuration#DPMAConfiguration-NetworkConfigurationOptions) that you’re applying to the phone profile matches the network segment the phone’s on (just use 0.0.0.0/0 as the cidr for easiest results).

If you’re getting a message requesting a config password and the one you’ve set as the global pin isn’t being accepted, make sure that there are actually phone profiles that have been created:

https://wiki.asterisk.org/wiki/display/DIGIUM/DPMA+and+the+Asterisk+CLI#DPMAandtheAsteriskCLI-ReconfiguringPhones

There a myriad ways for things to go wrong, so the best thing to do is start at the beginning and work forward. Also, if you’re using the Digium Phone Add-on for FreePBX, you’ll want to make sure you’re on the most current version of it and you may want to even compare the generated output of it to what you should be seeing, based on:
https://wiki.asterisk.org/wiki/display/DIGIUM/DPMA+Configuration

Also, if you’re running on a non-standard port, make sure you entered that when you selected “Digium Phone Config Server” from the phone’s Settings boot menu. And, I’d recommend you go ahead and factory default the phone just in case there’s been any attempt to configure it via multiple config methods simultaneously, which can result in unexpected behavior.

Cheers

5

Ok so taken your advice and I’ve gone through all of the configuration with a fine toothed comb, either nothing is wrong with it or I’ve been blinded to it…

My license is OK, the config is OK, there is nothing going on with the network (if I put the phone on the same subnet as the freepbx server it still hangs on “fetching user list”), we are using the standard port and the phone has been factory reset.

I also have a dump from the asterisk console when the problem occurs but nothing is jumping out at me (no big Red or Yellow warnings). I guess I’m not exactly sure what I’m looking at there either though. I’ll post it at the bottom of this post.

One other thing that I’ve failed to mention is that I do have Easy mode disabled. I’ve thought about enabling it again just for testing but I have 74 phones deployed and don’t want to go through and manually reconfigure each one of them. And from previous experience I learned that enabling easy mode again dumps the advanced configuration for each device (kind of a PITA with the GUI).

Anyway here is the dump from asterisk (phones address ends in .1.170 PBX address ends in .9.30):

-- Executing [proxy@dpma_message_context:1] Set("Message/ast_msg_queue", "MESSAGE(custom_data)=mark_all_outbound") in new stack
-- Executing [proxy@dpma_message_context:2] Set("Message/ast_msg_queue", "MESSAGE_DATA(X-Digium-AppServer-Response-URI)=sip:192.168.1.170:5060") in new stack
-- Executing [proxy@dpma_message_context:3] Set("Message/ast_msg_queue", "MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=sip:192.168.1.170:5060;ob") in new stack
-- Executing [proxy@dpma_message_context:4] MessageSend("Message/ast_msg_queue", "digium_phone:blah") in new stack
-- Executing [proxy@dpma_message_context:5] Hangup("Message/ast_msg_queue", "") in new stack

== Spawn extension (dpma_message_context, proxy, 5) exited non-zero on ‘Message/ast_msg_queue’
– Executing [digium_phone_module@dpma_message_context:1] Set(“Message/ast_msg_queue”, “MESSAGE(custom_data)=mark_all_outbound”) in new stack
– Executing [digium_phone_module@dpma_message_context:2] Set(“Message/ast_msg_queue”, “TMP_RESPONSE_URI=sip:192.168.1.170:5060”) in new stack
– Executing [digium_phone_module@dpma_message_context:3] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(Request-URI)=sip:192.168.1.170:5060;ob”) in new stack
– Executing [digium_phone_module@dpma_message_context:4] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-URI)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:5] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:6] MessageSend(“Message/ast_msg_queue”, “sip:192.168.1.170:5060,proxy”) in new stack
– Executing [digium_phone_module@dpma_message_context:7] Hangup(“Message/ast_msg_queue”, “”) in new stack
[2014-10-27 18:30:10] WARNING[2443][C-00000000]: channel.c:1309 __ast_queue_frame: Exceptionally long queue length queuing to Message/ast_msg_queue
[2014-10-27 18:30:10] WARNING[2443][C-00000000]: channel.c:1309 __ast_queue_frame: Exceptionally long queue length queuing to Message/ast_msg_queue
== Spawn extension (dpma_message_context, digium_phone_module, 7) exited non-zero on ‘Message/ast_msg_queue’
– Executing [proxy@dpma_message_context:1] Set(“Message/ast_msg_queue”, “MESSAGE(custom_data)=mark_all_outbound”) in new stack
– Executing [proxy@dpma_message_context:2] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-URI)=sip:192.168.1.170:5060”) in new stack
– Executing [proxy@dpma_message_context:3] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=sip:192.168.1.170:5060;ob”) in new stack
– Executing [proxy@dpma_message_context:4] MessageSend(“Message/ast_msg_queue”, “digium_phone:blah”) in new stack
– Executing [proxy@dpma_message_context:5] Hangup(“Message/ast_msg_queue”, “”) in new stack
== Spawn extension (dpma_message_context, proxy, 5) exited non-zero on ‘Message/ast_msg_queue’
– Executing [digium_phone_module@dpma_message_context:1] Set(“Message/ast_msg_queue”, “MESSAGE(custom_data)=mark_all_outbound”) in new stack
– Executing [digium_phone_module@dpma_message_context:2] Set(“Message/ast_msg_queue”, “TMP_RESPONSE_URI=sip:192.168.1.170:5060”) in new stack
– Executing [digium_phone_module@dpma_message_context:3] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(Request-URI)=sip:192.168.1.170:5060;ob”) in new stack
– Executing [digium_phone_module@dpma_message_context:4] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-URI)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:5] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:6] MessageSend(“Message/ast_msg_queue”, “sip:192.168.1.170:5060,proxy”) in new stack
– Executing [digium_phone_module@dpma_message_context:7] Hangup(“Message/ast_msg_queue”, “”) in new stack
== Spawn extension (dpma_message_context, digium_phone_module, 7) exited non-zero on ‘Message/ast_msg_queue’
– Executing [digium_phone_module@dpma_message_context:1] Set(“Message/ast_msg_queue”, “MESSAGE(custom_data)=mark_all_outbound”) in new stack
– Executing [digium_phone_module@dpma_message_context:2] Set(“Message/ast_msg_queue”, “TMP_RESPONSE_URI=sip:192.168.1.170:5060”) in new stack
– Executing [digium_phone_module@dpma_message_context:3] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(Request-URI)=sip:192.168.1.170:5060;ob”) in new stack
– Executing [digium_phone_module@dpma_message_context:4] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-URI)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:5] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:6] MessageSend(“Message/ast_msg_queue”, “sip:192.168.1.170:5060,proxy”) in new stack
– Executing [digium_phone_module@dpma_message_context:7] Hangup(“Message/ast_msg_queue”, “”) in new stack
== Spawn extension (dpma_message_context, digium_phone_module, 7) exited non-zero on ‘Message/ast_msg_queue’
– Executing [digium_phone_module@dpma_message_context:1] Set(“Message/ast_msg_queue”, “MESSAGE(custom_data)=mark_all_outbound”) in new stack
– Executing [digium_phone_module@dpma_message_context:2] Set(“Message/ast_msg_queue”, “TMP_RESPONSE_URI=sip:192.168.1.170:5060”) in new stack
– Executing [digium_phone_module@dpma_message_context:3] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(Request-URI)=sip:192.168.1.170:5060;ob”) in new stack
– Executing [digium_phone_module@dpma_message_context:4] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-URI)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:5] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:6] MessageSend(“Message/ast_msg_queue”, “sip:192.168.1.170:5060,proxy”) in new stack
– Executing [digium_phone_module@dpma_message_context:7] Hangup(“Message/ast_msg_queue”, “”) in new stack
== Spawn extension (dpma_message_context, digium_phone_module, 7) exited non-zero on ‘Message/ast_msg_queue’
– Executing [digium_phone_module@dpma_message_context:1] Set(“Message/ast_msg_queue”, “MESSAGE(custom_data)=mark_all_outbound”) in new stack
– Executing [digium_phone_module@dpma_message_context:2] Set(“Message/ast_msg_queue”, “TMP_RESPONSE_URI=sip:192.168.1.170:5060”) in new stack
– Executing [digium_phone_module@dpma_message_context:3] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(Request-URI)=sip:192.168.1.170:5060;ob”) in new stack
– Executing [digium_phone_module@dpma_message_context:4] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-URI)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:5] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:6] MessageSend(“Message/ast_msg_queue”, “sip:192.168.1.170:5060,proxy”) in new stack
– Executing [digium_phone_module@dpma_message_context:7] Hangup(“Message/ast_msg_queue”, “”) in new stack
== Spawn extension (dpma_message_context, digium_phone_module, 7) exited non-zero on ‘Message/ast_msg_queue’
– Executing [digium_phone_module@dpma_message_context:1] Set(“Message/ast_msg_queue”, “MESSAGE(custom_data)=mark_all_outbound”) in new stack
– Executing [digium_phone_module@dpma_message_context:2] Set(“Message/ast_msg_queue”, “TMP_RESPONSE_URI=sip:192.168.1.170:5060”) in new stack
– Executing [digium_phone_module@dpma_message_context:3] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(Request-URI)=sip:192.168.1.170:5060;ob”) in new stack
– Executing [digium_phone_module@dpma_message_context:4] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-URI)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:5] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:6] MessageSend(“Message/ast_msg_queue”, “sip:192.168.1.170:5060,proxy”) in new stack
– Executing [digium_phone_module@dpma_message_context:7] Hangup(“Message/ast_msg_queue”, “”) in new stack
== Spawn extension (dpma_message_context, digium_phone_module, 7) exited non-zero on ‘Message/ast_msg_queue’
– Executing [digium_phone_module@dpma_message_context:1] Set(“Message/ast_msg_queue”, “MESSAGE(custom_data)=mark_all_outbound”) in new stack
– Executing [digium_phone_module@dpma_message_context:2] Set(“Message/ast_msg_queue”, “TMP_RESPONSE_URI=sip:192.168.1.170:5060”) in new stack
– Executing [digium_phone_module@dpma_message_context:3] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(Request-URI)=sip:192.168.1.170:5060;ob”) in new stack
– Executing [digium_phone_module@dpma_message_context:4] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-URI)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:5] Set(“Message/ast_msg_queue”, “MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=”) in new stack
– Executing [digium_phone_module@dpma_message_context:6] MessageSend(“Message/ast_msg_queue”, “sip:192.168.1.170:5060,proxy”) in new stack
– Executing [digium_phone_module@dpma_message_context:7] Hangup(“Message/ast_msg_queue”, “”) in new stack
== Spawn extension (dpma_message_context, digium_phone_module, 7) exited non-zero on ‘Message/ast_msg_queue’
– Executing [proxy@dpma_message_contex

6

Were I troubleshooting, I’d take your res_digium_phone*.conf, sip*.conf and extensions*.conf files, load them on another machine and try to reproduce the problem. I’d also look at the actual SIP MESSAGE packets (via SIP debug from the Asterisk CLI) to see if things were perhaps going to an improper location.

Do you see SIP OKs from 192.168.1.170 (I presume the phone) as it responds to MESSAGE packets from Asterisk?

1 Like
7

Ok so I was able to replicate the results on my FreePBX server at home by loading(replacing) /etc/asterisk/res_digium_phones_devices.conf from the server in question (9.30). The problem does go away after reloading the original copy. So this definitely appears to be a problem with res_digium_phones_devices.conf.

I would imagine the best thing to do now is to start taking chunks out of the config until I can identify the problem.

I did notice one potential problem though, it appears that the FreePBX module is not loading the config into the phone admin page so none of the config edits appear in the GUI. How does the FreePBX module determine what is displayed on the GUI? I did try a core reload and a reboot and the config changes are not replicated in the GUI.

8

Yup, if you can diff it and find out what the offender is, that’d be great.

None of the config edits appear in the GUI? What GUI?

9

Unfortunately, diff wont work here, this is the configuration file for all of the phones. I don’t have the same extensions or phones at home as I do at work. Looks like I have to take the long road.

The GUI I’m referring to is the FreePBX GUI more specifically the Digium Phone Configuration GUI, its how I setup all of my phones, screenshot below. I’m concerned because the GUI doesn’t seem to pull values from the configuration and then display them I’m guessing it just remembers what you’ve done inside it. If I change the config and the GUI doesn’t update it could lead to inconsistencies.

10

Correct, changing the raw config files doesn’t mean a whole lot since the FreePBX Add-on will rebuild the config based on the DB with every press of the red button.

11

I ended up deleting phone configurations through freepbx until the test phone was able to fetch the user list.
Unfortunately this resulted in every deleted phone going down and needing to be rebuilt. I wouldn’t recommend this method to any one experiencing the same problem but the problem had persisted so long that it had to be properly resolved intermediately.

Thank you VERY much malcom for all of your help, I wish digium support would have been as helpful.

12

hrm…that’s weird. I don’t know why that would fix anything… :frowning:

I can say that once a phone profile has been claimed by a phone, you won’t see it in the default filter for available/unused phones in the list. If you change the filter, you can see phones already claimed, or you can type in that phone’s phone profile number, and you should see it.

13

I finally figured this out, it had absolutely nothing to do with the digium phone config. I traced this back to an extension, whenever the extension was associated with a phone config it broke provisioning. The extension in question had not been used for quite sometime so when I deleted all my phone configurations (in batches of 5 at a time) I eventually deleted the phone configuration associated with the bad extension. Last week the bad extension needed to be added to a new phone, as soon as I added it provisioning broke. If someone else has this problem the easiest way to find the bad extension is to go through and remove extensions from the phone configs until it works, then delete and recreate the extension and add it back to the phone config.