mhilbush
(Mark)
January 22, 2017, 2:16pm
7
Could be a bug. I’ll look into it.
Do you recall if the player was paused or powered off prior to the notification?
Were you streaming from a remote source (Pandora, Spotify, etc.) or from your local music library?
What was the player (squeezelite, squeezeplay, receiver, boom, etc.) and what was the version of LMS?
Yeah, I tracked down the issue in squeezelite. When streaming short content that can be read in a single read request, the streaming thread never gets into the state necessary to start the decoder. I’m hoping Ralphy can come up with a fix. I built a version that works on Ubuntu running on Intel, but I haven’t gotten around to building a version for the piCorePlayer.
Rob_Pope
(Rob Pope)
January 22, 2017, 3:32pm
8
Player was paused and is reproducable
Local music library
mhilbush:
What was the player (squeezelite, squeezeplay, receiver, boom, etc.) and what was the version of LMS?
Squeezelite 1.7 on a Pi3 and LMS is 7.7.5 - 1416570306
Hope this helps
mhilbush
(Mark)
January 22, 2017, 4:24pm
9
Thanks, that’s helpful. I’ll build a 1.7 version to see if I can reproduce.
Rob_Pope
(Rob Pope)
January 22, 2017, 6:23pm
10
Sorry, I told a lie, it’s as follows:
Player Model: SqueezeLite
Firmware: v1.8.5-823
mhilbush
(Mark)
January 22, 2017, 8:53pm
11
Rob_Pope:
Firmware: v1.8.5-823
Ah, even better. That’s the version I’m running on my pCP.
mhilbush
(Mark)
January 24, 2017, 11:56am
12
I reworked the logic that restores the player state after the notification finishes. There’s a new version here if you want to test it.
Rob_Pope
(Rob Pope)
January 24, 2017, 1:18pm
13
Thanks Mark, I’ll give it a go this evening
mhilbush
(Mark)
January 26, 2017, 12:30am
14
Hey @Rob_Pope , did you get a chance to see if this fixed the issue?
Rob_Pope
(Rob Pope)
January 26, 2017, 7:06am
15
Hi Mark. Sorry, I’ve been out for the past couple of evenings. I just copied the latest jar over and restarted OpenHAB, but it still resumes playback after TTS if the audio was paused. If the squeezelite player is powered off it does not resume music playback afterwards.
I’m having some issues with my amp cutting out during audio playback at the moment, which isn’t helping testing, but I can see the playlist on the web to see what’s happening and hear the occaisional utterance.
mhilbush
(Mark)
January 26, 2017, 11:39am
16
Ugh. Can you put the squeezebox binding in debug mode, then capture the openhab.log entries when the TTS plays? I’d like to see the state of the player before the TTS plays, as well as what happens when the player state is restored.
I’m not able to recreate this with my squeezelite 1.8.5 due to the squeezelite issue I described above. Not sure why your version is working.
Rob_Pope
(Rob Pope)
January 26, 2017, 1:17pm
17
Sorry, n00b question, how can I put the binding in debug mode?
I’ve just tidied up some old links though Karaf that were making my log look messy, so I’ll do some more testing this evening.
Rob
mhilbush
(Mark)
January 26, 2017, 1:24pm
18
Ah, sorry.
Launch the Karaf console as described here.
http://docs.openhab.org/administration/console.html
Then at the command prompt, enter this.
log:set DEBUG org.openhab.binding.squeezebox
You can turn off debug mode by entering this.
log:set INFO org.openhab.binding.squeezebox
1 Like
g_g_rich
(g_g_rich)
January 26, 2017, 7:22pm
19
Hi Mark.
I can confirm this happens - that the music resumes after TTS when the player is paused. This happens with both Squeezeplay and Squeezelite players.
log:
2017-01-26 12:55:53.325 [DEBUG] [eezebox.internal.SqueezeBoxAudioSink] - Squeezebox audiosink processing audioStream /audio/c8a3cac5-0fe7-4b9c-ab47-d286566ef124 of format AudioFormat [codec=MP3, container=NONE, ]
2017-01-26 12:55:53.326 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Play notification sound on player 20:cf:30:53:a1:cd at URI /audio/c8a3cac5-0fe7-4b9c-ab47-d286566ef124.mp3
2017-01-26 12:55:53.329 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Cur State: vol=90, mut=NOT MUTED, pwr=ON, stp=NOT STOPPED, ctl=PAUSED, shf=OFF, rpt=OFF, tix=0, tnm=38, tim=126
2017-01-26 12:55:53.331 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Setting up player for notification
2017-01-26 12:55:53.331 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 20:cf:30:53:a1:cd pause 1
2017-01-26 12:55:53.333 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 20:cf:30:53:a1:cd mixer volume 90
2017-01-26 12:55:53.334 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Playing notification
2017-01-26 12:55:53.335 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 20:cf:30:53:a1:cd playlist add http://192.xxx.xxx.xxx:8080/audio/c8a3cac5-0fe7-4b9c-ab47-d286566ef124.mp3
2017-01-26 12:55:53.336 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Waiting for playlist to be updated...
2017-01-26 12:55:53.738 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Done waiting for playlist to be updated
2017-01-26 12:55:53.740 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 20:cf:30:53:a1:cd playlist index 38
2017-01-26 12:55:53.743 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Waiting for notification message to finish...
2017-01-26 12:55:57.451 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Done waiting for notification to finish
2017-01-26 12:55:57.453 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 20:cf:30:53:a1:cd playlist delete 38
2017-01-26 12:55:57.455 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Waiting for playlist to be updated...
2017-01-26 12:55:59.160 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Done waiting for playlist to be updated
2017-01-26 12:55:59.162 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Restoring player state
2017-01-26 12:55:59.164 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 20:cf:30:53:a1:cd mixer volume 90
2017-01-26 12:55:59.167 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Resuming last item playing
2017-01-26 12:55:59.168 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 20:cf:30:53:a1:cd playlist index 0
2017-01-26 12:55:59.171 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 20:cf:30:53:a1:cd time 126
2017-01-26 12:55:59.173 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Pausing the player
2017-01-26 12:55:59.174 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 20:cf:30:53:a1:cd pause 1
I compiled the latest version of squeezelite with your workaround for the Raspberry Pi and it seems to be working ok in my piCorePlayers.
https://github.com/airix1/squeezelite/releases/download/v1.8.6-830/squeezelite-armv6hf-ffmpeg
https://github.com/airix1/squeezelite/releases/download/v1.8.6-830/squeezelite-armv6hf-noffmpeg
Rob_Pope
(Rob Pope)
January 26, 2017, 9:39pm
20
For some reason the TTS is timing out this evening for me. The logs are below (and I believe quite similar to @g_g_rich ’s)
2017-01-26 21:31:43.289 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:35:02:cc pause 1
2017-01-26 21:31:56.450 [DEBUG] [eezebox.internal.SqueezeBoxAudioSink] - Squeezebox audiosink processing audioStream /audio/a66430ee-1154-4cee-b71e-f6bcfd2e3bb5 of format AudioFormat [codec=MP3, container=NONE, ]
2017-01-26 21:31:56.452 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Play notification sound on player b8:27:eb:35:02:cc at URI /audio/a66430ee-1154-4cee-b71e-f6bcfd2e3bb5.mp3
2017-01-26 21:31:56.467 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Cur State: vol=40, mut=NOT MUTED, pwr=ON, stp=NOT STOPPED, ctl=PAUSED, shf=OFF, rpt=OFF, tix=10, tnm=21, tim=142
2017-01-26 21:31:56.469 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Setting up player for notification
2017-01-26 21:31:56.471 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:35:02:cc pause 1
2017-01-26 21:31:56.472 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Initializing notification volume to current player volume
2017-01-26 21:31:56.475 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:35:02:cc mixer volume 40
2017-01-26 21:31:56.477 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Playing notification
2017-01-26 21:31:56.478 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:35:02:cc playlist add http://192.168.5.3:8081/audio/a66430ee-1154-4cee-b71e-f6bcfd2e3bb5.mp3
2017-01-26 21:31:56.484 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Waiting for playlist to be updated...
2017-01-26 21:31:56.886 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Done waiting for playlist to be updated
2017-01-26 21:31:56.888 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:35:02:cc playlist index 21
2017-01-26 21:31:56.890 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Waiting for notification message to finish...
2017-01-26 21:32:26.921 [WARN ] [ebox.handler.SqueezeBoxPlayerHandler] - Timed out waiting for notification to complete!
2017-01-26 21:32:26.923 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:35:02:cc playlist delete 21
2017-01-26 21:32:26.925 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Waiting for playlist to be updated...
2017-01-26 21:32:27.327 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Done waiting for playlist to be updated
2017-01-26 21:32:27.328 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Restoring player state
2017-01-26 21:32:27.330 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:35:02:cc mixer volume 40
2017-01-26 21:32:27.332 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Resuming last item playing
2017-01-26 21:32:27.333 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:35:02:cc playlist index 10
2017-01-26 21:32:27.335 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:35:02:cc time 142
2017-01-26 21:32:27.337 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Pausing the player
2017-01-26 21:32:27.338 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:35:02:cc pause 1
2017-01-26 21:32:40.577 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
Thanks for the updated library too Rich, I’ll give it a go at the weekend.
mhilbush
(Mark)
January 26, 2017, 9:42pm
21
The timeout is a symptom of the squeezelite bug. Rich’s build of squeezelite should resolve that.
It might help the priority of getting a permanent fix if you posted a “me too” on the squeezelite thread.
Rob_Pope
(Rob Pope)
January 26, 2017, 9:46pm
22
It’s strange because the same text was working this morning. It’s a fairly long string which should have caused the buffer to fill up a few times. I’ll add my name to the list now
mhilbush
(Mark)
January 26, 2017, 10:01pm
23
Thanks for the debug log.
It definitely shows the player is paused prior to the notification playing. And, it definitely shows the pause command being issued after the notification completes. I’ll need to look into this more closely.
Awesome. Thanks for doing that!
How are you installing this on your piCorePlayer? Are you copying the executable to the pcp, then replacing the existing version of squeezelite at /tmp/tcloop/pcp-squeezelite/usr/local/bin/squeezelite
?
mhilbush
(Mark)
January 26, 2017, 10:37pm
24
The behavior is pretty unpredictable when squeezelite gets into this state. For me, it almost never works, even with very long TTS strings.
g_g_rich
(g_g_rich)
January 26, 2017, 10:55pm
25
Yes, you can replace the existing squeezelite-armv6hf located in /mnt/mmcblk0p2/tce/. You have to rename it to squeezelite-armv6hf of course, and chmod +x to make it executable. Both the ffmpeg and non-ffmpeg versions seem to work fine with VoiceRSS, I haven’t had any success with MaryTTS, although haven’t really had time to look at it too closely.
mhilbush
(Mark)
January 26, 2017, 11:36pm
26
I think that’s where it was in pCP 3.02. In 3.10, it looks like they moved the location of the executable.