[SOLVED] No contact to squeeze server with error message 'Could not start Jetty http client'

Add-ons Bindings
1

Hi,

I’m fairly new at playing with openhab, starting off with trying to get my squeezeboxes to run and then hopefully use one of them as an audio sink for TTS.

I’m running openhab2 on debian stretch, with

deb https://dl.bintray.com/openhab/apt-repo2 testing main

as my sources list and running the latest M6 version of 2.0.4

root@proliant:/etc# apt-cache policy openhab2
openhab2:
  Installed: 2.4.0~M6-1
  Candidate: 2.4.0~M6-1
  Version table:
 *** 2.4.0~M6-1 650
        650 https://dl.bintray.com/openhab/apt-repo2 testing/main amd64 Packages
        100 /var/lib/dpkg/status

The squeezebox binding finds the server correctly, and the connected clients, but I can’t control any of them.

When connecting to the openhab cli, it shows that I’m using the latest M6 binding:

list -s org.openhab.binding.squeezebox
START LEVEL 100 , List Threshold: 50
 ID │ State  │ Lvl │ Version  │ Symbolic name
────┼────────┼─────┼──────────┼───────────────$
196 │ Active │  80 │ 2.4.0.M6 │ org.openhab.binding.squeezebox

looking at the log with debug enabled for the binding I get this:

14:13:17.468 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.13.2:8080
14:13:17.469 [INFO ] [i.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.13.2:8443
14:13:17.589 [INFO ] [marthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
14:13:17.781 [DEBUG] [org.openhab.binding.squeezebox       ] - BundleEvent STARTING - org.openhab.binding.squeezebox
14:13:17.782 [DEBUG] [org.openhab.binding.squeezebox       ] - BundleEvent STARTED - org.openhab.binding.squeezebox
14:13:17.788 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={service.id=343, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.$
14:13:17.790 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.squeezebox.internal.SqueezeBoxStateDescriptionOptionsProvider}={service.id=344, s$
14:13:17.806 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=345, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.int$
14:13:17.852 [DEBUG] [.SqueezeBoxPlayerDiscoveryParticipant] - Request player job scheduled to run every 60 seconds
14:13:17.856 [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
14:13:17.870 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - initializing server handler for thing squeezebox:squeezeboxserver:6c76cba1
14:13:17.877 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxserver:6c76cba1' changed from UNINITIALIZED to INITIALIZING
14:13:17.882 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
14:13:17.883 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:000420061c8c' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
14:13:17.897 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - listener connection started to server 127.0.0.1:9090
14:13:17.903 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: players 0
14:13:17.904 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxserver:6c76cba1' changed from INITIALIZING to ONLINE
14:13:17.905 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: favorites items 0 100
14:13:17.907 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=349, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
14:13:17.907 [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
14:13:17.907 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: listen 1
14:13:17.923 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:06:1c:8c status - 1 subscribe:10 tags:yagJlNKjc
14:13:17.924 [DEBUG] [.SqueezeBoxPlayerDiscoveryParticipant] - player added 00:04:20:04:18:c1 : SLIMP3
14:13:17.926 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
14:13:17.930 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:6c76cba1:000420061c8c initialized.
14:13:17.929 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9 initialized.
14:13:17.930 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:000420061c8c' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
14:13:17.932 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from INITIALIZING to ONLINE
14:13:17.934 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:000420061c8c' changed from INITIALIZING to ONLINE
14:13:17.939 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:04:18:c1 status - 1 subscribe:10 tags:yagJlNKjc
14:13:17.940 [DEBUG] [.SqueezeBoxPlayerDiscoveryParticipant] - player added 00:04:20:1e:b2:fa : Squeezebox Boom
14:13:17.966 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:1e:b2:fa status - 1 subscribe:10 tags:yagJlNKjc
14:13:17.967 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Player e2:7c:a6:6e:92:f9 updating favorites list
14:13:17.968 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Player 00:04:20:06:1c:8c updating favorites list
14:13:17.974 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Trying to download the content of URL http://www.bbc.co.uk/radio/imda/logos/radio4_logomobile1-1.png
14:13:17.982 [ERROR] [et.http.internal.WebClientFactoryImpl] - Could not start Jetty http client
java.lang.IllegalStateException: Insufficient configured threads: required=13 < max=10 for QueuedThreadPool[common]@fee4838{STARTED,5<=5<=10,i=5,q=0}[ReservedThreadExecutor@3da228b{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) ~[?:?]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.leaseFrom(ThreadPoolBudget.java:175) ~[?:?]
        at org.eclipse.jetty.io.SelectorManager.doStart(SelectorManager.java:251) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[?:?]
        at org.eclipse.jetty.client.AbstractConnectorHttpClientTransport.doStart(AbstractConnectorHttpClientTransport.java:64) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[?:?]
        at org.eclipse.jetty.client.HttpClient.doStart(HttpClient.java:241) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl$2.run(WebClientFactoryImpl.java:258) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl$2.run(WebClientFactoryImpl.java:1) ~[?:?]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl.createHttpClientInternal(WebClientFactoryImpl.java:244) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl.access$7(WebClientFactoryImpl.java:242) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl$1.run(WebClientFactoryImpl.java:218) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl$1.run(WebClientFactoryImpl.java:1) ~[?:?]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl.initialize(WebClientFactoryImpl.java:209) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl.getCommonHttpClient(WebClientFactoryImpl.java:160) ~[?:?]
        at org.eclipse.smarthome.io.net.http.HttpUtil.executeUrlAndGetReponse(HttpUtil.java:194) ~[?:?]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadData(HttpUtil.java:438) ~[?:?]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadImage(HttpUtil.java:401) ~[?:?]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadImage(HttpUtil.java:372) ~[?:?]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadImage(HttpUtil.java:358) ~[?:?]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxPlayerHandler.lambda$0(SqueezeBoxPlayerHandler.java:419) ~[?:?]
        at org.eclipse.smarthome.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:97) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
        at org.eclipse.smarthome.core.cache.ExpiringCache.getValue(ExpiringCache.java:68) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
        at org.eclipse.smarthome.core.cache.ExpiringCacheMap.get(ExpiringCacheMap.java:198) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
        at org.eclipse.smarthome.core.cache.ExpiringCacheMap.putIfAbsentAndGet(ExpiringCacheMap.java:127) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
        at org.eclipse.smarthome.core.cache.ExpiringCacheMap.putIfAbsentAndGet(ExpiringCacheMap.java:112) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxPlayerHandler.downloadImage(SqueezeBoxPlayerHandler.java:416) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxPlayerHandler.coverArtChangeEvent(SqueezeBoxPlayerHandler.java:402) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler$SqueezeServerListener$14.updateListener(SqueezeBoxServerHandler.java:777) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler.updatePlayer(SqueezeBoxServerHandler.java:1000) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler.access$8(SqueezeBoxServerHandler.java:988) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler$SqueezeServerListener.handleStatusMessage(SqueezeBoxServerHandler.java:774) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler$SqueezeServerListener.handlePlayerUpdate(SqueezeBoxServerHandler.java:554) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler$SqueezeServerListener.run(SqueezeBoxServerHandler.java:434) [196:org.openhab.binding.squeezebox:2.4.0.M6]
14:13:27.855 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...
14:14:27.857 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...

And then it just repeats that there is no connection to squeeze server. I have tried changing the squeeze server ip or hostname to 192.168.13.2 from 127.0.0.1 with the same result.

Is the jetty server failure just a red herring and I’m looking in the wrong place to fix this?

The squeezeboxserver I run is pretty recent, and other third party clients (such as squeezer on android) seem to have no problem connecting and controlling the squeezebox server.

root@proliant:/etc# apt-cache policy logitechmediaserver
logitechmediaserver:
  Installed: 7.9.2~1542290182
  Candidate: 7.9.2~1542290182
  Version table:
 *** 7.9.2~1542290182 100
        100 /var/lib/dpkg/status

Any help would be appreciated…

Thanks,

Koen.

2

first of all, please edit your post above and include all code in fences

image

it’s easier to read the logs and entries

1 Like
3

Yes, that does look a lot better!

Thanks,

Koen.

1 Like
4

Thanks for providing this level of detail. Makes it much easier to see what’s going on.

So, it looks like your server and 2 players come ONLINE ok. The server successfully gets a connection to the LMS, which appears to be running on the same host as openHAB. So far, so good.

14:13:17.974 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Trying to download the content of URL http://www.bbc.co.uk/radio/imda/logos/radio4_logomobile1-1.png

Here the player tries to download the coverart for whatever is playing. But the Jetty client throws an IllegalStateException complaining that there are no threads available in the thread pool. That’s odd. I wonder what’s using up all the threads? Are you doing a lot of other http transactions (such as in rules, the http binding, etc.)?

Nope. The IllegalStateException thrown by Jetty is a runtime exception that is not handled by the squeezebox listener thread, causing it to exit.

What happens if you stop/start the squeezebox binding? Does it come up ok again, then fail a short time later with the same error?

5

Yes, it loads and fails pretty soon after:

openhab> bundle:stop org.openhab.binding.squeezebox 
openhab> bundle:start org.openhab.binding.squeezebox                                                                                                                                                                                                                                                     
openhab> log:tail
16:25:37.914 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=350, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
16:25:37.918 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9 disposed.
16:25:37.920 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:000420061c8c' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
16:25:37.922 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=349, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
16:25:37.923 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from ONLINE to UNINITIALIZED
16:25:37.924 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
16:25:37.924 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - disposing server handler for thing squeezebox:squeezeboxserver:6c76cba1
16:25:37.925 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - setting squeeze server listener terminate flag
16:25:37.926 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxserver:6c76cba1' changed from ONLINE to UNINITIALIZED
16:25:37.926 [DEBUG] [.SqueezeBoxPlayerDiscoveryParticipant] - canceling RequestPlayerJob
16:25:37.928 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=346, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
16:25:37.931 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxserver:6c76cba1' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
16:25:37.937 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=345, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.internal.SqueezeBoxHandlerFactory, component.id=204} - org.openhab.binding.squeezebox
16:25:37.940 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.squeezebox.internal.SqueezeBoxStateDescriptionOptionsProvider}={service.id=344, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.internal.SqueezeBoxStateDescriptionOptionsProvider, component.id=203} - org.openhab.binding.squeezebox
16:25:37.945 [DEBUG] [org.openhab.binding.squeezebox       ] - BundleEvent STOPPED - org.openhab.binding.squeezebox
16:25:43.310 [DEBUG] [org.openhab.binding.squeezebox       ] - BundleEvent STARTING - org.openhab.binding.squeezebox
16:25:43.312 [DEBUG] [org.openhab.binding.squeezebox       ] - BundleEvent STARTED - org.openhab.binding.squeezebox
16:25:43.318 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={service.id=353, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.internal.discovery.SqueezeBoxServerDiscoveryParticipant, component.id=209} - org.openhab.binding.squeezebox
16:25:43.321 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.squeezebox.internal.SqueezeBoxStateDescriptionOptionsProvider}={service.id=354, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.internal.SqueezeBoxStateDescriptionOptionsProvider, component.id=210} - org.openhab.binding.squeezebox
16:25:43.326 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=355, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.internal.SqueezeBoxHandlerFactory, component.id=211} - org.openhab.binding.squeezebox
16:25:43.333 [DEBUG] [.SqueezeBoxPlayerDiscoveryParticipant] - Request player job scheduled to run every 60 seconds
16:25:43.337 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=356, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
16:25:43.340 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - initializing server handler for thing squeezebox:squeezeboxserver:6c76cba1
16:25:43.340 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxserver:6c76cba1' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
16:25:43.342 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - listener connection started to server 192.168.13.2:9090
16:25:43.342 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
16:25:43.344 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:000420061c8c' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
16:25:43.345 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: players 0
16:25:43.345 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxserver:6c76cba1' changed from INITIALIZING to ONLINE
16:25:43.345 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: favorites items 0 100
16:25:43.346 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: listen 1
16:25:43.347 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=358, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
16:25:43.347 [DEBUG] [org.openhab.binding.squeezebox       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=357, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
16:25:43.353 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:6c76cba1:000420061c8c initialized.
16:25:43.354 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:000420061c8c' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
16:25:43.354 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9 initialized.
16:25:43.354 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
16:25:43.355 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:000420061c8c' changed from INITIALIZING to ONLINE
16:25:43.357 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:06:1c:8c status - 1 subscribe:10 tags:yagJlNKjc
16:25:43.357 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9' changed from INITIALIZING to ONLINE
16:25:43.358 [DEBUG] [.SqueezeBoxPlayerDiscoveryParticipant] - player added 00:04:20:04:18:c1 : SLIMP3 
16:25:43.361 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:04:18:c1 status - 1 subscribe:10 tags:yagJlNKjc
16:25:43.361 [DEBUG] [.SqueezeBoxPlayerDiscoveryParticipant] - player added 00:04:20:1e:b2:fa : Squeezebox Boom 
16:25:43.370 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:1e:b2:fa status - 1 subscribe:10 tags:yagJlNKjc
16:25:43.371 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Player e2:7c:a6:6e:92:f9 updating favorites list
16:25:43.372 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Player 00:04:20:06:1c:8c updating favorites list
16:25:43.376 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Trying to download the content of URL http://www.bbc.co.uk/radio/imda/logos/radio4_logomobile1-1.png
16:25:43.376 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_6c76cba1_000420061c8c_power changed from NULL to ON
16:25:43.378 [INFO ] [smarthome.event.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_6c76cba1_000420061c8c_control changed from NULL to PAUSE
16:25:43.381 [ERROR] [et.http.internal.WebClientFactoryImpl] - Could not start Jetty http client
java.lang.IllegalStateException: Insufficient configured threads: required=13 < max=10 for QueuedThreadPool[common]@75f3f957{STARTED,5<=5<=10,i=5,q=0}[ReservedThreadExecutor@16f08868{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) ~[?:?]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.leaseFrom(ThreadPoolBudget.java:175) ~[?:?]
        at org.eclipse.jetty.io.SelectorManager.doStart(SelectorManager.java:251) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[?:?]
        at org.eclipse.jetty.client.AbstractConnectorHttpClientTransport.doStart(AbstractConnectorHttpClientTransport.java:64) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[?:?]
        at org.eclipse.jetty.client.HttpClient.doStart(HttpClient.java:241) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl$2.run(WebClientFactoryImpl.java:258) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl$2.run(WebClientFactoryImpl.java:1) ~[?:?]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl.createHttpClientInternal(WebClientFactoryImpl.java:244) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl.access$7(WebClientFactoryImpl.java:242) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl$1.run(WebClientFactoryImpl.java:218) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl$1.run(WebClientFactoryImpl.java:1) ~[?:?]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl.initialize(WebClientFactoryImpl.java:209) ~[?:?]
        at org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl.getCommonHttpClient(WebClientFactoryImpl.java:160) ~[?:?]
        at org.eclipse.smarthome.io.net.http.HttpUtil.executeUrlAndGetReponse(HttpUtil.java:194) ~[?:?]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadData(HttpUtil.java:438) ~[?:?]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadImage(HttpUtil.java:401) ~[?:?]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadImage(HttpUtil.java:372) ~[?:?]
        at org.eclipse.smarthome.io.net.http.HttpUtil.downloadImage(HttpUtil.java:358) ~[?:?]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxPlayerHandler.lambda$0(SqueezeBoxPlayerHandler.java:419) ~[?:?]
        at org.eclipse.smarthome.core.cache.ExpiringCache.refreshValue(ExpiringCache.java:97) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
        at org.eclipse.smarthome.core.cache.ExpiringCache.getValue(ExpiringCache.java:68) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
        at org.eclipse.smarthome.core.cache.ExpiringCacheMap.get(ExpiringCacheMap.java:198) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
        at org.eclipse.smarthome.core.cache.ExpiringCacheMap.putIfAbsentAndGet(ExpiringCacheMap.java:127) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
        at org.eclipse.smarthome.core.cache.ExpiringCacheMap.putIfAbsentAndGet(ExpiringCacheMap.java:112) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxPlayerHandler.downloadImage(SqueezeBoxPlayerHandler.java:416) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxPlayerHandler.coverArtChangeEvent(SqueezeBoxPlayerHandler.java:402) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler$SqueezeServerListener$14.updateListener(SqueezeBoxServerHandler.java:777) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler.updatePlayer(SqueezeBoxServerHandler.java:1000) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler.access$8(SqueezeBoxServerHandler.java:988) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler$SqueezeServerListener.handleStatusMessage(SqueezeBoxServerHandler.java:774) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler$SqueezeServerListener.handlePlayerUpdate(SqueezeBoxServerHandler.java:554) [196:org.openhab.binding.squeezebox:2.4.0.M6]
        at org.openhab.binding.squeezebox.internal.handler.SqueezeBoxServerHandler$SqueezeServerListener.run(SqueezeBoxServerHandler.java:434) [196:org.openhab.binding.squeezebox:2.4.0.M6]
16:25:53.335 [DEBUG] [ernal.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...

I have tried to find where the max threads are being set, but no luck. Openhab runs on quite a beefy server, so I don’t mind increasing it if necessary.

The error happens even when squeezebox is the only binding running, and currently I have no rules defined, so I don’t think that anything else is using up the threads.

Thanks,

Koen.

6

Here

You can adjust this in runtime.cfg, but I’m not sure exactly what to put there. Possibly

org.eclipse.smarthome.io.net:maxThreadsCustom=some-number-greater-than-10

But, without understanding root cause, my fear is that you’ll just run out again. Worth a try, though.

7

You also could put org.eclipse.smarthome.io.net in DEBUG mode to get a little more information about what’s going on.

log:set DEBUG org.eclipse.smarthome.io.net
8

I’m not getting much more logging with this, although endpoint null is maybe a bit strange?

16:51:46.589 [DEBUG] [ernal.handler.SqueezeBoxPlayerHandler] - Trying to download the content of URL http://www.bbc.co.uk/radio/imda/logos/radio4_logomobile1-1.png
16:51:46.591 [DEBUG] [et.http.internal.WebClientFactoryImpl] - creating http client for consumer common, endpoint null
16:51:46.592 [DEBUG] [et.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@2b3a32ad
16:51:46.597 [ERROR] [et.http.internal.WebClientFactoryImpl] - Could not start Jetty http client
java.lang.IllegalStateException: Insufficient configured threads: required=13 < max=10 for QueuedThreadPool[common]@51cda85d{STARTED,5<=5<=10,i=5,q=0}[ReservedThreadExecutor@4f075b32{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) ~[?:?]

I tried this, but it looks like openhab2 didn’t pick it up, still showing 10 as max threads.

9

Maybe try restarting openHAB. That way you might see what’s driving the threads to be so high.

Yeah, I wasn’t sure that was the right thing to put in runtime.cfg. Maybe it’s

org.eclipse.smarthome.io.net.http:maxThreadsCustom=some-number-greater-than-10
10

Log from the start…

2018-11-20 17:05:10.545 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2018-11-20 17:05:10.570 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
2018-11-20 17:05:11.382 [DEBUG] [org.eclipse.smarthome.io.net        ] - BundleEvent STARTING - org.eclipse.smarthome.io.net
2018-11-20 17:05:11.384 [DEBUG] [org.eclipse.smarthome.io.net        ] - BundleEvent STARTED - org.eclipse.smarthome.io.net
2018-11-20 17:05:11.410 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.net.http.HttpClientFactory, org.eclipse.smarthome.io.net.http.WebSocketFactory}={service.id=223, service.bundleid=117, service.scope=bundle, component.name=org.eclipse.smarthome.io.net.http.in$
2018-11-20 17:05:11.411 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager}={service.id=222, service.bundleid=117, service.scope=bundle, component.name=org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager, compone$
2018-11-20 17:05:13.870 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2018-11-20 17:05:14.532 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.13.2:8080
2018-11-20 17:05:14.533 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.13.2:8443
2018-11-20 17:05:14.626 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2018-11-20 17:05:14.834 [DEBUG] [org.openhab.binding.squeezebox      ] - BundleEvent STARTING - org.openhab.binding.squeezebox
2018-11-20 17:05:14.835 [DEBUG] [org.openhab.binding.squeezebox      ] - BundleEvent STARTED - org.openhab.binding.squeezebox
2018-11-20 17:05:14.848 [DEBUG] [org.openhab.binding.squeezebox      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={service.id=343, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.internal.discovery.SqueezeBoxServerDiscoveryP$
2018-11-20 17:05:14.851 [DEBUG] [org.openhab.binding.squeezebox      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.squeezebox.internal.SqueezeBoxStateDescriptionOptionsProvider}={service.id=344, service.bundleid=196, service.scope=bundle, co$
2018-11-20 17:05:14.868 [DEBUG] [org.openhab.binding.squeezebox      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=345, service.bundleid=196, service.scope=bundle, component.name=org.openhab.binding.squeezebox.internal.SqueezeBoxHandlerFactory, component.id=$
2018-11-20 17:05:14.887 [DEBUG] [SqueezeBoxPlayerDiscoveryParticipant] - Request player job scheduled to run every 60 seconds
2018-11-20 17:05:14.891 [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
2018-11-20 17:05:14.920 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - initializing server handler for thing squeezebox:squeezeboxserver:6c76cba1
2018-11-20 17:05:14.946 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - listener connection started to server 192.168.13.2:9090
2018-11-20 17:05:14.951 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: players 0
2018-11-20 17:05:14.953 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: favorites items 0 100
2018-11-20 17:05:14.954 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: listen 1
2018-11-20 17:05:14.956 [DEBUG] [org.openhab.binding.squeezebox      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.audio.AudioSink}={service.id=349, service.bundleid=196, service.scope=singleton} - org.openhab.binding.squeezebox
2018-11-20 17:05:14.956 [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
2018-11-20 17:05:14.968 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:06:1c:8c status - 1 subscribe:10 tags:yagJlNKjc
2018-11-20 17:05:14.969 [DEBUG] [SqueezeBoxPlayerDiscoveryParticipant] - player added 00:04:20:04:18:c1 : SLIMP3
2018-11-20 17:05:14.980 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:6c76cba1:000420061c8c initialized.
2018-11-20 17:05:14.980 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - player thing squeezebox:squeezeboxplayer:6c76cba1:e27ca66e92f9 initialized.
2018-11-20 17:05:14.984 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:04:18:c1 status - 1 subscribe:10 tags:yagJlNKjc
2018-11-20 17:05:14.985 [DEBUG] [SqueezeBoxPlayerDiscoveryParticipant] - player added 00:04:20:1e:b2:fa : Squeezebox Boom
2018-11-20 17:05:15.008 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:1e:b2:fa status - 1 subscribe:10 tags:yagJlNKjc
2018-11-20 17:05:15.009 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - Player e2:7c:a6:6e:92:f9 updating favorites list
2018-11-20 17:05:15.010 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - Player 00:04:20:06:1c:8c updating favorites list
2018-11-20 17:05:15.020 [DEBUG] [rnal.handler.SqueezeBoxPlayerHandler] - Trying to download the content of URL http://www.bbc.co.uk/radio/imda/logos/radio4_logomobile1-1.png
2018-11-20 17:05:15.022 [DEBUG] [t.http.internal.WebClientFactoryImpl] - creating http client for consumer common, endpoint null
2018-11-20 17:05:15.023 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@1badaab4
2018-11-20 17:05:15.029 [ERROR] [t.http.internal.WebClientFactoryImpl] - Could not start Jetty http client
java.lang.IllegalStateException: Insufficient configured threads: required=13 < max=10 for QueuedThreadPool[common]@3e947c3e{STARTED,5<=5<=10,i=5,q=0}[ReservedThreadExecutor@57b72856{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) ~[?:?]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.leaseFrom(ThreadPoolBudget.java:175) ~[?:?]

That didn’t work either unfortunately.

I will look a bit deeper into where to configure this. I wonder if java somehow decides to launch a default number of http threads depending on the number of cores available, and because I run this on an old proliant server with 12 cores (24 counting hyperthreading), it just goes past the CONFIG_MAX_THREADS_CUSTOM from the start.

Thanks for your help so far!

Koen.

11

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…

12

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)
13

I’m on build 1431, BTW.

14

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.

15

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.

16

@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.

@Kai or @martinvw Do you have any thoughts on this?

17

@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.

18

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.

19

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) ~[?:?]
2 Likes
20

Nice bit of investigation.

It certainly looks like the Jetty issue you referenced above is indeed relevant to the issue you’re seeing.