Bug 56620 - Bogus access log entries with status 503 and date in year 1970 (the epoch) when pausing NIO connector
Bogus access log entries with status 503 and date in year 1970 (the epoch) wh...
Status: RESOLVED FIXED
Product: Tomcat 8
Classification: Unclassified
Component: Catalina
8.0.8
PC All
: P2 minor (vote)
: ----
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2014-06-13 12:37 UTC by Konstantin Kolinko
Modified: 2014-06-17 15:43 UTC (History)
0 users



Attachments
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
Details
TEST-org.apache.jasper.compiler.TestGenerator.NIO.txt (28.11 KB, text/plain)
2014-06-13 12:42 UTC, Konstantin Kolinko
Details

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

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.2014-06-13

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-org.apache.jasper.compiler.TestGenerator.NIO.txt

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.

127.0.0.1 - - [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.