MockWebServer tests got stuck after updating from 3.9.1 to 3.10.0

[Guardiola31337]

After updating from 3.9.1 to 3.10.0 mockwebserver tests got stuck.

This is how I configure the HttpClient (I'm setting up HTTPS and Certificate Pinning ) 👀

private OkHttpClient configureHttpClient() {
    CertificatePinnerFactory factory = new CertificatePinnerFactory();
    OkHttpClient.Builder builder = client.newBuilder()
      .addInterceptor(new GzipRequestInterceptor())
      .retryOnConnectionFailure(true)
      .certificatePinner(factory.provideCertificatePinnerFor(environment))
      .connectionSpecs(Arrays.asList(ConnectionSpec.MODERN_TLS, ConnectionSpec.COMPATIBLE_TLS));
    if (isSocketFactoryUnset(sslSocketFactory, x509TrustManager)) {
      builder.sslSocketFactory(sslSocketFactory, x509TrustManager);
    }

    return builder.build();
  }

3.9.1 👇

Feb 27, 2018 9:15:56 PM okhttp3.mockwebserver.MockWebServer$2 execute
INFO: MockWebServer[59072] starting to accept connections
Feb 27, 2018 9:15:57 PM okhttp3.mockwebserver.MockWebServer$3 processOneRequest
INFO: MockWebServer[59072] received request: POST /events/v2?access_token=anyAccessToken HTTP/1.1 and responded: HTTP/1.1 204 OK

3.10.0 👇

Feb 27, 2018 9:12:04 PM okhttp3.mockwebserver.MockWebServer$2 execute
INFO: MockWebServer[59055] starting to accept connections
Feb 27, 2018 9:12:06 PM okhttp3.mockwebserver.MockWebServer$3 processConnection
WARNING: MockWebServer[59055] connection from /127.0.0.1 didn't make a request

Following you can find a failing test 👀

package com.mapbox.android.telemetry;


import android.content.Context;

import org.junit.Test;

import java.net.HttpURLConnection;
import java.util.Arrays;
import java.util.List;

import okhttp3.Callback;
import okhttp3.HttpUrl;
import okhttp3.mockwebserver.MockResponse;
import okhttp3.mockwebserver.MockWebServer;
import okhttp3.mockwebserver.RecordedRequest;
import okhttp3.internal.tls.SslClient;

import static org.junit.Assert.assertEquals;
import static org.mockito.Mockito.RETURNS_DEEP_STUBS;
import static org.mockito.Mockito.mock;

public class Foo {

  @Test
  public void foo() throws Exception {
    MockWebServer server = new MockWebServer();
    server.useHttps(SslClient.localhost().socketFactory, false);
    server.start();
    Context mockedContext = mock(Context.class, RETURNS_DEEP_STUBS);
    MapboxTelemetry.applicationContext = mockedContext;
    TelemetryClient telemetryClient = obtainATelemetryClient("anyAccessToken", "anyUserAgent", server);
    List<Event> mockedEvent = obtainAnEvent();
    MockResponse mockResponse = new MockResponse();
    mockResponse.setResponseCode(HttpURLConnection.HTTP_NO_CONTENT);
    mockResponse.setBody("");
    server.enqueue(mockResponse);
    Callback mockedCallback = mock(Callback.class);

    telemetryClient.sendEvents(mockedEvent, mockedCallback);

    RecordedRequest request = server.takeRequest();
    assertEquals("/events/v2?access_token=anyAccessToken", request.getPath());
  }

  TelemetryClient obtainATelemetryClient(String accessToken, String userAgent, MockWebServer server) {
    TelemetryClientSettings mockedTelemetryClientSettings = provideDefaultTelemetryClientSettings(server);
    Logger mockedLogger = mock(Logger.class);
    return new TelemetryClient(accessToken, userAgent, mockedTelemetryClientSettings, mockedLogger);
  }

  private TelemetryClientSettings provideDefaultTelemetryClientSettings(MockWebServer server) {
    HttpUrl localUrl = obtainBaseEndpointUrl(server);
    SslClient sslClient = SslClient.localhost();

    return new TelemetryClientSettings.Builder()
      .baseUrl(localUrl)
      .sslSocketFactory(sslClient.socketFactory)
      .x509TrustManager(sslClient.trustManager)
      .build();
  }

  private List<Event> obtainAnEvent() {
    Event theEvent = new AppUserTurnstile("anySdkIdentifier", "anySdkVersion", false);

    return obtainEvents(theEvent);
  }

  private List<Event> obtainEvents(Event... theEvents) {
    return Arrays.asList(theEvents);
  }

  private HttpUrl obtainBaseEndpointUrl(MockWebServer server) {
    return server.url("/");
  }
}

☝️ is using https://github.com/mapbox/mapbox-events-android code.

You can check that we only bumped OkHttp version to 3.10.0 👉 mapbox/mapbox-events-android@c92a4ac and after that tests got stuck.

Tried many things without luck 😓
Any hints? What did it change that could affect tests in that sense?

[swankjesse]

Hmm. This is a little mystery. Can you attach a debugger and check out where OkHttp gets stuck?

[Guardiola31337]

Everything is working fine until

okhttp/mockwebserver/src/main/java/okhttp3/mockwebserver/MockWebServer.java

Line 475 in 9a6f88d

while (processOneRequest(socket, source, sink)) {

which calls readRequest(socket, source, sink, sequenceNumber) which also calls source.readUtf8LineStrict() which ends up calling RealBufferedSource#readUtf8LineStrict which finally throws a java.io.EOFException (\n not found: limit=0 content=…) because apparently the size of the Buffer is 0.
Then the exception is bubble up to readRequest which returns null

okhttp/mockwebserver/src/main/java/okhttp3/mockwebserver/MockWebServer.java

Line 590 in 9a6f88d

return null; // no request because we closed the stream

and then processOneRequest returns false

okhttp/mockwebserver/src/main/java/okhttp3/mockwebserver/MockWebServer.java

Line 512 in 9a6f88d

if (request == null) return false;

which breaks the processOneRequest loop and logs the WARNING: MockWebServer[59055] connection from /127.0.0.1 didn't make a request message because sequenceNumber is 0.
After that the test is still running (apparently waiting for new requests).

It seems that there's an issue when getting the buffer from the socket and in 3.10.0 we're not able to read that kind of requests anymore. I know that 3.10.0 brings Okio 1.14.0. Could it be related? My guess is that the root of the issue is around

okhttp/mockwebserver/src/main/java/okhttp3/mockwebserver/MockWebServer.java

Line 472 in 0b74bba

BufferedSource source = Okio.buffer(Okio.source(socket));

Let me know if you need any further information.

[Guardiola31337]

After that the test is still running (apparently waiting for new requests).

Wanted to add that apart from the issue when trying to obtain the buffer from the socket, ☝️ seems like another problem because if at that point we've already received an error, why the test doesn't continue its execution and it gets stuck instead? It seems that in that scenario there are still resources opened. Does that make sense?

[swankjesse]

Any chance you could isolate this into a standalone test case? All of OkHttp’s tests use OkHttp+MockWebServer and they’re all working fine.

[Guardiola31337]

Mystery solved! Well partially...

After a thoroughly debug session, @Sefford told me that when he bumped OkHttp version to 3.10.0, he started getting SSLPeerUnverifiedException: Hostname localhost not verified messages in their tests and he fixed it adding

.hostnameVerifier(new HostnameVerifier() {
  @Override
  public boolean verify(String hostname, SSLSession session) {
    return true;
  }
})

to the config of the OkHttpClient used in their tests. I wasn't getting those messages because I'm mocking the Callback so they weren't logged.

Thanks @Sefford for pointing me in that direction 🙏

It seems that after #3764 changes if you're using MockWebServer with HTTPS you need to add ☝️ to your tests in order to have them ✅
It'd be great if we could add that to the documentation somehow (if that's the best solution to follow in these cases).

After adding that config to my tests everything is working again 💃

But now I'm wondering why even when passing in an empty Callback implementation (without adding the hostname verifier stub) tests still get stuck. Shouldn't the exception bubble up and stop the execution of the test if the hostname is not verified?
It seems that although the Callback is fired it's not sending the notification to the lock properly and it remains opened forever. Does that make sense?

Let me know if it's worth it to open a new issue reporting ☝️ or if you prefer to keep the discussion here.

[yschimke]

There is still something worth digging into here regarding why the behaviour changed and why its hanging now. I'll try to take a look this week, but glad you have a workaround to unblock yourself.

[Guardiola31337]

@yschimke

I'll try to take a look this week

Awesome! Let me know if you have any questions or if you need further information/clarification.

[TarCV]

Any updates on this?
We use similar setup but without pinning and get SSLPeerUnverifiedException: Hostname localhost not verified too. So we had to use workaround by Guardiola31337.

Although I'm not sure if using SslClient.localhost() is supported as SslClient is inside internal package.

[swankjesse]

SslClient is not public API and we might break you in a future release.

[swankjesse]

SslClient public API: #3934

[swankjesse]

No action to take on this, other than to be afraid of how mocks + onFailure interact poorly.