Bugzilla – Bug 17006
Controller navigation malfunctioning
Last modified: 2011-05-09 12:56:33 UTC
My Controller becomes unresponsive in an very annoying way during playback: I can scroll the current menu with the scroll wheel, but pressing any of the buttons has no effect whatsoever. That means that I cannot change album or song, nor can I go back to the main menu, nor can I turn off the Controller. The only “solution” I’ve found so far is to reboot the Controller by brute force by taking out the battery and reinserting it. I suspect it can be avoided by returning to the main menu immediately after selecting an album, but my experiments doesn’t give consistent results, perhaps because it need be instantly not to get stuck. This error renders my Controller useless on most days, so I'd really like it solved. Controller Firmware version: 7.5.3.r9283 Squeezebox Server version: 7.5.3 - r31792 References: http://forums.slimdevices.com/showthread.php?t=85873
I see what i supose is the same bug in7.6 to, but not soo often on rare occasions, some times my controller gets stuck in the now playing playlist the arrow buttons do not take me out from there and home button does nothing.Left arrow is suposed to get you back to the np screen. Have not tested if context menu still functions. But the frequnce when this happens is not at the same anoing level as other experienced. Any hint re wich logs to fetch ?
I've confirmed this behaviour with 7.5.2 (Controller firmware 7.5.1 r9009) and 7.5.3 (Controller firmware 7.5.3 r9283) on a Debian platform.
same thing using 7.5.3 on windows 7. taking the battery out is the only fix I've found. that said for me I can enter the server control panel/web remote on my pc and it works fine. that leads me to believe it is in fact the remote and not the server or box.
*** This bug has been confirmed by popular vote. ***
I'd like to ask for some specific steps to reproduce this. When you say "I can scroll the current menu", are you referring to the current playlist menu? If you are referring to the current playlist menu, when the issue occurs is your playlist > 200 tracks in length? I appreciate the additional information.
flagging with bug_meeting keyword. recommend QA to find clear steps to reproduce the problem, and establish whether this is a controller-only problem or if it affects all SP devices.
@ Ben Klaas Yes, I'm refering to the current playlist menu. Usually my playlist contains only one album at the time.
I do not use actual playlist. while listening to music if I want to change albums/artist/stations (whatever I happen to be listening to) I can scroll though the albums/artist/stations (whatever I'm in) but can't change albums/artist or stations (ie I'm stuck on whatever is playing). also it won't let me back up out of the field I'm in (if I'm in albums I can't get out of it). so I can't go back to the main menu or anything. none of the buttons on the remote respond either (can't turn it off, skip etc etc).
Kim (and others)- what type of squeezebox is your controller controlling? A squeezebox receiver, or something else?
My Controller is controlling Squeezebox Receiver in a standard Duet setup.
As I'm the only one with 7.6 and sees this on rare occasions so seldom that I have not bother with a bug report myself as I have trouble to reproduce it in any reliable way to provide logs or similar (did not want to send the devs on a wild goose chase ) . Controller can do odd "one off" things that you never see again , I speculate that it's it's small cpu and ram and power-saving features that trow curvballs where Touch just works, for example the other day it had just freezed it had been on but not actively used for a week sitting in the cradle with blank screen as saver. So i thought this bug was "one of thoose" Untill other user saw it more often. maybe somethings done in 7.6 is an improvement on this , can some of the bugfixes be backported to 7.5.4b
I'm using both my Controllers with Receivers. When the problem occurs it only affects one Controller at a time, so it looks like something device-related rather than specifically server-related. When the problem occurs it seems to lock you into whatever display you're in, be it playlist or one of the menus. I never use long playlists, maybe two or three albums queued up but no longer than that, and usually just a single album.
duet as well.
Thanks all for the feedback on your setups. I will try to reproduce the issue here. The bug feels like it's a transient issue (i.e., can't reproduce every time), but if any of you find a set of steps where the bug appears every time, that would be very useful information. Mikael- would like to get at a root cause before considering backporting anything from 7.6. For those that want to help and understand how to use ssh/scp (ignore this if you don't): It's difficult to say what logging to turn on, but even with no extra logging from default the contents of syslog (stored at /var/log/messages unless you have an SD card in with a log/ folder, then it will be something like /mnt/media*/log/messages) when the issue occurs may uncover the problem. Turn ssh on at settings->advanced->remote login, then ssh to the device and scp the correct file off. Alternatively, use the SD card to store the log file by creating a top level log/ file on the card.
for me there is no rhyme or reason to it. it just happens every now and then.
Created attachment 7174 [details] /var/log/messages from Controller (firmware from SBS 7.5.2) after button lockup This is a de-sensitised copy of /var/log/messages taken from a Controller shortly after discovering that the buttons had locked up.
There isn't anything in the log that would indicate directly that the UI had gone off the rails, but there are some data that may be helpful 1. At 16:05 there are kernel warnings that I would not expect. This was a few hours before the log was grabbed, so could be unrelated to the bug. 2. Then at 18:11, probably at the time the UI got in a bad state, the controller loses network connectivity and tries repeatedly to restore it. After several minutes it is successful at 18:19. Log was grabbed via ssh at 18:36 1. Kernel warnings: Feb 28 16:05:07 kernel: NETDEV WATCHDOG: eth0: transmit timed out Feb 28 16:05:07 kernel: Unbalanced enable for IRQ 52 Feb 28 16:05:07 kernel: WARNING: at kernel/irq/manage.c:158 enable_irq() Feb 28 16:05:07 kernel: [<c0033b3c>] (dump_stack+0x0/0x14) from [<c0068180>] (enable_irq+0x68/0xac) Feb 28 16:05:07 kernel: [<c0068118>] (enable_irq+0x0/0xac) from [<bf01c3cc>] (sbi_get_int_status+0x4c/0x23c [gspi8xxx]) Feb 28 16:05:07 kernel: r5:c3c6e3a0 r4:00000005 Feb 28 16:05:07 kernel: [<bf01c380>] (sbi_get_int_status+0x0/0x23c [gspi8xxx]) from [<bf005f20>] (wlan_service_main_thread+0x1b4/0x544 [gspi8xxx]) Feb 28 16:05:07 kernel: r8:c3c6ed80 r7:c3c6ed70 r6:c3bf4000 r5:c3c6e3a0 r4:c3608000 Feb 28 16:05:07 kernel: [<bf005d6c>] (wlan_service_main_thread+0x0/0x544 [gspi8xxx]) from [<c005a820>] (kthread+0x50/0x7c) Feb 28 16:05:07 kernel: [<c005a7d0>] (kthread+0x0/0x7c) from [<c004a270>] (do_exit+0x0/0x7dc) Feb 28 16:05:07 kernel: r5:00000000 r4:0000000 2. Controller loses connection at 18:11, finally restored at 18:19 Feb 28 18:11:10 wpa_supplicant[526]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Feb 28 18:11:10 root: wpa_action eth0 DISCONNECTED Feb 28 18:11:25 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:11:26 wpa_supplicant[526]: Associated with <<ROUTER_MAC_ADDRESS>> Feb 28 18:11:26 wpa_supplicant[526]: WPA: Key negotiation completed with <<ROUTER_MAC_ADDRESS>> [PTK=CCMP GTK=CCMP] Feb 28 18:11:26 wpa_supplicant[526]: CTRL-EVENT-CONNECTED - Connection to <<ROUTER_MAC_ADDRESS>> completed (reauth) [id=0 id_str=] Feb 28 18:11:27 root: wpa_action eth0 CONNECTED Feb 28 18:11:27 udhcpc[575]: Performing a DHCP renew Feb 28 18:11:27 udhcpc[575]: Sending renew... Feb 28 18:11:30 udhcpc[575]: Lease of <<CONTROLLER_IP_ADDRESS>> obtained, lease time 259200 Feb 28 18:11:30 root: udhcpc_action eth0 renew ip=<<CONTROLLER_IP_ADDRESS>> Feb 28 18:11:33 wpa_supplicant[526]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Feb 28 18:11:33 root: wpa_action eth0 DISCONNECTED Feb 28 18:11:34 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:11:36 wpa_supplicant[526]: Associated with <<ROUTER_MAC_ADDRESS>> Feb 28 18:11:36 wpa_supplicant[526]: WPA: Key negotiation completed with <<ROUTER_MAC_ADDRESS>> [PTK=CCMP GTK=CCMP] Feb 28 18:11:36 wpa_supplicant[526]: CTRL-EVENT-CONNECTED - Connection to <<ROUTER_MAC_ADDRESS>> completed (reauth) [id=0 id_str=] Feb 28 18:11:36 root: wpa_action eth0 CONNECTED Feb 28 18:11:36 udhcpc[575]: Performing a DHCP renew Feb 28 18:11:36 udhcpc[575]: Sending renew... Feb 28 18:11:53 wpa_supplicant[526]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Feb 28 18:11:53 root: wpa_action eth0 DISCONNECTED Feb 28 18:11:54 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:11:56 wpa_supplicant[526]: Association request to the driver failed Feb 28 18:12:01 wpa_supplicant[526]: Authentication with 00:00:00:00:00:00 timed out. Feb 28 18:12:02 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:12:04 wpa_supplicant[526]: Associated with <<ROUTER_MAC_ADDRESS>> Feb 28 18:12:04 wpa_supplicant[526]: WPA: Key negotiation completed with <<ROUTER_MAC_ADDRESS>> [PTK=CCMP GTK=CCMP] Feb 28 18:12:04 wpa_supplicant[526]: CTRL-EVENT-CONNECTED - Connection to <<ROUTER_MAC_ADDRESS>> completed (reauth) [id=0 id_str=] Feb 28 18:12:04 root: wpa_action eth0 CONNECTED Feb 28 18:12:04 udhcpc[575]: Performing a DHCP renew Feb 28 18:12:04 root: udhcpc_action eth0 deconfig ip= Feb 28 18:12:04 udhcpc[575]: Sending discover... Feb 28 18:12:07 udhcpc[575]: Sending discover... Feb 28 18:12:10 udhcpc[575]: Sending discover... Feb 28 18:12:10 udhcpc[575]: Sending select for <<CONTROLLER_IP_ADDRESS>>... Feb 28 18:12:12 udhcpc[575]: Lease of <<CONTROLLER_IP_ADDRESS>> obtained, lease time 259200 Feb 28 18:12:12 root: udhcpc_action eth0 bound ip=<<CONTROLLER_IP_ADDRESS>> Feb 28 18:12:20 wpa_supplicant[526]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Feb 28 18:12:20 root: wpa_action eth0 DISCONNECTED Feb 28 18:12:22 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:12:23 wpa_supplicant[526]: Associated with <<ROUTER_MAC_ADDRESS>> Feb 28 18:12:23 wpa_supplicant[526]: WPA: Key negotiation completed with <<ROUTER_MAC_ADDRESS>> [PTK=CCMP GTK=CCMP] Feb 28 18:12:23 wpa_supplicant[526]: CTRL-EVENT-CONNECTED - Connection to <<ROUTER_MAC_ADDRESS>> completed (reauth) [id=0 id_str=] Feb 28 18:12:23 root: wpa_action eth0 CONNECTED Feb 28 18:12:23 udhcpc[575]: Performing a DHCP renew Feb 28 18:12:23 udhcpc[575]: Sending renew... Feb 28 18:12:26 udhcpc[575]: Lease of <<CONTROLLER_IP_ADDRESS>> obtained, lease time 259200 Feb 28 18:12:27 root: udhcpc_action eth0 renew ip=<<CONTROLLER_IP_ADDRESS>> Feb 28 18:12:42 wpa_supplicant[526]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Feb 28 18:12:42 root: wpa_action eth0 DISCONNECTED Feb 28 18:12:44 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:12:45 wpa_supplicant[526]: Associated with <<ROUTER_MAC_ADDRESS>> Feb 28 18:12:46 wpa_supplicant[526]: WPA: Key negotiation completed with <<ROUTER_MAC_ADDRESS>> [PTK=CCMP GTK=CCMP] Feb 28 18:12:46 wpa_supplicant[526]: CTRL-EVENT-CONNECTED - Connection to <<ROUTER_MAC_ADDRESS>> completed (reauth) [id=0 id_str=] Feb 28 18:12:46 root: wpa_action eth0 CONNECTED Feb 28 18:12:46 udhcpc[575]: Performing a DHCP renew Feb 28 18:12:46 udhcpc[575]: Sending renew... Feb 28 18:12:48 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:109 syncing system clock to hw clock: Mon Feb 28 18:12:48 2011 Feb 28 18:12:48 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:115 system clock now synced to hw clock: Mon Feb 28 18:12:48 2011 Feb 28 18:13:02 wpa_supplicant[526]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Feb 28 18:13:02 root: wpa_action eth0 DISCONNECTED Feb 28 18:13:03 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:13:05 wpa_supplicant[526]: Associated with <<ROUTER_MAC_ADDRESS>> Feb 28 18:13:05 wpa_supplicant[526]: WPA: Key negotiation completed with <<ROUTER_MAC_ADDRESS>> [PTK=CCMP GTK=CCMP] Feb 28 18:13:05 wpa_supplicant[526]: CTRL-EVENT-CONNECTED - Connection to <<ROUTER_MAC_ADDRESS>> completed (reauth) [id=0 id_str=] Feb 28 18:13:05 root: wpa_action eth0 CONNECTED Feb 28 18:13:05 udhcpc[575]: Performing a DHCP renew Feb 28 18:13:05 root: udhcpc_action eth0 deconfig ip= Feb 28 18:13:05 udhcpc[575]: Sending discover... Feb 28 18:13:05 udhcpc[575]: Sending select for <<CONTROLLER_IP_ADDRESS>>... Feb 28 18:13:07 udhcpc[575]: Lease of <<CONTROLLER_IP_ADDRESS>> obtained, lease time 259200 Feb 28 18:13:07 root: udhcpc_action eth0 bound ip=<<CONTROLLER_IP_ADDRESS>> Feb 28 18:14:31 wpa_supplicant[526]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Feb 28 18:14:31 root: wpa_action eth0 DISCONNECTED Feb 28 18:14:39 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:14:40 wpa_supplicant[526]: Associated with <<ROUTER_MAC_ADDRESS>> Feb 28 18:14:40 wpa_supplicant[526]: WPA: Key negotiation completed with <<ROUTER_MAC_ADDRESS>> [PTK=CCMP GTK=CCMP] Feb 28 18:14:40 wpa_supplicant[526]: CTRL-EVENT-CONNECTED - Connection to <<ROUTER_MAC_ADDRESS>> completed (reauth) [id=0 id_str=] Feb 28 18:14:41 root: wpa_action eth0 CONNECTED Feb 28 18:14:41 udhcpc[575]: Performing a DHCP renew Feb 28 18:14:41 udhcpc[575]: Sending renew... Feb 28 18:14:44 udhcpc[575]: Lease of <<CONTROLLER_IP_ADDRESS>> obtained, lease time 259200 Feb 28 18:14:44 root: udhcpc_action eth0 renew ip=<<CONTROLLER_IP_ADDRESS>> Feb 28 18:15:20 wpa_supplicant[526]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Feb 28 18:15:20 root: wpa_action eth0 DISCONNECTED Feb 28 18:15:22 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:15:23 wpa_supplicant[526]: Associated with <<ROUTER_MAC_ADDRESS>> Feb 28 18:15:24 wpa_supplicant[526]: WPA: Key negotiation completed with <<ROUTER_MAC_ADDRESS>> [PTK=CCMP GTK=CCMP] Feb 28 18:15:24 wpa_supplicant[526]: CTRL-EVENT-CONNECTED - Connection to <<ROUTER_MAC_ADDRESS>> completed (reauth) [id=0 id_str=] Feb 28 18:15:24 root: wpa_action eth0 CONNECTED Feb 28 18:15:24 udhcpc[575]: Performing a DHCP renew Feb 28 18:15:24 udhcpc[575]: Sending renew... Feb 28 18:15:42 wpa_supplicant[526]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Feb 28 18:15:43 root: wpa_action eth0 DISCONNECTED Feb 28 18:15:57 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:15:58 wpa_supplicant[526]: Associated with <<ROUTER_MAC_ADDRESS>> Feb 28 18:15:59 wpa_supplicant[526]: WPA: Key negotiation completed with <<ROUTER_MAC_ADDRESS>> [PTK=CCMP GTK=CCMP] Feb 28 18:15:59 wpa_supplicant[526]: CTRL-EVENT-CONNECTED - Connection to <<ROUTER_MAC_ADDRESS>> completed (reauth) [id=0 id_str=] Feb 28 18:15:59 root: wpa_action eth0 CONNECTED Feb 28 18:15:59 udhcpc[575]: Performing a DHCP renew Feb 28 18:15:59 root: udhcpc_action eth0 deconfig ip= Feb 28 18:15:59 udhcpc[575]: Sending discover... Feb 28 18:16:02 udhcpc[575]: Sending discover... Feb 28 18:16:02 udhcpc[575]: Sending select for <<CONTROLLER_IP_ADDRESS>>... Feb 28 18:16:04 udhcpc[575]: Lease of <<CONTROLLER_IP_ADDRESS>> obtained, lease time 259200 Feb 28 18:16:04 root: udhcpc_action eth0 bound ip=<<CONTROLLER_IP_ADDRESS>> Feb 28 18:16:13 wpa_supplicant[526]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Feb 28 18:16:13 root: wpa_action eth0 DISCONNECTED Feb 28 18:16:21 wpa_supplicant[526]: Trying to associate with <<ROUTER_MAC_ADDRESS>> (SSID='<<WPA_SSID>>' freq=2427 MHz) Feb 28 18:16:23 wpa_supplicant[526]: Associated with <<ROUTER_MAC_ADDRESS>> Feb 28 18:16:23 wpa_supplicant[526]: WPA: Key negotiation completed with <<ROUTER_MAC_ADDRESS>> [PTK=CCMP GTK=CCMP] Feb 28 18:16:23 wpa_supplicant[526]: CTRL-EVENT-CONNECTED - Connection to <<ROUTER_MAC_ADDRESS>> completed (reauth) [id=0 id_str=] Feb 28 18:16:23 root: wpa_action eth0 CONNECTED Feb 28 18:16:23 udhcpc[575]: Performing a DHCP renew Feb 28 18:16:23 udhcpc[575]: Sending renew... Feb 28 18:19:02 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:307 notify_playerModeChange: player (Player {Lounge}) mode has been changed to stop Feb 28 18:19:02 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:312 notify_playerModeChange: - audioState is 0 Feb 28 18:19:27 squeezeplay: INFO applet.ScreenSavers - ScreenSaversApplet.lua:292 activating BlankScreen screensaver Feb 28 18:22:47 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:109 syncing system clock to hw clock: Mon Feb 28 18:22:47 2011 Feb 28 18:22:48 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:115 system clock now synced to hw clock: Mon Feb 28 18:22:48 2011 Feb 28 18:30:04 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:146 acpower=1 Feb 28 18:30:04 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:682 setPowerState=active acpower=false Feb 28 18:30:04 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:1064 Set CPU speed 200000 Feb 28 18:30:44 squeezeplay: INFO applet.ScreenSavers - ScreenSaversApplet.lua:292 activating BlankScreen screensaver Feb 28 18:30:44 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:682 setPowerState=dimmed acpower=false Feb 28 18:30:44 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:1064 Set CPU speed 200000 Feb 28 18:30:45 squeezeplay: INFO net.socket - Networking.lua:1439 iwconfig power on Feb 28 18:32:14 dropbear[5908]: Child connection from <<SSH_CLIENT_IP_ADDRESS>>:4376 Feb 28 18:32:20 dropbear[5908]: password auth succeeded for 'root' from <<SSH_CLIENT_IP_ADDRESS>>:4376 Feb 28 18:32:20 dropbear[5911]: lastlog_perform_login: Couldn't stat /var/log/lastlog: No such file or directory Feb 28 18:32:20 dropbear[5911]: lastlog_openseek: /var/log/lastlog is not a file or directory! Feb 28 18:32:44 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:682 setPowerState=sleep acpower=false Feb 28 18:32:44 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:1064 Set CPU speed 50000 Feb 28 18:32:45 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:750 Store effect volume 50 Feb 28 18:32:47 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:109 syncing system clock to hw clock: Mon Feb 28 18:32:47 2011 Feb 28 18:32:48 squeezeplay: INFO applet.SqueezeboxJive - SqueezeboxJiveApplet.lua:115 system clock now synced to hw clock: Mon Feb 28 18:32:48 2011 Feb 28 18:35:52 dropbear[5955]: Child connection from <<SSH_CLIENT_IP_ADDRESS>>:60143 Feb 28 18:36:03 dropbear[5955]: password auth succeeded for 'root' from <<SSH_CLIENT_IP_ADDRESS>>:60143
FYI, still trying to reproduce the issue here. My goal is to reproduce with Settings->Advanced->Logging->Squeezeplay.ui set to DEBUG and see if there are any clues in the log when trying to navigate the broken UI.
Ben I'll add that I hadn't used the Controller all afternoon so the Kernel warning may also possibly have been the time it fell over. I was using the web interface to control the players in the afternoon and only tried the Controller at about 18.30, when I discovered it was locked up.
Just added debug-logging of Squeezeplay.ui and set up SSH so that I can post a log on next lock...
thanks Kim, I appreciate it. If you reproduce the issue, make sure to hit back arrow/home/any key that doesn't work after the UI lockup. What I'm looking for is whether those event handlers are firing and if there are clues to the problem when those non-working keys are hit
I've enabled the debug log on both of my Controllers. Where does this log get written (with no SD card) on a stock Controller, so I know where to pull the log file from if I get a lock up?
> Where does this log get written (with no SD card) on a stock Controller, so I know where to pull the log file from if I get a lock up? /var/log/messages
I'm thus far unable to reproduce (I'm testing with 7.5.3 r9283). A couple more questions for users seeing this issue if you'll indulge me... What is your "When Playing" screensaver? I am configured for the default, which pushes to the NP screen when music is playing. Does your normal use of the controller involve it going to sleep and waking up? That is, do you regularly set the controller down away from the cradle so it shows the "Please Wait" window when you pick it up? Outside of this problem, do you regularly see your controller losing its network connection? My hunch is that this isn't the root cause of the issue, but the log attached to this bug does show a lot of wifi network connectivity issues.
FYI, the steps I'm taking to try to reproduce is to play an album, let it play for a while, go to current playlist menu, confirm that I can navigate around, select other tracks, and exit this menu as desired. Select another album, let it play for a while, repeat process. If there's any modification to this test case I should make to better reproduce, please let me know and I will adjust accordingly
>What is your "When Playing" screensaver? I am configured for the default, > which pushes to the NP screen when music is playing. Same here. > Does your normal use of the controller involve it going to sleep and > waking up? That is, do you regularly set the controller down away from > the cradle so it shows the "Please Wait" window when you pick it up? No. My Controllers both live in their cradles. I have the Sleep Timeout set at 120, Suspend Enabled set to No, and Wireless Power Save set to Yes. I don't like having to wait whilst it comes out of suspend mode so I always disable that. > Outside of this problem, do you regularly see your controller losing > its network connection? My hunch is that this isn't the root cause of > the issue, but the log attached to this bug does show a lot of wifi > network connectivity issues. I've seen a red wireless status indicator a few times in the past but it's always actually worked fine when I've picked it up, and gone back to white, as if it was a red herring and the status hadn't updated itself. I guess the connection may have dropped but I'd not noticed it happening. > The steps I'm taking to try to reproduce is to play an album, let it play > for a while, go to current playlist menu, confirm that I can navigate > around, select other tracks, and exit this menu as desired. Select another > album, let it play for a while, repeat process. I find that I can listen to a load of albums using just the web interface and then as soon as I go to pick up the Controller because it's convenient to hit pause or because I don't have a computer to hand that it may have locked up. So the problem can occur when you're really not using the Controller itself at all.
My screensaver for "When playing" is "Now Playing" (showing album cover). Usually my Controller only leaves the cradle for the short time it takes to change albums. AFAIK I have no wifi network connectivity issues. My navigation behaviour pretty much matches your descriptions, Main Menu > My Music > Browse Albums > Pick Album Main Menu > Browse Albums > Pick Album Main Menu > New music > Pick Album After picking the album, I let it play an sometimes the menu lock as described.
Created attachment 7181 [details] Log from controller: Navigation and pressing keys after lock
My Controller navigation locked as described at 17:46 (or before). Unfortunately it appears that the logging was first turned on, when I scp'd the file /var/log/messages, so the actual event is not included in the log. Still, it made it possible to log navigation and keypressing afterwards: Event function errors appears to be triggered, so hopefully it might give some clues anyways ;o)
Additional info on navigation routes leading to the menu-lock: I have a hunch that picking a number of albums (one after the other) from "New music" or "Browse albums" without returning to the main menu might be involved: Main Menu > New music > Pick Album (Now playing, listen some) > Pick album > ... Also, when the menu is locked, I can change the playlist using the webinterface: The now playing screensaver on the Controller updates to the playing album, but the menu remains locked.
On the forum Mnyb mentioned that holding the power/home button for a while could be used to reset the Controller (instead of taking out the battery). I tried it and it works here to - only the button needs to be held down for 10-15 seconds before the Controller powers down, not the usual 2-3 seconds.
I'll concur that I discovered too that a long press of the home/power button will turn the Controller off after a lock. I'll also concur that when the Controller has gone into locked button state the screen will still update normally if controlled externally, so choosing a different album from another Controller or the web interface correctly updates the now playing screen, so it is seemingly just the buttons which stop working.
Excellent! Kim, thanks for that log-- the error message in your log looks to me to be the smoking gun this error in the event dispatcher Mar 2 18:01:15 squeezeplay: WARN squeezeplay.ui.draw - jiveL_dispatch_event:774 error in event function: Mar 2 18:01:15 squeezeplay: ...share/jive/applets/SlimBrowser/SlimBrowserApplet.lua:2239: attempt to index a nil value corresponds to this line in SlimBrowserApplet.lua: -- we don't care about events not on the current window -- assumption for event handling code: _curStep corresponds to current w if _getCurrentStep().menu != menu then Lua gets angry and dies when you try to drill into a nil object, so I think what's happening here is that _getCurrentStep() is nil, therefore _getCurrentStep().menu is a no-no. I believe this error would result in the "lockup" condition that many are seeing. Why _getCurrentStep() is nil in certain circumstances I don't have a handle on, but I'm willing to bet this issue can be fixed with a trivial change to this line. Line 2239 of /usr/share/jive/applets/SlimBrowser/SlimBrowserApplet.lua should be changed to: if _getCurrentStep() and _getCurrentStep().menu != menu then If you're feeling industrious and want to try that change out, you can vi that file when you are ssh'ed in, change it to that, and reboot. I'd love to hear how it goes.
flagging for bug_meeting again
Created attachment 7183 [details] proposed patch to fix problem with drilling into nil object
I've made the change to both of my Controllers and left debugging enabled for the time being. I'll try to give them a good workout and see if this will resolve the issue.
Great-- I really appreciate all of the extra debug you've all done here, it's been a tremendous help as my controller just seems to want to always work :)
Created attachment 7187 [details] Controller log: Playing one album ending in lock
I just added another log from the Controller: I played one album and when it ended, I noticed the Controller was locked. As this is a log of an entire playing session, maybe it can give hits as to why the nil object appears. I haven't tried the proposed fix yet, I'll try to implement the change later ;o)
That would be the expected failure before the code fix I proposed. Needs to be verified that the bug doesn't happen after the change.
Patch now implemented on my Controller, will be testing and hopefully nothing happens ;o)
Created attachment 7191 [details] /var/log/messages after a different navigation error Ben I've given both of my Controllers a really good workout yesterday with the patch applied and they've been flawless. Today I decided to do the same again began an album playing through the Controller menus. Then I hit the back button to get into the same artist and hit + to queue up a different album by the same artist. Every time I hit the + button I get the screen 'bounce' but no action is taken. I've attached a debug message log in case this is related to the other navigation problem and may help to identify the root cause. Paul
thanks for the feedback Paul. If your controller is still in this state or you can get it into this state again, can you see if going all the way to the home menu and then browsing back to that album and then hitting + works. I have a strong suspicion that it will, but would like to confirm. The root cause of this is very tricky, but what I think is happening is that the browse stack of window data (contains the entire tree of windows, underlying menus, command callbacks, etc.) is somehow getting lost or corrupted. Before the patch, the underlying issue was exposing a trivially fixed but critical bug in the code (trying to drill into a nil object causing the event handler to die), but now that the patch fixes that, the underlying problem of the browse stack data being incomplete is now visible. I hope that makes sense :) I'm of the opinion the patch I provided is a good step forward, and I will check this into 7.5/trunk. Getting at the underlying issue may prove more difficult, but this at least gets the controller past the I'm-so-angry-I-have-to-reboot-this-thing issue.
Ben I did mean to add that navigating back a step as far as the artists menu and then drilling back in to see the album list then allowed the + button to function normally so it does look like the populated list is somehow getting lost. My exact sequence of events was: Navigate to artist, click centre button Scroll to album, click play button Click back button Scoll to different album by same artist Click + button and get screen bounce Hopefully that information may help to track down where this may be happening in case it's an easy fix too and we can get a complete solution wrapped up. Paul
I've been testing with the patch implemented all weekend and so far i haven't had a menu-lock, so the fix appears to work just fine! Thanks! :o) I'm not entirely sure, but I think the Controller used to show the 'Browse albums'-catalog when having played an album, now it shows 'Now playing'-playlist - it adds an extra keypress on occation, but in any case it's way better than the lock. Just took a look at the log, only new thing is a couple bursts of these errors with maybe 40-50 identical lines running at 4-6 per second, don't know if it's related: Mar 5 20:02:30 squeezeplay: ERROR squeezeplay.ui - jive_surface_get_size:548 Underlying sdl surface already freed, possibly with release()
> I'm not entirely sure, but I think the Controller used to show the 'Browse > albums'-catalog when having played an album, now it shows 'Now > playing'-playlist - it adds an extra keypress on occation, but in any case it's > way better than the lock. I've noticed something similar. It seems that you can start an album playing and then hitting back may put you in the playlist or may put you at the album browse screen even when you haven't been into the actual playlist. But I've been through loads of albums and individual tracks to try to break it this weekend and haven't managed to. I think we've found something buggy in the navigation still, which was leading to the locks before, as I'm still also finding that condition I reported earlier in the thread where it won't let you click on an album until you've refreshed the screen but it's a whole lot better than locking up.
Question to users experiencing this bug: are you running any additional 3rd party applets, using the Patch Installer to install a 3rd party patch, or tweaking the firmware through ssh at all? Trying to understand why I'm unable to reproduce the issue. My hunch is that the root cause is a problem with the data structure being erroneously freed from memory. The error reported in comment#45 seems to suggest that. Mar 5 20:02:30 squeezeplay: ERROR squeezeplay.ui - jive_surface_get_size:548 Underlying sdl surface already freed, possibly with release() Without being able to reliably reproduce the bug here I'm not extremely optimistic about a quick answer to the root cause issue. To be clear, the patch is a solid fix for the event handler dying, but not for whatever is causing the browse stack data structure to disappear. That means that the root issue is still there, but the workaround now is not to reboot, but to go back to the home menu (e.g. via the home button) to start a new browse stack. Not ideal, but far better. The patch will be checked into a special branch so we can push out a fix to all 7.5.3 users without requiring a full 7.5.4 release. Though the users that are seeing this are reporting it on controller, I have no reason to believe it would be restricted to that platform. New 7.5.3 release should go to Controller, Radio, and Touch. The root issue is still unknown, but the priority can drop a bit with a firmware that includes the patch.
Ben The only Controller-related applet I'm running is the Switch Player (v0.2) plugin by Triode, which allows you to move a playlist on-the-fly from one player to another by temporarily engaging synchronization and then dropping it on the source player. Bear in mind also that the sequence of steps I posted in comment#45 to generate the issue is using the 7.5.2 version of SBS because I've found 7.5.3 too problematic with AAC internet radio decoding to be able to keep it as a production system. I can temporarily install 7.5.3, patch it, and then test against this if you think it will be of benefit. I did also wonder myself whether this same issue affects the other Jive players, or whether there is something peculiar to the Controller code.
> Question to users experiencing this bug: are you running any additional 3rd > party applets, using the Patch Installer to install a 3rd party patch, or > tweaking the firmware through ssh at all? Trying to understand why I'm unable > to reproduce the issue. I use no additional applets og plugins at all. Language is set to "Danish/Dansk", that the only change from default. The only patch I've made is the fix suggested in this thread, using SHH and VI. If it can be of help, I could provide you with my full logs for the past few days?
Kim, couldn't hurt. I'd be happy to look through them. Feel free to attach them to the bug.
Created attachment 7193 [details] Complete log for bug fix testing period Complete logs for bug testing period uploaded.
I've decided to have another go with 7.5.3 today so I've substituted in the 7.5.2 faad executable on the server, which should hopefully allow me to stream AAC radio stations between the 'proper' listening. I've upgraded the firmware on both Controllers and patched them, and made sure that debug logging is still enabled on the user interface. The test case I posted with artist -> album navigation appears to be working fine now, so this may have been something that was changed in the 7.5.3 release anyway.
patch was checked in on a 7.5 feature branch. We're likely going to push that fix out as a 7.5.3 firmware only release sometime in the reasonably near future. You will not need to update SBS to get this release when we do it, it will be pushed automatically. Sorry, as yet I have no idea re: the root cause of the underlying issue, but this patch alone is worth pushing out to workaround the issue of the event handler dying. == Auto-comment from SVN commit #9348 to the jive repo by bklaas == == http://svn.slimdevices.com/jive?view=revision&revision=9348 == Bug: 17006 Description: never drill into a _getCurrentStep() object before knowing if _getCurrentStep() exists
Ben I've had no more navigation issues with either of my Controllers since I applied the patch several weeks ago now, so it definitely seems to resolve the issue. You mentioned a firmware-only release. How would this be delivered for SBS-only users, i.e. users who never connect to mysqueezebox.com? And would this work for users currently on 7.5.2? Or is it going to be delivered in the 7.5.4 release once Andy fixes the AAC crashing problem (bug # 16874)? I'm having to retain 7.5.2 until this bug is resolved because we've got a couple of favourite radio stations that are AAC and keep crashing 7.5.3 but I'd prefer to be on a stable current release. I've just picked up another 3 Controllers and would prefer not to have to maintain them individually. Thanks Paul
I too can confirm that I haven't had any problems with my Controller since the patch.
Ben I've just looked at the changelog for 7.5.4 from the nightly repository now that Andy's flagged it as RC status for next week and I can't see this bug mentioned. Is this fix going to be included in the 7.5.4 release, or am I going to have to hack all of Controllers manually again when I apply it? Paul
Andy is only covering server-side things in that changelog, and this fix is client-side. I'm just back from a week's vacation so I don't know if the plan has changed, but we were going to push out a 7.5.3 firmware that includes this change. That means that anyone running 7.5.3 SBS (or connected to mysb.com) would receive a firmware update notification within 12 hours of it being published. If 7.5.4 is going to be released very soon though, it might make sense to just wait and push this out with 7.5.4. I'll catch up with my colleagues tomorrow regarding those plans. On 7.5.2, sorry. You won't get this fix if you are running an older version of the server.
7.5.3 firmware update was pushed a few minutes ago. If you are really anxious about this fix, you can restart your SBS and you should see the update push pretty soon after server restart. Otherwise expect a firmware update notification on your controller within the next 12 hours.
Thanks Ben. That's come through already.
Ben Running r9377 against a vanilla 7.5.3 server at the moment. Twice over the weekend I've picked up the Controller which is showing a blank Now Playing screen and not been able to navigate using the home or back buttons. I've started playing something from the web interface and it responds. Managed to click the centre button to get into the playlist but back and home weren't working. Then it crashed and rebooted. That's the exact same scenario I've seen twice. Time for debug logging again, or is it worth waiting until we get a 7.5.4 version of Controller firmware first when the new version is released? Cheers Paul
7.5.4 is coming soon, so I might suggest waiting for that one. What is of even more interest to me going forward is whether what you've been seeing is still present in 7.6.
Hi, may be another behavior related to that bug. I purchased last week the Duet and a Synology DS411+ (DSM 3.0-1354). Everything connected to a 1 Gbit wired LAN (cat 5e and Netgear GS608), with the same subnet mask, and to a 100-Mbit Belgacom Bebox2 router for accessing the Internet. I then created a mysqueezebox account and installed the Squeeze Server package on the Syno (Version : 7.5.3 - r31792 @ Mon Jan 24 08:21:38 MST 2011). At the first connection, the controller (and may be the receiver ?) upgraded to the new look'n feel (Version : 7.5.3 - r9377). Every evening, I face to the following: after listening to music for 2-3 hours (internet radio or *.wav cd collection), the controller seems to lose the connection to the receiver. The Pause button doesn't work anymore and I cannot deactivate the receiver because the controller display the "activate squeezebox receiver" command instead of "deactivate...". Pushing on any button causes a connection trial that fails in any case: the controller/receiver is unable to connect to the DiskStation nor to mysqueezebox.com. But the music is still playing ! At that moment, I only want to stop the music and deactivate the receiver... which seems impossible. There are however 2 things I can do: 1. from a computer, connect to the Squeeze Server and stop the music steam... and wait. After a few minutes, things seem back to normal, or, 2. remove the outlet of the receiver, and remove the battery from the controller (sounds like an MS-Windows reset). After reconnecting, everything works fine. To me, it seems something at some point is causing a confusion, from controller point of view, regarding the state of the receiver. Not really disturbing, just the felling it doesn't work perfectly. Regards
hi Olivier, I'm sorry you're having problems with your setup and hope we can come to some conclusion on how to remedy. After reading your description, I'm convinced your issue is unrelated to this bug, so I'm opening a separate one for it. This bug I'm moving to RESOLVED. FYI, 7.5.4 will probably be released within the next week. Current release candidate on the firmware side is r9408
Created attachment 7234 [details] /var/log/messages after Controller sticks in Now Playing screen Ben I don't know whether you want to reopen this applied to 7.5.4 or see if this is a separate issue but here's a capture of /var/log/messages when my Controller has got stuck into the Now Playing window and the Home and back buttons don't work. Power off does, so it can be rebooted. This is the issue I'd seen in 7.5.3 as well. Currently running the release version of 7.5.4. Paul
*** Bug 16309 has been marked as a duplicate of this bug. ***
Ben Can we get this reopened now please, as the related navigation bug (see the last log I attached) is affecting 7.5.4 as well, so it looks like there's still an underlying issue. Cheers Paul
FYI, I opened bug 17209 in response to comment#65 of this bug, which I feel is unlikely to be the same issue.
Updated to 7.6.0r32390 w/ fw 9430 Controller has not lost function while playing multiple albums