Re: SPA122 freezes when upgrading firmware via provisioning

Aaron Mount · ‎01-17-2013

I've started pushing out the v1.3.1(003) upgrade to a few of our deployed devices via the provisioning file, but in a test I did last night, 5 out of the 6 SPA122s that I upgraded froze after applying the update.

The server's access logs look like this:

$ zgrep '71.238.**.***' logs/access20130116.log.gz

71.238.**.*** - - [16/Jan/2013:21:47:29 -0800] "GET /ccef4******* HTTP/1.0" 200 17490 "-" "Cisco/SPA122-1.1.0(011) (CBT1*******)"

71.238.**.*** - - [16/Jan/2013:21:48:21 -0800] "GET /firmware/SPA112_SPA122_1.3.1_003.bin HTTP/1.0" 200 9945472 "-" "Cisco/SPA122-1.1.0(011) (CBT1*******)"

71.238.**.*** - - [16/Jan/2013:21:48:35 -0800] "GET /firmware/SPA112_SPA122_1.3.1_003.bin HTTP/1.0" 200 9945472 "-" "Cisco/SPA122-1.1.0(011) (CBT1*******)"

$

I would have expected the ATA to provision again after upgrading, but it has to be rebooted before it will come back online. It's kind of scary to reboot a device manually after a firmware upgrade without something saying it's okay to do so.

Has anyone else observed this behavior?

George Spanos · ‎01-17-2013

I haven't tried via provisioning yet but I had a 1 production device freeze at 98% when remotely upgrading through the GUI. After it froze, I couldn't log back into it (it was pingable but no GUI). I had someone hard reboot it on-site and then retried the upgrade and completed. Since then I rebooted each SPA122 to clear up any high memory usage before I attempted to upgrade them. I think that would be a good rule of thumb considering the stupidity that is v1.2.1-004.

Aaron Mount · ‎01-17-2013

Hmm, perhaps a good idea, though I'm not thrilled at the prospect of having to tell a thousand people to reboot their devices before we upgrade their firmware. On the other hand, I'm not thrilled at having a thousand devices freeze after upgrading them either.

George Spanos · ‎01-17-2013

What provisioning system are you using? How are you rolling out the upgrade rule URL to them?

Aaron Mount · ‎01-17-2013

When an ATA requests its config file from the server, the file is generated on the fly by a PHP script. To upgrade a limited pool of devices, I essentially added some language saying that "if the MAC address is in this range, upgrade the firmware to 1.3.1, otherwise keep 1.1.0 or 1.2.1, whatever is already on there."

Aaron Mount · ‎02-04-2013

I saw a post from Patrick a few days ago (https://supportforums.cisco.com/docs/DOC-29477) about the process the ATA goes through when upgrading.

I never considered incrementally stepping up the firmware. Is the doc saying that the correct way to upgrade the firmware is to go v1.1.0 >> v1.2.1 >> v1.3.1 ?

George Spanos · ‎02-05-2013

I plan on doing something like this for my next round of upgrades for the "Upgrade Rule" field. Still testing it in my lab.

($SWVER > 1.3.1(003)) ? http://provisioningserver/SPA122.bin

Aaron Mount · ‎02-14-2013

Okay, I tried the two-step upgrade process as Patrick's document suggested, but found that the ATA still froze, this time after upgrading from v1.1.0(011) to v1.2.1(004).

I was able to get syslog results this time, and the device seems to be freezing at the postupgrade handling.

Feb 13 23:31:27 c-ipaddress.hsd1.pa.comcast.net [FPRV] Upgrade status flags cleared

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net IDBG: LS, 262-4fb

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net IDBG: SOK

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net IDBG: st-0

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net get_dhcp_option66_67_info, voice interface is 'br0'

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net uchInitDTMFTbl(), dtmf level -100

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net uchEnableEchoCan(), lid 0 EP 2 enable

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net uch_syncParameter(), uch_syncDTMFHoldOffTime(0)=0

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net uchEnableEchoCan(), lid 1 EP 1 enable

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net uch_syncParameter(), uch_syncDTMFHoldOffTime(1)=0

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net CC: init after ether ...

Feb 13 23:32:04 c-ipaddress.hsd1.pa.comcast.net sys_events_comm_start_named(spr_voip) = 18

Feb 13 23:32:05 c-ipaddress.hsd1.pa.comcast.net SCAPC_init(): provision_enable=1 prule=https://provserver/$MA tftp=

Feb 13 23:32:05 c-ipaddress.hsd1.pa.comcast.net #011going to sleep 20 csec

Feb 13 23:32:06 c-ipaddress.hsd1.pa.comcast.net fs: 060406:060731:262144

Feb 13 23:32:06 c-ipaddress.hsd1.pa.comcast.net fbr: 0:3000:3000:010b84:0002:0001:1.1.0(011)

Feb 13 23:32:06 c-ipaddress.hsd1.pa.comcast.net PLKUP: 2048, 633, 7, 1.3

Feb 13 23:32:06 c-ipaddress.hsd1.pa.comcast.net [SCAPC]WaitTime: 10

Feb 13 23:32:07 c-ipaddress.hsd1.pa.comcast.net [SCAPC]WaitTime: 20

Feb 13 23:32:08 c-ipaddress.hsd1.pa.comcast.net [SCAPC]WaitTime: 40

Feb 13 23:32:09 c-ipaddress.hsd1.pa.comcast.net [SCAPC]WaitTime: 80

Feb 13 23:32:09 c-ipaddress.hsd1.pa.comcast.net [LVS]Cannot resolve LVS_PROXY. Read lvs address from flash. IP =

Feb 13 23:32:09 c-ipaddress.hsd1.pa.comcast.net sysstatus_set_led_status_payton(), led_id: 0, statusCode:0, systemEvent: 0xfffe

Feb 13 23:32:09 c-ipaddress.hsd1.pa.comcast.net sysstatus_set_led_status_payton(), led_id: 1, statusCode:0, systemEvent: 0xfffe

Feb 13 23:32:09 c-ipaddress.hsd1.pa.comcast.net sysstatus_set_led_status_payton(), led_id: 2, statusCode:0, systemEvent: 0xfffe

Feb 13 23:32:10 c-ipaddress.hsd1.pa.comcast.net [0]Reg Addr Change(0) 0:0->a2e0148:6060

Feb 13 23:32:10 c-ipaddress.hsd1.pa.comcast.net [0]RegOK. NextReg in 3570 (1)

Feb 13 23:32:10 c-ipaddress.hsd1.pa.comcast.net CC_eventProc(), event: CC_EV_SIG_REGISTER_OK(0x3A), lid: 0, par: 0, par2: (nil)

Feb 13 23:32:10 c-ipaddress.hsd1.pa.comcast.net AUD_ccEventProc: event 58 vid 0 par 0x0 par2 0x0

Feb 13 23:32:10 c-ipaddress.hsd1.pa.comcast.net sysstatus_set_led_status_payton(), led_id: 1, statusCode:1, systemEvent: 0x100093

Feb 13 23:32:12 c-ipaddress.hsd1.pa.comcast.net [0]CID: CID_initGen() >>> offhook 0 delay 0 phone - name -

Feb 13 23:32:12 c-ipaddress.hsd1.pa.comcast.net CID: OSI

Feb 13 23:32:12 c-ipaddress.hsd1.pa.comcast.net [0]CID CID_ST_OSI

Feb 13 23:32:12 c-ipaddress.hsd1.pa.comcast.net CID: OnHookTx Pol

Feb 13 23:32:12 c-ipaddress.hsd1.pa.comcast.net [0]CID CID_ST_OSI_POST_DELAY

Feb 13 23:32:12 c-ipaddress.hsd1.pa.comcast.net uchDisplayCIDFSK(), EP 2 lid 0 buflen 66 overhead 60 SZ_MAX_USERDATA 200

Feb 13 23:32:13 c-ipaddress.hsd1.pa.comcast.net [0]CID Start DTMF/FSK, CID_ST_ACTIVE

Feb 13 23:32:13 c-ipaddress.hsd1.pa.comcast.net [0]CID CID_ST_FSK_COMP_DELAY

Feb 13 23:32:13 c-ipaddress.hsd1.pa.comcast.net [0]CID CID:DONE

Feb 13 23:32:13 c-ipaddress.hsd1.pa.comcast.net [0]CID CID_ST_ACTIVE_POST_DELAY

Feb 13 23:32:13 c-ipaddress.hsd1.pa.comcast.net [0]CID CID_ST_IDLE

Feb 13 23:32:16 c-ipaddress.hsd1.pa.comcast.net fs: 060421:060731:262144:112812327999

Feb 13 23:32:16 c-ipaddress.hsd1.pa.comcast.net [fprv_test_download_file]test download url

Feb 13 23:32:16 c-ipaddress.hsd1.pa.comcast.net [fprv_test_download_file] get dn_schema 3 path=/firmware/SPA112_SPA122_1.2.1_FW.bin ip ipaddress

Feb 13 23:32:16 c-ipaddress.hsd1.pa.comcast.net [fprv_test_download_file] http(s) upg url provserver:443

Feb 13 23:32:18 c-ipaddress.hsd1.pa.comcast.net ok=0

Feb 13 23:32:29 c-ipaddress.hsd1.pa.comcast.net sysstatus_set_led_status_payton(), led_id: 0, statusCode:17, systemEvent: 0xffff

Feb 13 23:32:30 c-ipaddress.hsd1.pa.comcast.net ok=0

Feb 13 23:32:50 c-ipaddress.hsd1.pa.comcast.net sysstatus_set_led_status_payton(), led_id: 0, statusCode:0, systemEvent: 0xfffe

Feb 13 23:33:06 c-ipaddress.hsd1.pa.comcast.net [0]Reg Addr Change(0) 0:0->a2e0148:6060

Feb 13 23:33:06 c-ipaddress.hsd1.pa.comcast.net ** postupgrade handling (1, 0)

samfiller · ‎02-14-2013

Good afternoon,

I was having similar issues, I did not have enough time to go through the logs.

But I did try using TFTP and was successful. There maybe an issue with http.

( I sent a new config with tftp in the upgrade rule, forced a resync and around 20 minutes later it was upgraded)

Sam

Filip Frank · ‎03-20-2013

Hello,

I have same problem, i try upgrade my testing device(spa112) with TFTP and it freeze during update. I think TFTP is not solution. I need remotely upgrade about 50 devices in production without any manual restarting.

George Spanos · ‎03-20-2013

I used one of the SPA rebooter app's that are floating around the forums (http://www.freymond.ca/SPA112/) to reboot the devices (batch file to re-run the procedure on each device) and then used CURL to push a provisioning XML file called "upgrade.xml" to the SPA's which tells them to go to the upgrade server and grab the new file. The xml file contains

1.3.1

http://10.10.11.12/SPA122/firmware/Cisco-SPA122-1.3.1-003.bin

and the curl command is as follows:

curl -d @upgrade.xml "http://IPADDRESS/admin/config.xml&xuser=YOURUSER&xpassword=YOURPASS" -v

It does a HTTP POST to the SPA's URL and basically does, POST-->upgrade.xml ->SPA-IP & login --> verbose (show all steps during the process). Once the SPA gets the upgrade.xml it will try to grab the .bin file from your server.

samfiller · ‎04-26-2013

George I pretty much have the same in my configuration file.

Yes

3600

http://provisioningserver.com/spa122.bin

$PN $MAC -- Requesting upgrade $SCHEME://$SERVIP:$PORT$PATH

$PN $MAC -- Successful upgrade $SCHEME://$SERVIP:$PORT$PATH -- $ERR

$PN $MAC -- Upgrade failed: $ERR

And I have never seen my devices pull a firmware,

Any advise?

George Spanos · ‎04-29-2013

I haven't experimented in a while but I think that it doesn't check for FW unless it's initial provisioning, you've updated the upgrade rule or POST (just login then past this into the address bar) to "http://YOURIPHERE/admin/upgrade" to tell it to look at the upgrade rule for upgrade.

Aaron Mount · ‎04-29-2013

Thanks George. The ATA was checking the firmware at resync, but the problem was that the device would download the binary, then freeze when trying to apply it.

I never found a real solution to this, nor heard what could have caused it. Instead I sent out an email to 1000 people telling them they might need to reboot their ATA if they picked up the phone and didn't get a dial tone.

samfiller · ‎04-29-2013

George,

"http://YOURIPHERE/admin/upgrade" is not availiable on the SPA122, that was used on the original SPA series to mannualy update the devices. FYI http://YOURIPHERE/admin/resync is availiable on the SPA122.

SPA122 freezes when upgrading to 1.3.1(003) via provisioning