That is so bizarre. I have no idea why it’s saying it needs 13 threads. I’m running on a pretty powerful host, and I’ve never seen anything like this (and I’ve seen a lot).
When you figure it out, please post here.
I probably should catch the IllegalStateException. If the squeezebox binding can’t get the coverart, it’s not a big deal…
Here’s what my log looks like.
2018-11-20 12:42:47.005 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: favorites items 0 100
2018-11-20 12:42:47.005 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: listen 1
2018-11-20 12:42:47.013 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:36b70fd1:000420165ee2 initialized.
2018-11-20 12:42:47.015 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:36b70fd1:b827eb163f1e initialized.
2018-11-20 12:42:47.015 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:36b70fd1:000420164526 initialized.
2018-11-20 12:42:47.059 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: b8:27:eb:16:3f:1e status - 1 subscribe:10 tags:yagJlNKjc
2018-11-20 12:42:47.060 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:16:5e:e2 status - 1 subscribe:10 tags:yagJlNKjc
2018-11-20 12:42:47.062 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - Player b8:27:eb:16:3f:1e updating favorites list
2018-11-20 12:42:47.062 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - Player 00:04:20:16:45:26 updating favorites list
2018-11-20 12:42:47.062 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - Player 00:04:20:16:5e:e2 updating favorites list
2018-11-20 12:42:47.082 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - Trying to download the content of URL http://mediaserver-cont-dc6-1-v4v6.pandora.com/images/public/int/4/2/1/8/008811098124_500W_500H.jpg
2018-11-20 12:42:47.083 [DEBUG] [t.http.internal.WebClientFactoryImpl] - creating http client for consumer common, endpoint null
2018-11-20 12:42:47.083 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@59314766
2018-11-20 12:42:47.100 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Jetty shared http client created
2018-11-20 12:42:47.102 [DEBUG] [t.http.internal.WebClientFactoryImpl] - creating web socket client for consumer common, endpoint null
2018-11-20 12:42:47.106 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@59314766
2018-11-20 12:42:47.162 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Jetty shared web socket client created
2018-11-20 12:42:47.163 [DEBUG] [t.http.internal.WebClientFactoryImpl] - shared http client requested
2018-11-20 12:42:47.171 [DEBUG] [lipse.smarthome.io.net.http.HttpUtil] - About to execute http://mediaserver-cont-dc6-1-v4v6.pandora.com/images/public/int/4/2/1/8/008811098124_500W_500H.jpg
2018-11-20 12:42:47.349 [DEBUG] [lipse.smarthome.io.net.http.HttpUtil] - Media download response: status 200 content length 17411 media type image/jpeg (URL http://mediaserver-cont-dc6-1-v4v6.pandora.com/images/public/int/4/2/1/8/008811098124_500W_500H.jpg)
I’m on build 1431, BTW.
I’ve tried quite a few 2.4 versions, including bleeding edge, but they all exhibit the same behaviour, so I preferred to go back to the more stable M versions.
This does feel a bit like what is happening, but then I could just be going down the wrong rabbit hole…
Still haven’t figured out the magical incantation for the runtime.cfg to get the max threads changed :-(.
Koen.
I will check my ‘lots of cores’ theory by spinning up a VM with only one core on the same server and install openhab on that with the squeezebox plugin.
But that’s for later. I will report back.
Koen.
@koentav So, this area of code has changed pretty substantially recently. I’m wondering if a synchronization issue possibly has been introduced that is being exploited by your environment.
@koentav Can you try installing 2.4.0 M5? That version doesn’t include the above change. Will be interesting to see how it behaves.
I ran M5 last week with the same results. M6 only made it into the openhab testing repository a couple of days ago and I had hoped that upgrading would solve the problem.
I went ahead and set up a single cpu VM, with exactly the same setup, debian stretch, M6, zulu-8. And lo and behold it works out of the box. I can control the squeezebox perfectly through openhab, and no mention of jetty problems in the log:
openhab> log:tail
22:27:52.091 [INFO ] [mebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
22:27:52.222 [INFO ] [bpanel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
22:28:02.432 [INFO ] [rthome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
22:28:03.321 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_album-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:album' has been added.
22:28:03.346 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_currentPlaylistRepeat-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:currentPlaylistReeat' has been added.
22:28:03.347 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_currentPlayingTime-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:currentPlayingTime' as been added.
22:28:03.349 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_duration-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:duration' has been added.
22:28:03.350 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_artist-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:artist' has been added.
22:28:03.351 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_mute-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:mute' has been added.
22:28:03.367 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_currentPlaylistShuffle-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:currentPlaylistSuffle' has been added.
22:28:03.368 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_title-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:title' has been added.
22:28:03.369 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:control' has been added.
22:28:03.371 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_volume-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:volume' has been added.
22:28:03.372 [INFO ] [thome.event.ItemChannelLinkAddedEvent] - Link 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_power-squeezebox:squeezeboxplayer:f16ede86:000420061c8c:power' has been added.
22:28:04.119 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.13.5:8080
22:28:04.123 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.13.5:8443
22:28:04.490 [INFO ] [marthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
22:28:05.424 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxserver:f16ede86' changed from UNINITIALIZED to INITIALIZING
22:28:05.436 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:f16ede86:000420061c8c' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
22:28:05.494 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxserver:f16ede86' changed from INITIALIZING to ONLINE
22:28:05.607 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:f16ede86:000420061c8c' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
22:28:05.626 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:f16ede86:000420061c8c' changed from INITIALIZING to ONLINE
22:28:06.137 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_artist changed from NULL to
22:28:06.148 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_album changed from NULL to
22:28:15.628 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_power changed from NULL to ON
22:28:15.642 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control changed from NULL to PAUSE
22:28:15.659 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_currentPlayingTime changed from NULL to 0
22:28:15.663 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_volume changed from NULL to 11
22:28:15.668 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_currentPlaylistRepeat changed from NULL to 0
22:28:15.673 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_currentPlaylistShuffle changed from NULL to 0
22:28:15.678 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_title changed from NULL to BBC Radio 4
22:34:43.137 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control' received command PLAY
22:34:43.167 [INFO ] [arthome.event.ItemStatePredictedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control predicted to become PLAY
22:34:43.173 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control changed from PAUSE to PLAY
22:34:43.687 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_duration changed from NULL to 0
22:34:45.716 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_currentPlayingTime changed from 0 to 1
22:34:46.718 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_currentPlayingTime changed from 1 to 2
22:34:46.855 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control' received command PAUSE
22:34:46.875 [INFO ] [arthome.event.ItemStatePredictedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control predicted to become PAUSE
22:34:46.876 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control changed from PLAY to PAUSE
22:34:47.194 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_currentPlayingTime changed from 2 to 3
I actually quite like this solution, and might just stick with this.
I can try to slowly increase the number of CPUs and see at which point the jetty error shows up…
Koen.
It looks exactly like the CPU number is the problem, where it pre-allocates (?) half of the CPU number of threads. If another thread is needed and makes the total go over 10 it fails…
with 16 CPUs:
22:48:14.219 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:f16ede86:000420061c8c' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
22:48:14.222 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:f16ede86:000420061c8c' changed from INITIALIZING to ONLINE
22:48:26.861 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control' received command PLAY
22:48:26.868 [INFO ] [arthome.event.ItemStatePredictedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control predicted to become PLAY
22:48:26.882 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control changed from NULL to PLAY
22:48:27.414 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_duration changed from NULL to 0
22:48:28.141 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control' received command PAUSE
22:48:28.144 [INFO ] [arthome.event.ItemStatePredictedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control predicted to become PAUSE
22:48:28.145 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_f16ede86_000420061c8c_control changed from PLAY to PAUSE
with 18 CPUs:
22:45:56.566 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:f16ede86:000420061c8c' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
22:45:56.569 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:f16ede86:000420061c8c' changed from INITIALIZING to ONLINE
22:45:56.590 [ERROR] [et.http.internal.WebClientFactoryImpl] - Could not start Jetty http client
java.lang.IllegalStateException: Insufficient configured threads: required=10 < max=10 for QueuedThreadPool[common]@8ed1f47{STARTED,5<=5<=10,i=5,q=0}[ReservedThreadExecutor@582e1ee2{s=0/1,p=0}]
at org.eclipse.jetty.util.thread.ThreadPoolBudget.check(ThreadPoolBudget.java:149) ~[?:?]
with 20 CPUs:
22:42:48.659 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:f16ede86:000420061c8c' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
22:42:48.665 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:f16ede86:000420061c8c' changed from INITIALIZING to ONLINE
22:42:48.698 [ERROR] [et.http.internal.WebClientFactoryImpl] - Could not start Jetty http client
java.lang.IllegalStateException: Insufficient configured threads: required=11 < max=10 for QueuedThreadPool[common]@2f61ff91{STARTED,5<=5<=10,i=5,q=0}[ReservedThreadExecutor@6fd73573{s=0/1,p=0}]
at org.eclipse.jetty.util.thread.ThreadPoolBudget.check(ThreadPoolBudget.java:149) ~[?:?]
at org.eclipse.jetty.util.thread.ThreadPoolBudget.leaseTo(ThreadPoolBudget.java:130) ~[?:?]
Nice bit of investigation.
It certainly looks like the Jetty issue you referenced above is indeed relevant to the issue you’re seeing.
Going to mark this query as solved. I know it’s not actually fixed for systems with lots of cores, but at least I found a way around it.
Thanks for your help!
Koen.
It would be great if you could report this as an issue for eclipse smarthome:
It sounds solvable with a proper configuration
Before opening an issue, it would be good if we can solve it by changing one (or more) of the config parameters bny setting it in runtime.cfg? We tried doing that previously, but we either picked the wrong parameter, or didn’t have the syntax quite right for what we put in runtime.cfg.
We were trying to set maxThreadsCustom using
org.eclipse.smarthome.io.net:maxThreadsCustom=some-number-greater-than-10
or
org.eclipse.smarthome.io.net.http:maxThreadsCustom=some-number-greater-than-10
Those didn’t work. What should we be using? Possibly minThreadsShared? What’s the full path of the config parameter?
I did indeed try both configuration parameters, with a value of 30, but still 10 was reported as max threads in the error message.
Here are all the threads parameters, and the corresponding log message that shows they were applied.
org.eclipse.smarthome.webclient:minThreadsShared=20
org.eclipse.smarthome.webclient:maxThreadsShared=60
org.eclipse.smarthome.webclient:minThreadsCustom=15
org.eclipse.smarthome.webclient:maxThreadsCustom=25
2018-11-21 08:19:56.787 [DEBUG] [org.eclipse.smarthome.io.net ] - ServiceEvent MODIFIED - {org.eclipse.smarthome.io.net.http.HttpClientFactory, org.eclipse.smarthome.io.net.http.WebSocketFactory}={service.id=269, maxThreadsShared=60, service.bundleid=117, service.scope=bundle, maxThreadsCustom=25, minThreadsCustom=15, minThreadsShared=20, service.pid=org.eclipse.smarthome.webclient, component.name=org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl, component.id=157} - org.eclipse.smarthome.io.net
I can confirm that this works, no more jetty failure, however I get another error (Buffering capacity exceeded).
openhab> log:tail
13:26:24.248 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.13.2:8080
13:26:24.249 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.13.2:8443
13:26:24.346 [INFO ] [marthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
13:26:24.513 [DEBUG] [org.openhab.binding.squeezebox ] - BundleEvent STARTING - org.openhab.binding.squeezebox
13:26:24.514 [DEBUG] [org.openhab.binding.squeezebox ] - BundleEvent STARTED - org.openhab.binding.squeezebox
13:26:24.522 [DEBUG] [org.openhab.binding.squeezebox ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={service.id=344, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.internal.discovery.SqueezeBoxServerDiscoveryParticipant, component.id=202} - org.openhab.binding.squeezebox
13:26:24.525 [DEBUG] [org.openhab.binding.squeezebox ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.squeezebox.internal.SqueezeBoxStateDescriptionOptionsProvider}={service.id=345, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.internal.SqueezeBoxStateDescriptionOptionsProvider, component.id=203} - org.openhab.binding.squeezebox
13:26:24.547 [DEBUG] [org.openhab.binding.squeezebox ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=346, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.internal.SqueezeBoxHandlerFactory, component.id=204} - org.openhab.binding.squeezebox
13:26:24.556 [DEBUG] [.SqueezeBoxPlayerDiscoveryParticipant] - Request player job scheduled to run every 60 seconds
13:26:24.562 [DEBUG] [org.openhab.binding.squeezebox ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=348, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
13:26:24.613 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'yeelight:wonder:0x0000000007c48766' changed from UNINITIALIZED to INITIALIZING
13:26:24.614 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - initializing server handler for thing squeezebox:squeezeboxserver:6c76cba1
13:26:24.616 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxserver:6c76cba1' changed from UNINITIALIZED to INITIALIZING
13:26:24.618 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
13:26:24.619 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:000420061c8c' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
13:26:24.624 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'yeelight:wonder:0x0000000007c48766' changed from INITIALIZING to OFFLINE: Device is offline!
13:26:24.633 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'yeelight:wonder:0x0000000007c2c586' changed from UNINITIALIZED to INITIALIZING
13:26:24.633 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'yeelight:wonder:0x0000000007c2c586' changed from INITIALIZING to OFFLINE: Device is offline!
13:26:24.636 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - listener connection started to server 192.168.13.2:9090
13:26:24.641 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: players 0
13:26:24.642 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxserver:6c76cba1' changed from INITIALIZING to ONLINE
13:26:24.643 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: favorites items 0 100
13:26:24.643 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: listen 1
13:26:24.645 [DEBUG] [org.openhab.binding.squeezebox ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=350, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
13:26:24.645 [DEBUG] [org.openhab.binding.squeezebox ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=351, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
13:26:24.655 [DEBUG] [.SqueezeBoxPlayerDiscoveryParticipant] - player added 00:04:20:04:18:c1 : SLIMP3
13:26:24.662 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
13:26:24.665 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:04:18:c1 status - 1 subscribe:10 tags:yagJlNKjc
13:26:24.665 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:000420061c8c' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
13:26:24.665 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:06:1c:8c status - 1 subscribe:10 tags:yagJlNKjc
13:26:24.666 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:6c76cba1:000420061c8c initialized.
13:26:24.666 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9 initialized.
13:26:24.667 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:000420061c8c' changed from INITIALIZING to ONLINE
13:26:24.667 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Player e2:7c:a6:6e:92:f9 updating favorites list
13:26:24.668 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Player 00:04:20:06:1c:8c updating favorites list
13:26:24.668 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from INITIALIZING to ONLINE
13:26:24.682 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Trying to download the content of URL http://192.168.13.2:9000/music/eff02a6a/cover.jpg
13:26:24.684 [DEBUG] [et.http.internal.WebClientFactoryImpl] - creating http client for consumer common, endpoint null
13:26:24.684 [DEBUG] [et.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@46966fec
13:26:24.697 [DEBUG] [et.http.internal.WebClientFactoryImpl] - Jetty shared http client created
13:26:24.700 [DEBUG] [et.http.internal.WebClientFactoryImpl] - creating web socket client for consumer common, endpoint null
13:26:24.701 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'yeelight:wonder:0x0000000007c48766' changed from OFFLINE: Device is offline! to UNKNOWN
13:26:24.704 [DEBUG] [et.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@46966fec
13:26:24.706 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'yeelight:wonder:0x0000000007c48766' changed from UNKNOWN to ONLINE
13:26:24.716 [INFO ] [elight.internal.lib.device.DeviceBase] - status = DeviceStatus [isPowerOff=true, r=255, g=0, b=64, color=16711744, brightness=50, ct=1700, hue=345, sat=100, isFlowing=false, delayOff=-1, mFlowItems=null, mode=null, isMusicOn=false, name=]
13:26:24.742 [DEBUG] [et.http.internal.WebClientFactoryImpl] - Jetty shared web socket client created
13:26:24.743 [DEBUG] [et.http.internal.WebClientFactoryImpl] - shared http client requested
13:26:24.753 [DEBUG] [clipse.smarthome.io.net.http.HttpUtil] - About to execute http://192.168.13.2:9000/music/eff02a6a/cover.jpg
13:26:24.858 [DEBUG] [clipse.smarthome.io.net.http.HttpUtil] - Media download failed (URL http://192.168.13.2:9000/music/eff02a6a/cover.jpg) : java.util.concurrent.ExecutionException: java.lang.IllegalArgumentException: Buffering capacity exceeded
13:26:24.858 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Failed to download the content of URL http://192.168.13.2:9000/music/eff02a6a/cover.jpg
Actually, that was a ridiculously large cover image that caused the error.
koen@lembeke:~/tmp$ ls -alh cover.jpg
-rw-r--r-- 1 koen koen 7.7M Nov 21 15:08 cover.jpg
When playing a different album, the error doesn’t happen!
15:09:44.983 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Trying to download the content of URL http://192.168.13.2:9000/music/55be152d/cover.jpg
15:09:44.985 [DEBUG] [et.http.internal.WebClientFactoryImpl] - creating http client for consumer common, endpoint null
15:09:44.985 [DEBUG] [et.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@3dffeb59
15:09:45.003 [DEBUG] [et.http.internal.WebClientFactoryImpl] - Jetty shared http client created
15:09:45.004 [DEBUG] [et.http.internal.WebClientFactoryImpl] - creating web socket client for consumer common, endpoint null
15:09:45.009 [DEBUG] [et.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@3dffeb59
15:09:45.041 [DEBUG] [et.http.internal.WebClientFactoryImpl] - Jetty shared web socket client created
15:09:45.042 [DEBUG] [et.http.internal.WebClientFactoryImpl] - shared http client requested
15:09:45.051 [DEBUG] [clipse.smarthome.io.net.http.HttpUtil] - About to execute http://192.168.13.2:9000/music/55be152d/cover.jpg
15:09:45.165 [DEBUG] [clipse.smarthome.io.net.http.HttpUtil] - Media download response: status 200 content length 46822 media type image/jpeg (URL http://192.168.13.2:9000/music/55be152d/cover.jpg)
15:09:45.166 [DEBUG] [clipse.smarthome.io.net.http.HttpUtil] - Media downloaded: size 46822 type image/jpeg (URL http://192.168.13.2:9000/music/55be152d/cover.jpg)
Yes, but this error is handled more gracefully because I catch the IllegalArgumentException. So, this error doesn’t kill the listener thread, and everything should continue to work properly. Correct?
Yikes!
Everything is indeed still working properly, yes.
Thanks,
Koen.
FYI, I wrote up a little blurb here.