From 464525670386a2963b677dfe71750c75c6783967 Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Fri, 1 Sep 2023 15:40:32 -0700 Subject: [PATCH 01/21] Prototype two potential approaches to support adding linking metadata to Log4j2 JsonLayout --- ...AbstractJacksonLayout_Instrumentation.java | 45 +++++++++++++++++++ .../AbstractStringLayout_Instrumentation.java | 44 ++++++++++++++++++ 2 files changed, 89 insertions(+) create mode 100644 instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java create mode 100644 instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java new file mode 100644 index 0000000000..409f3a9ac5 --- /dev/null +++ b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java @@ -0,0 +1,45 @@ +/* + * + * * Copyright 2023 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package org.apache.logging.log4j.core.layout; + +import com.newrelic.api.agent.weaver.MatchType; +import com.newrelic.api.agent.weaver.Weave; +import com.newrelic.api.agent.weaver.Weaver; + +import java.util.Map; + +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingEnabled; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingLocalDecoratingEnabled; + +abstract class AbstractJacksonLayout_Instrumentation { + + @Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractJacksonLayout$LogEventWithAdditionalFields", type = MatchType.ExactClass) + public static class LogEventWithAdditionalFields_Instrumentation { + + private final Object logEvent; + private final Map additionalFields; + + public LogEventWithAdditionalFields_Instrumentation(final Object logEvent, final Map additionalFields) { + // This will only ever work if at least one additional field is set in the JsonLayout, doesn't matter what it is + // + // + // + + this.logEvent = Weaver.callOriginal(); + if (isApplicationLoggingEnabled()) { + if (isApplicationLoggingLocalDecoratingEnabled()) { + // Append New Relic linking metadata from agent to log message + additionalFields.put("In NR", getLinkingMetadataBlob()); + } + } + this.additionalFields = Weaver.callOriginal(); + } + } + +} diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java new file mode 100644 index 0000000000..9d57018e47 --- /dev/null +++ b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java @@ -0,0 +1,44 @@ +/* + * + * * Copyright 2023 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package org.apache.logging.log4j.core.layout; + +import com.newrelic.api.agent.weaver.MatchType; +import com.newrelic.api.agent.weaver.Weave; +import com.newrelic.api.agent.weaver.Weaver; +import org.apache.logging.log4j.core.util.StringEncoder; + +import java.io.UnsupportedEncodingException; +import java.nio.charset.Charset; + +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; + +@Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractStringLayout", type = MatchType.ExactClass) +public abstract class AbstractStringLayout_Instrumentation { + + private transient Charset charset = Weaver.callOriginal(); + private final String charsetName = Weaver.callOriginal(); + private final boolean useCustomEncoding = Weaver.callOriginal(); + + protected byte[] getBytes(final String s) { + String modified = s; + if (!s.contains("NR-LINKING")) { + int indexToInsertNrLinkingMetadata = s.indexOf("\n", s.indexOf("message")) - 1; + // Replace the JSON string with modified version + modified = new StringBuilder(s).insert(indexToInsertNrLinkingMetadata, getLinkingMetadataBlob()).toString(); + } + if (useCustomEncoding) { + return StringEncoder.encodeSingleByteChars(modified); + } + try { + return modified.getBytes(charsetName); + } catch (final UnsupportedEncodingException e) { + return modified.getBytes(charset); + } + } + +} From f129da057db4cace07ee4ef4bcae526236e64488 Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Tue, 5 Sep 2023 11:19:23 -0700 Subject: [PATCH 02/21] Remove AbstractJacksonLayout instrumentation. Split instrumentation into two modules to support log4j 2.6-2.14 and 2.15+ --- .../apache-log4j-2.15/build.gradle | 18 + .../instrumentation/log4j2/AgentUtil.java | 131 ++++ .../instrumentation/log4j2/ExceptionUtil.java | 49 ++ .../config/LoggerConfig_Instrumentation.java | 66 ++ .../AbstractStringLayout_Instrumentation.java | 33 + .../StringBuilderEncoder_Instrumentation.java | 40 ++ .../log4j2/ContextDataTest.java | 64 ++ .../log4j2/ExceptionUtilTest.java | 61 ++ .../LoggerConfig_InstrumentationTest.java | 622 ++++++++++++++++++ ...plication_logging_context_data_enabled.yml | 12 + .../resources/application_logging_enabled.yml | 10 + instrumentation/apache-log4j-2/build.gradle | 4 +- ...AbstractJacksonLayout_Instrumentation.java | 45 -- settings.gradle | 1 + 14 files changed, 1109 insertions(+), 47 deletions(-) create mode 100644 instrumentation/apache-log4j-2.15/build.gradle create mode 100644 instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java create mode 100644 instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java create mode 100644 instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java create mode 100644 instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java create mode 100644 instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java create mode 100644 instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java create mode 100644 instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java create mode 100644 instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java create mode 100644 instrumentation/apache-log4j-2.15/src/test/resources/application_logging_context_data_enabled.yml create mode 100644 instrumentation/apache-log4j-2.15/src/test/resources/application_logging_enabled.yml delete mode 100644 instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java diff --git a/instrumentation/apache-log4j-2.15/build.gradle b/instrumentation/apache-log4j-2.15/build.gradle new file mode 100644 index 0000000000..109a0ea164 --- /dev/null +++ b/instrumentation/apache-log4j-2.15/build.gradle @@ -0,0 +1,18 @@ +jar { + manifest { attributes 'Implementation-Title': 'com.newrelic.instrumentation.apache-log4j-2.15' } +} + +dependencies { + implementation(project(":agent-bridge")) + implementation("org.apache.logging.log4j:log4j-core:2.20.0") +} + +verifyInstrumentation { + passesOnly("org.apache.logging.log4j:log4j-core:[2.15.0,)") + excludeRegex '.*(alpha|beta|rc).*' +} + +site { + title 'Log4j2' + type 'Framework' +} diff --git a/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java b/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java new file mode 100644 index 0000000000..05ac051504 --- /dev/null +++ b/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java @@ -0,0 +1,131 @@ +/* + * + * * Copyright 2022 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package com.nr.agent.instrumentation.log4j2; + +import com.newrelic.agent.bridge.AgentBridge; +import com.newrelic.agent.bridge.logging.AppLoggingUtils; +import com.newrelic.agent.bridge.logging.LogAttributeKey; +import com.newrelic.agent.bridge.logging.LogAttributeType; +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.message.Message; +import org.apache.logging.log4j.util.ReadOnlyStringMap; + +import java.util.HashMap; +import java.util.Map; + +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.DEFAULT_NUM_OF_LOG_EVENT_ATTRIBUTES; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.ERROR_CLASS; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.ERROR_MESSAGE; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.ERROR_STACK; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.INSTRUMENTATION; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.LEVEL; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.LOGGER_FQCN; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.LOGGER_NAME; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.MESSAGE; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.THREAD_ID; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.THREAD_NAME; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.TIMESTAMP; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.UNKNOWN; + +public class AgentUtil { + /** + * Record a LogEvent to be sent to New Relic. + * + * @param event to parse + */ + public static void recordNewRelicLogEvent(LogEvent event) { + if (event != null) { + Message message = event.getMessage(); + Throwable throwable = event.getThrown(); + + if (shouldCreateLogEvent(message, throwable)) { + ReadOnlyStringMap contextData = event.getContextData(); + Map logEventMap = new HashMap<>(calculateInitialMapSize(contextData)); + logEventMap.put(INSTRUMENTATION, "apache-log4j-2.15"); + if (message != null) { + String formattedMessage = message.getFormattedMessage(); + if (formattedMessage != null && !formattedMessage.isEmpty()) { + logEventMap.put(MESSAGE, formattedMessage); + } + } + logEventMap.put(TIMESTAMP, event.getTimeMillis()); + + if (AppLoggingUtils.isAppLoggingContextDataEnabled() && contextData != null) { + for (Map.Entry entry : contextData.toMap().entrySet()) { + String key = entry.getKey(); + String value = entry.getValue(); + LogAttributeKey logAttrKey = new LogAttributeKey(key, LogAttributeType.CONTEXT); + logEventMap.put(logAttrKey, value); + } + } + + Level level = event.getLevel(); + if (level != null) { + String levelName = level.name(); + if (levelName.isEmpty()) { + logEventMap.put(LEVEL, UNKNOWN); + } else { + logEventMap.put(LEVEL, levelName); + } + } + + String errorStack = ExceptionUtil.getErrorStack(throwable); + if (errorStack != null) { + logEventMap.put(ERROR_STACK, errorStack); + } + + String errorMessage = ExceptionUtil.getErrorMessage(throwable); + if (errorMessage != null) { + logEventMap.put(ERROR_MESSAGE, errorMessage); + } + + String errorClass = ExceptionUtil.getErrorClass(throwable); + if (errorClass != null) { + logEventMap.put(ERROR_CLASS, errorClass); + } + + String threadName = event.getThreadName(); + if (threadName != null) { + logEventMap.put(THREAD_NAME, threadName); + } + + logEventMap.put(THREAD_ID, event.getThreadId()); + + String loggerName = event.getLoggerName(); + if (loggerName != null) { + logEventMap.put(LOGGER_NAME, loggerName); + } + + String loggerFqcn = event.getLoggerFqcn(); + if (loggerFqcn != null) { + logEventMap.put(LOGGER_FQCN, loggerFqcn); + } + + AgentBridge.getAgent().getLogSender().recordLogEvent(logEventMap); + } + } + } + + /** + * A LogEvent MUST NOT be reported if neither a log message nor an error is logged. If either is present report the LogEvent. + * + * @param message Message to validate + * @param throwable Throwable to validate + * @return true if a LogEvent should be created, otherwise false + */ + private static boolean shouldCreateLogEvent(Message message, Throwable throwable) { + return (message != null) || !ExceptionUtil.isThrowableNull(throwable); + } + + private static int calculateInitialMapSize(ReadOnlyStringMap mdcPropertyMap) { + return AppLoggingUtils.isAppLoggingContextDataEnabled() && mdcPropertyMap != null + ? mdcPropertyMap.size() + DEFAULT_NUM_OF_LOG_EVENT_ATTRIBUTES + : DEFAULT_NUM_OF_LOG_EVENT_ATTRIBUTES; + } +} diff --git a/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java b/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java new file mode 100644 index 0000000000..a0f650906a --- /dev/null +++ b/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java @@ -0,0 +1,49 @@ +package com.nr.agent.instrumentation.log4j2; + +public class ExceptionUtil { + public static final int MAX_STACK_SIZE = 300; + + public static boolean isThrowableNull(Throwable throwable) { + return throwable == null; + } + + public static String getErrorStack(Throwable throwable) { + if (isThrowableNull(throwable)) { + return null; + } + + StackTraceElement[] stack = throwable.getStackTrace(); + return getErrorStack(stack); + } + + public static String getErrorStack(StackTraceElement[] stack) { + return getErrorStack(stack, MAX_STACK_SIZE); + } + + public static String getErrorStack(StackTraceElement[] stack, Integer maxStackSize) { + if (stack == null || stack.length == 0) { + return null; + } + + StringBuilder stackBuilder = new StringBuilder(); + int stackSizeLimit = Math.min(maxStackSize, stack.length); + for (int i = 0; i < stackSizeLimit; i++) { + stackBuilder.append(" at ").append(stack[i].toString()).append("\n"); + } + return stackBuilder.toString(); + } + + public static String getErrorMessage(Throwable throwable) { + if (isThrowableNull(throwable)) { + return null; + } + return throwable.getMessage(); + } + + public static String getErrorClass(Throwable throwable) { + if (isThrowableNull(throwable)) { + return null; + } + return throwable.getClass().getName(); + } +} diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java new file mode 100644 index 0000000000..15f9df708c --- /dev/null +++ b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java @@ -0,0 +1,66 @@ +/* + * + * * Copyright 2022 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package org.apache.logging.log4j.core.config; + +import com.newrelic.api.agent.NewRelic; +import com.newrelic.api.agent.weaver.MatchType; +import com.newrelic.api.agent.weaver.NewField; +import com.newrelic.api.agent.weaver.Weave; +import com.newrelic.api.agent.weaver.WeaveAllConstructors; +import com.newrelic.api.agent.weaver.Weaver; +import org.apache.logging.log4j.core.LogEvent; + +import java.util.concurrent.atomic.AtomicBoolean; + +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingEnabled; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingForwardingEnabled; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingMetricsEnabled; +import static com.nr.agent.instrumentation.log4j2.AgentUtil.recordNewRelicLogEvent; + +@Weave(originalName = "org.apache.logging.log4j.core.config.LoggerConfig", type = MatchType.ExactClass) +public class LoggerConfig_Instrumentation { + @NewField + public static AtomicBoolean instrumented = new AtomicBoolean(false); + + @WeaveAllConstructors + public LoggerConfig_Instrumentation() { + // Generate the instrumentation module supportability metric only once + if (!instrumented.getAndSet(true)) { + NewRelic.incrementCounter("Supportability/Logging/Java/Log4j2/enabled"); + } + } + + protected void callAppenders(LogEvent event) { + // Do nothing if application_logging.enabled: false + if (isApplicationLoggingEnabled()) { + // Do nothing if logger has parents and isAdditive is set to true to avoid duplicated counters and logs + if (getParent() == null || !isAdditive()) { + if (isApplicationLoggingMetricsEnabled()) { + // Generate log level metrics + NewRelic.incrementCounter("Logging/lines"); + NewRelic.incrementCounter("Logging/lines/" + event.getLevel().toString()); + } + + if (isApplicationLoggingForwardingEnabled()) { + // Record and send LogEvent to New Relic + recordNewRelicLogEvent(event); + } + } + } + Weaver.callOriginal(); + } + + public LoggerConfig getParent() { + return Weaver.callOriginal(); + } + + public boolean isAdditive() { + return Weaver.callOriginal(); + } + +} diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java new file mode 100644 index 0000000000..5c5c42038a --- /dev/null +++ b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java @@ -0,0 +1,33 @@ +/* + * + * * Copyright 2023 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package org.apache.logging.log4j.core.layout; + +import com.newrelic.api.agent.weaver.MatchType; +import com.newrelic.api.agent.weaver.Weave; +import com.newrelic.api.agent.weaver.Weaver; + +import java.nio.charset.Charset; + +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; + +@Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractStringLayout", type = MatchType.ExactClass) +public abstract class AbstractStringLayout_Instrumentation { + + private final Charset charset = Weaver.callOriginal(); + + protected byte[] getBytes(final String s) { + String modified = s; + if (!s.contains("NR-LINKING")) { + int indexToInsertNrLinkingMetadata = s.indexOf("\n", s.indexOf("message")) - 1; + // Replace the JSON string with modified version + modified = new StringBuilder(s).insert(indexToInsertNrLinkingMetadata, getLinkingMetadataBlob()).toString(); + } + return modified.getBytes(charset); + } + +} diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java new file mode 100644 index 0000000000..e09c3e19a5 --- /dev/null +++ b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java @@ -0,0 +1,40 @@ +/* + * + * * Copyright 2022 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package org.apache.logging.log4j.core.layout; + +import com.newrelic.api.agent.weaver.MatchType; +import com.newrelic.api.agent.weaver.Weave; +import com.newrelic.api.agent.weaver.Weaver; + +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingEnabled; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingLocalDecoratingEnabled; + +@Weave(originalName = "org.apache.logging.log4j.core.layout.StringBuilderEncoder", type = MatchType.BaseClass) +public class StringBuilderEncoder_Instrumentation { + + public void encode(final StringBuilder source, final ByteBufferDestination destination) { + // Do nothing if application_logging.enabled: false + if (isApplicationLoggingEnabled()) { + if (isApplicationLoggingLocalDecoratingEnabled()) { + // Append New Relic linking metadata from agent to log message + appendAgentMetadata(source); + } + } + Weaver.callOriginal(); + } + + private void appendAgentMetadata(StringBuilder source) { + int breakLine = source.toString().lastIndexOf("\n"); + if (breakLine != -1) { + source.replace(breakLine, breakLine + 1, ""); + } + source.append(getLinkingMetadataBlob()).append("\n"); + } + +} \ No newline at end of file diff --git a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java new file mode 100644 index 0000000000..09b8893aec --- /dev/null +++ b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java @@ -0,0 +1,64 @@ +/* + * + * * Copyright 2022 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ +package com.nr.agent.instrumentation.log4j2; + +import com.newrelic.agent.introspec.InstrumentationTestConfig; +import com.newrelic.agent.introspec.InstrumentationTestRunner; +import com.newrelic.agent.introspec.Introspector; +import com.newrelic.agent.model.LogEvent; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.ThreadContext; +import org.apache.logging.log4j.core.config.Configurator; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; + +import java.util.Collection; +import java.util.Map; + +import static org.junit.Assert.*; + +@RunWith(InstrumentationTestRunner.class) +@InstrumentationTestConfig(includePrefixes = { "org.apache.logging.log4j.core" }, configName = "application_logging_context_data_enabled.yml") +public class ContextDataTest { + + private final Introspector introspector = InstrumentationTestRunner.getIntrospector(); + + @Before + public void reset() { + Configurator.reconfigure(); + introspector.clearLogEvents(); + } + + @Test + public void testAttributes() { + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + String attrKey1 = "key"; + String attrKey2 = "anotherKey"; + String val1 = "42"; + String val2 = "panic"; + + ThreadContext.put(attrKey1, val1); + ThreadContext.put(attrKey2, val2); + logger.error("message"); + + Collection logEvents = introspector.getLogEvents(); + assertEquals(1, logEvents.size()); + + LogEvent logEvent = logEvents.iterator().next(); + Map attributes = logEvent.getUserAttributesCopy(); + long contextAttrCount = attributes.keySet().stream() + .filter(key -> key.startsWith("context.")) + .count(); + // MDC data is filtered later in the process + assertEquals(2L, contextAttrCount); + assertEquals(val1, attributes.get("context." + attrKey1)); + assertEquals(val2, attributes.get("context." + attrKey2)); + } + +} diff --git a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java new file mode 100644 index 0000000000..85545ba746 --- /dev/null +++ b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java @@ -0,0 +1,61 @@ +package com.nr.agent.instrumentation.log4j2; + +import org.junit.Test; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertNull; +import static org.junit.Assert.assertTrue; + +public class ExceptionUtilTest { + + @Test + public void testIsThrowableNull() { + Throwable nullThrowable = null; + Throwable nonNullThrowable = new Throwable("Hi"); + + assertTrue(ExceptionUtil.isThrowableNull(nullThrowable)); + assertFalse(ExceptionUtil.isThrowableNull(nonNullThrowable)); + } + + @Test + public void testGetErrorStack() { + int maxStackSize = 3; + StackTraceElement stackTraceElement1 = new StackTraceElement("Class1", "method1", "File1", 1); + StackTraceElement stackTraceElement2 = new StackTraceElement("Class2", "method2", "File2", 2); + StackTraceElement stackTraceElement3 = new StackTraceElement("Class3", "method3", "File3", 3); + StackTraceElement stackTraceElement4 = new StackTraceElement("Class4", "method4", "File4", 4); + StackTraceElement stackTraceElement5 = new StackTraceElement("Class5", "method5", "File5", 5); + StackTraceElement[] stack = new StackTraceElement[] { stackTraceElement1, stackTraceElement2, stackTraceElement3, stackTraceElement4, + stackTraceElement5 }; + String errorStack = ExceptionUtil.getErrorStack(stack, maxStackSize); + + // Processed stack should be limited to only the first three lines + assertTrue(errorStack.contains(stackTraceElement1.toString())); + assertTrue(errorStack.contains(stackTraceElement2.toString())); + assertTrue(errorStack.contains(stackTraceElement3.toString())); + // Processed stack should omit the last two lines + assertFalse(errorStack.contains(stackTraceElement4.toString())); + assertFalse(errorStack.contains(stackTraceElement5.toString())); + } + + @Test + public void testGetErrorMessage() { + String expectedMessage = "Hi"; + Throwable nullThrowable = null; + Throwable nonNullThrowable = new Throwable(expectedMessage); + + assertNull(ExceptionUtil.getErrorMessage(nullThrowable)); + assertEquals(expectedMessage, ExceptionUtil.getErrorMessage(nonNullThrowable)); + } + + @Test + public void testGetErrorClass() { + String expectedExceptionClass = "java.lang.RuntimeException"; + Throwable nullThrowable = null; + RuntimeException runtimeException = new RuntimeException("Hi"); + + assertNull(ExceptionUtil.getErrorClass(nullThrowable)); + assertEquals(expectedExceptionClass, ExceptionUtil.getErrorClass(runtimeException)); + } +} diff --git a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java new file mode 100644 index 0000000000..5fc7516329 --- /dev/null +++ b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java @@ -0,0 +1,622 @@ +package com.nr.agent.instrumentation.log4j2; + +import com.newrelic.agent.introspec.InstrumentationTestConfig; +import com.newrelic.agent.introspec.InstrumentationTestRunner; +import com.newrelic.agent.introspec.Introspector; +import com.newrelic.agent.introspec.MetricsHelper; +import com.newrelic.agent.model.LogEvent; +import junit.framework.TestCase; +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.ThreadContext; +import org.apache.logging.log4j.core.Appender; +import org.apache.logging.log4j.core.Layout; +import org.apache.logging.log4j.core.LoggerContext; +import org.apache.logging.log4j.core.appender.ConsoleAppender; +import org.apache.logging.log4j.core.config.AppenderRef; +import org.apache.logging.log4j.core.config.Configuration; +import org.apache.logging.log4j.core.config.Configurator; +import org.apache.logging.log4j.core.config.LoggerConfig; +import org.apache.logging.log4j.core.layout.PatternLayout; +import org.junit.Assert; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; + +import java.util.Collection; +import java.util.List; +import java.util.Map; +import java.util.stream.Collectors; + +@RunWith(InstrumentationTestRunner.class) +@InstrumentationTestConfig(includePrefixes = { "org.apache.logging.log4j.core" }, configName = "application_logging_enabled.yml") +public class LoggerConfig_InstrumentationTest extends TestCase { + + private static final String CAPTURED = "This log message should be captured"; + private static final String NOT_CAPTURED = "This message should NOT be captured"; + private final Introspector introspector = InstrumentationTestRunner.getIntrospector(); + + @Before + public void reset() { + Configurator.reconfigure(); + introspector.clearLogEvents(); + } + + @Test + public void testLogEventsAllLevel() { + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + // Log at ALL level + setLoggerLevel(Level.ALL); + + int expectedTotalEventsCapturedAtFatal = 1; + logger.fatal(CAPTURED); + + int expectedTotalEventsCapturedAtError = 2; + logger.error(CAPTURED); + logger.error(CAPTURED); + + int expectedTotalEventsCapturedAtWarn = 3; + logger.warn(CAPTURED); + logger.warn(CAPTURED); + logger.warn(CAPTURED); + + int expectedTotalEventsCapturedAtInfo = 4; + logger.info(CAPTURED); + logger.info(CAPTURED); + logger.info(CAPTURED); + logger.info(CAPTURED); + + int expectedTotalEventsCapturedAtDebug = 5; + logger.debug(CAPTURED); + logger.debug(CAPTURED); + logger.debug(CAPTURED); + logger.debug(CAPTURED); + logger.debug(CAPTURED); + + int expectedTotalEventsCapturedAtTrace = 6; + logger.trace(CAPTURED); + logger.trace(CAPTURED); + logger.trace(CAPTURED); + logger.trace(CAPTURED); + logger.trace(CAPTURED); + logger.trace(CAPTURED); + + int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + + expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + + expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + + expectedTotalEventsCapturedAtTrace; + + Collection logEvents = introspector.getLogEvents(); + + assertEquals(expectedTotalEventsCaptured, logEvents.size()); + + List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); + List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); + List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); + List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); + List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); + List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); + + assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); + } + + @Test + public void testLogEventsOffLevel() { + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + // Logging is OFF at all levels + setLoggerLevel(Level.OFF); + + int expectedTotalEventsCapturedAtFatal = 0; + logger.fatal(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtError = 0; + logger.error(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtWarn = 0; + logger.warn(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtInfo = 0; + logger.info(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtDebug = 0; + logger.debug(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtTrace = 0; + logger.trace(NOT_CAPTURED); + + int expectedTotalEventsCaptured = 0; + + Collection logEvents = introspector.getLogEvents(); + + assertEquals(expectedTotalEventsCaptured, logEvents.size()); + + List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); + List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); + List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); + List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); + List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); + List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); + + assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); + } + + @Test + public void testLogEventsFatalLevel() { + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + // Log at FATAL level + setLoggerLevel(Level.FATAL); + + int expectedTotalEventsCapturedAtFatal = 1; + logger.fatal(CAPTURED); + + int expectedTotalEventsCapturedAtError = 0; + logger.error(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtWarn = 0; + logger.warn(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtInfo = 0; + logger.info(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtDebug = 0; + logger.debug(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtTrace = 0; + logger.trace(NOT_CAPTURED); + + int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + + expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + + expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + + expectedTotalEventsCapturedAtTrace; + + Collection logEvents = introspector.getLogEvents(); + + assertEquals(expectedTotalEventsCaptured, logEvents.size()); + + List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); + List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); + List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); + List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); + List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); + List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); + + assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); + } + + @Test + public void testLogEventsErrorLevel() { + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + // Log at ERROR level + setLoggerLevel(Level.ERROR); + + int expectedTotalEventsCapturedAtFatal = 1; + logger.fatal(CAPTURED); + + int expectedTotalEventsCapturedAtError = 1; + logger.error(CAPTURED); + + int expectedTotalEventsCapturedAtWarn = 0; + logger.warn(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtInfo = 0; + logger.info(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtDebug = 0; + logger.debug(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtTrace = 0; + logger.trace(NOT_CAPTURED); + + int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + + expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + + expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + + expectedTotalEventsCapturedAtTrace; + + Collection logEvents = introspector.getLogEvents(); + + assertEquals(expectedTotalEventsCaptured, logEvents.size()); + + List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); + List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); + List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); + List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); + List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); + List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); + + assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); + } + + @Test + public void testLogEventsWarnLevel() { + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + // Log at WARN level + setLoggerLevel(Level.WARN); + + int expectedTotalEventsCapturedAtFatal = 1; + logger.fatal(CAPTURED); + + int expectedTotalEventsCapturedAtError = 1; + logger.error(CAPTURED); + + int expectedTotalEventsCapturedAtWarn = 1; + logger.warn(CAPTURED); + + int expectedTotalEventsCapturedAtInfo = 0; + logger.info(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtDebug = 0; + logger.debug(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtTrace = 0; + logger.trace(NOT_CAPTURED); + + int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + + expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + + expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + + expectedTotalEventsCapturedAtTrace; + + Collection logEvents = introspector.getLogEvents(); + + assertEquals(expectedTotalEventsCaptured, logEvents.size()); + + List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); + List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); + List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); + List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); + List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); + List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); + + assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); + } + + @Test + public void testLogEventsInfoLevel() { + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + // Log at INFO level + setLoggerLevel(Level.INFO); + + int expectedTotalEventsCapturedAtFatal = 1; + logger.fatal(CAPTURED); + + int expectedTotalEventsCapturedAtError = 1; + logger.error(CAPTURED); + + int expectedTotalEventsCapturedAtWarn = 1; + logger.warn(CAPTURED); + + int expectedTotalEventsCapturedAtInfo = 1; + logger.info(CAPTURED); + + int expectedTotalEventsCapturedAtDebug = 0; + logger.debug(NOT_CAPTURED); + + int expectedTotalEventsCapturedAtTrace = 0; + logger.trace(NOT_CAPTURED); + + int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + + expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + + expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + + expectedTotalEventsCapturedAtTrace; + + Collection logEvents = introspector.getLogEvents(); + + assertEquals(expectedTotalEventsCaptured, logEvents.size()); + + List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); + List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); + List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); + List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); + List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); + List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); + + assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); + } + + @Test + public void testLogEventsDebugLevel() { + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + // Log at DEBUG level + setLoggerLevel(Level.DEBUG); + + int expectedTotalEventsCapturedAtFatal = 1; + logger.fatal(CAPTURED); + + int expectedTotalEventsCapturedAtError = 1; + logger.error(CAPTURED); + + int expectedTotalEventsCapturedAtWarn = 1; + logger.warn(CAPTURED); + + int expectedTotalEventsCapturedAtInfo = 1; + logger.info(CAPTURED); + + int expectedTotalEventsCapturedAtDebug = 1; + logger.debug(CAPTURED); + + int expectedTotalEventsCapturedAtTrace = 0; + logger.trace(NOT_CAPTURED); + + int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + + expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + + expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + + expectedTotalEventsCapturedAtTrace; + + Collection logEvents = introspector.getLogEvents(); + + assertEquals(expectedTotalEventsCaptured, logEvents.size()); + + List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); + List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); + List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); + List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); + List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); + List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); + + assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); + } + + @Test + public void testLogEventsTraceLevel() { + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + // Log at TRACE level + setLoggerLevel(Level.TRACE); + + int expectedTotalEventsCapturedAtFatal = 1; + logger.fatal(CAPTURED); + + int expectedTotalEventsCapturedAtError = 1; + logger.error(CAPTURED); + + int expectedTotalEventsCapturedAtWarn = 1; + logger.warn(CAPTURED); + + int expectedTotalEventsCapturedAtInfo = 1; + logger.info(CAPTURED); + + int expectedTotalEventsCapturedAtDebug = 1; + logger.debug(CAPTURED); + + int expectedTotalEventsCapturedAtTrace = 1; + logger.trace(CAPTURED); + + int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + + expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + + expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + + expectedTotalEventsCapturedAtTrace; + + Collection logEvents = introspector.getLogEvents(); + + assertEquals(expectedTotalEventsCaptured, logEvents.size()); + + List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); + List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); + List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); + List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); + List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); + List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); + + assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); + assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); + } + + private List getTraceLevelLogEvents(Collection logEvents) { + return logEvents.stream() + .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.TRACE.toString())) + .collect(Collectors.toList()); + } + + private List getDebugLevelLogEvents(Collection logEvents) { + return logEvents.stream() + .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.DEBUG.toString())) + .collect(Collectors.toList()); + } + + private List getInfoLevelLogEvents(Collection logEvents) { + return logEvents.stream() + .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.INFO.toString())) + .collect(Collectors.toList()); + } + + private List getWarnLevelLogEvents(Collection logEvents) { + return logEvents.stream() + .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.WARN.toString())) + .collect(Collectors.toList()); + } + + private List getErrorLevelLogEvents(Collection logEvents) { + return logEvents.stream() + .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.ERROR.toString())) + .collect(Collectors.toList()); + } + + private List getFatalLevelLogEvents(Collection logEvents) { + return logEvents.stream() + .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.FATAL.toString())) + .collect(Collectors.toList()); + } + + @Test + public void shouldIncrementEmittedLogsCountersIndependentlyIfLogLevelEnabled() { + // Given + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + setLoggerLevel(Level.INFO); + + // When + logger.trace(NOT_CAPTURED); + logger.debug(NOT_CAPTURED); + logger.info(CAPTURED); + logger.info(CAPTURED); + logger.info(CAPTURED); + logger.warn(CAPTURED); + logger.warn(CAPTURED); + logger.warn(CAPTURED); + logger.warn(CAPTURED); + logger.error(CAPTURED); + + // Then + Assert.assertEquals(8, MetricsHelper.getUnscopedMetricCount("Logging/lines")); + Assert.assertEquals(0, MetricsHelper.getUnscopedMetricCount("Logging/lines/TRACE")); + Assert.assertEquals(0, MetricsHelper.getUnscopedMetricCount("Logging/lines/DEBUG")); + Assert.assertEquals(3, MetricsHelper.getUnscopedMetricCount("Logging/lines/INFO")); + Assert.assertEquals(4, MetricsHelper.getUnscopedMetricCount("Logging/lines/WARN")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/ERROR")); + } + + @Test + public void shouldIncrementAllEmittedLogCountersIfLogLevelIsSetToTrace() { + // Given + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + setLoggerLevel(Level.TRACE); + + // When + logger.trace(CAPTURED); + logger.debug(CAPTURED); + logger.info(CAPTURED); + logger.warn(CAPTURED); + logger.error(CAPTURED); + + // Then + Assert.assertEquals(5, MetricsHelper.getUnscopedMetricCount("Logging/lines")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/TRACE")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/DEBUG")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/INFO")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/WARN")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/ERROR")); + } + + @Test + public void shouldIncrementAllEmittedLogCountersOnlyOnceWhenMultipleLoggersAreSet() { + // Given + createLogger("A_SPECIAL_LOGGER", createAppender("ConsoleAppender"), Level.TRACE, true); + final Logger logger = LogManager.getLogger("A_SPECIAL_LOGGER"); + setLoggerLevel(Level.TRACE); + + // When + logger.trace(CAPTURED); + logger.debug(CAPTURED); + logger.info(CAPTURED); + logger.warn(CAPTURED); + logger.error(CAPTURED); + + // Then + Assert.assertEquals(5, MetricsHelper.getUnscopedMetricCount("Logging/lines")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/TRACE")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/DEBUG")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/INFO")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/WARN")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/ERROR")); + } + + @Test + public void shouldIncrementAllEmittedLogCountersRespectingLevelFromOriginalLogger() { + // Given + createLogger("A_SPECIAL_LOGGER", createAppender("ConsoleAppender"), Level.INFO, true); + final Logger logger = LogManager.getLogger("A_SPECIAL_LOGGER"); + setLoggerLevel(Level.ERROR); + + // When + logger.trace(NOT_CAPTURED); + logger.debug(NOT_CAPTURED); + logger.info(CAPTURED); + logger.warn(CAPTURED); + logger.error(CAPTURED); + + // Then + Assert.assertEquals(3, MetricsHelper.getUnscopedMetricCount("Logging/lines")); + Assert.assertEquals(0, MetricsHelper.getUnscopedMetricCount("Logging/lines/TRACE")); + Assert.assertEquals(0, MetricsHelper.getUnscopedMetricCount("Logging/lines/DEBUG")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/INFO")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/WARN")); + Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/ERROR")); + } + + private void createLogger(String name, Appender appender, Level level, boolean additivity) { + final LoggerContext ctx = (LoggerContext) LogManager.getContext(false); + final Configuration config = ctx.getConfiguration(); + AppenderRef ref = AppenderRef.createAppenderRef("File", null, null); + AppenderRef[] refs = new AppenderRef[] { ref }; + LoggerConfig loggerConfig = LoggerConfig.createLogger(additivity, level, name, "true", refs, null, config, null); + loggerConfig.addAppender(appender, level, null); + config.addLogger(name, loggerConfig); + } + + private Appender createAppender(String name) { + Layout layout = PatternLayout.newBuilder() + .withPattern(PatternLayout.SIMPLE_CONVERSION_PATTERN) + .build(); + Appender appender = ConsoleAppender.newBuilder() + .setName(name) + .setLayout(layout) + .build(); + appender.start(); + return appender; + } + + private void setLoggerLevel(Level level) { + final LoggerContext context = (LoggerContext) LogManager.getContext(false); + final Configuration configuration = context.getConfiguration(); + final LoggerConfig rootConfig = configuration.getLoggerConfig(LogManager.ROOT_LOGGER_NAME); + rootConfig.setLevel(level); + context.updateLoggers(); + } + + @Test + public void contextDataDisabledTest() { + final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); + ThreadContext.put("include", "42"); + ThreadContext.put("exclude", "panic"); + + logger.error("message"); + + Collection logEvents = introspector.getLogEvents(); + assertEquals(1, logEvents.size()); + + // verify no context attrs + Map attributes = logEvents.iterator().next().getUserAttributesCopy(); + long contextAttrCount = attributes.keySet().stream() + .filter(key -> key.startsWith("context.")) + .count(); + assertEquals(0L, contextAttrCount); + } + +} diff --git a/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_context_data_enabled.yml b/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_context_data_enabled.yml new file mode 100644 index 0000000000..1212edc2e9 --- /dev/null +++ b/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_context_data_enabled.yml @@ -0,0 +1,12 @@ +common: &default_settings + application_logging: + enabled: true + forwarding: + enabled: true + max_samples_stored: 10000 + context_data: + enabled: true + metrics: + enabled: true + local_decorating: + enabled: false diff --git a/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_enabled.yml b/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_enabled.yml new file mode 100644 index 0000000000..583ffd2bba --- /dev/null +++ b/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_enabled.yml @@ -0,0 +1,10 @@ +common: &default_settings + application_logging: + enabled: true + forwarding: + enabled: true + max_samples_stored: 10000 + metrics: + enabled: true + local_decorating: + enabled: false diff --git a/instrumentation/apache-log4j-2/build.gradle b/instrumentation/apache-log4j-2/build.gradle index 2042aee68b..e52121e98b 100644 --- a/instrumentation/apache-log4j-2/build.gradle +++ b/instrumentation/apache-log4j-2/build.gradle @@ -4,11 +4,11 @@ jar { dependencies { implementation(project(":agent-bridge")) - implementation("org.apache.logging.log4j:log4j-core:2.17.1") + implementation("org.apache.logging.log4j:log4j-core:2.14.1") } verifyInstrumentation { - passesOnly("org.apache.logging.log4j:log4j-core:[2.6,)") + passesOnly("org.apache.logging.log4j:log4j-core:[2.6,2.15.0)") excludeRegex '.*(alpha|beta|rc).*' } diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java deleted file mode 100644 index 409f3a9ac5..0000000000 --- a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java +++ /dev/null @@ -1,45 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package org.apache.logging.log4j.core.layout; - -import com.newrelic.api.agent.weaver.MatchType; -import com.newrelic.api.agent.weaver.Weave; -import com.newrelic.api.agent.weaver.Weaver; - -import java.util.Map; - -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingEnabled; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingLocalDecoratingEnabled; - -abstract class AbstractJacksonLayout_Instrumentation { - - @Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractJacksonLayout$LogEventWithAdditionalFields", type = MatchType.ExactClass) - public static class LogEventWithAdditionalFields_Instrumentation { - - private final Object logEvent; - private final Map additionalFields; - - public LogEventWithAdditionalFields_Instrumentation(final Object logEvent, final Map additionalFields) { - // This will only ever work if at least one additional field is set in the JsonLayout, doesn't matter what it is - // - // - // - - this.logEvent = Weaver.callOriginal(); - if (isApplicationLoggingEnabled()) { - if (isApplicationLoggingLocalDecoratingEnabled()) { - // Append New Relic linking metadata from agent to log message - additionalFields.put("In NR", getLinkingMetadataBlob()); - } - } - this.additionalFields = Weaver.callOriginal(); - } - } - -} diff --git a/settings.gradle b/settings.gradle index 3d6120d011..12f612d170 100644 --- a/settings.gradle +++ b/settings.gradle @@ -87,6 +87,7 @@ include 'instrumentation:akka-http-core-10.0' include 'instrumentation:akka-http-core-10.2.0' include 'instrumentation:apache-log4j-1' include 'instrumentation:apache-log4j-2' +include 'instrumentation:apache-log4j-2.15' include 'instrumentation:async-http-client-2.0.0' include 'instrumentation:async-http-client-2.1.0' include 'instrumentation:cassandra-datastax-3.0.0' From 0e8249ad4a033c2fed71791ee2a67424994c6ece Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Tue, 5 Sep 2023 11:24:32 -0700 Subject: [PATCH 03/21] Update copyright headers --- .../com/nr/agent/instrumentation/log4j2/AgentUtil.java | 2 +- .../com/nr/agent/instrumentation/log4j2/ExceptionUtil.java | 7 +++++++ .../log4j/core/config/LoggerConfig_Instrumentation.java | 2 +- .../core/layout/StringBuilderEncoder_Instrumentation.java | 2 +- .../nr/agent/instrumentation/log4j2/ContextDataTest.java | 2 +- .../nr/agent/instrumentation/log4j2/ExceptionUtilTest.java | 7 +++++++ .../log4j2/LoggerConfig_InstrumentationTest.java | 7 +++++++ 7 files changed, 25 insertions(+), 4 deletions(-) diff --git a/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java b/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java index 05ac051504..0ef59817a8 100644 --- a/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java +++ b/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java @@ -1,6 +1,6 @@ /* * - * * Copyright 2022 New Relic Corporation. All rights reserved. + * * Copyright 2023 New Relic Corporation. All rights reserved. * * SPDX-License-Identifier: Apache-2.0 * */ diff --git a/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java b/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java index a0f650906a..fe87219561 100644 --- a/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java +++ b/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java @@ -1,3 +1,10 @@ +/* + * + * * Copyright 2023 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + package com.nr.agent.instrumentation.log4j2; public class ExceptionUtil { diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java index 15f9df708c..cc33972047 100644 --- a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java +++ b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java @@ -1,6 +1,6 @@ /* * - * * Copyright 2022 New Relic Corporation. All rights reserved. + * * Copyright 2023 New Relic Corporation. All rights reserved. * * SPDX-License-Identifier: Apache-2.0 * */ diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java index e09c3e19a5..121cbdfdaf 100644 --- a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java +++ b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java @@ -1,6 +1,6 @@ /* * - * * Copyright 2022 New Relic Corporation. All rights reserved. + * * Copyright 2023 New Relic Corporation. All rights reserved. * * SPDX-License-Identifier: Apache-2.0 * */ diff --git a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java index 09b8893aec..1ab8a4d5d5 100644 --- a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java +++ b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java @@ -1,6 +1,6 @@ /* * - * * Copyright 2022 New Relic Corporation. All rights reserved. + * * Copyright 2023 New Relic Corporation. All rights reserved. * * SPDX-License-Identifier: Apache-2.0 * */ diff --git a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java index 85545ba746..9ebc9ca804 100644 --- a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java +++ b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java @@ -1,3 +1,10 @@ +/* + * + * * Copyright 2023 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + package com.nr.agent.instrumentation.log4j2; import org.junit.Test; diff --git a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java index 5fc7516329..2d16b08b34 100644 --- a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java +++ b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java @@ -1,3 +1,10 @@ +/* + * + * * Copyright 2023 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + package com.nr.agent.instrumentation.log4j2; import com.newrelic.agent.introspec.InstrumentationTestConfig; From 3ef39c078d31b065a9521a27c439390eb7ee6fe5 Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Tue, 5 Sep 2023 11:29:51 -0700 Subject: [PATCH 04/21] Add comments --- .../core/layout/AbstractStringLayout_Instrumentation.java | 3 ++- .../core/layout/AbstractStringLayout_Instrumentation.java | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java index 5c5c42038a..1af85ae231 100644 --- a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java +++ b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java @@ -22,9 +22,10 @@ public abstract class AbstractStringLayout_Instrumentation { protected byte[] getBytes(final String s) { String modified = s; + // It is possible that the log being formatted into JSON might already have NR-LINKING metadata from JUL instrumentation if (!s.contains("NR-LINKING")) { int indexToInsertNrLinkingMetadata = s.indexOf("\n", s.indexOf("message")) - 1; - // Replace the JSON string with modified version + // Replace the JSON string with modified version that includes NR-LINKING metadata modified = new StringBuilder(s).insert(indexToInsertNrLinkingMetadata, getLinkingMetadataBlob()).toString(); } return modified.getBytes(charset); diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java index 9d57018e47..79c0bc487c 100644 --- a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java +++ b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java @@ -26,9 +26,10 @@ public abstract class AbstractStringLayout_Instrumentation { protected byte[] getBytes(final String s) { String modified = s; + // It is possible that the log being formatted into JSON might already have NR-LINKING metadata from JUL instrumentation if (!s.contains("NR-LINKING")) { int indexToInsertNrLinkingMetadata = s.indexOf("\n", s.indexOf("message")) - 1; - // Replace the JSON string with modified version + // Replace the JSON string with modified version that includes NR-LINKING metadata modified = new StringBuilder(s).insert(indexToInsertNrLinkingMetadata, getLinkingMetadataBlob()).toString(); } if (useCustomEncoding) { From c1571369f55dc19f2eb3e2158bf0ba05b29014b4 Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Tue, 5 Sep 2023 12:07:02 -0700 Subject: [PATCH 05/21] Prevent log4j2 instrumentation from adding NR-LINKING metadata if it was already added by other logger instrumentation (e.g. JUL). --- .../AbstractStringLayout_Instrumentation.java | 3 ++- .../StringBuilderEncoder_Instrumentation.java | 15 ++++++++++----- .../AbstractStringLayout_Instrumentation.java | 3 ++- .../StringBuilderEncoder_Instrumentation.java | 15 ++++++++++----- 4 files changed, 24 insertions(+), 12 deletions(-) diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java index 1af85ae231..4f448da82b 100644 --- a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java +++ b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java @@ -13,6 +13,7 @@ import java.nio.charset.Charset; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.BLOB_PREFIX; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; @Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractStringLayout", type = MatchType.ExactClass) @@ -23,7 +24,7 @@ public abstract class AbstractStringLayout_Instrumentation { protected byte[] getBytes(final String s) { String modified = s; // It is possible that the log being formatted into JSON might already have NR-LINKING metadata from JUL instrumentation - if (!s.contains("NR-LINKING")) { + if (!s.contains(BLOB_PREFIX)) { int indexToInsertNrLinkingMetadata = s.indexOf("\n", s.indexOf("message")) - 1; // Replace the JSON string with modified version that includes NR-LINKING metadata modified = new StringBuilder(s).insert(indexToInsertNrLinkingMetadata, getLinkingMetadataBlob()).toString(); diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java index 121cbdfdaf..e87d757bd3 100644 --- a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java +++ b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java @@ -11,6 +11,7 @@ import com.newrelic.api.agent.weaver.Weave; import com.newrelic.api.agent.weaver.Weaver; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.BLOB_PREFIX; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingEnabled; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingLocalDecoratingEnabled; @@ -30,11 +31,15 @@ public void encode(final StringBuilder source, final ByteBufferDestination desti } private void appendAgentMetadata(StringBuilder source) { - int breakLine = source.toString().lastIndexOf("\n"); - if (breakLine != -1) { - source.replace(breakLine, breakLine + 1, ""); + String sourceString = source.toString(); + // It is possible that the log might already have NR-LINKING metadata from JUL instrumentation + if (!sourceString.contains(BLOB_PREFIX)) { + int breakLine = sourceString.lastIndexOf("\n"); + if (breakLine != -1) { + source.replace(breakLine, breakLine + 1, ""); + } + source.append(getLinkingMetadataBlob()).append("\n"); } - source.append(getLinkingMetadataBlob()).append("\n"); } -} \ No newline at end of file +} diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java index 79c0bc487c..ac9c3a7b5f 100644 --- a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java +++ b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java @@ -15,6 +15,7 @@ import java.io.UnsupportedEncodingException; import java.nio.charset.Charset; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.BLOB_PREFIX; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; @Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractStringLayout", type = MatchType.ExactClass) @@ -27,7 +28,7 @@ public abstract class AbstractStringLayout_Instrumentation { protected byte[] getBytes(final String s) { String modified = s; // It is possible that the log being formatted into JSON might already have NR-LINKING metadata from JUL instrumentation - if (!s.contains("NR-LINKING")) { + if (!s.contains(BLOB_PREFIX)) { int indexToInsertNrLinkingMetadata = s.indexOf("\n", s.indexOf("message")) - 1; // Replace the JSON string with modified version that includes NR-LINKING metadata modified = new StringBuilder(s).insert(indexToInsertNrLinkingMetadata, getLinkingMetadataBlob()).toString(); diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java index e09c3e19a5..ef3469d0d7 100644 --- a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java +++ b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java @@ -11,6 +11,7 @@ import com.newrelic.api.agent.weaver.Weave; import com.newrelic.api.agent.weaver.Weaver; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.BLOB_PREFIX; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingEnabled; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingLocalDecoratingEnabled; @@ -30,11 +31,15 @@ public void encode(final StringBuilder source, final ByteBufferDestination desti } private void appendAgentMetadata(StringBuilder source) { - int breakLine = source.toString().lastIndexOf("\n"); - if (breakLine != -1) { - source.replace(breakLine, breakLine + 1, ""); + String sourceString = source.toString(); + // It is possible that the log might already have NR-LINKING metadata from JUL instrumentation + if (!sourceString.contains(BLOB_PREFIX)) { + int breakLine = sourceString.lastIndexOf("\n"); + if (breakLine != -1) { + source.replace(breakLine, breakLine + 1, ""); + } + source.append(getLinkingMetadataBlob()).append("\n"); } - source.append(getLinkingMetadataBlob()).append("\n"); } -} \ No newline at end of file +} From fc1379afe55e6283ad8b27e09e861376633dfa3d Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Tue, 5 Sep 2023 14:48:42 -0700 Subject: [PATCH 06/21] Insert NR-LINKING metadata within closing parenthesis --- .../core/layout/AbstractStringLayout_Instrumentation.java | 6 ++++-- .../core/layout/AbstractStringLayout_Instrumentation.java | 6 ++++-- 2 files changed, 8 insertions(+), 4 deletions(-) diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java index 4f448da82b..c4db3b4fba 100644 --- a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java +++ b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java @@ -23,9 +23,11 @@ public abstract class AbstractStringLayout_Instrumentation { protected byte[] getBytes(final String s) { String modified = s; - // It is possible that the log being formatted into JSON might already have NR-LINKING metadata from JUL instrumentation + // It is possible that the log might already have NR-LINKING metadata from JUL instrumentation if (!s.contains(BLOB_PREFIX)) { - int indexToInsertNrLinkingMetadata = s.indexOf("\n", s.indexOf("message")) - 1; + // Finds the index of the closing parenthesis for a substring that begins with "message" and ends with the sequence ",\n + // Example JSON substring: "message":"Tomcat initialized",\n + int indexToInsertNrLinkingMetadata = s.indexOf("\",\n", s.indexOf("message")); // Replace the JSON string with modified version that includes NR-LINKING metadata modified = new StringBuilder(s).insert(indexToInsertNrLinkingMetadata, getLinkingMetadataBlob()).toString(); } diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java index ac9c3a7b5f..16034ca258 100644 --- a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java +++ b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java @@ -27,9 +27,11 @@ public abstract class AbstractStringLayout_Instrumentation { protected byte[] getBytes(final String s) { String modified = s; - // It is possible that the log being formatted into JSON might already have NR-LINKING metadata from JUL instrumentation + // It is possible that the log might already have NR-LINKING metadata from JUL instrumentation if (!s.contains(BLOB_PREFIX)) { - int indexToInsertNrLinkingMetadata = s.indexOf("\n", s.indexOf("message")) - 1; + // Finds the index of the closing parenthesis for a substring that begins with "message" and ends with the sequence ",\n + // Example JSON substring: "message":"Tomcat initialized",\n + int indexToInsertNrLinkingMetadata = s.indexOf("\",\n", s.indexOf("message")); // Replace the JSON string with modified version that includes NR-LINKING metadata modified = new StringBuilder(s).insert(indexToInsertNrLinkingMetadata, getLinkingMetadataBlob()).toString(); } From dc96abfc2c71d999795eac9cbc515bf6b3e8f757 Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Wed, 6 Sep 2023 16:34:34 -0700 Subject: [PATCH 07/21] Refactor to use new approach with AbstractJacksonLayout --- .../apache-log4j-2.15/build.gradle | 18 - .../instrumentation/log4j2/AgentUtil.java | 131 ---- .../instrumentation/log4j2/ExceptionUtil.java | 56 -- .../config/LoggerConfig_Instrumentation.java | 66 -- .../AbstractStringLayout_Instrumentation.java | 37 -- .../StringBuilderEncoder_Instrumentation.java | 45 -- .../log4j2/ContextDataTest.java | 64 -- .../log4j2/ExceptionUtilTest.java | 68 -- .../LoggerConfig_InstrumentationTest.java | 629 ------------------ ...plication_logging_context_data_enabled.yml | 12 - .../resources/application_logging_enabled.yml | 10 - instrumentation/apache-log4j-2/build.gradle | 5 +- .../instrumentation/log4j2/AgentUtil.java | 32 +- ...AbstractJacksonLayout_Instrumentation.java | 51 ++ .../AbstractStringLayout_Instrumentation.java | 48 -- settings.gradle | 1 - 16 files changed, 84 insertions(+), 1189 deletions(-) delete mode 100644 instrumentation/apache-log4j-2.15/build.gradle delete mode 100644 instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java delete mode 100644 instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java delete mode 100644 instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java delete mode 100644 instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java delete mode 100644 instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java delete mode 100644 instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java delete mode 100644 instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java delete mode 100644 instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java delete mode 100644 instrumentation/apache-log4j-2.15/src/test/resources/application_logging_context_data_enabled.yml delete mode 100644 instrumentation/apache-log4j-2.15/src/test/resources/application_logging_enabled.yml create mode 100644 instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java delete mode 100644 instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java diff --git a/instrumentation/apache-log4j-2.15/build.gradle b/instrumentation/apache-log4j-2.15/build.gradle deleted file mode 100644 index 109a0ea164..0000000000 --- a/instrumentation/apache-log4j-2.15/build.gradle +++ /dev/null @@ -1,18 +0,0 @@ -jar { - manifest { attributes 'Implementation-Title': 'com.newrelic.instrumentation.apache-log4j-2.15' } -} - -dependencies { - implementation(project(":agent-bridge")) - implementation("org.apache.logging.log4j:log4j-core:2.20.0") -} - -verifyInstrumentation { - passesOnly("org.apache.logging.log4j:log4j-core:[2.15.0,)") - excludeRegex '.*(alpha|beta|rc).*' -} - -site { - title 'Log4j2' - type 'Framework' -} diff --git a/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java b/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java deleted file mode 100644 index 0ef59817a8..0000000000 --- a/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java +++ /dev/null @@ -1,131 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package com.nr.agent.instrumentation.log4j2; - -import com.newrelic.agent.bridge.AgentBridge; -import com.newrelic.agent.bridge.logging.AppLoggingUtils; -import com.newrelic.agent.bridge.logging.LogAttributeKey; -import com.newrelic.agent.bridge.logging.LogAttributeType; -import org.apache.logging.log4j.Level; -import org.apache.logging.log4j.core.LogEvent; -import org.apache.logging.log4j.message.Message; -import org.apache.logging.log4j.util.ReadOnlyStringMap; - -import java.util.HashMap; -import java.util.Map; - -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.DEFAULT_NUM_OF_LOG_EVENT_ATTRIBUTES; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.ERROR_CLASS; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.ERROR_MESSAGE; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.ERROR_STACK; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.INSTRUMENTATION; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.LEVEL; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.LOGGER_FQCN; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.LOGGER_NAME; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.MESSAGE; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.THREAD_ID; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.THREAD_NAME; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.TIMESTAMP; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.UNKNOWN; - -public class AgentUtil { - /** - * Record a LogEvent to be sent to New Relic. - * - * @param event to parse - */ - public static void recordNewRelicLogEvent(LogEvent event) { - if (event != null) { - Message message = event.getMessage(); - Throwable throwable = event.getThrown(); - - if (shouldCreateLogEvent(message, throwable)) { - ReadOnlyStringMap contextData = event.getContextData(); - Map logEventMap = new HashMap<>(calculateInitialMapSize(contextData)); - logEventMap.put(INSTRUMENTATION, "apache-log4j-2.15"); - if (message != null) { - String formattedMessage = message.getFormattedMessage(); - if (formattedMessage != null && !formattedMessage.isEmpty()) { - logEventMap.put(MESSAGE, formattedMessage); - } - } - logEventMap.put(TIMESTAMP, event.getTimeMillis()); - - if (AppLoggingUtils.isAppLoggingContextDataEnabled() && contextData != null) { - for (Map.Entry entry : contextData.toMap().entrySet()) { - String key = entry.getKey(); - String value = entry.getValue(); - LogAttributeKey logAttrKey = new LogAttributeKey(key, LogAttributeType.CONTEXT); - logEventMap.put(logAttrKey, value); - } - } - - Level level = event.getLevel(); - if (level != null) { - String levelName = level.name(); - if (levelName.isEmpty()) { - logEventMap.put(LEVEL, UNKNOWN); - } else { - logEventMap.put(LEVEL, levelName); - } - } - - String errorStack = ExceptionUtil.getErrorStack(throwable); - if (errorStack != null) { - logEventMap.put(ERROR_STACK, errorStack); - } - - String errorMessage = ExceptionUtil.getErrorMessage(throwable); - if (errorMessage != null) { - logEventMap.put(ERROR_MESSAGE, errorMessage); - } - - String errorClass = ExceptionUtil.getErrorClass(throwable); - if (errorClass != null) { - logEventMap.put(ERROR_CLASS, errorClass); - } - - String threadName = event.getThreadName(); - if (threadName != null) { - logEventMap.put(THREAD_NAME, threadName); - } - - logEventMap.put(THREAD_ID, event.getThreadId()); - - String loggerName = event.getLoggerName(); - if (loggerName != null) { - logEventMap.put(LOGGER_NAME, loggerName); - } - - String loggerFqcn = event.getLoggerFqcn(); - if (loggerFqcn != null) { - logEventMap.put(LOGGER_FQCN, loggerFqcn); - } - - AgentBridge.getAgent().getLogSender().recordLogEvent(logEventMap); - } - } - } - - /** - * A LogEvent MUST NOT be reported if neither a log message nor an error is logged. If either is present report the LogEvent. - * - * @param message Message to validate - * @param throwable Throwable to validate - * @return true if a LogEvent should be created, otherwise false - */ - private static boolean shouldCreateLogEvent(Message message, Throwable throwable) { - return (message != null) || !ExceptionUtil.isThrowableNull(throwable); - } - - private static int calculateInitialMapSize(ReadOnlyStringMap mdcPropertyMap) { - return AppLoggingUtils.isAppLoggingContextDataEnabled() && mdcPropertyMap != null - ? mdcPropertyMap.size() + DEFAULT_NUM_OF_LOG_EVENT_ATTRIBUTES - : DEFAULT_NUM_OF_LOG_EVENT_ATTRIBUTES; - } -} diff --git a/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java b/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java deleted file mode 100644 index fe87219561..0000000000 --- a/instrumentation/apache-log4j-2.15/src/main/java/com/nr/agent/instrumentation/log4j2/ExceptionUtil.java +++ /dev/null @@ -1,56 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package com.nr.agent.instrumentation.log4j2; - -public class ExceptionUtil { - public static final int MAX_STACK_SIZE = 300; - - public static boolean isThrowableNull(Throwable throwable) { - return throwable == null; - } - - public static String getErrorStack(Throwable throwable) { - if (isThrowableNull(throwable)) { - return null; - } - - StackTraceElement[] stack = throwable.getStackTrace(); - return getErrorStack(stack); - } - - public static String getErrorStack(StackTraceElement[] stack) { - return getErrorStack(stack, MAX_STACK_SIZE); - } - - public static String getErrorStack(StackTraceElement[] stack, Integer maxStackSize) { - if (stack == null || stack.length == 0) { - return null; - } - - StringBuilder stackBuilder = new StringBuilder(); - int stackSizeLimit = Math.min(maxStackSize, stack.length); - for (int i = 0; i < stackSizeLimit; i++) { - stackBuilder.append(" at ").append(stack[i].toString()).append("\n"); - } - return stackBuilder.toString(); - } - - public static String getErrorMessage(Throwable throwable) { - if (isThrowableNull(throwable)) { - return null; - } - return throwable.getMessage(); - } - - public static String getErrorClass(Throwable throwable) { - if (isThrowableNull(throwable)) { - return null; - } - return throwable.getClass().getName(); - } -} diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java deleted file mode 100644 index cc33972047..0000000000 --- a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig_Instrumentation.java +++ /dev/null @@ -1,66 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package org.apache.logging.log4j.core.config; - -import com.newrelic.api.agent.NewRelic; -import com.newrelic.api.agent.weaver.MatchType; -import com.newrelic.api.agent.weaver.NewField; -import com.newrelic.api.agent.weaver.Weave; -import com.newrelic.api.agent.weaver.WeaveAllConstructors; -import com.newrelic.api.agent.weaver.Weaver; -import org.apache.logging.log4j.core.LogEvent; - -import java.util.concurrent.atomic.AtomicBoolean; - -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingEnabled; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingForwardingEnabled; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingMetricsEnabled; -import static com.nr.agent.instrumentation.log4j2.AgentUtil.recordNewRelicLogEvent; - -@Weave(originalName = "org.apache.logging.log4j.core.config.LoggerConfig", type = MatchType.ExactClass) -public class LoggerConfig_Instrumentation { - @NewField - public static AtomicBoolean instrumented = new AtomicBoolean(false); - - @WeaveAllConstructors - public LoggerConfig_Instrumentation() { - // Generate the instrumentation module supportability metric only once - if (!instrumented.getAndSet(true)) { - NewRelic.incrementCounter("Supportability/Logging/Java/Log4j2/enabled"); - } - } - - protected void callAppenders(LogEvent event) { - // Do nothing if application_logging.enabled: false - if (isApplicationLoggingEnabled()) { - // Do nothing if logger has parents and isAdditive is set to true to avoid duplicated counters and logs - if (getParent() == null || !isAdditive()) { - if (isApplicationLoggingMetricsEnabled()) { - // Generate log level metrics - NewRelic.incrementCounter("Logging/lines"); - NewRelic.incrementCounter("Logging/lines/" + event.getLevel().toString()); - } - - if (isApplicationLoggingForwardingEnabled()) { - // Record and send LogEvent to New Relic - recordNewRelicLogEvent(event); - } - } - } - Weaver.callOriginal(); - } - - public LoggerConfig getParent() { - return Weaver.callOriginal(); - } - - public boolean isAdditive() { - return Weaver.callOriginal(); - } - -} diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java deleted file mode 100644 index c4db3b4fba..0000000000 --- a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java +++ /dev/null @@ -1,37 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package org.apache.logging.log4j.core.layout; - -import com.newrelic.api.agent.weaver.MatchType; -import com.newrelic.api.agent.weaver.Weave; -import com.newrelic.api.agent.weaver.Weaver; - -import java.nio.charset.Charset; - -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.BLOB_PREFIX; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; - -@Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractStringLayout", type = MatchType.ExactClass) -public abstract class AbstractStringLayout_Instrumentation { - - private final Charset charset = Weaver.callOriginal(); - - protected byte[] getBytes(final String s) { - String modified = s; - // It is possible that the log might already have NR-LINKING metadata from JUL instrumentation - if (!s.contains(BLOB_PREFIX)) { - // Finds the index of the closing parenthesis for a substring that begins with "message" and ends with the sequence ",\n - // Example JSON substring: "message":"Tomcat initialized",\n - int indexToInsertNrLinkingMetadata = s.indexOf("\",\n", s.indexOf("message")); - // Replace the JSON string with modified version that includes NR-LINKING metadata - modified = new StringBuilder(s).insert(indexToInsertNrLinkingMetadata, getLinkingMetadataBlob()).toString(); - } - return modified.getBytes(charset); - } - -} diff --git a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java b/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java deleted file mode 100644 index e87d757bd3..0000000000 --- a/instrumentation/apache-log4j-2.15/src/main/java/org/apache/logging/log4j/core/layout/StringBuilderEncoder_Instrumentation.java +++ /dev/null @@ -1,45 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package org.apache.logging.log4j.core.layout; - -import com.newrelic.api.agent.weaver.MatchType; -import com.newrelic.api.agent.weaver.Weave; -import com.newrelic.api.agent.weaver.Weaver; - -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.BLOB_PREFIX; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingEnabled; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingLocalDecoratingEnabled; - -@Weave(originalName = "org.apache.logging.log4j.core.layout.StringBuilderEncoder", type = MatchType.BaseClass) -public class StringBuilderEncoder_Instrumentation { - - public void encode(final StringBuilder source, final ByteBufferDestination destination) { - // Do nothing if application_logging.enabled: false - if (isApplicationLoggingEnabled()) { - if (isApplicationLoggingLocalDecoratingEnabled()) { - // Append New Relic linking metadata from agent to log message - appendAgentMetadata(source); - } - } - Weaver.callOriginal(); - } - - private void appendAgentMetadata(StringBuilder source) { - String sourceString = source.toString(); - // It is possible that the log might already have NR-LINKING metadata from JUL instrumentation - if (!sourceString.contains(BLOB_PREFIX)) { - int breakLine = sourceString.lastIndexOf("\n"); - if (breakLine != -1) { - source.replace(breakLine, breakLine + 1, ""); - } - source.append(getLinkingMetadataBlob()).append("\n"); - } - } - -} diff --git a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java deleted file mode 100644 index 1ab8a4d5d5..0000000000 --- a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ContextDataTest.java +++ /dev/null @@ -1,64 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ -package com.nr.agent.instrumentation.log4j2; - -import com.newrelic.agent.introspec.InstrumentationTestConfig; -import com.newrelic.agent.introspec.InstrumentationTestRunner; -import com.newrelic.agent.introspec.Introspector; -import com.newrelic.agent.model.LogEvent; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; -import org.apache.logging.log4j.ThreadContext; -import org.apache.logging.log4j.core.config.Configurator; -import org.junit.Before; -import org.junit.Test; -import org.junit.runner.RunWith; - -import java.util.Collection; -import java.util.Map; - -import static org.junit.Assert.*; - -@RunWith(InstrumentationTestRunner.class) -@InstrumentationTestConfig(includePrefixes = { "org.apache.logging.log4j.core" }, configName = "application_logging_context_data_enabled.yml") -public class ContextDataTest { - - private final Introspector introspector = InstrumentationTestRunner.getIntrospector(); - - @Before - public void reset() { - Configurator.reconfigure(); - introspector.clearLogEvents(); - } - - @Test - public void testAttributes() { - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - String attrKey1 = "key"; - String attrKey2 = "anotherKey"; - String val1 = "42"; - String val2 = "panic"; - - ThreadContext.put(attrKey1, val1); - ThreadContext.put(attrKey2, val2); - logger.error("message"); - - Collection logEvents = introspector.getLogEvents(); - assertEquals(1, logEvents.size()); - - LogEvent logEvent = logEvents.iterator().next(); - Map attributes = logEvent.getUserAttributesCopy(); - long contextAttrCount = attributes.keySet().stream() - .filter(key -> key.startsWith("context.")) - .count(); - // MDC data is filtered later in the process - assertEquals(2L, contextAttrCount); - assertEquals(val1, attributes.get("context." + attrKey1)); - assertEquals(val2, attributes.get("context." + attrKey2)); - } - -} diff --git a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java deleted file mode 100644 index 9ebc9ca804..0000000000 --- a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/ExceptionUtilTest.java +++ /dev/null @@ -1,68 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package com.nr.agent.instrumentation.log4j2; - -import org.junit.Test; - -import static org.junit.Assert.assertEquals; -import static org.junit.Assert.assertFalse; -import static org.junit.Assert.assertNull; -import static org.junit.Assert.assertTrue; - -public class ExceptionUtilTest { - - @Test - public void testIsThrowableNull() { - Throwable nullThrowable = null; - Throwable nonNullThrowable = new Throwable("Hi"); - - assertTrue(ExceptionUtil.isThrowableNull(nullThrowable)); - assertFalse(ExceptionUtil.isThrowableNull(nonNullThrowable)); - } - - @Test - public void testGetErrorStack() { - int maxStackSize = 3; - StackTraceElement stackTraceElement1 = new StackTraceElement("Class1", "method1", "File1", 1); - StackTraceElement stackTraceElement2 = new StackTraceElement("Class2", "method2", "File2", 2); - StackTraceElement stackTraceElement3 = new StackTraceElement("Class3", "method3", "File3", 3); - StackTraceElement stackTraceElement4 = new StackTraceElement("Class4", "method4", "File4", 4); - StackTraceElement stackTraceElement5 = new StackTraceElement("Class5", "method5", "File5", 5); - StackTraceElement[] stack = new StackTraceElement[] { stackTraceElement1, stackTraceElement2, stackTraceElement3, stackTraceElement4, - stackTraceElement5 }; - String errorStack = ExceptionUtil.getErrorStack(stack, maxStackSize); - - // Processed stack should be limited to only the first three lines - assertTrue(errorStack.contains(stackTraceElement1.toString())); - assertTrue(errorStack.contains(stackTraceElement2.toString())); - assertTrue(errorStack.contains(stackTraceElement3.toString())); - // Processed stack should omit the last two lines - assertFalse(errorStack.contains(stackTraceElement4.toString())); - assertFalse(errorStack.contains(stackTraceElement5.toString())); - } - - @Test - public void testGetErrorMessage() { - String expectedMessage = "Hi"; - Throwable nullThrowable = null; - Throwable nonNullThrowable = new Throwable(expectedMessage); - - assertNull(ExceptionUtil.getErrorMessage(nullThrowable)); - assertEquals(expectedMessage, ExceptionUtil.getErrorMessage(nonNullThrowable)); - } - - @Test - public void testGetErrorClass() { - String expectedExceptionClass = "java.lang.RuntimeException"; - Throwable nullThrowable = null; - RuntimeException runtimeException = new RuntimeException("Hi"); - - assertNull(ExceptionUtil.getErrorClass(nullThrowable)); - assertEquals(expectedExceptionClass, ExceptionUtil.getErrorClass(runtimeException)); - } -} diff --git a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java b/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java deleted file mode 100644 index 2d16b08b34..0000000000 --- a/instrumentation/apache-log4j-2.15/src/test/java/com/nr/agent/instrumentation/log4j2/LoggerConfig_InstrumentationTest.java +++ /dev/null @@ -1,629 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package com.nr.agent.instrumentation.log4j2; - -import com.newrelic.agent.introspec.InstrumentationTestConfig; -import com.newrelic.agent.introspec.InstrumentationTestRunner; -import com.newrelic.agent.introspec.Introspector; -import com.newrelic.agent.introspec.MetricsHelper; -import com.newrelic.agent.model.LogEvent; -import junit.framework.TestCase; -import org.apache.logging.log4j.Level; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; -import org.apache.logging.log4j.ThreadContext; -import org.apache.logging.log4j.core.Appender; -import org.apache.logging.log4j.core.Layout; -import org.apache.logging.log4j.core.LoggerContext; -import org.apache.logging.log4j.core.appender.ConsoleAppender; -import org.apache.logging.log4j.core.config.AppenderRef; -import org.apache.logging.log4j.core.config.Configuration; -import org.apache.logging.log4j.core.config.Configurator; -import org.apache.logging.log4j.core.config.LoggerConfig; -import org.apache.logging.log4j.core.layout.PatternLayout; -import org.junit.Assert; -import org.junit.Before; -import org.junit.Test; -import org.junit.runner.RunWith; - -import java.util.Collection; -import java.util.List; -import java.util.Map; -import java.util.stream.Collectors; - -@RunWith(InstrumentationTestRunner.class) -@InstrumentationTestConfig(includePrefixes = { "org.apache.logging.log4j.core" }, configName = "application_logging_enabled.yml") -public class LoggerConfig_InstrumentationTest extends TestCase { - - private static final String CAPTURED = "This log message should be captured"; - private static final String NOT_CAPTURED = "This message should NOT be captured"; - private final Introspector introspector = InstrumentationTestRunner.getIntrospector(); - - @Before - public void reset() { - Configurator.reconfigure(); - introspector.clearLogEvents(); - } - - @Test - public void testLogEventsAllLevel() { - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - // Log at ALL level - setLoggerLevel(Level.ALL); - - int expectedTotalEventsCapturedAtFatal = 1; - logger.fatal(CAPTURED); - - int expectedTotalEventsCapturedAtError = 2; - logger.error(CAPTURED); - logger.error(CAPTURED); - - int expectedTotalEventsCapturedAtWarn = 3; - logger.warn(CAPTURED); - logger.warn(CAPTURED); - logger.warn(CAPTURED); - - int expectedTotalEventsCapturedAtInfo = 4; - logger.info(CAPTURED); - logger.info(CAPTURED); - logger.info(CAPTURED); - logger.info(CAPTURED); - - int expectedTotalEventsCapturedAtDebug = 5; - logger.debug(CAPTURED); - logger.debug(CAPTURED); - logger.debug(CAPTURED); - logger.debug(CAPTURED); - logger.debug(CAPTURED); - - int expectedTotalEventsCapturedAtTrace = 6; - logger.trace(CAPTURED); - logger.trace(CAPTURED); - logger.trace(CAPTURED); - logger.trace(CAPTURED); - logger.trace(CAPTURED); - logger.trace(CAPTURED); - - int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + - expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + - expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + - expectedTotalEventsCapturedAtTrace; - - Collection logEvents = introspector.getLogEvents(); - - assertEquals(expectedTotalEventsCaptured, logEvents.size()); - - List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); - List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); - List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); - List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); - List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); - List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); - - assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); - } - - @Test - public void testLogEventsOffLevel() { - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - // Logging is OFF at all levels - setLoggerLevel(Level.OFF); - - int expectedTotalEventsCapturedAtFatal = 0; - logger.fatal(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtError = 0; - logger.error(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtWarn = 0; - logger.warn(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtInfo = 0; - logger.info(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtDebug = 0; - logger.debug(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtTrace = 0; - logger.trace(NOT_CAPTURED); - - int expectedTotalEventsCaptured = 0; - - Collection logEvents = introspector.getLogEvents(); - - assertEquals(expectedTotalEventsCaptured, logEvents.size()); - - List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); - List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); - List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); - List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); - List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); - List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); - - assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); - } - - @Test - public void testLogEventsFatalLevel() { - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - // Log at FATAL level - setLoggerLevel(Level.FATAL); - - int expectedTotalEventsCapturedAtFatal = 1; - logger.fatal(CAPTURED); - - int expectedTotalEventsCapturedAtError = 0; - logger.error(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtWarn = 0; - logger.warn(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtInfo = 0; - logger.info(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtDebug = 0; - logger.debug(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtTrace = 0; - logger.trace(NOT_CAPTURED); - - int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + - expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + - expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + - expectedTotalEventsCapturedAtTrace; - - Collection logEvents = introspector.getLogEvents(); - - assertEquals(expectedTotalEventsCaptured, logEvents.size()); - - List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); - List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); - List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); - List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); - List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); - List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); - - assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); - } - - @Test - public void testLogEventsErrorLevel() { - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - // Log at ERROR level - setLoggerLevel(Level.ERROR); - - int expectedTotalEventsCapturedAtFatal = 1; - logger.fatal(CAPTURED); - - int expectedTotalEventsCapturedAtError = 1; - logger.error(CAPTURED); - - int expectedTotalEventsCapturedAtWarn = 0; - logger.warn(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtInfo = 0; - logger.info(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtDebug = 0; - logger.debug(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtTrace = 0; - logger.trace(NOT_CAPTURED); - - int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + - expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + - expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + - expectedTotalEventsCapturedAtTrace; - - Collection logEvents = introspector.getLogEvents(); - - assertEquals(expectedTotalEventsCaptured, logEvents.size()); - - List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); - List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); - List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); - List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); - List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); - List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); - - assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); - } - - @Test - public void testLogEventsWarnLevel() { - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - // Log at WARN level - setLoggerLevel(Level.WARN); - - int expectedTotalEventsCapturedAtFatal = 1; - logger.fatal(CAPTURED); - - int expectedTotalEventsCapturedAtError = 1; - logger.error(CAPTURED); - - int expectedTotalEventsCapturedAtWarn = 1; - logger.warn(CAPTURED); - - int expectedTotalEventsCapturedAtInfo = 0; - logger.info(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtDebug = 0; - logger.debug(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtTrace = 0; - logger.trace(NOT_CAPTURED); - - int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + - expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + - expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + - expectedTotalEventsCapturedAtTrace; - - Collection logEvents = introspector.getLogEvents(); - - assertEquals(expectedTotalEventsCaptured, logEvents.size()); - - List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); - List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); - List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); - List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); - List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); - List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); - - assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); - } - - @Test - public void testLogEventsInfoLevel() { - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - // Log at INFO level - setLoggerLevel(Level.INFO); - - int expectedTotalEventsCapturedAtFatal = 1; - logger.fatal(CAPTURED); - - int expectedTotalEventsCapturedAtError = 1; - logger.error(CAPTURED); - - int expectedTotalEventsCapturedAtWarn = 1; - logger.warn(CAPTURED); - - int expectedTotalEventsCapturedAtInfo = 1; - logger.info(CAPTURED); - - int expectedTotalEventsCapturedAtDebug = 0; - logger.debug(NOT_CAPTURED); - - int expectedTotalEventsCapturedAtTrace = 0; - logger.trace(NOT_CAPTURED); - - int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + - expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + - expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + - expectedTotalEventsCapturedAtTrace; - - Collection logEvents = introspector.getLogEvents(); - - assertEquals(expectedTotalEventsCaptured, logEvents.size()); - - List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); - List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); - List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); - List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); - List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); - List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); - - assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); - } - - @Test - public void testLogEventsDebugLevel() { - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - // Log at DEBUG level - setLoggerLevel(Level.DEBUG); - - int expectedTotalEventsCapturedAtFatal = 1; - logger.fatal(CAPTURED); - - int expectedTotalEventsCapturedAtError = 1; - logger.error(CAPTURED); - - int expectedTotalEventsCapturedAtWarn = 1; - logger.warn(CAPTURED); - - int expectedTotalEventsCapturedAtInfo = 1; - logger.info(CAPTURED); - - int expectedTotalEventsCapturedAtDebug = 1; - logger.debug(CAPTURED); - - int expectedTotalEventsCapturedAtTrace = 0; - logger.trace(NOT_CAPTURED); - - int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + - expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + - expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + - expectedTotalEventsCapturedAtTrace; - - Collection logEvents = introspector.getLogEvents(); - - assertEquals(expectedTotalEventsCaptured, logEvents.size()); - - List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); - List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); - List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); - List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); - List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); - List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); - - assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); - } - - @Test - public void testLogEventsTraceLevel() { - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - // Log at TRACE level - setLoggerLevel(Level.TRACE); - - int expectedTotalEventsCapturedAtFatal = 1; - logger.fatal(CAPTURED); - - int expectedTotalEventsCapturedAtError = 1; - logger.error(CAPTURED); - - int expectedTotalEventsCapturedAtWarn = 1; - logger.warn(CAPTURED); - - int expectedTotalEventsCapturedAtInfo = 1; - logger.info(CAPTURED); - - int expectedTotalEventsCapturedAtDebug = 1; - logger.debug(CAPTURED); - - int expectedTotalEventsCapturedAtTrace = 1; - logger.trace(CAPTURED); - - int expectedTotalEventsCaptured = expectedTotalEventsCapturedAtFatal + - expectedTotalEventsCapturedAtError + expectedTotalEventsCapturedAtWarn + - expectedTotalEventsCapturedAtInfo + expectedTotalEventsCapturedAtDebug + - expectedTotalEventsCapturedAtTrace; - - Collection logEvents = introspector.getLogEvents(); - - assertEquals(expectedTotalEventsCaptured, logEvents.size()); - - List fatalLevelLogEvents = getFatalLevelLogEvents(logEvents); - List errorLevelLogEvents = getErrorLevelLogEvents(logEvents); - List warnLevelLogEvents = getWarnLevelLogEvents(logEvents); - List infoLevelLogEvents = getInfoLevelLogEvents(logEvents); - List debugLevelLogEvents = getDebugLevelLogEvents(logEvents); - List traceLevelLogEvents = getTraceLevelLogEvents(logEvents); - - assertEquals(expectedTotalEventsCapturedAtFatal, fatalLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtError, errorLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtWarn, warnLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtInfo, infoLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtDebug, debugLevelLogEvents.size()); - assertEquals(expectedTotalEventsCapturedAtTrace, traceLevelLogEvents.size()); - } - - private List getTraceLevelLogEvents(Collection logEvents) { - return logEvents.stream() - .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.TRACE.toString())) - .collect(Collectors.toList()); - } - - private List getDebugLevelLogEvents(Collection logEvents) { - return logEvents.stream() - .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.DEBUG.toString())) - .collect(Collectors.toList()); - } - - private List getInfoLevelLogEvents(Collection logEvents) { - return logEvents.stream() - .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.INFO.toString())) - .collect(Collectors.toList()); - } - - private List getWarnLevelLogEvents(Collection logEvents) { - return logEvents.stream() - .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.WARN.toString())) - .collect(Collectors.toList()); - } - - private List getErrorLevelLogEvents(Collection logEvents) { - return logEvents.stream() - .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.ERROR.toString())) - .collect(Collectors.toList()); - } - - private List getFatalLevelLogEvents(Collection logEvents) { - return logEvents.stream() - .filter(logEvent -> logEvent.getUserAttributesCopy().containsValue(Level.FATAL.toString())) - .collect(Collectors.toList()); - } - - @Test - public void shouldIncrementEmittedLogsCountersIndependentlyIfLogLevelEnabled() { - // Given - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - setLoggerLevel(Level.INFO); - - // When - logger.trace(NOT_CAPTURED); - logger.debug(NOT_CAPTURED); - logger.info(CAPTURED); - logger.info(CAPTURED); - logger.info(CAPTURED); - logger.warn(CAPTURED); - logger.warn(CAPTURED); - logger.warn(CAPTURED); - logger.warn(CAPTURED); - logger.error(CAPTURED); - - // Then - Assert.assertEquals(8, MetricsHelper.getUnscopedMetricCount("Logging/lines")); - Assert.assertEquals(0, MetricsHelper.getUnscopedMetricCount("Logging/lines/TRACE")); - Assert.assertEquals(0, MetricsHelper.getUnscopedMetricCount("Logging/lines/DEBUG")); - Assert.assertEquals(3, MetricsHelper.getUnscopedMetricCount("Logging/lines/INFO")); - Assert.assertEquals(4, MetricsHelper.getUnscopedMetricCount("Logging/lines/WARN")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/ERROR")); - } - - @Test - public void shouldIncrementAllEmittedLogCountersIfLogLevelIsSetToTrace() { - // Given - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - setLoggerLevel(Level.TRACE); - - // When - logger.trace(CAPTURED); - logger.debug(CAPTURED); - logger.info(CAPTURED); - logger.warn(CAPTURED); - logger.error(CAPTURED); - - // Then - Assert.assertEquals(5, MetricsHelper.getUnscopedMetricCount("Logging/lines")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/TRACE")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/DEBUG")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/INFO")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/WARN")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/ERROR")); - } - - @Test - public void shouldIncrementAllEmittedLogCountersOnlyOnceWhenMultipleLoggersAreSet() { - // Given - createLogger("A_SPECIAL_LOGGER", createAppender("ConsoleAppender"), Level.TRACE, true); - final Logger logger = LogManager.getLogger("A_SPECIAL_LOGGER"); - setLoggerLevel(Level.TRACE); - - // When - logger.trace(CAPTURED); - logger.debug(CAPTURED); - logger.info(CAPTURED); - logger.warn(CAPTURED); - logger.error(CAPTURED); - - // Then - Assert.assertEquals(5, MetricsHelper.getUnscopedMetricCount("Logging/lines")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/TRACE")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/DEBUG")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/INFO")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/WARN")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/ERROR")); - } - - @Test - public void shouldIncrementAllEmittedLogCountersRespectingLevelFromOriginalLogger() { - // Given - createLogger("A_SPECIAL_LOGGER", createAppender("ConsoleAppender"), Level.INFO, true); - final Logger logger = LogManager.getLogger("A_SPECIAL_LOGGER"); - setLoggerLevel(Level.ERROR); - - // When - logger.trace(NOT_CAPTURED); - logger.debug(NOT_CAPTURED); - logger.info(CAPTURED); - logger.warn(CAPTURED); - logger.error(CAPTURED); - - // Then - Assert.assertEquals(3, MetricsHelper.getUnscopedMetricCount("Logging/lines")); - Assert.assertEquals(0, MetricsHelper.getUnscopedMetricCount("Logging/lines/TRACE")); - Assert.assertEquals(0, MetricsHelper.getUnscopedMetricCount("Logging/lines/DEBUG")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/INFO")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/WARN")); - Assert.assertEquals(1, MetricsHelper.getUnscopedMetricCount("Logging/lines/ERROR")); - } - - private void createLogger(String name, Appender appender, Level level, boolean additivity) { - final LoggerContext ctx = (LoggerContext) LogManager.getContext(false); - final Configuration config = ctx.getConfiguration(); - AppenderRef ref = AppenderRef.createAppenderRef("File", null, null); - AppenderRef[] refs = new AppenderRef[] { ref }; - LoggerConfig loggerConfig = LoggerConfig.createLogger(additivity, level, name, "true", refs, null, config, null); - loggerConfig.addAppender(appender, level, null); - config.addLogger(name, loggerConfig); - } - - private Appender createAppender(String name) { - Layout layout = PatternLayout.newBuilder() - .withPattern(PatternLayout.SIMPLE_CONVERSION_PATTERN) - .build(); - Appender appender = ConsoleAppender.newBuilder() - .setName(name) - .setLayout(layout) - .build(); - appender.start(); - return appender; - } - - private void setLoggerLevel(Level level) { - final LoggerContext context = (LoggerContext) LogManager.getContext(false); - final Configuration configuration = context.getConfiguration(); - final LoggerConfig rootConfig = configuration.getLoggerConfig(LogManager.ROOT_LOGGER_NAME); - rootConfig.setLevel(level); - context.updateLoggers(); - } - - @Test - public void contextDataDisabledTest() { - final Logger logger = LogManager.getLogger(LoggerConfig_InstrumentationTest.class); - ThreadContext.put("include", "42"); - ThreadContext.put("exclude", "panic"); - - logger.error("message"); - - Collection logEvents = introspector.getLogEvents(); - assertEquals(1, logEvents.size()); - - // verify no context attrs - Map attributes = logEvents.iterator().next().getUserAttributesCopy(); - long contextAttrCount = attributes.keySet().stream() - .filter(key -> key.startsWith("context.")) - .count(); - assertEquals(0L, contextAttrCount); - } - -} diff --git a/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_context_data_enabled.yml b/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_context_data_enabled.yml deleted file mode 100644 index 1212edc2e9..0000000000 --- a/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_context_data_enabled.yml +++ /dev/null @@ -1,12 +0,0 @@ -common: &default_settings - application_logging: - enabled: true - forwarding: - enabled: true - max_samples_stored: 10000 - context_data: - enabled: true - metrics: - enabled: true - local_decorating: - enabled: false diff --git a/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_enabled.yml b/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_enabled.yml deleted file mode 100644 index 583ffd2bba..0000000000 --- a/instrumentation/apache-log4j-2.15/src/test/resources/application_logging_enabled.yml +++ /dev/null @@ -1,10 +0,0 @@ -common: &default_settings - application_logging: - enabled: true - forwarding: - enabled: true - max_samples_stored: 10000 - metrics: - enabled: true - local_decorating: - enabled: false diff --git a/instrumentation/apache-log4j-2/build.gradle b/instrumentation/apache-log4j-2/build.gradle index e52121e98b..2083af1595 100644 --- a/instrumentation/apache-log4j-2/build.gradle +++ b/instrumentation/apache-log4j-2/build.gradle @@ -4,12 +4,11 @@ jar { dependencies { implementation(project(":agent-bridge")) - implementation("org.apache.logging.log4j:log4j-core:2.14.1") + implementation("org.apache.logging.log4j:log4j-core:2.20.0") } verifyInstrumentation { - passesOnly("org.apache.logging.log4j:log4j-core:[2.6,2.15.0)") - excludeRegex '.*(alpha|beta|rc).*' + passesOnly("org.apache.logging.log4j:log4j-core:[2.6,3.0.0-alpha1)") } site { diff --git a/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java b/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java index df8761d0fc..d69fdd3d18 100644 --- a/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java +++ b/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java @@ -14,7 +14,6 @@ import org.apache.logging.log4j.Level; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.message.Message; -import org.apache.logging.log4j.util.ReadOnlyStringMap; import java.util.HashMap; import java.util.Map; @@ -128,4 +127,35 @@ private static int calculateInitialMapSize(Map mdcPropertyMap) { ? mdcPropertyMap.size() + DEFAULT_NUM_OF_LOG_EVENT_ATTRIBUTES : DEFAULT_NUM_OF_LOG_EVENT_ATTRIBUTES; } + + /** + * Checks a pretty and compact JSON strings for a series of characters and returns the index of + * the characters or -1 if they were not found. This is used to find the log "message" substring + * so that the NR-LINKING metadata blob can be inserted when using local decorating with JsonLayout. + * + * @param writerString String representing JSON formatted log event + * @return positive int if index was found, else -1 + */ + public static int getIndexToModifyJson(String writerString) { + int indexOfMessage = writerString.indexOf("message"); + // Pretty JSON format + int indexToModifyJson = writerString.indexOf("\",\n", indexOfMessage); + if (!foundIndexToInsertLinkingMetadata(indexToModifyJson)) { + // Compact JSON format + indexToModifyJson = writerString.indexOf("\",", indexOfMessage); + } + return indexToModifyJson; + } + + /** + * Check if a valid match was found when calling String.indexOf. + * If index value is -1 then no valid match was found, a positive integer represents a valid index. + * + * @param indexToModifyJson int representing index returned by indexOf + * @return true if a valid index was found, else false + */ + public static boolean foundIndexToInsertLinkingMetadata(int indexToModifyJson) { + return indexToModifyJson != -1; + } + } diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java new file mode 100644 index 0000000000..d6c696b45f --- /dev/null +++ b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java @@ -0,0 +1,51 @@ +/* + * + * * Copyright 2023 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package org.apache.logging.log4j.core.layout; + +import com.newrelic.api.agent.weaver.MatchType; +import com.newrelic.api.agent.weaver.Weave; +import com.newrelic.api.agent.weaver.Weaver; +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.util.StringBuilderWriter; + +import java.io.IOException; +import java.io.Writer; + +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.BLOB_PREFIX; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; +import static com.nr.agent.instrumentation.log4j2.AgentUtil.foundIndexToInsertLinkingMetadata; +import static com.nr.agent.instrumentation.log4j2.AgentUtil.getIndexToModifyJson; + +@Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractJacksonLayout", type = MatchType.ExactClass) +abstract class AbstractJacksonLayout_Instrumentation { + + public void toSerializable(final LogEvent event, final Writer writer) throws IOException { + Weaver.callOriginal(); + } + + public String toSerializable(final LogEvent event) { + final StringBuilderWriter writer = new StringBuilderWriter(); + try { + toSerializable(event, writer); + String writerString = writer.toString(); + String modified = writerString; + // It is possible that the log might already have NR-LINKING metadata from JUL instrumentation + if (!writerString.contains(BLOB_PREFIX)) { + int indexToModifyJson = getIndexToModifyJson(writerString); + if (foundIndexToInsertLinkingMetadata(indexToModifyJson)) { + // Replace the JSON string with modified version that includes NR-LINKING metadata + modified = new StringBuilder(writerString).insert(indexToModifyJson, getLinkingMetadataBlob()).toString(); + } + } + return modified; + } catch (final IOException e) { + return Weaver.callOriginal(); + } + } + +} diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java deleted file mode 100644 index 16034ca258..0000000000 --- a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout_Instrumentation.java +++ /dev/null @@ -1,48 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package org.apache.logging.log4j.core.layout; - -import com.newrelic.api.agent.weaver.MatchType; -import com.newrelic.api.agent.weaver.Weave; -import com.newrelic.api.agent.weaver.Weaver; -import org.apache.logging.log4j.core.util.StringEncoder; - -import java.io.UnsupportedEncodingException; -import java.nio.charset.Charset; - -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.BLOB_PREFIX; -import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; - -@Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractStringLayout", type = MatchType.ExactClass) -public abstract class AbstractStringLayout_Instrumentation { - - private transient Charset charset = Weaver.callOriginal(); - private final String charsetName = Weaver.callOriginal(); - private final boolean useCustomEncoding = Weaver.callOriginal(); - - protected byte[] getBytes(final String s) { - String modified = s; - // It is possible that the log might already have NR-LINKING metadata from JUL instrumentation - if (!s.contains(BLOB_PREFIX)) { - // Finds the index of the closing parenthesis for a substring that begins with "message" and ends with the sequence ",\n - // Example JSON substring: "message":"Tomcat initialized",\n - int indexToInsertNrLinkingMetadata = s.indexOf("\",\n", s.indexOf("message")); - // Replace the JSON string with modified version that includes NR-LINKING metadata - modified = new StringBuilder(s).insert(indexToInsertNrLinkingMetadata, getLinkingMetadataBlob()).toString(); - } - if (useCustomEncoding) { - return StringEncoder.encodeSingleByteChars(modified); - } - try { - return modified.getBytes(charsetName); - } catch (final UnsupportedEncodingException e) { - return modified.getBytes(charset); - } - } - -} diff --git a/settings.gradle b/settings.gradle index dc18fdd8e7..b221ac20f7 100644 --- a/settings.gradle +++ b/settings.gradle @@ -87,7 +87,6 @@ include 'instrumentation:akka-http-core-10.0' include 'instrumentation:akka-http-core-10.2.0' include 'instrumentation:apache-log4j-1' include 'instrumentation:apache-log4j-2' -include 'instrumentation:apache-log4j-2.15' include 'instrumentation:apache-struts-2.0' include 'instrumentation:async-http-client-2.0.0' include 'instrumentation:async-http-client-2.1.0' From 75f5a7938e17e51837c3e262aaca793c6fba83d3 Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Thu, 14 Sep 2023 12:21:28 -0700 Subject: [PATCH 08/21] Add support for local decorating when using log4j2 async appenders --- .../agent/bridge/logging/AppLoggingUtils.java | 27 ++++++- .../log4j/core/LogEvent_Instrumentation.java | 80 +++++++++++++++++++ ...AbstractJacksonLayout_Instrumentation.java | 37 ++++++--- 3 files changed, 130 insertions(+), 14 deletions(-) create mode 100644 instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/LogEvent_Instrumentation.java diff --git a/agent-bridge/src/main/java/com/newrelic/agent/bridge/logging/AppLoggingUtils.java b/agent-bridge/src/main/java/com/newrelic/agent/bridge/logging/AppLoggingUtils.java index d5cbf0f474..271f651134 100644 --- a/agent-bridge/src/main/java/com/newrelic/agent/bridge/logging/AppLoggingUtils.java +++ b/agent-bridge/src/main/java/com/newrelic/agent/bridge/logging/AppLoggingUtils.java @@ -6,8 +6,6 @@ */ package com.newrelic.agent.bridge.logging; -import com.newrelic.agent.bridge.logging.LogAttributeKey; -import com.newrelic.agent.bridge.logging.LogAttributeType; import com.newrelic.api.agent.NewRelic; import java.io.UnsupportedEncodingException; @@ -54,11 +52,32 @@ public class AppLoggingUtils { * @return agent linking metadata string blob */ public static String getLinkingMetadataBlob() { - Map agentLinkingMetadata = NewRelic.getAgent().getLinkingMetadata(); + return constructLinkingMetadataBlob(NewRelic.getAgent().getLinkingMetadata()); + } + + /** + * Gets a String representing the agent linking metadata in blob format: + * NR-LINKING|entity.guid|hostname|trace.id|span.id|entity.name| + * + * @param agentLinkingMetadata map of linking metadata + * @return agent linking metadata string blob + */ + public static String getLinkingMetadataBlobFromMap(Map agentLinkingMetadata) { + return constructLinkingMetadataBlob(agentLinkingMetadata); + } + + /** + * Constructs a String representing the agent linking metadata in blob format: + * NR-LINKING|entity.guid|hostname|trace.id|span.id|entity.name| + * + * @param agentLinkingMetadata map of linking metadata + * @return agent linking metadata string blob + */ + private static String constructLinkingMetadataBlob(Map agentLinkingMetadata) { StringBuilder blob = new StringBuilder(); blob.append(" ").append(BLOB_PREFIX).append(BLOB_DELIMITER); - if (agentLinkingMetadata != null && agentLinkingMetadata.size() > 0) { + if (agentLinkingMetadata != null && !agentLinkingMetadata.isEmpty()) { appendAttributeToBlob(agentLinkingMetadata.get(ENTITY_GUID), blob); appendAttributeToBlob(agentLinkingMetadata.get(HOSTNAME), blob); appendAttributeToBlob(agentLinkingMetadata.get(TRACE_ID), blob); diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/LogEvent_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/LogEvent_Instrumentation.java new file mode 100644 index 0000000000..4c86c4b000 --- /dev/null +++ b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/LogEvent_Instrumentation.java @@ -0,0 +1,80 @@ +/* + * + * * Copyright 2023 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package org.apache.logging.log4j.core; + +import com.newrelic.api.agent.NewRelic; +import com.newrelic.api.agent.weaver.MatchType; +import com.newrelic.api.agent.weaver.NewField; +import com.newrelic.api.agent.weaver.Weave; +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.Marker; +import org.apache.logging.log4j.ThreadContext; +import org.apache.logging.log4j.core.impl.ThrowableProxy; +import org.apache.logging.log4j.core.time.Instant; +import org.apache.logging.log4j.message.Message; +import org.apache.logging.log4j.util.ReadOnlyStringMap; + +import java.util.Map; + +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingLocalDecoratingEnabled; + +@Weave(originalName = "org.apache.logging.log4j.core.LogEvent", type = MatchType.Interface) +public abstract class LogEvent_Instrumentation { + + /* + * In cases where the LogEvent is sent to an AsyncAppender, getLinkingMetadata would get called on a new thread and the trace.id and span.id + * would be missing. To work around this we save the linking metadata on the LogEvent on the thread where it was created and use it later. + */ + @NewField + public Map agentLinkingMetadata = isApplicationLoggingLocalDecoratingEnabled() ? NewRelic.getAgent().getLinkingMetadata() : null; + + public abstract LogEvent toImmutable(); + + @Deprecated + public abstract Map getContextMap(); + + public abstract ReadOnlyStringMap getContextData(); + + public abstract ThreadContext.ContextStack getContextStack(); + + public abstract String getLoggerFqcn(); + + public abstract Level getLevel(); + + public abstract String getLoggerName(); + + public abstract Marker getMarker(); + + public abstract Message getMessage(); + + public abstract long getTimeMillis(); + + public abstract Instant getInstant(); + + public abstract StackTraceElement getSource(); + + public abstract String getThreadName(); + + public abstract long getThreadId(); + + public abstract int getThreadPriority(); + + public abstract Throwable getThrown(); + + public abstract ThrowableProxy getThrownProxy(); + + public abstract boolean isEndOfBatch(); + + public abstract boolean isIncludeLocation(); + + public abstract void setEndOfBatch(boolean endOfBatch); + + public abstract void setIncludeLocation(boolean locationRequired); + + public abstract long getNanoTime(); +} diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java index d6c696b45f..0eaacfecd9 100644 --- a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java +++ b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java @@ -10,7 +10,7 @@ import com.newrelic.api.agent.weaver.MatchType; import com.newrelic.api.agent.weaver.Weave; import com.newrelic.api.agent.weaver.Weaver; -import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.LogEvent_Instrumentation; import org.apache.logging.log4j.core.util.StringBuilderWriter; import java.io.IOException; @@ -18,31 +18,48 @@ import static com.newrelic.agent.bridge.logging.AppLoggingUtils.BLOB_PREFIX; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlobFromMap; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingEnabled; +import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingLocalDecoratingEnabled; import static com.nr.agent.instrumentation.log4j2.AgentUtil.foundIndexToInsertLinkingMetadata; import static com.nr.agent.instrumentation.log4j2.AgentUtil.getIndexToModifyJson; @Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractJacksonLayout", type = MatchType.ExactClass) abstract class AbstractJacksonLayout_Instrumentation { - public void toSerializable(final LogEvent event, final Writer writer) throws IOException { + public void toSerializable(final LogEvent_Instrumentation event, final Writer writer) throws IOException { Weaver.callOriginal(); } - public String toSerializable(final LogEvent event) { + public String toSerializable(final LogEvent_Instrumentation event) { final StringBuilderWriter writer = new StringBuilderWriter(); try { toSerializable(event, writer); String writerString = writer.toString(); String modified = writerString; - // It is possible that the log might already have NR-LINKING metadata from JUL instrumentation - if (!writerString.contains(BLOB_PREFIX)) { - int indexToModifyJson = getIndexToModifyJson(writerString); - if (foundIndexToInsertLinkingMetadata(indexToModifyJson)) { - // Replace the JSON string with modified version that includes NR-LINKING metadata - modified = new StringBuilder(writerString).insert(indexToModifyJson, getLinkingMetadataBlob()).toString(); + + // Append linking metadata to the log message if local decorating is enabled + if (isApplicationLoggingEnabled() && isApplicationLoggingLocalDecoratingEnabled()) { + // It is possible that the log might already have NR-LINKING metadata from JUL instrumentation + if (!writerString.contains(BLOB_PREFIX)) { + int indexToModifyJson = getIndexToModifyJson(writerString); + if (foundIndexToInsertLinkingMetadata(indexToModifyJson)) { + // Replace the JSON string with modified version that includes NR-LINKING metadata + if (event != null && event.agentLinkingMetadata != null && (!event.agentLinkingMetadata.isEmpty())) { + // Get linking metadata stored on LogEvent if available. This ensures that + // the trace.id and span.id will be available when using an async appender. + modified = new StringBuilder(writerString).insert(indexToModifyJson, getLinkingMetadataBlobFromMap(event.agentLinkingMetadata)) + .toString(); + } else { + // Get linking metadata from current thread if it is not available on LogEvent. + modified = new StringBuilder(writerString).insert(indexToModifyJson, getLinkingMetadataBlob()).toString(); + } + } } + return modified; } - return modified; + + return writerString; } catch (final IOException e) { return Weaver.callOriginal(); } From 7a2abf8f4ae79cac4a5b4b72b1627ff8abe0b4e6 Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Thu, 14 Sep 2023 12:23:40 -0700 Subject: [PATCH 09/21] Fix comment --- .../java/com/nr/agent/instrumentation/log4j2/AgentUtil.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java b/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java index d69fdd3d18..06ab79baff 100644 --- a/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java +++ b/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java @@ -129,7 +129,7 @@ private static int calculateInitialMapSize(Map mdcPropertyMap) { } /** - * Checks a pretty and compact JSON strings for a series of characters and returns the index of + * Checks pretty or compact JSON layout strings for a series of characters and returns the index of * the characters or -1 if they were not found. This is used to find the log "message" substring * so that the NR-LINKING metadata blob can be inserted when using local decorating with JsonLayout. * From 92e753ef98ba949964c0184aa9af619b77c55070 Mon Sep 17 00:00:00 2001 From: Saxon D'Aubin Date: Fri, 15 Sep 2023 07:33:44 -0700 Subject: [PATCH 10/21] Add database and external span attributes to correlate to metric data --- .../service/analytics/SpanEventFactory.java | 41 ++++++++++++------- .../analytics/SpanEventFactoryTest.java | 18 +++++++- .../analytics/SpanEventsServiceTest.java | 2 +- 3 files changed, 43 insertions(+), 18 deletions(-) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java index 42423a2942..8a743a6875 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java @@ -132,12 +132,6 @@ public SpanEventFactory putAllUserAttributes(Map userAttributes) { return this; } - public SpanEventFactory putAllUserAttributesIfAbsent(Map userAttributes) { - builder.putAllUserAttributesIfAbsent(filter.filterUserAttributes(appName, userAttributes)); - return this; - } - - public SpanEventFactory putAgentAttribute(String key, Object value) { builder.putAgentAttribute(key, value); return this; @@ -181,6 +175,10 @@ public SpanEventFactory setUri(URI uri) { final URI sanitizedURI = ExternalsUtil.sanitizeURI(uri); if (sanitizedURI != null) { builder.putAgentAttribute("http.url", sanitizedURI.toString()); + setServerAddress(sanitizedURI.getHost()); + if (sanitizedURI.getPort() > 0) { + setServerPort(sanitizedURI.getPort()); + } } } return this; @@ -221,13 +219,7 @@ public SpanEventFactory setDatabaseName(String databaseName) { // datastore parameter public SpanEventFactory setDatastoreComponent(String component) { - builder.putIntrinsic("component", component); - return this; - } - - // datastore parameter - public SpanEventFactory setHostName(String host) { - builder.putIntrinsic("peer.hostname", host); + builder.putIntrinsic("db.system", component); return this; } @@ -240,6 +232,16 @@ public SpanEventFactory setAddress(String hostName, String portPathOrId) { return this; } + public SpanEventFactory setServerAddress(String host) { + builder.putAgentAttribute("server.address", host); + return this; + } + + public SpanEventFactory setServerPort(int port) { + builder.putAgentAttribute("server.port", port); + return this; + } + // datastore parameter public SpanEventFactory setDatabaseStatement(String query) { if (query != null) { @@ -250,7 +252,12 @@ public SpanEventFactory setDatabaseStatement(String query) { // datastore parameter private SpanEventFactory setDatabaseCollection(String collection) { - builder.putIntrinsic("db.collection", collection); + builder.putIntrinsic("db.sql.table", collection); + return this; + } + + private SpanEventFactory setDatabaseOperation(String operation) { + builder.putIntrinsic("db.operation", operation); return this; } @@ -331,8 +338,12 @@ public SpanEventFactory setExternalParameterAttributes(ExternalParameters parame setDatastoreComponent(datastoreParameters.getProduct()); setDatabaseName(datastoreParameters.getDatabaseName()); setDatabaseCollection(datastoreParameters.getCollection()); - setHostName(datastoreParameters.getHost()); + setDatabaseOperation(datastoreParameters.getOperation()); + setServerAddress(datastoreParameters.getHost()); setKindFromUserAttributes(); + if (datastoreParameters.getPort() != null) { + setServerPort(datastoreParameters.getPort()); + } if (datastoreParameters instanceof SlowQueryDatastoreParameters) { SlowQueryDatastoreParameters queryDatastoreParameters = (SlowQueryDatastoreParameters) datastoreParameters; setDatabaseStatement(determineObfuscationLevel(queryDatastoreParameters)); diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java index fcdff75b3d..76e6602674 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java @@ -50,13 +50,16 @@ public void uriShouldBeSet() { SpanEvent target = spanEventFactory.setUri(URI.create("https://newrelic.com")).build(); assertEquals("https://newrelic.com", target.getAgentAttributes().get("http.url")); + assertEquals("newrelic.com", target.getAgentAttributes().get("server.address")); + assertNull(target.getAgentAttributes().get("server.port")); } @Test public void addressShouldBeSet() { - SpanEvent target = spanEventFactory.setAddress("localhost", "3306").build(); + SpanEvent target = spanEventFactory.setServerAddress("localhost").setServerPort(3306).build(); - assertEquals("localhost:3306", target.getIntrinsics().get("peer.address")); + assertEquals("localhost", target.getAgentAttributes().get("server.address")); + assertEquals(3306, target.getAgentAttributes().get("server.port")); } @Test @@ -170,10 +173,21 @@ public void shouldNotSetNullStatusText() { public void shouldSetDataStoreParameters() { DatastoreParameters mockParameters = mock(DatastoreParameters.class); when(mockParameters.getDatabaseName()).thenReturn("database name"); + when(mockParameters.getOperation()).thenReturn("select"); + when(mockParameters.getCollection()).thenReturn("users"); + when(mockParameters.getProduct()).thenReturn("MySQL"); + when(mockParameters.getHost()).thenReturn("dbserver"); + when(mockParameters.getPort()).thenReturn(3306); SpanEvent target = spanEventFactory.setExternalParameterAttributes(mockParameters).build(); assertEquals("database name", target.getIntrinsics().get("db.instance")); + assertEquals("select", target.getIntrinsics().get("db.operation")); + assertEquals("users", target.getIntrinsics().get("db.sql.table")); + assertEquals("MySQL", target.getIntrinsics().get("db.system")); + assertEquals("dbserver", target.getAgentAttributes().get("server.address")); + assertEquals("dbserver:3306", target.getIntrinsics().get("peer.address")); + assertEquals(3306, target.getAgentAttributes().get("server.port")); } @Test diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventsServiceTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventsServiceTest.java index 7343a78a6e..0ef04bf543 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventsServiceTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventsServiceTest.java @@ -125,7 +125,7 @@ public void testMaxSamplesStored() { .setDecider(true) .setPriority(1.23f) .setDurationInSeconds(1.3f) - .setHostName("yourHost") + .setServerAddress("yourHost") .setTraceId("gnisnacirema") .setGuid("globallyuniqueidentifier") .setSampled(true) From d62d679a3a100689fc670373ffc7a89c8ac6fc8e Mon Sep 17 00:00:00 2001 From: Saxon D'Aubin Date: Fri, 15 Sep 2023 11:03:31 -0700 Subject: [PATCH 11/21] Update code to match spec --- .../agent/service/analytics/SpanEventFactory.java | 13 +++++++------ .../service/analytics/SpanEventFactoryTest.java | 12 ++++++------ 2 files changed, 13 insertions(+), 12 deletions(-) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java index 8a743a6875..fc1be6f67f 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java @@ -213,13 +213,13 @@ public SpanEventFactory setHttpStatusText(String statusText) { // datastore parameter public SpanEventFactory setDatabaseName(String databaseName) { - builder.putIntrinsic("db.instance", databaseName); + builder.putAgentAttribute("db.instance", databaseName); return this; } // datastore parameter public SpanEventFactory setDatastoreComponent(String component) { - builder.putIntrinsic("db.system", component); + builder.putAgentAttribute("db.system", component); return this; } @@ -227,7 +227,7 @@ public SpanEventFactory setDatastoreComponent(String component) { public SpanEventFactory setAddress(String hostName, String portPathOrId) { if (portPathOrId != null && hostName != null) { String address = MessageFormat.format("{0}:{1}", hostName, portPathOrId); - builder.putIntrinsic("peer.address", address); + builder.putAgentAttribute("peer.address", address); } return this; } @@ -245,19 +245,20 @@ public SpanEventFactory setServerPort(int port) { // datastore parameter public SpanEventFactory setDatabaseStatement(String query) { if (query != null) { - builder.putIntrinsic("db.statement", truncateWithEllipsis(query, DB_STATEMENT_TRUNCATE_LENGTH)); + builder.putAgentAttribute("db.statement", truncateWithEllipsis(query, DB_STATEMENT_TRUNCATE_LENGTH)); } return this; } // datastore parameter private SpanEventFactory setDatabaseCollection(String collection) { - builder.putIntrinsic("db.sql.table", collection); + builder.putAgentAttribute("db.sql.table", collection); return this; } + // datastore parameter private SpanEventFactory setDatabaseOperation(String operation) { - builder.putIntrinsic("db.operation", operation); + builder.putAgentAttribute("db.operation", operation); return this; } diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java index 76e6602674..60547b06c1 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java @@ -70,7 +70,7 @@ public void shouldTruncate3KDBStatementTo2K() { SpanEvent target = spanEventFactory.setDatabaseStatement(threeKStatement).build(); assertEquals(2000, - target.getIntrinsics().get("db.statement").toString().length()); + target.getAgentAttributes().get("db.statement").toString().length()); } @Test @@ -181,13 +181,13 @@ public void shouldSetDataStoreParameters() { SpanEvent target = spanEventFactory.setExternalParameterAttributes(mockParameters).build(); - assertEquals("database name", target.getIntrinsics().get("db.instance")); - assertEquals("select", target.getIntrinsics().get("db.operation")); - assertEquals("users", target.getIntrinsics().get("db.sql.table")); - assertEquals("MySQL", target.getIntrinsics().get("db.system")); + assertEquals("database name", target.getAgentAttributes().get("db.instance")); + assertEquals("select", target.getAgentAttributes().get("db.operation")); + assertEquals("users", target.getAgentAttributes().get("db.sql.table")); + assertEquals("MySQL", target.getAgentAttributes().get("db.system")); assertEquals("dbserver", target.getAgentAttributes().get("server.address")); - assertEquals("dbserver:3306", target.getIntrinsics().get("peer.address")); assertEquals(3306, target.getAgentAttributes().get("server.port")); + assertEquals("dbserver:3306", target.getAgentAttributes().get("peer.address")); } @Test From f163ec0db3a31877986b0805f90b8560489537dc Mon Sep 17 00:00:00 2001 From: Saxon D'Aubin Date: Fri, 15 Sep 2023 11:48:03 -0700 Subject: [PATCH 12/21] Change some attributes to intrinsics --- .../service/analytics/SpanEventFactory.java | 10 +++++----- .../service/analytics/SpanEventFactoryTest.java | 16 ++++++++-------- 2 files changed, 13 insertions(+), 13 deletions(-) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java index fc1be6f67f..7e3c67ec65 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java @@ -219,7 +219,7 @@ public SpanEventFactory setDatabaseName(String databaseName) { // datastore parameter public SpanEventFactory setDatastoreComponent(String component) { - builder.putAgentAttribute("db.system", component); + builder.putIntrinsic("db.system", component); return this; } @@ -233,12 +233,12 @@ public SpanEventFactory setAddress(String hostName, String portPathOrId) { } public SpanEventFactory setServerAddress(String host) { - builder.putAgentAttribute("server.address", host); + builder.putIntrinsic("server.address", host); return this; } public SpanEventFactory setServerPort(int port) { - builder.putAgentAttribute("server.port", port); + builder.putIntrinsic("server.port", port); return this; } @@ -252,13 +252,13 @@ public SpanEventFactory setDatabaseStatement(String query) { // datastore parameter private SpanEventFactory setDatabaseCollection(String collection) { - builder.putAgentAttribute("db.sql.table", collection); + builder.putIntrinsic("db.sql.table", collection); return this; } // datastore parameter private SpanEventFactory setDatabaseOperation(String operation) { - builder.putAgentAttribute("db.operation", operation); + builder.putIntrinsic("db.operation", operation); return this; } diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java index 60547b06c1..118175b1a1 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java @@ -50,7 +50,7 @@ public void uriShouldBeSet() { SpanEvent target = spanEventFactory.setUri(URI.create("https://newrelic.com")).build(); assertEquals("https://newrelic.com", target.getAgentAttributes().get("http.url")); - assertEquals("newrelic.com", target.getAgentAttributes().get("server.address")); + assertEquals("newrelic.com", target.getIntrinsics().get("server.address")); assertNull(target.getAgentAttributes().get("server.port")); } @@ -58,8 +58,8 @@ public void uriShouldBeSet() { public void addressShouldBeSet() { SpanEvent target = spanEventFactory.setServerAddress("localhost").setServerPort(3306).build(); - assertEquals("localhost", target.getAgentAttributes().get("server.address")); - assertEquals(3306, target.getAgentAttributes().get("server.port")); + assertEquals("localhost", target.getIntrinsics().get("server.address")); + assertEquals(3306, target.getIntrinsics().get("server.port")); } @Test @@ -182,11 +182,11 @@ public void shouldSetDataStoreParameters() { SpanEvent target = spanEventFactory.setExternalParameterAttributes(mockParameters).build(); assertEquals("database name", target.getAgentAttributes().get("db.instance")); - assertEquals("select", target.getAgentAttributes().get("db.operation")); - assertEquals("users", target.getAgentAttributes().get("db.sql.table")); - assertEquals("MySQL", target.getAgentAttributes().get("db.system")); - assertEquals("dbserver", target.getAgentAttributes().get("server.address")); - assertEquals(3306, target.getAgentAttributes().get("server.port")); + assertEquals("select", target.getIntrinsics().get("db.operation")); + assertEquals("users", target.getIntrinsics().get("db.sql.table")); + assertEquals("MySQL", target.getIntrinsics().get("db.system")); + assertEquals("dbserver", target.getIntrinsics().get("server.address")); + assertEquals(3306, target.getIntrinsics().get("server.port")); assertEquals("dbserver:3306", target.getAgentAttributes().get("peer.address")); } From 97237cdf02938af0efd83f1bfab986c81ca52fb6 Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Mon, 25 Sep 2023 16:28:59 -0700 Subject: [PATCH 13/21] Address PR feedback --- .../com/nr/agent/instrumentation/log4j2/AgentUtil.java | 9 +-------- .../layout/AbstractJacksonLayout_Instrumentation.java | 4 +--- 2 files changed, 2 insertions(+), 11 deletions(-) diff --git a/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java b/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java index 06ab79baff..8b8ffdcef3 100644 --- a/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java +++ b/instrumentation/apache-log4j-2/src/main/java/com/nr/agent/instrumentation/log4j2/AgentUtil.java @@ -137,14 +137,7 @@ private static int calculateInitialMapSize(Map mdcPropertyMap) { * @return positive int if index was found, else -1 */ public static int getIndexToModifyJson(String writerString) { - int indexOfMessage = writerString.indexOf("message"); - // Pretty JSON format - int indexToModifyJson = writerString.indexOf("\",\n", indexOfMessage); - if (!foundIndexToInsertLinkingMetadata(indexToModifyJson)) { - // Compact JSON format - indexToModifyJson = writerString.indexOf("\",", indexOfMessage); - } - return indexToModifyJson; + return writerString.indexOf("\",", writerString.indexOf("message")); } /** diff --git a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java index 0eaacfecd9..d24a77cb4a 100644 --- a/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java +++ b/instrumentation/apache-log4j-2/src/main/java/org/apache/logging/log4j/core/layout/AbstractJacksonLayout_Instrumentation.java @@ -27,9 +27,7 @@ @Weave(originalName = "org.apache.logging.log4j.core.layout.AbstractJacksonLayout", type = MatchType.ExactClass) abstract class AbstractJacksonLayout_Instrumentation { - public void toSerializable(final LogEvent_Instrumentation event, final Writer writer) throws IOException { - Weaver.callOriginal(); - } + public abstract void toSerializable(final LogEvent_Instrumentation event, final Writer writer) throws IOException; public String toSerializable(final LogEvent_Instrumentation event) { final StringBuilderWriter writer = new StringBuilderWriter(); From a021241e2e5a2134e18a04b6cd90d9446aa1daa7 Mon Sep 17 00:00:00 2001 From: Saxon D'Aubin Date: Tue, 26 Sep 2023 08:05:11 -0700 Subject: [PATCH 14/21] Change attributes from intrinsic to agent --- .../service/analytics/SpanEventFactory.java | 11 +++++----- .../analytics/SpanEventFactoryTest.java | 20 ++++++++----------- 2 files changed, 13 insertions(+), 18 deletions(-) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java index 33e2b352ea..650b3b1c1a 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java @@ -223,7 +223,7 @@ public SpanEventFactory setDatabaseName(String databaseName) { // datastore parameter public SpanEventFactory setDatastoreComponent(String component) { - builder.putIntrinsic("db.system", component); + builder.putAgentAttribute("db.system", component); return this; } @@ -237,12 +237,12 @@ public SpanEventFactory setAddress(String hostName, String portPathOrId) { } public SpanEventFactory setServerAddress(String host) { - builder.putIntrinsic("server.address", host); + builder.putAgentAttribute("server.address", host); return this; } public SpanEventFactory setServerPort(int port) { - builder.putIntrinsic("server.port", port); + builder.putAgentAttribute("server.port", port); return this; } @@ -256,13 +256,13 @@ public SpanEventFactory setDatabaseStatement(String query) { // datastore parameter private SpanEventFactory setDatabaseCollection(String collection) { - builder.putIntrinsic("db.sql.table", collection); + builder.putAgentAttribute("db.sql.table", collection); return this; } // datastore parameter private SpanEventFactory setDatabaseOperation(String operation) { - builder.putIntrinsic("db.operation", operation); + builder.putAgentAttribute("db.operation", operation); return this; } @@ -380,4 +380,3 @@ public SpanEvent build() { return builder.build(); } } - diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java index 1b865fb389..2df0c623a4 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java @@ -53,7 +53,7 @@ public void uriShouldBeSet() { SpanEvent target = spanEventFactory.setUri(URI.create("https://newrelic.com")).build(); assertEquals("https://newrelic.com", target.getAgentAttributes().get("http.url")); - assertEquals("newrelic.com", target.getIntrinsics().get("server.address")); + assertEquals("newrelic.com", target.getAgentAttributes().get("server.address")); assertNull(target.getAgentAttributes().get("server.port")); } @@ -61,8 +61,8 @@ public void uriShouldBeSet() { public void addressShouldBeSet() { SpanEvent target = spanEventFactory.setServerAddress("localhost").setServerPort(3306).build(); - assertEquals("localhost", target.getIntrinsics().get("server.address")); - assertEquals(3306, target.getIntrinsics().get("server.port")); + assertEquals("localhost", target.getAgentAttributes().get("server.address")); + assertEquals(3306, target.getAgentAttributes().get("server.port")); } @Test @@ -185,11 +185,11 @@ public void shouldSetDataStoreParameters() { SpanEvent target = spanEventFactory.setExternalParameterAttributes(mockParameters).build(); assertEquals("database name", target.getAgentAttributes().get("db.instance")); - assertEquals("select", target.getIntrinsics().get("db.operation")); - assertEquals("users", target.getIntrinsics().get("db.sql.table")); - assertEquals("MySQL", target.getIntrinsics().get("db.system")); - assertEquals("dbserver", target.getIntrinsics().get("server.address")); - assertEquals(3306, target.getIntrinsics().get("server.port")); + assertEquals("select", target.getAgentAttributes().get("db.operation")); + assertEquals("users", target.getAgentAttributes().get("db.sql.table")); + assertEquals("MySQL", target.getAgentAttributes().get("db.system")); + assertEquals("dbserver", target.getAgentAttributes().get("server.address")); + assertEquals(3306, target.getAgentAttributes().get("server.port")); assertEquals("dbserver:3306", target.getAgentAttributes().get("peer.address")); } @@ -255,7 +255,3 @@ public boolean shouldIncludeAgentAttribute(String appName, String attributeName) } } } - - - - From 94ef48c4c7cb2be209726b1d532d9e65f99b9dcb Mon Sep 17 00:00:00 2001 From: Saxon D'Aubin Date: Tue, 26 Sep 2023 14:09:07 -0700 Subject: [PATCH 15/21] Add peer.hostname attribute back, fix tests --- .../service/analytics/SpanEventFactory.java | 1 + .../analytics/SpanEventFactoryTest.java | 3 ++ .../tracers/DefaultSqlTracerClmTest.java | 35 ++++++++++--------- .../agent/tracers/DefaultSqlTracerTest.java | 34 +++++++++--------- .../agent/tracers/DefaultTracerClmTest.java | 16 ++++----- .../agent/tracers/DefaultTracerTest.java | 16 ++++----- 6 files changed, 55 insertions(+), 50 deletions(-) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java index 650b3b1c1a..00c1b6b37d 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java @@ -238,6 +238,7 @@ public SpanEventFactory setAddress(String hostName, String portPathOrId) { public SpanEventFactory setServerAddress(String host) { builder.putAgentAttribute("server.address", host); + builder.putAgentAttribute("peer.hostname", host); return this; } diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java index 2df0c623a4..1e0f17b636 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java @@ -54,6 +54,7 @@ public void uriShouldBeSet() { assertEquals("https://newrelic.com", target.getAgentAttributes().get("http.url")); assertEquals("newrelic.com", target.getAgentAttributes().get("server.address")); + assertEquals("newrelic.com", target.getAgentAttributes().get("peer.hostname")); assertNull(target.getAgentAttributes().get("server.port")); } @@ -62,6 +63,7 @@ public void addressShouldBeSet() { SpanEvent target = spanEventFactory.setServerAddress("localhost").setServerPort(3306).build(); assertEquals("localhost", target.getAgentAttributes().get("server.address")); + assertEquals("localhost", target.getAgentAttributes().get("peer.hostname")); assertEquals(3306, target.getAgentAttributes().get("server.port")); } @@ -188,6 +190,7 @@ public void shouldSetDataStoreParameters() { assertEquals("select", target.getAgentAttributes().get("db.operation")); assertEquals("users", target.getAgentAttributes().get("db.sql.table")); assertEquals("MySQL", target.getAgentAttributes().get("db.system")); + assertEquals("dbserver", target.getAgentAttributes().get("peer.hostname")); assertEquals("dbserver", target.getAgentAttributes().get("server.address")); assertEquals(3306, target.getAgentAttributes().get("server.port")); assertEquals("dbserver:3306", target.getAgentAttributes().get("peer.address")); diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerClmTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerClmTest.java index b15658a0a4..a7f8f50649 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerClmTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerClmTest.java @@ -465,11 +465,11 @@ public void testSpanEventDatastore() throws SQLException { assertNotNull(spanEvent); assertEquals("datastore", spanEvent.getIntrinsics().get("category")); - assertEquals("MySQL", spanEvent.getIntrinsics().get("component")); - assertEquals("dbserver.nerd.us", spanEvent.getIntrinsics().get("peer.hostname")); - assertEquals("dbserver.nerd.us:9945", spanEvent.getIntrinsics().get("peer.address")); - assertEquals("SELECT price, name FROM BOOKS WHERE price <= 79.99", spanEvent.getIntrinsics().get("db.statement")); - assertEquals("books", spanEvent.getIntrinsics().get("db.collection")); + assertEquals("MySQL", spanEvent.getAgentAttributes().get("db.system")); + assertEquals("dbserver.nerd.us", spanEvent.getAgentAttributes().get("peer.hostname")); + assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); + assertEquals("SELECT price, name FROM BOOKS WHERE price <= 79.99", spanEvent.getAgentAttributes().get("db.statement")); + assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); @@ -500,12 +500,12 @@ public void testSpanEventDatastoreTruncation() throws SQLException { assertNotNull(spanEvent); assertEquals("datastore", spanEvent.getIntrinsics().get("category")); - assertEquals("MySQL", spanEvent.getIntrinsics().get("component")); - assertEquals("dbserver.nerd.us", spanEvent.getIntrinsics().get("peer.hostname")); - assertEquals("dbserver.nerd.us:9945", spanEvent.getIntrinsics().get("peer.address")); - assertEquals(2000, spanEvent.getIntrinsics().get("db.statement").toString().length()); - assertTrue(spanEvent.getIntrinsics().get("db.statement").toString().endsWith("a...")); - assertEquals("books", spanEvent.getIntrinsics().get("db.collection")); + assertEquals("MySQL", spanEvent.getAgentAttributes().get("db.system")); + assertEquals("dbserver.nerd.us", spanEvent.getAgentAttributes().get("peer.hostname")); + assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); + assertEquals(2000, spanEvent.getAgentAttributes().get("db.statement").toString().length()); + assertTrue(spanEvent.getAgentAttributes().get("db.statement").toString().endsWith("a...")); + assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); @@ -536,12 +536,13 @@ public void testSpanEventDatastoreTruncationAtExactLimit() throws SQLException { assertNotNull(spanEvent); assertEquals("datastore", spanEvent.getIntrinsics().get("category")); - assertEquals("MySQL", spanEvent.getIntrinsics().get("component")); - assertEquals("dbserver.nerd.us", spanEvent.getIntrinsics().get("peer.hostname")); - assertEquals("dbserver.nerd.us:9945", spanEvent.getIntrinsics().get("peer.address")); - assertEquals(2000, spanEvent.getIntrinsics().get("db.statement").toString().length()); - assertTrue(spanEvent.getIntrinsics().get("db.statement").toString().endsWith("aaa")); // Should not end with ... since it's exactly at the limit - assertEquals("books", spanEvent.getIntrinsics().get("db.collection")); + assertEquals("MySQL", spanEvent.getAgentAttributes().get("db.system")); + assertEquals("dbserver.nerd.us", spanEvent.getAgentAttributes().get("peer.hostname")); + assertEquals("dbserver.nerd.us", spanEvent.getAgentAttributes().get("server.address")); + assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); + assertEquals(2000, spanEvent.getAgentAttributes().get("db.statement").toString().length()); + assertTrue(spanEvent.getAgentAttributes().get("db.statement").toString().endsWith("aaa")); // Should not end with ... since it's exactly at the limit + assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerTest.java index 45dd239317..20bdfcf221 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerTest.java @@ -638,11 +638,11 @@ public void testSpanEventDatastore() throws SQLException { assertNotNull(spanEvent); assertEquals("datastore", spanEvent.getIntrinsics().get("category")); - assertEquals("MySQL", spanEvent.getIntrinsics().get("component")); - assertEquals("dbserver.nerd.us", spanEvent.getIntrinsics().get("peer.hostname")); - assertEquals("dbserver.nerd.us:9945", spanEvent.getIntrinsics().get("peer.address")); - assertEquals("SELECT price, name FROM BOOKS WHERE price <= 79.99", spanEvent.getIntrinsics().get("db.statement")); - assertEquals("books", spanEvent.getIntrinsics().get("db.collection")); + assertEquals("MySQL", spanEvent.getAgentAttributes().get("db.system")); + assertEquals("dbserver.nerd.us", spanEvent.getAgentAttributes().get("peer.hostname")); + assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); + assertEquals("SELECT price, name FROM BOOKS WHERE price <= 79.99", spanEvent.getAgentAttributes().get("db.statement")); + assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); @@ -673,12 +673,12 @@ public void testSpanEventDatastoreTruncation() throws SQLException { assertNotNull(spanEvent); assertEquals("datastore", spanEvent.getIntrinsics().get("category")); - assertEquals("MySQL", spanEvent.getIntrinsics().get("component")); - assertEquals("dbserver.nerd.us", spanEvent.getIntrinsics().get("peer.hostname")); - assertEquals("dbserver.nerd.us:9945", spanEvent.getIntrinsics().get("peer.address")); - assertEquals(2000, spanEvent.getIntrinsics().get("db.statement").toString().length()); - assertTrue(spanEvent.getIntrinsics().get("db.statement").toString().endsWith("a...")); - assertEquals("books", spanEvent.getIntrinsics().get("db.collection")); + assertEquals("MySQL", spanEvent.getAgentAttributes().get("db.system")); + assertEquals("dbserver.nerd.us", spanEvent.getAgentAttributes().get("peer.hostname")); + assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); + assertEquals(2000, spanEvent.getAgentAttributes().get("db.statement").toString().length()); + assertTrue(spanEvent.getAgentAttributes().get("db.statement").toString().endsWith("a...")); + assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); @@ -709,12 +709,12 @@ public void testSpanEventDatastoreTruncationAtExactLimit() throws SQLException { assertNotNull(spanEvent); assertEquals("datastore", spanEvent.getIntrinsics().get("category")); - assertEquals("MySQL", spanEvent.getIntrinsics().get("component")); - assertEquals("dbserver.nerd.us", spanEvent.getIntrinsics().get("peer.hostname")); - assertEquals("dbserver.nerd.us:9945", spanEvent.getIntrinsics().get("peer.address")); - assertEquals(2000, spanEvent.getIntrinsics().get("db.statement").toString().length()); - assertTrue(spanEvent.getIntrinsics().get("db.statement").toString().endsWith("aaa")); // Should not end with ... since it's exactly at the limit - assertEquals("books", spanEvent.getIntrinsics().get("db.collection")); + assertEquals("MySQL", spanEvent.getAgentAttributes().get("db.system")); + assertEquals("dbserver.nerd.us", spanEvent.getAgentAttributes().get("peer.hostname")); + assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); + assertEquals(2000, spanEvent.getAgentAttributes().get("db.statement").toString().length()); + assertTrue(spanEvent.getAgentAttributes().get("db.statement").toString().endsWith("aaa")); // Should not end with ... since it's exactly at the limit + assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultTracerClmTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultTracerClmTest.java index 4b53bbac29..5365cc7675 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultTracerClmTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultTracerClmTest.java @@ -687,10 +687,10 @@ public void testSpanEventDatastore() { assertNotNull(spanEvent); assertNull(spanEvent.getParentId()); - assertEquals("YourSQL", spanEvent.getIntrinsics().get("component")); - assertEquals("databaseServer", spanEvent.getIntrinsics().get("peer.hostname")); - assertEquals("dbName", spanEvent.getIntrinsics().get("db.instance")); - assertEquals("databaseServer:1234", spanEvent.getIntrinsics().get("peer.address")); + assertEquals("YourSQL", spanEvent.getAgentAttributes().get("db.system")); + assertEquals("databaseServer", spanEvent.getAgentAttributes().get("peer.hostname")); + assertEquals("dbName", spanEvent.getAgentAttributes().get("db.instance")); + assertEquals("databaseServer:1234", spanEvent.getAgentAttributes().get("peer.address")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertClm(tracer, spanEvent); } @@ -829,10 +829,10 @@ public void testParent() { assertEquals(rootSpan.getGuid(), siblingSpan.getParentId()); assertNull(siblingSpan.getIntrinsics().get("nr.entryPoint")); - assertEquals("YourSQL", child2Span.getIntrinsics().get("component")); - assertEquals("databaseServer", child2Span.getIntrinsics().get("peer.hostname")); - assertEquals("dbName", child2Span.getIntrinsics().get("db.instance")); - assertEquals("databaseServer:1234", child2Span.getIntrinsics().get("peer.address")); + assertEquals("YourSQL", child2Span.getAgentAttributes().get("db.system")); + assertEquals("databaseServer", child2Span.getAgentAttributes().get("peer.hostname")); + assertEquals("dbName", child2Span.getAgentAttributes().get("db.instance")); + assertEquals("databaseServer:1234", child2Span.getAgentAttributes().get("peer.address")); assertEquals("client", child2Span.getIntrinsics().get("span.kind")); assertEquals("library", siblingSpan.getIntrinsics().get("component")); diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultTracerTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultTracerTest.java index e361b46f38..f9ad55a733 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultTracerTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultTracerTest.java @@ -717,10 +717,10 @@ public void testSpanEventDatastore() { assertNotNull(spanEvent); assertNull(spanEvent.getParentId()); - assertEquals("YourSQL", spanEvent.getIntrinsics().get("component")); - assertEquals("databaseServer", spanEvent.getIntrinsics().get("peer.hostname")); - assertEquals("dbName", spanEvent.getIntrinsics().get("db.instance")); - assertEquals("databaseServer:1234", spanEvent.getIntrinsics().get("peer.address")); + assertEquals("YourSQL", spanEvent.getAgentAttributes().get("db.system")); + assertEquals("databaseServer", spanEvent.getAgentAttributes().get("peer.hostname")); + assertEquals("dbName", spanEvent.getAgentAttributes().get("db.instance")); + assertEquals("databaseServer:1234", spanEvent.getAgentAttributes().get("peer.address")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertClmAbsent(spanEvent); } @@ -860,10 +860,10 @@ public void testParent() { assertEquals(rootSpan.getGuid(), siblingSpan.getParentId()); assertNull(siblingSpan.getIntrinsics().get("nr.entryPoint")); - assertEquals("YourSQL", child2Span.getIntrinsics().get("component")); - assertEquals("databaseServer", child2Span.getIntrinsics().get("peer.hostname")); - assertEquals("dbName", child2Span.getIntrinsics().get("db.instance")); - assertEquals("databaseServer:1234", child2Span.getIntrinsics().get("peer.address")); + assertEquals("YourSQL", child2Span.getAgentAttributes().get("db.system")); + assertEquals("databaseServer", child2Span.getAgentAttributes().get("peer.hostname")); + assertEquals("dbName", child2Span.getAgentAttributes().get("db.instance")); + assertEquals("databaseServer:1234", child2Span.getAgentAttributes().get("peer.address")); assertEquals("client", child2Span.getIntrinsics().get("span.kind")); assertEquals("library", siblingSpan.getIntrinsics().get("component")); From 2912d541b1bfb2e8e960c76d6055a3fa1605c27d Mon Sep 17 00:00:00 2001 From: Saxon D'Aubin Date: Tue, 26 Sep 2023 15:43:11 -0700 Subject: [PATCH 16/21] Use db.collection instead of db.sql.table --- .../newrelic/agent/service/analytics/SpanEventFactory.java | 2 +- .../agent/service/analytics/SpanEventFactoryTest.java | 2 +- .../com/newrelic/agent/tracers/DefaultSqlTracerClmTest.java | 6 +++--- .../com/newrelic/agent/tracers/DefaultSqlTracerTest.java | 6 +++--- 4 files changed, 8 insertions(+), 8 deletions(-) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java index 00c1b6b37d..d292e69849 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/analytics/SpanEventFactory.java @@ -257,7 +257,7 @@ public SpanEventFactory setDatabaseStatement(String query) { // datastore parameter private SpanEventFactory setDatabaseCollection(String collection) { - builder.putAgentAttribute("db.sql.table", collection); + builder.putAgentAttribute("db.collection", collection); return this; } diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java index 1e0f17b636..d1b17269df 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/service/analytics/SpanEventFactoryTest.java @@ -188,7 +188,7 @@ public void shouldSetDataStoreParameters() { assertEquals("database name", target.getAgentAttributes().get("db.instance")); assertEquals("select", target.getAgentAttributes().get("db.operation")); - assertEquals("users", target.getAgentAttributes().get("db.sql.table")); + assertEquals("users", target.getAgentAttributes().get("db.collection")); assertEquals("MySQL", target.getAgentAttributes().get("db.system")); assertEquals("dbserver", target.getAgentAttributes().get("peer.hostname")); assertEquals("dbserver", target.getAgentAttributes().get("server.address")); diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerClmTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerClmTest.java index a7f8f50649..c47458fe77 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerClmTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerClmTest.java @@ -469,7 +469,7 @@ public void testSpanEventDatastore() throws SQLException { assertEquals("dbserver.nerd.us", spanEvent.getAgentAttributes().get("peer.hostname")); assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); assertEquals("SELECT price, name FROM BOOKS WHERE price <= 79.99", spanEvent.getAgentAttributes().get("db.statement")); - assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); + assertEquals("books", spanEvent.getAgentAttributes().get("db.collection")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); @@ -505,7 +505,7 @@ public void testSpanEventDatastoreTruncation() throws SQLException { assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); assertEquals(2000, spanEvent.getAgentAttributes().get("db.statement").toString().length()); assertTrue(spanEvent.getAgentAttributes().get("db.statement").toString().endsWith("a...")); - assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); + assertEquals("books", spanEvent.getAgentAttributes().get("db.collection")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); @@ -542,7 +542,7 @@ public void testSpanEventDatastoreTruncationAtExactLimit() throws SQLException { assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); assertEquals(2000, spanEvent.getAgentAttributes().get("db.statement").toString().length()); assertTrue(spanEvent.getAgentAttributes().get("db.statement").toString().endsWith("aaa")); // Should not end with ... since it's exactly at the limit - assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); + assertEquals("books", spanEvent.getAgentAttributes().get("db.collection")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerTest.java index 20bdfcf221..4e497e1bb0 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/tracers/DefaultSqlTracerTest.java @@ -642,7 +642,7 @@ public void testSpanEventDatastore() throws SQLException { assertEquals("dbserver.nerd.us", spanEvent.getAgentAttributes().get("peer.hostname")); assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); assertEquals("SELECT price, name FROM BOOKS WHERE price <= 79.99", spanEvent.getAgentAttributes().get("db.statement")); - assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); + assertEquals("books", spanEvent.getAgentAttributes().get("db.collection")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); @@ -678,7 +678,7 @@ public void testSpanEventDatastoreTruncation() throws SQLException { assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); assertEquals(2000, spanEvent.getAgentAttributes().get("db.statement").toString().length()); assertTrue(spanEvent.getAgentAttributes().get("db.statement").toString().endsWith("a...")); - assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); + assertEquals("books", spanEvent.getAgentAttributes().get("db.collection")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); @@ -714,7 +714,7 @@ public void testSpanEventDatastoreTruncationAtExactLimit() throws SQLException { assertEquals("dbserver.nerd.us:9945", spanEvent.getAgentAttributes().get("peer.address")); assertEquals(2000, spanEvent.getAgentAttributes().get("db.statement").toString().length()); assertTrue(spanEvent.getAgentAttributes().get("db.statement").toString().endsWith("aaa")); // Should not end with ... since it's exactly at the limit - assertEquals("books", spanEvent.getAgentAttributes().get("db.sql.table")); + assertEquals("books", spanEvent.getAgentAttributes().get("db.collection")); assertEquals("client", spanEvent.getIntrinsics().get("span.kind")); assertEquals("Datastore/statement/MySQL/books/select", spanEvent.getName()); assertNotNull(spanEvent.getTraceId()); From 7057e595e394912ead7a993849f634fa685246b2 Mon Sep 17 00:00:00 2001 From: Jerry Duffy Date: Thu, 5 Oct 2023 11:42:43 -0400 Subject: [PATCH 17/21] Check for Spring6 specific servlet attribute for advice-handled exception --- .../tomcat10/TomcatServletRequestListener.java | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/instrumentation/tomcat-10/src/main/java/com/nr/agent/instrumentation/tomcat10/TomcatServletRequestListener.java b/instrumentation/tomcat-10/src/main/java/com/nr/agent/instrumentation/tomcat10/TomcatServletRequestListener.java index a6073590ec..35fb47a70e 100644 --- a/instrumentation/tomcat-10/src/main/java/com/nr/agent/instrumentation/tomcat10/TomcatServletRequestListener.java +++ b/instrumentation/tomcat-10/src/main/java/com/nr/agent/instrumentation/tomcat10/TomcatServletRequestListener.java @@ -21,7 +21,8 @@ public final class TomcatServletRequestListener implements ServletRequestListener { - private static final String EXCEPTION_ATTRIBUTE_NAME = "jakarta.servlet.error.exception"; + private static final String SERVLET_EXCEPTION_ATTRIBUTE_NAME = "jakarta.servlet.error.exception"; + private static final String SPRING6_SERVLET_EXCEPTION_ATTRIBUTE_NAME = "org.springframework.web.servlet.DispatcherServlet.EXCEPTION"; private static final String REQUEST_FIELD = "request"; private final Field requestField; @@ -44,8 +45,7 @@ private Field getRequestField() { @CatchAndLog @Override public void requestDestroyed(ServletRequestEvent sre) { - - Throwable exception = (Throwable) sre.getServletRequest().getAttribute(EXCEPTION_ATTRIBUTE_NAME); + Throwable exception = retrieveExceptionFromServlet(sre); if (exception != null) { AgentBridge.privateApi.reportException(exception); } @@ -98,4 +98,12 @@ private Request_Weaved getRequest(HttpServletRequest httpServletRequest) { } return null; } + + private Throwable retrieveExceptionFromServlet(ServletRequestEvent sre) { + //As of Spring 6, when controller advice is used for controller exception handling, the caught exception is + //now stored in the servlet attribute map with the "org.springframework.web.servlet.DispatcherServlet.EXCEPTION" key. + return (Throwable) (sre.getServletRequest().getAttribute(SERVLET_EXCEPTION_ATTRIBUTE_NAME) != null ? + sre.getServletRequest().getAttribute(SERVLET_EXCEPTION_ATTRIBUTE_NAME) : + sre.getServletRequest().getAttribute(SPRING6_SERVLET_EXCEPTION_ATTRIBUTE_NAME)); + } } \ No newline at end of file From 3de75980fbf3a67765e995bd62ec905c4c6ce8dd Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Thu, 5 Oct 2023 10:15:29 -0700 Subject: [PATCH 18/21] Add readme to jetty-9.3 instrumentation --- instrumentation/jetty-9.3/README.md | 23 +++++++++++++++++++++++ 1 file changed, 23 insertions(+) create mode 100644 instrumentation/jetty-9.3/README.md diff --git a/instrumentation/jetty-9.3/README.md b/instrumentation/jetty-9.3/README.md new file mode 100644 index 0000000000..a11720350d --- /dev/null +++ b/instrumentation/jetty-9.3/README.md @@ -0,0 +1,23 @@ +# Async Transactions With Jetty + +This describes the basic behavior of an async request made using the Jetty Continuations or +Servlet async API with Jetty as the dispatcher + + +To be clear, we do not instrument the continuations API and we have no idea if undispatch is being called, we simply keep track of state based on what Jetty is doing with the request, what the AsyncContext being passed across threads tells us, and what notifications the AsyncListener we registered gets about the result of the async operation. + +## Request Flow + +The basic flow of an async request using continuations/async servlet API and being handled by Jetty is something like this: + +1. Jetty server receives a request and its `org.eclipse.jetty.server.Server.handle` method is invoked. +2. Our Jetty instrumentation weaves `org.eclipse.jetty.server.Server.handle` and calls into our `ServerHelper.preHandle` method where we start a `Transaction`, set the dispatcher, record the request initialized, create tracers, etc. +3. `org.eclipse.jetty.server.Request.startAsync` is then called by Jetty, which is another class that we instrument. This is where we register our `AsyncListener` with the `AsyncContext`. In Jetty the `AsyncContext` is an instance of `org.eclipse.jetty.server.AsyncContextState`, this is what allows us to manage transaction state across threads. +4. Execution returns back to `org.eclipse.jetty.server.Server.handle` and calls into our `ServerHelper.postHandle` method. If an async request was started we call `suspendAsync` on our `AsyncApiImpl`. We create an instance of `ServletAsyncTransactionStateImpl` and store it on the transaction. This is used to handle Servlet 3.0 and Jetty Continuations asynchronous processing state changes and manage the transaction instance across threads. We set the state to `SUSPENDING` and store the `Transaction` in the `asyncTransactions` map on `AsyncApiImpl`. We record the request as destroyed. +5. ------ The thread is released and eventually the async work is dispatched to a new Jetty thread ------ +6. Our `ServerHelper.preHandle` method is hit on the new thread, but this time it detects that the request is from `DispatcherType.ASYNC` and instead of creating a `Transaction` we call `resumeAsync` on our `AsyncApiImpl`. We get the suspended transaction from the `asyncTransactions` map and resume it, setting it as the current transaction on the new thread (storing it in the `ThreadLocal`) and changing the state from `SUSPENDING` to `RESUMING`. We verify that the transaction is active and if successful we change the state from `RESUMING` to `RUNNING`. We wrap the `Transaction` as a `BoundTransactionApiImpl` for reasons related to legacy async instrumentation. +7. We hit our `ServerHelper.postHandle` method again, this time on the new thread. We call `suspendAsync` on our `AsyncApiImpl` again but this time it doesn't really do much of anything as we already have an instance of `ServletAsyncTransactionStateImpl`. The state changes from `RUNNING` to `SUSPENDING` but it doesn't seem to actually matter at this point though. The transaction is already stored in the `asyncTransactions` map, so it doesn't get added again, even though we try. +8. At this point, we don’t have any way to know what the result on the async work was until the `AsyncListener` we register gets notified via one of the `onComplete`, `onError`, or `onTimeout` methods. + * If `onComplete` is called on the `AsyncListener` it will result in a call to `completeAsync` on our `AsyncApiImpl`. This will remove the transaction from the `asyncTransactions` map and complete the transaction. + * If `onError` is called on the `AsyncListener` it will result in a call to `errorAsync` on our `AsyncApiImpl`. This sets the `Throwable` on the `Transaction`. It doesn't seem to clear the stored transaction from the map on `AsyncApiImpl` though. + * If `onTimeout` is called on the `AsyncListener` it will result in a NoOp as we take no action. \ No newline at end of file From 6ddb6727c21bd82fdb3276808e01a1822d50798a Mon Sep 17 00:00:00 2001 From: jasonjkeller Date: Thu, 5 Oct 2023 10:45:50 -0700 Subject: [PATCH 19/21] Update readme --- instrumentation/jetty-9.3/README.md | 3 --- 1 file changed, 3 deletions(-) diff --git a/instrumentation/jetty-9.3/README.md b/instrumentation/jetty-9.3/README.md index a11720350d..31562a22df 100644 --- a/instrumentation/jetty-9.3/README.md +++ b/instrumentation/jetty-9.3/README.md @@ -3,9 +3,6 @@ This describes the basic behavior of an async request made using the Jetty Continuations or Servlet async API with Jetty as the dispatcher - -To be clear, we do not instrument the continuations API and we have no idea if undispatch is being called, we simply keep track of state based on what Jetty is doing with the request, what the AsyncContext being passed across threads tells us, and what notifications the AsyncListener we registered gets about the result of the async operation. - ## Request Flow The basic flow of an async request using continuations/async servlet API and being handled by Jetty is something like this: From acdee645ef78ea95b1893c7d6f5227649013cf59 Mon Sep 17 00:00:00 2001 From: Enriqueta De Leon Date: Fri, 6 Oct 2023 14:46:02 -0700 Subject: [PATCH 20/21] add s12y metrics for setUserId API call (#1540) --- .../src/main/java/com/newrelic/agent/MetricNames.java | 2 ++ .../newrelic/api/agent/NewRelicApiImplementation.java | 1 + .../api/agent/NewRelicApiImplementationTest.java | 11 +++++++++++ 3 files changed, 14 insertions(+) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/MetricNames.java b/newrelic-agent/src/main/java/com/newrelic/agent/MetricNames.java index 9a5314c588..f37def43fc 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/MetricNames.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/MetricNames.java @@ -359,6 +359,7 @@ public class MetricNames { public static final String SUPPORTABILITY_API_SET_SERVER_INFO = "SetServerInfo"; public static final String SUPPORTABILITY_API_SET_USER_NAME = "SetUserName"; public static final String SUPPORTABILITY_API_SET_ACCOUNT_NAME = "SetAccountName"; + public static final String SUPPORTABILITY_API_SET_USER_ID = "SetUserId"; //Transaction supportability metrics public static final String SUPPORTABILITY_TRANSACTION_STARTED = "Supportability/Transaction/StartedCount"; @@ -492,6 +493,7 @@ public class MetricNames { public static final String SUPPORTABILITY_ERROR_GROUPING_CALLBACK_ENABLED = "Supportability/ErrorGrouping/Callback/enabled"; public static final String SUPPORTABILITY_ERROR_GROUPING_CALLBACK_EXECUTION_TIME = "Supportability/ErrorGrouping/Callback/ExecutionTime"; + /** * Utility method for adding supportability metrics to APIs * diff --git a/newrelic-agent/src/main/java/com/newrelic/api/agent/NewRelicApiImplementation.java b/newrelic-agent/src/main/java/com/newrelic/api/agent/NewRelicApiImplementation.java index 62b3984de0..f88a12169a 100644 --- a/newrelic-agent/src/main/java/com/newrelic/api/agent/NewRelicApiImplementation.java +++ b/newrelic-agent/src/main/java/com/newrelic/api/agent/NewRelicApiImplementation.java @@ -298,6 +298,7 @@ public void addCustomParameters(Map params) { */ @Override public void setUserId(String userId) { + MetricNames.recordApiSupportabilityMetric(MetricNames.SUPPORTABILITY_API_SET_USER_ID); if (ServiceFactory.getConfigService().getDefaultAgentConfig().isHighSecurity()) { return; } diff --git a/newrelic-agent/src/test/java/com/newrelic/api/agent/NewRelicApiImplementationTest.java b/newrelic-agent/src/test/java/com/newrelic/api/agent/NewRelicApiImplementationTest.java index 3acc1ed2ac..bb05b2813d 100644 --- a/newrelic-agent/src/test/java/com/newrelic/api/agent/NewRelicApiImplementationTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/api/agent/NewRelicApiImplementationTest.java @@ -446,6 +446,17 @@ public void setInstanceName_recordsSupportabilityMetric() { } } + @Test + public void setUserId_recordsSupportabilityMetric() { + mockOutServices(); + NewRelicApiImplementation target = new NewRelicApiImplementation(); + + try(MockedStatic mockMetricNames = Mockito.mockStatic(MetricNames.class)) { + target.setUserId("instance"); + mockMetricNames.verify(() -> MetricNames.recordApiSupportabilityMetric(MetricNames.SUPPORTABILITY_API_SET_USER_ID)); + } + } + @Test public void setErrorGroupCallback_setsCallback() { mockOutServices(); From 5f6995fb8906f9e7c6ea24b81f5dafea23bc9e43 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Andr=C3=A9=20Onuki?= Date: Mon, 9 Oct 2023 12:48:58 -0400 Subject: [PATCH 21/21] Changing HttpUrlConnection instr to not rely on segment/cleanup thread (#1537) --- .../pointcuts/net/HttpURLConnectionTest.java | 69 +++- .../newrelic/test/agent/HttpCommonsTest.java | 6 +- instrumentation/httpurlconnection/README.md | 141 ++----- .../DefaultThreadFactory.java | 42 --- .../httpurlconnection/GuidSwapper.java | 103 ++++++ .../HttpURLConnectionConfig.java | 28 -- .../httpurlconnection/MetricState.java | 349 ++++++------------ .../main/java/java/net/HttpURLConnection.java | 51 ++- .../httpurlconnection/ConnectTest.java | 99 +++++ ...ResponseCodeTest.java => InboundTest.java} | 146 ++++---- .../InstrumentedHttpUrlConnection.java | 68 ++++ .../MetricStateConnectTest.java | 99 ----- 12 files changed, 585 insertions(+), 616 deletions(-) delete mode 100644 instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/DefaultThreadFactory.java create mode 100644 instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/GuidSwapper.java create mode 100644 instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/ConnectTest.java rename instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/{MetricStateResponseCodeTest.java => InboundTest.java} (56%) create mode 100644 instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/InstrumentedHttpUrlConnection.java delete mode 100644 instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/MetricStateConnectTest.java diff --git a/functional_test/src/test/java/com/newrelic/agent/instrumentation/pointcuts/net/HttpURLConnectionTest.java b/functional_test/src/test/java/com/newrelic/agent/instrumentation/pointcuts/net/HttpURLConnectionTest.java index 2570983d32..a45d7d6b4a 100644 --- a/functional_test/src/test/java/com/newrelic/agent/instrumentation/pointcuts/net/HttpURLConnectionTest.java +++ b/functional_test/src/test/java/com/newrelic/agent/instrumentation/pointcuts/net/HttpURLConnectionTest.java @@ -39,6 +39,8 @@ public class HttpURLConnectionTest { static final TransactionDataList transactions = new TransactionDataList(); private static final String GET_OUTPUT_STREAM = "getOutputStream"; private static final String GET_INPUT_STREAM = "getInputStream"; + private static final String GET_RESPONSE_CODE = "getResponseCode"; + private static final String GET_RESPONSE_MSG = "getResponseMessage"; private static final String URL = "example.com"; private static final String REAL_HOST = "https://example.com"; private static final String FAKE_HOST = "http://www.thishostdoesnotexistbro.com"; // Better hope no one buys this domain... @@ -95,7 +97,7 @@ public void outputStreamFirstTest() { doOutputStreamFirstTest(); String scope = format("OtherTransaction/Custom/{0}/doOutputStreamFirstTest", TEST_CLASS); - verifyMetrics(URL, scope, true, GET_OUTPUT_STREAM); + verifyMetrics(URL, scope, false, GET_OUTPUT_STREAM); } @Trace(dispatcher = true) @@ -130,7 +132,7 @@ public void connectFirstTest() { doConnectFirstTest(); String scope = format("OtherTransaction/Custom/{0}/doConnectFirstTest", TEST_CLASS); - verifyMetrics(URL, scope, true, GET_OUTPUT_STREAM); + verifyMetrics(URL, scope, false, GET_OUTPUT_STREAM); } @Trace(dispatcher = true) @@ -255,7 +257,7 @@ public void testHttpURLConnectionMetrics3() { run3(); String scope = format("OtherTransaction/Custom/{0}/run3", TEST_CLASS); - verifyMetrics(URL, scope, true, GET_INPUT_STREAM); + verifyMetrics(URL, scope, true, GET_RESPONSE_CODE); } @Trace(dispatcher = true) @@ -330,7 +332,7 @@ public void testHttpURLConnectionMetrics6() { run6(); String scope = format("OtherTransaction/Custom/{0}/run6", TEST_CLASS); - verifyMetrics(URL, scope, true, GET_OUTPUT_STREAM); + verifyMetrics(URL, scope, false, GET_OUTPUT_STREAM); } @Trace(dispatcher = true) @@ -355,7 +357,7 @@ public void testHttpURLConnectionMetrics7() { run7(); String scope = format("OtherTransaction/Custom/{0}/run7", TEST_CLASS); - verifyMetrics(URL, scope, true, GET_OUTPUT_STREAM); + verifyMetrics(URL, scope, true, GET_RESPONSE_CODE); } @Trace(dispatcher = true) @@ -383,7 +385,7 @@ public void testHttpURLConnectionMetrics8() { run8(); String scope = format("OtherTransaction/Custom/{0}/run8", TEST_CLASS); - verifyMetrics(URL, scope, true, GET_OUTPUT_STREAM); + verifyMetrics(URL, scope, true, GET_RESPONSE_CODE); } @Trace(dispatcher = true) @@ -410,7 +412,7 @@ public void testHttpURLConnectionMetrics9() { run9(); String scope = format("OtherTransaction/Custom/{0}/run9", TEST_CLASS); - verifyMetrics(URL, scope, true, GET_INPUT_STREAM); + verifyMetrics(URL, scope, true, GET_RESPONSE_CODE); } @Trace(dispatcher = true) @@ -430,6 +432,31 @@ private void run9() { } } + @Test + public void testHttpURLConnectionMetrics10() { + run10(); + String scope = format("OtherTransaction/Custom/{0}/run10", TEST_CLASS); + + verifyMetrics(URL, scope, true, GET_RESPONSE_MSG); + } + + @Trace(dispatcher = true) + private void run10() { + HttpURLConnection connection = null; + try { + // Test 9: getResponseMessage() + connection = getHttpsExampleComConnection(); + // GETs URL and reads response message (Network I/O) + System.out.println("Response message: " + connection.getResponseMessage()); + } catch (Exception e) { + e.printStackTrace(); + } finally { + if (connection != null) { + connection.disconnect(); + } + } + } + @Test public void testUnresolvedHost() throws Exception { unresolvedHost(); @@ -475,7 +502,8 @@ private void verifyMetrics(String url, String scope, boolean reportedExternalCal Set metrics = AgentHelper.getMetrics(); // Scoped external metrics String httpURLConnectionGetInputStreamMetric = format("External/{0}/HttpURLConnection/getInputStream", url); - String httpURLConnectionGetOutputStreamMetric = format("External/{0}/HttpURLConnection/getOutputStream", url); + String httpURLConnectionGetResponseCodeMetric = format("External/{0}/HttpURLConnection/getResponseCode", url); + String httpURLConnectionGetResponseMessageMetric = format("External/{0}/HttpURLConnection/getResponseMessage", url); // Unscoped external metrics String externalHostAllMetric = format("External/{0}/all", url); String externalAllMetric = "External/all"; @@ -488,8 +516,7 @@ private void verifyMetrics(String url, String scope, boolean reportedExternalCal scopedMetricCount = 1; // One of these scoped metrics should be generated when an external call is reported Assert.assertTrue(metrics.toString(), - metrics.contains(httpURLConnectionGetOutputStreamMetric) || - metrics.contains(httpURLConnectionGetInputStreamMetric)); + metrics.contains(format("External/{0}/HttpURLConnection/" + methodInExternalMetric, url))); unscopedMetricCount = 3; // All three of these unscoped metrics should be generated when an external call is reported @@ -498,8 +525,7 @@ private void verifyMetrics(String url, String scope, boolean reportedExternalCal Assert.assertTrue(metrics.toString(), metrics.contains(externalAllOtherMetric)); } else { Assert.assertFalse(metrics.toString(), - metrics.contains(httpURLConnectionGetOutputStreamMetric) || - metrics.contains(httpURLConnectionGetInputStreamMetric)); + metrics.contains(format("External/{0}/HttpURLConnection/" + methodInExternalMetric, url))); Assert.assertFalse(metrics.toString(), metrics.contains(externalHostAllMetric)); Assert.assertFalse(metrics.toString(), metrics.contains(externalAllMetric)); @@ -507,16 +533,19 @@ private void verifyMetrics(String url, String scope, boolean reportedExternalCal } Map scopedMetricCounts = getMetricCounts( - MetricName.create(httpURLConnectionGetOutputStreamMetric, scope), - MetricName.create(httpURLConnectionGetInputStreamMetric, scope)); + MetricName.create(httpURLConnectionGetInputStreamMetric, scope), + MetricName.create(httpURLConnectionGetResponseCodeMetric, scope), + MetricName.create(httpURLConnectionGetResponseMessageMetric, scope) + ); Map unscopedMetricCounts = getMetricCounts( MetricName.create(externalHostAllMetric), MetricName.create(externalAllMetric), MetricName.create(externalAllOtherMetric)); - int actualHttpURLConnectionScopedMetricCount = scopedMetricCounts.get(httpURLConnectionGetOutputStreamMetric) + - scopedMetricCounts.get(httpURLConnectionGetInputStreamMetric); + int actualHttpURLConnectionScopedMetricCount = scopedMetricCounts.get(httpURLConnectionGetInputStreamMetric) + + scopedMetricCounts.get(httpURLConnectionGetResponseCodeMetric) + + scopedMetricCounts.get(httpURLConnectionGetResponseMessageMetric); int actualHttpURLConnectionUnscopedMetricCount = unscopedMetricCounts.get(externalHostAllMetric) + unscopedMetricCounts.get(externalAllMetric) + @@ -525,15 +554,17 @@ private void verifyMetrics(String url, String scope, boolean reportedExternalCal assertEquals(scopedMetricCount, actualHttpURLConnectionScopedMetricCount); if (scopedMetricCount == 0) { - assertEquals(0, (int) scopedMetricCounts.get(httpURLConnectionGetOutputStreamMetric)); assertEquals(0, (int) scopedMetricCounts.get(httpURLConnectionGetInputStreamMetric)); } else { if (methodInExternalMetric != null) { if (methodInExternalMetric.equals(GET_INPUT_STREAM)) { assertEquals(1, (int) scopedMetricCounts.get(httpURLConnectionGetInputStreamMetric)); } - if (methodInExternalMetric.equals(GET_OUTPUT_STREAM)) { - assertEquals(1, (int) scopedMetricCounts.get(httpURLConnectionGetOutputStreamMetric)); + if (methodInExternalMetric.equals(GET_RESPONSE_CODE)) { + assertEquals(1, (int) scopedMetricCounts.get(httpURLConnectionGetResponseCodeMetric)); + } + if (methodInExternalMetric.equals(GET_RESPONSE_MSG)) { + assertEquals(1, (int) scopedMetricCounts.get(httpURLConnectionGetResponseMessageMetric)); } } } diff --git a/functional_test/src/test/java/test/newrelic/test/agent/HttpCommonsTest.java b/functional_test/src/test/java/test/newrelic/test/agent/HttpCommonsTest.java index 75c98defdb..b60341294b 100644 --- a/functional_test/src/test/java/test/newrelic/test/agent/HttpCommonsTest.java +++ b/functional_test/src/test/java/test/newrelic/test/agent/HttpCommonsTest.java @@ -65,13 +65,13 @@ public void httpURLConnection() throws Exception { httpURLConnectionTx(); Set metrics = AgentHelper.getMetrics(); - assertTrue(metrics.toString(), metrics.contains("External/" + HOST + "/HttpURLConnection/getInputStream")); + assertTrue(metrics.toString(), metrics.contains("External/" + HOST + "/HttpURLConnection/getResponseCode")); Map metricCounts = getMetricCounts( - MetricName.create("External/" + HOST + "/HttpURLConnection/getInputStream", + MetricName.create("External/" + HOST + "/HttpURLConnection/getResponseCode", "OtherTransaction/Custom/test.newrelic.test.agent.HttpCommonsTest/httpURLConnectionTx")); - assertEquals(1, (int) metricCounts.get("External/" + HOST + "/HttpURLConnection/getInputStream")); + assertEquals(1, (int) metricCounts.get("External/" + HOST + "/HttpURLConnection/getResponseCode")); } @Trace(dispatcher = true) diff --git a/instrumentation/httpurlconnection/README.md b/instrumentation/httpurlconnection/README.md index 6043abe5ba..13a83274ad 100644 --- a/instrumentation/httpurlconnection/README.md +++ b/instrumentation/httpurlconnection/README.md @@ -2,117 +2,52 @@ This is a very old HTTP client and the APIs can be called in many combinations which can lead to unpredictable scenarios when trying to instrument it. -There is also the added complication that once the `connect` method has been called, whether explicitly or not, the `HttpURLConnection` headers become -immutable, and we can no longer add our distributed tracing headers. - -Furthermore, legacy CAT (Cross Application Tracing) can cause additional problems if `reportAsExternal` is called too early which causes exceptions. - -Because of these things, we need to keep some state on the order that `HttpURLConnection` APIs are invoked and in some cases we need to defer making a decision -on whether an external call should be recorded or not until we have a more complete picture on what APIs were called and in what order. - -## Usage scenarios/implementation - -This instrumentation creates a segment to do timing of external calls, starting when the first `HttpURLConnection` API is called and lasting until the external -call is recorded. Because of this the timing isn't as exact as tracing the individual methods. The reason for doing the timing in this manner is that it allows -the instrumentation to call `addOutboundRequestHeaders` and `reportAsExternal` on the same segment regardless of the order that the `HttpURLConnection` APIs are called in. - -Calling `addOutboundRequestHeaders` will result in a span (which could be generated from a segment or a tracer) that links one APM entity to another APM entity -in a distributed trace, whereas calling `reportAsExternal` will result in a span being marked as "External HTTP" that links one APM entity to any host (whether -it is monitored by New Relic, or not). Calling both methods on a single segment instance ensures that both scenarios are associated with a single span in a -distributed trace. This mitigates a bug in previous versions of this instrumentation that was using tracers instead of a segment. The bug was that a tracer -associated with one method (typically `connect`) would call `addOutboundRequestHeaders` and a tracer for another method would call `reportAsExternal`, resulting -in two different spans in a single distributed trace showing the same external call being made twice, one linked to an APM entity and the other linked to an external host. - -Much of this complication is due to the fact that once the `connect` method has been called, the `HttpURLConnection` header map can no longer be updated and any -calls to `addOutboundRequestHeaders` will fail. This means that if `connect` is explicitly called first we have no choice but to call `addOutboundRequestHeaders` -at that point and try to predict what sequence of events happens next and whether an external call should be recorded and, if so, how to call `reportAsExternal` -on the same tracer/segment so that only a single external span gets generated. - -Behavior expected when `HttpURLConnection` APIs are called in different combos and orders. -* If only `connect` is called, then NO request is made over the wire and NO external call is reported. The instrumentation starts a `SegmentCleanupTask` if`connect` is called first, waits for a set period of time to determine if any further `HttpURLConnection` APIs are called before deciding how to proceed. If no other API is called, then the segment is just ignored and no external is reported. If any other method is called an external call will be recorded. -* If `getOutputStream` is called alone or in combination with `connect`, then an external will only be recorded with DT (not CAT due to it causing exceptions when it reads from the input stream too early). When using CAT a `SegmentCleanupTask` will be started to determine if any methods were called after `getOutputStream` that would warrant reporting an external, or if the segment should be ignored. -* Calling any of `getInputStream`, `getResponseCode`, or `getHeaderFields` all result in an external call being recorded. - -## SegmentCleanupTask and ScheduledThreadPoolExecutor tuning - -For each external request where `connect` (or `getOutputStream` combined with CAT) is called first a `SegmentCleanupTask` `Runnable` gets scheduled to execute on a `ScheduledThreadPoolExecutor`. The -`SegmentCleanupTask` waits for a configurable period of time (default is 5 seconds) to determine if any other `HttpURLConnection` APIs are called that result in -a network request being issued. In most cases, another method will be called within this time period which will result in the scheduled task being cancelled and -removed from the executor's scheduled queue. In cases where no method is called that issues a network request, the `SegmentCleanupTask` `Runnable` will execute -and mark the Segment started when connect was called as ignored so that it doesn't appear as an external call in the related distributed trace. - -The `ScheduledThreadPoolExecutor` is shared amongst all `HttpURLConnection` instances making external requests and the size of its managed threadpool can be -configured via `thread_pool_size`. The delay after which each `SegmentCleanupTask` queued up with the `ScheduledThreadPoolExecutor` will be executed can be -configured with `delay_ms`. - -Config examples: - -Yaml -```yaml - class_transformer: - com.newrelic.instrumentation.httpurlconnection: - enabled: true - segment_cleanup_task: - thread_pool_size: 5 - delay_ms: 5000 -``` +There is also the added complication that once the `connect` method has been called, whether explicitly or not, the `HttpURLConnection` headers become immutable, and we can no longer add our distributed tracing headers. -System property -``` --Dnewrelic.config.class_transformer.com.newrelic.instrumentation.httpurlconnection.segment_cleanup_task.thread_pool_size=5 --Dnewrelic.config.class_transformer.com.newrelic.instrumentation.httpurlconnection.segment_cleanup_task.delay_ms=5000 -``` +This causes a problem where the DT headers have to be added in the `connect` tracer, but the real external call happens when one of `getResponseCode`, `getResponseMessage` or `getInputStream` is called. -Environment variable -``` -NEW_RELIC_CLASS_TRANSFORMER_COM_NEWRELIC_INSTRUMENTATION_HTTPURLCONNECTION_SEGMENT_CLEANUP_TASK_THREAD_POOL_SIZE=5 -NEW_RELIC_CLASS_TRANSFORMER_COM_NEWRELIC_INSTRUMENTATION_HTTPURLCONNECTION_SEGMENT_CLEANUP_TASK_DELAY_MS=5000 -``` +## History -## Troubleshooting +The instrumentation in version 7.11 would add the DT headers in the first method that was called but add the external to the method that read the response. This caused troubles in DT page, where it would appear that 2 calls were made, one to the DT entity and another to the external. -Whenever a `SegmentCleanupTask` runs and marks the external `Segment` as ignored it means that no external call will be recorded for the `Segment`. -When this happens it will generate a supportability metric named `Supportability/HttpURLConnection/SegmentIgnore/connect`. This means that either one of two -things: -1. There is a scenario where `connect` is called and never followed by any other `HttpURLConnection` APIs that issue a network request. In this case, it is correct that the `Segment` was ignored and no external call was recorded. -2. There is a scenario where `connect` is called and any other `HttpURLConnection` APIs that issue a network request did not occur before the `SegmentCleanupTask` ran. In this case, you can increase the `delay_ms` so that the `SegmentCleanupTask` is delayed long enough for the external call to successfully take place. -3. There is a scenario where CAT is enabled and `getOutputStream` is called and never followed by any other `HttpURLConnection` APIs that issue a network request. In this case, it is correct that the `Segment` was ignored and no external call was recorded. +The instrumentation in version 8.0 added a segment that would hold both the DT headers and be marked as the external. This solved the problem with the previous instrumentation, but caused a problem with the timing of the request. Segments are used for async work, so now it looked like there was async work in a single threaded part of the application. And since it is async, its time was not removed from the parent tracer, making the time of the segment to be double counted in the request. But the total request time was correct. -At `FINEST` level agent logs the number of queued tasks in the executor at the time of each external request will be logged. You can find these logs by -searching for the string `HttpURLConnection - number of queued cleanup tasks`. This can be useful to see if there are too many runnable tasks queued up at once -that could lead to memory pressure. Setting the `delay_ms` to a lower value will have the biggest impact on lowering the number of tasks that can be queued at -a given time, while increasing `thread_pool_size` can help remove queued tasks quicker. +## New solution -Threads in the threadpool managed by the executor will be named `New Relic HttpURLConnection Segment Cleanup Task`. +The current solution resembles the 7.11 instrumentation, but after the external is reported, the guid of the DT tracer and the external tracer are swapped. This causes the downstream DT to be linked to the external tracer. This is a dangerous if done carelessly, but in this case, both tracers are leaf tracers, so there are no tracers that depend on the guids of these tracers. -Another issue to be aware of is that legacy CAT (Cross Application Tracing) can cause additional problems if `reportAsExternal` is called too early. As seen in the stacktrace below -it tries to process the inbound response headers which will trigger a call to `getHeaderField` on the `HttpURLConnection` instance which -forces it to connect and read from the input stream. Unfortunately, for users of `HttpURLConnection` this has the unexpected effect of rendering the -`HttpURLConnection` header map immutable as well as causing `ProtocolException: Cannot write output after reading input` and -`IOException: Stream is closed` exceptions when attempting to write to the output stream. Because the headers become immutable some customers saw the `Content-Length` header disappear from certain outgoing HTTP requests from their applications, which resulted in external servers rejecting requests with HTTP `411 Length Required` errors. +### Usage scenarios/implementation -```java -"java.base/sun.net.www.protocol.http.HttpURLConnection$StreamingOutputStream.close(HttpURLConnection.java:3834)" -"java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1622)" -"java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1589)" -"java.base/sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:3221)" -"com.nr.agent.instrumentation.httpurlconnection.InboundWrapper.getHeader(InboundWrapper.java:26)" -"com.newrelic.agent.HeadersUtil.getAppDataHeader(HeadersUtil.java:122)" -"com.newrelic.agent.CrossProcessTransactionStateImpl.processInboundResponseHeaders(CrossProcessTransactionStateImpl.java:330)" -"com.newrelic.agent.tracers.DefaultTracer.recordInboundResponseHeaders(DefaultTracer.java:685)" -"com.newrelic.agent.tracers.DefaultTracer.recordExternalMetricsHttp(DefaultTracer.java:722)" -"com.newrelic.agent.tracers.DefaultTracer.recordExternalMetrics(DefaultTracer.java:664)" -"com.newrelic.agent.tracers.DefaultTracer.recordMetrics(DefaultTracer.java:469)" -"com.newrelic.agent.tracers.DefaultTracer.performFinishWork(DefaultTracer.java:284)" -"com.newrelic.agent.tracers.DefaultTracer.finish(DefaultTracer.java:236)" -"com.newrelic.agent.Transaction.finishTracer(Transaction.java:2370)" -"com.newrelic.agent.Transaction.finishSegment(Transaction.java:2365)" -"com.newrelic.agent.Segment$1.run(Segment.java:202)" -"com.newrelic.agent.ExpirationService.expireSegmentInline(ExpirationService.java:47)" -"com.newrelic.agent.Segment.finish(Segment.java:214)" -"com.newrelic.agent.Segment.end(Segment.java:144)" -"com.nr.agent.instrumentation.httpurlconnection.MetricState.reportExternalCall(MetricState.java:255)" -``` +The instrumentation cares mostly about the following methods: `connect`, `getOutputStream`, `getResponseCode`, `getResponseMessage` and `getInputStream`. These are the methods that change the state of the HttpURLConnection and affect the instrumentation. Henceforth, _response methods_ can refer to any of `getResponseCode`, `getResponseMessage` and `getInputStream`. + +#### Scenario 1 (connect + response) + +When `connect` or `getOutputStream` is the first method called, DT headers are added to the request, linked to the method's tracer (DT tracer). In any subsequent call to these methods, the instrumentation code is noop. + +Then in a subsequent call to a response method, the method's tracer will be marked as the external (external tracer) and the guids from the external tracer, and the DT tracer are swapped. In subsequent calls for any methods the instrumentation code is noop. + +Depending on the configuration of the HttpURLConnection, the external call can start after the call to `getOutpuStram` is finished and before any response method is called. In this case, the external metric will (most likely) record a duration lower than the real duration of the outgoing request. + +#### Scenario 2 (response) + +When a response method is the first method called, then the tracer will be marked as both the DT tracer and the external tracer. No guid swapping needed in this case. + +In further calls to any method, the instrumentation code is noop. + +#### Scenario 3 (fire and forget) + +When `getOutputStream` is called (with or without a preceding `connect` call), but none of the response methods is called after, could result in a fire and forget call. + +As in scenario 1, the first method called will have the DT headers associated with it. But since there is no external tracer, there is no guids to swap. + +In this case, there will be no external reported, but if the call reaches a server that is instrumented, then the DT will be linked to the first method call. + +Not setting an external in this case is reasonable because there is no way for the agent to report how long the call really took. The call itself may start after the transaction has ended and will usually be longer than the time taken by the `connect` or `getOutputStream` call. + +### Flaws + +- Fire and forget are not computed into the metrics. +- The timing of the external may be shorter than it really is when `getOutputStream` is called under certain circumstances. ## Example HttpURLConnection usage diff --git a/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/DefaultThreadFactory.java b/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/DefaultThreadFactory.java deleted file mode 100644 index a487b546c0..0000000000 --- a/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/DefaultThreadFactory.java +++ /dev/null @@ -1,42 +0,0 @@ -/* - * - * * Copyright 2023 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package com.nr.agent.instrumentation.httpurlconnection; - -import java.util.concurrent.ThreadFactory; -import java.util.concurrent.atomic.AtomicInteger; - -// this is a simplified copy of the DefaultThreadFactory -public class DefaultThreadFactory implements ThreadFactory { - /** - * The name created threads will use. - */ - private final String name; - /** - * Whether the created thread is a daemon thread. - */ - private final boolean daemon; - private final AtomicInteger threadNumber = new AtomicInteger(1); - - /** - * Constructs a thread factory that will created named threads. - */ - public DefaultThreadFactory(String name, boolean daemon) { - this.name = name; - this.daemon = daemon; - } - - @Override - public Thread newThread(Runnable r) { - int num = threadNumber.getAndIncrement(); - Thread t = new Thread(r, name + " " + num); - if (daemon) { - t.setDaemon(true); - } - return t; - } -} diff --git a/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/GuidSwapper.java b/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/GuidSwapper.java new file mode 100644 index 0000000000..8b04be9b7f --- /dev/null +++ b/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/GuidSwapper.java @@ -0,0 +1,103 @@ +/* + * + * * Copyright 2023 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package com.nr.agent.instrumentation.httpurlconnection; + +import com.newrelic.api.agent.TracedMethod; + +import java.lang.reflect.Field; +import java.lang.reflect.Modifier; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; + +/** + * This class is an attempt to make swapping tracers' guids less hacky. + */ +class GuidSwapper { + + /** + * Swaps the guids from the provided tracers. + */ + static void swap(TracedMethod tracer1, TracedMethod tracer2) { + if (tracer1 == tracer2 || tracer1 == null || tracer2 == null) { + return; + } + GuidChanger changer1 = GuidSwapper.getGuidChanger(tracer1.getClass()); + GuidChanger changer2 = GuidSwapper.getGuidChanger(tracer2.getClass()); + + if (changer1 != GuidChanger.NULL_GUIDCHANGER && changer2 != GuidChanger.NULL_GUIDCHANGER) { + String guid1 = changer1.getGuid(tracer1); + String guid2 = changer2.getGuid(tracer2); + changer1.setGuid(tracer1, guid2); + changer2.setGuid(tracer2, guid1); + } + } + + // this cache should not be big, maybe just a single entry, so there is no mechanism to expire items + private static Map, GuidChanger> CACHE = new ConcurrentHashMap<>(8); + + /** + * Get a GuidChanger for a given TracedMethod subclass. + * In most, if not all, cases it will be a DefaultTracer. + * But this makes sure that it will be able to read/write the guid regardless of class. + * + */ + private static GuidChanger getGuidChanger(Class clazz) { + GuidChanger guidChanger = CACHE.get(clazz); + if (guidChanger != null) { + return guidChanger; + } + + Field field = null; + for (Field declaredField : clazz.getDeclaredFields()) { + if ("guid".equals(declaredField.getName())) { + // make sure the field is not final + if ((declaredField.getModifiers() & Modifier.FINAL) == 0 ) { + field = declaredField; + field.setAccessible(true); + } + break; + } + } + guidChanger = GuidChanger.forField(field); + CACHE.put(clazz, guidChanger); + return guidChanger; + } + + private static class GuidChanger { + + // Dummy instance for classes that do not have a guid + static final GuidChanger NULL_GUIDCHANGER = new GuidChanger(null); + + static GuidChanger forField(Field field) { + return field == null ? NULL_GUIDCHANGER : new GuidChanger(field); + } + + private final Field declaredField; + + private GuidChanger(Field declaredField) { + this.declaredField = declaredField; + } + + public String getGuid(Object target) { + try { + return declaredField.get(target).toString(); + } catch (IllegalAccessException e) { + throw new RuntimeException(e); + } + } + + public void setGuid(Object target, String guid) { + try { + declaredField.set(target, guid); + } catch (IllegalAccessException e) { + throw new RuntimeException(e); + } + } + } + +} diff --git a/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/HttpURLConnectionConfig.java b/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/HttpURLConnectionConfig.java index 523f9033db..f3ee51f6d9 100644 --- a/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/HttpURLConnectionConfig.java +++ b/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/HttpURLConnectionConfig.java @@ -20,39 +20,11 @@ * See README for config examples. */ public class HttpURLConnectionConfig { - private static final String configPrefix = "class_transformer.com.newrelic.instrumentation.httpurlconnection.segment_cleanup_task."; - /* - * The following tests do a Thread.sleep to account for this delay. If this value is changed then the tests will also need to be updated. - * functional_test/src/test/java/com/newrelic/agent/instrumentation/pointcuts/net/HttpURLConnectionTest - * instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/MetricStateConnectTest - */ - private static final int DEFAULT_TASK_DELAY_MS = 5_000; - private static final int DEFAULT_THREAD_POOL_SIZE = 5; private static final boolean DEFAULT_DISTRIBUTED_TRACING_ENABLED = true; private HttpURLConnectionConfig() { } - public static int getThreadPoolSize() { - int threadPoolSize = DEFAULT_THREAD_POOL_SIZE; - try { - threadPoolSize = NewRelic.getAgent().getConfig().getValue(configPrefix + "thread_pool_size", DEFAULT_THREAD_POOL_SIZE); - } catch (Exception e) { - AgentBridge.getAgent().getLogger().log(Level.FINEST, "HttpURLConnection - using default thread_pool_size: " + threadPoolSize); - } - return threadPoolSize; - } - - public static int getDelayMs() { - int delayMs = DEFAULT_TASK_DELAY_MS; - try { - delayMs = NewRelic.getAgent().getConfig().getValue(configPrefix + "delay_ms", DEFAULT_TASK_DELAY_MS); - } catch (Exception e) { - AgentBridge.getAgent().getLogger().log(Level.FINEST, "HttpURLConnection - using default task delay_ms: " + delayMs); - } - return delayMs; - } - public static boolean distributedTracingEnabled() { boolean dtEnabled = DEFAULT_DISTRIBUTED_TRACING_ENABLED; try { diff --git a/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/MetricState.java b/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/MetricState.java index faa2fd83a9..75dc9f715a 100644 --- a/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/MetricState.java +++ b/instrumentation/httpurlconnection/src/main/java/com/nr/agent/instrumentation/httpurlconnection/MetricState.java @@ -11,277 +11,99 @@ import com.newrelic.agent.bridge.TracedMethod; import com.newrelic.agent.bridge.Transaction; import com.newrelic.agent.bridge.external.URISupport; +import com.newrelic.api.agent.HeaderType; import com.newrelic.api.agent.HttpParameters; -import com.newrelic.api.agent.NewRelic; -import com.newrelic.api.agent.Segment; +import com.newrelic.api.agent.OutboundHeaders; import java.net.HttpURLConnection; import java.net.URI; -import java.util.concurrent.Executors; -import java.util.concurrent.ScheduledFuture; -import java.util.concurrent.ScheduledThreadPoolExecutor; -import java.util.concurrent.TimeUnit; -import java.util.logging.Level; +/** + *

+ * This class stores the state and methods to add outbound headers and mark a tracer as an external. + *

+ *

+ * The methods addOutboundHeadersIfNotAdded and reportExternalCall should only be executed once each. + *

+ *

+ * To prevent addOutboundHeadersIfNotAdded from being executed twice, the first call will set the dtTracer variable. + *
+ * dtTracer not being null signals that the method should not be executed again, and the reference is later used to swap guids. + *

+ *

+ * The methods inboundPreamble and inboundPostamble are called by the HttpUrlConnection instrumented methods: + * getInputStream, getResponseCode, getResponseMessage. And these methods make calls to each other. + *
+ * To prevent a child call from executing inboundPreamble or inboundPostamble, the first call will set the externalTracer.
+ * This signals to inboundPreamble that the method should not be executed and inboundPostamble will only execute if the tracer passed + * is the same as the one recorded earlier. + *

+ * + */ public class MetricState { private static final String LIBRARY = "HttpURLConnection"; - private static final String CATEGORY = "Java"; - public static final String CONNECT_OP = "connect"; - public static final String GET_OUTPUT_STREAM_OP = "getOutputStream"; - public static final String GET_INPUT_STREAM_OP = "getInputStream"; - public static final String GET_RESPONSE_CODE_OP = "getResponseCode"; - - private boolean metricsRecorded; - private boolean recordedANetworkCall; - private boolean addedOutboundRequestHeaders; - - // records the last HttpURLConnection operation - private String lastOperation = null; - // records true if any methods that cause a network request were called - private boolean networkRequestMethodCalled; - // segment used to track timing of external request, add addOutboundRequestHeaders, and reportAsExternal - private Segment segment; - private static final String NEW_RELIC_HTTPURLCONNECTION_SEGMENT_CLEANUP = "New Relic HttpURLConnection Segment Cleanup"; - - private static final ScheduledThreadPoolExecutor threadPool = (ScheduledThreadPoolExecutor) Executors.newScheduledThreadPool( - HttpURLConnectionConfig.getThreadPoolSize(), new DefaultThreadFactory(NEW_RELIC_HTTPURLCONNECTION_SEGMENT_CLEANUP, true)); - - static { - // This forces cancelled tasks to be immediately removed from the thread pool - threadPool.setRemoveOnCancelPolicy(true); - } - - private ScheduledFuture segmentCleanupTaskFuture; - - /** - * Start Segment timing when the first HttpURLConnection API method is invoked. - * The Segment timing should end when a request has taken place and an external call has been recorded. - * - * @param tx current Transaction - * @param operation HttpURLConnection method being invoked - */ - private void startSegmentIfNull(Transaction tx, String operation) { - if (segment == null) { - segment = tx.startSegment(CATEGORY, operation); - segment.setMetricName(CATEGORY, LIBRARY, operation); - } - } - - /** - * Keep track of which HttpURLConnection API method was most recently called. - * If connect or getOutputStream was called first, then start a cleanup task to potentially ignore the segment - * if it is determined that no network call actually took place. - * - * @param operation HttpURLConnection method being invoked - */ - private void handleSegmentsForNonNetworkMethods(String operation) { - if (operation.equals(CONNECT_OP) || operation.equals(GET_OUTPUT_STREAM_OP)) { - // Potentially start a cleanup task if either connect or getOutputStream is the first method called - if (lastOperation == null) { - lastOperation = operation; - /* - * Don't start task if operation is getOutputStream and DT is enabled. This is only a necessary precaution when using CAT - * as it can't call reportAsExternal (which calls segment.end) in certain conditions when the stream hasn't been read from yet. - * When using DT, it will always call reportAsExternal and end the segment properly. - */ - if (!(lastOperation.equals(GET_OUTPUT_STREAM_OP) && HttpURLConnectionConfig.distributedTracingEnabled())) { - startSegmentCleanupTask(); - } - } - if (operation.equals(GET_OUTPUT_STREAM_OP)) { - // Cancel the SegmentCleanupTask before it runs if possible when DT is enabled and getOutputStream was the last method called - if (HttpURLConnectionConfig.distributedTracingEnabled()) { - if (segmentCleanupTaskFuture != null && !segmentCleanupTaskFuture.isCancelled()) { - segmentCleanupTaskFuture.cancel(false); - } - } - lastOperation = operation; - } - } else { - networkRequestMethodCalled = true; - // Cancel the SegmentCleanupTask before it runs if possible - if (segmentCleanupTaskFuture != null && !segmentCleanupTaskFuture.isCancelled()) { - segmentCleanupTaskFuture.cancel(false); - } - lastOperation = operation; - } - } - - /** - * If connect (or getOutputStream with CAT) was the first method invoked from the HttpURLConnection APIs then a - * cleanup task will be started which will determine if the segment should be ignored or not. - *

- * Note: If the user configurable segment_timeout is explicitly configured to be lower than the timer delay set - * here then the segment timing will already have been ended and trying to end/ignore it again will have no effect. - */ - private void startSegmentCleanupTask() { - // Submit a SegmentCleanupTask to a ScheduledThreadPoolExecutor to be run after a configured delay - SegmentCleanupTask segmentCleanupTask = new SegmentCleanupTask(NEW_RELIC_HTTPURLCONNECTION_SEGMENT_CLEANUP); - segmentCleanupTaskFuture = threadPool.schedule(segmentCleanupTask, HttpURLConnectionConfig.getDelayMs(), TimeUnit.MILLISECONDS); - AgentBridge.getAgent().getLogger().log(Level.FINEST, "HttpURLConnection - number of queued cleanup tasks: " + threadPool.getQueue().size()); - } - - /** - * A Runnable task that can be scheduled to run to determine if a segment should be ignored or not - */ - private class SegmentCleanupTask implements Runnable { - String taskName; - public SegmentCleanupTask(String taskName) { - this.taskName = taskName; - } - - public void run() { - ignoreNonNetworkSegment(); - } - } - - /** - * This method executes when a cleanup task completes. If it is determined that connect (or getOutputStream with CAT) was the first and only HttpURLConnection - * API called then it will have the effect of ignoring the segment, and no external call will be reported. A supportability metric will also be recorded. - * The purpose of this is to avoid hitting the default segment timeout of 10 minutes and to also prevent the segment from showing in traces. - */ - private void ignoreNonNetworkSegment() { - if (lastOperation != null && segment != null) { - if (!networkRequestMethodCalled) { - if (lastOperation.equals(CONNECT_OP) || lastOperation.equals(GET_OUTPUT_STREAM_OP)) { - segment.ignore(); - NewRelic.incrementCounter("Supportability/HttpURLConnection/SegmentIgnore/" + lastOperation); - } - } - } - } + // the guids for these tracers are swapped so the DT is attached to the tracer that + // has the external + private TracedMethod dtTracer; + private TracedMethod externalTracer; + private boolean externalReported = false; /** - * This can be called when either connect or getOutputStream are invoked. - * If only connect was called then no external call should be recorded. If getOutputStream was call alone, or in - * any combination with connect, then an external call should be recorded (except for some scenarios involving CAT). + * This can be called by either connect or getOutputStream. + * Even though both these methods start network activity, neither will make a full request. + * DT/CAT headers have to be added here. + * Analyzing DTs, only when the other methods are called that we can see a transaction in the downstream entity. * - * @param isConnected true if a connection has already been made, else false + * @param isConnected whether a connection has already been made * @param connection HttpURLConnection - * @param operation HttpURLConnection method being invoked */ - public void nonNetworkPreamble(boolean isConnected, HttpURLConnection connection, String operation) { - handleSegmentsForNonNetworkMethods(operation); + public void nonNetworkPreamble(boolean isConnected, HttpURLConnection connection) { TracedMethod method = AgentBridge.getAgent().getTracedMethod(); Transaction tx = AgentBridge.getAgent().getTransaction(false); if (!isConnected && method.isMetricProducer() && tx != null) { - startSegmentIfNull(tx, operation); - - /* - * Add CAT/Distributed tracing headers to this outbound request. - * - * Whichever TracedMethod/Segment calls addOutboundRequestHeaders first will be the method that is associated with making the - * external request to another APM entity. However, if the external request isn't to another APM entity then this does - * nothing and reportAsExternal must be called to establish the link between the TracedMethod/Segment and external host. - */ - if (!addedOutboundRequestHeaders && segment != null) { - segment.addOutboundRequestHeaders(new OutboundWrapper(connection)); - this.addedOutboundRequestHeaders = true; - } - } - - /* - * Report an external call for getOutputStream only if distributed tracing is being used instead of CAT. - * If the input stream hasn't been read from already and CAT is being used instead of DT, then calling reportAsExternal will trigger a call to - * getHeaderField on the HttpURLConnection instance which forces it to connect and read the input stream. Unfortunately, for users of - * HttpURLConnection this has the unexpected effect of rendering the HttpURLConnection header map immutable as well as causing - * "ProtocolException: Cannot write output after reading input" and "IOException: Stream is closed" exceptions when attempting to write - * to the output stream. - */ - if (lastOperation.equals(GET_OUTPUT_STREAM_OP) && tx != null) { - if (HttpURLConnectionConfig.distributedTracingEnabled()) { - networkRequestMethodCalled = true; - reportExternalCall(connection, lastOperation, 0, null); - } + addOutboundHeadersIfNotAdded(connection); } } /** - * Called when getInputStream is invoked. - * This code path guarantees that getInboundPostamble will ultimately be called and an external call will be reported. + * Called when any of getInputStream, getResponseCode, getResponseMessage is invoked, before the original code is executed. + * This code path guarantees that getInboundPostamble will be called by the first method that called this method. * * @param isConnected true if a connection has already been made, else false - * @param connection HttpURLConnection - * @param method traced method that will be the parent of the segment + * @param tracer traced method that will be the external */ - public void getInputStreamPreamble(boolean isConnected, HttpURLConnection connection, TracedMethod method) { - handleSegmentsForNonNetworkMethods(GET_INPUT_STREAM_OP); - - Transaction tx = AgentBridge.getAgent().getTransaction(false); - if (method.isMetricProducer() && tx != null) { - startSegmentIfNull(tx, GET_INPUT_STREAM_OP); - if (!recordedANetworkCall) { - this.recordedANetworkCall = true; - } - - if (!isConnected) { - /* - * Add CAT/Distributed tracing headers to this outbound request. - * - * Whichever TracedMethod/Segment calls addOutboundRequestHeaders first will be the method that is associated with making the - * external request to another APM entity. However, if the external request isn't to another APM entity then this does - * nothing and reportAsExternal must be called to establish the link between the TracedMethod/Segment and external host. - */ - if (!addedOutboundRequestHeaders && segment != null) { - segment.addOutboundRequestHeaders(new OutboundWrapper(connection)); - this.addedOutboundRequestHeaders = true; - } - } + public void inboundPreamble(boolean isConnected, HttpURLConnection connection, TracedMethod tracer) { + if (externalReported || externalTracer != null) { + // another method already ran the preamble + return; } - } - - /** - * Called when getResponseCode is invoked. - * This code path guarantees that getInboundPostamble will ultimately be called and an external call will be reported. - * - * @param method traced method that will be the parent of the segment - */ - public void getResponseCodePreamble(TracedMethod method) { - handleSegmentsForNonNetworkMethods(GET_RESPONSE_CODE_OP); - Transaction tx = AgentBridge.getAgent().getTransaction(false); - if (method.isMetricProducer() && tx != null && !recordedANetworkCall) { - this.recordedANetworkCall = true; - startSegmentIfNull(tx, GET_RESPONSE_CODE_OP); + externalTracer = tracer; + + if (!isConnected && tracer.isMetricProducer() && tx != null) { + addOutboundHeadersIfNotAdded(connection); } } /** - * Called when either getInputStream or getResponseCode is invoked. + * Called when any of getInputStream, getResponseCode, getResponseMessage is invoked, after the original code is executed. * This code path is what ultimately calls reportExternalCall to create an External HTTP span. + * This method will only execute if the tracer passed to this method is the same as the one passed to the first invocation of inboundPreamble. * - * @param connection HttpURLConnection - * @param responseCode HttpURLConnection response code - * @param responseMessage HttpURLConnection response message - * @param operation HttpURLConnection method being invoked - * @param method traced method that will be the parent of the segment + * @param operation + * @param tracer traced method that will be the external */ - public void getInboundPostamble(HttpURLConnection connection, int responseCode, String responseMessage, String operation, TracedMethod method) { - handleSegmentsForNonNetworkMethods(operation); - + public void inboundPostamble(HttpURLConnection connection, int responseCode, String responseMessage, Ops operation, + TracedMethod tracer) { + // make sure that only the method that first invoked inboundPreamble runs this method + if (externalReported || externalTracer != tracer) { + return; + } Transaction tx = AgentBridge.getAgent().getTransaction(false); - if (method.isMetricProducer() && !metricsRecorded && tx != null) { - startSegmentIfNull(tx, operation); - this.metricsRecorded = true; - - /* - * Add CAT/Distributed tracing headers to this outbound request. - * - * Whichever TracedMethod/Segment calls addOutboundRequestHeaders first will be the method that is associated with making the - * external request to another APM entity. However, if the external request isn't to another APM entity then this does - * nothing and reportAsExternal must be called to establish the link between the TracedMethod/Segment and external host. - * - * If already connected then we cannot modify the HttpURLConnection header map and this will fail to add outbound request headers - */ - if (!addedOutboundRequestHeaders && segment != null) { - segment.addOutboundRequestHeaders(new OutboundWrapper(connection)); - this.addedOutboundRequestHeaders = true; - } - - // This will result in External rollup metrics being generated + if (tx != null) { reportExternalCall(connection, operation, responseCode, responseMessage); } } @@ -292,27 +114,70 @@ public void getInboundPostamble(HttpURLConnection connection, int responseCode, * calls to be properly recorded when they are made to a host that isn't another APM entity. * * @param connection HttpURLConnection instance - * @param operation HttpURLConnection API method being invoked + * @param operation * @param responseCode response code from HttpURLConnection * @param responseMessage response message from HttpURLConnection */ - void reportExternalCall(HttpURLConnection connection, String operation, int responseCode, String responseMessage) { - if (connection != null && segment != null) { + void reportExternalCall(HttpURLConnection connection, Ops operation, int responseCode, String responseMessage) { + if (connection != null) { // This conversion is necessary as it strips query parameters from the URI String uri = URISupport.getURI(connection.getURL()); InboundWrapper inboundWrapper = new InboundWrapper(connection); // This will result in External rollup metrics being generated (e.g. External/all, External/allWeb, External/allOther, External/{HOST}/all) // Calling reportAsExternal is what causes an HTTP span to be created - segment.reportAsExternal(HttpParameters + externalTracer.reportAsExternal(HttpParameters .library(LIBRARY) .uri(URI.create(uri)) - .procedure(operation) + .procedure(operation.label) .inboundHeaders(inboundWrapper) .status(responseCode, responseMessage) .build()); - segment.end(); + // need to call this method to set addedOutboundRequestHeaders in the Tracer + externalTracer.addOutboundRequestHeaders(DummyHeaders.INSTANCE); + GuidSwapper.swap(dtTracer, externalTracer); + dtTracer = null; + externalTracer = null; + externalReported = true; + } + } + + /** + * Checks whether outboundheaders (DT/CAT) were already added and if not, add them to the connection. + */ + private void addOutboundHeadersIfNotAdded(HttpURLConnection connection) { + if (dtTracer == null) { + dtTracer = AgentBridge.getAgent().getTracedMethod(); + dtTracer.addOutboundRequestHeaders(new OutboundWrapper(connection)); + } + } + + public enum Ops { + CONNECT("connect"), + GET_OUTPUT_STREAM("getOutputStream"), + GET_INPUT_STREAM("getInputStream"), + GET_RESPONSE_CODE("getResponseCode"), + GET_RESPONSE_MSG("getResponseMessage"), + ; + + Ops(String label) { + this.label = label; + } + + private String label; + } + + private static class DummyHeaders implements OutboundHeaders { + private static final DummyHeaders INSTANCE = new DummyHeaders(); + @Override + public HeaderType getHeaderType() { + return HeaderType.HTTP; + } + + @Override + public void setHeader(String name, String value) { + } } } diff --git a/instrumentation/httpurlconnection/src/main/java/java/net/HttpURLConnection.java b/instrumentation/httpurlconnection/src/main/java/java/net/HttpURLConnection.java index e9f24381eb..2abbdfdb53 100644 --- a/instrumentation/httpurlconnection/src/main/java/java/net/HttpURLConnection.java +++ b/instrumentation/httpurlconnection/src/main/java/java/net/HttpURLConnection.java @@ -9,6 +9,7 @@ import com.newrelic.agent.bridge.AgentBridge; import com.newrelic.agent.bridge.TracedMethod; +import com.newrelic.api.agent.Trace; import com.newrelic.api.agent.weaver.MatchType; import com.newrelic.api.agent.weaver.NewField; import com.newrelic.api.agent.weaver.Weave; @@ -19,10 +20,9 @@ import java.io.InputStream; import java.io.OutputStream; -import static com.nr.agent.instrumentation.httpurlconnection.MetricState.CONNECT_OP; -import static com.nr.agent.instrumentation.httpurlconnection.MetricState.GET_INPUT_STREAM_OP; -import static com.nr.agent.instrumentation.httpurlconnection.MetricState.GET_OUTPUT_STREAM_OP; -import static com.nr.agent.instrumentation.httpurlconnection.MetricState.GET_RESPONSE_CODE_OP; +import static com.nr.agent.instrumentation.httpurlconnection.MetricState.Ops.GET_INPUT_STREAM; +import static com.nr.agent.instrumentation.httpurlconnection.MetricState.Ops.GET_RESPONSE_CODE; +import static com.nr.agent.instrumentation.httpurlconnection.MetricState.Ops.GET_RESPONSE_MSG; @Weave(type = MatchType.BaseClass) public abstract class HttpURLConnection extends URLConnection { @@ -30,6 +30,9 @@ public abstract class HttpURLConnection extends URLConnection { @NewField private MetricState metricStateField; + /** + * Return the existing MetricState for this object, or create a new one if it does not exist. + */ private MetricState lazyGetMetricState() { if (metricStateField == null) { metricStateField = new MetricState(); @@ -46,25 +49,29 @@ protected HttpURLConnection(URL url) { // connect can be called explicitly, but it doesn't need to be as it will implicitly be called by other // methods that read or write over the connection such as getInputStream, getResponseCode, and getOutputStream. // Calling connect directly doesn't cause a request to happen over the wire. + @Trace(leaf=true) public void connect() throws IOException { - lazyGetMetricState().nonNetworkPreamble(connected, this, CONNECT_OP); + lazyGetMetricState().nonNetworkPreamble(connected, this); Weaver.callOriginal(); } // This can be called to write data over the wire in a fire and forget manner without inspecting the response. There's // no guarantee or requirement that another method (e.g. getInputStream) will be called to get the results or response code. - // Calling this alone should be considered as a valid external call. + // Though it is not guaranteed that a call to this method will fire the external call and if it does there is no correlation + // between this method's call to the start or length of the external call. + @Trace(leaf=true) public synchronized OutputStream getOutputStream() throws IOException { - lazyGetMetricState().nonNetworkPreamble(connected, this, GET_OUTPUT_STREAM_OP); + lazyGetMetricState().nonNetworkPreamble(connected, this); return Weaver.callOriginal(); } // getInputStream opens a stream with the intention of reading response data from the server. // Calling getInputStream causes a request to happen over the wire. + @Trace(leaf=true) public synchronized InputStream getInputStream() throws IOException { MetricState metricState = lazyGetMetricState(); TracedMethod method = AgentBridge.getAgent().getTracedMethod(); - metricState.getInputStreamPreamble(connected, this, method); + metricState.inboundPreamble(connected, this, method); InputStream inputStream; try { @@ -78,17 +85,18 @@ public synchronized InputStream getInputStream() throws IOException { throw e; } - metricState.getInboundPostamble(this, 0, null, GET_INPUT_STREAM_OP, method); + metricState.inboundPostamble(this, responseCode, responseMessage, GET_INPUT_STREAM, method); return inputStream; } // getResponseCode gets the status code from an HTTP response message. // If the request was already made (e.g. because getInputStream was called before it) it will simply return the status code from the response. // Otherwise, it will initiate the request itself by calling getInputStream which calls connect (or potentially getOutputStream if streaming). + @Trace(leaf=true) public int getResponseCode() throws Exception { MetricState metricState = lazyGetMetricState(); TracedMethod method = AgentBridge.getAgent().getTracedMethod(); - metricState.getResponseCodePreamble(method); + metricState.inboundPreamble(connected, this, method); int responseCodeValue; try { @@ -102,12 +110,33 @@ public int getResponseCode() throws Exception { throw e; } - metricState.getInboundPostamble(this, responseCodeValue, null, GET_RESPONSE_CODE_OP, method); + metricState.inboundPostamble(this, responseCodeValue, responseMessage, GET_RESPONSE_CODE, method); return responseCodeValue; } + @Trace(leaf=true) + public String getResponseMessage() throws IOException { + MetricState metricState = lazyGetMetricState(); + TracedMethod method = AgentBridge.getAgent().getTracedMethod(); + metricState.inboundPreamble(connected, this, method); + String responseMessageValue; + try { + responseMessageValue = Weaver.callOriginal(); + } catch (Exception e) { + if (e instanceof UnknownHostException) { + method.setMetricName("External", "UnknownHost", "HttpURLConnection"); + } + throw e; + } + metricState.inboundPostamble(this, responseCode, responseMessageValue, GET_RESPONSE_MSG, method); + return responseMessageValue; + } + public abstract String getHeaderField(String name); public abstract void setRequestProperty(String key, String value); + protected int responseCode = Weaver.callOriginal(); + + protected String responseMessage = Weaver.callOriginal(); } diff --git a/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/ConnectTest.java b/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/ConnectTest.java new file mode 100644 index 0000000000..2351311f5a --- /dev/null +++ b/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/ConnectTest.java @@ -0,0 +1,99 @@ +/* + * + * * Copyright 2020 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package com.nr.agent.instrumentation.httpurlconnection; + +import com.newrelic.agent.introspec.InstrumentationTestConfig; +import com.newrelic.agent.introspec.InstrumentationTestRunner; +import com.newrelic.agent.introspec.Introspector; +import com.newrelic.agent.introspec.TracedMetricData; +import com.newrelic.agent.introspec.TransactionEvent; +import com.newrelic.agent.introspec.TransactionTrace; +import com.newrelic.agent.introspec.internal.HttpServerRule; +import com.newrelic.api.agent.Trace; +import org.junit.Rule; +import org.junit.Test; +import org.junit.runner.RunWith; + +import java.net.HttpURLConnection; +import java.util.Map; + +import static org.hamcrest.Matchers.notNullValue; +import static org.hamcrest.Matchers.nullValue; +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertNotEquals; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertNull; +import static org.junit.Assert.assertThat; +import static org.junit.Assert.assertTrue; + +@RunWith(InstrumentationTestRunner.class) +@InstrumentationTestConfig(includePrefixes = { "leave-me-alone" }, configName = "distributed_tracing.yml") +public class ConnectTest { + + @Rule + public HttpServerRule server = new HttpServerRule(); + + @Test + public void shouldSetHeadersOnFirstConnect() throws Exception { + InstrumentedHttpUrlConnection fakeConnection = new InstrumentedHttpUrlConnection(server); + runTransactionAndIntrospect(fakeConnection, false); + + // assert that the headers were set + HttpURLConnection realConnection = fakeConnection.getRealConnection(); + assertNotNull(realConnection.getRequestProperty("tracestate")); + assertNotNull(realConnection.getRequestProperty("traceparent")); + assertNotNull(realConnection.getRequestProperty("newrelic")); + } + + @Test + public void shouldNotSetHeadersOnSecondConnect() throws Exception { + InstrumentedHttpUrlConnection fakeConnection = new InstrumentedHttpUrlConnection(server); + runTransactionAndIntrospect(fakeConnection, true); + + // assert that the headers were not set + HttpURLConnection realConnection = fakeConnection.getRealConnection(); + assertNull(realConnection.getRequestProperty("tracestate")); + assertNull(realConnection.getRequestProperty("traceparent")); + assertNull(realConnection.getRequestProperty("newrelic")); + } + + + private void runTransactionAndIntrospect(InstrumentedHttpUrlConnection connection, boolean pretendToBeConnected) throws Exception { + callConnect(connection, pretendToBeConnected); + + Introspector introspector = InstrumentationTestRunner.getIntrospector(); + assertEquals(1, introspector.getFinishedTransactionCount(500)); + + String transactionName = introspector.getTransactionNames().iterator().next(); + boolean foundExpectedEvent = false; + for (TransactionEvent event : introspector.getTransactionEvents(transactionName)) { + foundExpectedEvent = foundExpectedEvent || event.getName().endsWith("/callConnect"); + } + assertTrue("Did not find an event ending in callConnect", foundExpectedEvent); + + TransactionTrace trace = introspector.getTransactionTracesForTransaction(transactionName).iterator().next(); + Map metricsForTransaction = introspector.getMetricsForTransaction(transactionName); + + String defaultMetricName = transactionName.replace("OtherTransaction/Custom", "Java"); + assertEquals(defaultMetricName, trace.getInitialTraceSegment().getName()); + assertTrue(metricsForTransaction.containsKey(defaultMetricName)); + + // calling connect does not create external + long externalCount = metricsForTransaction.keySet().stream().filter(metricName -> metricName.startsWith("External")).count(); + assertEquals(0, externalCount); + + assertTrue(metricsForTransaction.containsKey("Custom/" + InstrumentedHttpUrlConnection.class.getName() + "/connect")); + } + + + @Trace(dispatcher = true) // NOTE: Method name is used as a string in the metric! + public void callConnect(InstrumentedHttpUrlConnection connection, boolean pretendToBeConnected) throws Exception { + connection.connect(pretendToBeConnected); + } +} diff --git a/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/MetricStateResponseCodeTest.java b/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/InboundTest.java similarity index 56% rename from instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/MetricStateResponseCodeTest.java rename to instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/InboundTest.java index 85b8e4dc6c..8eed56ca47 100644 --- a/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/MetricStateResponseCodeTest.java +++ b/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/InboundTest.java @@ -7,11 +7,11 @@ package com.nr.agent.instrumentation.httpurlconnection; -import com.newrelic.agent.bridge.AgentBridge; import com.newrelic.agent.introspec.InstrumentationTestConfig; import com.newrelic.agent.introspec.InstrumentationTestRunner; import com.newrelic.agent.introspec.Introspector; import com.newrelic.agent.introspec.TraceSegment; +import com.newrelic.agent.introspec.TracedMetricData; import com.newrelic.agent.introspec.TransactionEvent; import com.newrelic.agent.introspec.TransactionTrace; import com.newrelic.agent.introspec.internal.HttpServerRule; @@ -20,23 +20,26 @@ import org.junit.Test; import org.junit.runner.RunWith; -import java.net.HttpURLConnection; -import java.net.URL; -import java.net.URLConnection; +import java.util.Map; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertTrue; +/** + * Tests the methods that receive data from the downstream server and thus create the external. + */ @RunWith(InstrumentationTestRunner.class) @InstrumentationTestConfig(includePrefixes = { "leave-me-alone" }, configName = "distributed_tracing.yml") -public class MetricStateResponseCodeTest { +public class InboundTest { + @Rule + public HttpServerRule server = new HttpServerRule(); + /** * Objective: make sure that a single call to an instance reports the metric and segment as expected. */ @Test public void shouldSetMetricsAndSegmentWhenCalledOnce() throws Exception { - MetricState target = new MetricState(); - runAndVerifyFirstCall(target, 1); + runAndVerifyFirstCall(new InstrumentedHttpUrlConnection(server), 1); } /** @@ -45,19 +48,18 @@ public void shouldSetMetricsAndSegmentWhenCalledOnce() throws Exception { */ @Test public void shouldSetMetricsAndSegmentOnceWhenCalledTwice() throws Exception { - MetricState target = new MetricState(); int nCalls = 2; - TraceSegment callGetResponseCodeSegment = runAndVerifyFirstCall(target, nCalls); + TraceSegment callGetResponseCodeSegment = runAndVerifyFirstCall(new InstrumentedHttpUrlConnection(server), nCalls); // The second call to getResponseCode is named Custom/../methodName because it doesn't result in additional I/O. TraceSegment defaultName = callGetResponseCodeSegment.getChildren().get(1); assertEquals(1, defaultName.getCallCount()); - assertEquals("Custom/" + this.getClass().getName() + "/simulatedInstrumentedGetResponseCodeMethod", defaultName.getName()); + assertEquals("Custom/" + InstrumentedHttpUrlConnection.class.getName() + "/getResponseCode", defaultName.getName()); } - private TraceSegment runAndVerifyFirstCall(MetricState target, int nCalls) throws Exception { + private TraceSegment runAndVerifyFirstCall(InstrumentedHttpUrlConnection conn, int nCalls) throws Exception { Introspector introspector = InstrumentationTestRunner.getIntrospector(); - callGetResponseCode(target, nCalls); + callGetResponseCode(conn, nCalls); // The name of the @Trace(dispatcher = true) method String transactionName = fetchTransactionName(introspector, "callGetResponseCode"); @@ -72,7 +74,7 @@ private TraceSegment runAndVerifyFirstCall(MetricState target, int nCalls) throw assertEquals(nCalls, callGetResponseCodeSegment.getChildren().size()); // Only the first call is named External/.../getResponseCode - TraceSegment renamedSegment = callGetResponseCodeSegment.getChildren().get(0).getChildren().get(0); + TraceSegment renamedSegment = callGetResponseCodeSegment.getChildren().get(0); assertEquals(1, renamedSegment.getCallCount()); assertEquals("External/localhost/HttpURLConnection/getResponseCode", renamedSegment.getName()); return callGetResponseCodeSegment; @@ -85,28 +87,30 @@ private TraceSegment runAndVerifyFirstCall(MetricState target, int nCalls) throw @Test public void shouldBumpMetricOnceIfAlreadyHaveResponseCode() throws Exception { Introspector introspector = InstrumentationTestRunner.getIntrospector(); - MetricState target = new MetricState(); - callGetResponseCodeThenGetInputStream(target); + callGetResponseCodeThenGetInputStream(); // Only one external call. String transactionName = fetchTransactionName(introspector, "callGetResponseCodeThenGetInputStream"); - assertTrue(introspector.getMetricsForTransaction(transactionName).containsKey("External/localhost/HttpURLConnection/getResponseCode")); - assertEquals(1, introspector.getMetricsForTransaction(transactionName).get("External/localhost/HttpURLConnection/getResponseCode").getCallCount()); + Map metricsForTransaction = introspector.getMetricsForTransaction(transactionName); + long externalMetricsCount = metricsForTransaction.keySet().stream().filter(metricName -> metricName.startsWith("External")).count(); + assertEquals(1, externalMetricsCount); + assertTrue(metricsForTransaction.containsKey("External/localhost/HttpURLConnection/getResponseCode")); + assertEquals(1, metricsForTransaction.get("External/localhost/HttpURLConnection/getResponseCode").getCallCount()); // Two child segments within the transaction. TransactionTrace trace = introspector.getTransactionTracesForTransaction(transactionName).iterator().next(); TraceSegment traceSegment = trace.getInitialTraceSegment(); assertEquals(2, traceSegment.getChildren().size()); - // The child of the first segment is external. - TraceSegment renamedSegment = traceSegment.getChildren().get(0).getChildren().get(0); + // The first segment is external. + TraceSegment renamedSegment = traceSegment.getChildren().get(0); assertEquals(1, renamedSegment.getCallCount()); assertEquals("External/localhost/HttpURLConnection/getResponseCode", renamedSegment.getName()); // The second is a normal method call. TraceSegment defaultName = traceSegment.getChildren().get(1); assertEquals(1, defaultName.getCallCount()); - assertEquals("Custom/" + this.getClass().getName() + "/simulatedInstrumentedGetInputStreamMethod", defaultName.getName()); + assertEquals("Custom/" + InstrumentedHttpUrlConnection.class.getName() + "/getInputStream", defaultName.getName()); } /** @@ -116,13 +120,15 @@ public void shouldBumpMetricOnceIfAlreadyHaveResponseCode() throws Exception { @Test public void shouldBumpMetricOnceIfAlreadyHaveInputStream() throws Exception { Introspector introspector = InstrumentationTestRunner.getIntrospector(); - MetricState target = new MetricState(); - callGetInputStreamThenResponseCode(target); + callGetInputStreamThenResponseCode(); // Only one external call. String transactionName = fetchTransactionName(introspector, "callGetInputStreamThenResponseCode"); - assertTrue(introspector.getMetricsForTransaction(transactionName).containsKey("External/localhost/HttpURLConnection/getInputStream")); - assertEquals(1, introspector.getMetricsForTransaction(transactionName).get("External/localhost/HttpURLConnection/getInputStream").getCallCount()); + Map metricsForTransaction = introspector.getMetricsForTransaction(transactionName); + long externalMetricsCount = metricsForTransaction.keySet().stream().filter(metricName -> metricName.startsWith("External")).count(); + assertEquals(1, externalMetricsCount); + assertTrue(metricsForTransaction.containsKey("External/localhost/HttpURLConnection/getInputStream")); + assertEquals(1, metricsForTransaction.get("External/localhost/HttpURLConnection/getInputStream").getCallCount()); // Two child segments within the transaction. TransactionTrace trace = introspector.getTransactionTracesForTransaction(transactionName).iterator().next(); @@ -130,14 +136,43 @@ public void shouldBumpMetricOnceIfAlreadyHaveInputStream() throws Exception { assertEquals(2, traceSegment.getChildren().size()); // The first segment is external. - TraceSegment renamedSegment = traceSegment.getChildren().get(0).getChildren().get(0); + TraceSegment renamedSegment = traceSegment.getChildren().get(0); assertEquals(1, renamedSegment.getCallCount()); assertEquals("External/localhost/HttpURLConnection/getInputStream", renamedSegment.getName()); // The second is a normal method call. TraceSegment defaultName = traceSegment.getChildren().get(1); assertEquals(1, defaultName.getCallCount()); - assertEquals("Custom/" + this.getClass().getName() + "/simulatedInstrumentedGetResponseCodeMethod", defaultName.getName()); + assertEquals("Custom/" + InstrumentedHttpUrlConnection.class.getName() + "/getResponseCode", defaultName.getName()); + } + + @Test + public void connectResponseMessageTest() throws Exception { + Introspector introspector = InstrumentationTestRunner.getIntrospector(); + callConnectThenGetMessage(); + + // Only one external call. + String transactionName = fetchTransactionName(introspector, "callConnectThenGetMessage"); + Map metricsForTransaction = introspector.getMetricsForTransaction(transactionName); + long externalMetricsCount = metricsForTransaction.keySet().stream().filter(metricName -> metricName.startsWith("External")).count(); + assertEquals(1, externalMetricsCount); + assertTrue(metricsForTransaction.containsKey("External/localhost/HttpURLConnection/getResponseMessage")); + assertEquals(1, metricsForTransaction.get("External/localhost/HttpURLConnection/getResponseMessage").getCallCount()); + + // Two child segments within the transaction. + TransactionTrace trace = introspector.getTransactionTracesForTransaction(transactionName).iterator().next(); + TraceSegment traceSegment = trace.getInitialTraceSegment(); + assertEquals(2, traceSegment.getChildren().size()); + + // The first s. + TraceSegment defaultName = traceSegment.getChildren().get(0); + assertEquals(1, defaultName.getCallCount()); + assertEquals("Custom/" + InstrumentedHttpUrlConnection.class.getName() + "/connect", defaultName.getName()); + + // The second is a normal method call. + TraceSegment renamedSegment = traceSegment.getChildren().get(1); + assertEquals(1, renamedSegment.getCallCount()); + assertEquals("External/localhost/HttpURLConnection/getResponseMessage", renamedSegment.getName()); } private String fetchTransactionName(Introspector introspector, String expectedMethod) { @@ -148,64 +183,37 @@ private String fetchTransactionName(Introspector introspector, String expectedMe for (TransactionEvent event : introspector.getTransactionEvents(transactionName)) { foundExpectedEvent = foundExpectedEvent || event.getName().endsWith("/" + expectedMethod); } - assertTrue("Did not find an event ending in callGetResponseCode", foundExpectedEvent); + assertTrue("Did not find an event ending in " + expectedMethod, foundExpectedEvent); return transactionName; } - @Rule - public HttpServerRule server = new HttpServerRule(); - - private URL getURL() throws Exception { - return server.getEndPoint().toURL(); - } - @Trace(dispatcher = true) // NOTE: Method name is used as a string in the metric! - public void callGetResponseCode(MetricState target, int nCalls) throws Exception { + private void callGetResponseCode(InstrumentedHttpUrlConnection target, int nCalls) throws Exception { assertTrue(nCalls > 0); - URLConnection connection = getURL().openConnection(); - assertTrue(connection instanceof HttpURLConnection); - HttpURLConnection conn = (HttpURLConnection) connection; - for (int i = 0; i < nCalls; i++) { - simulatedInstrumentedGetResponseCodeMethod(conn, target); + target.getResponseCode(); } } @Trace(dispatcher = true) - public void callGetResponseCodeThenGetInputStream(MetricState target) throws Exception { - URLConnection connection = getURL().openConnection(); - assertTrue(connection instanceof HttpURLConnection); - HttpURLConnection conn = (HttpURLConnection) connection; - - simulatedInstrumentedGetResponseCodeMethod(conn, target); - simulatedInstrumentedGetInputStreamMethod(true, conn, target); + private void callGetResponseCodeThenGetInputStream() throws Exception { + InstrumentedHttpUrlConnection connection = new InstrumentedHttpUrlConnection(server); + connection.getResponseCode(); + connection.getInputStream(true); } @Trace(dispatcher = true) - public void callGetInputStreamThenResponseCode(MetricState target) throws Exception { - URLConnection connection = getURL().openConnection(); - assertTrue(connection instanceof HttpURLConnection); - HttpURLConnection conn = (HttpURLConnection) connection; - - simulatedInstrumentedGetInputStreamMethod(false, conn, target); - simulatedInstrumentedGetResponseCodeMethod(conn, target); + private void callGetInputStreamThenResponseCode() throws Exception { + InstrumentedHttpUrlConnection connection = new InstrumentedHttpUrlConnection(server); + connection.getInputStream(false); + connection.getResponseCode(); } - /** - * The purpose of this method is to simulate the woven method from the instrumentation - * code. Since we can't weave JRE classes in these tests, we can't use the "real" code. - * This is the best approximation. - */ - @Trace - private void simulatedInstrumentedGetResponseCodeMethod(HttpURLConnection conn, MetricState target) { - target.getResponseCodePreamble(AgentBridge.getAgent().getTracedMethod()); - target.getInboundPostamble(conn, 0, null, "getResponseCode", AgentBridge.getAgent().getTracedMethod()); - } - - @Trace - private void simulatedInstrumentedGetInputStreamMethod(boolean isConnected, HttpURLConnection conn, MetricState target) { - target.getInputStreamPreamble(isConnected, conn, AgentBridge.getAgent().getTracedMethod()); - target.getInboundPostamble(conn, 0, null, "getInputStream", AgentBridge.getAgent().getTracedMethod()); + @Trace(dispatcher = true) + private void callConnectThenGetMessage() throws Exception { + InstrumentedHttpUrlConnection connection = new InstrumentedHttpUrlConnection(server); + connection.connect(false); + connection.getResponseMessage(); } } diff --git a/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/InstrumentedHttpUrlConnection.java b/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/InstrumentedHttpUrlConnection.java new file mode 100644 index 0000000000..87a86e41dc --- /dev/null +++ b/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/InstrumentedHttpUrlConnection.java @@ -0,0 +1,68 @@ +/* + * + * * Copyright 2023 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package com.nr.agent.instrumentation.httpurlconnection; + +import com.newrelic.agent.bridge.AgentBridge; +import com.newrelic.agent.bridge.TracedMethod; +import com.newrelic.agent.introspec.internal.HttpServerRule; +import com.newrelic.api.agent.Trace; + +import java.io.IOException; +import java.net.HttpURLConnection; +import java.net.URISyntaxException; +import java.net.URLConnection; + +import static org.junit.Assert.assertTrue; + +/** + * The purpose of this class is to simulate the woven HttpUrlConnection. + * Since we can't weave JRE classes in these tests, we can't use the "real" code. + * This is the best approximation. + */ +public class InstrumentedHttpUrlConnection { + private MetricState metricState; + private HttpURLConnection realConnection; + + public InstrumentedHttpUrlConnection(HttpServerRule server) throws URISyntaxException, IOException { + URLConnection connection = server.getEndPoint().toURL().openConnection(); + assertTrue(connection instanceof HttpURLConnection); + this.realConnection = (HttpURLConnection) connection; + + this.metricState = new MetricState(); + } + + @Trace(leaf = true) + public void connect(boolean isConnected) { + metricState.nonNetworkPreamble(isConnected, realConnection); + } + + @Trace(leaf = true) + public void getResponseCode() { + TracedMethod tracedMethod = AgentBridge.getAgent().getTracedMethod(); + metricState.inboundPreamble(false, realConnection, tracedMethod); + metricState.inboundPostamble(realConnection, 0, null, MetricState.Ops.GET_RESPONSE_CODE, tracedMethod); + } + + @Trace(leaf = true) + public void getInputStream(boolean isConnected) { + TracedMethod tracedMethod = AgentBridge.getAgent().getTracedMethod(); + metricState.inboundPreamble(isConnected, realConnection, tracedMethod); + metricState.inboundPostamble(realConnection, 0, null, MetricState.Ops.GET_INPUT_STREAM, tracedMethod); + } + + @Trace(leaf = true) + public void getResponseMessage() { + TracedMethod tracedMethod = AgentBridge.getAgent().getTracedMethod(); + metricState.inboundPreamble(false, realConnection, tracedMethod); + metricState.inboundPostamble(realConnection, 0, null, MetricState.Ops.GET_RESPONSE_MSG, tracedMethod); + } + + public HttpURLConnection getRealConnection() { + return realConnection; + } +} diff --git a/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/MetricStateConnectTest.java b/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/MetricStateConnectTest.java deleted file mode 100644 index 21bda6b66a..0000000000 --- a/instrumentation/httpurlconnection/src/test/java/com/nr/agent/instrumentation/httpurlconnection/MetricStateConnectTest.java +++ /dev/null @@ -1,99 +0,0 @@ -/* - * - * * Copyright 2020 New Relic Corporation. All rights reserved. - * * SPDX-License-Identifier: Apache-2.0 - * - */ - -package com.nr.agent.instrumentation.httpurlconnection; - -import com.newrelic.agent.introspec.InstrumentationTestConfig; -import com.newrelic.agent.introspec.InstrumentationTestRunner; -import com.newrelic.agent.introspec.Introspector; -import com.newrelic.agent.introspec.TransactionEvent; -import com.newrelic.agent.introspec.TransactionTrace; -import com.newrelic.agent.introspec.internal.HttpServerRule; -import com.newrelic.api.agent.Trace; -import org.junit.Assert; -import org.junit.Rule; -import org.junit.Test; -import org.junit.runner.RunWith; - -import java.net.HttpURLConnection; -import java.net.URL; -import java.net.URLConnection; - -import static org.junit.Assert.assertEquals; -import static org.junit.Assert.assertFalse; -import static org.junit.Assert.assertNotEquals; -import static org.junit.Assert.assertTrue; - -@RunWith(InstrumentationTestRunner.class) -@InstrumentationTestConfig(includePrefixes = { "leave-me-alone" }, configName = "distributed_tracing.yml") -public class MetricStateConnectTest { - // This timeout is required if connect is the only HttpURLConnection API called - private static final int TEST_SLEEP_TIME_MILLIS = 7_000; - - @Rule - public HttpServerRule server = new HttpServerRule(); - - private URL getURL() throws Exception { - return server.getEndPoint().toURL(); - } - - @Test - public void shouldNotSetMetricIfOnlyConnectIsCalled() throws Exception { - Introspector introspector = InstrumentationTestRunner.getIntrospector(); - String transactionName = runTransactionAndIntrospect(introspector, false); - - TransactionTrace trace = introspector.getTransactionTracesForTransaction(transactionName).iterator().next(); - - assertEquals("Java/com.nr.agent.instrumentation.httpurlconnection.MetricStateConnectTest/callConnect", trace.getInitialTraceSegment().getName()); - assertFalse(introspector.getMetricsForTransaction(transactionName).containsKey("External/localhost/HttpURLConnection/connect")); - - String defaultMetricName = transactionName.replace("OtherTransaction/Custom", "Java"); - assertEquals(defaultMetricName, trace.getInitialTraceSegment().getName()); - assertTrue(introspector.getMetricsForTransaction(transactionName).containsKey(defaultMetricName)); - } - - @Test - public void shouldNotSetMetricOnSecondConnect() throws Exception { - Introspector introspector = InstrumentationTestRunner.getIntrospector(); - String transactionName = runTransactionAndIntrospect(introspector, true); - - TransactionTrace trace = introspector.getTransactionTracesForTransaction(transactionName).iterator().next(); - - assertNotEquals("External/localhost/HttpURLConnection/connect", trace.getInitialTraceSegment().getName()); - assertFalse(introspector.getMetricsForTransaction(transactionName).containsKey("External/localhost/HttpURLConnection/connect")); - - String defaultMetricName = transactionName.replace("OtherTransaction/Custom", "Java"); - assertEquals(defaultMetricName, trace.getInitialTraceSegment().getName()); - assertTrue(introspector.getMetricsForTransaction(transactionName).containsKey(defaultMetricName)); - } - - private String runTransactionAndIntrospect(Introspector introspector, boolean pretendToBeConnected) throws Exception { - MetricState target = new MetricState(); - callConnect(target, pretendToBeConnected); - - assertEquals(1, introspector.getFinishedTransactionCount(500)); - - String transactionName = introspector.getTransactionNames().iterator().next(); - boolean foundExpectedEvent = false; - for (TransactionEvent event : introspector.getTransactionEvents(transactionName)) { - foundExpectedEvent = foundExpectedEvent || event.getName().endsWith("/callConnect"); - } - assertTrue("Did not find an event ending in callConnect", foundExpectedEvent); - return transactionName; - } - - @Trace(dispatcher = true) // NOTE: Method name is used as a string in the metric! - public void callConnect(MetricState target, boolean pretendToBeConnected) throws Exception { - URLConnection connection = getURL().openConnection(); - Assert.assertTrue(connection instanceof HttpURLConnection); - HttpURLConnection conn = (HttpURLConnection) connection; - - target.nonNetworkPreamble(pretendToBeConnected, conn, "connect"); - // sleep long enough for the connect TimerTask to complete - Thread.sleep(TEST_SLEEP_TIME_MILLIS); - } -}