https://issues.apache.org/bugzilla/show_bug.cgi?id=56620
Bug ID: 56620
Summary: Bogus access log entries with status 503 and date in
year 1970 (the epoch) when pausing NIO connector
Product: Tomcat 8
Version: 8.0.8
Hardware: PC
Status: NEW
Severity: normal
Priority: P2
Component: Catalina
Assignee: dev@tomcat.apache.org
Reporter: knst.koli...@gmail.com
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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
