Test reliably hangs waiting on response from WireMock (though some reliably pass)

[bretthoerner]

The wiremock branch of raven-java is a reproducible case for me: getsentry/sentry-java#316

The main project, raven and the first listed submodule, raven-android, use WireMock and succeed. The next submodule, raven-log4j hangs 100% of the time waiting on a response from WireMock. I've traced it down to a .read() call deep down inside HttpURLConnection. External calls from curl also fail when this test is running (though java is listening on 8080...). In the tests that pass I can use curl and get a 404 at / as expected.

I've tried with the WireMockClassRule also, since I saw that mentioned as a fix for hanging in another issue, but no dice.

Any thoughts? Thanks!

[tomakehurst]

Thanks for reporting. I'll try and take a look on the way home today.

[bretthoerner]

Thanks, I guess I should have mentioned mvn verify to run integration tests... and it's ultra annoying but the version of jmockit we use doesn't work with the latest JVM point releases for some reason... I use 1.7.0_80 or 1.8.0_102. 😢

[tomakehurst]

Yeah, I spotted that in .travis.yml. I've managed to get it to hang on my laptop now.

For me at least, it looks like WM is blocking when trying to write log messages (thread dumps show this), which is odd.

I've noticed you've got log4j 2 in the deps. I've not got round to using this yet so I'm not familiar. Is there anything in how this is configured that might be the issue?

[bretthoerner]

That's interesting about the logs. Most of what raven-java does is to provide new logging appenders so that logged exceptions can be sent to Sentry. The raven submodule is our integration for java.util.logging and passes... the first one that tries and hangs for me is log4j. If anything logs at WARN or above it is configured to send to Sentry, which means another web request.

[bretthoerner]

To add to that, my tests are already deep inside logging when they send a request, so if this is locking up during logging then it's possible that it's a logging deadlock issue. When I used a debugger I only managed to find the request side read hanging. Can you point me to where you found the server side hanging on logs? This is most likely not a WireMock issue at all, sorry about that.

[tomakehurst]

Here's a snippet from my thread dump:

"qtp1276611190-17-acceptor-1@4d465b11-NetworkTrafficServerConnector@37883b97{HTTP/1.1}{0.0.0.0:8080}" #17 prio=5 os_prio=31 tid=0x00007fd2e9291800 nid=0x5c03 waiting for monitor entry [0x00007000016d8000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:205)
	- waiting to lock <0x00000006c00757b8> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.java:581)
	at wiremock.org.eclipse.jetty.util.log.JettyAwareLogger.log(JettyAwareLogger.java:620)
	at wiremock.org.eclipse.jetty.util.log.JettyAwareLogger.debug(JettyAwareLogger.java:206)
	at wiremock.org.eclipse.jetty.util.log.Slf4jLog.debug(Slf4jLog.java:89)
	at wiremock.org.eclipse.jetty.io.SelectorManager$ManagedSelector.submit(SelectorManager.java:480)
	at wiremock.org.eclipse.jetty.io.SelectorManager.accept(SelectorManager.java:218)
	at wiremock.org.eclipse.jetty.io.SelectorManager.accept(SelectorManager.java:202)
	at wiremock.org.eclipse.jetty.server.ServerConnector.accepted(ServerConnector.java:387)
	at wiremock.org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:378)
	at wiremock.org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:500)
	at wiremock.org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
	at wiremock.org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
	at java.lang.Thread.run(Thread.java:745)

[bretthoerner]

Thank you! This has got to be a logging deadlock that I'll have to figure out.

[tomakehurst]

No probs. Hope it's easy to track down.

[jeffmay]

@bretthoerner did you ever figure out the cause for this one?