Java Agent Auto Instrumentation is not working

[Sergey.Spasskiy]

Hello all, 

I'm trying to utilize Cluster Agent Auto Instrumentations for java application in k8s cluster. the agent seems to be copied and started on app pods but doesn't report any metrics - I've checked agent's logs folders and there is no folder named for node-name and no files there as well. It seems like the issue can be in permission but why would Java agent reports to be started successfully. Can you please advice how to troubleshoot the issue? Here are logs from app pod and from cluster agent pod:

Cluster Agent pod:

[DEBUG]: 2022-09-21 22:10:46 - podhandler.go:230 - Handling pod update test/api-server-6c998f544b-6czbx
[ERROR]: 2022-09-21 22:10:47 - executor.go:73 - Command basename `find /opt/appdynamics-java/ver21.7.0.32930/logs/ -maxdepth 1 -type d -name '*api-server*'` returned an error when exec on pod api-server-6c998f544b-rz8vr. command terminated with exit code 1
[WARNING]: 2022-09-21 22:10:47 - executor.go:75 - Exit status of command 'basename `find /opt/appdynamics-java/ver21.7.0.32930/logs/ -maxdepth 1 -type d -name '*api-server*'`' in container api-server in pod test/api-server-6c998f544b-rz8vr is 1
[DEBUG]: 2022-09-21 22:10:47 - javaappmetadatahelper.go:53 - Node folder name in container: api-server, pod: test/api-server-6c998f544b-rz8vr: 
[ERROR]: 2022-09-21 22:10:47 - javaappmetadatahelper.go:55 - Failed to find node name command terminated with exit code 1
[WARNING]: 2022-09-21 22:10:47 - podhandler.go:149 - Unable to find node name in pod test/api-server-6c998f544b-rz8vr, container api-server
[DEBUG]: 2022-09-21 22:10:47 - podhandler.go:75 - Pod test/api-server-6c998f544b-rz8vr is in Pending state with annotations to be updated map[]
[DEBUG]: 2022-09-21 22:10:47 - podhandler.go:87 - No annotations to update for pod test/api-server-6c998f544b-rz8vr 

App Pod:

Picked up JAVA_TOOL_OPTIONS:  -Dappdynamics.agent.accountAccessKey= -Dappdynamics.agent.reuse.nodeName=true -Dappdynamics.socket.collection.bci.enable=true -javaagent:/opt/appdynamics-java/javaagent.jar
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_APPLICATION_NAME] for application name [PreProd-EU]
Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_TIER_NAME] for tier name [api-server]
Full Agent Registration Info Resolver using selfService [false]
Full Agent Registration Info Resolver using selfService [false]
Full Agent Registration Info Resolver using ephemeral node setting [false]
Full Agent Registration Info Resolver using application name [PreProd-EU]
Read property [reuse node name] from system property [appdynamics.agent.reuse.nodeName]
Full Agent Registration Info Resolver using tier name [api-server]
Full Agent Registration Info Resolver using node name [null]
Install Directory resolved to[/opt/appdynamics-java]
[AD Agent init] Tue Sep 20 22:49:40 UTC 2022[INFO]: JavaAgent - Low Entropy Mode: Attempting to swap to non-blocking PRNG algorithm
[AD Agent init] Tue Sep 20 22:49:40 UTC 2022[INFO]: JavaAgent - UUIDPool size is 10
Agent conf directory set to [/opt/appdynamics-java/ver21.7.0.32930/conf]
[AD Agent init] Tue Sep 20 22:49:40 UTC 2022[INFO]: JavaAgent - Agent conf directory set to [/opt/appdynamics-java/ver21.7.0.32930/conf]
[AD Agent init] Tue Sep 20 22:49:40 UTC 2022[DEBUG]: AgentInstallManager - Full Agent Registration Info Resolver is running
[AD Agent init] Tue Sep 20 22:49:40 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_APPLICATION_NAME] for application name [PreProd-EU]
[AD Agent init] Tue Sep 20 22:49:40 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver found env variable [APPDYNAMICS_AGENT_TIER_NAME] for tier name [api-server]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using selfService [false]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using selfService [false]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using ephemeral node setting [false]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using application name [PreProd-EU]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: AgentInstallManager - Read property [reuse node name] from system property [appdynamics.agent.reuse.nodeName]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using tier name [api-server]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: AgentInstallManager - Full Agent Registration Info Resolver using node name [null]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[DEBUG]: AgentInstallManager - Full Agent Registration Info Resolver finished running
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: AgentInstallManager - Agent runtime directory set to [/opt/appdynamics-java/ver21.7.0.32930]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: AgentInstallManager - Agent node directory set to [api-server-6c998f544b-mvx7s]
Agent runtime conf directory set to /opt/appdynamics-java/ver21.7.0.32930/conf
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: AgentInstallManager - Agent runtime conf directory set to /opt/appdynamics-java/ver21.7.0.32930/conf
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - JDK Compatibility: 1.8+
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - Using Java Agent Version [Server Agent #21.7.0.32930 v21.7.0 GA compatible with 4.4.1.0 rc6a2713daa53e64a5abed3707e82fd87c36b5e49 release/21.7.0]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - Running IBM Java Agent [No]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - Java Agent Directory [/opt/appdynamics-java/ver21.7.0.32930]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - Java Agent AppAgent directory [/opt/appdynamics-java/ver21.7.0.32930]
Agent logging directory set to [/opt/appdynamics-java/ver21.7.0.32930/logs]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - Agent logging directory set to [/opt/appdynamics-java/ver21.7.0.32930/logs]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - Logging set up for log4j2
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - ####################################################################################
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - Java Agent Directory [/opt/appdynamics-java/ver21.7.0.32930]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - Java Agent AppAgent directory [/opt/appdynamics-java/ver21.7.0.32930]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - Using Java Agent Version [Server Agent #21.7.0.32930 v21.7.0 GA compatible with 4.4.1.0 rc6a2713daa53e64a5abed3707e82fd87c36b5e49 release/21.7.0]
[AD Agent init] Tue Sep 20 22:49:41 UTC 2022[INFO]: JavaAgent - All agent classes have been pre-loaded
Agent will mark node historical at normal shutdown of JVM
Started AppDynamics Java Agent Successfully.
[AD Agent init] Tue Sep 20 22:50:14 UTC 2022[INFO]: JavaAgent - Started AppDynamics Java Agent Successfully.
2022-09-20 22:50:16,300 ~main ERROR Recursive call to appender Buffer
2022-09-20 22:50:16,302 ~main ERROR Recursive call to appender Buffer
WARN  [2022-09-20 22:50:27,572] com.netflix.config.sources.URLConfigurationSource: No URLs will be polled as dynamic configuration sources. 

[Dolamani.Pradhan]

Is anyone having any solutions for this.

[Sunil.Agarwal]

Hi @Dolamani.Pradhan ,

[ERROR]: 2022-09-21 22:10:47 - javaappmetadatahelper.go:55 - Failed to find node name command terminated with exit code 1

If there is no {nodename}-{uniqueid} folder created in opt/appdynamics-java/, then this issue occurs.

You can run below command :           kubectl describe pod <deployment pod> -n <namespace>
-  Without reviewing the output, it is difficult to determine what could be the problem. However, you can review the "APPD_POD_INSTRUMENTATION_STATE" status (Successful, Failed, Pending) and look for any errors or clues there.

Also,  verify that config file is correct.

You can run below steps to enable DEBIG log so find any additional ERROR messages. 
1: Stop cluster agent: kubectl delete -f cluster-agent.yaml
2: Edit the yaml file as below to set the logLevel to DEBUG as shown below and save it.
3: Start cluster agent: kubectl create -f cluster-agent.yaml
4: Let cluster agent run for 15 minutes
5: Collect logs by executing kubectl logs <cluster-agent-pod> -n appdynamics > cluster-agent.log
spec:
logLevel: "DEBUG"
logFileSizeMb: 20
logFileBackups: 5
https://docs.appdynamics.com/21.9/en/infrastructure-visibility/monitor-kubernetes-with-the-cluster-a...

Here are steps to follow install cluster agent:  https://docs.appdynamics.com/appd/22.x/22.3/en/infrastructure-visibility/monitor-kubernetes-with-the... 

[Marcie.Sirbaugh]

Was there ever a resolution to this error, I am seeing that the directory "unknown" is being created, not the actual microservice name.  Seems like a permissions issue, anyone thoughts?

[Ryan.Paredez]

Hi @Marcie.Sirbaugh, 

Did you read @Sunil.Agarwal reply above? Did that offer any insight into next steps you can take to troubleshoot?

[Marcie.Sirbaugh]

Yes, I read the reply above and concur that this error occurs when the proper directory is not created and in our case it was "unknown" instead of the actual service name, ultimately we upgraded from jdk 11 to jdk 21 and like magic it started working, so imagine this was a bug in jdk 11.

[Ryan.Paredez]

Hi @Marcie.Sirbaugh,

Thanks for sharing that additional info and I'm glad upgrading helped solve the issue for you.