2 Replies Latest reply on Sep 30, 2015 5:29 PM by Radek Koubský

    Unexpected behavior in TRY-CATCH-FINALLY

    Radek Koubský Newbie

      Hi,

      I am using Byteman in try-catch-finally block and something does not work as I would expect.

      Byteman 3.0.1

      wildfly-8.2.0.Final,

      resteasy version 3.0.10.Final:

      source code: https://github.com/RadekKoubsky/byteman-wildfly-log/blob/master/rules/rest.btm

       

      Here is the source code for both cases:

      public void service(String httpMethod, HttpServletRequest request, HttpServletResponse response, boolean handleNotFound) throws IOException, NotFoundException
         {
            try
            {
               //logger.info(httpMethod + " " + request.getRequestURL().toString());
               //logger.info("***PATH: " + request.getRequestURL());
               // classloader/deployment aware RestasyProviderFactory.  Used to have request specific
               // ResteasyProviderFactory.getInstance()
               ResteasyProviderFactory defaultInstance = ResteasyProviderFactory.getInstance();
               if (defaultInstance instanceof ThreadLocalResteasyProviderFactory)
               {
                  ThreadLocalResteasyProviderFactory.push(providerFactory);
               }
               ResteasyHttpHeaders headers = null;
               ResteasyUriInfo uriInfo = null;
               try
               {
                  headers = ServletUtil.extractHttpHeaders(request);
                  uriInfo = ServletUtil.extractUriInfo(request, servletMappingPrefix);
               }
               catch (Exception e)
               {
                  response.sendError(HttpServletResponse.SC_BAD_REQUEST);
                  // made it warn so that people can filter this.
                  logger.warn("Failed to parse request.", e);
                  return;
               }
      
      
               HttpResponse theResponse = responseFactory.createResteasyHttpResponse(response);
               HttpRequest in = requestFactory.createResteasyHttpRequest(httpMethod, request, headers, uriInfo, theResponse, response);
      
      
               try
               {
                  ResteasyProviderFactory.pushContext(HttpServletRequest.class, request);
                  ResteasyProviderFactory.pushContext(HttpServletResponse.class, response);
      
      
                  ResteasyProviderFactory.pushContext(SecurityContext.class, new ServletSecurityContext(request));
                  if (handleNotFound)
                  {
                     dispatcher.invoke(in, theResponse);
                  }
                  else
                  {
                     ((SynchronousDispatcher) dispatcher).invokePropagateNotFound(in, theResponse);
                  }
               }
               finally
               {
                  ResteasyProviderFactory.clearContextData();
               }
            }
            finally
            {
               ResteasyProviderFactory defaultInstance = ResteasyProviderFactory.getInstance();
               if (defaultInstance instanceof ThreadLocalResteasyProviderFactory)
               {
                  ThreadLocalResteasyProviderFactory.pop();
               }
      
      
            }
         }
      


      1) NullPointerException

      I have following rules:

      #Log extracting headers
      RULE logServletContainerDispatcher.service.headers
      CLASS org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher
      METHOD service(String, HttpServletRequest, HttpServletResponse, boolean)
      AFTER WRITE $headers 2
      IF true
      DO log($CLASS, "DEBUG", "(Method service) Extracted HTTP headers: " + $headers.requestHeaders + "\nCookies: " + $headers.cookies)
      ENDRULE
      
      
      #Log extracting uri info
      RULE logServletContainerDispatcher.service.uriInfo
      CLASS org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher
      METHOD service(String, HttpServletRequest, HttpServletResponse, boolean)
      AFTER WRITE $uriInfo 2
      IF true
      DO log($CLASS, "DEBUG", "(Method service) Extracted URI info (see details in logs below).")
      ENDRULE
      

       

      When I try to compile these rules, I am getting the same NullPointerException for both of them

      # File /home/koubsky/byteman-wildfly-log/rules/rest.btm line 27

      RULE logServletContainerDispatcher.service.headers

      CLASS org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher

      METHOD service(String, HttpServletRequest, HttpServletResponse, boolean)

      HELPER org.jboss.byteman.koubsky.LogHelper

      AFTER WRITE $headers 2

      IF true

      DO log($CLASS, "DEBUG", "(Method service) Extracted HTTP headers: " + $headers.requestHeaders + "\nCookies: " + $headers.cookies)

      ENDRULE

      Transformed in:

      loader: ModuleClassLoader for Module "org.jboss.resteasy.resteasy-jaxrs:main" from local module loader @6fb525d8 (finder: local module finder @5dc7c133 (roots: /home/koubsky/Wildfly8/wildfly-8.2.0.Final/modules,/home/koubsky/Wildfly8/wildfly-8.2.0.Final/modules/system/layers/base))

      trigger class: org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher

      threw java.lang.NullPointerException

      java.lang.NullPointerException

      at org.jboss.byteman.agent.adapter.cfg.CFG.inBytemanTrigger(CFG.java:1704)

      at org.jboss.byteman.agent.adapter.RuleTriggerMethodAdapter.inBytemanTrigger(RuleTriggerMethodAdapter.java:588)

      at org.jboss.byteman.agent.adapter.VariableAccessTriggerAdapter$VariableAccessTriggerMethodAdapter.visitVarInsn(VariableAccessTriggerAdapter.java:136)

      at org.jboss.byteman.objectweb.asm.tree.VarInsnNode.accept(Unknown Source)

      at org.jboss.byteman.agent.adapter.BMInsnList.accept(BMInsnList.java:81)

      at org.jboss.byteman.objectweb.asm.tree.MethodNode.accept(Unknown Source)

      at org.jboss.byteman.objectweb.asm.commons.JSRInlinerAdapter.visitEnd(Unknown Source)

      at org.jboss.byteman.objectweb.asm.ClassReader.b(Unknown Source)

      at org.jboss.byteman.objectweb.asm.ClassReader.accept(Unknown Source)

      at org.jboss.byteman.objectweb.asm.ClassReader.accept(Unknown Source)

      at org.jboss.byteman.agent.TransformContext.transform(TransformContext.java:150)

      at org.jboss.byteman.agent.Transformer.transform(Transformer.java:746)

      at org.jboss.byteman.agent.Transformer.tryTransform(Transformer.java:814)

      at org.jboss.byteman.agent.Transformer.tryTransform(Transformer.java:785)

      at org.jboss.byteman.agent.Transformer.transform(Transformer.java:257)

      at sun.instrument.TransformerManager.transform(TransformerManager.java:188)

      at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:424)

      at sun.instrument.InstrumentationImpl.retransformClasses0(Native Method)

      at sun.instrument.InstrumentationImpl.retransformClasses(InstrumentationImpl.java:144)

      at org.jboss.byteman.agent.Retransformer.installScript(Retransformer.java:144)

      at org.jboss.byteman.agent.TransformListener.handleScripts(TransformListener.java:349)

      at org.jboss.byteman.agent.TransformListener.loadScripts(TransformListener.java:272)

      at org.jboss.byteman.agent.TransformListener.handleConnection(TransformListener.java:225)

      at org.jboss.byteman.agent.TransformListener.run(TransformListener.java:158)

       

      NOTE: I use AFTER WRITE location specifier in different rules in the same script and it works properly. The only difference I see is try-catch-finally block in code which does not work. Am I missing something?

       

      2) Rule is not triggered

      In the same code in the last finally block, I defined this rule:

      #Log popping provider factory
      RULE logServletContainerDispatcher.service.pop
      CLASS org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher
      METHOD service(String, HttpServletRequest, HttpServletResponse, boolean)
      AT INVOKE org.jboss.resteasy.core.ThreadLocalResteasyProviderFactory.pop()
      IF true
      DO log($CLASS, "DEBUG", "(Method service) Default instance of ResteasyProviderFactory is instance of " +
        "ThreadLocalResteasyProviderFactory, popping provider factory.")
      ENDRULE
      

       

      When the code is executed (and it is, I tried to debug it), the rule is not triggered. Maybe it has something to do with the try-catch-finally again.

      On the other hand, this rule (which applies at the beginning of the first try block) is triggered:

      #Log pushing provider factory onto stack
      RULE logServletContainerDispatcher.service.push
      CLASS org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher
      METHOD service(String, HttpServletRequest, HttpServletResponse, boolean)
      AT INVOKE org.jboss.resteasy.core.ThreadLocalResteasyProviderFactory.push(ResteasyProviderFactory)
      IF true
      DO log($CLASS, "DEBUG", "(Method service) Default instance of ResteasyProviderFactory is instance of " +
        "ThreadLocalResteasyProviderFactory, pushing provider factory onto thread local stack.")
      ENDRULE
      

       

      Thank you for help, I can make a workaround, but it is not a solution...

        • 1. Re: Unexpected behavior in TRY-CATCH-FINALLY
          Andrew Dinn Master

          Hi Radek,

           

          Thanks very much for reporting this problem.

           

          1) The NullPointerException problem has only just been reported and fixed by Marco Rietveld.

           

            https://issues.jboss.org/browse/BYTEMAN-296

           

          It arises due to the fact that you are injecting into a catch region which has an associated finally block. Byteman assumes that a catch block will refer to a named (String) type but in this case the name is NULL. It's quite bizarre that this never showed until now and suddenly turned up twice within a few days. Anyway, Marco's fix should go into the next release (3.0.2) which will probably be released some time in the next month. If this is important for you let me know and I can accelerate the release.

           

          2) This problem requires a little bit of background to explain what is going wrong:

           

          Normally when you count textual occurences of Java calls they match up 1-1 with invokeStatic/invokeSpecial/invokeVrtual insrtructions in the bytecode. So, if your rule says

           

            AT INVOKE org.jboss.resteasy.core.ThreadLocalResteasyProviderFactory.push(ResteasyProviderFactory)

           

          or

           

            AT INVOKE org.jboss.resteasy.core.ThreadLocalResteasyProviderFactory.push(ResteasyProviderFactory) 4


          all Byteman has to do to identify the injection point is to walk through the bytecode looking at invokXXX instructions which refer to method push and count up to the number specified (default count is 1). That's also true for any other location specifier that takes a count e.g. AFTER READ $myLocalVar 3 etc.


          Unfortunately, when your code conatins finally blocks that 1-1 correspondence between source and bytecode is no longer valid.

           

          The problem is that a finally block can be entered via more than one path. In your example,  the outer finally block which contains the call to pop() can be entered normally if no exceptions occur inside the try catch region. It can also be entered if an uncaught exception occurs in the calls n that region which are not embedded in nested try-catch blocks


          Now, before JDK1.5 bytecode only ever contained 1 copy of the finally bytecode. At the end of the try-catch region a special bytecode called JSR was used to save the ciurrent bytecode position and jump to the finally code. The finally code would end with a RET instruction to return to the saved position (in your case that would have been a RETURN insruction -- that's a different bytecode which returns to the caller method). The try-catch region would also be marked as a catch-all exception region (i..e it would have exception type NULL meaning catch any Throwable). The handler code for that catch-all region would include a JSR to save the current position and jump to the finally code followed by a THROW bytecode. When the finally block executes  RET it returns to the THROW bytecode and rethrows the Throwabl.


          The JSR instruction was removed in JDK6 for reasons I won't go into. The alternative is for javac to omit teh JSR and inline the finall bytecodes in place of  it. So it inserts insert one copy of the finally bytecodes immediately after the bytecode sequence for the try-catch block. It inserts a second copy in the catch-all handler code. So, when you write


            AT INVOKE org.jboss.resteasy.core.ThreadLocalResteasyProviderFactory.pop()


          this will match the first call to pop() injected immeidately after the try-catch block. However, it won't match the second call to pop() injected into the catch-all exception handler code. So, you rrule ought to get triggered if no exception occurs inside the try catch block but will not trigger when the finally code is entered because of an exception.


          If you add another rule using count 2


            AT INVOKE org.jboss.resteasy.core.ThreadLocalResteasyProviderFactory.pop() 2


          then you will cover both cases. Alternatively try using this


            AT INVOKE org.jboss.resteasy.core.ThreadLocalResteasyProviderFactory.pop() ALL


          This should inject the rule at every call to pop(). (I think ALL works for every location which accepts a count). Please try these options and let me know whehter it fixes the problem.

           

          In summary, you need to realise that when you see a finally block then the normal counts don't apply. Operations inside the finally block will happen once for the normal patch through the code, once for every catch block that sits parallel with the finally block and then once for the uncaught exception path. That doesn't just affect the location count for rules injected into the finally block. It also affects the location cout for later rules. Unifortunately, when it comes to finally blocks Byteman is cheating when it pretends that source locations can uniquely identify bytecode locations.


          regards,



          Andrew Dinn


          • 2. Re: Unexpected behavior in TRY-CATCH-FINALLY
            Radek Koubský Newbie

            Thanks for your advice and clarification, I really like to learn about bytecode.

             

            ad 1)

            Ok, I will wait for the bug fix in order to test it. I will let you know when there is new byteman release.

             

            ad 2)

            I tried both solutions and both of them worked properly. Seems like try-catch-finally is more complicated than I thought.