Blockhound failing with new version of micrometer

Question

Blockhound failing with new version of micrometer

Alexspenc212 opened this issue a year ago · 24 comments

Alexspenc212 commented a year ago

Expected Behavior

Should detecting blocking calls

Actual Behavior

When we i request my endpoint, Blockhound failed with exception:

[Byte Buddy] ERROR reactor.core.publisher.ContextPropagation [jdk.internal.loader.ClassLoaders$AppClassLoader@251a69d7, unnamed module @50c87b21, Thread[parallel-1,5,main], loaded=false]
reactor.blockhound.shaded.net.bytebuddy.pool.TypePool$Resolution$NoSuchTypeException: Cannot resolve type description for io.micrometer.context.ContextSnapshot$Scope
	at reactor.blockhound.shaded.net.bytebuddy.pool.TypePool$Resolution$Illegal.resolve(TypePool.java:191)
	at reactor.blockhound.shaded.net.bytebuddy.pool.TypePool$Default$LazyTypeDescription$TokenizedGenericType.toErasure(TypePool.java:6901)
	at reactor.blockhound.shaded.net.bytebuddy.pool.TypePool$Default$LazyTypeDescription$TokenizedGenericType.asErasure(TypePool.java:6915)
	at reactor.blockhound.shaded.net.bytebuddy.description.method.MethodDescription$AbstractBase.getDescriptor(MethodDescription.java:529)
	at reactor.blockhound.shaded.net.bytebuddy.asm.AsmVisitorWrapper$ForDeclaredMethods.wrap(AsmVisitorWrapper.java:493)
	at reactor.blockhound.shaded.net.bytebuddy.asm.AsmVisitorWrapper$Compound.wrap(AsmVisitorWrapper.java:746)
	at reactor.blockhound.shaded.net.bytebuddy.dynamic.scaffold.TypeWriter$Default$ForInlining$WithDecorationOnly$DecorationClassVisitor.visit(TypeWriter.java:5808)
	at reactor.blockhound.shaded.net.bytebuddy.jar.asm.ClassReader.accept(ClassReader.java:569)
	at reactor.blockhound.shaded.net.bytebuddy.jar.asm.ClassReader.accept(ClassReader.java:424)
	at reactor.blockhound.shaded.net.bytebuddy.dynamic.scaffold.TypeWriter$Default$ForInlining.create(TypeWriter.java:4014)
	at reactor.blockhound.shaded.net.bytebuddy.dynamic.scaffold.TypeWriter$Default.make(TypeWriter.java:2224)
	at reactor.blockhound.shaded.net.bytebuddy.dynamic.DynamicType$Builder$AbstractBase$UsingTypeWriter.make(DynamicType.java:4057)
	at reactor.blockhound.shaded.net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.doTransform(AgentBuilder.java:12225)
	at reactor.blockhound.shaded.net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.transform(AgentBuilder.java:12160)
	at reactor.blockhound.shaded.net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.access$1800(AgentBuilder.java:11869)
	at reactor.blockhound.shaded.net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$Java9CapableVmDispatcher.run(AgentBuilder.java:12647)
	at reactor.blockhound.shaded.net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$Java9CapableVmDispatcher.run(AgentBuilder.java:12579)
	at java.base/java.security.AccessController.doPrivileged(AccessController.java:399)
	at reactor.blockhound.shaded.net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.doPrivileged(AgentBuilder.java)
	at reactor.blockhound.shaded.net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.transform(AgentBuilder.java:12103)
	at reactor.blockhound.shaded.net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$ByteBuddy$ModuleSupport.transform(Unknown Source)
	at java.instrument/sun.instrument.TransformerManager.transform(TransformerManager.java:188)

Steps to Reproduce

Spring boot v: 3.0.4
actuator v: 3.0.4
micrometer-observation v: 1.10.4
micrometer-core v: 1.10.4
blockhound v: 1.0.8

It just failed at any request.

But, it was working with older version:
Spring boot 2.7.0
micrometer-core v: 1.9.0

Possible Solution

Your Environment

Spring boot v: 3.0.4
actuator v: 3.0.4
micrometer-observation v: 1.10.4
micrometer-core v: 1.10.4
blockhound v: 1.0.8
reactor-core v: 3.5.3

Answer 1 · 2023-05-08T21:26:06.000Z

Hi @Alexspenc212 ,

Thanks for reporting.
Can you please confirm if this log is really breaking anything, or is it just about logging and your application is actually operational and working fine ?

I tend to think that it's a duplicate of #311, where the trace is actually not harmful, but just a noisy log.
Normally, there is a work around which avoids the log: you can add io.micrometer:context-propagation:1.0.2 into your classpath. Can you please confirm if adding io.micrometer:context-propagation:1.0.2 in your classpath is removing the log ?

thanks.

Answer 2 · 2023-05-09T07:40:14.000Z

Notice that we can do something in Reactor-Core API in order to avoid the log; and I will work on this during this week (the problem is not coming from Blockhound itself, but I keep this issue opened until you confirm that adding context-propagation jar in the classpath makes the log disappear).

Answer 3 · 2023-05-09T09:29:58.000Z

Hi @Alexspenc212 ,

Thanks for reporting. Can you please confirm if this log is really breaking anything, or is it just about logging and your application is actually operational and working fine ?

I tend to think that it's a duplicate of #311, where the trace is actually not harmful, but just a noisy log. Normally, there is a work around which avoids the log: you can add io.micrometer:context-propagation:1.0.2 into your classpath. Can you please confirm if adding io.micrometer:context-propagation:1.0.2 in your classpath is removing the log ?

thanks.

Thank you for this quick answer. Yes, the error log not appears anymore. But BlockHound is still not working. It's not detecting blocking calls. It looks like nothing has happened. Back to your question, yes, this log doesn't break the whole app, but blockhound stops working after this error.

Answer 4 · 2023-05-09T10:04:31.000Z

That's strange, because I have double checked and did a small application without context-propagation in the classpath, and I managed to add an illegal blocking call somewhere in my sample app which has been detected and logged by blockhound, despite the unexpected log.

Anyway, the only thing that can be done is a I think a patch in the reactor-core API, and it will avoid the problem (which seems to randomly make blockhound dysfunctional (it seems to be the case in your situation).

So, I will start working on a patch this week in reactor-core; In the mean time, can you please live with context-propgation in your classpath ?

I'm closing this issue, but I'll get back to here once something will have been done in reactor-core. feel free to reopen if needed.

thank you.

Answer 5 · 2023-05-09T10:34:52.000Z

`

That's strange, because I have double checked and did a small application without context-propagation in the classpath, and I managed to add an illegal blocking call somewhere in my sample app which has been detected and logged by blockhound, despite the unexpected log.

Anyway, the only thing that can be done is a I think a patch in the reactor-core API, and it will avoid the problem (which seems to randomly make blockhound dysfunctional (it seems to be the case in your situation).

So, I will start working on a patch this week in reactor-core; In the mean time, can you please live with context-propgation in your classpath ?

I'm closing this issue, but I'll get back to here once something will have been done in reactor-core. feel free to reopen if needed.

thank you.

It's stop detecting "readBytes(FileInputStream.java)" If it helps. Stack trace from old version

Original Stack Trace:
		at java.base/java.io.FileInputStream.readBytes(FileInputStream.java)
		at java.base/java.io.FileInputStream.read(FileInputStream.java:276)
		at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132)
		at java.base/sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:425)
		at java.base/sun.security.provider.NativePRNG$RandomIO.ensureBufferValid(NativePRNG.java:528)
		at java.base/sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:547)
		at java.base/sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:221)
		at java.base/java.security.SecureRandom.nextBytes(SecureRandom.java:758)
		at java.base/java.util.UUID.randomUUID(UUID.java:151)

Answer 6 · 2023-05-09T10:37:48.000Z

ok, I'm about to start working on a reactor-core PR, and I'll get back to here, and will double check the stacktrace you indicated, in case something else must be done.
but for the moment, I tend to think that it's better to first do a PR in reactor-core.

thanks a lot for the info !

Answer 7 · 2023-05-29T08:18:48.000Z

Hello! Good day! As i see, issues was closed. Can we implement it?

Answer 8 · 2023-05-29T09:44:31.000Z

Hi @Alexspenc212 ,

The necessary fix for this issue has been merged in reactor-core project, see reactor/reactor-core#3459, so the fix is currently available in io.projectreactor:reactor-core:3.5.7-SNAPSHOT, and will be available in the next official io.projectreactor:reactor-core:3.5.7 release (not yet released).

So, for the moment, if you are able to use snapshot version, you can try to use io.projectreactor:reactor-core:3.5.7-SNAPSHOT. Else, if you can't use snapshots, you will need to continue including the contextpropagation jar in your classpath until the official io.projectreactor:reactor-core:3.5.7 version is made available.

thanks.

Answer 9 · 2023-06-27T13:38:53.000Z

It's working thank you! I have 2 questions here, sorry but I assume it's the best place to ask, if not, please advise the link.

As I found in the documentation, BlockHound added new versions of the reactor core. From your point of view, what is the right way to check blocking calls on whole project?
I also found that we can add detecting blocking calls without any code in a project by using an agent in JVM arguments. Where i can find jar file? Can you please advise? I was trying to compile it from this project, but I faced problems with test, probably some env problems.

Answer 10 · 2023-06-27T14:33:56.000Z

Hi @Alexspenc212 ,

Usually, you will use blockhound from junit tests in order to detect blocking calls. But if you want to also test your whole project, you can either include in your classpath the blockhound jar and call BlockHound.install(); from your main method, or you can run your application using the javaagent option. In this case, no need to initialize BlockHound from your main method (see bellow).
you will find the jar from maven central (currently , the latest downloadable version is 1.0.8-RELEASE).
If you want to build the jar: as of today, tests can only be run using Java 13. So, better is to build without tests using
./gradlew jar command.

Then you can run your application like this for example:

java -XX:+AllowRedefinitionToAddDeleteMethods -javaagent:blockhound-1.0.8.RELEASE.jar  -jar my-application.jar

I assume here that my-application.jar embeds all application dependencies, and that JDK13+ is used, else you don't need to use the -XX:+AllowRedefinitionToAddDeleteMethods option.

Answer 11 · 2023-07-05T13:37:02.000Z

Thank you! javaagent is working and detecting calls!

But is it possible that allowBlockingCallsInside stop working in new spring boot and reactor versions ? I've tried both ways
BlockHound.install(builder -> builder.allowBlockingCallsInside(BlockingClass.class.getName(), "inner"));
and for test

@AutoService(Config.class)
public class Config implements BlockHoundIntegration {

    @Override
    public void applyTo(BlockHound.Builder builder) {
        builder.allowBlockingCallsInside(BlockingClass.class.getName(), "inner");
    }
}

Spring boot v: 3.0.4
actuator v: 3.0.4
micrometer-observation v: 1.10.4
micrometer-core v: 1.10.4
blockhound v: 1.0.8
reactor-core v: 3.5.7 latest

Answer 12 · 2023-07-05T15:37:10.000Z

Hi @Alexspenc212 ,

I just did a test, it seems to work for me, but in your example, I think that the @autoservice should be declared like this:

@AutoService(BlockHoundIntegration.class)

can you retry ?

I have attached below my sample project:
blockhound-premain-spi.tgz

to test:

mvn clean package
java -XX:+AllowRedefinitionToAddDeleteMethods -javaagent:blockhound-1.0.8.RELEASE.jar -jar target/test-0.0.1-SNAPSHOT.jar
reactor.blockhound.BlockingOperationError: Blocking call! java.lang.Thread.sleep
	at java.base/java.lang.Thread.sleep(Thread.java)
	at com.example.BlockingDisallowTest$NonBlockingClass.inner(BlockingDisallowTest.java:46)
	at com.example.BlockingDisallowTest$NonBlockingClass.outer(BlockingDisallowTest.java:60)
	at com.example.BlockingDisallowTest.lambda$main$0(BlockingDisallowTest.java:22)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)

Answer 13 · 2023-07-06T07:56:56.000Z

Thank you a lot !

Answer 14 · 2023-07-10T07:29:54.000Z

Hi @Alexspenc212 ,

I have attached below my sample project: blockhound-premain-spi.tgz

Sorry, i feel stupid, but i want to understand this.

If i've changed you project like this:

public static void main(String[] args) {
        BlockHound.install();
        NonBlockingClass nbc = new NonBlockingClass();
        nbc.outer();
    }

    static class NonBlockingClass {

        String outer() {
            try {
                FutureTask<?> task = new FutureTask<>(() -> {
                    Thread.sleep(0);
                    return "";
                });
                Schedulers.parallel().schedule(task);

                task.get(10, TimeUnit.SECONDS);
            } catch (Exception e) {
                System.out.println(e.getMessage());
            }
            Thread.yield();
            return "";
        }
    }

@AutoService(BlockHoundIntegration.class)
public class Config implements BlockHoundIntegration {

    @Override
    public void applyTo(BlockHound.Builder builder) {
        builder.allowBlockingCallsInside(BlockingDisallowTest.NonBlockingClass.class.getName(), "outer");
    }
}

It still detecting that we have blocking call inside outer method, but builder.allowBlockingCallsInside doesn't work. What i missed ?

Answer 15 · 2023-07-10T19:31:04.000Z

if you only declare this :

@AutoService(BlockHoundIntegration.class)
public class Config implements BlockHoundIntegration {

    @Override
    public void applyTo(BlockHound.Builder builder) {
        builder.allowBlockingCallsInside(BlockingDisallowTest.NonBlockingClass.class.getName(), "outer");
    }
}

it means that NonBlockingClass.outer() method is allowed to block and all the methods called down the stack.
So, here, outer() won't throw any exceptions, and since inner() is called by outer(), inner() is also allowed to block.
(see https://github.com/reactor/BlockHound/blob/master/docs/customization.md)

So, can you clarify ? I'm not sure I understand when you say builder.allowBlockingCallsInside doesn't work ? could you elaborate ?

Answer 16 · 2023-07-10T20:24:51.000Z

Yes, i'm trying to simplify this example(there is no inner() method, only outer()) to understand why i still get stack trace(...blocking call inside!!!) with
builder.allowBlockingCallsInside(BlockingDisallowTest.NonBlockingClass.class.getName(), "outer")

So blockhound is detecting blocking calls, but i cannot add this method to white list for some reasons.

Answer 17 · 2023-07-10T20:58:48.000Z

ah ok, sorry, I misunderstood !

So, here, I think that the blocking code is detected because the configuration only enables the outer methods and all methods called down the stack of the current thread that is calling outer().

But here, the outer() method schedules the blocking task, which is executed in the parallel scheduler, not from the current thread that is calling outer().

Note that if you schedule the task in the boundedElastic scheduler, then the blocking method won't be detected (because boundedElastic allows to execute blocking code).

does this help ?

Answer 18 · 2023-07-11T07:42:02.000Z

Yes i see why it's detecting blocking call, but how can i add this method to whitelist? Because for some reasons in my project i faced with the same problems. It's detecting and failing in tests, but i cannon add those methods to whitelist.

I also noticed, that it works fine in your project blockhound-premain-spi.tgz

Different only that you add Schedulers.parallel().schedule(() in main method, and also add CountDownLatch.

Answer 19 · 2023-07-12T09:40:22.000Z

can you try to do a sample reproducer project, and attached it to new GH issue ? I'll take a look.
thanks

Answer 20 · 2023-07-12T11:07:24.000Z

blockhound.tgz
So basically my question is - if blockhound detect blocking call, this method can be added to whitelist? i've tried both methods:
BlockHound.install(builder -> builder.allowBlockingCallsInside(BlockingDisallowTest.NonBlockingClass.class.getName(), "outer"));

and with config in example.

Answer 21 · 2023-07-12T12:00:24.000Z

so, in this example from your previous post, we have:

public class BlockingDisallowTest {

    public static void main(String[] args) throws InterruptedException, ExecutionException, TimeoutException {
        BlockHound.install();
        NonBlockingClass.outer();
    }

    static class NonBlockingClass {

       static void outer() throws ExecutionException, InterruptedException, TimeoutException {
            FutureTask<?> task = new FutureTask<>(() -> {
                System.out.println(Thread.currentThread().getName());
                Thread.sleep(0);
                return "";
            });
            Schedulers.parallel().schedule(task);
            task.get(10, TimeUnit.SECONDS);
            Thread.yield();
       }
    }
}

@AutoService(BlockHoundIntegration.class)
public class Config implements BlockHoundIntegration {

    @Override
    public void applyTo(BlockHound.Builder builder) {
        builder.allowBlockingCallsInside(BlockingDisallowTest.NonBlockingClass.class.getName(), "outer");
    }
}

two things:

here, outer() is invoked from the main() thread, it can block on task.get(10, TimeUnit.SECONDS), because main() is not considered as a "non blocking" thread. So, you don't have to declare "outer" as allowed to block using allowBlockingCallsInside(BlockingDisallowTest.NonBlockingClass.class.getName(), "outer");.
now, it's the code that is scheduled in the parallel scheduler which is blocking: the one calling Thread.sleep(0);.
So, if you want to add the task scheduled in the parallel executor in the white list, what you can do is extract the blocking code in a method, like this:

    static class NonBlockingClass {
	static void outer() throws ExecutionException, InterruptedException, TimeoutException {
            FutureTask<?> task = new FutureTask<>(() -> {
		    System.out.println(Thread.currentThread().getName());
		    blockingCode();
		    return "";
            });
            Schedulers.parallel().schedule(task);
            task.get(10, TimeUnit.SECONDS);
	    Thread.sleep(0);	    
            Thread.yield();
	}

	static void blockingCode() throws InterruptedException {
	    Thread.sleep(0);
	}
    }

and then you can add the blockingCode()method in the whiltelist like this:

    @Override
    public void applyTo(BlockHound.Builder builder) {
        builder
	    .allowBlockingCallsInside(BlockingDisallowTest.NonBlockingClass.class.getName(), "blockingCode");
    }

hope this helps ?

Answer 22 · 2023-07-12T13:54:42.000Z

Yes, it works on pet project. Thank you a lot! I understand it better now!

And dig deeper in my project and find out, that we got blocking call on that package
org.springframework.test.web.reactive.server

WebTestClient.ResponseSpec -> DefaultRequestBodyUriSpec.exchange()

line
ClientResponse response = (ClientResponse)DefaultWebTestClient.this.exchangeFunction.exchange(request).block(DefaultWebTestClient.this.getResponseTimeout());

Is it possible to add to whitelist methods from framework? I tried examples form https://github.com/reactor/BlockHound/blob/master/agent/src/main/java/reactor/blockhound/integration

But probably i missed something.

Answer 23 · 2023-07-12T14:16:42.000Z

you can add any methods from any classes to the whitelist.

Answer 24 · 2023-07-18T23:57:52.000Z

Hello! good day. I finally figured out this. So in my example, if we add to configuration kind of proxy name of method in my case it was lambda$outer$0 it is start working! It's name which we get from stack trace. I'm not sure but i think it looks like bug.
blockhound.tgz