From ae22f8dbbbe3ca4aac8376bb047b0b283d34d568 Mon Sep 17 00:00:00 2001 From: Jerry Duffy Date: Mon, 30 Dec 2024 09:34:57 -0500 Subject: [PATCH 1/4] Fix edge case in JsonTemplateLayout with certain escaped sequences --- .../layout/template/json/AgentUtils.java | 28 ++++--- .../layout/template/json/AgentUtilsTest.java | 74 +++++++++++++++++++ 2 files changed, 93 insertions(+), 9 deletions(-) create mode 100644 instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java diff --git a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java index 8610227679..314005fe33 100644 --- a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java +++ b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java @@ -10,6 +10,8 @@ import org.apache.logging.log4j.core.LogEvent; import java.util.Map; +import java.util.regex.Matcher; +import java.util.regex.Pattern; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.BLOB_PREFIX; import static com.newrelic.agent.bridge.logging.AppLoggingUtils.getLinkingMetadataBlob; @@ -18,6 +20,11 @@ import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingLocalDecoratingEnabled; public class AgentUtils { + // Detect the end of the "message" field when it's not the last field -- ", + private static final Pattern JSON_MESSAGE_VALUE_END = Pattern.compile("\"message\".+?[^\\\\](\",)"); + // Detect the end of the "message" field when it is the last field -- "} + private static final Pattern JSON_MESSAGE_VALUE_END2 = Pattern.compile("\"message\".+?(\"})"); + /** * 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 @@ -27,17 +34,20 @@ public class AgentUtils { * @return positive int if index was found, else -1 */ public static int getIndexToModifyJson(String writerString) { - int msgIndex = writerString.indexOf("message"); - if (msgIndex < 0) { - return msgIndex; - } - // If the "message" field is before other fields in the json string - int index = writerString.indexOf("\",", msgIndex); + int index = -1; + Matcher matcher = JSON_MESSAGE_VALUE_END.matcher(writerString); - if (index < 0 ) { - // If "message" is the last field in the json string - index = writerString.indexOf("\"}", msgIndex); + if (matcher.find()) { + // Group 1 in the match is the ", char sequence + index = matcher.start(1); + } else { + matcher = JSON_MESSAGE_VALUE_END2.matcher(writerString); + if (matcher.find()) { + // Group 1 in the match is "} + index = matcher.start(1); + } } + return index; } diff --git a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java new file mode 100644 index 0000000000..cbffa71d2e --- /dev/null +++ b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java @@ -0,0 +1,74 @@ +/* + * + * * Copyright 2024 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ +package com.nr.agent.instrumentation.log4j2.layout.template.json; + +import com.newrelic.agent.bridge.Agent; +import com.newrelic.agent.bridge.AgentBridge; +import com.newrelic.api.agent.Config; +import com.newrelic.api.agent.Logger; +import org.apache.logging.log4j.core.LogEvent; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + +import java.util.logging.Level; + +import static org.mockito.Mockito.*; +import static org.junit.Assert.*; + +public class AgentUtilsTest { + private static final String LOG_JSON_WITH_MESSAGE_FIELD_ESCAPED_QUOTE_COMMA = "{\"instant\" : {\"epochSecond\" : 1734983121,\"nanoOfSecond\" : 537701000},\"level\" : \"INFO\",\"loggerName\" : \"org.hibernate.validator.internal.util.Version\",\"message\" : \"info \\\"bar\\\",\",\"endOfBatch\" : true,\"loggerFqcn\" : \"org.hibernate.validator.internal.util.logging.Log_$logger\"}\n"; + private static final String LOG_JSON_WITH_MESSAGE_LAST_FIELD_ESCAPED_QUOTE_COMMA = "{\"instant\": {\"epochSecond\": 1734983121,\"nanoOfSecond\": 537701000},\"level\": \"INFO\",\"loggerName\": \"org.hibernate.validator.internal.util.Version\",\"endOfBatch\": true,\"loggerFqcn\": \"org.hibernate.validator.internal.util.logging.Log_$logger\",\"message\": \"info \\\"bar\\\",\"}"; + private static final String LOG_JSON_WITH_MESSAGE_FIELD = "{\"instant\" : {\"epochSecond\" : 1734983121,\"nanoOfSecond\" : 537701000},\"level\" : \"INFO\",\"loggerName\" : \"org.hibernate.validator.internal.util.Version\",\"message\" : \"normal msg text\",\"endOfBatch\" : true,\"loggerFqcn\" : \"org.hibernate.validator.internal.util.logging.Log_$logger\"}\n"; + private static final String LOG_JSON_NO_MESSAGE_FIELD = "{\"instant\": {\"epochSecond\": 1734983121,\"nanoOfSecond\": 537701000},\"level\": \"INFO\",\"loggerName\": \"org.hibernate.validator.internal.util.Version\",\"endOfBatch\": true,\"loggerFqcn\": \"org.hibernate.validator.internal.util.logging.Log_$logger\",\"foobar\": \"info \\\"bar\\\",\"}"; + + private final Agent originalAgent = AgentBridge.getAgent(); + private final Agent mockAgent = mock(Agent.class); + private final Logger mockLogger = mock(Logger.class); + private final Config mockConfig = mock(Config.class); + + private final LogEvent mockLockEvent = mock(LogEvent.class); + + @Before + public void before() { + AgentBridge.agent = mockAgent; + when(mockAgent.getConfig()).thenReturn(mockConfig); + when(mockAgent.getLogger()).thenReturn(mockLogger); + when(mockLogger.isLoggable(Level.FINEST)).thenReturn(false); + } + + @After + public void after() { + AgentBridge.agent = originalAgent; + } + + @Test + public void getIndexToModifyJson_withMessageField_findsProperIndex() { + assertEquals(175, AgentUtils.getIndexToModifyJson(LOG_JSON_WITH_MESSAGE_FIELD_ESCAPED_QUOTE_COMMA)); + assertEquals(262, AgentUtils.getIndexToModifyJson(LOG_JSON_WITH_MESSAGE_LAST_FIELD_ESCAPED_QUOTE_COMMA)); + } + + @Test + public void getIndexToModifyJson_withNoMessageField_returnsNegativeOne() { + assertEquals(-1, AgentUtils.getIndexToModifyJson(LOG_JSON_NO_MESSAGE_FIELD)); + } + + @Test + public void writeLinkingMetadata_addsMetadataProperly() { + // This simply validates that the NR_LINKING payload is being inserted into the message properly even + // though the payload is incomplete + when(mockConfig.getValue(anyString(), anyBoolean())).thenReturn(true); + + StringBuilder sb = new StringBuilder(LOG_JSON_WITH_MESSAGE_FIELD_ESCAPED_QUOTE_COMMA); + AgentUtils.writeLinkingMetadata(mockLockEvent, sb); + assertTrue(sb.toString().contains("\"message\" : \"info \\\"bar\\\", NR-LINKING|\"")); + + sb = new StringBuilder(LOG_JSON_WITH_MESSAGE_FIELD); + AgentUtils.writeLinkingMetadata(mockLockEvent, sb); + assertTrue(sb.toString().contains("\"message\" : \"normal msg text NR-LINKING|\"")); + } +} From 79a28f820f00a035020dbe651e1cc8b4f1c72ace Mon Sep 17 00:00:00 2001 From: Jerry Duffy Date: Mon, 30 Dec 2024 10:03:30 -0500 Subject: [PATCH 2/4] Correct const name in test --- .../log4j2/layout/template/json/AgentUtilsTest.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java index cbffa71d2e..e622b73f10 100644 --- a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java +++ b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java @@ -22,7 +22,7 @@ public class AgentUtilsTest { private static final String LOG_JSON_WITH_MESSAGE_FIELD_ESCAPED_QUOTE_COMMA = "{\"instant\" : {\"epochSecond\" : 1734983121,\"nanoOfSecond\" : 537701000},\"level\" : \"INFO\",\"loggerName\" : \"org.hibernate.validator.internal.util.Version\",\"message\" : \"info \\\"bar\\\",\",\"endOfBatch\" : true,\"loggerFqcn\" : \"org.hibernate.validator.internal.util.logging.Log_$logger\"}\n"; - private static final String LOG_JSON_WITH_MESSAGE_LAST_FIELD_ESCAPED_QUOTE_COMMA = "{\"instant\": {\"epochSecond\": 1734983121,\"nanoOfSecond\": 537701000},\"level\": \"INFO\",\"loggerName\": \"org.hibernate.validator.internal.util.Version\",\"endOfBatch\": true,\"loggerFqcn\": \"org.hibernate.validator.internal.util.logging.Log_$logger\",\"message\": \"info \\\"bar\\\",\"}"; + private static final String LOG_JSON_WITH_MESSAGE_LAST_FIELD_ESCAPED_QUOTE_BRACE = "{\"instant\": {\"epochSecond\": 1734983121,\"nanoOfSecond\": 537701000},\"level\": \"INFO\",\"loggerName\": \"org.hibernate.validator.internal.util.Version\",\"endOfBatch\": true,\"loggerFqcn\": \"org.hibernate.validator.internal.util.logging.Log_$logger\",\"message\": \"info \\\"bar\\\",\"}"; private static final String LOG_JSON_WITH_MESSAGE_FIELD = "{\"instant\" : {\"epochSecond\" : 1734983121,\"nanoOfSecond\" : 537701000},\"level\" : \"INFO\",\"loggerName\" : \"org.hibernate.validator.internal.util.Version\",\"message\" : \"normal msg text\",\"endOfBatch\" : true,\"loggerFqcn\" : \"org.hibernate.validator.internal.util.logging.Log_$logger\"}\n"; private static final String LOG_JSON_NO_MESSAGE_FIELD = "{\"instant\": {\"epochSecond\": 1734983121,\"nanoOfSecond\": 537701000},\"level\": \"INFO\",\"loggerName\": \"org.hibernate.validator.internal.util.Version\",\"endOfBatch\": true,\"loggerFqcn\": \"org.hibernate.validator.internal.util.logging.Log_$logger\",\"foobar\": \"info \\\"bar\\\",\"}"; @@ -49,7 +49,7 @@ public void after() { @Test public void getIndexToModifyJson_withMessageField_findsProperIndex() { assertEquals(175, AgentUtils.getIndexToModifyJson(LOG_JSON_WITH_MESSAGE_FIELD_ESCAPED_QUOTE_COMMA)); - assertEquals(262, AgentUtils.getIndexToModifyJson(LOG_JSON_WITH_MESSAGE_LAST_FIELD_ESCAPED_QUOTE_COMMA)); + assertEquals(262, AgentUtils.getIndexToModifyJson(LOG_JSON_WITH_MESSAGE_LAST_FIELD_ESCAPED_QUOTE_BRACE)); } @Test From d7cb8da1a3b6c19b66ecb83e029783de0b0690db Mon Sep 17 00:00:00 2001 From: Jerry Duffy Date: Thu, 2 Jan 2025 10:00:01 -0500 Subject: [PATCH 3/4] Convert to a single regex; add perf test to test class --- .../layout/template/json/AgentUtils.java | 6 +-- .../layout/template/json/AgentUtilsTest.java | 51 ++++++++++++++++++- 2 files changed, 52 insertions(+), 5 deletions(-) diff --git a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java index 314005fe33..3eda1dcbf1 100644 --- a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java +++ b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java @@ -21,7 +21,7 @@ public class AgentUtils { // Detect the end of the "message" field when it's not the last field -- ", - private static final Pattern JSON_MESSAGE_VALUE_END = Pattern.compile("\"message\".+?[^\\\\](\",)"); + private static final Pattern JSON_MESSAGE_VALUE_END = Pattern.compile("\"message\".+?[^\\\\]((\",)|(\"}))"); // Detect the end of the "message" field when it is the last field -- "} private static final Pattern JSON_MESSAGE_VALUE_END2 = Pattern.compile("\"message\".+?(\"})"); @@ -40,13 +40,13 @@ public static int getIndexToModifyJson(String writerString) { if (matcher.find()) { // Group 1 in the match is the ", char sequence index = matcher.start(1); - } else { + } /*else { matcher = JSON_MESSAGE_VALUE_END2.matcher(writerString); if (matcher.find()) { // Group 1 in the match is "} index = matcher.start(1); } - } + }*/ return index; } diff --git a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java index e622b73f10..1273bb4465 100644 --- a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java +++ b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/test/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtilsTest.java @@ -15,6 +15,9 @@ import org.junit.Before; import org.junit.Test; +import java.util.ArrayList; +import java.util.List; +import java.util.Random; import java.util.logging.Level; import static org.mockito.Mockito.*; @@ -59,16 +62,60 @@ public void getIndexToModifyJson_withNoMessageField_returnsNegativeOne() { @Test public void writeLinkingMetadata_addsMetadataProperly() { - // This simply validates that the NR_LINKING payload is being inserted into the message properly even - // though the payload is incomplete when(mockConfig.getValue(anyString(), anyBoolean())).thenReturn(true); StringBuilder sb = new StringBuilder(LOG_JSON_WITH_MESSAGE_FIELD_ESCAPED_QUOTE_COMMA); AgentUtils.writeLinkingMetadata(mockLockEvent, sb); assertTrue(sb.toString().contains("\"message\" : \"info \\\"bar\\\", NR-LINKING|\"")); + sb = new StringBuilder(LOG_JSON_WITH_MESSAGE_LAST_FIELD_ESCAPED_QUOTE_BRACE); + AgentUtils.writeLinkingMetadata(mockLockEvent, sb); + assertTrue(sb.toString().contains("\"message\": \"info \\\"bar\\\", NR-LINKING|\"}")); + sb = new StringBuilder(LOG_JSON_WITH_MESSAGE_FIELD); AgentUtils.writeLinkingMetadata(mockLockEvent, sb); assertTrue(sb.toString().contains("\"message\" : \"normal msg text NR-LINKING|\"")); + + sb = new StringBuilder(LOG_JSON_NO_MESSAGE_FIELD); + AgentUtils.writeLinkingMetadata(mockLockEvent, sb); + assertFalse(sb.toString().contains("NR-LINKING|")); + + } + + // Leaving these next two methods here in case anyone wants to run a simple performance test of the regex matching. + // Simple uncomment the @Test annotation and run like a normal test. + //@Test + public void simplePerfTest() { + final String JSON_TEMPLATE = "{\"instant\" : {\"epochSecond\" : 1734983121,\"nanoOfSecond\" : 537701000},\"level\" : \"INFO\",\"loggerName\" : \"org.hibernate.validator.internal.util.Version\",\"message\" : \"{MSG_VAL}\",\"endOfBatch\" : true,\"loggerFqcn\" : \"org.hibernate.validator.internal.util.logging.Log_$logger\"}\n"; + final String ESCAPED_QUOTE_COMMA = "info \\\"bar\\\","; + final int LOOP_SIZE = 1000000; + Random random = new Random(); + List randomStringList = new ArrayList<>(); + + // Gen up a list of random Strings so we don't spend cycles in the actual timing loop creating them + for (int i=0; i= 90) { + AgentUtils.getIndexToModifyJson(JSON_TEMPLATE.replace("{MSG_VAL}", ESCAPED_QUOTE_COMMA)); + } else { + AgentUtils.getIndexToModifyJson(JSON_TEMPLATE.replace("{MSG_VAL}", randomStringList.get(i))); + } + } + System.out.println("Time ---> " + (System.currentTimeMillis() - start)); + } + + private static String generateRandomStr(int length) { + String CANDIDATE_CHARS = "ABCDEFGHIJKLMNOPQRSTUVWXYZ"; + StringBuilder sb = new StringBuilder(); + Random random = new Random(); + for (int i = 0; i < length; i ++) { + sb.append(CANDIDATE_CHARS.charAt(random.nextInt(26))); + } + + return sb.toString(); } } From 51a81f1fded375c32cf31cd13963b808fa06d27d Mon Sep 17 00:00:00 2001 From: Jerry Duffy Date: Thu, 2 Jan 2025 10:02:46 -0500 Subject: [PATCH 4/4] Code cleanup --- .../log4j2/layout/template/json/AgentUtils.java | 11 +---------- 1 file changed, 1 insertion(+), 10 deletions(-) diff --git a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java index 3eda1dcbf1..263a4a3445 100644 --- a/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java +++ b/instrumentation/apache-log4j-layout-template-json-2.14.0/src/main/java/com/nr/agent/instrumentation/log4j2/layout/template/json/AgentUtils.java @@ -20,10 +20,7 @@ import static com.newrelic.agent.bridge.logging.AppLoggingUtils.isApplicationLoggingLocalDecoratingEnabled; public class AgentUtils { - // Detect the end of the "message" field when it's not the last field -- ", private static final Pattern JSON_MESSAGE_VALUE_END = Pattern.compile("\"message\".+?[^\\\\]((\",)|(\"}))"); - // Detect the end of the "message" field when it is the last field -- "} - private static final Pattern JSON_MESSAGE_VALUE_END2 = Pattern.compile("\"message\".+?(\"})"); /** * Checks pretty or compact JSON layout strings for a series of characters and returns the index of @@ -40,13 +37,7 @@ public static int getIndexToModifyJson(String writerString) { if (matcher.find()) { // Group 1 in the match is the ", char sequence index = matcher.start(1); - } /*else { - matcher = JSON_MESSAGE_VALUE_END2.matcher(writerString); - if (matcher.find()) { - // Group 1 in the match is "} - index = matcher.start(1); - } - }*/ + } return index; }