Identify What - Problem with writing the data, class org.openhab.core.io.rest.Stream2JSONInputStream

jwiseman · July 26, 2023, 10:37am

Over the last few weeks, I’m getting these often now in my log.

Is there anyway to identify what binding and/or script could be causing this. The error is not identifying anything specific.

Running OH 3.2 since it came out, been very stable.

2023-07-26 03:46:48.743 [ERROR] [org.apache.cxf.jaxrs.utils.JAXRSUtils             ] - Problem with writing the data, class org.openhab.core.io.rest.Stream2JSONInputStream, ContentType: application/json
2023-07-26 03:46:48.744 [ERROR] [.io.rest.core.internal.JSONResponseExceptionMapper] - Unexpected exception occurred while processing REST request.
java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
	at org.eclipse.jetty.util.SharedBlockingCallback$Blocker.block(SharedBlockingCallback.java:257) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.HttpOutput.channelWrite(HttpOutput.java:270) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:869) ~[bundleFile:9.4.43.v20210629]
	at org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWrappedOutputStream.java:51) ~[bundleFile:3.4.5]
	at java.io.InputStream.transferTo(InputStream.java:705) ~[?:?]
	at org.openhab.core.io.rest.core.internal.GsonMessageBodyWriter.writeTo(GsonMessageBodyWriter.java:84) ~[?:?]
	at org.openhab.core.io.rest.core.internal.MediaTypeExtension.writeTo(MediaTypeExtension.java:84) ~[?:?]
	at org.apache.cxf.jaxrs.utils.JAXRSUtils.writeMessageBody(JAXRSUtils.java:1543) ~[bundleFile:3.4.5]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:249) ~[bundleFile:3.4.5]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.processResponse(JAXRSOutInterceptor.java:122) ~[bundleFile:3.4.5]
	at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleMessage(JAXRSOutInterceptor.java:84) ~[bundleFile:3.4.5]
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) ~[bundleFile:3.4.5]
	at org.apache.cxf.interceptor.OutgoingChainInterceptor.handleMessage(OutgoingChainInterceptor.java:90) ~[bundleFile:3.4.5]
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:225) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:298) ~[bundleFile:3.4.5]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:222) ~[bundleFile:3.4.5]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) ~[bundleFile:3.1.0]
	at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:273) ~[bundleFile:3.4.5]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:550) ~[bundleFile:9.4.43.v20210629]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[bundleFile:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) ~[bundleFile:9.4.43.v20210629]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:294) ~[bundleFile:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.43.v20210629]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:82) ~[bundleFile:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.43.v20210629]
	at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[bundleFile:9.4.43.v20210629]
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[bundleFile:9.4.43.v20210629]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
	... 1 more

rlkoshak · July 26, 2023, 1:57pm

From the exception all I can say is that it’s associated with the REST API so the request is likely coming from a UI. And the request timed out waiting for something to happen that took more than 30 seconds to complete.

Are there any systemic problems on the machine which might be slowing things down? Can you correlate the exceptions with some action you’ve taken? Is there anything else going weird with other parts of OH?

jwiseman · July 26, 2023, 4:04pm

The only thing I added was another tablet showing habpanel. This brings the total to 4 tablets pulling against OH. All the panels show ipcamera views which the camera objects refresh every 2 seconds. This could be the cause BUT this line makes me believe it may not be.

A scheduler line item:
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]

Wouldn’t this point to a binding of some sort?

Best, Jay

rlkoshak · July 26, 2023, 4:21pm

No. Each web requests get handled by separate Thread and that’s done by the ThreadPool. Everything in the call stack is associated with the Jetty web server which means you are dealing with a request on the REST API which is either send directly or comes from a UI.

All those lines at the bottom mean is that the thread that was spawned to handle a web request timed out.