Unexpected behavior while tracing output

[purringpigeon]

Hello,

This one is very odd to me, and likely it's something I am doing incorrectly.  It just seems odd that the behavior is so different.

I have the following statement:

traceln("a"," dispatched at: " + $1.getTimeStamp());

This traces out just fine - to the console it includes the thread name, but to the file it simple outputs:

dispatched at: Mon Oct 27 09:27:50 MDT 2014

To assist in tracing the threads I changed the above line to:

traceln("a",Thread.currentThread().getName() + " dispatched at: " + $1.getTimeStamp());

However when this runs I get the following error:

2014-10-27|08:33:40,174 ERROR [org.jboss.as.ejb3] (Thread-132 (HornetQ-client-global-threads-1505424423)) javax.ejb.EJBTransactionRolledbackException: MethodExpression.interpret : exception invoking method traceln file TaskMDB.btm line 56

2014-10-27|08:33:40,174 ERROR [org.jboss.as.ejb3.invocation] (Thread-132 (HornetQ-client-global-threads-1505424423)) JBAS014134: EJB Invocation failed on component TaskEventHandlerMDB for method public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message): javax.ejb.EJBTransactionRolledbackException: MethodExpression.interpret : exception invoking method traceln file TaskMDB.btm line 56

at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleInCallerTx(CMTTxInterceptor.java:137)

at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:202)

at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:304)

at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:188)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:42)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:43)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.as.ejb3.component.messagedriven.MessageDrivenComponentDescription$5$1.processInvocation(MessageDrivenComponentDescription.java:184)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)

at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)

at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:181)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)

at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72)

at javax.jms.MessageListener$$$view163.onMessage(Unknown Source)

at sun.reflect.GeneratedMethodAccessor422.invoke(Unknown Source) [:1.7.0_25]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]

at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]

at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:142)

at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73)

at com.sun.proxy.$Proxy49.onMessage(Unknown Source)

at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:311)

at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:1033)

at org.hornetq.core.client.impl.ClientConsumerImpl.access$400(ClientConsumerImpl.java:50)

at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:1178)

at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_25]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_25]

at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_25]

Caused by: org.jboss.byteman.rule.exception.ExecuteException: MethodExpression.interpret : exception invoking method traceln file TaskMDB.btm line 56

at org.jboss.byteman.rule.expression.MethodExpression.interpret(MethodExpression.java:353) [byteman.jar:]

at org.jboss.byteman.rule.Action.interpret(Action.java:144) [byteman.jar:]

at org.jboss.byteman.rule.helper.InterpretedHelper.fire(InterpretedHelper.java:169) [byteman.jar:]

at org.jboss.byteman.rule.helper.InterpretedHelper.execute0(InterpretedHelper.java:137) [byteman.jar:]

at org.jboss.byteman.rule.helper.InterpretedHelper.execute(InterpretedHelper.java:100) [byteman.jar:]

at org.jboss.byteman.rule.Rule.execute(Rule.java:684) [byteman.jar:]

at org.jboss.byteman.rule.Rule.execute(Rule.java:653) [byteman.jar:]

at insureworx.workflow.eventhandler.ejb.TaskEventHandlerMDB.processEvent(TaskEventHandlerMDB.java)

at insureworx.ejbservices.eventhandler.ejb.EventHandlerBase.onMessage(EventHandlerBase.java:126)

at sun.reflect.GeneratedMethodAccessor473.invoke(Unknown Source) [:1.7.0_25]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]

at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]

at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)

at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)

at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)

at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)

at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:200)

... 38 more

Caused by: java.lang.ClassCastException: java.util.Date cannot be cast to java.lang.String

at org.jboss.byteman.rule.expression.PlusExpression.interpret(PlusExpression.java:75) [byteman.jar:]

at org.jboss.byteman.rule.expression.MethodExpression.interpret(MethodExpression.java:335) [byteman.jar:]

... 64 more

[adinn]

Hi Derek,

Oooh, interesting error! (oops, sorry, I don't suppose that's the sort of response that users of a piece of software really like to hear from it's developers :-)

To assist in tracing the threads I changed the above line to:

traceln("a",Thread.currentThread().getName() + " dispatched at: " + $1.getTimeStamp());

. . .

Caused by: org.jboss.byteman.rule.exception.ExecuteException: MethodExpression.interpret : exception invoking method traceln file TaskMDB.btm line 56

at org.jboss.byteman.rule.expression.MethodExpression.interpret(MethodExpression.java:353) [byteman.jar:]

at org.jboss.byteman.rule.Action.interpret(Action.java:144) [byteman.jar:]

. . .

Caused by: java.lang.ClassCastException: java.util.Date cannot be cast to java.lang.String

at org.jboss.byteman.rule.expression.PlusExpression.interpret(PlusExpression.java:75) [byteman.jar:]

This is an error in the interpreter which I am very pleased you have found. I have raised JIRA BYTEMAN-275 to track it and I already have a fix for it which I will commit today (once I have added a bugfix unit test case for it) The fix which will go into the next release (2.2.1).

As a workaround I suggest you make your rule do the missing toString conversion that Byteman is supposed to do i.e. use

traceln("a",Thread.currentThread().getName() + " dispatched at: " + $1.getTimeStamp().toString());

In case you are interested in why it occurs in one case and not the other here is an explanation of what was wrong. The difference between you two examples arises because the  two rules get parsed into different types of expressions and those expressions have different implementations of the interpret method. It's all to do with the ambiguity of the '+' operator. Is it a string concat or an arithmetic add?

When the parser parses StringLiteral + Expression (e.g."dispatched at: " + $1.getTimeStamp() ) it creates a StringPlusExpression. That's because it knows that the '+' must be a String concatenation (StringLiteral means an actual string written between quotes like "foo", "dispatched at " etc). Method StringPlusExpression.interpret knows it is dealing with Strings and knows that the first argument is a specific String. So, it computes the value for the second argument, calls toString() to ensure it is converted to a String then appends that value to the first argument to produce its result. This is what happens when your first rule is executed.

When the parser sees Expression + Expression where the left hand term is not a StringLiteral it creates a PlusExpression. It needs to run the type checker before it can decide whether the arguments are numbers or Strings. So, with your second rule the parser  sees Thread.currentThread().getName() + " dispatched at: " + $1.getTimeStamp()) which it recognises  as being of the form ((MethodExpression + StringLiteral) + MethodExpression). The parser creates a parse tree which looks like this

PlusExpression(PlusExpression(MethodExpression,
                              StringLiteral),
               MethodExpression)

The type checker actually handles this correctly. It identifies that the inner MethodExpression is a call to a method which returns a String (the thread name). It then verifies that the second argument is a valid argument for a string concatenation (yes, it's a string!). So, the inner PlusExpression is typed with type String -- which is why the interpreter knows to do a string concat. The type checker then recognises that the first argument to the outer PlusExpression is a String. It checks that the 2nd argument is a valid argument for a string concatenation (yes, it's an object and any object can be converted by callng toString()!). So the outer PlusExpression is typed with type String and, once again, the interpreter knows to do a string concat.

The bug is in the interpreter code, specifically in PlusExpression.interpret:

public Object interpret(HelperAdapter helper) throws ExecuteException {
    Object value1 = getoperand(0).interpret(helper);
    Object value2 = getOperand(1).interpret(helper);
    if (type == Type.STRING) {
            String s1 = (String)value1;
            String s2 =(String)value2;
            return s1 + s2;
    } else {
        . . .

This code is ok when the inner PlusExpression executes because value1 and value2 are actually String objects (the thread name and the string "dispatched at: ". Unfortunately, when the outer PlusExpression executes the first argument is a String while the second argument is a Date. So the cast at line 6 throws an exception. The correct code is this:

public Object interpret(HelperAdapter helper) throws ExecuteException {
   Object value1 = getOperand(0).interpret(helper);
    Object value2 = getOperand(1).interpret(helper);
    if (type == Type.STRING) {
        String s1 = (value1 != null ? value1.toString() : "null");
        String s2 = (value2 != null ? value2.toString() : "null");
        return s1 + s2;
    } else {
        . . .

Thanks very much for finding and reporting this bug.

regards,

Andrew Dinn

[purringpigeon]

Thanks for the explanation.  I did use toString() to solve my issue, however when I tried it with a HashMap it also gave me all kinds of trouble.  So I reverted back to the original call and reported the bug.

Hopefully this fix will also correct HashMap which didn't seem to work with the toString() method.