Byteman and JDK 10.0.1

[ehugonnet]

Hi,

While my test using BMUnit is working nicely on Java 9 it fails on Oracle JDK 10.0.1 with the following error from Surefire :

# Created at 2018-06-20T12:08:53.880

Corrupted STDOUT by directly writing to native stream in forked JVM 1. Stream 'Invoking lock of ContentRepositoryImpl'.

java.lang.IllegalArgumentException: Stream stdin corrupted. Expected comma after third character in command 'Invoking lock of ContentRepositoryImpl'.

    at org.apache.maven.plugin.surefire.booterclient.output.ForkClient$OperationalData.<init>(ForkClient.java:511)

    at org.apache.maven.plugin.surefire.booterclient.output.ForkClient.processLine(ForkClient.java:209)

    at org.apache.maven.plugin.surefire.booterclient.output.ForkClient.consumeLine(ForkClient.java:176)

    at org.apache.maven.plugin.surefire.booterclient.output.ThreadedStreamConsumer$Pumper.run(ThreadedStreamConsumer.java:88)

    at java.base/java.lang.Thread.run(Thread.java:844)

.... which are traceln in my rule.

And I have the following message in maven  console :

[WARNING] Corrupted STDOUT by directly writing to native stream in forked JVM 1. See FAQ web page and the dump file /home/ehsavoie/dev/wildfly/core/deployment-repository/target/surefire-reports/2018-06-20T12-10-52_497-jvmRun1.dumpstream

[DEBUG] Creating countDown for org.jboss.as.repository.ContentRepositoryImpl@32b260fa

[DEBUG] Invoking lock of ContentRepositoryImpl

[DEBUG] org.jboss.as.repository.ContentRepositoryImpl.lock(ContentRepositoryImpl.java:526)

[DEBUG] org.jboss.as.repository.ContentRepositoryImpl.removeContent(ContentRepositoryImpl.java:297)

[DEBUG] org.jboss.as.repository.DeletionCollisionTest.lambda$testFileLockByRemoveContent$2(DeletionCollisionTest.java:108)

[DEBUG] java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)

[DEBUG] java.util.concurrent.FutureTask.run(FutureTask.java:264)

[DEBUG] java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135)

[DEBUG] java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)

[DEBUG] java.lang.Thread.run(Thread.java:844)

[DEBUG] I'm byteman and waiting for 3s org.jboss.as.repository.ContentRepositoryImpl@32b260fa

which leads me to think that the rule is working properly.

....

The forked VM terminated without properly saying goodbye. VM crash or System.exit called?

Command was /bin/sh -c cd /home/ehsavoie/dev/wildfly/core/deployment-repository && /usr/lib/jvm/java-10-oracle/bin/java -javaagent:/home/ehsavoie/.m2/repository/org/jboss/byteman/byteman/4.0.2/byteman-4.0.2.jar=port:17091,address:127.0.0.1,boot:/home/ehsavoie/.m2/repository/org/jboss/byteman/byteman/4.0.2/byteman-4.0.2.jar --add-exports=java.base/sun.nio.ch=ALL-UNNAMED --illegal-access=permit -Dsun.util.logging.disableCallerCheck=true -Djdk.attach.allowAttachSelf=true -ea -Duser.region=US -Duser.language=en -Duser.timezone=America/Chicago -XX:MaxMetaspaceSize=256m -jar /home/ehsavoie/dev/wildfly/core/deployment-repository/target/surefire/surefirebooter1741649362879056134.jar /home/ehsavoie/dev/wildfly/core/deployment-repository/target/surefire 2018-06-20T12-10-52_497-jvmRun1 surefire3786702292358327602tmp surefire_01211028534385003857tmp

Process Exit Code: 0

Crashed tests:

org.jboss.as.repository.DeletionCollisionTest

I've tried to update to the latest versions of Surefire / Byteman (aka 4.0.2 and even current master) with no changes at all in the 'result'.

Am I missing something ?

[adinn]

Hi Emmanuel,

It looks like your rules are writing debug (and/or possibly verbose) output to System.out. However, the test also seems to rely on parsing output read from System.out. So, it looks like the Byteman output may be foiling the expectations of the prser.

I'm not quite sure why you are seeing a difference between JDK9 and JDK10 but that may be to do with when System.out gets picked up and used for output (it can depend upon the timing of when the Byteman agent gets loaded --- see BYTEMAN-370 for a related problem).

Perhaps you could disable generation of debug and/or verbose output for the test and see if that is the cause. Is your maven pom configuring properties -Dorg.jboss.byteman.verbose or -Dorg.jboss.byteman.debugu onthe command line or via a property setting in the test exec config? Alternatively, does any of your test classes include a BMUnitConfig annotation which specifies set debug=true or verbose=true?

regards,

Andrew Dinn

[ehugonnet]

I commented out the org.jboss.byteman.verbose being set to true and moved all my System.out to traceln.

I don't have a BMUnitConfig annotation either.

Removing the traces from the rule creates the following dump:

# Created at 2018-06-20T07:13:24.206

Unexpected IOException: 6,1,org.jboss.as.repository.DeletionCollisionTest,testFileLockByRemoveContent(org.jboss.as.repository.DeletionCollisionTest),null,null,null

# Created at 2018-06-20T07:13:24.207

Unexpected IOException: 5,1,org.jboss.as.repository.DeletionCollisionTest,testFileLockByReadContent(org.jboss.as.repository.DeletionCollisionTest),null,null,null

# Created at 2018-06-20T07:13:27.264

Unexpected IOException: 6,1,org.jboss.as.repository.DeletionCollisionTest,testFileLockByReadContent(org.jboss.as.repository.DeletionCollisionTest),null,null,null

# Created at 2018-06-20T07:13:27.267

Unexpected IOException: 2,1,org.jboss.as.repository.DeletionCollisionTest,org.jboss.as.repository.DeletionCollisionTest,null,null,null

I guess i'll try to debug and see where does this exception comes from.

[adinn]

Hi Emmanuel,

ehugonnet  wrote:

. . .

I guess i'll try to debug and see where does this exception comes from.

Well, since you already have Byteman installed I was going to suggest you inject a rule into the constructor for IOException and have it call traceStack() but . . . err . . . ;-)

Actually, that will work if you avoid writing to System.out. if you open a trace stream to a file and call traceStack passing the traceStream label object as 1st argument that should show you where the IOException is being generated.

RULE trace IOException create
CLASS IOException
METHOD 
AT EXIT
DO traceOpen("foo", "/tmp/foo.log");
  traceStack("foo");
ENDRULE

Note that the traceOpen call will open the stream first time the rule fires, returning true. At subsequent firings traceOpen will find an existing trace stream and return false.

[ehugonnet]

Using the stream I can get my own traces to work properly but I don't get any information on that IOException

Creating countDown org.jboss.as.repository.ContentRepositoryImpl@6b81ce95

Invoking lock of ContentRepositoryImpl

org.jboss.as.repository.ContentRepositoryImpl.lock(ContentRepositoryImpl.java:526)

org.jboss.as.repository.ContentRepositoryImpl.removeContent(ContentRepositoryImpl.java:297)

org.jboss.as.repository.DeletionCollisionTest.lambda$testFileLockByRemoveContent$2(DeletionCollisionTest.java:108)

java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)

java.util.concurrent.FutureTask.run(FutureTask.java:264)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)

java.lang.Thread.run(Thread.java:844)

I'm byteman and waiting for 3s org.jboss.as.repository.ContentRepositoryImpl@6b81ce95

Creating countDown org.jboss.as.repository.ContentRepositoryImpl@17a7f733

Invoking lock of ContentRepositoryImpl

org.jboss.as.repository.ContentRepositoryImpl.lock(ContentRepositoryImpl.java:526)

org.jboss.as.repository.ContentRepositoryImpl.readContent(ContentRepositoryImpl.java:549)

org.jboss.as.repository.DeletionCollisionTest.lambda$testFileLockByReadContent$0(DeletionCollisionTest.java:84)

java.util.concurrent.FutureTask.run(FutureTask.java:264)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)

java.lang.Thread.run(Thread.java:844)

I'm byteman and waiting for 3s org.jboss.as.repository.ContentRepositoryImpl@17a7f733

This is the fork command line and I don't see anything that might explain the problem:

[DEBUG] Forking command line: /bin/sh -c cd /home/ehsavoie/dev/wildfly/core/deployment-repository && /usr/lib/jvm/java-10-oracle/bin/java -javaagent:/home/ehsavoie/.m2/repository/org/jboss/byteman/byteman/4.0.2/byteman-4.0.2.jar=port:17091,address:127.0.0.1,boot:/home/ehsavoie/.m2/repository/org/jboss/byteman/byteman/4.0.2/byteman-4.0.2.jar --add-exports=java.base/sun.nio.ch=ALL-UNNAMED --illegal-access=permit -Dsun.util.logging.disableCallerCheck=true -Djdk.attach.allowAttachSelf=true -ea -Duser.region=US -Duser.language=en -Duser.timezone=America/Chicago -XX:MaxMetaspaceSize=256m -jar /home/ehsavoie/dev/wildfly/core/deployment-repository/target/surefire/surefirebooter2278813165425487078.jar /home/ehsavoie/dev/wildfly/core/deployment-repository/target/surefire 2018-06-20T21-28-42_073-jvmRun1 surefire17876840788029691173tmp surefire_02875681530915692789tm

I'm METHOD <init> AT EXIT on IOException but no trace at all. I'm wondering if the IOException occurs between the maven run and the forked process (so out of byteman scope).

[adinn]

Hi Emmanuel,

Hmm, that's weird. Yes, the exception is probably in the Maven driver JVM rather than the one running the Byteman agent. I'm not sure what more help I can offer here as it stands(Maven, eh? :-). Let me know if you can find out more about what is causing the problem.

regadrs,

Andrew Dinn