Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ArrayIndexOutOfBoundsException in VariableMapper #377

Closed
zeocio opened this issue Mar 1, 2019 · 8 comments
Closed

ArrayIndexOutOfBoundsException in VariableMapper #377

zeocio opened this issue Mar 1, 2019 · 8 comments
Milestone
2.0.0

Comments

@zeocio
Copy link

zeocio commented Mar 1, 2019 •
edited
Loading

Using version 1.13.1.3 I ran into a number of the following problems tracing on a custom web server app:

java.lang.ArrayIndexOutOfBoundsException: 18
    at com.sun.btrace.runtime.VariableMapper.remap(VariableMapper.java:60)
    at com.sun.btrace.runtime.InstrumentingMethodVisitor.visitVarInsn(InstrumentingMethodVisitor.java:658)
    at com.sun.btrace.org.objectweb.asm.MethodVisitor.visitVarInsn(Unknown Source)
    at com.sun.btrace.util.templates.TemplateExpanderVisitor.visitVarInsn(TemplateExpanderVisitor.java:79)
    at com.sun.btrace.org.objectweb.asm.MethodVisitor.visitVarInsn(Unknown Source)
    at com.sun.btrace.org.objectweb.asm.MethodVisitor.visitVarInsn(Unknown Source)
    at com.sun.btrace.org.objectweb.asm.ClassReader.a(Unknown Source)
    at com.sun.btrace.org.objectweb.asm.ClassReader.b(Unknown Source)
    at com.sun.btrace.org.objectweb.asm.ClassReader.accept(Unknown Source)
    at com.sun.btrace.runtime.BTraceClassReader.accept(BTraceClassReader.java:174)
    at com.sun.btrace.org.objectweb.asm.ClassReader.accept(Unknown Source)
    at com.sun.btrace.runtime.BTraceClassReader.accept(BTraceClassReader.java:183)
    at com.sun.btrace.runtime.InstrumentUtils.accept(InstrumentUtils.java:177)
    at com.sun.btrace.runtime.InstrumentUtils.accept(InstrumentUtils.java:171)
    at com.sun.btrace.runtime.BTraceClassWriter.instrument(BTraceClassWriter.java:82)
    at com.sun.btrace.runtime.BTraceTransformer.transform(BTraceTransformer.java:198)
    at sun.instrument.TransformerManager.transform(TransformerManager.java:188)
    at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:428)
    at sun.instrument.InstrumentationImpl.retransformClasses0(Native Method)
    at sun.instrument.InstrumentationImpl.retransformClasses(InstrumentationImpl.java:144)
    at com.sun.btrace.agent.Client.retransformLoaded(Client.java:479)
    at com.sun.btrace.agent.Main$3.run(Main.java:693)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

The common theme for these exceptions seems to be visiting of a method body of M of class C where we have:

interface A {
...
M();
...
}
abstract class B implements A {
...
}
class C extends B {
...
@Override
M(){...;}
...
}

I have added a debug print in InstrumentingMethodVisitor.java:658 but I don't know how to interpret the output:

btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 0
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 1
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 2
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 2
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 3
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 2
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 4
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 2
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 5
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 2
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 6
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 2
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 7
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 8
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 3
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 7
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 8
btrace INFO: About to remap with Owner: identity/provisioning/UserProvRequestInsertOnUserCreateMessageHandler, Name: handleMessage, argsSize: 3, var: 21
btrace DEBUG: java.lang.ArrayIndexOutOfBoundsException: 18
    at com.sun.btrace.runtime.VariableMapper.remap(VariableMapper.java:60)
    at com.sun.btrace.runtime.InstrumentingMethodVisitor.visitVarInsn(InstrumentingMethodVisitor.java:659)
    at com.sun.btrace.org.objectweb.asm.MethodVisitor.visitVarInsn(Unknown Source)
    at com.sun.btrace.util.templates.TemplateExpanderVisitor.visitVarInsn(TemplateExpanderVisitor.java:79)
    at com.sun.btrace.org.objectweb.asm.MethodVisitor.visitVarInsn(Unknown Source)
    at com.sun.btrace.org.objectweb.asm.MethodVisitor.visitVarInsn(Unknown Source)
    at com.sun.btrace.org.objectweb.asm.ClassReader.a(Unknown Source)
    at com.sun.btrace.org.objectweb.asm.ClassReader.b(Unknown Source)
    at com.sun.btrace.org.objectweb.asm.ClassReader.accept(Unknown Source)
    at com.sun.btrace.runtime.BTraceClassReader.accept(BTraceClassReader.java:174)
    at com.sun.btrace.org.objectweb.asm.ClassReader.accept(Unknown Source)
    at com.sun.btrace.runtime.BTraceClassReader.accept(BTraceClassReader.java:183)
    at com.sun.btrace.runtime.InstrumentUtils.accept(InstrumentUtils.java:177)
    at com.sun.btrace.runtime.InstrumentUtils.accept(InstrumentUtils.java:171)
    at com.sun.btrace.runtime.BTraceClassWriter.instrument(BTraceClassWriter.java:82)
    at com.sun.btrace.runtime.BTraceTransformer.transform(BTraceTransformer.java:198)

Any suggestion what the cause might be?
@jbachorik
Copy link
Collaborator

This is related to stackmap frames and variable index remapping in general.
There seems to be a variable index suddenly increasing from 8 to 21 - meaning the offset goes from 5 to 18 and the array resize is not sufficient. This is pretty easy to fix - but just out of curiosity - is the bytecode generated by javac or some other means?

@zeocio
Copy link
Author

zeocio commented Mar 1, 2019

Although we do have some cglib/scala generated classes in the same jvm I am 80% certain the offending classes are generated by javac.

@zeocio
Copy link
Author

zeocio commented Mar 1, 2019

Is there any other debug log i can add to provide more insight for a fix?

@zeocio
Copy link
Author

zeocio commented Mar 2, 2019

Here is the javap -p -s -c -l output for that class method, with the load/store of local vars only:

    Code:
       0: aload_2
       6: astore_3
       7: aload_2
      15: astore        4
      17: aload_2
      25: astore        5
      27: aload_2
      35: astore        6
      37: aload_2
      45: astore        7
      60: astore        8
      66: aload_3
      67: aload         7
      75: aload         8
      89: astore        21
     110: aload         21
     116: astore        9
     121: astore        10
     130: astore        11
     132: aload         8
     134: aload         5
     146: astore        13
     151: aload         13
     161: astore        12
     163: aload         8
     165: aload_3
     166: aload         12
     174: aload         10
     189: astore        14
     192: astore        15
     198: aload         6
     215: astore        16
     226: astore        17
     228: aload         17
     234: aload         17
     236: aload         12
     247: aload         17
     249: aload         12
     260: aload         17
     262: aload         16
     267: aload         8
     269: aload         4
     271: aload         12
     279: aload_3
     285: astore        18
     287: aload         18
     292: aload         18
     300: astore        19
     302: aload         19
     307: aload         19
     312: astore        14
     314: aload         19
     319: astore        15
     321: aload         18
     329: astore        10
     334: astore        18
     345: aload         18
     354: aload         17
     356: aload         10
     361: aload         17
     363: aload         9
     368: aload         17
     370: aload         4
     375: aload         17
     377: aload         15
     382: aload         17
     384: aload         14
     389: aload         8
     391: aload         12
     412: astore        18
     414: aload         18
     419: aload         17
     421: aload         18
     441: aload         17
     443: aload         18
     467: aload         12
     492: aload         11
     494: aload         17
     502: aload         13
     512: aload         11
     537: astore        21
     558: aload         21
     561: astore        8
     583: aload         4
     594: aload_3
     601: aload         8
     637: astore        21
     658: aload         21
     661: astore        20
     682: aload         20

@jbachorik
Copy link
Collaborator

It's difficult to tell but the bytecode seems to be doing a lot of shuffling of values between local variable slots.
Anyway, the mapping array resize code should be adjusted like this:

if (offset >= mapping.length) {
    mapping = Arrays.copyOf(mapping, Math.max(mapping.length * 2, offset * 1.5));
}

@zeocio
Copy link
Author

zeocio commented Mar 3, 2019

The new resizing logic works, thanks.

However I notice a few java.lang.VerifyError: Stack map does not match the one at exception handler in the logs. This is not caused by the resizing fix, I will open a new tracking issue.

@jbachorik
Copy link
Collaborator

Any chance sharing more details about that VerifyError?

@jbachorik
Copy link
Collaborator

IMO, the verification error was fixed by #397
Closing for now. Please, reopen if still can reproduce.

@jbachorik jbachorik added this to the 2.0.0 milestone Feb 11, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
2.0.0
Development

No branches or pull requests
2 participants
@jbachorik @zeocio