-
1. Re: Trying to read synchronized block
adinn Nov 10, 2015 5:02 AM (in response to alexmarinho)HI Alessandro,
Could you please tell me what version of Byteman you are using? Also, could you provide precise details of how you ran your program (please show Java command line), how you installed the agent (using -javaagent or bminstall -- please show full bminstall command line) and how you uploaded your rules (uising -javaagent or bmsubmit -- please show full bmsubmit command line). Thanks.
regards,
Andrew Dinn
-
2. Re: Trying to read synchronized block
alexmarinho Nov 10, 2015 5:21 AM (in response to adinn)Thanks again Andrew!
Here:
Byteman: 3.0.1
VM Arguments: "-Dprogram.name=JBossTools: JBoss Enterprise Application Platform 6.0" -server -Xms1303m -Xmx1303m -XX:MaxPermSize=256m -Dorg.jboss.resolver.warning=true -Djava.net.preferIPv4Stack=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true "-Dorg.jboss.boot.log.file=/home/X/Arquivos_IBM/jboss-eap-6.0.1/standalone/log/boot.log" "-Dlogging.configuration=file:/home/X/Arquivos_IBM/jboss-eap-6.0.1/standalone/configuration/logging.properties" "-Djboss.home.dir=/home/X/Arquivos_IBM/jboss-eap-6.0.1" -Djboss.bind.address.management=localhost -javaagent:/home/X/Downloads/byteman-download-3.0.1/lib/byteman.jar=script:/home/X/Downloads/byteman-download-3.0.1/bin/sgp.btm,prop:org.jboss.byteman.verbose=true,prop:org.jboss.byteman.debug=true,listener:true,boot:/home/X/Downloads/byteman-download-3.0.1/lib/byteman.jar -Dorg.jboss.byteman.transform.all
I update my rules using:
./bmsubmit.sh -l sgp.btm
-
3. Re: Trying to read synchronized block
adinn Nov 10, 2015 5:52 AM (in response to alexmarinho)Hi Alessandro,
I think this problem is very likely to be related to an issue I just fixed in the 3.0.2 release. Could you please try re-running with 3.0.2 and see if it resolves the problme? This release is accessible from the Byteman downloads page.
regards,
Andrew Dinn
-
4. Re: Trying to read synchronized block
alexmarinho Nov 10, 2015 7:00 AM (in response to adinn)Hello Andrew,
Byteman: 3.0.2
VM Arguments:
"-Dprogram.name=JBossTools: JBoss Enterprise Application Platform 6.0" -server -Xms1303m -Xmx1303m -XX:MaxPermSize=256m -Dorg.jboss.resolver.warning=true -Djava.net.preferIPv4Stack=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true "-Dorg.jboss.boot.log.file=/home/X/Arquivos_IBM/jboss-eap-6.0.1/standalone/log/boot.log" "-Dlogging.configuration=file:/home/X/Arquivos_IBM/jboss-eap-6.0.1/standalone/configuration/logging.properties" "-Djboss.home.dir=/home/X/Arquivos_IBM/jboss-eap-6.0.1" -Djboss.bind.address.management=localhost -javaagent:/home/X/Downloads/byteman-download-3.0.2/lib/byteman.jar=script:/home/X/Downloads/byteman-download-3.0.2/bin/sgp.btm,prop:org.jboss.byteman.verbose=true,prop:org.jboss.byteman.debug=true,listener:true,boot:/home/X/Downloads/byteman-download-3.0.2/lib/byteman.jar -Dorg.jboss.byteman.transform.all
Same thing:RULE trace alterarFerias entry
CLASS br.modify.TestModify
METHOD programar
AT ENTRY
IF true
DO traceln("Test..")
ENDRULE
Its strange , when i restart jboss, the first command: bmsubmit -l sgp.bmt, its fine. after run the operation, when i do the bmsubmit.sh -ls again :
9:49:16,525 INFO [stdout] (Thread-0) org.jboss.byteman.agent.Transformer : possible trigger for rule trace alterarFerias entry in class br.modify.TestModify.TestModify
09:49:16,529 INFO [stdout] (Thread-0) RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into br.modify.TestModify.TestModify.programar(org.apache.struts.action.ActionMapping,org.apache.struts.action.ActionForm,javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse) org.apache.struts.action.ActionForward for rule trace alterarFerias entry
09:49:16,533 INFO [stdout] (Thread-0) CFG.carryForward: unexpected! invalid open enters count for block L23565714 in method br.modify.TestModify.TestModify.programar(Lorg/apache/struts/action/ActionMapping;Lorg/apache/struts/action/ActionForm;Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)Lorg/apache/struts/action/ActionForward;
09:49:16,534 INFO [stdout] (Thread-0) CFG.carryForward: unexpected! invalid open enters count for block L24298527 in method br.modify.TestModify.TestModify.programar(Lorg/apache/struts/action/ActionMapping;Lorg/apache/struts/action/ActionForm;Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)Lorg/apache/struts/action/ActionForward;
09:49:16,534 INFO [stdout] (Thread-0) exits unaccounted for in block B46
09:49:16,534 INFO [stdout] (Thread-0) org.jboss.byteman.agent.Transformer : unexpected error injecting trigger for rule trace alterarFerias entry into class br.modify.TestModify.TestModify
09:49:16,534 INFO [stdout] (Thread-0) java.lang.NullPointerException
09:49:16,535 INFO [stdout] (Thread-0) java.lang.NullPointerException
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.adapter.cfg.CFG.computeContainment(CFG.java:1205)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.adapter.cfg.CFG.carryForward(CFG.java:1041)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.adapter.cfg.CFG.split(CFG.java:1319)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.adapter.RuleTriggerMethodAdapter.visitInsn(RuleTriggerMethodAdapter.java:665)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.adapter.EntryTriggerAdapter$EntryTriggerMethodAdapter.visitInsn(EntryTriggerAdapter.java:104)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.objectweb.asm.tree.InsnNode.accept(Unknown Source)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.objectweb.asm.tree.InsnList.accept(Unknown Source)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.objectweb.asm.tree.MethodNode.accept(Unknown Source)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.objectweb.asm.commons.JSRInlinerAdapter.visitEnd(Unknown Source)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.objectweb.asm.ClassReader.b(Unknown Source)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.objectweb.asm.ClassReader.accept(Unknown Source)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.objectweb.asm.ClassReader.accept(Unknown Source)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.TransformContext.transform(TransformContext.java:150)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.Transformer.transform(Transformer.java:746)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.Transformer.tryTransform(Transformer.java:814)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.Transformer.tryTransform(Transformer.java:785)
09:49:16,535 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.Transformer.transform(Transformer.java:257)
09:49:16,536 INFO [stdout] (Thread-0) at sun.instrument.TransformerManager.transform(TransformerManager.java:188)
09:49:16,536 INFO [stdout] (Thread-0) at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:385)
09:49:16,536 INFO [stdout] (Thread-0) at sun.instrument.InstrumentationImpl.retransformClasses0(Native Method)
09:49:16,536 INFO [stdout] (Thread-0) at sun.instrument.InstrumentationImpl.retransformClasses(InstrumentationImpl.java:144)
09:49:16,536 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.Retransformer.installScript(Retransformer.java:144)
09:49:16,536 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.TransformListener.handleScripts(TransformListener.java:349)
09:49:16,536 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.TransformListener.loadScripts(TransformListener.java:272)
09:49:16,536 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.TransformListener.handleConnection(TransformListener.java:225)
09:49:16,536 INFO [stdout] (Thread-0) at org.jboss.byteman.agent.TransformListener.run(TransformListener.java:158)
-
5. Re: Trying to read synchronized block
adinn Nov 10, 2015 10:17 AM (in response to alexmarinho)Hi Alessandro,
I tried to recreate this error using your rule and simple test program like the one you describe in the original post. Unfortunately, the code you have posted is incomplete and the program I tried does not reproduce the error.
Can you provide me with a more complete version of your code or, assuming you are concerned about confidentiality, at least try to isolate a disclosable variant of your program which reproduces the problem without revealing any details of the code that are confidential? The important thing is to come up with something which includes the same nesting of synchronizations, try catch regions and calls which may throw exceptions.
I am afraid I cannot easily proceed to diagnose this problem unless I can reproduce it.
regards,
Andrew DInn
-
6. Re: Trying to read synchronized block
alexmarinho Nov 10, 2015 12:14 PM (in response to adinn)I cant post the whole code here
But one thing really strange...
synchronized (this) {...
if(...) {
Date dataInicio = new Date();
VacationPeriod secondPeriod = null;
for (VacationPeriod vacationPeriod : listaPeriodVacation) {
if (vacationPeriod.getDataInicioVigencia().after(dataInicio)) {
secondPeriod = vacationPeriod;
}
}
VacationSituationDAO vacationSituacaoDAO = new VacationSituationDAO(holder);
Collection<VacationSituation> listPeriodVacationSituation =
vacationSituacaoDAO.retrieveSituations(secondPeriod.getId());
for (VacationSituation periodVacationSituation : listPeriodVacationSituation) {
periodVacationSituation.setUltimaAcao(XXConstants.ACAO_DELETE);periodVacationSituation.delete(periodVacationSituation);
secondPeriod.getListPeriodVacationSituation().remove(periodVacationSituation);
}
secondPeriod.setUltimaAcao(XXConstants.ACAO_DELETE);
periodVacationDAO.delete(segundoPeriodo);
} // end if
...
} //END BLOCK SYNC
UPDATED :
1342: new #601; // class java/util/Date 1345: dup 1346: invokespecial #603; // Method java/util/Date."<init>":()V 1349: astore 18 1351: aconst_null 1352: astore 19 1354: aload 17 1356: invokevirtual #604; // Method java/util/ArrayList.iterator:()Ljava/util/Iterator; 1359: astore 21 1361: goto 1393 1364: aload 21 1366: invokeinterface #190, 1; // InterfaceMethod java/util/Iterator.next:()Ljava/lang/Object; 1371: checkcast #485; // class xx/xx/xx/xx/xx/xx/VacationPeriod 1374: astore 20 1376: aload 20 1378: invokevirtual #605; // Method xx/xx/xx/xx/pojo/ferias/VacationPeriod.getDataInicioVigencia:()Ljava/util/Date; 1381: aload 18 1383: invokevirtual #608; // Method java/util/Date.after:(Ljava/util/Date;)Z 1386: ifeq 1393 1389: aload 20 1391: astore 19 1393: aload 21 1395: invokeinterface #251, 1; // InterfaceMethod java/util/Iterator.hasNext:()Z 1400: ifne 1364 1403: new #612; // class xx/xx/xx/xx/xx/xx/VacationSituationDAO 1406: dup 1407: aload 11 1409: invokespecial #614; // Method xx/xx/xx/xx/xx/xx/VacationSituationDAO."<init>":(Lxx/xx/xx/xx/xx/HibernateHolder;)V 1412: astore 20 1414: aload 20 1416: aload 19 1418: invokevirtual #484; // Method xx/xx/xx/xx/xx/xx/VacationPeriod.getId:()Ljava/lang/Long; 1421: invokevirtual #615; // Method xx/xx/xx/xx/xx/xx/VacationSituationDAO.retrieveSituations:(Ljava/lang/Long;)Ljava/util/Collection; 1424: astore 21 1426: aload 21 1428: invokeinterface #184, 1; // InterfaceMethod java/util/Collection.iterator:()Ljava/util/Iterator; 1433: astore 23 1435: goto 1480 1438: aload 23 1440: invokeinterface #190, 1; // InterfaceMethod java/util/Iterator.next:()Ljava/lang/Object; 1445: checkcast #618; // class xx/xx/xx/xx/xx/xx/VacationSituation 1448: astore 22 1450: aload 22 1452: bipush 68 1454: invokestatic #620; // Method java/lang/Character.valueOf:(C)Ljava/lang/Character; 1457: invokevirtual #625; // Method xx/xx/xx/xx/xx/xx/VacationSituation.setUltimaAcao:(Ljava/lang/Character;)V 1460: aload 20 1462: aload 22 1464: invokevirtual #629; // Method xx/xx/xx/xx/xx/xx/PeriodVacationSituationDAO.delete:(Lxx/xx/xx/xx/xx/Persistent;)V 1467: aload 19 1469: invokevirtual #632; // Method xx/xx/xx/xx/xx/xx/VacationPeriod.getListPeriodVacationSituation:()Ljava/util/Set; 1472: aload 22 1474: invokeinterface #636, 2; // InterfaceMethod java/util/Set.remove:(Ljava/lang/Object;)Z 1479: pop 1480: aload 23 1482: invokeinterface #251, 1; // InterfaceMethod java/util/Iterator.hasNext:()Z 1487: ifne 1438 1490: aload 19 1492: bipush 68 1494: invokestatic #620; // Method java/lang/Character.valueOf:(C)Ljava/lang/Character; 1497: invokevirtual #641; // Method xx/xx/xx/xx/xx/xx/VacationPeriod.setUltimaAcao:(Ljava/lang/Character;)V 1500: aload 16 1502: aload 19 1504: invokevirtual #642; // Method xx/xx/xx/xx/xx/xx/PeriodVacationDAO.delete:(Lxx/xx/xx/xx/xx/Persistent;)V 1507: aload 10 1509: invokevirtual #448; // Method java/lang/Boolean.booleanValue:()Z 1512: ifne 1545 1515: aload_0 1516: aload_3 If i remove this block above no error prints , and it works .
Do you have any idea?
-
7. Re: Trying to read synchronized block
adinn Nov 10, 2015 1:07 PM (in response to alexmarinho)Alessandro Marinho wrote:
Do you have any idea?
I am not surprised by this. The block you identify will include more than one region in which exceptions can (potentially at least) occur. Since those exceptions pass out of the synchronized block -- either to an outer catch or, depending upon what happens in the rest of your code, right out of the method itself -- then the bytecode will almost certainly include some extra catch-all handlers planted by the javac compiler. These handlers are placed so that they trap the exception flow at the end of the synchronized block, ensure the synchronization object is unlocked (i.e. they execute a monitorexit bytecode) and then rethrow the exception so it continues to propagate. If you take out those calls then javac does not need to introduce the extra handlers.
The reason why this changes things for Byteman is because it also has to deal with exception flow out of synchronized blocks. It uses exceptions to propagate control out of injected code when the injected rule's DO clause uses THROW or RETURN. Byteman installs a top-level handler for these Byteman exceptions. However, like javac it must also ensure that any injected code which is inside a synchronized block is protected by an intermediate handler which executes monitorexit and then rethrows the Byteman exception.
The problem you are seeing arises because Byteman must ensure its exception handling does not interfere with the exception handling inserted by javac. The messages about "invalid open enters count" and "exits unaccounted for" are an indication that Byteman is not able to to fully account for the javac exception flow. I fixed several bugs which relate to this problem in the 3.0.2 release -- however, there are probably one or more related bugs that I have not yet seen and your code looks like it has run up against one of them.
What is different about your case (as oppsoed to the bugs I just fixed) is that the problem is arising even though Byteman is not injecting inside the synchronized block. I am assuming that your AT ENTRY location is valid and is the only injection point for this method -- if it is not then I really need to know about that. If this assumption is correct then it looks like the problem here is not that Byteman's exception flow is getting tangled up with the method's exception flow. Instead it looks like Byteman just cannot understand the original program exception flow. That's rather odd and also unexpected. So, I would really like to be able to recreate this error. If you can produce a method which causes the problme without including proprietary information I'd be very interested to see it.
Meanwhile, I will try to generate some more complex test cases that might trigger this problem (or something like it).
regards,
Andrew Dinn
-
8. Re: Trying to read synchronized block
alexmarinho Nov 10, 2015 2:06 PM (in response to adinn)Can you reproduce if i send the whole javap output?
-
9. Re: Trying to read synchronized block
adinn Nov 11, 2015 6:59 AM (in response to alexmarinho)Hi Alessandro
Alessandro Marinho wrote:
Can you reproduce if i send the whole javap output?
Thanks, that would be very useful -- I may well be able to use the full output to help recreate a reproducer that was not specific to your application. I only really need the bytecode dump for the method you are injecting into (including the exception table).
regards,
Andrew Dinn
-
10. Re: Trying to read synchronized block
alexmarinho Nov 11, 2015 8:26 AM (in response to adinn)Ok, what comand should i run for that?
-
11. Re: Trying to read synchronized block
adinn Nov 11, 2015 10:32 AM (in response to alexmarinho)HI Alessandro
Alessandro Marinho wrote:
Ok, what comand should i run for that?
You can just use a normal javap -c command
javap -c -classpath /path/to/my/jar br.modify.TestModify
javap always prints out exception table entries. I don't actually need the full verbose output but if you are interested in seeing see details of the constant pool and other method info like line number and local variable tables then add flag -v
javap -c -v -classpath /path/to/my/jar br.modify.TestModify
-
12. Re: Trying to read synchronized block
alexmarinho Nov 11, 2015 11:24 AM (in response to adinn)Attached . If you reproduce, update me with news !
Thank you.
-
test.txt.zip 10.8 KB
-
-
13. Re: Trying to read synchronized block
adinn Nov 17, 2015 6:00 AM (in response to alexmarinho)Hi Alessandro,
This is the same problem that I explained in your previous posting.
You have recompiled this code with ecj, the Eclipse compiler. I can tell because of the way the bytecode has been generated from offset 1361 to 1400. This corresponds to the while loop in the middle of your method (the one where you iterate over the ArrayList returned by PeriodoGozoFeriasDAO.recuperaPeriodoGozoFeriasValidoAtivo(Long)). ecj has generated bytecode which skips forward from loop entry at 1361 to a loop test at 1393 and then jumps back to the loop body at 1364. Byteman cannot inject rules into code which has been generated in this way (see issue https://issues.jboss.org/browse/BYTEMAN-197 for details).
To resolve this you need to make sure that all your code is compiled by javac.