Search code examples
javabytecodeinstrumentation

Why does getLineNumber return -1 when using StackTraceElement


I want to get the current code line number when instrumenting the java bytecode. Instrumentation is achieved through ASM. Insert the bytecode corresponding to getLineNumber after the visitcode, the return value is -1, but the return value obtained by instrumentation in other locations is normal.

for example,the source code is as follows

public static int add(int a, int b){
        int sum = a + b;
        return sum;
    }

According to the logic of ASM, the bytecode to obtain the line number information should be inserted after the add method. But when I call the function in the main method, the line number obtained is -1

At the same time, I also analyzed the assembly code before and after instrumentation, as follows

//this is before instrumentation
public static int add(int, int);
    Code:
       0: iload_0
       1: iload_1
       2: iadd
       3: istore_2
       4: iload_2
       5: ireturn
//this is after instrumentation
public static int add(int, int);
    Code:
       0: new           #33                 // class java/lang/StringBuilder
       3: dup
       4: invokespecial #34                 // Method java/lang/StringBuilder."<init>":()V
       7: ldc           #36                 // String _
       9: invokevirtual #40                 // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      12: invokestatic  #46                 // Method java/lang/Thread.currentThread:()Ljava/lang/Thread;
      15: invokevirtual #50                 // Method java/lang/Thread.getStackTrace:()[Ljava/lang/StackTraceElement;
      18: iconst_1
      19: aaload
      20: invokevirtual #56                 // Method java/lang/StackTraceElement.getLineNumber:()I
      23: invokevirtual #59                 // Method java/lang/StringBuilder.append:(I)Ljava/lang/StringBuilder;
      26: invokevirtual #63                 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
      29: invokestatic  #69                 // Method afljava/logger/Logger.writeToLogger:(Ljava/lang/String;)V
      32: iload_0
      33: iload_1
      34: iadd
      35: istore_2
      36: iload_2
      37: ireturn

As you can see, I get not only the line number, but also the class name and method name. Among them, the class name and method name are obtained normally, and the line number is obtained as -1.

Additionally, Only inserting after the visitcode position will let the line number be -1, and inserting the same bytecode at other positions will not have this problem.

And this is one part of my instrumentation code

private void instrument(){
            mv.visitTypeInsn(Opcodes.NEW, "java/lang/StringBuilder");
            mv.visitInsn(Opcodes.DUP);

            mv.visitMethodInsn(Opcodes.INVOKESPECIAL, "java/lang/StringBuilder", "<init>", "()V", false);
            mv.visitMethodInsn(Opcodes.INVOKESTATIC, "java/lang/Thread", "currentThread", "()Ljava/lang/Thread;", false);
            mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, "java/lang/Thread", "getName", "()Ljava/lang/String;", false);
            mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false);
            mv.visitLdcInsn("_" + classAndMethodName + "_");

            mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false);
            mv.visitMethodInsn(Opcodes.INVOKESTATIC, "java/lang/Thread", "currentThread", "()Ljava/lang/Thread;", false);
            mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, "java/lang/Thread", "getStackTrace", "()[Ljava/lang/StackTraceElement;", false);
            mv.visitInsn(Opcodes.ICONST_1);
            mv.visitInsn(Opcodes.AALOAD);
            
            mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, "java/lang/StackTraceElement", "getLineNumber", "()I", false);
            mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(I)Ljava/lang/StringBuilder;", false);
            mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "toString", "()Ljava/lang/String;", false);
            mv.visitMethodInsn(Opcodes.INVOKESTATIC, "afljava/logger/Logger", "writeToLogger", "(Ljava/lang/String;)V", false);
        }

        @Override
        public void visitCode() {
            super.visitCode();
            instrument();
        }

Like Holger's code,instead I insert code by using visitcode.


Solution

  • The line numbers are given by the LineNumberTable Attribute which maps bytecode locations to source code lines. When you transform code with the ASM library, it will take care to adapt code locations to reflect changes.

    This implies that when you inject code before any original code, the location of the first code associated with a line number gets adapted too, so your new code is not covered by the line numbers.

    Instead of injecting the code on visitCode, you may inject it after the first line number has been reported through visitLineNumber. In the best case, this still is before any executable code (it may not, if synthetic code has been injected by other means already).

    This way, the new code gets associated with the first recorded line number. However, you don’t need to deal with stack traces to reconstitute this information, as it is already known at this point of code injection. Since class and method name are known too, there is not even a need to generate string concatenation code. You can assemble the string beforehand.

    package com.example;
    
    import java.lang.invoke.MethodHandles;
    
    import org.objectweb.asm.*;
    
    public class AsmExample {
        static class Test {
            public static int add(int a, int b){
                int sum = a + b;
                return sum;
            }
        }
    
        public static void main(String[] args) throws Exception {
            ClassReader cr = new ClassReader(AsmExample.class.getName()+"$Test");
            ClassWriter cw = new ClassWriter(cr, ClassWriter.COMPUTE_MAXS);
            cr.accept(new ClassVisitor(Opcodes.ASM9, cw) {
                String className;
                @Override
                public void visit(int ver,
                    int acc, String name, String sig, String superName, String[] ifs) {
    
                    super.visit(ver, acc, name, sig, superName, ifs);
                    className = name.replace('/', '.');
                }
                @Override
                public MethodVisitor visitMethod(
                    int acc, String name, String desc, String sig, String[] ex) {
    
                    MethodVisitor mv = super.visitMethod(acc, name, desc, sig, ex);
                    if(name.equals("add")) mv = new Injector(mv, className + '_' + name);
                    return mv;
                }
            }, 0);
    
            MethodHandles.lookup().defineClass(cw.toByteArray());
    
            System.out.println("return value: " + Test.add(30, 12));
        }
    
        static class Injector extends MethodVisitor {
            private final String classAndMethodName;
            private boolean logStatementAdded;
    
            public Injector(MethodVisitor methodVisitor, String classAndMethod) {
                super(Opcodes.ASM9, methodVisitor);
                classAndMethodName = classAndMethod;
            }
    
            @Override
            public void visitLineNumber(int line, Label start) {
                super.visitLineNumber(line, start);
                if(!logStatementAdded) {
                    logStatementAdded = true;
                    visitFieldInsn(Opcodes.GETSTATIC,
                        "java/lang/System", "out", "Ljava/io/PrintStream;");
                    visitLdcInsn(classAndMethodName + "_" + line);
                    visitMethodInsn(Opcodes.INVOKEVIRTUAL,
                        "java/io/PrintStream", "println", "(Ljava/lang/String;)V", false);
                }
            }
        }
    }
    
    com.example.AsmExample$Test_add_10
    return value: 42
    

    I used a simple print statement instead of your logger, but the example should be easy to adapt.


    As an alternative, if you want to stay with your original logic as much as possible, you may just alter the bytecode location of the first reported line number association, to cover your injected code:

    static class Injector extends MethodVisitor {
        private final String classAndMethodName;
        Label newStart = new Label();
    
        public Injector(MethodVisitor methodVisitor, String classAndMethod) {
            super(Opcodes.ASM9, methodVisitor);
            classAndMethodName = classAndMethod;
        }
    
        @Override
        public void visitCode() {
            super.visitCode();
            visitLabel(newStart);
            instrument();
        }
    
        @Override
        public void visitLineNumber(int line, Label start) {
            if(newStart != null) {
                start = newStart;
                newStart = null;
            }
            super.visitLineNumber(line, start);
        }
    
        …
    

    Keep in mind that a line number reported for a code location is associated with all following instructions, until the next line number is reported. While ASM will invoke the visitor methods in the order of the code locations, we don’t need to be as strict when calling into the class writer.

    So we can associate a Label with the beginning of the method by calling visitLabel(newStart); before instrument();, without knowing the line number. By the time, visitLineNumber is called for the first time, we replace the label start, which represents the original start of the method, with our new label, representing the new start. ASM doesn’t mind that we didn’t call visitLineNumber before instrument();, as only the code location associated with the Label matters.