Discussion:
Snom 320 phones not registering with 4.6
Kurt Albershardt
2012-07-11 15:55:25 UTC
Permalink
All three phones have pulled configs now, but none has successfully registered. Displays show "NR" at the top and the web interfaces show:

Identity 1 Status: ***@sipx.domain.com: Network Failure

I can ping all three phones from the sipx server command line. Don't see a ping tool in the phone web UI, but they do pull configs from the same host, and do so on reboots now.

Not sure where registration attempts get logged, but grepping for parts for the MAC address in /var/log/sipxpbx/* yields nothing.
Kurt Albershardt
2012-07-11 16:28:43 UTC
Permalink
Post by Kurt Albershardt
they do pull configs from the same host, and do so on reboots now.
Correction here - rebooting either from the webUI or by unplugging and replugging the PoE causes the phones to hang on DHCP requests. If I 'cancel out of that, I get a Provisioning Server Failed. Only by resetting the config and re-entering the provisioning URL in the phone's webUI can I get them to restart.


I'm suspicious that something in that config might be borking the network settings. I've attached the config file.
Here's the info form the phone webUI:


System Information:
Phone Type: snom320-SIP
MAC-Address: 00041338400C
IP-Address: 192.168.44.180
Firmware-Version: snom320-SIP 7.3.30 6059
Firmware-URL:
Production Information: Mac:00041338400C;Version:Standard;Hardware:snom320 (H: R5B);Date:14/11/11;Copyright(C) snom technology AG
Uptime: 0 days, 15 hours, 2 minutes
Memfree: 3076 K
Bootloader-Version: 1.1.3-u

SIP Identity Status:
Identity 1 Status: ***@sipx.murray-hotel.com: Network Failure
Identity 2 Status:
Identity 3 Status:
Identity 4 Status:
Identity 5 Status: Identity 6 Status:
Identity 7 Status:
Identity 8 Status:
Identity 9 Status:
Identity 10 Status:
Identity 11 Status:
Identity 12 Status:

Ethernet Status:
Net Port: Connection Type: 100 Mbit Full Duplex
Status: connected

PC Port: Connection Type:
Status: not connected
Kurt Albershardt
2012-07-11 18:04:19 UTC
Permalink
Post by Kurt Albershardt
Firmware-Version: snom320-SIP 7.3.30 6059
Updating to firmware 8.7.3.7 does not fix this, but does seem to indicate a problem with the generated config:

Clear settings from phone menu after DHCP fails, triggers reboot.
Unplug & replug PoE to force a real restart.
Grabs DHCP address and config, then display says "New network policy -> Reboot"
at which point phone restarts and hangs on "Sending DHCP requests" as with previous firmware.

BTW, no VLANs have been configured yet - everything is in the default switch VLAN.
Kurt Albershardt
2012-07-11 19:36:01 UTC
Permalink
Looks like this might be related to LLDP-MED. Even though I had not assigned a VLAN in the config, the Cisco "Auto Voice VLAN" feature may have jumped in. I defaulted the switch back to factory settings, with everything including voice in VLAN 1. Now I'm still seeing provisioning failures, but at least we can still reach the phones after the restarts. sipx can ping all three phones, but none will register yet.

Here's a log from a phone running 7.3.30:

5] 24/12/2001 00:00:18:DHCP: Received IP address 192.168.44.212
[0] 24/12/2001 00:00:18:Phone::uboot_version:1.1.3-u
[5] 24/12/2001 00:00:18:Opening TCP socket on port 843
[5] 24/12/2001 00:00:23:Setting server was already set: http://sipx.murray-hotel.com:8090/phone/profile/docroot/{mac}.xml
[5] 24/12/2001 00:00:23:Fetching URL: http://sipx.murray-hotel.com:8090/phone/profile/docroot/0004133842E0.xml
[5] 24/12/2001 00:00:23:timeout::callback: Registering with timeout of 0 ms
[5] 24/12/2001 00:00:23:read_xml_settings: found settings (container) XML header
[5] 24/12/2001 00:00:23:read_xml_settings: found phone-settings XML header
[5] 24/12/2001 00:00:23:read_xml_settings: found one byte encoding: 0
[5] 24/12/2001 00:00:24:read_xml_settings: found phone-book XML header
[5] 24/12/2001 00:00:24:read_xml_settings: found one byte encoding: 0
[5] 24/12/2001 00:00:24:read_xml_settings: found function-keys XML header
[5] 24/12/2001 00:00:24:read_xml_settings: found one byte encoding: 0
[5] 24/12/2001 00:00:24:Conf setup: found xml style settings
[5] 24/12/2001 00:00:24:Fetching URL: http://127.0.0.1/dummy.htm
[1] 24/12/2001 00:00:24:Conf setup: code: 500, host: 127.0.0.1:80, file: /dummy.htm
[5] 24/12/2001 00:00:24:Fetching FW URL: http://sipx.murray-hotel.com:8090/snom320/snom320-firmware.htm
[5] 24/12/2001 00:00:24:Fetching URL: http://sipx.murray-hotel.com:8090/snom320/snom320-firmware.htm
[2] 23/12/2001 19:00:24:start_dst(984276000) end_dst(1004839200) offset_dst(3600) offset_utc(-18000)
[2] 23/12/2001 19:00:24:start DST: 03/11/2001 02:00:00 (984276000)
[2] 23/12/2001 19:00:24:end DST: 11/04/2001 02:00:00 (1004839200)
[0] 23/12/2001 19:00:25:allocated local SIP tcp port 5060![5] 23/12/2001 19:00:25:Using GUI language English from: /mnt/snomlang/gui_lang_EN.xml
[5] 23/12/2001 19:00:25:Using WEB language English from: /mnt/snomlang/web_lang_EN.xml
[5] 23/12/2001 19:00:26:Opening TCP socket on port 80
[5] 23/12/2001 19:00:26:Opening TCP socket on port 443
[5] 23/12/2001 19:00:26:Opening TCP socket on port 1800
[5] 23/12/2001 19:00:26:timeout::callback: Registering with timeout of 0 ms
[5] 23/12/2001 19:00:26:Opening TCP socket on port 5060
[3] 23/12/2001 19:00:27:Invalid Date: 23.12.2001 Time: 19:00
[2] 11/7/2012 15:12:09:start_dst(1331431200) end_dst(1351994400) offset_dst(3600) offset_utc(-18000)
[2] 11/7/2012 15:12:09:start DST: 03/11/2012 02:00:00 (1331431200)
[2] 11/7/2012 15:12:09:end DST: 11/04/2012 02:00:00 (1351994400)
[5] 11/7/2012 15:12:10:timeout::callback: Registering with timeout of 0 ms
[5] 11/7/2012 15:12:10:Add dirty host: udp/192.168.44.31/5060
[5] 11/7/2012 15:12:10:timeout::callback: Registering with timeout of 0 ms
[2] 11/7/2012 15:12:10:Transport Error: Pending packet 1000000: generating fake
[2] 11/7/2012 15:12:10:Registrar ***@sipx.murray-hotel.com timed out
[5] 11/7/2012 15:12:21:Applying Settings...
[5] 11/7/2012 15:12:21:Settings applied!
[5] 11/7/2012 15:13:11:timeout::callback: Registering with timeout of 0 ms
[5] 11/7/2012 15:13:11:Add dirty host: udp/192.168.44.31/5060
[5] 11/7/2012 15:13:11:timeout::callback: Registering with timeout of 0 ms
[2] 11/7/2012 15:13:11:Transport Error: Pending packet 1000002: generating fake
[2] 11/7/2012 15:13:11:Registrar ***@sipx.murray-hotel.com timed out
[5] 11/7/2012 15:14:12:timeout::callback: Registering with timeout of 0 ms
[5] 11/7/2012 15:14:12:Add dirty host: udp/192.168.44.31/5060
[5] 11/7/2012 15:14:12:timeout::callback: Registering with timeout of 0 ms
[2] 11/7/2012 15:14:12:Transport Error: Pending packet 1000004: generating fake
[2] 11/7/2012 15:14:12:Registrar ***@sipx.murray-hotel.com timed out



Looks like there may be some issues with these configs and 8.x firmware:


1/1/2000 00:00:34 [NOTICE] PHN: read_xml_settings: found no XML header; probably old style format
1/1/2000 00:00:34 [NOTICE] PHN: read_xml_settings: found function-keys XML header
1/1/2000 00:00:34 [NOTICE] PHN: read_xml_settings: found one byte encoding: 0
1/1/2000 00:00:34 [NOTICE] PHN: Config setup: found xml style settings
1/1/2000 00:00:34 [NOTICE] PHN: last prov successful:1; uri: >http://sipx.murray-hotel.com:8090/phone/profile/docroot/{mac}.xml<; default uri: >http://provisioning.snom.com:80/snom320/snom320.php?mac={mac}<
1/1/2000 00:00:34 [NOTICE] PHN: Fetching URL: http://127.0.0.1:80/dummy.htm
1/1/2000 00:00:34 [ERROR ] PHN: TPL: Socket Error: 13/19/connecting, connect_cb -> Operation now in progress (150)
1/1/2000 00:00:34 [NOTICE] PHN: webclient::on_tcp_close conn_id:2
1/1/2000 00:00:34 [ALERT ] PHN: Config setup: code: 500, uri: http://127.0.0.1:80/dummy.htm
1/1/2000 00:00:34 [NOTICE] PHN: Fetching FW URL: http://sipx.murray-hotel.com:8090/snom320/snom320-firmware.htm
1/1/2000 00:00:34 [NOTICE] PHN: Fetching URL: http://sipx.murray-hotel.com:8090/snom320/snom320-firmware.htm
1/1/2000 00:00:34 [NOTICE] PHN: Last provisioning was successful, thus stop here!
1/1/2000 00:00:34 [CRITIC] PHN: Go to wizzard if all settings have been read.
31/12/1999 19:00:34 [CRITIC] PHN: start_dst(952826400) end_dst(973389600) offset_dst(3600) offset_utc(-18000)
31/12/1999 19:00:34 [CRITIC] PHN: start DST: 03/12/2000 02:00:00 (952826400)
31/12/1999 19:00:34 [CRITIC] PHN: end DST: 11/05/2000 02:00:00 (973389600)
31/12/1999 19:00:34 [FATAL ] PHN: allocated local SIP tcp port 5060!31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey0 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey1 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey2 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey3 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey4 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey5 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey6 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey7 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey8 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey9 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey10 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter fkey11 is not permitted
31/12/1999 19:00:34 [ERROR ] PHN: Writing to parameter dkey_retrieve is not permitted
31/12/1999 19:00:35 [NOTICE] PHN: Settings stored!
31/12/1999 19:00:36 [NOTICE] PHN: Opening TCP socket on port 5060
31/12/1999 19:00:43 [NOTICE] PHN: Update: Fetching FW URL: http://sipx.murray-hotel.com:8090/snom320/snom320-firmware.htm done, result 404
31/12/1999 19:00:44 [NOTICE] PHN: TPL: Socket 16 idle/connect timeout
31/12/1999 19:00:44 [NOTICE] PHN: TPL: Socket 17 idle/connect timeout
11/7/2012 15:07:53 [CRITIC] PHN: start_dst(1331431200) end_dst(1351994400) offset_dst(3600) offset_utc(-18000)
11/7/2012 15:07:53 [CRITIC] PHN: start DST: 03/11/2012 02:00:00 (1331431200)
11/7/2012 15:07:53 [CRITIC] PHN: end DST: 11/04/2012 02:00:00 (1351994400)
11/7/2012 15:07:53 [ERROR ] PHN: SIP: transport error: 1000000 -> udp:192.168.44.31:5060
11/7/2012 15:07:53 [NOTICE] PHN: SIP: Add dirty host: udp:192.168.44.31:5060 (0 sec)
11/7/2012 15:07:53 [NOTICE] PHN: SIP: final transport error: 1000000 -> udp:192.168.44.31:5060
11/7/2012 15:07:53 [ERROR ] PHN: SIP: transport error 1000000: generating fake 599
Loading...