Another thought…
As an alternative way to play a notification on more than one player, have you considered syncing the players:
I have tried starting playSound on 3 non-synced players simultaneously.
They play just fine, but in sequence. I play the default OH ding-dong sound and it takes 15-20s until all players are done.
I don’t know about that. The log posted shows the notification playing on both players simultaneously, which is resulting in timeouts on both players.
2018-10-20 17:08:36.338 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Notification message timed out after 20 seconds
2018-10-20 17:08:36.338 [DEBUG] [handler.SqueezeBoxNotificationPlayer] - Notification message timed out after 20 seconds
Maybe try updating LMS.
Mine is currently:
Logitech Media Server Version: 7.9.2 - 1539967036 @ Fri Oct 19 19:15:30 CEST 2018I’ve updated mine to 7.9.2 too however I don’t believe that the problem is on LMS side. LMS just works fine all the time. If I restart binding then everything gets back to normal immediately. And it works perfectly despite I call multiple players at once. Just after some time something happens and it stops work.
Ah, I see.
Is your pi eth wired?
What kind of Squeezes are you using?
Everything is wired. Im using piCorePlayers, currently all are 4.0.0. Even though the bundle says that there is no connection. Does it try to reconnect? What exactly the message means?
Normally, when the connection is lost between the Squeezebox Server thing handler and the LMS, the binding will try to reconnect every 60 seconds. That does not appear to be happening in this case.
Does the issue only occur when you are playing notifications? If so, does it ever occur when you are playing a notification to just one player?
Hi Mark,
From OpenHAB I only call notifications as sounds like dong, opened door, locked door, flood or fire alarms etc.
I always call 2 players, the main in Hall and the other in Bathroom by sending postupdate with sound name to simple rules that further run playsound to appropriate sink. I can try to leave just one player just for tests and see if the problem occurs, however i think that it does not explain why binding stops trying to reconnect and only restarting binding helps. I also still fight with the notifications as they often don’t back volume to the correct previous value or are not removed from the playlist as I noted here.
Is there any chance to make the binding more reliable?
Setting it to play the notification on one player will help narrow down the issue. If it works reliably with just one player, then that would point to a synchronization/timing issue in the notification code.
This could be another symptom of the problem.
This behavior is visible in the logs, and is definitely a symptom of playing multiple notifications simultaneously.
One other thing you could check…
When the problem occurs, if you look in PaperUI, are any of the Squeezebox things showing a status of OFFLINE?
You also could try putting the binding into TRACE logging mode. It will generate a lot of log messages, but it may give some hints at what’s going on.
When the problem occurs, if you look in PaperUI, are any of the Squeezebox things showing a status of OFFLINE?
I didn’t noticed this behavior. I will check it yet.
You also could try putting the binding into TRACE logging mode. It will generate a lot of log messages, but it may give some hints at what’s going on.
Will try this out.
One other question as I try to reproduce this.
How are you invoking playSound simultaneously? It is a blocking call (subsequent instructions in a rule won’t execute until playSound returns), so I’m not sure how the calls to playSound are overlapping unless it’s being called from multiple rules that trigger simultaneously.
I’m not sure if it’s simultanously but I want it to be played pretty at the same time. I do it by calling simple rules through item postupdate:
Player_Squeezelite_Bathroom_StreamAddress.postUpdate("doorlock_unlocked.mp3")
Player_Squeezelite_Hall_StreamAddress.postUpdate("doorlock_unlocked.mp3")
Rules:
var String sinkLazienka = "squeezebox:squeezeboxplayer:external:Player_Squeezelite_Bathroom"
var String sinkHol = "squeezebox:squeezeboxplayer:external:Player_Squeezelite_Hall"
rule "piLazienka playsound"
when
Item Player_Squeezelite_Bathroom_StreamAddress received update
then
logInfo("Info", "Playing: " + Player_Squeezelite_Bathroom_StreamAddress.state.toString)
playSound(sinkLazienka, Player_Squeezelite_Bathroom_StreamAddress.state.toString)
end
rule "piHol playsound"
when
Item Player_Squeezelite_Hall_StreamAddress received update
then
logInfo("Info", "Playing: " + Player_Squeezelite_Hall_StreamAddress.state.toString)
playSound(sinkHol, Player_Squeezelite_Hall_StreamAddress.state.toString)
That’s it.
Thanks. This qualifies as simultaneous, and is pretty much what I expected you were doing. 
I just tested this scenario pretty heavily to try to reproduce your problem, but was unable to generate the lost connection error.
Hopefully the trace level logging will shed some light on what’s happening.
Can you also confirm your config for me? You have one pi running the LMS and a player, and another pi running just the player?
And a couple final questions about the condition of the system when the problem occurs:
threads | grep "Squeeze Server Listener"
You should see something like this
"Squeeze Server Listener" Id=132950 in RUNNABLE
Hopefully the trace level logging will shed some light on what’s happening.
Turned on already.
Can you also confirm your config for me? You have one pi running the LMS and a player, and another pi running just the player?
Exactly like this. Both pi are piCorePlayers, one of them is also LMS, however I have also UPnP and Chromecast addon turned on in LMS as I have Google Home and Google Home mini, however I don’t use them at all with openhab via squeezebox binding and those two are not even configured.
- did you happen to notice the CPU utilization on the openHAB system?
Nope. Will do on next occasion.
- in the Karaf console, can you run the following when the problem occurs again?
Will do on next occasion.
Just checked log and see a lot of unhandled status messages e.g.
2018-10-22 22:50:51.530 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Updating channel currentPlayingTime for thing squeezebox:squeezeboxplayer:external:Player_Squeezelite_Bathroom with mac b8:27:eb:e2:3a:a3 to state 10650
2018-10-22 22:50:52.536 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Updating channel currentPlayingTime for thing squeezebox:squeezeboxplayer:external:Player_Squeezelite_Bathroom with mac b8:27:eb:e2:3a:a3 to state 10651
2018-10-22 22:50:53.132 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: cc%3Acc%3A63%3A49%3A0e%3Ae3 status - 1 subscribe%3A10 tags%3AyagJlNKjc player_name%3AgooglePokoj player_connected%3A1 player_ip%3A192.168.1.186%3A49422 power%3A1 signalstrength%3A0 mode%3Astop mixer%20volume%3A45 playlist%20repeat%3A0 playlist%20shuffle%3A0 playlist%20mode%3Aoff seq_no%3A0 playlist_tracks%3A0 digital_volume_control%3A1
2018-10-22 22:50:53.137 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'cc%3Acc%3A63%3A49%3A0e%3Ae3'
2018-10-22 22:50:53.140 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'status'
2018-10-22 22:50:53.145 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type '-'
2018-10-22 22:50:53.152 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type '1'
2018-10-22 22:50:53.157 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'subscribe%3A10'
2018-10-22 22:50:53.160 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'tags%3AyagJlNKjc'
2018-10-22 22:50:53.167 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_name%3AgooglePokoj'
2018-10-22 22:50:53.169 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_connected%3A1'
2018-10-22 22:50:53.176 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_ip%3A192.168.1.186%3A49422'
2018-10-22 22:50:53.183 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'signalstrength%3A0'
2018-10-22 22:50:53.186 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist%20mode%3Aoff'
2018-10-22 22:50:53.201 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'seq_no%3A0'
2018-10-22 22:50:53.209 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'digital_volume_control%3A1'
2018-10-22 22:50:53.215 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - cc:cc:63:49:0e:e3: URL for cover art is http://192.168.1.186:9000/music/current/cover.jpg?player=cc%3Acc%3A63%3A49%3A0e%3Ae3
2018-10-22 22:50:53.489 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3A0f%3Afa%3Aa9 status - 1 subscribe%3A10 tags%3AyagJlNKjc player_name%3ApiHol player_connected%3A1 player_ip%3A192.168.1.187%3A52114 power%3A1 signalstrength%3A0 mode%3Astop remote%3A1 current_title%3ANotification time%3A0 rate%3A1 mixer%20volume%3A80 playlist%20repeat%3A0 playlist%20shuffle%3A0 playlist%20mode%3Aoff seq_no%3A0 playlist_cur_index%3A0 playlist_timestamp%3A1540240974.71442 playlist_tracks%3A1 digital_volume_control%3A1 remoteMeta%3AHASH(0x9af1dc0) playlist%20index%3A0 id%3A-78476568 title%3ANotification year%3A0 remote_title%3ANotification artwork_url%3Ahtml%2Fimages%2Fradio.png coverart%3A0 coverid%3A-78476568
2018-10-22 22:50:53.494 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'b8%3A27%3Aeb%3A0f%3Afa%3Aa9'
2018-10-22 22:50:53.496 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'status'
2018-10-22 22:50:53.515 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type '-'
2018-10-22 22:50:53.517 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type '1'
2018-10-22 22:50:53.519 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'subscribe%3A10'
2018-10-22 22:50:53.521 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'tags%3AyagJlNKjc'
2018-10-22 22:50:53.523 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_name%3ApiHol'
2018-10-22 22:50:53.526 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_connected%3A1'
2018-10-22 22:50:53.538 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_ip%3A192.168.1.187%3A52114'
2018-10-22 22:50:53.540 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'signalstrength%3A0'
2018-10-22 22:50:53.542 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'remote%3A1'
2018-10-22 22:50:53.543 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Updating channel currentPlayingTime for thing squeezebox:squeezeboxplayer:external:Player_Squeezelite_Bathroom with mac b8:27:eb:e2:3a:a3 to state 10652
2018-10-22 22:50:53.549 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'current_title%3ANotification'
2018-10-22 22:50:53.551 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'rate%3A1'
2018-10-22 22:50:53.553 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist%20mode%3Aoff'
2018-10-22 22:50:53.554 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'seq_no%3A0'
2018-10-22 22:50:53.572 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist_timestamp%3A1540240974.71442'
2018-10-22 22:50:53.574 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'digital_volume_control%3A1'
2018-10-22 22:50:53.576 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'remoteMeta%3AHASH(0x9af1dc0)'
2018-10-22 22:50:53.585 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist%20index%3A0'
2018-10-22 22:50:53.597 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'id%3A-78476568'
2018-10-22 22:50:53.600 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - b8:27:eb:0f:fa:a9: URL for cover art is http://192.168.1.186:9000/html/images/radio.png
2018-10-22 22:50:54.370 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: cc%3Acc%3A53%3A7e%3A0e%3A68 status - 1 subscribe%3A10 tags%3AyagJlNKjc player_name%3AgoogleSalon player_connected%3A1 player_ip%3A192.168.1.186%3A49458 power%3A1 signalstrength%3A0 mode%3Astop mixer%20volume%3A60 playlist%20repeat%3A0 playlist%20shuffle%3A0 playlist%20mode%3Aoff seq_no%3A0 playlist_tracks%3A0 digital_volume_control%3A1
2018-10-22 22:50:54.373 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'cc%3Acc%3A53%3A7e%3A0e%3A68'
2018-10-22 22:50:54.378 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'status'
2018-10-22 22:50:54.381 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type '-'
2018-10-22 22:50:54.388 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type '1'
2018-10-22 22:50:54.401 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'subscribe%3A10'
2018-10-22 22:50:54.403 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'tags%3AyagJlNKjc'
2018-10-22 22:50:54.406 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_name%3AgoogleSalon'
2018-10-22 22:50:54.409 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_connected%3A1'
2018-10-22 22:50:54.419 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_ip%3A192.168.1.186%3A49458'
2018-10-22 22:50:54.422 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'signalstrength%3A0'
2018-10-22 22:50:54.425 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist%20mode%3Aoff'
2018-10-22 22:50:54.428 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'seq_no%3A0'
2018-10-22 22:50:54.440 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'digital_volume_control%3A1'
2018-10-22 22:50:54.443 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - cc:cc:53:7e:0e:68: URL for cover art is http://192.168.1.186:9000/music/current/cover.jpg?player=cc%3Acc%3A53%3A7e%3A0e%3A68
Is it normal?
Yes, normal. It logs everything, even if it’s not used.
few times with 2 seconds pause:
openhab> threads | grep "Squeeze Server Listener"
"pipe-grep "Squeeze Server Listener"" Id=26053 in TIMED_WAITING on lock=java.io.PipedInputStream@1d59569
~ openhab> threads | grep "Squeeze Server Listener"
"pipe-grep "Squeeze Server Listener"" Id=26050 in RUNNABLE
~ openhab> threads | grep "Squeeze Server Listener"
"pipe-grep "Squeeze Server Listener"" Id=26053 in RUNNABLE
~ openhab> threads | grep "Squeeze Server Listener"
"pipe-grep "Squeeze Server Listener"" Id=26050 in TIMED_WAITING on lock=java.io.PipedInputStream@13de78b
~ openhab> threads | grep "Squeeze Server Listener"
"pipe-grep "Squeeze Server Listener"" Id=26052 in RUNNABLE
~ openhab> threads | grep "Squeeze Server Listener"
"pipe-grep "Squeeze Server Listener"" Id=26050 in RUNNABLE
~ openhab>