Jetty thread warnings and delay during shutdown

[mhilbush]

I'm running openHAB build 1448 with no bindings loaded, and just one System started rule that makes an http request using sendHttpGetRequest.

If Jetty starts up, there are warnings shown at shutdown, along with an ~30 second delay waiting for threads to stop.

Without the rule, the startup & shutdown looks like this.

2018-12-05 08:45:25.447 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'US/Eastern'.
2018-12-05 08:45:25.453 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to 'XXXXXX'.
2018-12-05 08:45:25.455 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_US'.
2018-12-05 08:45:26.159 [DEBUG] [org.eclipse.smarthome.io.net        ] - BundleEvent STARTING - org.eclipse.smarthome.io.net
2018-12-05 08:45:26.160 [DEBUG] [org.eclipse.smarthome.io.net        ] - BundleEvent STARTED - org.eclipse.smarthome.io.net
2018-12-05 08:45:26.162 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent REGISTERED - {org.osgi.service.cm.ManagedService}={service.id=220, service.bundleid=117, service.scope=singleton} - org.eclipse.smarthome.io.net
2018-12-05 08:45:26.171 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager}={service.id=221, service.bundleid=117, service.scope=bundle, component.name=org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager, component.id=104} - org.eclipse.smarthome.io.net
2018-12-05 08:45:26.177 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.net.http.HttpClientFactory, org.eclipse.smarthome.io.net.http.WebSocketFactory}={service.id=222, maxThreadsShared=60, service.bundleid=117, service.scope=bundle, maxThreadsCustom=20, minThreadsCustom=10, minThreadsShared=10, service.pid=org.eclipse.smarthome.webclient, component.name=org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl, component.id=102} - org.eclipse.smarthome.io.net
2018-12-05 08:45:27.670 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2018-12-05 08:45:28.191 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at 
2018-12-05 08:45:28.193 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at 
2018-12-05 08:45:44.130 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.io.net.http.HttpClientFactory, org.eclipse.smarthome.io.net.http.WebSocketFactory}={service.id=222, maxThreadsShared=60, service.bundleid=117, service.scope=bundle, maxThreadsCustom=20, minThreadsCustom=10, minThreadsShared=10, service.pid=org.eclipse.smarthome.webclient, component.name=org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl, component.id=102} - org.eclipse.smarthome.io.net
2018-12-05 08:45:44.131 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager}={service.id=221, service.bundleid=117, service.scope=bundle, component.name=org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager, component.id=104} - org.eclipse.smarthome.io.net
2018-12-05 08:45:44.132 [DEBUG] [org.eclipse.smarthome.io.net        ] - BundleEvent STOPPING - org.eclipse.smarthome.io.net
2018-12-05 08:45:44.133 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent UNREGISTERING - {org.osgi.service.cm.ManagedService}={service.id=220, service.bundleid=117, service.scope=singleton} - org.eclipse.smarthome.io.net
2018-12-05 08:45:44.133 [DEBUG] [org.eclipse.smarthome.io.net        ] - BundleEvent STOPPED - org.eclipse.smarthome.io.net
2018-12-05 08:45:44.140 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard

With the rule, the startup and shutdown looks like this.

2018-12-05 08:47:07.299 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'US/Eastern'.
2018-12-05 08:47:07.305 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to 'XXXX'.
2018-12-05 08:47:07.306 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_US'.
2018-12-05 08:47:07.960 [DEBUG] [org.eclipse.smarthome.io.net        ] - BundleEvent STARTING - org.eclipse.smarthome.io.net
2018-12-05 08:47:07.963 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent REGISTERED - {org.osgi.service.cm.ManagedService}={service.id=220, service.bundleid=117, service.scope=singleton} - org.eclipse.smarthome.io.net
2018-12-05 08:47:07.980 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.net.http.HttpClientFactory, org.eclipse.smarthome.io.net.http.WebSocketFactory}={service.id=222, maxThreadsShared=60, service.bundleid=117, service.scope=bundle, maxThreadsCustom=20, minThreadsCustom=10, minThreadsShared=10, service.pid=org.eclipse.smarthome.webclient, component.name=org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl, component.id=102} - org.eclipse.smarthome.io.net
2018-12-05 08:47:07.981 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager}={service.id=221, service.bundleid=117, service.scope=bundle, component.name=org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager, component.id=104} - org.eclipse.smarthome.io.net
2018-12-05 08:47:07.982 [DEBUG] [org.eclipse.smarthome.io.net        ] - BundleEvent STARTED - org.eclipse.smarthome.io.net
2018-12-05 08:47:09.554 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2018-12-05 08:47:10.148 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'
2018-12-05 08:47:10.571 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at 
2018-12-05 08:47:10.572 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at 
2018-12-05 08:47:17.450 [INFO ] [eclipse.smarthome.model.script.build] - Sending http request
2018-12-05 08:47:17.453 [DEBUG] [t.http.internal.WebClientFactoryImpl] - creating http client for consumer common, endpoint null
2018-12-05 08:47:17.453 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@55b4128
2018-12-05 08:47:17.468 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Jetty shared http client created
2018-12-05 08:47:17.469 [DEBUG] [t.http.internal.WebClientFactoryImpl] - creating web socket client for consumer common, endpoint null
2018-12-05 08:47:17.474 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Setting up SSLContext for org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager@55b4128
2018-12-05 08:47:17.497 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Jetty shared web socket client created
2018-12-05 08:47:17.497 [DEBUG] [t.http.internal.WebClientFactoryImpl] - shared http client requested
2018-12-05 08:47:17.505 [DEBUG] [lipse.smarthome.io.net.http.HttpUtil] - About to execute https://ci.openhab.org/job/openHAB-Distribution/api/json?tree=lastSuccessfulBuild[number]
2018-12-05 08:47:18.068 [INFO ] [eclipse.smarthome.model.script.build] - Got response
2018-12-05 08:47:38.061 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.io.net.http.HttpClientFactory, org.eclipse.smarthome.io.net.http.WebSocketFactory}={service.id=222, maxThreadsShared=60, service.bundleid=117, service.scope=bundle, maxThreadsCustom=20, minThreadsCustom=10, minThreadsShared=10, service.pid=org.eclipse.smarthome.webclient, component.name=org.eclipse.smarthome.io.net.http.internal.WebClientFactoryImpl, component.id=102} - org.eclipse.smarthome.io.net
2018-12-05 08:48:08.065 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - QueuedThreadPool[common]@793141ea{STOPPING,10<=10<=60,i=0,q=6}[org.eclipse.jetty.util.thread.TryExecutor$$Lambda$116/4716790@48e4268e] Couldn't stop Thread[common-145,5,main]
2018-12-05 08:48:08.066 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - QueuedThreadPool[common]@793141ea{STOPPING,10<=10<=60,i=0,q=6}[org.eclipse.jetty.util.thread.TryExecutor$$Lambda$116/4716790@48e4268e] Couldn't stop Thread[common-147,5,main]
2018-12-05 08:48:08.067 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - QueuedThreadPool[common]@793141ea{STOPPING,10<=10<=60,i=0,q=6}[org.eclipse.jetty.util.thread.TryExecutor$$Lambda$116/4716790@48e4268e] Couldn't stop Thread[common-146,5,main]
2018-12-05 08:48:08.067 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Jetty shared http client stopped
2018-12-05 08:48:08.071 [DEBUG] [t.http.internal.WebClientFactoryImpl] - Jetty shared web socket client stopped
2018-12-05 08:48:08.072 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager}={service.id=221, service.bundleid=117, service.scope=bundle, component.name=org.eclipse.smarthome.io.net.http.internal.ExtensibleTrustManager, component.id=104} - org.eclipse.smarthome.io.net
2018-12-05 08:48:08.072 [DEBUG] [org.eclipse.smarthome.io.net        ] - BundleEvent STOPPING - org.eclipse.smarthome.io.net
2018-12-05 08:48:08.073 [DEBUG] [org.eclipse.smarthome.io.net        ] - ServiceEvent UNREGISTERING - {org.osgi.service.cm.ManagedService}={service.id=220, service.bundleid=117, service.scope=singleton} - org.eclipse.smarthome.io.net
2018-12-05 08:48:08.073 [DEBUG] [org.eclipse.smarthome.io.net        ] - BundleEvent STOPPED - org.eclipse.smarthome.io.net
2018-12-05 08:48:08.077 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard

[mhilbush]

@kaikreuzer I've not seen this behavior before, so I'm wondering if it was introduced with the fix to use the common thread pool.

[kaikreuzer]

You mean #6588? Might be...

[mhilbush]

Yeah, that's the one.

[kaikreuzer]

Ok, I can reproduce the problem. Not nice.

[kaikreuzer]

I've created #6636, which solves the issue for me - at least for the shared client.

[mhilbush]

Confirming that this resolved the issue. Thanks!!