Slf4j error not captured

nugusbayevkk · January 29, 2020, 11:09am

If you are asking about a problem you are experiencing, please use the following template, as it will help us help you. If you have a different problem, please delete all of this text

Kibana version: 7.5.1

Elasticsearch version: 7.5.1

APM Server version: 7.5.1

APM Agent language and version: java, 1.12.1

Browser version: chromium Version 79.0.3945.130 (Official Build) snap (64-bit)

Original install method (e.g. download page, yum, deb, from source, etc.) and version: source, 1.12.1

Fresh install or upgraded from other version?

Is there anything special in your setup? For example, are you using the Logstash or Kafka outputs? Are you using a load balancer in front of the APM Servers? Have you changed index pattern, generated custom templates, changed agent configuration etc.

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
slf4j error logging instrumentation doesn't work.

Steps to reproduce:

run application slf4j-plugin-spring-boot-test
send GET request to http://localhost:8080/log-error
error not captured.

Errors in browser console (if relevant):

Provide logs and/or server output (if relevant):

gist.github.com

https://gist.github.com/kananindzya/5d91b5c1971c4be46f2861cd223ceddd

gistfile1.txt

/opt/nindzya/jdk-10.0.2/bin/java -javaagent:/home/nindzya/Documents/PROJECTS/apm-agent-java/elastic-apm-agent/target/elastic-apm-agent-1.12.1-SNAPSHOT.jar -XX:TieredStopAtLevel=1 -noverify -Dspring.output.ansi.enabled=always -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=33645 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Djava.rmi.server.hostname=localhost -Dspring.liveBeansView.mbeanDomain -Dspring.application.admin.enabled=true -javaagent:/home/nindzya/idea-IU-182.3684.101/lib/idea_rt.jar=38777:/home/nindzya/idea-IU-182.3684.101/bin -Dfile.encoding=UTF-8 -classpath /home/nindzya/Documents/PROJECTS/apm-exampleuse/slf4j-plugin-spring-boot-test/target/classes:/home/nindzya/.m2/repository/org/springframework/boot/spring-boot-starter-web/2.0.2.RELEASE/spring-boot-starter-web-2.0.2.RELEASE.jar:/home/nindzya/.m2/repository/org/springframework/boot/spring-boot-starter/2.0.2.RELEASE/spring-boot-starter-2.0.2.RELEASE.jar:/home/nindzya/.m2/repository/org/springframework/boot/spring-boot/2.0.2.RELEASE/spring-boot-2.0.2.RELEASE.jar:/home/nindzya/.m2/repository/org/springframework/boot/spring-boot-autoconfigure/2.0.2.RELEASE/spring-boot-autoconfigure-2.0.2.RELEASE.jar:/home/nindzya/.m2/repository/org/springframework/boot/spring-boot-starter-logging/2.0.2.RELEASE/spring-boot-starter-logging-2.0.2.RELEASE.jar:/home/nindzya/.m2/repository/ch/qos/logback/logback-classic/1.2.3/logback-classic-1.2.3.jar:/home/nindzya/.m2/repository/ch/qos/logback/logback-core/1.2.3/logback-core-1.2.3.jar:/home/nindzya/.m2/repository/org/slf4j/slf4j-api/1.7.25/slf4j-api-1.7.25.jar:/home/nindzya/.m2/repository/org/apache/logging/log4j/log4j-to-slf4j/2.10.0/log4j-to-slf4j-2.10.0.jar:/home/nindzya/.m2/repository/org/apache/logging/log4j/log4j-api/2.10.0/log4j-api-2.10.0.jar:/home/nindzya/.m2/repository/org/slf4j/jul-to-slf4j/1.7.25/jul-to-slf4j-1.7.25.jar:/home/nindzya/.m2/repository/javax/annotation/javax.annotation-api/1.3.2/javax.annotation-api-1.3.2.jar:/home/nindzya/.m2/repository/org/springframework/spring-core/5.0.6.RELEASE/spring-core-5.0.6.RELEASE.jar:/home/nindzya/.m2/repository/org/springframework/spring-jcl/5.0.6.RELEASE/spring-jcl-5.0.6.RELEASE.jar:/home/nindzya/.m2/repository/org/yaml/snakeyaml/1.19/snakeyaml-1.19.jar:/home/nindzya/.m2/repository/org/springframework/boot/spring-boot-starter-json/2.0.2.RELEASE/spring-boot-starter-json-2.0.2.RELEASE.jar:/home/nindzya/.m2/repository/com/fasterxml/jackson/core/jackson-databind/2.9.5/jackson-databind-2.9.5.jar:/home/nindzya/.m2/repository/com/fasterxml/jackson/core/jackson-annotations/2.9.0/jackson-annotations-2.9.0.jar:/home/nindzya/.m2/repository/com/fasterxml/jackson/core/jackson-core/2.9.5/jackson-core-2.9.5.jar:/home/nindzya/.m2/repository/com/fasterxml/jackson/datatype/jackson-datatype-jdk8/2.9.5/jackson-datatype-jdk8-2.9.5.jar:/home/nindzya/.m2/repository/com/fasterxml/jackson/datatype/jackson-datatype-jsr310/2.9.5/jackson-datatype-jsr310-2.9.5.jar:/home/nindzya/.m2/repository/com/fasterxml/jackson/module/jackson-module-parameter-names/2.9.5/jackson-module-parameter-names-2.9.5.jar:/home/nindzya/.m2/repository/org/springframework/boot/spring-boot-starter-tomcat/2.0.2.RELEASE/spring-boot-starter-tomcat-2.0.2.RELEASE.jar:/home/nindzya/.m2/repository/org/apache/tomcat/embed/tomcat-embed-core/8.5.31/tomcat-embed-core-8.5.31.jar:/home/nindzya/.m2/repository/org/apache/tomcat/embed/tomcat-embed-el/8.5.31/tomcat-embed-el-8.5.31.jar:/home/nindzya/.m2/repository/org/apache/tomcat/embed/tomcat-embed-websocket/8.5.31/tomcat-embed-websocket-8.5.31.jar:/home/nindzya/.m2/repository/org/hibernate/validator/hibernate-validator/6.0.9.Final/hibernate-validator-6.0.9.Final.jar:/home/nindzya/.m2/repository/javax/validation/validation-api/2.0.1.Final/validation-api-2.0.1.Final.jar:/home/nindzya/.m2/repository/org/jboss/logging/jboss-logging/3.3.2.Final/jboss-logging-3.3.2.Final.jar:/home/nindzya/.m2/repository/com/fasterxml/classmate/1.3.4/classmate-1.3.4.jar:/home/nindzya/.m2/repository/org/springframework/spring-web/5.0.6.RELEASE/spring-web-5.0.6.RELEASE.jar:/home/nindzya/.m2/repository/org/springframework/spring-beans/5.0.6.RELEASE/spring-beans-5.0.6.RELEASE.jar:/home/nindzya/.m2/repository/org/springframework/spring-webmvc/5.0.6.RELEASE/spring-webmvc-5.0.6.RELEASE.jar:/home/nindzya/.m2/repository/org/springframework/spring-aop/5.0.6.RELEASE/spring-aop-5.0.6.RELEASE.jar:/home/nindzya/.m2/repository/org/springframework/spring-context/5.0.6.RELEASE/spring-context-5.0.6.RELEASE.jar:/home/nindzya/.m2/repository/org/springframework/spring-expression/5.0.6.RELEASE/spring-expression-5.0.6.RELEASE.jar com.kananindzya.apm.java.slf4j.Slf4jErrorCaptureApplication
2020-01-29 16:39:43.743 [elastic-apm-server-healthcheck] DEBUG co.elastic.apm.agent.report.ApmServerHealthChecker - Starting healthcheck to http://localhost:8200/
2020-01-29 16:39:43.753 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 12:blkio:/user.slice
2020-01-29 16:39:43.754 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 11:cpu,cpuacct:/user.slice
2020-01-29 16:39:43.754 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 10:rdma:/
2020-01-29 16:39:43.754 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 9:perf_event:/
2020-01-29 16:39:43.754 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 8:hugetlb:/
2020-01-29 16:39:43.754 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 7:devices:/user.slice
2020-01-29 16:39:43.755 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 6:net_cls,net_prio:/
2020-01-29 16:39:43.755 [main] DEBUG co.elastic.apm.agent.impl.payload.SystemInfo - Could not parse container ID from '/proc/self/cgroup' line: 5:pids:/user.slice/user-1002.slice/user@1002.service

This file has been truncated. show original

[INFO] Building slf4j-plugin-spring-boot-test 2.0.2.RELEASE
[INFO] --------------------------------[ jar ]---------------------------------
[INFO] 
[INFO] --- maven-dependency-plugin:3.0.2:tree (default-cli) @ slf4j-plugin-spring-boot-test ---
[INFO] org.springframework.boot:slf4j-plugin-spring-boot-test:jar:2.0.2.RELEASE
[INFO] \- org.springframework.boot:spring-boot-starter-web:jar:2.0.2.RELEASE:compile
[INFO]    +- org.springframework.boot:spring-boot-starter:jar:2.0.2.RELEASE:compile
[INFO]    |  +- org.springframework.boot:spring-boot:jar:2.0.2.RELEASE:compile
[INFO]    |  +- org.springframework.boot:spring-boot-autoconfigure:jar:2.0.2.RELEASE:compile
[INFO]    |  +- org.springframework.boot:spring-boot-starter-logging:jar:2.0.2.RELEASE:compile
[INFO]    |  |  +- ch.qos.logback:logback-classic:jar:1.2.3:compile
[INFO]    |  |  |  +- ch.qos.logback:logback-core:jar:1.2.3:compile
[INFO]    |  |  |  \- org.slf4j:slf4j-api:jar:1.7.25:compile
[INFO]    |  |  +- org.apache.logging.log4j:log4j-to-slf4j:jar:2.10.0:compile
[INFO]    |  |  |  \- org.apache.logging.log4j:log4j-api:jar:2.10.0:compile
[INFO]    |  |  \- org.slf4j:jul-to-slf4j:jar:1.7.25:compile
[INFO]    |  +- javax.annotation:javax.annotation-api:jar:1.3.2:compile
[INFO]    |  +- org.springframework:spring-core:jar:5.0.6.RELEASE:compile
[INFO]    |  |  \- org.springframework:spring-jcl:jar:5.0.6.RELEASE:compile
[INFO]    |  \- org.yaml:snakeyaml:jar:1.19:runtime
[INFO]    +- org.springframework.boot:spring-boot-starter-json:jar:2.0.2.RELEASE:compile
[INFO]    |  +- com.fasterxml.jackson.core:jackson-databind:jar:2.9.5:compile
[INFO]    |  |  +- com.fasterxml.jackson.core:jackson-annotations:jar:2.9.0:compile
[INFO]    |  |  \- com.fasterxml.jackson.core:jackson-core:jar:2.9.5:compile
[INFO]    |  +- com.fasterxml.jackson.datatype:jackson-datatype-jdk8:jar:2.9.5:compile
[INFO]    |  +- com.fasterxml.jackson.datatype:jackson-datatype-jsr310:jar:2.9.5:compile
[INFO]    |  \- com.fasterxml.jackson.module:jackson-module-parameter-names:jar:2.9.5:compile
[INFO]    +- org.springframework.boot:spring-boot-starter-tomcat:jar:2.0.2.RELEASE:compile
[INFO]    |  +- org.apache.tomcat.embed:tomcat-embed-core:jar:8.5.31:compile
[INFO]    |  +- org.apache.tomcat.embed:tomcat-embed-el:jar:8.5.31:compile
[INFO]    |  \- org.apache.tomcat.embed:tomcat-embed-websocket:jar:8.5.31:compile
[INFO]    +- org.hibernate.validator:hibernate-validator:jar:6.0.9.Final:compile
[INFO]    |  +- javax.validation:validation-api:jar:2.0.1.Final:compile
[INFO]    |  +- org.jboss.logging:jboss-logging:jar:3.3.2.Final:compile
[INFO]    |  \- com.fasterxml:classmate:jar:1.3.4:compile
[INFO]    +- org.springframework:spring-web:jar:5.0.6.RELEASE:compile
[INFO]    |  \- org.springframework:spring-beans:jar:5.0.6.RELEASE:compile
[INFO]    \- org.springframework:spring-webmvc:jar:5.0.6.RELEASE:compile
[INFO]       +- org.springframework:spring-aop:jar:5.0.6.RELEASE:compile
[INFO]       +- org.springframework:spring-context:jar:5.0.6.RELEASE:compile
[INFO]       \- org.springframework:spring-expression:jar:5.0.6.RELEASE:compile

felixbarny · January 29, 2020, 12:12pm

Could you tell me what's the value of logger.getClass().getName()?

github.com

kananindzya/apm-example-use/blob/d7d5162b6f1a4e8155f84603a721bf836fe0d602/slf4j-plugin-spring-boot-test/src/main/java/com/kananindzya/apm/java/slf4j/Slf4jErrorCaptureApplication.java#L22


public class Slf4jErrorCaptureApplication {


    private static final Logger logger = LoggerFactory.getLogger(Slf4jErrorCaptureApplication.class);


    public static void main(String[] args) {
        SpringApplication.run(Slf4jErrorCaptureApplication.class, args);
    }


    @GetMapping("/log-error")
    public String logError() {
        logger.error("test log error", new RuntimeException("some exception"));
        return "logged";
    }
}

nugusbayevkk · January 29, 2020, 12:15pm

ch.qos.logback.classic.Logger

nugusbayevkk · January 29, 2020, 4:03pm

After adding a new condition to Slf4jLoggingInstrumentation#getTypeMatcher:

.or(named("ch.qos.logback.classic.Logger"));

It works fine.
But why is hasSuperType method not instrumented ch.qos.logback.classic.Logger?

felixbarny · February 18, 2020, 9:10am

Have you found out what the problem is? I'm also puzzled why the existing matcher

github.com

elastic/apm-agent-java/blob/9528d35842985671e90f20e9699ad27cc21a8f30/apm-agent-plugins/apm-error-logging-plugin/src/main/java/co/elastic/apm/agent/error/logging/Slf4jLoggingInstrumentation.java#L39-L41


public ElementMatcher<? super TypeDescription> getTypeMatcher() {
    return hasSuperType(named("org.slf4j.Logger")).and(not(hasSuperType(named("org.apache.logging.log4j.Logger"))));
}

Does not match ch.qos.logback.classic.Logger, as it does implement org.slf4j.Logger:

github.com

qos-ch/logback/blob/7ee74ad132bf74ead68c5bb553f5353aa2588bb0/logback-classic/src/main/java/ch/qos/logback/classic/Logger.java#L38-L39


public final class Logger implements org.slf4j.Logger, LocationAwareLogger, AppenderAttachable<ILoggingEvent>, Serializable {

nugusbayevkk · February 24, 2020, 4:25am

wow , I found solution. I sent PR.

Sylvain_Juge · February 26, 2020, 3:55pm

You are amazing @nugusbayevkk ! I've just reviewed it and it will likely be merged in a future release (1.14.0 or the following).

system · March 18, 2020, 12:00pm

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.