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=&apos;GET&apos;, responseCode=401, 
requestUri=&apos;/test-secured-resource&apos;}] expected:&lt;2&gt; but was:&lt;1&gt;" 
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

Reply via email to