Spring-cloud-gateway: Intermittent Blocking Call Test Failures

[ryanjbaxter]

Describe the bug
I am noticing 3 test failures due to blocking calls made. This happens intermittently and cannot be reproduced running the Maven build. I can consistently see the failures if I run the tests from my IDE.
If I run all the tests in org.springframework.cloud.gateway the 3 tests that fail are

1. GatewayControllerEndpointTests.testPostValidRouteDefinition
2. FormIntegrationTests.multipartFormDataWorksRestTemplate
3. FormIntegrationTests.multipartFormDataWorksWebClient

All tests are failing with java.lang.Error: Blocking call! java.io.FileInputStream#readBytes]

However there is no stacktrace to see where it is coming from. My guess is reading the POST body.

Sample
Run all the tests in org.springframework.cloud.gateway from your IDE

[ryanjbaxter]

@bsideup would appreciate any thoughts you might have on the issue here.

[ryanjbaxter]

cc: @TYsewyn

[TYsewyn]

I saw following during the run of GatewayControllerEndpointTests.testPostValidRouteDefinition:

2019-12-10 18:40:26.689 DEBUG 55751 --- [ctor-http-nio-3] a.w.r.e.AbstractErrorWebExceptionHandler : [b00a54b8] Resolved [ServerWebInputException: 400 BAD_REQUEST "Failed to read HTTP message"; nested exception is org.springframework.core.codec.DecodingException: JSON decoding error: Cannot construct instance of `org.springframework.cloud.gateway.route.RouteDefinition`, problem: Blocking call! java.io.FileInputStream#readBytes; nested exception is com.fasterxml.jackson.databind.exc.ValueInstantiationException: Cannot construct instance of `org.springframework.cloud.gateway.route.RouteDefinition`, problem: Blocking call! java.io.FileInputStream#readBytes at [Source: (io.netty.buffer.ByteBufInputStream); line: 1, column: 2]] for HTTP POST /actuator/gateway/routes/test-route

Looks to be happening while accepting the request body and deserializing it using Jackson. Haven’t found any additional things up until now.

[spencergibb]

yeah, I think it's jackson trying to load config files or somesuch.

[ryanjbaxter]

I haven't been able to reproduce the problem with @spencergibb's latest changes

I will see if the author of this PR can merge those changes in and if the issue goes away

[bsideup]

However there is no stacktrace to see where it is coming from

Without the stacktrace it is almost impossible to know from where the blocking calls are coming from. Is it just not displayed in the build log, or it is not possible to get it?
Hint: you can override the callback and log before throwing

[TYsewyn]

After doing a lot of trial and error it looks like this additional whitelisted blocking call is making the tests succeed:
builder.allowBlockingCallsInside("io.netty.util.concurrent.SingleThreadEventExecutor$6", "run");

[bsideup]

I would highly recommend whitelisting the callsite of it. It sounds too generic and may also be called from other places

[TYsewyn]

Thanks @bsideup! I found the culprit using your hint!
This is the complete stacktrace:

java.lang.Error: java.io.FileInputStream#readBytes
    at reactor.blockhound.integration.CustomBlockHoundIntegration.lambda$applyTo$0(CustomBlockHoundIntegration.java:68)
    at reactor.blockhound.BlockHound$Builder.lambda$install$6(BlockHound.java:318)
    at reactor.blockhound.BlockHoundRuntime.checkBlocking(BlockHoundRuntime.java:46)
    at java.io.FileInputStream.readBytes(FileInputStream.java)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
    at sun.security.provider.NativePRNG$RandomIO.ensureBufferValid(NativePRNG.java:526)
    at sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:545)
    at sun.security.provider.NativePRNG$RandomIO.access$400(NativePRNG.java:331)
    at sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:220)
    at java.security.SecureRandom.nextBytes(SecureRandom.java:468)
    at java.util.UUID.randomUUID(UUID.java:145)
    at org.springframework.cloud.gateway.route.RouteDefinition.<init>(RouteDefinition.java:45)
    at sun.reflect.GeneratedConstructorAccessor47.newInstance(Unknown Source)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.fasterxml.jackson.databind.introspect.AnnotatedConstructor.call(AnnotatedConstructor.java:119)
    at com.fasterxml.jackson.databind.deser.std.StdValueInstantiator.createUsingDefault(StdValueInstantiator.java:270)
    at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserializeFromObject(BeanDeserializer.java:344)
    at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:159)
    at com.fasterxml.jackson.databind.ObjectReader._bindAndClose(ObjectReader.java:1719)
    at com.fasterxml.jackson.databind.ObjectReader.readValue(ObjectReader.java:1228)
    at org.springframework.http.codec.json.AbstractJackson2Decoder.decode(AbstractJackson2Decoder.java:142)
    at org.springframework.http.codec.json.AbstractJackson2Decoder.lambda$decodeToMono$1(AbstractJackson2Decoder.java:133)
...

During initialization of a RouteDefinition we're generating a new UUID if none has been sent.
UUID.randomUUID() looks to be a real pain when migrating to a reactive setup! 😬

[TYsewyn]

I'm going to look at org.springframework.http.codec.json.AbstractJackson2Decoder since that is an

Abstract base class for Jackson 2.9 decoding, leveraging non-blocking parsing.

But it is unfortunately blocking in some cases at the moment.

[ryanjbaxter]

This was fixed by https://github.com/spring-cloud/spring-cloud-gateway/commit/6936c83b18b42b3a8bf75ec1f4f2a7ca672e24c8