Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

NettyBlockHoundIntegrationTest.testBlockingCallsInNettyThreads fails with JDK 13 #9738

Closed
normanmaurer opened this issue Oct 31, 2019 · 10 comments
Closed

NettyBlockHoundIntegrationTest.testBlockingCallsInNettyThreads fails with JDK 13 #9738

normanmaurer opened this issue Oct 31, 2019 · 10 comments
Milestone
4.1.44.Final

Comments

@normanmaurer
Copy link
Member 

[INFO] --- xml-maven-plugin:1.0.1:check-format (check-style) @ netty-transport-blockhound-tests ---
[INFO] 
[INFO] --- maven-dependency-plugin:2.10:get (get-jetty-alpn-agent) @ netty-transport-blockhound-tests ---
[INFO] Resolving org.mortbay.jetty.alpn:jetty-alpn-agent:jar:2.0.8 with transitive dependencies
[INFO] 
[INFO] --- build-helper-maven-plugin:1.10:parse-version (parse-version) @ netty-transport-blockhound-tests ---
[INFO] 
[INFO] --- maven-antrun-plugin:1.8:run (write-version-properties) @ netty-transport-blockhound-tests ---
[INFO] Executing tasks

main:
     [echo] Current commit: 47f82b6 on 2019-10-30 19:36:03 +0100
    [mkdir] Created dir: /code/transport-blockhound-tests/target/classes/META-INF
[propertyfile] Creating new property file: /code/transport-blockhound-tests/target/classes/META-INF/io.netty.versions.properties
[INFO] Executed tasks
[INFO] 
[INFO] --- maven-remote-resources-plugin:1.5:process (default) @ netty-transport-blockhound-tests ---
[INFO] 
[INFO] --- maven-resources-plugin:3.0.1:resources (default-resources) @ netty-transport-blockhound-tests ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /code/transport-blockhound-tests/src/main/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.8.0:compile (default-compile) @ netty-transport-blockhound-tests ---
[INFO] No sources to compile
[INFO] 
[INFO] --- forbiddenapis:2.2:check (check-forbidden-apis) @ netty-transport-blockhound-tests ---
[INFO] Skipping forbidden-apis checks.
[INFO] 
[INFO] --- animal-sniffer-maven-plugin:1.16:check (default) @ netty-transport-blockhound-tests ---
[INFO] Checking unresolved references to org.codehaus.mojo.signature:java18:1.0
[INFO] 
[INFO] >>> maven-bundle-plugin:2.5.4:manifest (generate-manifest) > process-classes @ netty-transport-blockhound-tests >>>
[INFO] 
[INFO] --- maven-enforcer-plugin:3.0.0-M1:enforce (enforce-maven) @ netty-transport-blockhound-tests ---
[INFO] 
[INFO] --- maven-enforcer-plugin:3.0.0-M1:enforce (enforce-tools) @ netty-transport-blockhound-tests ---
[INFO] 
[INFO] --- maven-checkstyle-plugin:3.0.0:check (check-style) @ netty-transport-blockhound-tests ---
[INFO] Starting audit...
Audit done.
[INFO] 
[INFO] --- xml-maven-plugin:1.0.1:check-format (check-style) @ netty-transport-blockhound-tests ---
[INFO] 
[INFO] --- maven-dependency-plugin:2.10:get (get-jetty-alpn-agent) @ netty-transport-blockhound-tests ---
[INFO] Resolving org.mortbay.jetty.alpn:jetty-alpn-agent:jar:2.0.8 with transitive dependencies
[INFO] 
[INFO] --- build-helper-maven-plugin:1.10:parse-version (parse-version) @ netty-transport-blockhound-tests ---
[INFO] 
[INFO] --- maven-antrun-plugin:1.8:run (write-version-properties) @ netty-transport-blockhound-tests ---
[INFO] Executing tasks

main:
     [echo] Current commit: 47f82b6 on 2019-10-30 19:36:03 +0100
   [delete] Deleting: /code/transport-blockhound-tests/target/classes/META-INF/io.netty.versions.properties
[propertyfile] Creating new property file: /code/transport-blockhound-tests/target/classes/META-INF/io.netty.versions.properties
[INFO] Executed tasks
[INFO] 
[INFO] --- maven-remote-resources-plugin:1.5:process (default) @ netty-transport-blockhound-tests ---
[INFO] 
[INFO] --- maven-resources-plugin:3.0.1:resources (default-resources) @ netty-transport-blockhound-tests ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /code/transport-blockhound-tests/src/main/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.8.0:compile (default-compile) @ netty-transport-blockhound-tests ---
[INFO] No sources to compile
[INFO] 
[INFO] --- forbiddenapis:2.2:check (check-forbidden-apis) @ netty-transport-blockhound-tests ---
[INFO] Skipping forbidden-apis checks.
[INFO] 
[INFO] --- animal-sniffer-maven-plugin:1.16:check (default) @ netty-transport-blockhound-tests ---
[INFO] Checking unresolved references to org.codehaus.mojo.signature:java18:1.0
[INFO] 
[INFO] <<< maven-bundle-plugin:2.5.4:manifest (generate-manifest) < process-classes @ netty-transport-blockhound-tests <<<
[INFO] 
[INFO] 
[INFO] --- maven-bundle-plugin:2.5.4:manifest (generate-manifest) @ netty-transport-blockhound-tests ---
[WARNING] Manifest io.netty:netty-transport-blockhound-tests:jar:5.0.0.Final-SNAPSHOT : Unused Export-Package instructions: [io.netty.*] 
[WARNING] Manifest io.netty:netty-transport-blockhound-tests:jar:5.0.0.Final-SNAPSHOT : Unused Import-Package instructions: [sun.misc.*, sun.security.*] 
[INFO] 
[INFO] --- maven-resources-plugin:3.0.1:testResources (default-testResources) @ netty-transport-blockhound-tests ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /code/transport-blockhound-tests/src/test/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.8.0:testCompile (default-testCompile) @ netty-transport-blockhound-tests ---
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 1 source file to /code/transport-blockhound-tests/target/test-classes
[INFO] 
[INFO] --- forbiddenapis:2.2:testCheck (check-forbidden-test-apis) @ netty-transport-blockhound-tests ---
[INFO] Skipping forbidden-apis checks.
[INFO] 
[INFO] --- maven-surefire-plugin:2.22.1:test (default-test) @ netty-transport-blockhound-tests ---
[INFO] 
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[WARNING] Corrupted STDOUT by directly writing to native stream in forked JVM 1. See FAQ web page and the dump file /code/transport-blockhound-tests/target/surefire-reports/2019-10-31T01-09-13_174-jvmRun1.dumpstream
[INFO] Running io.netty.util.internal.NettyBlockHoundIntegrationTest
01:33:52.851 [main] DEBUG i.n.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework
01:33:52.866 [main] DEBUG i.n.u.i.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
01:33:52.866 [main] DEBUG i.n.u.i.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 1.521 s <<< FAILURE! - in io.netty.util.internal.NettyBlockHoundIntegrationTest
[ERROR] testBlockingCallsInNettyThreads(io.netty.util.internal.NettyBlockHoundIntegrationTest)  Time elapsed: 0.32 s  <<< FAILURE!
java.lang.AssertionError: Expected an exception due to a blocking call but none was thrown
	at org.junit.Assert.fail(Assert.java:88)
	at io.netty.util.internal.NettyBlockHoundIntegrationTest.testBlockingCallsInNettyThreads(NettyBlockHoundIntegrationTest.java:48)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)

[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Failures: 
[ERROR]   NettyBlockHoundIntegrationTest.testBlockingCallsInNettyThreads:48 Expected an exception due to a blocking call but none was thrown
[INFO] 
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0
[INFO]
@normanmaurer
Copy link
Member Author

@bsideup can you have a look ? It works with all other JDK version that we use on the CI :/

@bsideup
Copy link
Contributor

bsideup commented Oct 31, 2019

@normanmaurer JDK13+ requires a flag ( -XX:+AllowRedefinitionToAddDeleteMethod ) to be set, see reactor/BlockHound#33 for more details.

We're still investigating what to do about it, since it was a behaviour change in OpenJDK's instrumentation logic...

@normanmaurer
Copy link
Member Author

@bsideup I see... I will add these to the java13 profile then for now.

@normanmaurer
Copy link
Member Author

@bsideup this did not work :(

[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.22.1:test (default-test) on project netty-transport-blockhound-tests: There are test failures.
[ERROR]
[ERROR] Please refer to /Users/norman/Documents/workspace/netty/transport-blockhound-tests/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /Users/norman/Documents/workspace/netty/transport-blockhound-tests && /Users/norman/.jabba/jdk/adopt@1.13.0-1/Contents/Home/bin/java -server -dsa -da -ea:io.netty... -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDetails -XX:+AllowRedefinitionToAddDeleteMethod -D_ -D_ -D_ -D_ -jar /Users/norman/Documents/workspace/netty/transport-blockhound-tests/target/surefire/surefirebooter16207235744509438163.jar /Users/norman/Documents/workspace/netty/transport-blockhound-tests/target/surefire 2019-10-31T11-59-30_222-jvmRun1 surefire15970040776949416610tmp surefire_08978095701992529987tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 1
[ERROR] org.apache.maven.surefire.booter.SurefireBooterForkException: The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /Users/norman/Documents/workspace/netty/transport-blockhound-tests && /Users/norman/.jabba/jdk/adopt@1.13.0-1/Contents/Home/bin/java -server -dsa -da -ea:io.netty... -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDetails -XX:+AllowRedefinitionToAddDeleteMethod -D_ -D_ -D_ -D_ -jar /Users/norman/Documents/workspace/netty/transport-blockhound-tests/target/surefire/surefirebooter16207235744509438163.jar /Users/norman/Documents/workspace/netty/transport-blockhound-tests/target/surefire 2019-10-31T11-59-30_222-jvmRun1 surefire15970040776949416610tmp surefire_08978095701992529987tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 1
[ERROR] 	at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:669)
[ERROR] 	at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:282)
[ERROR] 	at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:245)
[ERROR] 	at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1183)
[ERROR] 	at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1011)
[ERROR] 	at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:857)
[ERROR] 	at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
[ERROR] 	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
[ERROR] 	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:154)
[ERROR] 	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:146)
[ERROR] 	at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
[ERROR] 	at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
[ERROR] 	at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
[ERROR] 	at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
[ERROR] 	at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:309)
[ERROR] 	at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:194)
[ERROR] 	at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:107)
[ERROR] 	at org.apache.maven.cli.MavenCli.execute(MavenCli.java:955)
[ERROR] 	at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:290)
[ERROR] 	at org.apache.maven.cli.MavenCli.main(MavenCli.java:194)
[ERROR] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[ERROR] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[ERROR] 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[ERROR] 	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
[ERROR] 	at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
[ERROR] 	at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
[ERROR] 	at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
[ERROR] 	at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
[ERROR] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[ERROR] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[ERROR] 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[ERROR] 	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
[ERROR] 	at org.apache.maven.wrapper.BootstrapMainStarter.start(BootstrapMainStarter.java:39)
[ERROR] 	at org.apache.maven.wrapper.WrapperExecutor.execute(WrapperExecutor.java:122)
[ERROR] 	at org.apache.maven.wrapper.MavenWrapperMain.main(MavenWrapperMain.java:60)
[ERROR]
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException

@bsideup
Copy link
Contributor

bsideup commented Oct 31, 2019

@normanmaurer on it, trying locally

@normanmaurer
Copy link
Member Author

@bsideup thanks... PRs welcome :)

@bsideup
Copy link
Contributor

bsideup commented Oct 31, 2019

@normanmaurer interesting. It works when I run BlockHound's tests with Java 13 but fails in Netty.
I will continue the investigation and eventually send a PR.

Trying to find how to check that the flag is actually set in the tests' JVM...

@bsideup
Copy link
Contributor

bsideup commented Oct 31, 2019 •
edited

status update:
I am still unable to fix it in Netty, although it seems to work in isolation:
https://gist.github.com/bsideup/02d09c5723d956b27c958fa881de5495

Checking whether it is a problem with BlockHound or with the whitelisting we do in the integration, so that the call is instrumented but not reported

update 2:
running it from IntelliJ with JDK13 + -XX:+AllowRedefinitionToAddDeleteMethods works. Seems to be something related to Maven...

@bsideup bsideup mentioned this issue Oct 31, 2019
Merged
@bsideup
Copy link
Contributor

bsideup commented Oct 31, 2019

Ok, it seems that Maven was using an old SNAPSHOT from pre-BlockHound era, this is why running it with IDEA was giving me a positive result but with Maven I was getting errors.

I submitted #9742 with a simple profile-based fix, and will submit another one with a test checking that ServiceLoader can load the integration

bsideup added a commit to bsideup/netty that referenced this issue Oct 31, 2019
@bsideup
Test that NettyBlockHoundIntegration can be loaded with `ServiceLoa…
7f55b86 
…der`

Motivation:

If something is mis-configured, the "main" test will fail but it is unclear
whether it fails because the integration does not work or it wasn't applied
at all.
Also see:
netty#9738 (comment)

Modifications:

This change adds a test that uses the same mechanism as BlockHound does
(`ServiceLoader`) and checks that `NettyBlockHoundIntegration` is present.

Result:

It is now clear whether the integration is not working or it wasn't loaded at all.
@bsideup bsideup mentioned this issue Oct 31, 2019
Merged
@bsideup
Copy link
Contributor

bsideup commented Oct 31, 2019

Ok, I think now we're good :) #9743 is an optional addition to make it easier to debug issues in future, since I spent quite some time fighting with JDK13 while the problem was in my Maven setup and Maven's vision on how modular projects should be built 😅

@normanmaurer normanmaurer added this to the 4.1.44.Final milestone Nov 1, 2019
normanmaurer pushed a commit that referenced this issue Nov 1, 2019
@bsideup @normanmaurer
Test that NettyBlockHoundIntegration can be loaded with `ServiceLoa…
cedfa41 
…der` (#9743)

Motivation:

If something is mis-configured, the "main" test will fail but it is unclear
whether it fails because the integration does not work or it wasn't applied
at all.
Also see:
#9738 (comment)

Modifications:

This change adds a test that uses the same mechanism as BlockHound does
(`ServiceLoader`) and checks that `NettyBlockHoundIntegration` is present.

Result:

It is now clear whether the integration is not working or it wasn't loaded at all.
normanmaurer pushed a commit that referenced this issue Nov 1, 2019
@bsideup @normanmaurer
Test that NettyBlockHoundIntegration can be loaded with `ServiceLoa…
6591a65 
…der` (#9743)

Motivation:

If something is mis-configured, the "main" test will fail but it is unclear
whether it fails because the integration does not work or it wasn't applied
at all.
Also see:
#9738 (comment)

Modifications:

This change adds a test that uses the same mechanism as BlockHound does
(`ServiceLoader`) and checks that `NettyBlockHoundIntegration` is present.

Result:

It is now clear whether the integration is not working or it wasn't loaded at all.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
4.1.44.Final
Development

No branches or pull requests
2 participants
@normanmaurer @bsideup