Unexpected behavior in TRY-CATCH-FINALLY

[radek.koubsky]

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...

[adinn]

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

[radek.koubsky]

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.