Squeezebox trouble in openHAB2

Thanks. Hopefully, it will happen in minutes and not days. :wink:

This is the version Iā€™m running, BTW.

Normally, the playlist message from the LMS has the form mac-address playlist [1 or more additional arguments]

In your case, the LMS appears to be sending just mac-address playlist, which isnā€™t defined in the LMS api spec. I donā€™t understand why this would be happening.

I opened an issue for this.

Here you go. If was working, I turned a few players on and off, and then left it and it stopped working.

So it looks like it gets a message that doesnā€™t contain a mac addressā€¦ hummm

> 2018-10-24 13:34:06.205 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 playlist pause 1
> 2018-10-24 13:34:08.509 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 playlist pause 0
> 2018-10-24 13:35:44.264 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 playlist open http%3A%2F%2Fa.files.bbci.co.uk%2Fmedia%2Flive%2Fmanifesto%2Faudio%2Fsimulcast%2Fhls%2Fuk%2Fsbr_high%2Fak%2Fbbc_radio_two.m3u8
> 2018-10-24 13:35:44.265 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 playlist open http%3A%2F%2Fa.files.bbci.co.uk%2Fmedia%2Flive%2Fmanifesto%2Faudio%2Fsimulcast%2Fhls%2Fuk%2Fsbr_high%2Fak%2Fbbc_radio_two.m3u8
> 2018-10-24 13:35:44.526 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 playlist newsong http%3A%2F%2Fa.files.bbci.co.uk%2Fmedia%2Flive%2Fmanifesto%2Faudio%2Fsimulcast%2Fhls%2Fuk%2Fsbr_high%2Fak%2Fbbc_radio_two.m3u8 0
> 2018-10-24 13:36:05.988 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 playlist open http%3A%2F%2Fa.files.bbci.co.uk%2Fmedia%2Flive%2Fmanifesto%2Faudio%2Fsimulcast%2Fhls%2Fuk%2Fsbr_high%2Fak%2Fbbc_radio_two.m3u8
> 2018-10-24 13:36:05.989 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 playlist open http%3A%2F%2Fa.files.bbci.co.uk%2Fmedia%2Flive%2Fmanifesto%2Faudio%2Fsimulcast%2Fhls%2Fuk%2Fsbr_high%2Fak%2Fbbc_radio_two.m3u8
> 2018-10-24 13:36:06.217 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 playlist newsong http%3A%2F%2Fa.files.bbci.co.uk%2Fmedia%2Flive%2Fmanifesto%2Faudio%2Fsimulcast%2Fhls%2Fuk%2Fsbr_high%2Fak%2Fbbc_radio_two.m3u8 0
> 2018-10-24 13:36:24.755 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 playlist pause 1
> 2018-10-24 13:36:31.700 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 playlist pause 0
> 2018-10-24 13:38:35.338 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: subscribe playlist
2018-10-24 13:38:35.338 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: subscribe playlist

Interesting. I didnā€™t expect that. I wonder what generates that subscribe messageā€¦ Iā€™ll look into it.

I have what I need to you can go back to INFO level logging.

Thanks!!

No problem.

One other thingā€¦

From openhab.log, can you post the 10-20 lines that precede the line containing subscribe playlist?

Thanks.

Just waiting for it to happen again as I cleared the logsā€¦

Oh, sorry. I shouldā€™ve asked for that info earlier.

Still trying to figure out what generates the subscribe playlist command, since I canā€™t see it coming from the bindingā€¦ Do you have anything (other than openHAB) thatā€™s used to control the LMS? Smartphone app?

Sending subscribe playlist to the LMS CLI directly, Iā€™m also able reproduce another problem that was reported on the forum. :+1:

It looks pretty repeaative. Let me know if you need a filter. Iā€™ll leave it running as is for now this time :grin:

>     2018-10-24 14:20:37.312 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'rescan%3A1'
>     2018-10-24 14:20:37.312 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_name%3ABedroom-Master'
>     2018-10-24 14:20:37.312 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_connected%3A1'
>     2018-10-24 14:20:37.313 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_ip%3A10.10.30.100%3A40158'
>     2018-10-24 14:20:37.313 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'signalstrength%3A0'
>     2018-10-24 14:20:37.313 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'remote%3A1'
>     2018-10-24 14:20:37.313 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'current_title%3Ahttp%3A%2F%2Fa.files.bbci.co.uk%2Fmedia%2Flive%2Fmanifesto%2Faudio%2Fsimulcast%2Fhls%2Fuk%2Fsbr_high%2Fak%2Fbbc_radio_two.m3u8'
>     2018-10-24 14:20:37.314 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Updating channel currentPlayingTime for thing squeezebox:squeezeboxplayer:squeeze:bansteadBedroom1 with mac b8:27:eb:ed:87:ba to state 120
>     2018-10-24 14:20:37.314 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'rate%3A1'
>     2018-10-24 14:20:37.314 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'can_seek%3A1'
>     2018-10-24 14:20:37.314 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'sync_master%3Ab8%3A27%3Aeb%3Ac7%3A2a%3A45'
>     2018-10-24 14:20:37.314 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'sync_slaves%3Ab8%3A27%3Aeb%3Aed%3A87%3Aba%2Cb8%3A27%3Aeb%3A63%3Ab2%3A91%2Cb8%3A27%3Aeb%3A49%3Ae4%3A6c%2Cb8%3A27%3Aeb%3A8a%3Ad3%3Af0%2Cb8%3A27%3Aeb%3$
>     2018-10-24 14:20:37.315 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist%20mode%3Aoff'
>     2018-10-24 14:20:37.315 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'seq_no%3A0'
>     2018-10-24 14:20:37.315 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist_timestamp%3A1540370508.85623'
>     2018-10-24 14:20:37.315 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'digital_volume_control%3A1'
>     2018-10-24 14:20:37.316 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'remoteMeta%3AHASH(0x561880f8ae60)'
>     2018-10-24 14:20:37.316 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist%20index%3A0'
>     2018-10-24 14:20:37.316 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'id%3A-94663233975696'
>     2018-10-24 14:20:37.316 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - b8:27:eb:ed:87:ba: URL for cover art is http://10.10.1.105:9000/html/images/radio.png
>     2018-10-24 14:20:37.360 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: b8%3A27%3Aeb%3Ac7%3A2a%3A45 status - 1 subscribe%3A10 tags%3AyagJlNKjc rescan%3A1 player_name%3AGarage player_connected%3A1 player_ip%3A10.10.30.46%3A36290 power$
>     2018-10-24 14:20:37.361 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'b8%3A27%3Aeb%3Ac7%3A2a%3A45'
>     2018-10-24 14:20:37.361 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'status'
>     2018-10-24 14:20:37.362 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type '-'
>     2018-10-24 14:20:37.362 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type '1'
>     2018-10-24 14:20:37.362 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'subscribe%3A10'
>     2018-10-24 14:20:37.363 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'tags%3AyagJlNKjc'
>     2018-10-24 14:20:37.363 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'rescan%3A1'
>     2018-10-24 14:20:37.364 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_name%3AGarage'
>     2018-10-24 14:20:37.364 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_connected%3A1'
>     2018-10-24 14:20:37.364 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'player_ip%3A10.10.30.46%3A36290'
>     2018-10-24 14:20:37.365 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'signalstrength%3A0'
>     2018-10-24 14:20:37.365 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'remote%3A1'
>     2018-10-24 14:20:37.366 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'current_title%3Ahttp%3A%2F%2Fa.files.bbci.co.uk%2Fmedia%2Flive%2Fmanifesto%2Faudio%2Fsimulcast%2Fhls%2Fuk%2Fsbr_high%2Fak%2Fbbc_radio_two.m3u8'
>     2018-10-24 14:20:37.366 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Updating channel currentPlayingTime for thing squeezebox:squeezeboxplayer:squeeze:bansteadGarage with mac b8:27:eb:c7:2a:45 to state 120
>     2018-10-24 14:20:37.367 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'rate%3A1'
>     2018-10-24 14:20:37.367 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'can_seek%3A1'
>     2018-10-24 14:20:37.368 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'sync_master%3Ab8%3A27%3Aeb%3Ac7%3A2a%3A45'
>     2018-10-24 14:20:37.368 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'sync_slaves%3Ab8%3A27%3Aeb%3Aed%3A87%3Aba%2Cb8%3A27%3Aeb%3A63%3Ab2%3A91%2Cb8%3A27%3Aeb%3A49%3Ae4%3A6c%2Cb8%3A27%3Aeb%3A8a%3Ad3%3Af0%2Cb8%3A27%3Aeb%3$
>     2018-10-24 14:20:37.369 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist%20mode%3Aoff'
>     2018-10-24 14:20:37.369 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'seq_no%3A0'
>     2018-10-24 14:20:37.369 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist_timestamp%3A1540370508.85623'
>     2018-10-24 14:20:37.370 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'digital_volume_control%3A1'
>     2018-10-24 14:20:37.370 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'remoteMeta%3AHASH(0x561881301250)'
>     2018-10-24 14:20:37.370 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'playlist%20index%3A0'
>     2018-10-24 14:20:37.371 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Unhandled status message type 'id%3A-94663233975696'
>     2018-10-24 14:20:37.371 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - b8:27:eb:c7:2a:45: URL for cover art is http://10.10.1.105:9000/html/images/radio.png
>     2018-10-24 14:20:39.135 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Updating channel currentPlayingTime for thing squeezebox:squeezeboxplayer:squeeze:bansteadGarage with mac b8:27:eb:c7:2a:45 to state 121
>     2018-10-24 14:20:40.136 [TRACE] [ebox.handler.SqueezeBoxPlayerHandler] - Updating channel currentPlayingTime for thing squeezebox:squeezeboxplayer:squeeze:bansteadGarage with mac b8:27:eb:c7:2a:45 to state 122
>     2018-10-24 14:20:40.914 [TRACE] [ebox.handler.SqueezeBoxServerHandler] - Message received: subscribe playlist

Hmm. Can you go back a little farther in the log. Try looking for the string Sending command.

Do you want the whole log file?

    2018-10-24 14:14:09.730 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
    2018-10-24 14:14:09.731 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: favorites items 0 100
    2018-10-24 14:14:09.731 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: listen 1
    2018-10-24 14:14:09.791 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:8a:d3:f0 status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:14:09.801 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:c7:2a:45 status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:14:09.803 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:63:b2:91 status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:14:09.811 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:14:49:01 status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:14:09.815 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:14:09.828 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:49:e4:6c status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:14:17.464 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:c7:2a:45 power 0
    2018-10-24 14:14:19.355 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:c7:2a:45 power 1
    2018-10-24 14:14:19.693 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
    2018-10-24 14:14:57.513 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:c7:2a:45 power 0
    2018-10-24 14:14:59.008 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:c7:2a:45 power 1
    2018-10-24 14:15:19.694 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
    2018-10-24 14:16:19.696 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
    2018-10-24 14:16:27.302 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba power 1
    2018-10-24 14:16:28.407 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba power 0
    2018-10-24 14:16:46.378 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba power 1
    2018-10-24 14:16:47.481 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba power 0
    2018-10-24 14:17:19.697 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
    2018-10-24 14:17:51.828 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba power 1
    2018-10-24 14:17:52.830 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba power 0
    2018-10-24 14:17:54.040 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba power 1
    2018-10-24 14:17:55.153 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba power 0
    2018-10-24 14:18:19.698 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
    2018-10-24 14:18:35.960 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba power 1
    2018-10-24 14:18:36.877 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba power 0
    2018-10-24 14:19:19.698 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
    2018-10-24 14:20:19.699 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
    2018-10-24 14:27:18.675 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
    2018-10-24 14:27:18.675 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: favorites items 0 100
    2018-10-24 14:27:18.675 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: listen 1
    2018-10-24 14:27:18.683 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:8a:d3:f0 status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:27:18.685 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:c7:2a:45 status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:27:18.686 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:63:b2:91 status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:27:18.688 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:14:49:01 status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:27:18.690 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:ed:87:ba status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:27:18.692 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:49:e4:6c status - 1 subscribe:10 tags:yagJlNKjc
    2018-10-24 14:27:19.706 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0
    2018-10-24 14:27:22.830 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:49:e4:6c power 1
    2018-10-24 14:27:25.654 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:49:e4:6c power 0
    2018-10-24 14:27:27.189 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:c7:2a:45 power 1
    2018-10-24 14:28:19.707 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - Sending command: players 0

Sure.

That subscribe playlist command doesnā€™t appear to be coming from the binding :open_mouth:, as there would be a Sending command: subscribe playlist in the log.

Do you use any other apps for controlling the LMS? Smartphone app, for example?

Squeezer which Iā€™ve been using for years andā€¦ ah I tried an app on Windows 10ā€¦ let me turn off my laptop. Itā€™s been behaving since so far!!! :roll_eyes:

Canā€™t upload the log on here, hereā€™s a link - https://cloud.mcy.space/s/innqJ7fXmZEjyfr

Which app?

Thatā€™s it, as soon as I turn on my laptop - Message received: subscribe playlist

Its called Squeeze 11 (and now being uninstalled)!!

Sweet. Found it!

Iā€™ll make a fix, but until the next milestone or release build, it will only be available in the snapshot release.

Great, thanksā€¦ might jump on the 2.4 train then.

I submitted a PR containing a fix for this. Iā€™ll post back here when itā€™s merged and included in a snapshot release.

@jmccoy555 FYI, the fix is included in snapshot build 1401.

Hi @mhilbush thanks; Iā€™ll try and give it a test as soon as I get a min.