13 Replies Latest reply on Nov 17, 2015 6:00 AM by adinn

    Trying to read synchronized block

    alexmarinho

      Hello guys!
      Please, somebody help me to understand what is going on..


      RULE trace modifyTest entry

       

      CLASS br.modify.TestModify

       

      METHOD programar

       

      AT ENTRY

      IF true

      DO traceln("Test..")

       

      ENDRULE

       

       

      .. Code...

       

      public ActionForward programar(ActionMapping mapping, ActionForm form, HttpServletRequest request, HttpServletResponse response) throws Exception {

       

      ...

       

      synchronized (this) {

       

      if (this.canProgram(mapping, formTest, request, response, ferias)) {

       

         TestDAO feriasDAO = new TestDAO(formTest);

       

      }

       

      }//end sync block

       

      }//END METHOD

       

       

      When i try to update the rule using bmsubmit...

      14:16:36,926 INFO  [stdout] (Thread-0) CFG.carryForward: unexpected! invalid open enters count for block L24981869 in method br.modify.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;

      14:16:36,926 INFO  [stdout] (Thread-0) CFG.carryForward: unexpected! invalid open enters count for block L23411947 in method br.modify.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;

      14:16:36,926 INFO  [stdout] (Thread-0) exits unaccounted for in block B46

       

       

      Result: prints nothing!

        • 1. Re: Trying to read synchronized block
          adinn

          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

            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

              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

                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

                  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

                    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

                      Alessandro Marinho wrote:

                       

                      If i remove this block above no error  prints , and it works .

                       

                      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

                        Can you reproduce if i send the   whole javap output?

                        • 9. Re: Trying to read synchronized block
                          adinn

                          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

                            Ok, what comand should i run for that?

                            • 11. Re: Trying to read synchronized block
                              adinn

                              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

                                Attached .  If you reproduce, update me with news !

                                 

                                Thank you.

                                • 13. Re: Trying to read synchronized block
                                  adinn

                                  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.