DispatchingAuthenticator gets mixed up under high concurrency

[rburgst]

DispatchingAuthenticator gets mixed up under high concurrency

[rburgst]

This is correct, the caching prevents the code from being used on multiple threads. The code is definitely not thread safe. If you are using multiple threads, then you would need to create either a synchronous wrapper(which would probably defeat the purpose), or someone needs to rework the code to be thread safe.

[sammefford]

Is this true if I just use DigestAuthenticator directly? I notice that the authenticate method is synchronized. While not ideal from a performance perspective as it might create a contention point, at least it could mean it is thread-safe. Do you know off-hand whether I should still be concerned if I bypass DispatchingAuthenticator and use DigestAuthenticator directly?

[sammefford]

Looks like I'm getting the same warning and failed requests when I just use DigestAuthenticator directly.

[rburgst]

I think the quick fix would be to synchronize authenticateWithState in DigestAuthenticator. Unfortunately I don't have a practical test case where I can easily replicate the problem. If you are willing to provide a unit test, then this would probably be not too hard to fix in a better way.

[rburgst]

BTW, I checked your change in java-client-api and I think that the Dispatcher should be reasonably safe. I dont believe that it causes and problems in a multi threaded environment.

[sammefford]

I added a unit test to demonstrate some issues in a multi-threaded environment. This probably doesn't show all the issues, and I'm not even sure it shows the one I'm encountering. It just takes the existing digest unit tests and runs them multi-threaded. I loosened up a few of the tests so they don't expect nc to be 0000001 when it is likely higher when multi-threaded. That way those tests can pass so we can focus on the ones that fail because of a problem in the core code.

[rburgst]

The test is misleading as you are calling all test methods (which share the same instance variables) at the same time. This is not really a realistic scenario. All this shows is that the tests were not written with concurrency in mind (nor would this be useful). We would need a test that attempts a similar approach as you are using in your production code. However, I am not sure how we can get that to work without having a mockhttpserver in place that responds somewhat reasonably.

Is there a way where we can create a test (at least to analyze the problem better) which simulates your app behaviour? I.e. multithreaded download requests. I do have a server at hand that I could configure and run the tests against.

[sammefford]

I think it's important to note that I'm creating an API that interfaces with a database. So I don't have one production environment, I have an API used in hundreds of production envs. This API could be used in any production env: J2EE app servers, Spring Boot, Hadoop, Storm, Android, etc. The Stress test where I first duplicated the issues is overly complicated to share. You may be right that the interaction of instance variables in the test I shared is distracting in the example I gave. I'll try to find time to create another test.

[sammefford]

Ok, I removed all but the necessary shared instance variables. I believe it makes sense to share the Route and DigestAuthenticator as those are likely to be shared in an application. The DigestAuthenticator, in particular, is the thing we need to support multi-threaded invocation. It will be used by one OkHttpClient instance which will be accessed by many concurrent threads which need to authenticate different users simultaneously. While the OkHttpClient uses an underlying ConnectionPool to support these high-volume multi-threaded requests, I'm thinking that doesn't affect the use of a single DigestAuthenticator.

[rburgst]

Hi, thanks a lot for your work. I see that most of the tests fail because their expectations are no longer met. The expectations dont factor in that the nonce count will change. Therefore, I fear the tests dont really show the problem.

Would it be possible for you to share logs of a configured network level HttpLoggingInterceptor maybe I can set up a test here that recreates a somewhat similar situation as you are experiencing.

[sammefford]

Ok, you're right. I knew those would distract so I tried to loosen all those match assertions, but it looks like I missed two. I've pushed an update so those won't distract. I believe the following error is not a test bug. In other words, the behavior of DigestAuthenticator is different when run in a multi-threaded env vs single-threaded env. Here's what I'm seeing on STDERR:

Jul 11, 2017 9:26:47 AM okhttp3.internal.platform.Platform log
WARNING: previous digest authentication with same nonce failed, returning null
Test testAuthenticate_withWrongPassword_shouldNotRepeat failed under testMultithreadedAuthenticate:
java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at com.burgstaller.okhttp.digest.DigestAuthenticatorTest$1.run(DigestAuthenticatorTest.java:309)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.AssertionError: 
Expected: is null
     but: was <Request{method=GET, url=http://www.google.com/, tag=Request{method=GET, url=http://www.google.com/, tag=null}}>
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
	at org.junit.Assert.assertThat(Assert.java:956)
	at org.junit.Assert.assertThat(Assert.java:923)
	at com.burgstaller.okhttp.digest.DigestAuthenticatorTest.testAuthenticate_withWrongPassword_shouldNotRepeat(DigestAuthenticatorTest.java:216)
	... 8 more

I get similar errors sometimes from testAuthenticate__withProxy__shouldWork and testAuthenticate_withDifferentNonce_shouldNotRetry. I don't always see the "WARNING: previous digest authentication with same nonce failed, returning null" although I was seeing that pretty consistently in the output from my failing stress test.

[sammefford]

In case it helps, here are two examples of when the others fail:

Test testAuthenticate_withDifferentNonce_shouldNotRetry failed under testMultithreadedAuthenticate:
java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at com.burgstaller.okhttp.digest.DigestAuthenticatorTest$1.run(DigestAuthenticatorTest.java:309)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.AssertionError: 
Expected: is null
     but: was <Request{method=GET, url=http://www.google.com/, tag=Request{method=GET, url=http://www.google.com/, tag=null}}>
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
	at org.junit.Assert.assertThat(Assert.java:956)
	at org.junit.Assert.assertThat(Assert.java:923)
	at com.burgstaller.okhttp.digest.DigestAuthenticatorTest.testAuthenticate_withDifferentNonce_shouldNotRetry(DigestAuthenticatorTest.java:241)
	... 8 more
Test testAuthenticate__withProxy__shouldWork failed under testMultithreadedAuthenticate:
java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at com.burgstaller.okhttp.digest.DigestAuthenticatorTest$1.run(DigestAuthenticatorTest.java:309)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.AssertionError: 
Expected: a string matching the pattern 'Digest username="user1", realm="myrealm", nonce="NnjGCdMhBQA=8ede771f94b593e46e5d0dd10b68313226c133f4", uri="/", response="[0-9a-f]+", qop=auth, nc=00000001, cnonce="[0-9a-f]+", algorithm=MD5'
     but: was "Digest username=\"user1\", realm=\"myrealm\", nonce=\"NnjGCdMhBQA=8ede771f94b593e46e5d0dd10b68313226c133f4\", uri=\"/\", response=\"0222dac12825f93e1697e8cb34cb5ece\", qop=auth, nc=00000002, cnonce=\"0f9866728b5cd1fc\", algorithm=MD5"
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
	at org.junit.Assert.assertThat(Assert.java:956)
	at org.junit.Assert.assertThat(Assert.java:923)
	at com.burgstaller.okhttp.digest.DigestAuthenticatorTest.testAuthenticate__withProxy__shouldWork(DigestAuthenticatorTest.java:98)
	... 8 more

[sammefford]

Ok, it appears that the problem lies in the shared "parameters" variable. IIUC, that parameter was intended to be used for caching, but isn't actually since authenticateWithState goes ahead and calls createDigestHeader anyway for every request. I'm not 100% positive about this change, but all the unit tests pass when I run "gradle test". Could you take a look?

[sammefford]

I re-ran my stress tests today with this change in place, and I don't see the issues anymore. So I'm submitting PR #35 for your review.