| Summary: | Bogus access log entries with status 503 and date in year 1970 (the epoch) when pausing NIO connector | ||
|---|---|---|---|
| Product: | Tomcat 8 | Reporter: | Konstantin Kolinko <knst.kolinko> |
| Component: | Catalina | Assignee: | Tomcat Developers Mailing List <dev> |
| Status: | RESOLVED FIXED | ||
| Severity: | minor | ||
| Priority: | P2 | ||
| Version: | 8.0.8 | ||
| Target Milestone: | ---- | ||
| Hardware: | PC | ||
| OS: | All | ||
| Attachments: |
2014-06-13_tc8_56620_debug.patch
access_log.2014-06-13 TEST-org.apache.jasper.compiler.TestGenerator.NIO.txt |
||
Created attachment 31711 [details]
2014-06-13_tc8_56620_debug.patch
Debug logging statement for AbstractAccessLogValve, as mentioned in description.
Not for production.
Created attachment 31712 [details]
access_log.2014-06-13
Access log file from the test run, demonstrating the issue
Created attachment 31713 [details]
TEST-org.apache.jasper.compiler.TestGenerator.NIO.txt
Test log file from the test run, demonstrating the issue
Testing org.apache.coyote.http11.TestInternalInputBuffer + test.accesslog=true Its "testNewLinesExcessive" test generates an error 400 entry with bogus date. 127.0.0.1 - - [01/Jan/1970:02:59:59 +0300] "-" 400 - null 0 I was just about to close this when you posted the additional issue. I've modified the fix so it is more general and should fix all cases of request start times back in the 1970's. This is fixed in 8.0.x for 8.0.9 onwards and in 7.0.x for 7.0.55 onwards. Looks good. For a record: Processing time for HTTP connectors is now measured starting from when the first byte of the next request is read. (r1602956) The old implementation measured it starting from when the whole HTTP request line was read. I think the new implementation is the correct one. I am just noting it here, as sometimes people ask on the users mailing list about how the timing is measured. In any case I expect that for usual requests the difference between the two implementations is rather small. |
This issue is reproducible with the current trunk (@1602359), plus I added the following lines to AbstractAccessLogValve.log() after line 630, to help me debug this issue: [[[ long start = request.getCoyoteRequest().getStartTime(); + if (start == -1) { + // Request processing has not started yet + log.warn("Unexpected timestamp", new Throwable()); + } Date date = getDate(start + time); ]]] To reproduce, run "org.apache.jasper.compiler.TestGenerator" test with access log being enabled. Run it with NIO connector. I use the following configuration in build.properties: [[[ test.accesslog=true test.entry=org.apache.jasper.compiler.TestGenerator ]]] Depending on your luck, there will be one or several of the following lines in access_log.$DATE file produced by the tests: [[[ 127.0.0.1 - - [01/Jan/1970:02:59:59 +0300] "-" 503 - null 0 ]]] The entry is bogus, as in this particular test there is one request per test asking for a JSP page. Those requests are processed and properly logged. Thanks to the log.warn patch above it logs the following stacktrace: [[[ 13-Jun-2014 15:01:37.441 WARNING [http-nio-127.0.0.1-auto-2-exec-1] org.apache.catalina.valves.AbstractAccessLogValve.log Unexpected timestamp java.lang.Throwable at org.apache.catalina.valves.AbstractAccessLogValve.log(AbstractAccessLogValve.java:633) at org.apache.catalina.core.AccessLogAdapter.log(AccessLogAdapter.java:51) at org.apache.catalina.core.StandardEngine.logAccess(StandardEngine.java:342) at org.apache.catalina.connector.CoyoteAdapter.log(CoyoteAdapter.java:674) at org.apache.coyote.http11.Http11NioProcessor.handleIncompleteRequestLineRead(Http11NioProcessor.java:240) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:992) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:655) at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1565) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1522) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:745) ]]] The issue is that logging is invoked at org.apache.coyote.http11.Http11NioProcessor.handleIncompleteRequestLineRead(Http11NioProcessor.java:240) As that time Tomcat runs a keep-alive loop, and the loop is interrupted because connector is paused. Expected behaviour ------------------- 1. If none characters from the request line have been read, then do not log anything. There was no request coming. 2. If some characters from the request line have been read, then create an access log entry, but one must call req.setStartTime() to initialize the tine value. In "2." the request line will be truncated, but there might be some (though small) worth in logging it.