Strange StackOverFlowError for Proxy class

[bluegol]

Hi Andrew,

(It's me again.) Not really a narrowed-down report, but I'd like to share in case anyone has any idea.

Background: I'm trying to trace all jdbc prepared statements (among other things.)

The target app is an in-house jsp on tomcat, using myBatis, Spring framework, log4jdbc and so on.

Specifically, I have rules:

RULE pstmt reserve start

INTERFACE ^java.sql.Connection

METHOD prepareStatement

AT ENTRY

IF TRUE

DO

  reserve(true, com.brainzsquare.apm.TraceItem.TIT_JDBC_PSTMT);

ENDRULE

RULE pstmt start

INTERFACE ^java.sql.Connection

METHOD prepareStatement

AT EXIT

IF TRUE

DO

  traceln(">>>>>> " + $CLASS);

  start(true, $!, com.brainzsquare.apm.TraceItem.TIT_JDBC_PSTMT, null);

ENDRULE

The function reserve increases a counter (attached to the type given as the second parameter),

and the function start decreases a counter, and if the counter becomes 0, it creates a TraceItem

and saves it.

It works with other types (servlet, jdbc connections, etc.) and other instances of the prepared statement.

But I received the following error in some of the trace (only relevant logs are shown):

...

Installed rule using default helper : pstmt reserve start

08:57:56.302 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - rese

rved. type: JDBC_PSTMT, ...

08:57:56.324 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - not

reserved. isStart: true, type: JDBC_PSTMT, counter: 2

... (skipped counters 3, 4, 5, 6)

08:57:56.441 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - not

reserved. isStart: true, type: JDBC_PSTMT, counter: 7

... (callstack to be shown later)

Installed rule using default helper : pstmt start

>>>>>> org.postgresql.jdbc3g.Jdbc3gConnection

08:57:56.605 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - not

started. target: <class org.postgresql.jdbc3g.Jdbc3gPreparedStatement>1226825917

:select z_myid as z_infraid ...

                order by z_myid asc, type:JDBC_PSTMT, counter: 6

... (skipped counters 5, 4, 3, 2)

Installed rule using default helper : pstmt start

>>>>>> org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper

08:57:56.717 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - not

started. target: <class org.apache.commons.dbcp.DelegatingPreparedStatement>7967

80858:net.sf.log4jdbc.PreparedStatementSpy@2f7de93a, type:JDBC_PSTMT, counter: 1

Installed rule using default helper : pstmt start

>>>>>> com.sun.proxy.$Proxy77

*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message

transform method call failed at JPLISAgent.c line: 844

... ---------------------------------------------------------- (this appears total 12 times in a row)

pstmt start : java.lang.StackOverflowError

And when the counter is 7, i.e, when the callstack is deepest, it is:

org.postgresql.jdbc3g.Jdbc3gConnection.prepareStatement(Jdbc3gConnection.java)

org.postgresql.jdbc3.AbstractJdbc3Connection.prepareStatement(AbstractJdbc3Connection.java:274)

org.postgresql.jdbc2.AbstractJdbc2Connection.prepareStatement(AbstractJdbc2Connection.java:301)

net.sf.log4jdbc.ConnectionSpy.prepareStatement(ConnectionSpy.java:388)

org.apache.commons.dbcp.DelegatingConnection.prepareStatement(DelegatingConnection.java:281)

org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.prepareStatement(PoolingDataSource.java:313)

sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

java.lang.reflect.Method.invoke(Method.java:497)

org.apache.ibatis.logging.jdbc.ConnectionLogger.invoke(ConnectionLogger.java:50)

com.sun.proxy.$Proxy77.prepareStatement(Unknown Source)

So it seems the counter logic works well.

I'd like to emphasize that the function "start" works fine in other cases. No recursion is in its logic. Also I tried doubling up jvm stack size,

only to get the same error at the same place.

After banging my head against my desk for some time, I realized the class in question is a Proxy class. So I changed my rule:

RULE pstmt reserve start

INTERFACE ^java.sql.Connection

METHOD prepareStatement

AT ENTRY

IF classNameOK($CLASS)

DO

  reserve(true, com.brainzsquare.apm.TraceItem.TIT_JDBC_PSTMT);

ENDRULE

RULE pstmt start

INTERFACE ^java.sql.Connection

METHOD prepareStatement

AT EXIT

IF classNameOK($CLASS)

DO

  traceln(">>>>>> " + $CLASS);

  start(true, $!, com.brainzsquare.apm.TraceItem.TIT_JDBC_PSTMT, null);

ENDRULE

so that the rules skip "com.sun.proxy.*" classes. Then it worked! (Of course, by adding that rule, lots of

states are changed and I can't be 100% sure. But it worked in this specific case, and all other trace injection

worked without problem in my case...)

(Question #1) Do you have any suspicion that proxy classes might have conflict with byteman? Or do you have any idea why

StackOverFlowError occurred? (I'm 99% sure that it's not due to recursion, since I don't have any.)

Now why do I suspect proxy classes? I checked my rules with byteman-submit.jar -l, which shows lots of TypeWarningExceptions

involving proxy classes: unknown local variable $this, no matching injection, and esp.

failed to find any matching trigger method in class com.sun.proxy.$Proxy77.

(Question #2) Are these TypeWarningException with proxy classes harmless?

Best,

Jahwan

[adinn]

Hi Jahwan,

Jahwan Kim wrote:

Hi Andrew,

(It's me again.) Not really a narrowed-down report, but I'd like to share in case anyone has any idea.

Thanks for posting this all the same. It is good to know that something is wrong even if you don't have all the details figured out.

Background: I'm trying to trace all jdbc prepared statements (among other things.)

  . . .

But I received the following error in some of the trace (only relevant logs are shown):

...

Installed rule using default helper : pstmt start

>>>>>> com.sun.proxy.$Proxy77

*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message

transform method call failed at JPLISAgent.c line: 844

... ---------------------------------------------------------- (this appears total 12 times in a row)

Hmm, which JDK are you using? I have seen that error with a Jigsaw enabled JDK9 but not in prior releases. It has been discusssed on the Jigsaw list and I believe a fix is pending. Anyway, I have not noticed it actually causing problems with Byteman's Transformer so I'll leave this issue aside just for now.

pstmt start : java.lang.StackOverflowError

And when the counter is 7, i.e, when the callstack is deepest, it is:

org.postgresql.jdbc3g.Jdbc3gConnection.prepareStatement(Jdbc3gConnection.java)

org.postgresql.jdbc3.AbstractJdbc3Connection.prepareStatement(AbstractJdbc3Connection.java:274)

org.postgresql.jdbc2.AbstractJdbc2Connection.prepareStatement(AbstractJdbc2Connection.java:301)

net.sf.log4jdbc.ConnectionSpy.prepareStatement(ConnectionSpy.java:388)

org.apache.commons.dbcp.DelegatingConnection.prepareStatement(DelegatingConnection.java:281)

org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.prepareStatement(PoolingDataSource.java:313)

sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

java.lang.reflect.Method.invoke(Method.java:497)

org.apache.ibatis.logging.jdbc.ConnectionLogger.invoke(ConnectionLogger.java:50)

com.sun.proxy.$Proxy77.prepareStatement(Unknown Source)

So it seems the counter logic works well.

Well, this looks like what you would expect in the stack trace for a proxy call -- it is indirecting through to an underlying 'real' instance of the connection and has to use a Method invoke to do that. Do you have the rest of the stack trace? If so then it might wel show whether Byteman is involved in causing the stack overflow.

n.b. if you don't get a full trace in the output then you might be able to add some tracing code to help you observe the stack frames building up. If your helper class extends the Byteman helper then you could try changing your start rule to add a call to traceStack() before the call to reserve(). That will print a stacktrace at each trigger point which will show you whether Byteman calls are involved in the recursion. If you helper class does not extend the Byteman helper then you could plant the following code new RuntimeException("trace stack").printStacktrace() in method reserve to do much the same thing. This ought to be enough to determine if there is a recursive call cycle involving Byteman.

I'd like to emphasize that the function "start" works fine in other cases. No recursion is in its logic. Also I tried doubling up jvm stack size,

only to get the same error at the same place.

Hmm, it's a bit weird that it happens in the same place with a larger stack. Perhaps the problem is actually happening under that last call rather than across the hierarchy of prepare calls in the stack trace.

After banging my head against my desk for some time, I realized the class in question is a Proxy class. So I changed my rule:

RULE pstmt reserve start

INTERFACE ^java.sql.Connection

METHOD prepareStatement

AT ENTRY

IF classNameOK($CLASS)

DO

  reserve(true, com.brainzsquare.apm.TraceItem.TIT_JDBC_PSTMT);

ENDRULE

RULE pstmt start

INTERFACE ^java.sql.Connection

METHOD prepareStatement

AT EXIT

IF classNameOK($CLASS)

DO

  traceln(">>>>>> " + $CLASS);

  start(true, $!, com.brainzsquare.apm.TraceItem.TIT_JDBC_PSTMT, null);

ENDRULE

so that the rules skip "com.sun.proxy.*" classes. Then it worked! (Of course, by adding that rule, lots of

states are changed and I can't be 100% sure. But it worked in this specific case, and all other trace injection

worked without problem in my case...)

Well, that's interesting but it isn't really enough to know what is going on.

(Question #1) Do you have any suspicion that proxy classes might have conflict with byteman? Or do you have any idea why

StackOverFlowError occurred? (I'm 99% sure that it's not due to recursion, since I don't have any.)

Now why do I suspect proxy classes? I checked my rules with byteman-submit.jar -l, which shows lots of TypeWarningExceptions

involving proxy classes: unknown local variable $this, no matching injection, and esp.

failed to find any matching trigger method in class com.sun.proxy.$Proxy77.

(Question #2) Are these TypeWarningException with proxy classes harmless?

No, I have not seen any issues to do with proxy classes. It doesn't look to me anything like it is to do with recursion as far as the calls in the stack trace are concerned. However, there may be more to it than meets the eye. I assume your helper methods don't call anything which might indirectly involve a connection prepare? (yes, I'm grabbing at straws here :-).

The TypeWarning messages are merely that -- warnings -- and almost certainly indicate no problem -- although I'm not quite sure why you are getting these specific warning given the rules you have quoted. The explanation for the warnings as quoted is as follows:

Firstly, lets just get something out of the way. The error indicates that the offending rule includes a reference to $this which suggests it is not to do with the rules you quoted. I don't see any such reference in those rules -- perhaps this was in some variant of them or in some other rules that you have tried to load? I'll assume oen or toher of those.

Interface rules, especially overriding rules can match more than one implementation and that may include implementations belonging to proxy classes that are generated at runtime. The problem with that is that the corresponding method of the proxy does not include a symbol table mappnig var names to slots for some specific range of bytecodes. It's a generated class rather than a class derived from source code so there are no var names to map -- although you might reasonably  expect this to be treated specially and implictly mapped to slot 0 for the full range of bytcode posiitons for any instance method. Anyway, with a proxy there is no info allowing Byteman to map the name this to the target instance of the method lcoated in slot 0. As a result Byteman decides it is not in a position to inject into this method because the rule does not match the bytecode. If the rule in question used $0 then Byteman would be able to correlate the indexed reference with the target instance and would inject it

n.b. this problem does not apply to the rules you have cited because neither of them uses references to local or parameter args by name. That tallies with the fact that these rules do get injected, requiring you to filter them out.

Let me know if adding the stack trace calls to your rules gives any further information about the recursion. I am afraid I cannot really diagnose this any further without more information. Even if it doesn't show anything that in itself might help to know where to go next.

fact

regards,

Andrew Dinn

[bluegol]

Hi Andrew,

Thanks for the prompt reply.

Apparently, I didn't spend enough time last night with the problem. I'll write down what I have found.

BTW, I'm using the standard Java 8 SE: java -version

java version "1.8.0_73"

Java(TM) SE Runtime Environment (build 1.8.0_73-b02)

Java HotSpot(TM) 64-Bit Server VM (build 25.73-b02, mixed mode)

TL; DR. The error happened at o.hashCode().

First the trace start was reserved:

Installed rule using default helper : pstmt reserve start

19:31:21.570 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - ente

ring reserve

Stack trace for thread localhost-startStop-1

com.sun.proxy.$Proxy77.prepareStatement (Unknown Source)

org.apache.ibatis.executor.statement.PreparedStatementHandler.instantiateStatement(PreparedStatementHandler.java:72)

...

Then after going into 7 layers of super calls and delegation, the program is exiting com.sun.proxy.$Proxy77.prepareStatement

That is it's time to start trace:

Installed rule using default helper : pstmt start

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - entering start

Stack trace for thread localhost-startStop-1

com.sun.proxy.$Proxy77.prepareStatement (Unknown Source)

org.apache.ibatis.executor.statement.PreparedStatementHandler.instantiateStatement(PreparedStatementHandler.java:72)

...

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - in MainTracer.start

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - in Tracer.start

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - entering Tracer.checkReservation

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - ... finished while loop 0 com.brainzsquare.apm.agent.MainTracer$Tracer$Reservation@4552387d 1

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - ... finished check loop 0 com.brainzsquare.apm.agent.MainTracer$Tracer$Reservation@4552387d 1 1

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - ... ... after dec

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - ... ... in if block

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - ... ... true

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - ... ... net.sf.log4jdbc.PreparedStatementSpy@4c652d2d

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - ... ... 122

19:31:22.077 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - entering TraceItem.objInfo

19:31:22.078 [localhost-startStop-1] INFO com.brainzsquare.apm.agent.Main - ... a

*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message transform method call failed at JPLISAgent.c line: 844

*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message transform method call failed at JPLISAgent.c line: 844

*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message transform method call failed at JPLISAgent.c line: 844

pstmt start : java.lang.StackOverflowError

I inserted lots of logs (using binary search along the way), and found the above one. The last log corresponds to the following code:

Main.logger.info("... a");

int i0 = o.hashCode();

Main.logger.info("... aa");

String sa = String.format("%s", Integer.toHexString(o.hashCode()));

Main.logger.info("... b");

String sb = String.format("%s", o.getClass().getName());

Main.logger.info("... c");

String sc = String.format("%s", o);

So it died on o.hashCode(), where o was an object of com.sun.proxy.$Proxy77, while o.prepareStatement() was being transformed.

A proxy class does not really have bytecode other than that of InvocationHandler.invoke.

If jvm is trying to transform bytecode of InvocationHandler.invoke, well, then StackOverFlowError makes sense,

since hashCode() call goes through InvocationHandler. I'm not sure.

But should jvm transform bytecode of InvocationHandler.invoke, when asked to transform Connection.prepareStatement()?

I don't think the official doc includes any info on this. Well, as far as I can tell, the official jvm doc doesn't mention instrumentation.

So many subtle points remain unclear.

I'll try some really isolated experiments on this, and report it back tomorrow.

Jahwan

[bluegol]

OK, my bad (sort of).

I think I nailed down the problem after about a day or two.

TL;DR: it seems that calling hashCode() net.sf.log4jdbc.PreparedStatementSpy,

which is a proxy class, causes StackOverFlowError! And why? well,

Closes #152. Indentation for nested selects logging · mybatis/mybatis-3@074cef5 · GitHub

(It was fixed with this commit, without any explicit mention! I found out we're using a pretty old lib.)

Look for the file: src/main/java/org/apache/ibatis/logging/jdbc/PreparedStatementLogger.java, and then around old line nos. 77-81.

That's what you should not do in InvocationHandler of Proxy class, calling proxy.hashCode()! Of course

it will be an infinite recursion!

It's good to find out that byteman and instrumentation mechanism don't have a problem, but it also made me worry

about robustness of instrumentation software in general.

Best,

Jahwan

[adinn]

Hi Jahwan,

Look for the file: src/main/java/org/apache/ibatis/logging/jdbc/PreparedStatementLogger.java, and then around old line nos. 77-81.

That's what you should not do in InvocationHandler of Proxy class, calling proxy.hashCode()! Of course

it will be an infinite recursion!

Hmm, yes not a very good idea :-) Well done for working out what as going wrong.

It's good to find out that byteman and instrumentation mechanism don't have a problem, but it also made me worry

about robustness of instrumentation software in general.

If you had been here about 6 years ago your concerns about the injected trigger code entering into a recursive loop would have been well founded. I mostly sorted that problem out in  a 1.x release. I did get bitten about a year ago where someone injected a rule into one of the very few JDK APIs I use to detect recursive entry (a method of ThreadLocal) and, of course, it blew up again for that very special case. That is now dealt with as a very special corner case where injection fails. Rceursive triggering still costs a little (Byteman has to do a ThreadLocal check to see if it is legitimate) but it i at least safe.

As this example shows most software has bugs even when it is quite mature software. The JVMTI agent API, especially bytecode rewriting, looks decidedly risky when you first encounter it, given that it promises to allow you to rebuild the boat while still sailing, but it does actually fulfil that promise and really has to be regarded as quite astonishingly reliable.

I'm not going to be so foolish as to suggest that Byteman does not still have bugs in it -- I am sure they are in there -- but after 7 years of development and wide-scale use it is a mature piece of software so many of the obvious problems have been sorted out, particularly those which relate to the core functionality that has been implemented for a long time. So,  I don't think the Byteman implementation itself merits being placed in a higher risk category than a lot of other software. That's not to say that the wrong rules won't completely break your program. Like most powerful tools it can wreak havoc if used indiscriminately. But to be fair I think that ought to be regarded as the users' problem not Byteman's ;-)

regards,

Andrew Dinn