Rule.execute for decommissioned key

[ochaloup]

Hi adinn,

I'm here with like a dummy question. Unfortunately I'm not even capable to describe it somehow technically. I feel my problem is caused by some random memory swaps or by the mood of my JVM Anyway...

I run JBoss EAP 7.1.0/Wildfly 13 with JTA crash quickstart for OpenShift enriched with the byteman rules: openshift-quickstarts/xa.btm at master · jboss-openshift/openshift-quickstarts. The result of starting the app server with Byteman and then invoking the servlet to start a XA transaction to send message to JMS broker queue and make changes in H2 database ends with Byteman messages

Rule.execute called for Start a count down when a 2 phase transaction starts_0

Start a count down when a 2 phase transaction starts execute

Rule.execute called for Generate an XA Recovery Record_2

Rule.execute for decommissioned key Generate an XA Recovery Record_2

Rule.execute called for Trace topLevelCommit (phase 2 of a 2PC transaction)_1

Rule.execute for decommissioned key Trace topLevelCommit (phase 2 of a 2PC transaction)_1

Rule.execute called for Generate an XA Recovery Record_2

Rule.execute for decommissioned key Generate an XA Recovery Record_2

Rule.execute called for Trace topLevelCommit (phase 2 of a 2PC transaction)_1

Rule.execute for decommissioned key Trace topLevelCommit (phase 2 of a 2PC transaction)_1

I do change in WFLY bin/standalone.conf in way

JAVA_OPTS="-javaagent:/opt/byteman/lib/byteman.jar=script:/home/ochaloup/tmp/xa.btm,boot:/opt/byteman/lib/byteman.jar -Djboss.modules.system.pkgs=org.jboss.byteman\
  -Dorg.jboss.byteman.transform.all -Dorg.jboss.byteman.verbose -Dorg.jboss.byteman.debug=true"

The point is that the error of invoking of the Byteman rule does not happen each execution. It fails sometime and sometime the app server runs the rules correctly (no messages "for decommissioned key..." are shown).

I can't track how to fix the issue in the deterministic way for getting the rules to run correctly all the time. I found your response at Trying to instrument the Command Line with Byteman and I was thinking if there is not a multiple jars on the classpath or if there could be some issue on loading order of jars onto the classpath. But after doublechecking there is only one byteman jar defined and any variation of the "boot:" value has no effect. Neither trying various versions of Byteman library itself.

Even there is no many pointers in my text here wouldn't you have an idea what to check?

Thanks

Ondra

[adinn]

Hi Ondra,

Well, you managed to explain the problem quite effectively so I don't think this counts as a dummy question.

It looks very much like you are seeing a similar circumstance to the one Francesco encountered i.e. there are two versions of the Byteman code getting loaded, one via the bootstrap loader and one via the sys loader, and hence two versions of the hash map containing the String keys. That seems to be the most likely thing since, obviously, your code is no unloading rules.

The fact that it happens occasionally rather than all the time also makes sense and suggests to me why it is happening. I suspect there is a class in one of the jars your app loads -- perhaps in WFLY itself -- that includes a link reference to a Byteman class (i.e. one of the classes in the Byteman agent jar is named as a class in its class pool). Now lazy loading is not a deterministic process. So, in some cases that reference may be resolved before the Byteman jar has been hoisted into the bootstrap and in other cases it may be resolved after hoisting. That will be enough to cause the problem you are seeing. n.b. it does not need to be class Transformer itself that is referenced -- a reference to other Byteman classes (such as Rule) could be enough to cause this problem.

The most likely culprit is a Byteman helper class (there is little or no reason for any other classes to reference Byteman-specific classes). Of course, the most likely culprit amongst those culprits is your own helper jar (but I'll assume you have ruled that out :-). I suggest you unpack the classes in your app jars and the WFLY jars and run a grep over them to see if the String "org.jboss.byteman" appears anywhere unexpected.

regards,

Andrew Dinn

[ochaloup]

thanks adinn

It's kind of strange...

As I found your response to Francesco I already searched the code for byteman occurrences. In fact the deployed jta quickstart is really simple there is no dependencies to byteman which I'm aware of and the byteman script uses just the default byteman helper class. I  can't find any jboss jar that would contain the classes of byteman itself (when you unpack jar and check what are classes they bring together).

I tried to run the quickstart with the JVM flags: -verbose:class -verbose:jni

My chain of thoughts is:

I want to check if a byteman class is loaded twice. If I define the byteman.jar with 'boot:<path/to/byteman.jar>' or with '-Xbootclasspath/a:<path/to/byteman.jar>' the byteman classes are always loaded by this classloader (at least for jboss modules). I mean the request for the class is redirected to the most upward classloader which means to boot classloader. If there will be class defined somewhere in a jboss module I can expect the class will be shown to be loaded twice. But I haven't found any such class (cat sysout.log | grep -e 'Loaded.*org.jboss.byteman' | sort). Am I wrong in this expectation?

More about internals. I can see the rule says

Rule.execute called for Generate an XA Recovery Record_2

Does it means there is somewhere already created rule "Rule.execute called for Generate an XA Recovery Record_1"? I mean the rule was created for second time but it was put under another classloader and now they do not match?

Thanks again

Ondra

[adinn]

Hi Ondra,

ochaloup  wrote:

As I found your response to Francesco I already searched the code for byteman occurrences. In fact the deployed jta quickstart is really simple there is no dependencies to byteman which I'm aware of and the byteman script uses just the default byteman helper class. I  can't find any jboss jar that would contain the classes of byteman itself (when you unpack jar and check what are classes they bring together).

I was not suggesting that a Byteman class might be in a  WFLY jar, merely that a WFLY class might include a link reference to a Byteman class.

ochaloup  wrote:

thanks adinn 

I tried to run the quickstart with the JVM flags: -verbose:class -verbose:jni

My chain of thoughts is:

I want to check if a byteman class is loaded twice. If I define the byteman.jar with 'boot:<path/to/byteman.jar>' or with '-Xbootclasspath/a:<path/to/byteman.jar>' the byteman classes are always loaded by this classloader (at least for jboss modules). I mean the request for the class is redirected to the most upward classloader which means to boot classloader. If there will be class defined somewhere in a jboss module I can expect the class will be shown to be loaded twice. But I haven't found any such class (cat sysout.log | grep -e 'Loaded.*org.jboss.byteman' | sort). Am I wrong in this expectation?

No, your expectation is correct. If the problem is to do with having two versions of the hash data in the system then you should be seeing at least one Byteman class being loaded twice. However, the attached file doesn't appear to contain any details of loaded files.

ochaloup  wrote:

More about internals. I can see the rule says

Rule.execute called for Generate an XA Recovery Record_2

Does it means there is somewhere already created rule "Rule.execute called for Generate an XA Recovery Record_1"? I mean the rule was created for second time but it was put under another classloader and now they do not match?

No, the number appended after the underscore is just a global counter that is incremented each time an injection occurs. If the rule was injected twice you might see the strings

More about internals. I can see the rule says
Rule.execute called for Generate an XA Recovery Record_2
Does it means there is somewhere already created rule "Rule.execute called for Generate an XA Recovery Record_1"? I mean the rule was created for second time but it was put under another classloader and now they do not match?

No, the number appended after the underscore is just a global counter that is incremented each time an injection occurs. If the rule was injected twice in a row you might see the strings "Generate an XA Recovery Record_1" and "Generate an XA Recovery Record_2". However, note two things

Firstly,

it is sometimes legitimate to inject the same rule twice e.g.

RULE inject into every Thread's run method

CLASS ^Thread

METHOD run()

. . .

or

RULE inject into add(value) and add(index, value)

INTERFACE List

METHOD add

. . .

Secondly, multiple injections is not going to account the behaviour you are seeing. What is happening is nothing to do with two versions of the rule. The code which does the injection and registers the String key in the hashtable is accessing that hashtable from a field of class Transformer as loaded in the bootstrap loader. However the injected code which looks  up the key in the hashtable is accessing it form a field of class Transformer as loaded by some other loader (probably the system loader).

Are you running this using maven? If so then it may well be that maven is replacing the system loader during startip and then failing to correctly delegate requests to lookup Byteman classes from subordinate (i.e. JBoss Modules)  loaders to the bootstrap loader, with the result that it's system loader is loading its own version of the Byteman classes.

regards,

Andrew Dinn

[ochaloup]

Pretty thanks adinn. I have few more findings after started to debug the code. But I haven't understood the cause yet.

First, sorry I added the log with class loading. I'm adding it again now (cat byteman-decomission-class-loading-server.log | grep org.jboss.byteman | sort | uniq -d). But I think the reason is not in double loading of the byteman classes. During my testing I tried the get the byteman being loaded by system class loader (I just used the 'sys:' property) but the behaviour is the same. I was thinking if system classloader can do some change from your point

If so then it may well be that maven is replacing the system loader during startip and then failing to correctly delegate requests to lookup Byteman classes from subordinate

To clarify I do not use maven I just run WildFly server, I do change the bin/standalone.conf to pass the byteman javaagent property to JAVA_OPTS.

After that I decided to check how is it with this unloading the rules. And what I can say the rules are really unloaded at some point of processing. I looked at the Rule class and methods getKey and purge

byteman/Rule.java at master · bytemanproject/byteman · GitHub

byteman/Rule.java at master · bytemanproject/byteman · GitHub

I can see the same rule is added twice, each time under different key, differentiated with the _# suffix. That's what you described above.

And I can observe the the flow like (I'm not sure about precise order to be honest):

the rule key is created during time the rule is injected at a trigger point (byteman/RuleTriggerMethodAdapter.java at master) -> at that time the key is generated and the Rule map ruleKeyMap is filled -> a code do some reflection changes which causes regeneration of the byteman rules -> rule is purged from the ruleKeyMap -> injecting trigger again with generating new rule in the ruleKeyMap -> trigger point is reached by program execution -> the injection point invokes the rule with the old name (which was already removed from the ruleKeyMap)

I think there is not a trouble with class loading (being done twice) from other reason as well. The xa.btm contains three rules (if you check here openshift-quickstarts/xa.btm at master · jboss-openshift/openshift-quickstarts · GitHub). One is bound to com.arjuna.ats.arjuna.coordinator.BasicAction. That's correctly executed all the time. Then there are two other bound to com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord#topLevelCommit. None of them is executed correctly - both are decommisioned. If I change the both rules to be bound to ^AbstractRecord#topLevelCommit instead the rules are executed fine (it seems in deterministic way).

Now this is the stacktrace where the the purge from ruleKeyMap happens

Thread [MSC service thread 1-5] (Suspended (breakpoint at line 881 in Rule)) 
 owns: RuleScript  (id=338) 
 Rule.purge() line: 881 
 RuleScript.purge(ClassLoader, String) line: 376 
 TransformContext.transform(byte[]) line: 85 
 Transformer.transform(RuleScript, ClassLoader, String, byte[]) line: 746 
 Transformer.tryTransform(byte[], String, ClassLoader, String, boolean, boolean) line: 813 
 Transformer.tryTransform(byte[], String, ClassLoader, String, boolean) line: 785 
 Transformer.transform(ClassLoader, String, Class, ProtectionDomain, byte[]) line: 258 
 TransformerManager.transform(ClassLoader, String, Class, ProtectionDomain, byte[]) line: 188 
 InstrumentationImpl.transform(ClassLoader, String, Class, ProtectionDomain, byte[], boolean) line: 428 
 ClassLoader.defineClass1(String, byte[], int, int, ProtectionDomain, String) line: not available [native method] 
 ModuleClassLoader(ClassLoader).defineClass(String, byte[], int, int, ProtectionDomain) line: 763 
 ModuleClassLoader.doDefineOrLoadClass(String, byte[], int, int, ProtectionDomain) line: 358 
 ModuleClassLoader.defineClass(String, ClassSpec, ResourceLoader) line: 437 
 ModuleClassLoader.loadClassLocal(String, boolean) line: 274 
 ModuleClassLoader$1.loadClassLocal(String, boolean) line: 77 
 Module.loadModuleClass(String, boolean) line: 713 
 ModuleClassLoader.findClass(String, boolean, boolean) line: 190 
 ModuleClassLoader(ConcurrentClassLoader).performLoadClassUnchecked(String, boolean, boolean) line: 412 
 ModuleClassLoader(ConcurrentClassLoader).performLoadClass(String, boolean, boolean) line: 400 
 ModuleClassLoader(ConcurrentClassLoader).loadClass(String) line: 116 
 Class.getDeclaredMethods0(boolean) line: not available [native method] 
 Class.privateGetDeclaredMethods(boolean) line: 2701 
 Class.getDeclaredMethod(String, Class...) line: 2128 
 JBossJTALocalTransactionProvider.lambda$static$0() line: 71 
 167706628.run() line: not available 
 AccessController.doPrivileged(PrivilegedAction) line: not available [native method] 
 JBossJTALocalTransactionProvider.() line: 69 
 JBossLocalTransactionProvider$Builder.build() line: 746 
 LocalTransactionContextService.start(StartContext) line: 57 
 ServiceControllerImpl$StartTask.startService(Service, StartContext) line: 2032 
 ServiceControllerImpl$StartTask.run() line: 1955 
 ServiceContainerImpl$ContainerExecutor(ThreadPoolExecutor).runWorker(ThreadPoolExecutor$Worker) line: 1149 
 ThreadPoolExecutor$Worker.run() line: 624 
 ServiceContainerImpl$ServiceThread(Thread).run() line: 748 

It's reflection from wildfly transaction client at wildfly-transaction-client/JBossJTALocalTransactionProvider.java at master · wildfly/wildfly-transaction-client · GitHub

Now my doubt - do you think there could be issue in Byteman that do not remove injection trigger when re-creation of the key happens? Or is there possibility of some wrong reflection handling at the wfly txn client?

[adinn]

Hi Ondra,

Ok, so this is starting to make some more sense now. I'm not clear exactly what the scenario is you are describing with this comment

the rule key is created during time the rule is injected at a trigger point (byteman/RuleTriggerMethodAdapter.java at master) -> at that time the key is generated and the Rule map ruleKeyMap is filled -> a code do some reflection changes which causes regeneration of the byteman rules -> rule is purged from the ruleKeyMap -> injecting trigger again with generating new rule in the ruleKeyMap -> trigger point is reached by program execution -> the injection point invokes the rule with the old name (which was already removed from the ruleKeyMap)

When you say "a code do some reflection changes which causes regeneration of the byteman rules" what does that mean?

The interesting thing for me is the stack trace:

Thread [MSC service thread 1-5] (Suspended (breakpoint at line 881 in Rule))   
 owns: RuleScript  (id=338)   
 Rule.purge() line: 881   
 RuleScript.purge(ClassLoader, String) line: 376   
 TransformContext.transform(byte[]) line: 85   
 Transformer.transform(RuleScript, ClassLoader, String, byte[]) line: 746   
 Transformer.tryTransform(byte[], String, ClassLoader, String, boolean, boolean) line: 813   
 Transformer.tryTransform(byte[], String, ClassLoader, String, boolean) line: 785   
 Transformer.transform(ClassLoader, String, Class, ProtectionDomain, byte[]) line: 258   
 TransformerManager.transform(ClassLoader, String, Class, ProtectionDomain, byte[]) line: 188   
 InstrumentationImpl.transform(ClassLoader, String, Class, ProtectionDomain, byte[], boolean) line: 428   
 ClassLoader.defineClass1(String, byte[], int, int, ProtectionDomain, String) line: not available [native method]   
 ModuleClassLoader(ClassLoader).defineClass(String, byte[], int, int, ProtectionDomain) line: 763   
 ModuleClassLoader.doDefineOrLoadClass(String, byte[], int, int, ProtectionDomain) line: 358   
 ModuleClassLoader.defineClass(String, ClassSpec, ResourceLoader) line: 437   
 ModuleClassLoader.loadClassLocal(String, boolean) line: 274   
 ModuleClassLoader$1.loadClassLocal(String, boolean) line: 77   
 Module.loadModuleClass(String, boolean) line: 713   
 ModuleClassLoader.findClass(String, boolean, boolean) line: 190   
 ModuleClassLoader(ConcurrentClassLoader).performLoadClassUnchecked(String, boolean, boolean) line: 412   
 ModuleClassLoader(ConcurrentClassLoader).performLoadClass(String, boolean, boolean) line: 400   
 ModuleClassLoader(ConcurrentClassLoader).loadClass(String) line: 116   
 Class.getDeclaredMethods0(boolean) line: not available [native method]   
 Class.privateGetDeclaredMethods(boolean) line: 2701   
 Class.getDeclaredMethod(String, Class...) line: 2128   
 JBossJTALocalTransactionProvider.lambda$static$0() line: 71   
 167706628.run() line: not available   
 AccessController.doPrivileged(PrivilegedAction) line: not available [native method]   
 JBossJTALocalTransactionProvider.() line: 69   
 JBossLocalTransactionProvider$Builder.build() line: 746   
 LocalTransactionContextService.start(StartContext) line: 57   
 ServiceControllerImpl$StartTask.startService(Service, StartContext) line: 2032   
 ServiceControllerImpl$StartTask.run() line: 1955   
 ServiceContainerImpl$ContainerExecutor(ThreadPoolExecutor).runWorker(ThreadPoolExecutor$Worker) line: 1149   
 ThreadPoolExecutor$Worker.run() line: 624   
 ServiceContainerImpl$ServiceThread(Thread).run() line: 748   

This is happening when a class is being transformed at load time (i.e. under ClassLoader.defineClass1). The critical thing is what goes on in the call to RuleScript.purge(ClassLoader, String) that is made from TransformContext.transform(byte[]).

The RuleScript identifies the text for a single Byteman rule. It has an associated set of transforms which tracks all the locations it has been injected into. There may be more than one injection location per trigger class (i.e. injection target) either multiple points in a given method or even location sin multiple methods. However, those locations are split into distinct sets, indexed by classloader and trigger class name. Note that for a given class loader and name that key pair should identify a trigger class uniquely.

The purge operation occurs when a the transformer is trying to inject a specific rule script into a specific trigger class. It's purpose is to remove transform records associated with prior injections of that same rule script into the trigger class. However, I'm not really clear why there would ever be any such records in the situation you are observing. The class has just been loaded, the transformer has fond all scripts which might refer to methods in this trigger class and it is in the process of iterating over those scripts, injecting them one after another into the just loaded class's bytecode. It should only find existing transform records for a given script when perfoming a retransform.

Are you able to reproduce this reliably? If so can you either trace or debug the code that updates the info stored in field RuleScript.transformSets to see how the relevant entry is being added and then purged. It may be that there is a bug in this code.

regards,

Andrew Dinn

[ochaloup]

Hi Andrew,

I will try to clarify my previous post and add a bit more.

First yes I'm able to reproduce it easily. I will write the scenario in more details. I hope it will be more comprehensible and better connected with the observation.

If you are interested I can provide steps how I run this and how it could be reproduced (hopefully) by you too.

1. with debugging I track the execution of three rules - openshift-quickstarts/xa.btm at master · jboss-openshift/openshift-quickstarts · GitHub - "Start a count down when a 2 phase transaction starts", "com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord", "Trace topLevelCommit (phase 2 of a 2PC transaction)". I do track only what happens in Rule class mostly.
2. I'm starting WildFly with bytemen agent and boot option
3. The first rule  "Start a count down when a 2 phase transaction starts" invokes method RuleScript#purge(CL, String). As there was no such rule in the transformerSet it returns. The classloader in use is:
   ModuleClassLoader for Module "org.jboss.jts" from local module loader @52aa2946 (finder: local module finder @4de5031f (roots: /home/ochaloup/jboss/jboss-eap-7.1.0.GA/modules,/home/ochaloup/jboss/jboss-eap-7.1.0.GA/modules/system/layers/base))
   As I was checking the same classloader is used for any #purge operation mentioned in this listing.
4. RuleTriggerMethodAdapter#injectTriggerPoint is invoked. There is no key (Rule#getKey) for this rule thus the new key is generated (it's indexed from 0 thus Start a count down when a 2 phase transaction starts_0).
5. The same action happens for next two rules. The Rule#ruleKeyMap contains 3 rules of names: Start a count down when a 2 phase transaction starts_0, Trace topLevelCommit (phase 2 of a 2PC transaction)_1 and Generate an XA Recovery Record_2
6. There is invoked static {} class block from wildfly-transaction-client/JBossJTALocalTransactionProvider.java at master · wildfly/wildfly-transaction-client
   This is the place which the stacktrace presented in my previous post was from (i.e. under ClassLoader.defineClass1). Please check the java code you can see what is the reflection call there. It does not touch the XAResourceRecord but it works with txn synchronization. I bet there is some transitive bytecode dependency which causes that code transformation happens and the Byteman regenerates the injection points.
7. For the rules "com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord", "Trace topLevelCommit (phase 2 of a 2PC transaction)" happens following (the rule "Start a count down when a 2 phase transaction starts" stays untouched with existing key in Rule#ruleKeyMap of name Start a count down when a 2 phase transaction starts_0
   1. RuleScript#purge(CL, String)is called. The class loader is the module class loader for jts (as mentioned above). The trigger classname is "com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord"
   2. As there is a rule in the transformSets then there is called Rule#purge. The Rule#ruleKeyMap is removed from both Trace topLevelCommit (phase 2 of a 2PC transaction)_1 and Generate an XA Recovery Record_2
   3. RuleTriggerMethodAdapter#injectTriggerPoint is called. There is new rule instance (if I understand the transaformers set was cleaned during purge) and the rule key is generated. We get two new rule keys which are put to Rule#ruleKeyMap: Trace topLevelCommit (phase 2 of a 2PC transaction)_3 and Generate an XA Recovery Record_4
   4. Server is started and business logic which does commit is invoked. We can see in the log that the rules bound to topLevelCommit was invoked twice. Here I tip there are two injection points as there were two calls on the RuleTriggerMethodAdapter#injectTriggerPoint we have two invocation of the rule.[1]
   5. Rule#execute(String key, Object recipient, Object[] args) method is called. It's called twice for each rule as it was mentioned. The key is the same both time. There is not passed e.g. the Generate an XA Recovery Record_3 . Here I do not understand how the trigger bytecode is created neither how the execute method is launched as the trace of the execute is [2].

[1]

16:38:22,103 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Rule.execute called for Start a count down when a 2 phase transaction starts_0
16:38:22,104 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Start a count down when a 2 phase transaction starts execute
16:38:22,104 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Starting countdown at 5
16:38:27,031 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Rule.execute called for Generate an XA Recovery Record_2
16:38:27,031 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Rule.execute for decommissioned key Generate an XA Recovery Record_2
16:38:31,823 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Rule.execute called for Trace topLevelCommit (phase 2 of a 2PC transaction)_1
16:38:31,823 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Rule.execute for decommissioned key Trace topLevelCommit (phase 2 of a 2PC transaction)_1
16:38:36,247 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Rule.execute called for Generate an XA Recovery Record_2
16:38:36,247 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Rule.execute for decommissioned key Generate an XA Recovery Record_2
16:38:40,559 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Rule.execute called for Trace topLevelCommit (phase 2 of a 2PC transaction)_1
16:38:40,559 INFO  [stdout] (Thread-0 (ActiveMQ-client-global-threads)) Rule.execute for decommissioned key Trace topLevelCommit (phase 2 of a 2PC transaction)_1

[2]

Thread [default task-1] (Suspended (breakpoint at line 767 in Rule)) 
 owns: AtomicAction  (id=351) 
 Rule.execute(String, Object, Object[]) line: 767 
 AtomicAction(BasicAction).phase2Commit(boolean) line: 1846 
 AtomicAction(BasicAction).End(boolean) line: 1529 
 AtomicAction(TwoPhaseCoordinator).end(boolean) line: 96 
 AtomicAction(AtomicAction).commit(boolean) line: 162 
 TransactionImple.commitAndDisassociate() line: 1288 
 TransactionManagerImple(BaseTransaction).commit() line: 126 
 TransactionManagerDelegate(BaseTransactionManagerDelegate).commit() line: 89 
 LocalTransaction.commitAndDissociate() line: 73 
 ContextTransactionManager.commit() line: 71 
 LocalUserTransaction.commit() line: 53 
 NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method] 
 NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62 
 DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43 
 Method.invoke(Object, Object...) line: 498 
 Reflections.invokeAndUnwrap(Object, Method, Object...) line: 433 
 CallableMethodHandler.invoke(Object, Method, Method, Object[]) line: 42 
 EnterpriseTargetBeanInstance.invoke(Object, Method, Object...) line: 56 
 ProxyMethodHandler.invoke(Object, Method, Method, Object[]) line: 100 
 UserTransaction$$Proxy$_$$_Weld$Proxy$.commit() line: not available 
 XAService.updateKeyValueDatabase(boolean, String, String) line: 185 
 XAServlet.doGet(HttpServletRequest, HttpServletResponse) line: 123 
 XAServlet(HttpServlet).service(HttpServletRequest, HttpServletResponse) line: 687 
 XAServlet(HttpServlet).service(ServletRequest, ServletResponse) line: 790 
 ServletHandler.handleRequest(HttpServerExchange) line: 85 
 ServletSecurityRoleHandler.handleRequest(HttpServerExchange) line: 62 
 ServletDispatchingHandler.handleRequest(HttpServerExchange) line: 36 
 SecurityContextAssociationHandler.handleRequest(HttpServerExchange) line: 78 
 PredicateHandler.handleRequest(HttpServerExchange) line: 43 
 SSLInformationAssociationHandler.handleRequest(HttpServerExchange) line: 131 
 ServletAuthenticationCallHandler.handleRequest(HttpServerExchange) line: 57 
 PredicateHandler.handleRequest(HttpServerExchange) line: 43 
 ServletConfidentialityConstraintHandler(AbstractConfidentialityHandler).handleRequest(HttpServerExchange) line: 46 
 ServletConfidentialityConstraintHandler.handleRequest(HttpServerExchange) line: 64 
 AuthenticationMechanismsHandler.handleRequest(HttpServerExchange) line: 60 
 CachedAuthenticatedSessionHandler.handleRequest(HttpServerExchange) line: 77 
 NotificationReceiverHandler.handleRequest(HttpServerExchange) line: 50 
 SecurityInitialHandler(AbstractSecurityContextAssociationHandler).handleRequest(HttpServerExchange) line: 43 
 PredicateHandler.handleRequest(HttpServerExchange) line: 43 
 JACCContextIdHandler.handleRequest(HttpServerExchange) line: 61 
 PredicateHandler.handleRequest(HttpServerExchange) line: 43 
 GlobalRequestControllerHandler.handleRequest(HttpServerExchange) line: 68 
 PredicateHandler.handleRequest(HttpServerExchange) line: 43 
 ServletInitialHandler.handleFirstRequest(HttpServerExchange, ServletRequestContext) line: 292 
 ServletInitialHandler.access$100(ServletInitialHandler, HttpServerExchange, ServletRequestContext) line: 81 
 ServletInitialHandler$2.call(HttpServerExchange, ServletRequestContext) line: 138 
 ServletInitialHandler$2.call(HttpServerExchange, Object) line: 135 
 ServletRequestContextThreadSetupAction$1.call(HttpServerExchange, C) line: 48 
 ContextClassLoaderSetupAction$1.call(HttpServerExchange, C) line: 43 
 SecurityContextThreadSetupAction.lambda$create$0(ThreadSetupHandler$Action, HttpServerExchange, Object) line: 105 
 851844117.call(HttpServerExchange, Object) line: not available 
 UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(ThreadSetupHandler$Action, HttpServerExchange, Object) line: 1508 
 164352863.call(HttpServerExchange, Object) line: not available 
 UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(ThreadSetupHandler$Action, HttpServerExchange, Object) line: 1508 
 164352863.call(HttpServerExchange, Object) line: not available 
 UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(ThreadSetupHandler$Action, HttpServerExchange, Object) line: 1508 
 164352863.call(HttpServerExchange, Object) line: not available 
 UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(ThreadSetupHandler$Action, HttpServerExchange, Object) line: 1508 
 164352863.call(HttpServerExchange, Object) line: not available 
 UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(ThreadSetupHandler$Action, HttpServerExchange, Object) line: 1508 
 164352863.call(HttpServerExchange, Object) line: not available 
 ServletInitialHandler.dispatchRequest(HttpServerExchange, ServletRequestContext, ServletChain, DispatcherType) line: 272 
 ServletInitialHandler.access$000(ServletInitialHandler, HttpServerExchange, ServletRequestContext, ServletChain, DispatcherType) line: 81 
 ServletInitialHandler$1.handleRequest(HttpServerExchange) line: 104 
 Connectors.executeRootHandler(HttpHandler, HttpServerExchange) line: 326 
 HttpServerExchange$1.run() line: 812 
 XnioWorker$TaskPool(ThreadPoolExecutor).runWorker(ThreadPoolExecutor$Worker) line: 1149 
 ThreadPoolExecutor$Worker.run() line: 624 
 Thread.run() line: 748 

[adinn]

Hi Ondra,

This is very strange behaviour to me. I'd really like to know why the Byteman Transformer is being invoked twice at the point where this class is being loaded. I'm wondering if the Transformer has been registered more than once. That's the only legitimate reason I can think of for the purge to find an existing transform record.

Can you look at the TransformManager class and see if its list of ClassTransformer instances contains a repeat of the Byteman transformer?

If that is not the case or you cannot inspect it then I think I'll need to debug the JDK runtime code and, possibly, the JVM code to find out what is going on here. It might be a good idea for me to try that anyway. Could you give me precise instructions on how to set up a test run that might reproduce this problem?

regards,

Andrew Dinn

[ochaloup]

From what I can say there is only one instance of the Byteman transformer (org.jboss.byteman.agent.Transformer) at the sun.instrument.TransformerManager at the variable mTransformerList.

The steps to reproduce the behaviour (which I hope won't be specific for my laptop) are:

1. clone the quickstarts
   git clone https://github.com/wildfly/quickstart.git
2. build the jta crash quickstart
   cd quickstart/jta-crash-rec/
   mvn clean install -DskipTests
3. download WildFly 13 + unzip
   wget http://download.jboss.org/wildfly/13.0.0.Final/wildfly-13.0.0.Final.zip
   unzip *.zip
4. setup byteman for the wildfly
   cd wildfly-*.Final
   vim -or- cat bin/standalone.conf [1]
5. you can change the xa.btm script to remove the 'killJVM()': quickstart/xa.btm at master
6. deploy jta war
   cp ../target/jta-crash-rec.war standalone/deployments/
7. start the wildfly
   ./bin/standalone.sh -c standalone-full.xml
8. the standalone.conf contains the debugging options thus there will be waiting at port 8787 to get connected a remote debugger
9. when wildfly is started go to http://localhost:8080/jta-crash-rec/XA and submit a value or submit directly
   curl -X GET http://localhost:8080/jta-crash-rec/XA?key=a&value=b&submit=Submit
10. observe the server log

Thanks a lot!

[1]

cat >> bin/standalone.conf << EOF

JAVA_OPTS="$JAVA_OPTS -agentlib:jdwp=transport=dt_socket,address=8787,server=y,suspend=y"

BYTEMAN_JAR="/opt/byteman/lib/byteman.jar"

SCRIPT="../src/main/scripts/xa.btm"

JAVA_OPTS="$JAVA_OPTS -javaagent:$BYTEMAN_JAR=script:$SCRIPT,boot:$BYTEMAN_JAR -Dorg.jboss.byteman.transform.all -Dorg.jboss.byteman.verbose -Dorg.jboss.byteman.debug=true" # -verbose:class -verbose:jni"

EOF

[adinn]

Hi Ondra,

I finally got time to debug this and it am beginning to understand what is going on. It looks . . . very . . . tricky . . . !

Here is a sample of the log output from a run I tried which indicates what is happening:

(MSC service thread 1-3) org.jboss.byteman.agent.Transformer : possible trigger for
  rule Start a count down when a 2 phase transaction starts in class
  com.arjuna.ats.arjuna.coordinator.BasicAction
(MSC service thread 1-3) RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into
  com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(boolean) void for
  rule Start a count down when a 2 phase transaction starts
(MSC service thread 1-3) org.jboss.byteman.agent.Transformer : inserted trigger for
  Start a count down when a 2 phase transaction starts in class
  com.arjuna.ats.arjuna.coordinator.BasicAction
. . .
(Periodic Recovery) org.jboss.byteman.agent.Transformer : possible trigger for
  rule Trace topLevelCommit (phase 2 of a 2PC transaction) in class
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
. . .
(Periodic Recovery) RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit() int for
  rule Trace topLevelCommit (phase 2 of a 2PC transaction)
(Periodic Recovery) org.jboss.byteman.agent.Transformer : inserted trigger for
  Trace topLevelCommit (phase 2 of a 2PC transaction) in class
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
. . .
(Periodic Recovery) org.jboss.byteman.agent.Transformer : possible trigger for
  rule Generate an XA Recovery Record in class
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
(MSC service thread 1-5) org.jboss.byteman.agent.Transformer : possible trigger for
  rule Trace topLevelCommit (phase 2 of a 2PC transaction) in class
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
(MSC service thread 1-5) RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit() int for
  rule Trace topLevelCommit (phase 2 of a 2PC transaction)
(Periodic Recovery) RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit() int for
  rule Generate an XA Recovery Record
(MSC service thread 1-5) org.jboss.byteman.agent.Transformer : inserted trigger for
  Trace topLevelCommit (phase 2 of a 2PC transaction) in class
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
. . .
(Periodic Recovery) org.jboss.byteman.agent.Transformer : inserted trigger for
  Generate an XA Recovery Record in class
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
. . .
(MSC service thread 1-5) org.jboss.byteman.agent.Transformer : possible trigger for
  rule Generate an XA Recovery Record in class
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
(MSC service thread 1-5) RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit() int for
  rule Generate an XA Recovery Record
(MSC service thread 1-5) org.jboss.byteman.agent.Transformer : inserted trigger for
  Generate an XA Recovery Record in class
  com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord

n.b. I stripped off the header with timestamp, level and output stream and added some line breaks so you can see the thread id and message more clearly.

The trace shows two different threads printing output and each message occurs underneath the Byteman Transformer's transform routine. That gets called from the JDK Runtime class TransformerManager class which is utlimately entered via InstrumentationImpl.transform. That entry point is actually arrived at by going through the JVM, either via a call to Transformer.transformClasses or via a call to ClassLoader.defineClass1. In the above trace the entry is via ClassLoader.defineClass1 because the transform is happening when classes BasicAction and XAResourceRecord are first being loaded.

You can see that the MSC service thread first calls defineClass1 for BasicAction, enters the TransformerManager and then the Byteman Transformer, finds a trigger point and injects rule "Start a count down when a 2 phase transaction starts" just as expected.

Next, the Periodic Recovery thread calls defineClass1 for XAResourceRecord, enters the TransformerManager and Byteman Transformer  and finds a trigger point and injects rule "Trace topLevelCommit (phase 2 of a 2PC transaction)". It then continues processing the next rule "Generate an XA Recovery Record" finds a trigger point for that rule and prepares to inject it.

However, before the second injection step is  completed (i.e.while the byecode for this call to define1Calss is still being processed and, therefore, the class is not yet defined) the MSC service thread also calls defineClass1, trying to define class XAResourceRecord. WTF? It also enters the TransformerManager and starts looking for trigger points and constructing a modified bytecode array for the class.

Now, the key thing to note here is that this is not an attempt to redefine XAResourceRecord in a different class loader. Both threads are racing to produce the bytecode array that will be used to define the JVM-internal InstanceKlass that defines the Java class and is used to tag the headers of heap allocated objects of type XAResourceRecord  and also the associated Java Class<?> that is used to resolve references to XAResourecRecord.class. One of the threads will return first and the bytecode array it returns will be used to create the InstanceKlass whihc then becomes the definitive version of XAResourceRecord. The other thread may hand over a bytecode array but it will be discarded because another thread already got there. So, both calls to defineClass1 will eventually complete and there will be one unique InstanceKlass and one unique Class<?> for XAResourecRecord. What's not to like?

Well, of course, the problem is that the Transformer does not know which of the two parallel transform operations is going to win. This matters because Byteman has to allocate data to track each transform and that data includes a String key K which indexes the hash table used to associate an injection sites the  parsed rule R that was used to derive the injected code. When a thread starts injection into a class with name X and loader L Byteman clears out any previous transform data indexed using the unique id X:L and that includes deleting the hash table entry for its key K and dropping any reference to the associated parsed rule R.

Byteman does that because the presence of an existing record is taken to indicate that the class has previously  been transformed and the current operation is a retransform. If Byteman didn't clear the entry then hash table entry for R would retain references to loader data that needed to be dropped (the parsed rule references a classloader used to define a custom-generated subclass of R's helper and may also reference other classes mentioned in the rule that might potentially need to  be collected). So, GCing old transform records is really critical to performance.

However, the problem here is that we see two concurrent transforms when a class is first defined, The first thread records a transform for XAResourceRecord:JBossLoaderNNN which references rule R1 with key K1. While it is still running a second one can record a transform for XAResourceRecord:JBossLoaderNNN which references rule R2 with key K2, deleting the transform record for rule r1 and key K1. If the first thread wins the race and hands back its transformed bytecode then the injected code will  try to look up a rule using key K1 and fails to find it, aborting rule execution. If the second thread wins the race then the bytecode used to define the class will find key K2 and all is well.

I am not sure if parallel execution of transforms is a new feature or not. I have certainly changed Byteman recently to be more strict about tracking and deleting transform records. This was needed to ensure that lifecycle processing correctly counted injection and removal of rules and this is where the purging of existing rules was introduced. So, it may be that the reason I was seeing what appeared to be redundant trasnforms was not because the old code was failing to count properly but because of transforms being discounted.

Why not just leave existing transform records? Well, as I said there is the problem of tracking and corrcecly accounting for injection and uninjection that I mentioned. That's critical because it gives the rule helper classes an opportunity to clear up resources they allocate (e.g. the deactivated callback for he default Helper clears out the LinkMap tables, CountDowns etc). Also, getting this right ensures that at some point you really do GC redundant parsed rules which avoids hanging on to classloaders for old versions of classes. Also, transform records are used when reporting what has been injected to bmsumit. So, leaving around will records for phantom transformations will result in misleading reports.

Ideally, I would prefer either for TransformManager calls to be seralized by the JVM or for the Transformer to get a callback to notify it that a transform was rejected (or even that another one succeeded). That would be a much cleaner model but, unfortunately would require backporting to all older JDKs (at least jdk7 and maybe even jdk6) for it to be a workable solution. So, I think I am going to have to find a way to resolve this myself. I'll do some more investigation and also maybe bring this up on the relevant OpenJDK lists (jdk-runtime I think).

[ochaloup]

Yay, what a exhaustive answer (as usual ). Thanks a lot for taking look at this! I was really interested what was behind the scene here. It's much clearer for me now.