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.