Hi Dan,
Am 2016-12-25 um 19:51 schrieb Dan Tran:
Just want to confirm, your FreeBSD and build.apache.org's ubuntu see the
same test failure??
Do you think we should cancel the vote and wait for your fix?
I was finally able to complete my coding and testings. After several
hours of testing and debugging, I've found the reasons why several tests
were failing sporadically, some were bad test conditions
(testSecuredGet(), testSecuredGetToStream()) and some rooted in bugs in
HttpWagon. I'll go in detail:
1. Flaky testSecuredGet(ToStream):
This failed once in a while due to race conditions between Jetty's qtp
threads and the main thread running the tests and the assertions. Jetty
did not fully complete the process chain while Surefire continued to
verify the result. This yielded to: expected <2> requests found <1> and
so forth. I added a simple sleep() and it did work. I avoided to have
complex sync code with CountDownLatch or alike. Some logging added to
the code shows the following in Surefire's XML output:
<failure message="not 2 security handler use [HandlerRequestResponse{method='GET', responseCode=401,
requestUri='/test-secured-resource'}] expected:<2> but was:<1>"
type="junit.framework.AssertionFailedError"><![CDATA[junit.framework.AssertionFailedError: not 2 security handler use
[HandlerRequestResponse{method='GET', responseCode=401, requestUri='/test-secured-resource'}] expected:<2> but was:<1>
at junit.framework.Assert.fail(Assert.java:57)
at junit.framework.Assert.failNotEquals(Assert.java:329)
at junit.framework.Assert.assertEquals(Assert.java:78)
at junit.framework.Assert.assertEquals(Assert.java:234)
at junit.framework.TestCase.assertEquals(TestCase.java:401)
at
org.apache.maven.wagon.http.HttpWagonTestCase.testPreemptiveAuthentication(HttpWagonTestCase.java:1910)
at
org.apache.maven.wagon.http.HttpWagonTestCase.testPreemptiveAuthenticationGet(HttpWagonTestCase.java:1891)
at
org.apache.maven.wagon.http.HttpWagonTestCase.runTestSecuredGetToStream(HttpWagonTestCase.java:1409)
at
org.apache.maven.wagon.http.HttpWagonTestCase.testSecuredGetToStream(HttpWagonTestCase.java:1374)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at junit.framework.TestCase.runTest(TestCase.java:176)
at junit.framework.TestCase.runBare(TestCase.java:141)
at junit.framework.TestResult$1.protect(TestResult.java:122)
at junit.framework.TestResult.runProtected(TestResult.java:142)
at junit.framework.TestResult.run(TestResult.java:125)
at junit.framework.TestCase.run(TestCase.java:129)
at junit.framework.TestSuite.runTest(TestSuite.java:255)
at junit.framework.TestSuite.run(TestSuite.java:250)
at
org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:84)
at
org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:283)
at
org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:173)
at
org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
at
org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:128)
at
org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:203)
at
org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:155)
at
org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
]]></failure>
now the logging:
<system-err><![CDATA[[main] INFO org.eclipse.jetty.server.Server -
jetty-8.1.22.v20160922
[main] INFO org.eclipse.jetty.server.AbstractConnector - Started
SelectChannelConnector@0.0.0.0:45658
[main] DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec
selected: compatibility
[main] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager -
Connection request: [route: {}->http://localhost:45658][total kept alive: 39;
route allocated: 0 of 20; total allocated: 39 of 40]
[main] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager -
Connection leased: [id: 86][route: {}->http://localhost:45658][total kept
alive: 39; route allocated: 1 of 20; total allocated: 40 of 40]
[main] DEBUG org.apache.http.impl.execchain.MainClientExec - Opening connection
{}->http://localhost:45658
[main] DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator -
Connecting to localhost/127.0.0.1:45658
[main] DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator -
Connection established 127.0.0.1:45659<->127.0.0.1:45658
[main] DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection -
http-outgoing-86: set socket timeout to 1800000
[main] DEBUG org.apache.http.impl.execchain.MainClientExec - Executing request
GET /test-secured-resource HTTP/1.1
[main] DEBUG org.apache.http.impl.execchain.MainClientExec - Target auth state:
UNCHALLENGED
[main] DEBUG org.apache.http.impl.execchain.MainClientExec - Proxy auth state:
UNCHALLENGED
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> GET
/test-secured-resource HTTP/1.1
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Cache-control:
no-cache
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Cache-store: no-store
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Pragma: no-cache
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Expires: 0
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Accept-Encoding: gzip
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Host: localhost:45658
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Connection:
Keep-Alive
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> User-Agent:
Apache-HttpClient/4.5.2 (Java/1.7.0_111)
[main] DEBUG org.apache.http.headers - http-outgoing-86 << HTTP/1.1 401
Unauthorized
[main] DEBUG org.apache.http.headers - http-outgoing-86 << WWW-Authenticate: basic
realm="MyRealm"
[main] DEBUG org.apache.http.headers - http-outgoing-86 << Cache-Control:
must-revalidate,no-cache,no-store
[main] DEBUG org.apache.http.headers - http-outgoing-86 << Content-Type:
text/html;charset=ISO-8859-1
[main] DEBUG org.apache.http.headers - http-outgoing-86 << Content-Length: 1311
[main] DEBUG org.apache.http.headers - http-outgoing-86 << Server:
Jetty(8.1.22.v20160922)
[main] DEBUG org.apache.http.impl.execchain.MainClientExec - Connection can be
kept alive indefinitely
[main] DEBUG org.apache.http.impl.auth.HttpAuthenticator - Authentication
required
[main] DEBUG org.apache.http.impl.auth.HttpAuthenticator - localhost:45658
requested authentication
[main] DEBUG org.apache.http.impl.client.TargetAuthenticationStrategy -
Authentication schemes in the order of preference: [Negotiate, Kerberos, NTLM,
Digest, Basic]
[main] DEBUG org.apache.http.impl.client.TargetAuthenticationStrategy -
Challenge for Negotiate authentication scheme not available
[main] DEBUG org.apache.http.impl.client.TargetAuthenticationStrategy -
Challenge for Kerberos authentication scheme not available
[main] DEBUG org.apache.http.impl.client.TargetAuthenticationStrategy -
Challenge for NTLM authentication scheme not available
[main] DEBUG org.apache.http.impl.client.TargetAuthenticationStrategy -
Challenge for Digest authentication scheme not available
[main] DEBUG org.apache.http.impl.auth.HttpAuthenticator - Selected
authentication options: [BASIC [complete=true]]
[main] DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection -
http-outgoing-86: set socket timeout to 1800000
[main] DEBUG org.apache.http.impl.execchain.MainClientExec - Executing request
GET /test-secured-resource HTTP/1.1
[main] DEBUG org.apache.http.impl.execchain.MainClientExec - Target auth state:
CHALLENGED
[main] DEBUG org.apache.http.impl.auth.HttpAuthenticator - Generating response
to an authentication challenge using basic scheme
[main] DEBUG org.apache.http.impl.execchain.MainClientExec - Proxy auth state:
UNCHALLENGED
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> GET
/test-secured-resource HTTP/1.1
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Cache-control:
no-cache
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Cache-store: no-store
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Pragma: no-cache
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Expires: 0
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Accept-Encoding: gzip
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Host: localhost:45658
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Connection:
Keep-Alive
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> User-Agent:
Apache-HttpClient/4.5.2 (Java/1.7.0_111)
[main] DEBUG org.apache.http.headers - http-outgoing-86 >> Authorization: Basic
dXNlcjpzZWNyZXQ=
org.apache.maven.wagon.http.HttpWagonTestCase$TestSecurityHandler@9187167
(count 1): handled GET /test-secured-resource with status 401
[main] DEBUG org.apache.http.headers - http-outgoing-86 << HTTP/1.1 200 OK
[main] DEBUG org.apache.http.headers - http-outgoing-86 << Accept-Ranges: bytes
[main] DEBUG org.apache.http.headers - http-outgoing-86 << Content-Length: 10
[main] DEBUG org.apache.http.headers - http-outgoing-86 << Last-Modified: Mon,
26 Dec 2016 23:07:55 GMT
[main] DEBUG org.apache.http.headers - http-outgoing-86 << Server:
Jetty(8.1.22.v20160922)
[main] DEBUG org.apache.http.impl.execchain.MainClientExec - Connection can be
kept alive indefinitely
[main] DEBUG org.apache.http.impl.auth.HttpAuthenticator - Authentication
succeeded
[main] DEBUG org.apache.http.impl.client.TargetAuthenticationStrategy - Caching
'basic' auth scheme for http://localhost:45658
[main] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager -
Connection [id: 86][route: {}->http://localhost:45658] can be kept alive
indefinitely
[main] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager -
Connection released: [id: 86][route: {}->http://localhost:45658][total kept
alive: 40; route allocated: 1 of 20; total allocated: 40 of 40]
org.apache.maven.wagon.http.HttpWagonTestCase$TestSecurityHandler@9187167 (1)
org.apache.maven.wagon.http.HttpWagonTestCase$TestSecurityHandler@9187167
(count 2): handled GET /test-secured-resource with status 200
[main] INFO org.eclipse.jetty.server.handler.ContextHandler - stopped
o.e.j.s.ServletContextHandler{/,file:/usr/home/mosipov/Projekte/maven-wagon/wagon-providers/wagon-http/target/test-output/}
]]></system-err>
now take a look at TestSecurityHandler output. I added it after
super.handle() called by Jetty. As you can see,
"org.apache.maven.wagon.http.HttpWagonTestCase$TestSecurityHandler@9187167
(1)" is printed where the assertions kick in, after Wagon has completed,
but the second request is handled afterwards. A traditional race condition.
2. Bugs found:
Several auth tests fail for no reason too once in a while. Logging
showed me that HttpClient simply did not send any Basic data, regardless
if preemptive or after a roundtrip. The basic problem was that
non-threadsafe classes have been used in a non-threadsafe manner as well
as auth caches have not beed released properly, and preemptive auth was
configured incorrectly. After fixing the issues one by one, the tests
never failed again.
I have tested the code on three platforms and six JDK versions tens of
times, they never failed again. After we have resolved your
HugeDowloadTest issue and no one else objects, I'd like to merge this
into master and like you to reroll 2.11 with those changes.
Meanwhile, I'll test this branch with Maven Core IT Suite too.
Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@maven.apache.org
For additional commands, e-mail: dev-h...@maven.apache.org