Bugzilla – Bug 13432
can't update from 7.3r5580->7.4
Last modified: 2009-09-16 13:11:28 UTC
controller running 7.3 r5580, trying to update to 7.4 firmware via custom.jive.* serial output: Erasing old environment /dev/mtd/3:4000 Writing environment to /dev/mtd/3:4000 Erasing old environment /dev/mtd/3:0 Writing environment to /dev/mtd/3:0 Aug 17 09:54:42 SqueezeboxController user.info jive: (SlimServer.lua:499) - SlimServer {mediumspicy}:disconnect Aug 17 09:54:42 SqueezeboxController user.info jive: (NetworkThread.lua:256) - NOTIFY: cometDisconnected(Comet {mediumspicy}) Aug 17 09:54:42 SqueezeboxController user.info jive: (NetworkThread.lua:256) - NOTIFY: serverDisconnected(SlimServer {mediumspicy}, 0) Aug 17 09:54:42 SqueezeboxController user.info jive: (SlimDiscoveryApplet.lua:426) - serverDisconnected SlimServer {mediumspicy} Aug 17 09:54:42 SqueezeboxController user.info jive: (UpgradeMTD.lua:358) - mtdset=1 nextKernelblock=c nextMtdset=0 Aug 17 09:54:42 SqueezeboxController user.info jive: (UpgradeMTD.lua:382) - fw_setenv: /usr/sbin/fw_setenv sw7 "" Aug 17 09:54:42 SqueezeboxController user.info jive: (UpgradeMTD.lua:471) - flash: /usr/sbin/flash_eraseall -q /dev/mtd/4 Aug 17 09:54:44 SqueezeboxController user.info jive: (UpgradeMTD.lua:471) - flash: /usr/sbin/flash_eraseall -q /dev/mtd/5 Aug 17 09:54:48 SqueezeboxController user.info jive: (UpgradeMTD.lua:395) - self.url=http://192.168.1.2:9000/firmware/custom.jive.bin Aug 17 09:54:49 SqueezeboxController user.info jive: (UpgradeMTD.lua:246) - flash: /usr/sbin/nandwrite -qp /dev/mtd/4 - Aug 17 09:55:25 SqueezeboxController user.info jive: (UpgradeMTD.lua:246) - flash: /usr/sbin/nandwrite -qp /dev/mtd/5 - Aug 17 09:55:36 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Aug 17 09:55:36 SqueezeboxController user.notice root: wpa_action eth0 DISCONNECTED Aug 17 09:55:38 SqueezeboxController local0.info udhcpc[698]: Received SIGTERM Aug 17 09:55:38 SqueezeboxController local0.info udhcpc[698]: Unicasting a release of 192.168.1.182 to 192.168.1.2 Aug 17 09:55:38 SqueezeboxController local0.info udhcpc[698]: Sending release... Aug 17 09:55:38 SqueezeboxController local0.err udhcpc[698]: bind(UDP): Cannot assign requested address Aug 17 09:55:38 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 09:55:38 SqueezeboxController local0.info udhcpc[698]: Entering released state Aug 17 09:55:44 SqueezeboxController daemon.notice wpa_supplicant[569]: Trying to associate with 00:16:b6:da:e7:dd (SSID='squeezewifi' freq=2447 MHz) Aug 17 09:55:45 SqueezeboxController daemon.notice wpa_supplicant[569]: Associated with 00:16:b6:da:e7:dd Aug 17 09:55:45 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-CONNECTED - Connection to 00:16:b6:da:e7:dd completed (reauth) [id=1 id_str=] Aug 17 09:55:46 SqueezeboxController user.notice root: wpa_action eth0 CONNECTED Aug 17 09:55:47 SqueezeboxController user.notice root: Checking for WLAN association... Aug 17 09:55:48 SqueezeboxController user.notice root: Found association! Aug 17 09:55:48 SqueezeboxController local0.info udhcpc[801]: udhcpc (v1.13.3) started Aug 17 09:55:49 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 09:55:49 SqueezeboxController local0.info udhcpc[801]: Sending discover... Aug 17 09:55:52 SqueezeboxController local0.info udhcpc[801]: Sending discover... Aug 17 09:55:52 SqueezeboxController local0.info udhcpc[801]: Sending select for 192.168.1.182... Aug 17 09:55:52 SqueezeboxController local0.info udhcpc[801]: Lease of 192.168.1.182 obtained, lease time 43200 Aug 17 09:55:52 SqueezeboxController user.notice root: udhcpc_action eth0 bound ip=192.168.1.182 Aug 17 09:57:05 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Aug 17 09:57:05 SqueezeboxController user.notice root: wpa_action eth0 DISCONNECTED Aug 17 09:57:06 SqueezeboxController local0.info udhcpc[814]: Received SIGTERM Aug 17 09:57:06 SqueezeboxController local0.info udhcpc[814]: Unicasting a release of 192.168.1.182 to 192.168.1.1 Aug 17 09:57:06 SqueezeboxController local0.info udhcpc[814]: Sending release... Aug 17 09:57:06 SqueezeboxController local0.err udhcpc[814]: bind(UDP): Cannot assign requested address Aug 17 09:57:06 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 09:57:07 SqueezeboxController local0.info udhcpc[814]: Entering released state Aug 17 09:57:25 SqueezeboxController daemon.notice wpa_supplicant[569]: Trying to associate with 00:16:b6:da:e7:dd (SSID='squeezewifi' freq=2447 MHz) Aug 17 09:57:26 SqueezeboxController daemon.notice wpa_supplicant[569]: Associated with 00:16:b6:da:e7:dd Aug 17 09:57:26 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-CONNECTED - Connection to 00:16:b6:da:e7:dd completed (reauth) [id=1 id_str=] Aug 17 09:57:27 SqueezeboxController user.notice root: wpa_action eth0 CONNECTED Aug 17 09:57:28 SqueezeboxController user.notice root: Checking for WLAN association... Aug 17 09:57:28 SqueezeboxController user.notice root: Found association! Aug 17 09:57:29 SqueezeboxController local0.info udhcpc[892]: udhcpc (v1.13.3) started Aug 17 09:57:29 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 09:57:29 SqueezeboxController local0.info udhcpc[892]: Sending discover... Aug 17 09:57:29 SqueezeboxController local0.info udhcpc[892]: Sending select for 192.168.1.182... Aug 17 09:57:29 SqueezeboxController local0.info udhcpc[892]: Lease of 192.168.1.182 obtained, lease time 86400 Aug 17 09:57:29 SqueezeboxController user.notice root: udhcpc_action eth0 bound ip=192.168.1.182 Aug 17 09:58:18 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Aug 17 09:58:18 SqueezeboxController user.notice root: wpa_action eth0 DISCONNECTED Aug 17 09:58:19 SqueezeboxController daemon.notice wpa_supplicant[569]: Trying to associate with 00:16:b6:da:e7:dd (SSID='squeezewifi' freq=2447 MHz) Aug 17 09:58:20 SqueezeboxController daemon.notice wpa_supplicant[569]: Associated with 00:16:b6:da:e7:dd Aug 17 09:58:20 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-CONNECTED - Connection to 00:16:b6:da:e7:dd completed (reauth) [id=1 id_str=] Aug 17 09:58:21 SqueezeboxController local0.info udhcpc[903]: Received SIGTERM Aug 17 09:58:21 SqueezeboxController local0.info udhcpc[903]: Unicasting a release of 192.168.1.182 to 192.168.1.1 Aug 17 09:58:21 SqueezeboxController local0.info udhcpc[903]: Sending release... Aug 17 09:58:21 SqueezeboxController local0.err udhcpc[903]: bind(UDP): Cannot assign requested address Aug 17 09:58:22 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 09:58:22 SqueezeboxController user.notice root: wpa_action eth0 CONNECTED Aug 17 09:58:22 SqueezeboxController local0.info udhcpc[903]: Entering released state Aug 17 09:58:23 SqueezeboxController user.notice root: Checking for WLAN association... Aug 17 09:58:24 SqueezeboxController user.notice root: Found association! Aug 17 09:58:24 SqueezeboxController local0.info udhcpc[963]: udhcpc (v1.13.3) started Aug 17 09:58:25 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 09:58:25 SqueezeboxController local0.info udhcpc[963]: Sending discover... Aug 17 09:58:28 SqueezeboxController local0.info udhcpc[963]: Sending discover... Aug 17 09:58:31 SqueezeboxController local0.info udhcpc[963]: Sending discover... Aug 17 09:58:32 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Aug 17 09:58:34 SqueezeboxController user.notice root: udhcpc_action eth0 leasefail ip= Aug 17 09:58:34 SqueezeboxController local0.info udhcpc[963]: No lease, forking to background Aug 17 09:58:35 SqueezeboxController user.notice root: wpa_action eth0 DISCONNECTED Aug 17 09:58:35 SqueezeboxController local0.info udhcpc[976]: Received SIGTERM Aug 17 09:58:35 SqueezeboxController local0.info udhcpc[976]: Entering released state Aug 17 09:58:40 SqueezeboxController daemon.notice wpa_supplicant[569]: Trying to associate with 00:16:b6:da:e7:dd (SSID='squeezewifi' freq=2447 MHz) Aug 17 09:58:41 SqueezeboxController daemon.notice wpa_supplicant[569]: Associated with 00:16:b6:da:e7:dd Aug 17 09:58:41 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-CONNECTED - Connection to 00:16:b6:da:e7:dd completed (reauth) [id=1 id_str=] Aug 17 09:58:41 SqueezeboxController user.notice root: wpa_action eth0 CONNECTED Aug 17 09:58:43 SqueezeboxController user.notice root: Checking for WLAN association... Aug 17 09:58:43 SqueezeboxController user.notice root: Found association! Aug 17 09:58:44 SqueezeboxController local0.info udhcpc[1015]: udhcpc (v1.13.3) started Aug 17 09:58:44 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 09:58:44 SqueezeboxController local0.info udhcpc[1015]: Sending discover... Aug 17 09:58:44 SqueezeboxController local0.info udhcpc[1015]: Sending select for 192.168.1.182... Aug 17 09:58:44 SqueezeboxController local0.info udhcpc[1015]: Lease of 192.168.1.182 obtained, lease time 43200 Aug 17 09:58:44 SqueezeboxController user.notice root: udhcpc_action eth0 bound ip=192.168.1.182 Aug 17 09:59:05 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Aug 17 09:59:05 SqueezeboxController user.notice root: wpa_action eth0 DISCONNECTED Aug 17 09:59:07 SqueezeboxController local0.info udhcpc[1026]: Received SIGTERM Aug 17 09:59:07 SqueezeboxController local0.info udhcpc[1026]: Unicasting a release of 192.168.1.182 to 192.168.1.2 Aug 17 09:59:07 SqueezeboxController local0.info udhcpc[1026]: Sending release... Aug 17 09:59:07 SqueezeboxController local0.err udhcpc[1026]: bind(UDP): Cannot assign requested address Aug 17 09:59:07 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 09:59:07 SqueezeboxController local0.info udhcpc[1026]: Entering released state Aug 17 09:59:19 SqueezeboxController daemon.notice wpa_supplicant[569]: Trying to associate with 00:16:b6:da:e7:dd (SSID='squeezewifi' freq=2447 MHz) Aug 17 09:59:20 SqueezeboxController daemon.notice wpa_supplicant[569]: Associated with 00:16:b6:da:e7:dd Aug 17 09:59:20 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-CONNECTED - Connection to 00:16:b6:da:e7:dd completed (reauth) [id=1 id_str=] Aug 17 09:59:20 SqueezeboxController user.notice root: wpa_action eth0 CONNECTED Aug 17 09:59:23 SqueezeboxController user.notice root: Checking for WLAN association... Aug 17 09:59:23 SqueezeboxController user.notice root: Found association! Aug 17 09:59:24 SqueezeboxController local0.info udhcpc[1080]: udhcpc (v1.13.3) started Aug 17 09:59:24 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 09:59:24 SqueezeboxController local0.info udhcpc[1080]: Sending discover... Aug 17 09:59:24 SqueezeboxController local0.info udhcpc[1080]: Sending select for 192.168.1.182... Aug 17 09:59:24 SqueezeboxController local0.info udhcpc[1080]: Lease of 192.168.1.182 obtained, lease time 43200 Aug 17 09:59:24 SqueezeboxController user.notice root: udhcpc_action eth0 bound ip=192.168.1.182 Aug 17 10:00:10 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Aug 17 10:00:10 SqueezeboxController user.notice root: wpa_action eth0 DISCONNECTED Aug 17 10:00:11 SqueezeboxController local0.info udhcpc[1091]: Received SIGTERM Aug 17 10:00:11 SqueezeboxController local0.info udhcpc[1091]: Unicasting a release of 192.168.1.182 to 192.168.1.2 Aug 17 10:00:11 SqueezeboxController local0.info udhcpc[1091]: Sending release... Aug 17 10:00:11 SqueezeboxController local0.err udhcpc[1091]: bind(UDP): Cannot assign requested address Aug 17 10:00:11 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 10:00:12 SqueezeboxController local0.info udhcpc[1091]: Entering released state Aug 17 10:00:49 SqueezeboxController daemon.notice wpa_supplicant[569]: Trying to associate with 00:16:b6:da:e7:dd (SSID='squeezewifi' freq=2447 MHz) Aug 17 10:00:50 SqueezeboxController daemon.notice wpa_supplicant[569]: Associated with 00:16:b6:da:e7:dd Aug 17 10:00:50 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-CONNECTED - Connection to 00:16:b6:da:e7:dd completed (reauth) [id=1 id_str=] Aug 17 10:00:51 SqueezeboxController user.notice root: wpa_action eth0 CONNECTED Aug 17 10:00:52 SqueezeboxController user.notice root: Checking for WLAN association... Aug 17 10:00:53 SqueezeboxController user.notice root: Found association! Aug 17 10:00:53 SqueezeboxController local0.info udhcpc[1163]: udhcpc (v1.13.3) started Aug 17 10:00:53 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 10:00:54 SqueezeboxController local0.info udhcpc[1163]: Sending discover... Aug 17 10:00:54 SqueezeboxController local0.info udhcpc[1163]: Sending select for 192.168.1.182... Aug 17 10:00:54 SqueezeboxController local0.info udhcpc[1163]: Lease of 192.168.1.182 obtained, lease time 86400 Aug 17 10:00:54 SqueezeboxController user.notice root: udhcpc_action eth0 bound ip=192.168.1.182 Aug 17 10:03:28 SqueezeboxController user.info jive: (SqueezeboxJiveApplet.lua:140) - syncing system clock to hw clock: Mon Aug 17 10:03:28 2009 Aug 17 10:03:29 SqueezeboxController user.info jive: (SqueezeboxJiveApplet.lua:143) - system clock now synced to hw clock: Mon Aug 17 10:03:29 2009 Aug 17 10:03:31 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Aug 17 10:03:31 SqueezeboxController user.notice root: wpa_action eth0 DISCONNECTED Aug 17 10:03:32 SqueezeboxController local0.info udhcpc[1176]: Received SIGTERM Aug 17 10:03:32 SqueezeboxController local0.info udhcpc[1176]: Unicasting a release of 192.168.1.182 to 192.168.1.1 Aug 17 10:03:32 SqueezeboxController local0.info udhcpc[1176]: Sending release... Aug 17 10:03:32 SqueezeboxController local0.err udhcpc[1176]: bind(UDP): Cannot assign requested address Aug 17 10:03:32 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 10:03:33 SqueezeboxController local0.info udhcpc[1176]: Entering released state Aug 17 10:03:45 SqueezeboxController daemon.notice wpa_supplicant[569]: Trying to associate with 00:16:b6:da:e7:dd (SSID='squeezewifi' freq=2447 MHz) Aug 17 10:03:46 SqueezeboxController daemon.notice wpa_supplicant[569]: Associated with 00:16:b6:da:e7:dd Aug 17 10:03:46 SqueezeboxController daemon.notice wpa_supplicant[569]: CTRL-EVENT-CONNECTED - Connection to 00:16:b6:da:e7:dd completed (reauth) [id=1 id_str=] Aug 17 10:03:47 SqueezeboxController user.notice root: wpa_action eth0 CONNECTED Aug 17 10:03:48 SqueezeboxController user.notice root: Checking for WLAN association... Aug 17 10:03:49 SqueezeboxController user.notice root: Found association! Aug 17 10:03:49 SqueezeboxController local0.info udhcpc[1286]: udhcpc (v1.13.3) started Aug 17 10:03:49 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Aug 17 10:03:50 SqueezeboxController local0.info udhcpc[1286]: Sending discover... Aug 17 10:03:53 SqueezeboxController local0.info udhcpc[1286]: Sending discover... Aug 17 10:03:56 SqueezeboxController local0.info udhcpc[1286]: Sending discover... Aug 17 10:03:56 SqueezeboxController local0.info udhcpc[1286]: Sending select for 192.168.1.182... Aug 17 10:03:56 SqueezeboxController local0.info udhcpc[1286]: Lease of 192.168.1.182 obtained, lease time 43200 Aug 17 10:03:56 SqueezeboxController user.notice root: udhcpc_action eth0 bound ip=192.168.1.182 Aug 17 10:04:02 SqueezeboxController user.err jive: (NetworkThread.lua:146) - network thread timeout for Task(SocketHttp {192.168.1.2}(R)) Aug 17 10:04:02 SqueezeboxController user.err jive: (SocketHttp.lua:796) - SocketHttp {192.168.1.2}:t_rcvResponse.pump() error:inactivity timeout Aug 17 10:04:02 SqueezeboxController user.info jive: (UpgradeMTD.lua:166) - sinkErr=inactivity timeout Aug 17 10:04:02 SqueezeboxController user.info jive: (UpgradeMTD.lua:448) - sinkErr=inactivity timeout Aug 17 10:04:02 SqueezeboxController user.warn jive: (UpgradeMTD.lua:91) - download Failed err=inactivity timeout Aug 17 10:04:02 SqueezeboxController user.err jive: (SetupFirmwareUpgradeApplet.lua:271) - Upgrade failed: inactivity timeout Aug 17 10:04:02 SqueezeboxController user.info jive: (SlimServer.lua:481) - SlimServer {mediumspicy}:connect Aug 17 10:04:03 SqueezeboxController user.info jive: (SlimServer.lua:481) - SlimServer {SqueezeNetwork}:connect Aug 17 10:04:03 SqueezeboxController user.info jive: (AppletManager.lua:737) - Freeing: SetupFirmwareUpgrade Mon Aug 17 10:04:06 UTC 2009 Aug 17 10:04:03 SqueezeboxController user.info jive: (SlimDiscoveryApplet.lua:172) - Removing server SlimServer {mediumspicy} Aug 17 10:04:03 SqueezeboxController user.info jive: (NetworkThread.lua:256) - NOTIFY: serverDelete(SlimServer {mediumspicy}) Aug 17 10:04:03 SqueezeboxController user.info jive: (SlimDiscoveryApplet.lua:190) - Removing player Player {Squeezebox 160244} Aug 17 10:04:03 SqueezeboxController user.info jive: (Player.lua:530) - Player {Squeezebox 160244} delete for false Aug 17 10:04:03 SqueezeboxController user.info jive: (NetworkThread.lua:256) - NOTIFY: playerDelete(Player {Squeezebox 160244}) Aug 17 10:04:03 SqueezeboxController user.info jive: (NetworkThread.lua:256) - NOTIFY: serverNew(SlimServer {mediumspicy}) Aug 17 10:04:03 SqueezeboxController user.info jive: (NetworkThread.lua:256) - NOTIFY: cometConnected(Comet {mediumspicy}) Aug 17 10:04:03 SqueezeboxController user.info jive: (SlimServer.lua:523) - SlimServer {mediumspicy} connected Aug 17 10:04:03 SqueezeboxController user.info jive: (NetworkThread.lua:256) - NOTIFY: serverConnected(SlimServer {mediumspicy}) Aug 17 10:04:03 SqueezeboxController user.info jive: (SlimDiscoveryApplet.lua:442) - serverConnected Aug 17 10:04:03 SqueezeboxController user.info jive: (SlimServer.lua:499) - SlimServer {SqueezeNetwork}:disconnect Aug 17 10:04:03 SqueezeboxController user.info jive: (NetworkThread.lua:256) - NOTIFY: cometDisconnected(Comet {SqueezeNetwork}) Aug 17 10:04:03 SqueezeboxController user.info jive: (NetworkThread.lua:256) - NOTIFY: serverDisconnected(SlimServer {SqueezeNetwork}, 0) Aug 17 10:04:03 SqueezeboxController user.info jive: (SlimDiscoveryApplet.lua:426) - serverDisconnected SlimServer {SqueezeNetwork} Aug 17 10:04:03 SqueezeboxController user.info jive: (NetworkThread.lua:256) - NOTIFY: playerNew(Player {Squeezebox 160244}) Aug 17 10:04:03 SqueezeboxController user.info jive: (SqueezeboxJiveApplet.lua:328) - CCYY=2009 MM=08 DD=17 hh=10 mm=04 ss=06 TZ=-05:00
Network drops several times during update, which eventually times out because of how slow this makes the download
this is an administrative shuffle on priority fields to help make better judgment on the top end of the priority list. P4->P5, P3->P4, and P2->P3.
closeing this bug, as most people will be upgrading from 7.3x r6038 (which does work)