Just a heads up: Trunk, TC 8 and TC 7 fail on Gump for various
connectors sporadically at
Testcase: testBug57621 took 3.145 sec
FAILED
null
junit.framework.AssertionFailedError
at
org.apache.coyote.http11.TestAbstractHttp11Processor.testBug57621(TestAbstractHttp11Processor.java:796)
(line number for TC 7).
I don't see any obvious timing params in that test.
The test fails when doing the second call of the test client and
checking for a 200 status code. I can reproduce locally at least for TC
7 and trunk (haven't tried tc 8). Here is some log output. First TC 7 data:
APR:
Failed 1/20 runs.
The access log entries are:
127.0.0.1 - - [18/Mar/2015:13:15:51 +0100] "PUT /test HTTP/1.1" 200 2
http-apr-127.0.0.1-auto-7-exec-4 999
127.0.0.1 - - [18/Mar/2015:13:15:52 +0100] "-" 400 - null 0
so the first request takes a second and then the second request is being
logged with a 400.
The test log contains:
Mar 18, 2015 1:15:50 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler register
FINE: Register
Tomcat:type=RequestProcessor,worker="http-apr-127.0.0.1-auto-7-38664",name=HttpRequest1
Mar 18, 2015 1:15:50 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@83e5f1:6522256], Status
in: [OPEN_READ], State out: [LONG]
Mar 18, 2015 1:15:51 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@83e5f1:6522256], Status
in: [OPEN_READ], State out: [ASYNC_END]
and then probably for the second request
Mar 18, 2015 1:15:51 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@83e5f1:6522256], Status
in: [OPEN_READ], State out: [OPEN]
Mar 18, 2015 1:15:52 PM org.apache.coyote.http11.AbstractHttp11Processor
process
INFO: Error parsing HTTP request header
Note: further occurrences of HTTP header parsing errors will be logged
at DEBUG level.
Mar 18, 2015 1:15:52 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@83e5f1:6522256], Status
in: [OPEN_READ], State out: [CLOSED]
The message "INFO: Error parsing HTTP request header" does not show up
when the test succeeds.
The succeeding runs log
127.0.0.1 - - [18/Mar/2015:13:26:13 +0100] "PUT /test HTTP/1.1" 200 2
http-apr-127.0.0.1-auto-7-exec-4 999
127.0.0.1 - - [18/Mar/2015:13:26:14 +0100] "PUT /test HTTP/1.1" 200 2
http-apr-127.0.0.1-auto-7-exec-7 995
and
Mar 18, 2015 1:26:12 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-apr-127.0.0.1-auto-7-39423"]
Mar 18, 2015 1:26:12 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler register
FINE: Register
Tomcat:type=RequestProcessor,worker="http-apr-127.0.0.1-auto-7-39423",name=HttpRequest1
Mar 18, 2015 1:26:12 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1e9f5cc:1905808],
Status in: [OPEN_READ], State out: [LONG]
Mar 18, 2015 1:26:13 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1e9f5cc:1905808],
Status in: [OPEN_READ], State out: [ASYNC_END]
Mar 18, 2015 1:26:13 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1e9f5cc:1905808],
Status in: [OPEN_READ], State out: [OPEN]
Mar 18, 2015 1:26:13 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1e9f5cc:1905808],
Status in: [OPEN_READ], State out: [LONG]
Mar 18, 2015 1:26:14 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1e9f5cc:1905808],
Status in: [OPEN_READ], State out: [ASYNC_END]
Mar 18, 2015 1:26:14 PM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["http-apr-127.0.0.1-auto-7-39423"]
Mar 18, 2015 1:26:14 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1e9f5cc:1905808],
Status in: [OPEN_READ], State out: [OPEN]
Mar 18, 2015 1:26:14 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1e9f5cc:1905808],
Status in: [OPEN_READ], State out: [CLOSED]
Mar 18, 2015 1:26:14 PM org.apache.catalina.core.StandardService
stopInternal
INFO: Stopping service Tomcat
NIO:
Failed 20/20.
access log:
127.0.0.1 - - [18/Mar/2015:13:26:53 +0100] "PUT /test HTTP/1.1" 200 2
http-nio-127.0.0.1-auto-7-exec-3 998
127.0.0.1 - - [18/Mar/2015:13:26:54 +0100] "-" 400 - null 0
test log
Mar 18, 2015 1:26:52 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler register
FINE: Register
Tomcat:type=RequestProcessor,worker="http-nio-127.0.0.1-auto-7-39480",name=HttpRequest1
Mar 18, 2015 1:26:52 PM org.apache.coyote.http11.InternalNioInputBuffer
parseRequestLine
FINE: Received [PUT http://localhost:8080/test HTTP/1.1^M
Transfer-encoding: chunked^M
^M
2^M
OK]
Mar 18, 2015 1:26:52 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@1f52460:org.apache.tomcat.util.net.NioChannel@129c445:java.nio.channels.SocketChannel[connected
local=/127.0.0.1:39480 remote=/127.0.0.1:39481]], Status in:
[OPEN_READ], State out: [LONG]
Mar 18, 2015 1:26:53 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@1f52460:org.apache.tomcat.util.net.NioChannel@129c445:java.nio.channels.SocketChannel[connected
local=/127.0.0.1:39480 remote=/127.0.0.1:39481]], Status in:
[OPEN_READ], State out: [ASYNC_END]
Mar 18, 2015 1:26:53 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@1f52460:org.apache.tomcat.util.net.NioChannel@129c445:java.nio.channels.SocketChannel[connected
local=/127.0.0.1:39480 remote=/127.0.0.1:39481]], Status in:
[OPEN_READ], State out: [OPEN]
Mar 18, 2015 1:26:54 PM org.apache.coyote.http11.InternalNioInputBuffer
parseRequestLine
FINE: Received [0^M
^M
]
Mar 18, 2015 1:26:54 PM org.apache.coyote.http11.AbstractHttp11Processor
process
INFO: Error parsing HTTP request header
Note: further occurrences of HTTP header parsing errors will be logged
at DEBUG level.
Mar 18, 2015 1:26:54 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@1f52460:org.apache.tomcat.util.net.NioChannel@129c445:java.nio.channels.SocketChannel[connected
local=/127.0.0.1:39480 remote=/127.0.0.1:39481]], Status in:
[OPEN_READ], State out: [CLOSED]
Mar 18, 2015 1:26:54 PM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["http-nio-127.0.0.1-auto-7-39480"]
Mar 18, 2015 1:26:54 PM org.apache.catalina.core.StandardService
stopInternal
INFO: Stopping service Tomcat
Mar 18, 2015 1:26:54 PM org.apache.catalina.loader.WebappClassLoader
clearReferencesThreads
SEVERE: The web application [] appears to have started a thread named
[http-nio-127.0.0.1-auto-7-exec-3] but has failed to stop it. This is
very likely to create a memory leak.
Mar 18, 2015 1:26:54 PM org.apache.coyote.AbstractProtocol stop
BIO:
Failed 1/20
access log
127.0.0.1 - - [18/Mar/2015:13:48:51 +0100] "PUT /test HTTP/1.1" 200 2
http-bio-127.0.0.1-auto-7-exec-3 1002
127.0.0.1 - - [18/Mar/2015:13:48:52 +0100] "-" 400 - null 0
successful test:
127.0.0.1 - - [18/Mar/2015:13:49:29 +0100] "PUT /test HTTP/1.1" 200 2
http-bio-127.0.0.1-auto-7-exec-3 999
127.0.0.1 - - [18/Mar/2015:13:49:30 +0100] "PUT /test HTTP/1.1" 200 2
http-bio-127.0.0.1-auto-7-exec-6 997
test log:
Mar 18, 2015 1:48:50 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler register
FINE: Register
Tomcat:type=RequestProcessor,worker="http-bio-127.0.0.1-auto-7-41703",name=HttpRequest1
Mar 18, 2015 1:48:50 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@ad5fab:Socket[addr=/127.0.0.1,port=41704,localport=41703]],
Status in: [OPEN_READ], State out: [LONG]
Mar 18, 2015 1:48:51 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@ad5fab:Socket[addr=/127.0.0.1,port=41704,localport=41703]],
Status in: [OPEN_READ], State out: [ASYNC_END]
Mar 18, 2015 1:48:51 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@ad5fab:Socket[addr=/127.0.0.1,port=41704,localport=41703]],
Status in: [OPEN_READ], State out: [OPEN]
Mar 18, 2015 1:48:52 PM org.apache.coyote.http11.AbstractHttp11Processor
process
INFO: Error parsing HTTP request header
Note: further occurrences of HTTP header parsing errors will be logged
at DEBUG level.
Mar 18, 2015 1:48:52 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@ad5fab:Socket[addr=/127.0.0.1,port=41704,localport=41703]],
Status in: [OPEN_READ], State out: [CLOSED]
successful run
Mar 18, 2015 1:49:28 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler register
FINE: Register
Tomcat:type=RequestProcessor,worker="http-bio-127.0.0.1-auto-7-41762",name=HttpRequest1
Mar 18, 2015 1:49:28 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@e1eae7:Socket[addr=/127.0.0.1,port=41763,localport=41762]],
Status in: [OPEN_READ], State out: [LONG]
Mar 18, 2015 1:49:29 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@e1eae7:Socket[addr=/127.0.0.1,port=41763,localport=41762]],
Status in: [OPEN_READ], State out: [ASYNC_END]
Mar 18, 2015 1:49:29 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@e1eae7:Socket[addr=/127.0.0.1,port=41763,localport=41762]],
Status in: [OPEN_READ], State out: [OPEN]
Mar 18, 2015 1:49:29 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@e1eae7:Socket[addr=/127.0.0.1,port=41763,localport=41762]],
Status in: [OPEN_READ], State out: [LONG]
Mar 18, 2015 1:49:30 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@e1eae7:Socket[addr=/127.0.0.1,port=41763,localport=41762]],
Status in: [OPEN_READ], State out: [ASYNC_END]
Mar 18, 2015 1:49:30 PM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["http-bio-127.0.0.1-auto-7-41762"]
Mar 18, 2015 1:49:30 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@e1eae7:Socket[addr=/127.0.0.1,port=41763,localport=41762]],
Status in: [OPEN_READ], State out: [OPEN]
Mar 18, 2015 1:49:30 PM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
FINE: Socket:
[org.apache.tomcat.util.net.SocketWrapper@e1eae7:Socket[addr=/127.0.0.1,port=41763,localport=41762]],
Status in: [OPEN_READ], State out: [CLOSED]
Mar 18, 2015 1:49:30 PM org.apache.catalina.core.StandardService
stopInternal
INFO: Stopping service Tomcat
For trunk I checked nio (1/20) and nio2 (3/20). access log looks like
for tc 7, test output for nio:
18-Mar-2015 14:33:20.122 FINE [http-nio-127.0.0.1-auto-7-exec-1]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.register
Register
Tomcat:type=RequestProcessor,worker="http-nio-127.0.0.1-auto-7-42822",name=HttpRequest1
18-Mar-2015 14:33:20.124 FINE [http-nio-127.0.0.1-auto-7-exec-1]
org.apache.coyote.http11.Http11InputBuffer.parseRequestLine Received
[PUT http://localhost:8080/test HTTP/1.1^M
Transfer-encoding: chunked^M
^M
2^M
OK]
18-Mar-2015 14:33:20.136 FINE [http-nio-127.0.0.1-auto-7-exec-1]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@38828697:org.apache.tomcat.util.net.NioChannel@327aede7:java.nio.channels.SocketChannel[connected
local=/127.0.0.1:42822 remote=/127.0.0.1:42823]], Status in:
[OPEN_READ], State out: [LONG]
18-Mar-2015 14:33:21.120 FINE [http-nio-127.0.0.1-auto-7-exec-3]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@38828697:org.apache.tomcat.util.net.NioChannel@327aede7:java.nio.channels.SocketChannel[connected
local=/127.0.0.1:42822 remote=/127.0.0.1:42823]], Status in:
[OPEN_READ], State out: [ASYNC_END]
18-Mar-2015 14:33:21.124 FINE [http-nio-127.0.0.1-auto-7-exec-3]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@38828697:org.apache.tomcat.util.net.NioChannel@327aede7:java.nio.channels.SocketChannel[connected
local=/127.0.0.1:42822 remote=/127.0.0.1:42823]], Status in:
[OPEN_READ], State out: [OPEN]
18-Mar-2015 14:33:22.121 FINE [http-nio-127.0.0.1-auto-7-exec-4]
org.apache.coyote.http11.Http11InputBuffer.parseRequestLine Received [0^M
^M
]
18-Mar-2015 14:33:22.125 INFO [http-nio-127.0.0.1-auto-7-exec-4]
org.apache.coyote.http11.Http11Processor.process Error parsing HTTP
request header
Note: further occurrences of HTTP header parsing errors will be logged
at DEBUG level.
18-Mar-2015 14:33:22.132 FINE [http-nio-127.0.0.1-auto-7-exec-4]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@38828697:org.apache.tomcat.util.net.NioChannel@327aede7:java.nio.channels.SocketChannel[connected
local=/127.0.0.1:42822 remote=/127.0.0.1:42823]], Status in:
[OPEN_READ], State out: [CLOSED]
18-Mar-2015 14:33:22.135 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio-127.0.0.1-auto-7-42822"]
and for nio2:
18-Mar-2015 14:41:31.897 FINE [http-nio2-127.0.0.1-auto-7-exec-1]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.register
Register
Tomcat:type=RequestProcessor,worker="http-nio2-127.0.0.1-auto-7-43496",name=HttpRequest1
18-Mar-2015 14:41:31.899 FINE [http-nio2-127.0.0.1-auto-7-exec-1]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@36761f61:org.apache.tomcat.util.net.Nio2Channel@3c8e7411:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:43496 remote=/127.0.0.1:43497]], Status in:
[OPEN_READ], State out: [LONG]
18-Mar-2015 14:41:31.902 FINE [http-nio2-127.0.0.1-auto-7-exec-2]
org.apache.coyote.http11.Http11InputBuffer.parseRequestLine Received
[PUT http://localhost:8080/test HTTP/1.1^M
Transfer-encoding: chunked^M
^M
2^M
OK]
18-Mar-2015 14:41:31.916 FINE [http-nio2-127.0.0.1-auto-7-exec-2]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@36761f61:org.apache.tomcat.util.net.Nio2Channel@3c8e7411:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:43496 remote=/127.0.0.1:43497]], Status in:
[OPEN_READ], State out: [LONG]
18-Mar-2015 14:41:32.879 FINE [http-nio2-127.0.0.1-auto-7-exec-4]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@36761f61:org.apache.tomcat.util.net.Nio2Channel@3c8e7411:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:43496 remote=/127.0.0.1:43497]], Status in:
[OPEN_READ], State out: [ASYNC_END]
18-Mar-2015 14:41:32.883 FINE [http-nio2-127.0.0.1-auto-7-exec-4]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@36761f61:org.apache.tomcat.util.net.Nio2Channel@3c8e7411:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:43496 remote=/127.0.0.1:43497]], Status in:
[OPEN_READ], State out: [OPEN]
18-Mar-2015 14:41:33.876 FINE [http-nio2-127.0.0.1-auto-7-exec-5]
org.apache.coyote.http11.Http11InputBuffer.parseRequestLine Received [0^M
^M
]
18-Mar-2015 14:41:33.881 INFO [http-nio2-127.0.0.1-auto-7-exec-5]
org.apache.coyote.http11.Http11Processor.process Error parsing HTTP
request header
Note: further occurrences of HTTP header parsing errors will be logged
at DEBUG level.
18-Mar-2015 14:41:33.891 FINE [http-nio2-127.0.0.1-auto-7-exec-5]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@36761f61:org.apache.tomcat.util.net.Nio2Channel@3c8e7411:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:43496 remote=/127.0.0.1:43497]], Status in:
[OPEN_READ], State out: [CLOSED]
18-Mar-2015 14:41:33.894 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio2-127.0.0.1-auto-7-43496"]
Regards,
Rainer
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
