Logging socket timeout in integration test?

[Thomas Vaughan]

Hello dropwizards - 

I have Dropwizard 0.8.1 + Guice + JDBI and I'm trying to get a maven failsafe integration-test working.  I'm basically just using the DropwizardAppRule, as laid out in the dropwizard documentation, with a DB migration run against an in-memory H2 database in a @BeforeClass method.

While setting all this up, I've never had any success getting my application's logging to spit out anything to the failsafe reports, and I suspect that may be "part of the problem" I'm experiencing here, but I'm a little stumped at the moment and would really appreciate a 2nd pair of eyes:

First off, Le Stack Trace:

testAuthGet(com.foo.arc.auth.v1.resources.IntTestAuthResource)  Time elapsed: 1.068 sec  <<< ERROR!

javax.ws.rs.ProcessingException: java.net.SocketTimeoutException: Read timed out

at java.net.SocketInputStream.socketRead0(Native Method)

at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)

at java.net.SocketInputStream.read(SocketInputStream.java:170)

at java.net.SocketInputStream.read(SocketInputStream.java:141)

at org.apache.http.impl.conn.LoggingInputStream.read(LoggingInputStream.java:87)

at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:136)

at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:152)

at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:270)

at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:140)

at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)

at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:260)

at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:161)

at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:153)

at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:271)

at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:123)

at com.codahale.metrics.httpclient.InstrumentedHttpRequestExecutor.execute(InstrumentedHttpRequestExecutor.java:44)

at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:254)

at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)

at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:86)

at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:108)

at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)

at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)

at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:106)

at io.dropwizard.client.DropwizardApacheConnector.apply(DropwizardApacheConnector.java:89)

at org.glassfish.jersey.client.ClientRuntime.invoke(ClientRuntime.java:245)

at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:671)

at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:668)

at org.glassfish.jersey.internal.Errors.process(Errors.java:315)

at org.glassfish.jersey.internal.Errors.process(Errors.java:297)

at org.glassfish.jersey.internal.Errors.process(Errors.java:228)

at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:444)

at org.glassfish.jersey.client.JerseyInvocation.invoke(JerseyInvocation.java:668)

at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:402)

at org.glassfish.jersey.client.JerseyInvocation$Builder.get(JerseyInvocation.java:302)

at com.foo.arc.auth.v1.resources.IntTestAuthResource.executeGet(IntTestAuthResource.java:86)

at com.foo.arc.auth.v1.resources.IntTestAuthResource.testAuthGet(IntTestAuthResource.java:52)

The integration-test:

public class IntTestAuthResource {

    private static final Logger logger = LoggerFactory.getLogger(IntTestAuthResource.class);

    private static final ObjectMapper objectMapper = Jackson.newObjectMapper();

    private static final String CONFIG_PATH = ResourceHelpers.resourceFilePath("app-test-config.yml");

    @ClassRule

    public static final DropwizardAppRule<ArcAuthConfiguration> RULE =

            new DropwizardAppRule<>(ArcAuthApplication.class, CONFIG_PATH);

    @BeforeClass

    public static void migrateDb() throws Exception {

        RULE.getApplication().run("db", "migrate", CONFIG_PATH);

    }

    @Test

    public void testAuthGet() throws IOException {

        String token = "FakeDemoToken";

        Response response = executeGet("testAuthGet",

                String.format("http://localhost:%d/v1/auth?token=%s", RULE.getLocalPort(), token));

        

        assertThat(response.getStatus()).isEqualTo(Response.Status.OK.getStatusCode());

        UserContextData data = objectMapper.readValue((InputStream)response.getEntity(), UserContextData.class);

        assertThat(data.getUser().getFirstName()).isEqualTo("Tom");

        assertThat(data.getOrganizationId()).isEqualTo("Demo Org");

        assertThat(data.getToken()).isEqualTo(AdmiralTokenHasher.hash(token));

    }

    @Test

    public void testAuthGetWithBadTokenQueryParameter() throws IOException {

        Response response = executeGet("testAuthGetWithBadTokenQueryParameter",

                String.format("http://localhost:%d/v1/auth", RULE.getLocalPort()));

        assertThat(response.getStatus()).isEqualTo(Response.Status.BAD_REQUEST.getStatusCode());

    }

    private Response executeGet(String testName, String targetString) {

        BootstrapUtils.reset();     //allegedly need this when using Guice

        Client client = new JerseyClientBuilder(RULE.getEnvironment()).build(testName);

        logger.debug("Issuing GET against '{}'", targetString);

        return client.target(targetString).request().get();

    }

}

I've walked through the stack trace and I'm not really sure what I'm not providing... the key bit seems - to me - to be the InstrumentedHttpRequestExecutor  that ultimately uses Apache's LoggingInputStream.read.  

Just for completeness, here's my test config yaml:

# Logging settings.

# For full configuration options, see https://dropwizard.github.io/dropwizard/manual/configuration.html#logging

logging:

  level: INFO     # The default level of all loggers. Can be OFF, ERROR, WARN, INFO, DEBUG, TRACE, or ALL.

  loggers:

    "com.foo": DEBUG

swagger: 

   resourcePackage: com.foo.arc.auth.v1.resources

   

database:

  driverClass: org.h2.Driver

  user: sa

  password: sa

  url: jdbc:h2:mem:admiral;MODE=MySQL;DB_CLOSE_DELAY=-1;INIT=CREATE SCHEMA IF NOT EXISTS "public";

  

flyway:

  locations:

    - db/migrations/h2/common

    - db/migrations/h2/basic

    - db/migrations/h2/test

Does anyone see the problem with this setup?  Thanks in advance!

[Thomas Vaughan]

Self-reply:  I ripped out the guice integration and this problem went away.

[Thomas Vaughan]

Actually, that problem came back and appeared to be intermittent - e.g. when my machine was under lots of load the timeout stack trace would happen.  When it was relatively idle, the IntTests would pass without the timeout stack trace.  Short of fixing the actual underlying problem, adding longer timeouts to the JerseyClient appears to have solved it.  I define CLIENT_TIMEOUT_MS = 20000 as a constant and changed my "executeGet" method a bit to add ClientProperties for timeouts and this appears to be working:

 

     private static final int CLIENT_TIMEOUT_MS = 30000;

 

Client client = new JerseyClientBuilder(RULE.getEnvironment()).build(testName);

client.property(ClientProperties.CONNECT_TIMEOUT, CLIENT_TIMEOUT_MS);

client.property(ClientProperties.READ_TIMEOUT, CLIENT_TIMEOUT_MS);

On Monday, June 8, 2015 at 4:52:06 PM UTC-4, Thomas Vaughan wrote: