Bug 56620 - Bogus access log entries with status 503 and date in year 1970 (the epoch) when pausing NIO connector
Summary: Bogus access log entries with status 503 and date in year 1970 (the epoch) wh...
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 8.0.8
Hardware: PC All
: P2 minor (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
Depends on:
Reported: 2014-06-13 12:37 UTC by Konstantin Kolinko
Modified: 2014-06-17 15:43 UTC (History)
0 users

2014-06-13_tc8_56620_debug.patch (706 bytes, patch)
2014-06-13 12:40 UTC, Konstantin Kolinko
Details | Diff
access_log.2014-06-13 (1.51 KB, text/plain)
2014-06-13 12:41 UTC, Konstantin Kolinko
TEST-org.apache.jasper.compiler.TestGenerator.NIO.txt (28.11 KB, text/plain)
2014-06-13 12:42 UTC, Konstantin Kolinko

Note You need to log in before you can comment on or make changes to this bug.
Description Konstantin Kolinko 2014-06-13 12:37:17 UTC
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:

Depending on your luck, there will be one or several of the following lines in access_log.$DATE file produced by the tests:
[[[ - - [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-] org.apache.catalina.valves.AbstractAccessLogValve.log Unexpected timestamp
	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

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.
Comment 1 Konstantin Kolinko 2014-06-13 12:40:10 UTC
Created attachment 31711 [details]

Debug logging statement for AbstractAccessLogValve, as mentioned in description.
Not for production.
Comment 2 Konstantin Kolinko 2014-06-13 12:41:27 UTC
Created attachment 31712 [details]

Access log file from the test run, demonstrating the issue
Comment 3 Konstantin Kolinko 2014-06-13 12:42:27 UTC
Created attachment 31713 [details]

Test log file from the test run, demonstrating the issue
Comment 4 Konstantin Kolinko 2014-06-16 11:23:01 UTC
Testing org.apache.coyote.http11.TestInternalInputBuffer + test.accesslog=true
Its "testNewLinesExcessive" test generates an error 400 entry with bogus date. - - [01/Jan/1970:02:59:59 +0300] "-" 400 - null 0
Comment 5 Mark Thomas 2014-06-16 20:00:17 UTC
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.
Comment 6 Konstantin Kolinko 2014-06-17 15:43:36 UTC
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.