ujibang
commented
6 years ago Hi,
I just pushed a simple commit that avoids exchange.addExchangeCompleteListener() call if exchange is complete in MetricsInstrumentationHandler
This should avoid that exception log and allow to further debug this issue.
Please try your use case with latest 3.5.0-SNAPSHOT.
Few question:
- are that GET requests actually failing (eg error 500), or they succeed but logging that error?
- are the GET request to the files bucket
/assets.files, specific files/assets.files/idor specific files' binary/assets.files/id/binary
christiangroth
grossmueller-espirit
mkjsix
We encountered quite a few "exchange already complete" exceptions while pushing data to restheart. The stacktraces come in two flavors, so to say. Sometimes it's the MetricsInstrumentationHandler that crashes and sometimes the RequestLoggerHandler.
First kind of exception:
12:31:01.171 [XNIO-1 task-14] ERROR org.restheart.handlers.ErrorHandler - Error handling the request java.lang.IllegalStateException: UT000139: Exchange already complete at io.undertow.server.HttpServerExchange.addExchangeCompleteListener(HttpServerExchange.java:941) at org.restheart.handlers.MetricsInstrumentationHandler.handleRequest(MetricsInstrumentationHandler.java:50) at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:121) at org.restheart.handlers.injectors.RequestContextInjectorHandler.handleRequest(RequestContextInjectorHandler.java:655) at org.restheart.handlers.injectors.RequestContextInjectorHandler.handleRequest(RequestContextInjectorHandler.java:660) at io.undertow.server.handlers.PathHandler.handleRequest(PathHandler.java:94) at io.undertow.server.handlers.HttpContinueAcceptingHandler.handleRequest(HttpContinueAcceptingHandler.java:83) at org.restheart.handlers.ErrorHandler.handleRequest(ErrorHandler.java:70) at io.undertow.server.handlers.encoding.EncodingHandler.handleRequest(EncodingHandler.java:66) at org.restheart.handlers.GzipEncodingHandler.handleRequest(GzipEncodingHandler.java:75) at io.undertow.server.Connectors.executeRootHandler(Connectors.java:336) at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:748)Second kind of exception:
07:10:49.565 [XNIO-1 task-14] ERROR org.restheart.handlers.ErrorHandler - Error handling the request java.lang.IllegalStateException: UT000139: Exchange already complete at io.undertow.server.HttpServerExchange.addExchangeCompleteListener(HttpServerExchange.java:941) at org.restheart.handlers.RequestLoggerHandler.addExchangeCompleteListener(RequestLoggerHandler.java:168) at org.restheart.handlers.RequestLoggerHandler.dumpExchange(RequestLoggerHandler.java:164) at org.restheart.handlers.RequestLoggerHandler.handleRequest(RequestLoggerHandler.java:80) at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:121) at org.restheart.handlers.MetricsInstrumentationHandler.handleRequest(MetricsInstrumentationHandler.java:65) at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:121) at org.restheart.handlers.injectors.RequestContextInjectorHandler.handleRequest(RequestContextInjectorHandler.java:665) at org.restheart.handlers.injectors.RequestContextInjectorHandler.handleRequest(RequestContextInjectorHandler.java:670) at io.undertow.server.handlers.PathHandler.handleRequest(PathHandler.java:94) at io.undertow.server.handlers.HttpContinueAcceptingHandler.handleRequest(HttpContinueAcceptingHandler.java:83) at org.restheart.handlers.ErrorHandler.handleRequest(ErrorHandler.java:70) at io.undertow.server.handlers.encoding.EncodingHandler.handleRequest(EncodingHandler.java:66) at org.restheart.handlers.GzipEncodingHandler.handleRequest(GzipEncodingHandler.java:75) at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360) at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:748)What we have done to further analyze these errors is patching the MetricsInstrumentationHandler based on current master branch to get some more logging in this cases. As this patch should not be needed when #298 is done, I won't provide a PR here, but just paste the diff.
logging-patch.txt
As you can see, the only goal was to provide logging in this cases so we can analyze which requests run into this errors. What we've found out is, that
We've never seen this happen on any other collection than assets.files or with another request method than GET. This of course is just what we've seen and does not mean this can't ever happen in other cases.
Further we noticed this errors more often when pushing data in parallel to restheart (8 threads). But we also have seen this error when pushing data single threaded, but this is a really really really rare case. So paralelism increases the chance to get this error but may not be the root cause.
As we have seen so far the client does not run into any errors and all request are responded as expected, mostly with HTTP 200 OK. So this does not crash anything or produce errors on client side. But the effect might be, that either logging is missing or metrics for these requests are not collected.
Expected Behavior
No errors. ;)
Current Behavior
See above.
Context
Can't provide any more details here, this seems to be quite a general thing.
Environment
Happens using restheart 3.3.1, 3.3.9, 3.4.0 and current master 3.5.0-SNAPSHOT.
Steps to Reproduce
Unfortunately there is no 'safe way' to reproduce this error. Just push assets using multiple threads. We do not have a separate test case or script to reproduce this issue, it just happens in day to day life using our application.