elastic / apm-agent-java

https://www.elastic.co/guide/en/apm/agent/java/current/index.html
Apache License 2.0
567 stars 321 forks source link

Why can't I get the method‘s real parameter name when i use apm-agent? #3237

Open hhhhhxm opened 1 year ago

hhhhhxm commented 1 year ago

Why can't I get the method‘s real parameter name by reflect? i can get the method‘s real parameter name When the program first started,but i can‘t get the method's real parameter name after printing this log.

2023-07-14 13:58:27,588 [http-nio-8081-exec-4] INFO  co.elastic.apm.agent.servlet.ServletVersionInstrumentation - Servlet container info = Apache Tomcat/9.0.60

2023-07-14 13:58:27,710 [Attach Listener] INFO  co.elastic.apm.agent.impl.ElasticApmTracer - Tracer switched to RUNNING state

my code like this

@GetMapping("/test01")
    public String test01() throws NoSuchMethodException {
        Method testMethod = HelloController.class.getDeclaredMethod("test", int.class);
        for (Parameter parameter : testMethod.getParameters()) {
            System.out.println("param name is" + parameter.getName());
        }
        return "ok";
    }

    private static void test(int num) {

    }

and log info like this

param name isnum

2023-07-14 13:58:27,588 [http-nio-8081-exec-4] INFO  co.elastic.apm.agent.servlet.ServletVersionInstrumentation - Servlet container info = Apache Tomcat/9.0.60

2023-07-14 13:58:27,710 [Attach Listener] INFO  co.elastic.apm.agent.impl.ElasticApmTracer - Tracer switched to RUNNING state

param name isarg0

first result is “param name isnum” but the second result is “param name isarg0”,the expected result is “param name isnum”,how can i fix it?

my runtime environment is jdk8 and apm-agent-attach 1.39.0

jackshirazi commented 1 year ago

I'd guess that it gets lost when the class is transformed. Even if there is a way to maintain it (unlikely) we don't support that. Sorry

barlowHua commented 1 year ago

However, this causes MyBatis to fail sql execution without explicitly specifying the parameter name using @param. The error message is as follows: org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.binding.BindingException: Parameter 'ids' not found. Available parameters are [collection, list]。 @jackshirazi

I321065 commented 1 year ago

@jackshirazi I think it not impact mybatis, but also all frameworks that need to get some information by java reflect mechanism, so I think it is a bug that need to fix

jackshirazi commented 1 year ago

There is no guarantee in Java that a parameter name is retained, if you compile without debugging information it wouldn't be. Any framework that relies on that is buggy. I appreciate this is frustrating for you but we won't be priortising any work on this. Perhaps raising the issue with MyBatis might help?

I321065 commented 1 year ago

@jackshirazi I partially agree with your point, but this issue was introduced starting from version 1.25.0 not exists before, so it would cause regression issues for upgrading users and it is not mentioned in release notes, so I do not think not supporting is reasonable, please reestimate this issue, thanks!!!

jackshirazi commented 1 year ago

I really can't see this as a bug or breaking change in the agent, MyBatis is erroring on a implementation detail that is explicitly not guaranteed to hold in the JVM. Possible workarounds for you (but I don't know it will prevent the error):

I321065 commented 1 year ago

@jackshirazi apm will erase the method real name even though I compile java code with -parameter, this is my concerned; besides mybatis, I also found feign have the same problem, so please reopen this issue and schedule to resolve it;

img_v2_d8be9a17-f378-4c53-bdca-bc5fed2e8a7g

I321065 commented 1 year ago

I think it is hard to upgrade if this issue can not resolve, because I need to care all codes that use this feature @jackshirazi

jackshirazi commented 1 year ago

I've reopened it, but I still don't see this as an agent bug, more a feature request. But whether bug or feature request, this is not prioritized for the current quarter

SylvainJuge commented 10 months ago

I tried to reproduce the issue and did not succeed at it using:

import java.lang.reflect.Method;

public class Main {
    public static void main(String[] args){
        toInstrument(args);
    }

    public static void toInstrument(String[] args){
        test(Main.class);
    }

    public static void test(Class<?> type){
        Method[] methods = type.getDeclaredMethods();
        for (Method method : methods) {
            for (int i = 0; i < method.getParameterCount(); i++) {
                String name = method.getParameters()[i].getName();
                if (name.startsWith("arg0")) {
                    throw new IllegalArgumentException("boom !");
                } else {
                    System.out.println("arg ok: " + name);
                }
            }
        }
    }

}

Without the agent, when compiled with javac Main.java then we get an exception as expected when running it with java Main. Still without the agent, when compiled with javac -parameters Main.java it works as expected.

On the bytecode level when looking at it with javap, the difference is that when the -parameters argument is provided to the compiler the genereted bytecode will include an extra MethodParameters section at the end of each method, here for toInstrument method above with the option:

  public static void toInstrument(java.lang.String[]);
    descriptor: ([Ljava/lang/String;)V
    flags: ACC_PUBLIC, ACC_STATIC
    Code:
      stack=1, locals=1, args_size=1
         0: ldc           #3                  // class Main
         2: invokestatic  #4                  // Method test:(Ljava/lang/Class;)V
         5: return
      LineNumberTable:
        line 9: 0
        line 10: 5
    MethodParameters:
      Name                           Flags
      args

When adding the agent with -javaagent JVM argument and by configuring it with trace_methods=Main#toInstrument, the toInstrument method is instrumented as a transaction, and the method parameter names are preserved.

In order to verify what is happening here, it would be required to investigate the bytecode that is modified by the agent, in order to do that you will have to set bytecode_dump_path option to an empty folder and this will write the classes before and after instrumentation, then they could be compared by using a tool like javap.

How does the agent is setup in your applications here ? is is using -javaagent or does it uses on the runtime attach ? The initial report from @hhhhhxm seemed to indicate that it was using runtime attach.

The part that confuses me the most is that two invocations of the same method might yield different results, which seems to be more a JVM bug when the code is instrumented rather than something that the agent has control over. Here, having the exact JVM version that you are using would also be relevant.

DanielYWoo commented 4 months ago

We had the same problem with JDK 17. The most important core feature, Spring SPEL, which is used in hundreds of our microservices, cannot work because the parameter names are erased. To be honest, I don't think Spring SPEL is a decent design relying on the parameter names, but this is what it is, the world most popular framework. Appreciate if you guys can reconsider whether or not to keep the parameter names.

SylvainJuge commented 4 months ago

Hi @DanielYWoo , this is not something that is in our control as the agent just reads the existing bytecode that was compiled by the Java compiler. If the bytecode does not contain the information, there is nothing we can do to restore it.

In order to investigate further your case I would suggest to inspect the compiled classes with javap to see if the parameter names are preserved in the bytecode or not.

If they aren't, then you need to find the right parameters for the javac compiler to keep them.

DanielYWoo commented 4 months ago

Hi @DanielYWoo , this is not something that is in our control as the agent just reads the existing bytecode that was compiled by the Java compiler. If the bytecode does not contain the information, there is nothing we can do to restore it.

In order to investigate further your case I would suggest to inspect the compiled classes with javap to see if the parameter names are preserved in the bytecode or not.

If they aren't, then you need to find the right parameters for the javac compiler to keep them.

Thanks for the tips but we do have the debug info. Sorry I don't have enough time to further debug this, fortunately the agent allows us to customize the instrument filters, so now we exclude the affected classes here and there to temporarily make it work.

DanielYWoo commented 4 months ago

BTW, we also purchased another commercial APM tool which works without a problem. So I believe this could be a tricky bug in Elastic APM agent. But I just don't have time to take a deep look at this. (I am still working at 1:15 AM Saturday right now)

SylvainJuge commented 4 months ago

Sorry, I completely misunderstood the issue here. I thought that the parameter names were not included in the original bytecode.

However here the problem is that code that gets instrumented apparently looses the parameter names once transformed, which is a bit different.

SylvainJuge commented 4 months ago

You are using "runtime attach" setup method, does the same issue also happens when you are using the -javaagent JVM command-line option ?

That would be interesting (and quite quick) to know here, apparently some older JVMs discard the argument names when re-defining classes, which happens when using runtime attach. When using -javaagent setup method the classes the instrumentation happens before the classes are loaded for the first time, hence this problem might not appear.