Hi Lei,

I'm not sure what is happening here. However, I think the error is unlikely to have anything to do with Byteman itself. It does not care how many application classes are loaded or how many times they run. As far as it is concerned all the code you deploy is just code. It doesn't know or care whether it belongs to 1, 2 or 100 apps. It doesn't even distinguish between code that exists in the JDK runtime and code defined by users.

If the rules have stopped firing then I think it most likely that the application is no longer executing the code the rules have been injected into. I cannot really say for sure whether that is the case without having more details of:

  i) what the apps are doing?

  ii) what Byteman is doing?

You will need to talk to your customer to answer that first question, Luckily, you can do something relaively simple to get an answer for the second question.

I recommend you ask your customer to set System property org.jboss.byteman.verbose when they start up their application by adding -Dorg.jboss.byteman.verbose to the java command line (when using JBoss EAP/Wildfly you can do that by editing the standalone.sh script). Alternatively, if they are installing the Byteman agent into an already running JBoss process using bminstall they can add -Dorg.jboss.byteman.verbose to the bminstall command line.

Setting that property makes Byteman generate trace output to explain which classes it is injecting rules into and log a message every time a rule is triggered (hint: it will also switch on output from calls to builtin method debug in the rules so you could add some debug calls to see even more info about what the rules are doing). If you can show me the output generated by Byteman and split it up into sections which group output that was generated before or after each JSF app was started then that might help to identify the problem.

It would also help if you could show me your rules and tell me something about what the app is doing and how the rules are being used to change its behaviour. Of course, I understand that you might not be able to let me see any details that are confidential. If that is a problem then perhaps you could create a test case which also suffers from the problem but does not contain any confidential details.

regards,

Andrew Dinn

Hi Lei,

leiyu  wrote:

 

We are trying to see what the JBoss class doing when the server is restarted with several jsf applications deployed. In detail, I want to see if in the JBoss code, under what circumstance, it will look for jsf implementation factory with 0-argument constructor. In this case, do you still need to know what customer's applications are doing?

 

I will ask customer to add -Dorg.jboss.byteman.verbose to JBoss and see if it is clear why the number of applications goes up, the byteman script stops working.

Thanks for providing all that information. The rules look ok. I don't need to know more about what the application is doing at the moment. It would be very good to see what gets written by Byteman when your customer enables the verbose trace setting.

regards,

Andrew Dinn

Hi Lei,

Thanks very much for persevering with debugging this problem and providing me with this log info. Your help is really appreciated and it has helped to make it clearer what is happening here. I hope we can get to the bottom of it with a bit more investigation.

leiyu  wrote:

 

I got the logs with debug on back, for working ones, I can see the following:

14:35:10,456 INFO  [stdout] (ServerService Thread Pool -- 31) Rule.execute called for getImplementationInstance_5

14:35:10,458 INFO  [stdout] (ServerService Thread Pool -- 31) HelperManager.install for helper class org.jboss.byteman.rule.helper.Helper

14:35:10,459 INFO  [stdout] (ServerService Thread Pool -- 31) calling activated() for helper class org.jboss.byteman.rule.helper.Helper

14:35:10,459 INFO  [stdout] (ServerService Thread Pool -- 31) Default helper activated

14:35:10,459 INFO  [stdout] (ServerService Thread Pool -- 31) calling installed(getImplementationInstance) for helper classorg.jboss.byteman.rule.helper.Helper

14:35:10,459 INFO  [stdout] (ServerService Thread Pool -- 31) Installed rule using default helper : getImplementationInstance

14:35:10,460 INFO  [stdout] (ServerService Thread Pool -- 31) getImplementationInstance execute

14:35:10,460 INFO  [stdout] (ServerService Thread Pool -- 31) ************> getImplementationInstance classLoader ==

ModuleClassLoader for Module ...

I'm not sure what you mean by working and non-working but I don't think the difference between these messages and the later messages means what you think it does. Every time that rule code injected by Byteman is executed you see a message saying "Rule.execute called for ...". So, you are seeing those messages in both cases which means the methods are being executed and the injected code is being entered (the term I use for that is triggered) even if it seems like it does not complete. However, the other messages whic only appear in the first case do not indicate an error because they are missing in the second case.

These message notify life-cycle operations which relate to installation and deinstallation of the rules as follows:

Helper install events (once per helper):

The first time that any rule using helper class H is executed the helper class H is notified with an install event. You also see a verbose trace message explaining that method H.install is being called. When all the rules using helper H get deinstalled then H.deinstall gets called. So, normally you only see the install event message once.

Helper activation events (once per rule):

For each rule r that uses a helper class H the first time r is executed the helper class H is notified with an activation event for that rule and you see a verbose trace message explainign that H.activate is being called. The Helper method can be passed either the rule r or the name of the rule r . When a r is deinstalled then H.deactivated is called. So, normally you see an activated event message once for each installed rule.

Rule execute events (once per trigger):

For each rule r every time the injected code is executed Byteman prints a verbose trace message to log the trigger event. So, you may see lots of execute message for every rule.

So, the interesting thing in this output is not the installed or activated messages only being present in the first set. The ones that indicate a problem are those in the second set which mention decommissioned keys.

leiyu  wrote:

 

whilst the nonworking ones have the following:

 

14:50:19,455 INFO  [stdout] (ServerService Thread Pool -- 110) Rule.execute called for getImplementationInstance_5

14:50:19,455 INFO  [stdout] (ServerService Thread Pool -- 110) Rule.execute for decommissioned key getImplementationInstance_5

14:50:19,463 INFO  [stdout] (ServerService Thread Pool -- 110) Rule.execute called for getImplGivenPreviousImpl_0

14:50:19,463 INFO  [stdout] (ServerService Thread Pool -- 110) Rule.execute for decommissioned key getImplGivenPreviousImpl_0

14:50:19,463 INFO  [stdout] (ServerService Thread Pool -- 108) Rule.execute called for getImplementationInstance_5

14:50:19,463 INFO  [stdout] (ServerService Thread Pool -- 108) Rule.execute for decommissioned key getImplementationInstance_5

14:50:19,463 INFO  [stdout] (ServerService Thread Pool -- 104) Rule.execute called for getImplementationInstance_5

14:50:19,464 INFO  [stdout] (ServerService Thread Pool -- 104) Rule.execute for decommissioned key getImplementationInstance_5

14:50:19,464 INFO  [stdout] (ServerService Thread Pool -- 108) Rule.execute called for getImplGivenPreviousImpl_0

14:50:19,464 INFO  [stdout] (ServerService Thread Pool -- 108) Rule.execute for decommissioned key getImplGivenPreviousImpl_0

14:50:19,464 INFO  [stdout] (ServerService Thread Pool -- 104) Rule.execute called for getImplGivenPreviousImpl_0

 

What does "decommissioned key" mean here?

The injected code uses a unique String key to relate the injected code to the original Byteman rule. The String actually appears as a constant in the transformed bytecode for the method Byteman has injected code into. Before the method can execute the code in the rule it has to look up the rule in a global hash table to ensure that the rule is still installed. When a rule is deinstalled it is removed for mthe hash table and they key lookup fails. This is needed to ensure that a deinstall has a well-defined, immediate effect without the need to to 'uninject' the rule code. Here is how this might work:

user                       Byteman                     app

bmnstall rule r

                          install s --> r in table

                          inject r into method C.m

                          return success

bminstall complete

                                                       call method C.m

                                                       lookup key s returns r

                                                       execute code for r

                                                       continue executing m

bminstall -u r            remove s --> r from table

                          (i.e. decommission key s)

                                                       call method C.m

                                                       lookup key s returns null

                                                       skip code for r and

                                                          print verbose trace 'decommissioned key'

                                                       continue executing C.m

                          uninject r from method C.m*

                          return success

bminstall -u complete

The key removal ensures that the rule stops executing immediately so that when bminstall -u returns the user can know that the rule has been stopped. You might wonder why this is needed? The problem can happen at the uninject step marked with a *.

When Byteman injects the code for rule r into C.m it asks the JVM to change the bytecode of the method. It does not return success until the new bytecode has been installed by the JVM. So, any call to C.m after that point will use the new bytecode. However, threads which are in the middle of executing C.m will still continue to use the original bytecode until they return and make a new call. So, if the injected rule sist inside a long-running method or is inside a loop the method may continue for some time without triggering the rule code.

A similar thing happens when Byteman uninjects the code for rule r. Byteman asks the JVM to update the bytecode and does not return until the new bytecode has been installed. However, there may be threads which are still running the previous version of the bytecode which still contains the injected code. Removing the key ensures that those threads stop executing the rule immediately. The reason this is important is that when a set of rules are unloaded you very often need them all to stop at once otherwise yo may get inconsistent results. Byteman cannot do anything about delayed start of rule triggering but it can and does ensure that rules all stop triggering at once.

I am wondering why your client is seeing these decommissioned key messages? it looks like they may be deinstalling their rules before they start a new copy of the app? Is that a possibility? That is not the only way this can happen though. There are two other ways that might a rule might get deinstalled and reinstalled.

Imagine you load a script R containing rules r1, r2 etc that affect methods C1.m, C2.m etc. If you call bminstall R twice then Byteman will uninstall r1, r2 etc and the reinstall r1, r2. The reason it does this is that it cannot know whether the rules in the script i) have been changed or ii) will be injected with a different outcome because of changes to the loaded code base. So, if a rule r with name n has been injected already and then a rule r with the same name n is installed the old rule r is deinstalled before the new r is installed. This means that the original key for r will be decommissioned and a new key used for the second install.

Ok, now for the second possibility. Imagine you have already installed a rule r with name n that modifies method C.m and you know install a different rule r' with name n' for method C.m'. Indeed, the new rule r' may inject code into the same method i.e. ir doesn't matter whether  m' == m. The important thing is that n' !=n. In order to inject the new code for rule r' Byteman has to start with the original bytecode for class  C and transform it to inject the code for r into C.m and the code for r' into C.m'. It hands this new bytecode back to the JVM and the old bytecode is eventually removed when it is no longer being executed by other threads. So, it has to decommission the original key for r and install the new key for r and a new key for r' into the global lookup table.

So, is your customer running bminstall every time a new app is restarted? That isn't actually needed unless the customer wants different rules to run. If a new app  deployed the rules will be injected into the code for that app. That is true even if a class of the same name is deployed in its own classloader (e.g. if the app is deployed as an ear).

Even if the customer *is* running bminstall that shouldn't stop all rule triggerings. It should only affect rules which are injected into methdos that are being executed in tight loops. So, if at some point you only ever see Rule.execute trace messages followed by a decommissioned key message then it may be that something more serious is going wrong here. In order to debug that further I will need you to tell me exactly what the customer is doing when they deploy their rules and apps, It would be better still if you could provide me with a verison of the app that I can run to reproduce the problem.

regards,

Andrew Dinn

Hi Lei,

leiyu  wrote:

 

Thanks a lot for your help and the detailed explanation. Sorry I was not clear in my previous message:

 

Working one -- debugging for byteman script found in the JBoss server log. For this test, 4 wars were deployed.

NonWorking one -- debugging for byteman script does not print in the JBoss server log. For this test, 5 wars were deployed.

 

Ah, ok, I understand now! Sorry for the misunderstanding and thanks for clarifying.

Do you think there is a possible racing condition when more than one of the application have been deployed? The following are the facts I know about the applications

 

1) they are sym links in the JBoss deployment directory, which is not recommended.

2) all the wars are generated from one of the app, they are all on the same code base.

Hmm, that's a very interesting possibility. In theory there should be no race here. Am I right to assume that the javax.faces classes exist once only in the runtime? Or are they locate din the war file (in which case 4 or 5 versions of the class will get loaded). In the first case it might be that there is a race in the JVM to load the code and invoke Byteman's class transformer. I think I may have seen something similar to what you are seeing in the Narayana (JBoss Transactions) code and your suggestion might well explain what is going on here.

Consider this scenario, where X is an app class and Y is one of the javax.faces classes:

war app 1                                war app 2                              Byteman

                                                                                Byteman loads rule r for Y.m

method X.m' references class Y

load of class named "Y" is initiated

                                         method X.m' references class Y

                                         load of class named "Y" is initiated

load resolves to class Y                                                        Byteman transforms Y (1)

                                         load resolves to same class Y

                                                                                Byteman transforms Y (2)

transform (1) returns Y'

load completes and installs Y'

                                         transform (2) returns Y''

                                         load rejects Y'' and uses Y' instead

The problem is that Byteman may be asked to perform two transforms of the bytecode in parallel (in two separate threads). The first transform call will install a key K for r and return Y' whose method m includes injected code that looks for key K. Meanwhile the second transform call will delete the key K and install a key K' for r, returning Y''. Method m of Y'' will look for key K'. However, the loader will install the class Y' bytecode from the first transform attempt and reject the class Y'' returned by the second transform attempt.

I am not sure that the JVM really will allow the transform requests to proceed in parallel but I think it is certainly possible. If so then there is no guarantee that the error will occur. Whether the problem happens depends on the exact timing of the load requests. he probability of the transform requests overlapping is low when there are only two loads. However, when there are 5 apps running I guess it is very likely that an overlap will occur.

For the test, customer has enabled different numbers of application for JBoss, then start it. In the JBoss, java options has been added for byteman

 

 

JAVA_OPTS="$JAVA_OPTS -javaagent:/home/jboss/byteman/byteman-download-4.0.7/lib/byteman.jar=script:/home/jboss/scripts/jsfClassload.btm,sys:/home/jboss/byteman/byteman-download-4.0.7/lib/byteman.jar  -Dorg.jboss.byteman.transform.all=true -Dorg.jboss.byteman.verbose"

 

I don't have all the applications and I don't think I can share customer's applications here even I have them.

I thought that was probably likely. Never mind. If the analysis above is correct then I think I may be able to create my own reproducer for this problem. I'll try to do that and let you know what I find.

It may take some time to verify that this is the problem and also to fix it. So, I am afraid you will have to explain to your customer that this looks like a race between the JVM class loader and the Byteman agent and may take some time to fix. One thing they might be able to do to work around this problem is to start one of the apps, wait for a bit and then start the other apps. That should allow Byteman to load the target classes and inject the rules without any danger of a race. After that when the other apps are started the rules should already be in place.

Apologies for not being able to sort this problem out right away. And *immense* thanks for providing the information that helped diagnose the problem this far.

regards,

Andrew DInn

Hi Lei,

leiyu  wrote:

 

Just want you know I have customer's applications, 5 wars, and I can reproduce the byteman issue in my test env. I am wondering if is there a way to tell JVM they are different, for example: appending context path of the war?

Thanks. It's good to know the error is reproducible. I'd like to concentrate on creating my own simple reproducer to debug this. It would be much easier to debug if I can avoid having to run all of wildfly. If that doesn't work may I ask you fora copy of the customer app in order to recreate the problem?

I don't believe renaming the app code is going to help with this problem. Let me explain the situation and then explain why renaming won't help.

The rules apply to classes in the javax.faces package and the problem happens when the apps race to resolve one of those referenced classes, lets assume it's name is "F". Several application threads will be executing code that mentions "F" and the JVM is invoked to ensure that a class with name "F" is in scope and can be loaded and resolved. The JVM will call back into Java to ask the current classoloader to find the bytecode for the corresponding class F. When the bytecode is returned the JVM resolves the class. What resolve means is that 1) the JVM creates its own internal record of the class's structure (a C++ object of type Klass) and 2) it creates a corresponding Class<?> instance on the heap. For any given class loader CL there will only ever be one Klass/Class<?> F(CL) obtained from class loader CL with name "F". If the same bytecode is loaded by class loader CL2 then there will be a different instance F(CL2) with the same name "F" but with its own Klass/Class<?>

Resolution has to be synchronized. So, if several threads start to load and resolve the same name "F" from the same class loader CL then only one will succeed in creating the unique Klass/Class<?> F(CL). Other threads attempting to resolve "F" via CL have to return the same F(CL). However, a load may be started by several threads at once. The parallelism does not need to extend to the actual reading of the classloader bytes from file. Even if the classloader synchronizes uses a lock and caches a single copy of the file contents that doesn't stop several threads asking for the bytes in parallel. So, the JVM synchronizes before trying to use that bytecode to resolve the class. Only one thread gets to create F(CL).

Before the resolve step can happen the JVM has to give Java agents a chance to change the bytecode. So, in each load thread the JVM asks Byteman if it wants to transform the bytecode. If there is a rule with a matching classname then Byteman transforms the bytecode and saves details of the injected rule. The problem is that Byteman saves the information for the most recent transform request and throws away information for earlier requests (it cannot keep details from all previous load requests because that will end up keeping the classlaoders alive forever). However, the order in which the transform requests occur is not necessarily the order in which those requests complete or get dealt with by the JVM. So, the JVM may decide to use the transformed bytecode from an earlier request with injected code that Byteman does not recognize.

So, what about your idea of renaming the app classes? Well, if you follow the steps above you will notice that there is no mention of the app class that is making the reference to F. The problem is that lots of app threads are trying to load a class with the same name from the same class loader. So, it is the name of the class being resolved not the class trying to resolve it that matters.

You don't even need to have several copies of the app to run into this problem. If the app created lots of threads and those threads all entered a routine that tries to resolve "F" at the same time then the same problem could happen in just that one app. This  is very unlikely to happen. You would need a lot of threads and would need to ensure they all synchronize just before before any of them enters code the references "F" for the first time.

So, the problem you are seeing depends upon the fact that the apps are all trying to resolve class name "F" from the same class loader. If the javax.faces code was bundled into the app jar  then each deployment would be loading F(CLn) from its own app class loader (CLn). So, this is one way to avoid the trace. I'm unsure if this woudl work. Is the javax.faces code supplied by wildlfy? Do the apps all need to share javax.faces instances with each other? or with wildfly code? If the answer to either question is yes then bundling the javax.faces code might well solve the Byteman problem but would land you in classloader hell.

Meanwhile, what I need to try to do to fix this problem is ensure that either 1) Byteman stores exactly the same details when transforming a class with a given name and classloader or 2) it finds some way of synchronizing so that it can identify and sequence parallel requests.

I think option 2 is impossible because there is a window between the point where Byteman returns transformed bytecode and the point where the JVM synchronizes to resolve the class where another transform request can be started. I'm still thinking about option 1 :-)

regards,

Andrew Dinn

Hi Lei,

Thanks for clearing things with the customer. That is very helpful.

Also, I'm glad to hear you are enjoying this bug :-)

I am currently working on a fix which look promising. I'll let you know when I have something ready and we can try using the customer case as a test.

regards,

Andrew Dinn

Hi Lei,

Apologies for the delay in getting back to you. I had to sort out some OpenJDK issues and then had to fix another Byteman bug that I stumbled into (BYTEMAN-388) before I could get back to fixing the problem you identified.

I think I now have a version of Byteman that handles the race condition you are seeing. I have uploaded a 4.0.9-SNAPSHOT release to the Sonatype snapshots repo. Do you think you could use it to test your customer app? Thanks.

regards,

Andrew Dinn