Phone Provisioning (RESOLVED)

Hi,

We have our first set of S500 phones arrive and want to start provisioning them… however looks like the phones are not downloading their xml file from the tftp server, or if they are downloading it, they are not applying settings. Also there appears to be some anomalies in the Endpoint Manager.

Bit of an overview, our switchports are configured with a voice vlan and dot1q tagging and when the phone first boots, its on our workstation vlan, and there is an option 150 set that redirects it to our freepbx server.

The Basefile for all the phones has been edited to contain the correct vLan settings and Directory settings for LDAP directory

A Template has been made for the phones however when changing the “Country Tones” to Australia, clicking save and returning to edit the template, the changes are lost.

When looking in the tftpboot folder, the config files for the various phone MAC’s can be seen, if i view the files, i can see all the custom settings (vlan / LDAP / etc)

However when the phone boots, it does not pull any of these settings.

I can manually set the correct vlan settings on the phone while its on the workstation network and move it to the voice vlan (which also has the correct tftp options set), when the phone reboots, again it doesnt seem to get any of the settings within the config files on the server

if i use my workstation and try to pull the config file with a tftp client, i get the file

i have increased the tftp service verbose settings and can see this in the messages log:

Apr 13 17:49:43 FreePBX in.tftpd[6767]: RRQ from 10.10.10.5 filename sangoma/1/fw500.rom
Apr 13 17:49:44 FreePBX in.tftpd[6767]: tftpd: read(ack): Connection refused

Any ideas why this is happening or whats going on ? i can see the phone pulling the rom but not the config…

Daniel

Just did some further testing, if i put the vlan details back to default (so both the phone and the computer port are on the computer vlan) it works, I can see the device pulling all the config from the TFTP server

When i change the vlan back afterwards, again it fails to pull from TFTP (other than the ROM check). however when the vlan is set as we want it set, the phone happily registers with FreePBX and calls work so from what i can see this isnt a vlan configuration issue

I have not tested with option 150, but I can confirm that option 66 works with an up to date firmware. It looks like this might be a vlan issue, but try provisioning with option 66 first just to rule that out.

So if you are setup with VLAN are you saying the phone never request a Config file? Is your VLAN setup to allow the phone to get to the data side of the PBX?

Thats correct, when the vlan is tagged, the phone does not request the configuration file.

Yes the vlan allows the phone to get to data side of PBX with the vlan tag enabled as i can see the logs on the PBX showing the tftp connection from the tagged vlan IP, i can also see the phone pull the ROM file but not the configuration. Also the phone registers with the PBX and can make calls so the traffic path appears to be working

If there is any more testing i can do to help or info i can provide, please let me know…

Are you able to reproduce the issue ?

i actually have both set on the voice vlan, 150 is only set on the data vlan so preconfig it can get to the pbx, which works 100%

1 Like

Hey Tony,

I tried using LLDP, the vLan applies with the same result…

If there is any more testing i can do to help or info i can provide, please let me know…
Are you able to reproduce the issue ?

Im happy to provide logs / configs to try to resolve this… let me know…

We really want to resolve this asap

I have 4 other customers this week all get VLANs setup without any issues. @SkykingOH was one of them and even updated the wiki http://wiki.freepbx.org/display/PHON/VLAN

Hi Scott here, we are a Sangoma Gold partner and very familiar with the phones.

Please make sure you have version 2.0.4.7 software installed on your phone

Make sure that you your voice server connected to an access port configured for the voice VLAN in your switch

Make sure you set the voice VLAN in the LLDP configuration of your switch (we tested with a Cisco IOS Based switch running IOS 15)

Make sure your option 66 in DHCP is set to the phone servers IP in the voice vlan

Make sure that option 66 is not set on DHCP server in data LAN (especially if you have an administrative route from the data vlan to the voice vlan to access FreePBX and UCP from data VLAN, if you do you might also want an access list limitng the ports that can traverse the vlans)

Make sure your phone ports have 802.1q trunking enabled

Set the voice vlan packets to be tagged and the data vlan untagged

In the EPM make sure LLDP is enabled

I know that’s a lot of “Make sures” however we have extensively tested the LLDP functionality as I believe zero touch installs are the best way to deploy phones.

If you need assistance with these issues, or other enterprise integration of FreePBX, our firm MIcro Advantage offers various remote support and managed service offerings (including hosted FreePBX with OpenVPN support)

Please feel free to contact us with any FreePBX or Sangoma integration, OEM support or managed services.

I will post the switch config to the wiki as a reference.

Scott for clarification the setting of all those make sures for the phone can be done in EPM so the configs in the phones will have the proper vlan tagging.

Hi Scott / Tom,

I had already done each item as listed

  1. 2.0.4.7 - yes this is the version thats running
  2. The FreePBX server is on a different vLan to the phones but its routable with no firewall / etc in the way (see below this cant be the reason as when the phones are on the workstation vlan they work)
  3. LLDP is enabled globally (also cisco switch - C3750G)
  4. Option 66 is set
  5. I did have 66 set on the data vlan, but i removed this and made no difference
  6. Switch phone ports have “switchport trunk encapsulation dot1q” set, voice vlan set and data vlan set
  7. Voice is set to be tagged and data untagged on the phone
  8. LLDP is enabled in EPM

Just to clarify, the phone boots up, LLDP works and the phone switches to the correct voice vlan, gets the correct IP and it registers with the PBX server on the server vlan, the pc connected gets the correct IP from the workstation vlan.

The issue is the phone does not pull the correct files and updates from TFTP. When the phone is on the workstation vlan it pulls the rom file and the configuration xml file. when the phone is on the voice vlan it only pulls the rom file

LLDP info:
show lldp neighbors
Capability codes:
® Router, (B) Bridge, (T) Telephone, © DOCSIS Cable Device
(W) WLAN Access Point, § Repeater, (S) Station, (O) Other

Device ID Local Intf Hold-time Capability Port ID
UC8xx Gi1/0/9 180 B,T 0050.XXXX.XXXX

VoIP server: PBX01 - 192.168.0.16 (vLan 100) the following are from the /var/log/messages file on this machine

TFTP Logs:
Phone on Workstation vLan (vLan 101):
Apr 17 06:27:49 PBX01 in.tftpd[23923]: RRQ from 10.10.1.11 filename factory0500.bin
Apr 17 06:27:49 PBX01 in.tftpd[23924]: RRQ from 10.10.1.11 filename /cfg0500.xml
Apr 17 06:27:50 PBX01 in.tftpd[23931]: RRQ from 10.10.1.11 filename /cfg0050XXXXXXXX
Apr 17 06:27:50 PBX01 in.tftpd[23932]: RRQ from 10.10.1.11 filename /cfg0050XXXXXXXX.xml
Apr 17 06:27:52 PBX01 in.tftpd[23937]: RRQ from 10.10.1.11 filename sangoma/1/fw500.rom

Phone on VoIP vLan (vLan 200):
Apr 17 06:29:14 PBX01 in.tftpd[24026]: RRQ from 10.10.4.14 filename sangoma/1/
Apr 17 06:29:37 PBX01 in.tftpd[24030]: RRQ from 10.10.4.14 filename sangoma/1/fw500.rom

So in both cases, you can see the phone is communicating with the VoIP server, the networking is working but in the second scenario (LLDP enabled) the phone does not pull down its configuration files

When you say the server is in a differnet LAN what is providing DHCP for the voice VLAN?

Does the phone get the correct IP address for that VLAN (indicating the broadcast was properly encapped and decapped, remember VLANs are a layer 2 construct) If you look at the phones status did it get the proper IP of the provisioning server? Can the provisioning server ping the phone?

Are you sure you have LLDP on in the EPM? If you don’t it will pick up the conight and drop the vlan setting.

Do you have verbosity cranked up on the tftp service of the provisioning server, if so what do you see in the logs.

Lastly in addition to the Cisco settings you mentioned do you have a LLDP service policy for the voice vlan and is it applied to the interface the phone is in?

Sorry ill clarify further

The server vlan (100) does not have DHCP
the workstation vlan (101) DHCP is managed by a windows server (in the server vlan) with an IP Helper enabled on the workstation vlan
the VoIP vlan (120) has DHCP configured on the switch itself

Routing between the vlan’s is done by the layer 3 switch

with LLDP disabled on the switch, the phone gets a workstation vlan IP (if i enabled option 66 TFTP works perfectly as per the above log)
with LLDP enabled on the switch the phone gets an IP from the switch with option 66 to the PBX (TFTP only partially works as per the above log)

In both cases the PBX/Provisioning server can ping the phone and access the web interface of it too

Yes verbosity is cranked up, well its set to -v (i guess i can move it to -vvvv)

I dont have a LLDP policy, its enabled across the switch, and is working as i can see the phone change vlans depending on what i set as the voice vlan on the interface

Ok so i have done a little more testing (and made sure tftp was set to -vvvv)

When i remove all the LLDP config and just put the phone into the voip vlan, it still doesn’t work with this log:

Apr 17 10:30:15 PBX01 in.tftpd[6445]: RRQ from 10.10.4.17 filename sangoma/1/
Apr 17 10:30:15 PBX01 in.tftpd[6445]: sending NAK (0, Is a directory) to 10.10.4.17
Apr 17 10:30:38 PBX01 in.tftpd[6447]: RRQ from 10.10.4.17 filename sangoma/1/fw500.rom
Apr 17 10:30:39 PBX01 in.tftpd[6447]: tftpd: read(ack): Connection refused

When i do a TCP dump something is happening to the TFTP transfer, i can see the TFTP data packets and TFTP acknowledgement packets from the phone. Then at one point this stops (after 256 blocks), the phone stops replying and sends a malformed packet thats contained within an ICMP packet for some reason. That error packet relates to the lasts line of the TFTP log.

So I put a workstation on the same VoIP vlan and ran a TFTP GET of the same file. No issue, it pulled the file as expected

Whats weird, is if i move the phone or workstation into the workstation vlan, both work as expected.

No matter what i seem to do, the phone doesnt like pulling from TFTP within the VoIP vlan (even though a PC does).

I also just pulled the log from the phone:
First TFTP REQ Log Line
[04-17 00:26:38 50:10:6f] Will check file file_url sangoma/1/ path sangoma/1 Save as fw500.rom
[04-17 00:26:38 50:10:6f] ###### TFTPC will get Comm File sangoma/1/ From 192.168.0.16
[04-17 00:26:38 50:10:6f] ====
[04-17 00:26:38 50:10:6f] ====================TFTPC GET AF_INET4
[04-17 00:26:38 50:10:6f] TFTPC: sin4_port server_port 53569
[04-17 00:26:38 50:10:6f] TFTPC: Badly ordered/invalid data packet (Got OP: 5 Block: 0) (Wanted Op: 3 Block: 0)
[04-17 00:26:38 50:10:6f] RTOS Upgrade: ROM, ======>> Get sangoma/1/ Fail, ret -1<<======

Second TFTP REQ Log Line
[04-17 10:30:31 50:10:6f] RTOS_Upgrade: Ready Check file fw500.rom
[04-17 10:30:31 50:10:6f] Will check file file_url sangoma/1/fw500.rom path sangoma/1 Save as fw500.rom
[04-17 10:30:31 50:10:6f] ###### TFTPC will get Comm File sangoma/1/fw500.rom From 192.168.0.16
[04-17 10:30:31 50:10:6f] ====
[04-17 10:30:31 50:10:6f] ====================TFTPC GET AF_INET4
[04-17 10:30:31 50:10:6f] TFTPC: sin4_port server_port 47760
[04-17 10:30:32 50:10:6f] IniAccountSipUdp:1772===Aid=0==SIP Creat Socket Bind NetMode = 0======
[04-17 10:30:32 50:10:6f] Create Udp Socket: SrcIp=0x a0a0411 SrcPort=5060 Pno=4 Event=4111 NetId=0x80000000…
[04-17 10:30:32 50:10:6f] IPV4 Init UDPSocket: bind socket 162 Success, pos[138]locip[a0a0411]port[5060]!
[04-17 10:30:32 50:10:6f] Create Udp Socket: CurPos=138 Port=5060 Create UDP Socket OK!
[04-17 10:30:32 50:10:6f] IniSipUdp: aid 0 Create UdpSocket OK pos 138!!!
[04-17 10:30:32 50:10:6f] IniSipUdp aid 0 OK
[04-17 10:30:32 50:10:6f] TFTPC: upgrade file /hlfs/fw500.rom is the same as old, need not upgrade
[04-17 10:30:32 50:10:6f] RTOS Upgrade: ROM, ======>> Get sangoma/1/fw500.rom Fail, ret -1<<======
[04-17 10:30:32 50:10:6f]
My guess is the fail here is the connection refused line

further down in the log there is a tftpc_post error, could this be where the phone tried to pull the xml file but failed before it made a connection ??
[04-17 10:30:47 50:10:6f] GUI:DEBUGINFO:can’t open digit photo directory,File:phone.c------Line:4176
[04-17 10:30:47 50:10:6f] GUI: ====load hlpres photo:wallpaper1.jpg error=======
[04-17 10:30:49 50:10:6f] GUI:DEBUGINFO:ReadXmlFileNode NULL!!,File:phone.c------Line:7128
[04-17 10:30:50 50:10:6f] Source file open failure!
[04-17 10:30:50 50:10:6f] GUI: RemoteDir 3, BSDir 3, APDir 3
[04-17 10:30:50 50:10:6f] GUI:DEBUGINFO:DeleteAllPhoneBookItem Item is NULL,File:phone.c------Line:6933
[04-17 10:30:53 50:10:6f] PostStartLogToServer, len:50658
[04-17 10:30:53 50:10:6f] tftpc_post: Client could not get host address information[04-17 10:30:53 50:XX:XX] GUI: MSG_PAINT
[04-17 10:30:53 50:10:6f] GUI: num:0,HLGUIData.ScrewView.ScrewItemNum:0
[04-17 10:30:53 50:10:6f] GUI:DEBUGINFO:OpenXmlFile Fail!,File:./src/directory.c------Line:642
[04-17 10:30:53 50:10:6f] GUI: Idle Softkey ,
[04-17 10:30:53 50:10:6f] LCM: Select aid:0
[04-17 10:30:53 50:10:6f] L2C: LCM set aid 0
[04-17 10:30:53 50:10:6f] ####===>>>MS Socket OK!!!
[04-17 10:30:53 50:10:6f] GUI: =====LoadSoftkeyLayoutFromXml start!========
[04-17 10:30:53 50:10:6f] GUI: aid:0, AccountInfo->name:USER-315
[04-17 10:30:53 50:10:6f] GUI: aid:0, AccountInfo->name:USER-315
[04-17 10:30:53 50:10:6f] GUI: aid:0, AccountInfo->name:USER-315
[04-17 10:30:53 50:10:6f] GUI:DEBUGINFO:UpdateCustomKeySeting GetActiveWindow is not Desktop,File:phone.c------Line:2363
[04-17 10:30:53 50:10:6f] GUI: aid:0, AccountInfo->name:USER-315
[04-17 10:30:53 50:10:6f] GUI: aid:0, AccountInfo->name:USER-315
[04-17 10:30:53 50:10:6f] GUI: aid:0, AccountInfo->name:USER-315
[04-17 10:30:53 50:10:6f] GUI:DEBUGINFO:UpdateCustomKeySeting GetActiveWindow is not Desktop,File:phone.c------Line:2363
[04-17 10:30:54 50:10:6f] CALL: State=0x60, Event=0x91c, Chn=0
[04-17 10:30:54 50:10:6f] CALL: LCM Exit MenuCfg
[04-17 10:30:54 50:10:6f] GUI:DEBUGINFO:UpdateCallTimeDisplay CallData is Null,File:./src/callwin.c------Line:4107


So not sure if this helps at all…

What version of FreePBX Distro are you using? I am relying on Scott here as he has confirmed its working fine and we worked together Thur and Friday on VLAN stuff and making sure it all worked.

But based on the logs it appears the Phone is having delays with TFTP and giving up.

[04-17 10:30:53 50:10:6f] tftpc_post: Client could not get host address information[04-17 10:30:53 50:XX:XX] GUI: MSG_PAINT

Are you using a IP address or FQDN

Im using IP address in option 66 and FreePBX 13 / Asterisk 13 (set to auto update in the console)

i just factory reset one of the phones, just to see what happens… the phone is currently on the voip vlan (no trunking or anything, just an access port) option 66 is set to point to the pbx

Should it auto configure at this point ? or do i need to set something else ?

the only difference between the voip and workstation vlans is the DHCP server… voip is cisco switch and workstation is windows… im going to test setting the voip one up on the windows box… see if that works (just trying to narrow it all down)

OMG

I just found the issue, and resolved it…

So… something very specific…

When configuring the DHCP server, option 66 MUST be a string, not IP… Cisco switches let you set option 66 to be an IP… Windows DHCP does not allow this by default, and forces you to set a string

As i as making the windows config, i noticed this, just updated the switch and tested, the phone booted instantly as expected :slight_smile:

what do you mean a string. like tftp://xxx.xxx.xxx.xxx? If so ya option 66 is not just for tftp it can be tftp and http or whatever protocol you want so you need to tell the phone what protocol you want.

well Cisco switches allow you to store and IP, Instance, HEX or ASCII in the variable assigned to an option

for example:
192.168.0.1 as an ASCII string is “192.168.0.1” but as IP its broken up into 4 numbers “192” then “168” then “0” then “1”, its not a string, but when queried, its delivered as an IP object so 192.168.0.1.

Think of it like a Database field, an INT (number field) thats 123 is not the same as a string thats 123. They look the same to the human eye, but are very different when used by the system.

Same applies here… the contents of Option 66 or 150 must be a string/ASCII object.

I dont know how to update the WIKI page but might be worthwhile noting this there for anyone else that comes across this