Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Prevent errors in log when client closes the HTTP connection #2781

Merged
merged 2 commits into from
Feb 20, 2022
Merged

Prevent errors in log when client closes the HTTP connection #2781

merged 2 commits into from
Feb 20, 2022

Conversation

cweitkamp
Copy link
Contributor

  • Prevent errors in log when client closes the HTTP connection

We already added a block to catch exceptions in #2655. This PR makes it even harder (similar to #2654).

2022-02-18 12:36:01.404 [WARN ] [ache.cxf.phase.PhaseInterceptorChain] - Interceptor for {http://resources.internal.rest.io.core.openhab.org/}SystemInfoResource has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: Could not send Message.
        at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:67) ~[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.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) [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(Unknown Source) [?:?]
Caused by: java.io.IOException: Close SendCallback@107681e[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@5e41a] in state PROCESSING
        at org.eclipse.jetty.util.IteratingCallback.close(IteratingCallback.java:428) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.HttpConnection.onClose(HttpConnection.java:519) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.ssl.SslConnection.onClose(SslConnection.java:378) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.SelectorManager.connectionClosed(SelectorManager.java:345) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint.run(ManagedSelector.java:1104) ~[bundleFile:9.4.43.v20210629]
        ... 3 more
2022-02-18 12:36:01.507 [ERROR] [internal.JSONResponseExceptionMapper] - Unexpected exception occurred while processing REST request.
java.io.IOException: Close SendCallback@107681e[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@5e41a] in state PROCESSING
        at org.eclipse.jetty.util.IteratingCallback.close(IteratingCallback.java:428) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.HttpConnection.onClose(HttpConnection.java:519) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.ssl.SslConnection.onClose(SslConnection.java:378) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.SelectorManager.connectionClosed(SelectorManager.java:345) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint.run(ManagedSelector.java:1104) ~[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(Unknown Source) [?:?]

Signed-off-by: Christoph Weitkamp github@christophweitkamp.de

@cweitkamp
Prevent errors in log when client closes the HTTP connection
acc53a0 
Signed-off-by: Christoph Weitkamp <github@christophweitkamp.de>
@cweitkamp cweitkamp added bug An unexpected problem or unintended behavior of the Core REST/SSE labels Feb 18, 2022
@cweitkamp cweitkamp requested a review from a team as a code owner February 18, 2022 13:40
@wborn
Copy link
Member

wborn commented Feb 19, 2022

Makes sense to me, but I think it would be useful to still see the the original exception in the debug log statement where it missing now.

You could also make it trace level only using:

            logger.debug("Failed writing HTTP response, since other side closed the connection",
                    logger.isTraceEnabled() ? e : null);

@cweitkamp
Incorporated comments from review
1682f1e 
Signed-off-by: Christoph Weitkamp <github@christophweitkamp.de>
wborn
wborn approved these changes Feb 20, 2022
View reviewed changes
Copy link
Member

@wborn wborn left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the tweaks!

@wborn wborn merged commit 7997e26 into openhab:main Feb 20, 2022
@wborn wborn added this to the 3.3 milestone Feb 20, 2022
@cweitkamp cweitkamp deleted the bugfix-ioexception branch February 20, 2022 10:21
@wborn wborn mentioned this pull request Feb 28, 2022
Closed
@openhab-bot
Copy link
Collaborator

This pull request has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/oh3-problem-with-writing-the-data-class-org-openhab-core-io-rest-sitemap-internal-pagedto/111255/34

splatch pushed a commit to ConnectorIO/copybara-hab-core that referenced this pull request Jul 12, 2023
@cweitkamp @splatch
Prevent errors in log when client closes the HTTP connection (openhab…
3465b53 
…#2781)

Signed-off-by: Christoph Weitkamp <github@christophweitkamp.de>
GitOrigin-RevId: 7997e26
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@wborn wborn wborn approved these changes

Assignees
No one assigned
Labels
bug An unexpected problem or unintended behavior of the Core REST/SSE
Projects
None yet
Milestone
3.3
Development

Successfully merging this pull request may close these issues.
3 participants
@cweitkamp @wborn @openhab-bot