Squeezebox: Can't get Audio Sink to work for notifications

Christoph_B · March 9, 2019, 4:55pm

Hi there,

I’m using the latest version of Openhab (2.4, docker) and I’m trying to get my squeezebox players to work as audio sinks.

Audio sinks are working if I use webaudio as the default sink, but if I use one of my squeezebox players (they are working fine when playing music) it does not work.

Some details:

Notification Volume is set to 27 (music setting)
Command is: smarthome:audio play doorbell.mp3
Squeezelite Version is: v1.8.7-1052 (I’m aware of the problems with other versions)
Squeezelite Command to start it is: squeezelite -n p[layer01 -o hw:0,0 -f /tmp/squeeze.log -d all=debug

The output I get in events.log is:

2019-03-09 16:49:44.422 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f3ddcc30_b827eb564bf4_power changed from OFF to ON
2019-03-09 16:49:44.464 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f3ddcc30_b827eb564bf4_volume changed from 20 to 27
2019-03-09 16:50:45.976 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f3ddcc30_b827eb564bf4_volume changed from 27 to 0
2019-03-09 16:50:46.436 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f3ddcc30_b827eb564bf4_volume changed from 0 to 20
2019-03-09 16:50:46.437 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f3ddcc30_b827eb564bf4_power changed from ON to OFF

Note the relatively long time it takes (Timeout is set to 60 secs for the player).

Does anyone have an idea what I’m missing?

mhilbush · March 9, 2019, 5:25pm

Everything you’re doing looks right, but it looks like it’s hitting the timeout.

Are there any errors in openhab.log?

Maybe put the binding in debug mode, then post the log messages back here.

Christoph_B · March 9, 2019, 5:45pm

Thanks @mhilbush here is the output:

 2019-03-09 17:42:02.131 [DEBUG] [eezebox.internal.SqueezeBoxAudioSink] - Processing audioStream http://172.17.0.9:8080/audio/d7bbb08e-ad2f-4c38-8476-50d0b21de3ac.mp3 of format AudioFormat [codec=MP3, container=NONE, ]
2019-03-09 17:42:02.132 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - Play notification sound on player b8:27:eb:56:4b:f4 at URI http://172.17.0.9:8080/audio/d7bbb08e-ad2f-4c38-8476-50d0b21de3ac.mp3
2019-03-09 17:42:02.132 [DEBUG] [ternal.handler.SqueezeBoxPlayerState] - Cur State: vol=20, mut=NOT MUTED, pwr=ON, stp=STOPPED, ctl=PAUSED, shf=OFF, rpt=OFF, tix=0, tnm=0, tim=0
2019-03-09 17:42:02.133 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Setting up player for notification
2019-03-09 17:42:02.133 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:56:4b:f4 mixer volume 27
2019-03-09 17:42:02.240 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Adding notification message to playlist
2019-03-09 17:42:02.241 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:56:4b:f4 playlist add http://172.17.0.9:8080/audio/d7bbb08e-ad2f-4c38-8476-50d0b21de3ac.mp3 Notification
2019-03-09 17:42:02.751 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Playlist updated
2019-03-09 17:42:02.752 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Playing notification
2019-03-09 17:42:02.753 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:56:4b:f4 playlist index 0
2019-03-09 17:42:12.925 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Restoring player state
2019-03-09 17:42:12.926 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:56:4b:f4 mixer volume 0
2019-03-09 17:42:12.927 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Removing notification message from playlist
2019-03-09 17:42:12.929 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:56:4b:f4 playlist delete 0
2019-03-09 17:42:13.334 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Playlist updated
2019-03-09 17:42:13.335 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:56:4b:f4 playlist index 0
2019-03-09 17:42:13.336 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:56:4b:f4 time 0
2019-03-09 17:42:13.337 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Stopping the player
2019-03-09 17:42:13.339 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:56:4b:f4 stop
2019-03-09 17:42:13.340 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:56:4b:f4 mixer volume 20
2019-03-09 17:42:27.734 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: players 0
2019-03-09 17:42:35.373 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - Trying to download the content of URL http://192.168.1.25:9000/music/current/cover.jpg?player=b8%3A27%3Aeb%3A56%3A4b%3Af4

I’m not sure how squeezeserver works, but I think it is getting a link to a playlist to play, right?
The the problem is probably related to Docker.

The IP 172.17.0.9 is the internal docker container IP. My home network is on 192.168.1.x. So I guess it cannot access that file. If I test fetching it it doesn’t work, if I substitute the IP in that URL with my openhab IP, I can open the file.

Is there any way to handle this?

mhilbush · March 9, 2019, 7:12pm

You’re probably right.

The openHAB core gives the binding a URL to the sound. The binding adds that URL to the beginning of the currently playing playlist, then tells the squeezebox server to play the first item on the playlist. I’m guessing that the squeezebox server can’t access the URL.

I’m not sure how to handle this.

Christoph_B · March 9, 2019, 8:52pm

You probably got the notification already but GH (https://github.com/openhab/openhab2-addons/issues/5074) pointed me to:
Squeezebox binding - callbackurl for reverse proxy configuration

Looks like this would solve it?

mhilbush · March 9, 2019, 8:55pm

Not sure. I never heard back from the person who requested it after I pinged him several times. I think I deleted the branch…

Christoph_B · March 9, 2019, 8:56pm

Oh that’s unfortunate… however, I think a simple setting to specify the hostname should be sufficient if I’m not mistaken…

mhilbush · March 9, 2019, 9:00pm

Yes, it is. It sat around so long that there were a bunch of merge conflicts. With no one to test it, it wasn’t worth spending my time to resolve the conflicts.

Yes, it’s a config parameter on the binding (like this in Sonos). Then the necessary code to use the callback URL, if it’s present.

Christoph_B · March 9, 2019, 9:03pm

Exactly yeah…

Is there any way I could work around that? How is it acquiring the IP/hostname right now?

mhilbush · March 9, 2019, 9:10pm

I forget. I haven’t looked at it in a while. I’d have to go back and look at the code.

I seem to recall it was an hour or two of work to implement. I probably could fine some time to do that over the next couple days if you’d be willing to test it.

Christoph_B · March 9, 2019, 9:13pm

That would be great! I’ll be glad to test it!

mhilbush · March 9, 2019, 9:16pm

Ok. I need to finish up something else I’m working on. Then I’ll do this. Having done it once before, it should go more quickly. LOL

I’ll post back here when I have something ready.

Christoph_B · March 9, 2019, 9:57pm

Thanks a lot @mhilbush. For the record, I worked around this temporarily with a redirect to the real IP on my players RPi:

iptables -t nat -A OUTPUT -d 192.168.1.15 -j DNAT --to-destination 54.3.22.1

Just a quick followup question, if I have something like:

…
when Item testvoice received command
then
playSound(“doorbell.mp3”)
say(“The garage door is still open!”, “voicerss:enGB”, new PercentType(25))
…

I noticed that if music is playing it gets correctly suspended and then continues.
However, if I have those two lines, it seems to return after playSound already, then stops again
for the say command and after say it doesn’t continue the music stream.

Is there any way to do this as a single block of interruption?
This is a sample log: https://gist.github.com/solars/865841a903b0b5a3b9d4357b5fee8e8f
Instead of resuming it ends up stopped with volume set to 0

mhilbush · March 9, 2019, 10:36pm

Not that I know about, unfortunately.

I’ve seen this behavior a couple times, and I don’t know how to fix it. The LMS (Squeezebox Server) is a bit slow in how it handles the commands to add and remove from the playlist, which is difficult to account for in the binding because there’s no reliable way to know if the LMS has fully completed the previous command before sending it the next command.

While I find this an unpleasant workaround, try putting a slight pause between the commands. Maybe a sleep of 1 second.

mhilbush · March 9, 2019, 11:27pm

@Christoph_B There’s a version with the callback functionality posted here, along with installation instructions.

Christoph_B · March 10, 2019, 8:24am

wow that was fast! Thank you very much I will try it today, just switched to 2.5.0M1 to solve a hue-emulation problem.

Christoph_B · March 10, 2019, 9:30am

@mhilbush do you have any experience with the docker setup? Somehow the binding does not seem to get picked up, the volume is:

-v /mnt/nfs-1/openhab/addons:/openhab/addons

mhilbush · March 10, 2019, 11:15am

So, when you put the jar file in the addons directory, it’s not getting installed?

What do you see in the console when you type the following?

list -s | grep squeezebox

What’s the size of the jar file you downloaded? It should be 83682 bytes.

Christoph_B · March 10, 2019, 11:31am

Sorry my mistake, the docker config that I used here had an error because a directory didn’t exist.

Other than that: The callback URL is working nicely! I tried it on all my players, no workarounds needed!
Thanks a lot for the quick fix @mhilbush!

mhilbush · March 10, 2019, 11:34am

Ok, sounds good. I’ll submit the change shortly. It usually takes a few days for it to get included in the distribution.