Bugzilla – Bug 14423
IR play command handled twice
Last modified: 2010-04-08 17:25:42 UTC
Created attachment 5955 [details] player.source=INFO,plugin.slacker=DEBUG Finally was able to reproduce this, and I don't think I ever filed a bug. Steps to reproduce were: Make sure player was stopped On player UI, go to My Apps -> Slacker -> Favorites -> some favorite Play Should be able to reproduce it with Pandora too. Log attached.
It is a pity you saw this with Slacker as I cannot test with it and it is the only service protocol handler that has not been fully converted to new-streaming. From the log, the interesting section is: [09-09-29 21:39:38.8990] Slim::Player::StreamingController::play (1947) 00:04:20:05:ab:fa [09-09-29 21:39:38.8998] Slim::Player::StreamingController::_setPlayingState (2215) new playing state STOPPED [09-09-29 21:39:38.9001] Slim::Player::StreamingController::_setStreamingState (2228) new streaming state IDLE [09-09-29 21:39:38.9008] Slim::Player::Song::new (107) index 0 -> slacker://stations/1601610/446.mp3 [09-09-29 21:39:38.9013] Slim::Player::StreamingController::_setStreamingState (2228) new streaming state TRACKWAIT [09-09-29 21:39:38.9017] Slim::Player::Song::getNextSong (228) slacker://stations/1601610/446.mp3 [09-09-29 21:39:38.9021] Slim::Player::Song::getNextSong (250) scanning URL slacker://stations/1601610/446.mp3 [09-09-29 21:39:38.9026] Slim::Player::Song::getNextSong (228) slacker://stations/1601610/446.mp3 [09-09-29 21:39:38.9032] Slim::Plugin::Slacker::ProtocolHandler::_getNextTrack (149) 00:04:20:05:ab:fa Getting next track from SqueezeNetwork [09-09-29 21:39:38.9053] Slim::Player::StreamingController::_playersMessage (770) Getting stream info...: slacker://stations/1601610/446.mp3 [09-09-29 21:39:39.1498] Slim::Player::StreamingController::play (1947) 00:04:20:05:ab:fa StreamingController::play gets invoked a second time. Just at the moment I don't know why. What UI did you use to invoke this? Any chance of a double press of the play button? After this double _getNextTrack(), do the display and the playing track coincide? Possibly not, as part of Slacker's non-conversion to new-streaming is that it still stores the track metatdata in Client->master->pluginData('currentTrack')/('prevTrack'), rather than using Song->pluginData() as used by all the converted handlers. The associated tracking and assumptions cannot handle a track that has been got not being played. So far, I have been unable to recreate this with Pandora.
Created attachment 5956 [details] One with Pandora and backtraces May be IR or button-related. Can only reproduce from the player UI, not the web UI.
It turns out this is an IR or button handling bug. One IR play command comes in, but it is handled twice. Triode/KDF: would one of you be able to take a look?
Is there a reproduceable case that doesn't depend on services I cannot use?
Both of the items I tested are plain type=audio items in XMLBrowser. Maybe it will work with a radio stream?
I haven't had any time to test (not near any hardware). However, from the log it's loopking like it's triggering the play command on press AND release (Slim::Hardware::IR::checkRelease). In a lot of cases in Default.map, if we are using play.single mapped to play, then we map play to dead: [browsedb] play = dead play.single = play_0 play.hold = create_mix However, in [common] this is not the case. The mapping heirarchy may be at play, and this would mean that if xmlbrowse mode came from an INPUT.List (I think a lot of cases do this) then it gets the play.single = play from xmlbrowse, then gets the play = passback from INPUT.List and causes a play function call from the common mode. Not sure how to handle, aside from adding a line to [common] play = dead Try that with the reproduceable case. Perhaps also turn on some of the IR debugging.
I tried that. It solves the specific problem but then 'play' does not act as it should in some other cases. For example, play will no longer resume from pause on the NP screen.
So can this be reproduced outside US Alan?
The bug should occur on any playable item within XMLBrowser.
Triode, KDF, Any more ideas on how to fix this?
may have some time this weekend to have a look (if writing a job app doesn't take up all my time). To help shorten the demand, anyone got some steps to reproduce the original problem and the problem caused by my proposed change using an xmlbrowse-based plugin that's not restricted? Do they show up when the Queen plugin, for example or shoutcast?
Looking at this, looks like the second play occurs on play.single in mode block - this could be the reason why we only see it in xmlbrowser? What about mapping play.* to dead in mode block? [09-12-04 21:31:47.9895] Slim::Hardware::IR::lookupCodeBytes (450) 768910ef -> code: play [09-12-04 21:31:47.9901] Slim::Hardware::IR::processIR (690) 768910ef 628.696 1259962307.99005 [09-12-04 21:31:47.9907] Slim::Hardware::IR::lookup (479) Found button play for 768910ef [09-12-04 21:31:47.9912] Slim::Hardware::IR::lookupFunction (523) Found function: play for button play in mode INPUT.Choice [09-12-04 21:31:47.9917] Slim::Hardware::IR::processIR (784) irCode = [play] timer = [628.696] timediff = [0.642000000000053] last = [exit_right] [09-12-04 21:31:47.9921] Slim::Hardware::IR::processCode (1117) irCode: play, 00:04:20:1e:00:57 [09-12-04 21:31:47.9928] Slim::Hardware::IR::lookupFunction (523) Found function: play for button play in mode INPUT.Choice [09-12-04 21:31:47.9943] Slim::Hardware::IR::executeButton (1064) Trying to execute button [play] for irCode: [play] [09-12-04 21:31:47.9951] Slim::Hardware::IR::executeButton (1095) Executing button [play] for irCode: [play] Slim::Buttons::Input::Choice::__ANON__ [09-12-04 21:31:48.0397] Slim::Hardware::IR::lookupCodeBytes (450) 768910ef -> code: play [09-12-04 21:31:48.0400] Slim::Hardware::IR::processIR (690) 768910ef 628.747 1259962308.03999 [09-12-04 21:31:48.0403] Slim::Hardware::IR::lookup (479) Found button play for 768910ef [09-12-04 21:31:48.0405] Slim::Hardware::IR::lookupFunction (530) irCode not defined: [play.repeat] for mode: [block] [09-12-04 21:31:48.0407] Slim::Hardware::IR::repeatCode (970) irCode = [undef] timer = [628.747] timediff = [0.0509999999999309] last = [play] [09-12-04 21:31:48.2482] Slim::Hardware::IR::lookup (479) Found button play for 768910ef [09-12-04 21:31:48.2485] Slim::Hardware::IR::lookupFunction (523) Found function: play for button play.single in mode common [09-12-04 21:31:48.2488] Slim::Hardware::IR::processCode (1117) irCode: play, 00:04:20:1e:00:57 [09-12-04 21:31:48.2491] Slim::Hardware::IR::lookupFunction (530) irCode not defined: [play] for mode: [playlist] [09-12-04 21:31:48.2494] Slim::Hardware::IR::executeButton (1064) Trying to execute button [play] for irCode: [play] [09-12-04 21:31:48.2499] Slim::Hardware::IR::executeButton (1095) Executing button [play] for irCode: [play] Slim::Buttons::Playlist::__ANON__
Hum - its more complex than this and is an example of something I've wrestled with in the past. The checkRelease timer can fire after the button mode changes with the new push into NP on play operation. This means that we get play.single occuring in playlist mode even though the original play is in INPUT.Choice. (we can also see play.repeat or single occuring in block mode depending on how long it takes to do the intial processing of the xmlbrowser play) I think the right way to solve this is to modify the ir handling so checkRelease only does something if it fires in the mode which it was set in. Does this sound reasonable?
== Auto-comment from SVN commit #29543 to the slim repo by adrian == == https://svn.slimdevices.com/slim?view=revision&revision=29543 == Bug: 14423 Description: don't fire checkRelease if the mode has changed from the time it was initiated - this avoids additional button processing which is unexpected due to .hold and .single being processed when checkRelease fires
Alan/Andy - please check if #29543 fixed the original issue. From the debugs I believe it no longer causes a second play command, but I don't know the original problem. Kdf - hopefully saved you some time for more important things..
are there any use cases where play would trigger a mode change, and still want to be tracking for a hold or hold_release? Very tricky trying to act on press and release events while covering all cases.
Well I think those cases would be broken with the move to 7.4 as prior to that play caused a show briefly but no mode change, now there is a mode change to mode playlist which also has a play handler and so any .single .hold would be processed in playlist mode. I've seen this in problem cases before caused by the forced mode change and thought about the change I've just made. Lets see if any side effects turn up, but it seems the right thing to do.
I'm with you now. Sounds good and will have a watch at the results. Thanks for leaving me the time (I'll need it)
This looks good to me. It passes all the test cases I can think of.
== Auto-comment from SVN commit #29550 to the slim repo by ayoung == == https://svn.slimdevices.com/slim?view=revision&revision=29550 == Fixed bug 14423: IR play command handled twice
Unfortunately the fix for this in #29550 has caused a side effect that passback from screensave modes for .single and .hold (play, pause) does not work and now needs two button presses. It looks like the old code relied on the timer events firing in a different mode rather than passback working... I will look at it.
Created attachment 6398 [details] proposed patch - resend button event on passback Attached fixes the problem with pause/stop not working in a screensaver caused by the previous fix for this bug. Can anyone see a problem with it? It means that screensavers will "passback" the button event which triggered them to be cancelled rather than passing back the raw ir.
I don't know the IR code well enough to spot any issues, but I'm fine with you just checking it in and we'll see what happens. :)
== Auto-comment from SVN commit #29670 to the slim repo by adrian == == https://svn.slimdevices.com/slim?view=revision&revision=29670 == Bug: 14423 Description: change 29550 caused a side effect that pause and stop (holding pause) required two button presses when in a screensaver as the passback mechanism was not the reason these worked... This patch causes passback from a screensaver to repeat the button event which caused the screensaver to exit rather than repeating the ircode bytes which will not lead to .single or .hold events being passed back.
Fixing target, this was not fixed in 7.4.
This bug has been marked fixed in a released version of Squeezebox Server or the accompanying firmware or mysqueezebox.com release. If you are still seeing this issue, please let us know!