On 18/03/2015 13:52, Rainer Jung wrote: > 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)
There are various tests that appear to have issues at the moment. Now I've cleared the Bugzilla backlog ready for the next 8.0.x release I plan to spend some time on the CI systems. One of the things I want to do is move the BuildBot builds to a less loaded slave. That should result in reduced run times for the builds. Mark > > > (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: [email protected] > For additional commands, e-mail: [email protected] > --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
