[ARTEMIS-5073] Formatting error of AMQ601771 audit log event

• Type: Bug
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 2.36.0, 2.37.0
• Fix Version/s: 2.38.0
• Assignee: Justin Bertram
• Reporter: Aleksandr Milovidov
• Created: 27/Sep/24 12:27
• Updated: 16/Oct/24 16:02
• Resolved: 01/Oct/24 18:15

Description

When audit logging is enabled and the Prometheus JMX exporter is used as a Java agent, some errors are written to stdout. It happens when the exporter collects metrics. Username in this case may be null or anonymous.
Reproducible in versions 2.36.0 and 2.37.0.

Steps to reproduce:

1. Create Artemis instance. 
2. Enable base audit logging in log4j2.properties: 

   logger.audit_base.level = INFO

3. Add JMX exporter as Java agent: add following arguments to the JAVA_ARGS variable in the artemis.profile (change paths according to the environment):

   -javaagent:/path/to/jmx_prometheus_javaagent.jar=9404:/path/to/jmx_exporter_config.yml

   Example jmx_exporter_config.yml: 

   lowercaseOutputName: true
   lowercaseOutputLabelNames: true
   rules: 
     - pattern: "^org.apache.activemq.artemis<broker=\"([^\"]*)\"><>([^:]*):\\s(.*)"
       attrNameSnakeCase: true
       name: artemis_$2
       type: GAUGE

   JMX Exporter can be downloaded here.

4. Start Artemis and access http://your-server-name:9404/metrics/ using a browser or curl command-line utility.

Event is logged to stdout of Artemis process:

2024-09-27T11:39:06.041494200Z prometheus-http-1-1 ERROR Unable to format msg: AMQ601771: User {} is getting name on target resource: {} java.lang.IllegalArgumentException: found 2 argument placeholders, but provided 1 for pattern `AMQ601771: User {} is getting name on target resource: {}`
        at org.apache.logging.log4j.message.ParameterFormatter.formatMessage(ParameterFormatter.java:248)
        at org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMessage.java:282)
        at org.apache.logging.log4j.core.pattern.MessagePatternConverter$SimpleMessagePatternConverter.format(MessagePatternConverter.java:120)
        at org.apache.logging.log4j.core.layout.PatternLayout$NoFormatPatternSerializer.toSerializable(PatternLayout.java:355)
        at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:252)
        at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:238)
        at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:58)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:227)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:220)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:211)
        at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:337)
        at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:160)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:133)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:124)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:88)
        at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:705)
        at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:663)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:639)
        at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:575)
        at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:92)
        at org.apache.logging.log4j.core.Logger.log(Logger.java:169)
        at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2906)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2859)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2841)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2637)
        at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2402)
        at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:178)
        at org.apache.activemq.artemis.logs.AuditLogger_impl.getCurrentTimeMillis(AuditLogger_impl.java:2875)
        at org.apache.activemq.artemis.logs.AuditLogger.getCurrentTimeMillis(AuditLogger.java:2672)
        at org.apache.activemq.artemis.core.management.impl.ActiveMQServerControlImpl.getCurrentTimeMillis(ActiveMQServerControlImpl.java:233)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at sun.reflect.misc.Trampoline.invoke(MethodUtil.java:72)
        at jdk.internal.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at java.base/sun.reflect.misc.MethodUtil.invoke(MethodUtil.java:262)
        at java.management/com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:112)
        at java.management/com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:46)
        at java.management/com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:237)
        at java.management/com.sun.jmx.mbeanserver.PerInterface.getAttribute(PerInterface.java:83)
        at java.management/com.sun.jmx.mbeanserver.MBeanSupport.getAttribute(MBeanSupport.java:206)
        at java.management/com.sun.jmx.mbeanserver.MBeanSupport.getAttributes(MBeanSupport.java:213)
        at java.management/javax.management.StandardMBean.getAttributes(StandardMBean.java:390)
        at java.management/com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getAttributes(DefaultMBeanServerInterceptor.java:705)
        at java.management/com.sun.jmx.mbeanserver.JmxMBeanServer.getAttributes(JmxMBeanServer.java:706)
        at io.prometheus.jmx.JmxScraper.scrapeBean(JmxScraper.java:200)
        at io.prometheus.jmx.JmxScraper.doScrape(JmxScraper.java:152)
        at io.prometheus.jmx.JmxCollector.collect(JmxCollector.java:739)
        at io.prometheus.metrics.model.registry.MultiCollector.collect(MultiCollector.java:26)
        at io.prometheus.metrics.model.registry.PrometheusRegistry.scrape(PrometheusRegistry.java:72)
        at io.prometheus.metrics.exporter.common.PrometheusScrapeHandler.scrape(PrometheusScrapeHandler.java:112)
        at io.prometheus.metrics.exporter.common.PrometheusScrapeHandler.handleRequest(PrometheusScrapeHandler.java:53)
        at io.prometheus.metrics.exporter.httpserver.MetricsHandler.handle(MetricsHandler.java:43)
        at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:95)
        at jdk.httpserver/sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:82)
        at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:98)
        at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:851)
        at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:95)
        at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:818)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:833)

Issue Links

• links to: GitHub Pull Request #5266