playSound mit Squeezebox

Tags: #<Tag:0x00007fc3ee50a028> #<Tag:0x00007fc3ee509e20>

Hi there,
since 2 weeks i try to get playSound in a rule get to work with openhab 2.2 stable.
I work with the Logitech Media Server Version: 7.7.5 on the same device Openhab is running.
The sinks are 2 x Squeezebox + 1x Squeezebox touch.
When i restart the Server playSound often works, not ever. But after a few hours it stops working.
Then the music is getting loud (60 notification Sound Volume) and on the Squeezebox there is the file listed in the display that should play but it doesn’t. After a while the sounds goes off (Volume 0) and later on (25)
Openhab is installed on Linux Mint 17.1.

Things are installed with Paper UI.
Logitech Media Server [server] - squeezebox:squeezeboxserver:9A9BF401-7BA5-4561-80B1-D33726583417
Mac Adress 00:04:20:2d:43:e5

IP Adresse Server 10.1.2.150
Web Port: 9000
Cli Port:9090

I can see every Squeezebox and the Server under Things

Items in File:
Dimmer kueche_Ansage “Lautstärke Durchsage” (SB_Kueche) {channel=“squeezebox:squeezeboxplayer:9A9BF401-7BA5-4561-80B1-D33726583417:0004202d43e5:notificationSoundVolume”}
String kueche_stream “Stream” (SB_Kueche) {channel=“squeezebox:squeezeboxplayer:9A9BF401-7BA5-4561-80B1-D33726583417:0004202d43e5:stream”}

rule:
rule "Klingel Squeezebox Küche"
when
Item Klingel_Haustuer changed to OFF
then
var String sinkKitchen = “squeezebox:squeezeboxplayer:9A9BF401-7BA5-4561-80B1-D33726583417:0004202d43e5”

playSound(sinkKitchen, “BigBen.mp3”)

end

openhab log:
2018-01-26 17:43:59.770 [DEBUG] [eezebox.internal.SqueezeBoxAudioSink] - Processing audioStream http://10.1.2.150:8080/audio/6d289f2b-070a-468d-be1f-e7780f19ec24.mp3 of format AudioFormat [codec=MP3, container=NONE, ]
2018-01-26 17:43:59.770 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Play notification sound on player 00:04:20:2d:43:e5 at URI http://10.1.2.150:8080/audio/6d289f2b-070a-468d-be1f-e7780f19ec24.mp3
2018-01-26 17:43:59.770 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Cur State: vol=25, mut=NOT MUTED, pwr=ON, stp=NOT STOPPED, ctl=PLAYING, shf=OFF, rpt=OFF, tix=0, tnm=1, tim=691
2018-01-26 17:43:59.770 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Setting up player for notification
2018-01-26 17:43:59.771 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:2d:43:e5 stop
2018-01-26 17:43:59.776 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:2d:43:e5 mixer volume 60
2018-01-26 17:44:03.781 [WARN ] [ebox.handler.SqueezeBoxPlayerHandler] - TIMEOUT after 4000 waiting for volume to update!
2018-01-26 17:44:03.782 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Playing notification
2018-01-26 17:44:03.782 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:2d:43:e5 playlist add http://10.1.2.150:8080/audio/6d289f2b-070a-468d-be1f-e7780f19ec24.mp3
2018-01-26 17:44:05.172 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine 'wget http://admin:flower112@10.1.2.205/Streaming/channels/101/picture -O /var/lib/openhab2/tmp/Türklingel2.jpg’
2018-01-26 17:44:08.786 [WARN ] [ebox.handler.SqueezeBoxPlayerHandler] - TIMEOUT after 5000 waiting for playlist to update!
2018-01-26 17:44:08.786 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:2d:43:e5 mixer volume 25
2018-01-26 17:44:12.790 [WARN ] [ebox.handler.SqueezeBoxPlayerHandler] - TIMEOUT after 4000 waiting for volume to update!
2018-01-26 17:44:18.195 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0

Sometimes in the log is
2018-01-26 17:43:43.000 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Could not get album art data
java.net.SocketException: Unexpected end of file from server
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:851) [?:?]
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:678) [?:?]
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:848) [?:?]
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:678) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1587) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1492) [?:?]
at org.openhab.binding.squeezebox.internal.utils.HttpUtils.getData(HttpUtils.java:89) [240:org.openhab.binding.squeezebox:2.2.0]
at org.openhab.binding.squeezebox.handler.SqueezeBoxPlayerHandler.coverArtChangeEvent(SqueezeBoxPlayerHandler.java:370) [240:org.openhab.binding.squeezebox:2.2.0]
at org.openhab.binding.squeezebox.handler.SqueezeBoxServerHandler$SqueezeServerListener$13.updateListener(SqueezeBoxServerHandler.java:728) [240:org.openhab.binding.squeezebox:2.2.0]
at org.openhab.binding.squeezebox.handler.SqueezeBoxServerHandler.updatePlayer(SqueezeBoxServerHandler.java:831) [240:org.openhab.binding.squeezebox:2.2.0]
at org.openhab.binding.squeezebox.handler.SqueezeBoxServerHandler.access$8(SqueezeBoxServerHandler.java:815) [240:org.openhab.binding.squeezebox:2.2.0]
at org.openhab.binding.squeezebox.handler.SqueezeBoxServerHandler$SqueezeServerListener.handleStatusMessage(SqueezeBoxServerHandler.java:725) [240:org.openhab.binding.squeezebox:2.2.0]
at org.openhab.binding.squeezebox.handler.SqueezeBoxServerHandler$SqueezeServerListener.handlePlayerUpdate(SqueezeBoxServerHandler.java:532) [240:org.openhab.binding.squeezebox:2.2.0]
at org.openhab.binding.squeezebox.handler.SqueezeBoxServerHandler$SqueezeServerListener.run(SqueezeBoxServerHandler.java:410) [240:org.openhab.binding.squeezebox:2.2.0]

Has anybody an idea?

There is another thing:
The LMS in PaperUI /Things has to set up the IP-Adress to 10.1.2.150 after every reboot. After reboot there is the IP "re"set to 127.0.0.1
2018-01-26 18:15:04.117 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - listener connection started to server 127.0.0.1:9090

But with 127.0.0.1 the control of the Squeezebox (play, pause,stream…) works also well as with 10.1.2.150.

Thanks very much

I can confirm that the play Command appears to be very buggy currently (working very unreliably: always thought it was connected to this issue:

@lipp_markus and @frost80 The problem cited above was fixed about a week ago. Also, today a fix went in for the cover art not updating correctly. When build 1198 comes out, it will contain both these fixes. It would be great if you could install that version, then report whether you still are seeing problems.

As for the IP address issue, I haven’t seen that before. Are you saying that the IP address is being changed to 127.0.0.1 in the Squeezebox Server thing configuration?

great news, thanks so much; will test and report back

@frost80 Concerning the IP address issue…

In Paper UI, under Configuration->System, there’s a panel titled “Network Settings”. If the Primary Address is blank, can you try setting it to this. See if that resolves the problem you’re seeing.

10.1.2.150/8

Thanks very much for the quick answers.
Glad to hear that i’m not the only one with these problems and that there will be a fix.

Do i have to install the 2.3 Snapshot of Openhab? Or is it possible to update only the addon?
When it is possible what do i have to do?

The Bug with “Could not get album art data” is in my log too.

@mhilbush Yes, the IP address is being changed to 127.0.0.1 in the Squeezebox Server thing configuration after every restart. My Primary Address is still set to 10.1.2.150/24. But i tried to change to blank and it is no difference.
I have OpenVPN installed and it makes a lot of troubles in Openhab2, so i stopped that service for a while. I’m not sure, but i think it is the IP-Adress for OpenVPN. No idea why Openhab knows the adress. I can’t choose this IP under “Primary Adress” in Paper UI, only when OpenVPN is started.

I took a look at the OpenVPN IP Address. It is 10.8.0.1/32 when started.
Then i have no idea where 127.0.0.1 comes from…

Can you try setting it to just 10.1.2.150

no, it is’t possible. i can choose only between blank and 10.1.2.150/24.
i can’t type anything

There’s a way to install a snapshot binding into a release build, but I’ve never done it (I’ve only ever run snapshot builds).

OK, then i will try the snapshot and hope that there are no other bugs…
Thank you very much

The current snapshot builds have been pretty stable. :slight_smile:

Wait for build 1198 since it has the artwork fix.

OK. I will install the build 1198 and report…

Well, this had me scratching my head…

So, after some digging, I figured out why this is happening. I guess I would describe it as a “feature” of the way the system works.

  • your Squeezebox Server thing has an LMS IP address 10.1.2.150
  • at startup, when the Squeezebox discovery service finds the LMS, it finds it with address 127.0.0.1, which is the loopback address (because the LMS is on the same box, it’s reachable on both 10.1.2.150 and 127.0.0.1)
  • the Squeezebox discovery service tries to add the LMS to the inbox
  • the inbox determines that the LMS already exists as a thing
  • the inbox updates the thing with the config from the discovery, which results in the thing now having IP address 127.0.0.1

I recreated this on my system (I also have the LMS running on the same server as OH). In my case, I set the Squeezebox Server thing to the loopback address. Then I restarted OH and the thing was updated to have the 192.168.1.31 address. Voila!

In short, it’s nothing to worry about. You probably can leave the IP as 127.0.0.1 as long as you’re running LMS and OH on the same box.

Oh, i see. Alright.
Then i know the reason why the squeezebox server and sinks appear in the inbox when i set up things manual in the things folder. I thought i had a mistake in the syntax, so i deleted the SQUEEZE.things file and created things with paper ui.
Same with samsung tv.
Thanks very much for the good statement.

Hello,
i updated Openhab to build 1198, but it is still the same.
playSound doesn’t work. And with the new build there appears nothing on the display of the squeezebox.

2018-01-28 10:14:57.022 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Restoring player state
2018-01-28 10:14:57.022 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Resuming last item playing
2018-01-28 10:14:57.022 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:2d:43:e5 playlist index 0
2018-01-28 10:14:57.028 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:2d:43:e5 time 81
2018-01-28 10:14:57.029 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:2d:43:e5 mixer volume 25
2018-01-28 10:14:57.029 [WARN ] [ebox.handler.SqueezeBoxPlayerHandler] - Problem during notification playback.
org.openhab.binding.squeezebox.internal.utils.SqueezeBoxTimeoutException: Unable to update volume.
at org.openhab.binding.squeezebox.handler.SqueezeBoxNotificationPlayer.setVolume(SqueezeBoxNotificationPlayer.java:138) ~[?:?]
at org.openhab.binding.squeezebox.handler.SqueezeBoxNotificationPlayer.setupPlayerForNotification(SqueezeBoxNotificationPlayer.java:109) ~[?:?]
at org.openhab.binding.squeezebox.handler.SqueezeBoxNotificationPlayer.play(SqueezeBoxNotificationPlayer.java:67) ~[?:?]
at org.openhab.binding.squeezebox.handler.SqueezeBoxPlayerHandler.playNotificationSoundURI(SqueezeBoxPlayerHandler.java:635) ~[?:?]
at org.openhab.binding.squeezebox.internal.SqueezeBoxAudioSink.process(SqueezeBoxAudioSink.java:106) ~[?:?]
at org.eclipse.smarthome.core.audio.internal.AudioManagerImpl.play(AudioManagerImpl.java:98) ~[?:?]
at org.eclipse.smarthome.core.audio.internal.AudioManagerImpl.playFile(AudioManagerImpl.java:118) ~[?:?]
at org.eclipse.smarthome.model.script.actions.Audio.playSound(Audio.java:49) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1085) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1060) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1046) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:991) ~[?:?]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:141) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:901) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:864) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:223) ~[?:?]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:215) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:203) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:446) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:227) ~[?:?]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:215) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:203) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:189) ~[?:?]
at org.eclipse.smarthome.model.script.runtime.internal.engine.ScriptImpl.execute(ScriptImpl.java:82) ~[?:?]
at org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl.lambda$2(RuleEngineImpl.java:339) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2018-01-28 10:14:57.728 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0

And instead of “Could not get album art data" there appears every few seconds:

2018-01-28 10:22:07.034 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Failed to download the content of URL http://10.1.2.150:9000/music/current/cover.jpg?player=00%3A04%3A20%3A2d%3A43%3Ae5
2018-01-28 10:22:07.035 [DEBUG] [ebox.handler.SqueezeBoxPlayerHandler] - Trying to download the content of URL http://10.1.2.150:9000/music/current/cover.jpg?player=00%3A04%3A20%3A23%3A22%3A43

Items, things and rules are still the same.

The control of every Squeezebox (play, pause power,…) is OK, the things of the squeezebox/server are Online (paper ui).

Hmm. Not sure why this is happening.

What’s in the log file prior to the messages shown above? Could you include the entire debug log from the time when the squeezebox starts to process the notification? Please wrap with code fences, as it’s much easier to read.

You have three players, right? I assume you’re getting the same result on all three of your players?

I also assume you’re getting the same result no matter what music source you’re playing?

Have you tried playing a notification when the player is paused.

I see you are on LMS version 7.7.5. I’m not saying that’s a problem, but it is a difference. I think a lot of people (myself included) are running 7.9. There have been over 1700 changes to LMS since 7.7.5.

Update LMS to 7.9 was the trick. Everything works fine now.
I didn’t know that there was a new Version from the LMS out.
Thank you very much. Without your help i never found the error.

Have a nice weekend

That’s great. I’m very relieved that that was the issue.

If you haven’t done so already, could you close the issue on github? Thanks!

Yes, maybe there should be a hint in the docs for the Squeezebox binding?
The issue on github is closed.