Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[SPARK-48490][CORE] Unescapes any literals for message of MessageWithContext #46824

Closed
wants to merge 2 commits into from
Closed

[SPARK-48490][CORE] Unescapes any literals for message of MessageWithContext #46824

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
31fb7c2
[SPARK-48490][CORE] Unescapes any literals for message of MessageWith…
panbingkun May 31, 2024
a5d44a7
optimize
panbingkun May 31, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 2 additions & 1 deletion common/utils/src/main/scala/org/apache/spark/internal/Logging.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ package org.apache.spark.internal

import scala.jdk.CollectionConverters._

import org.apache.commons.text.StringEscapeUtils
import org.apache.logging.log4j.{CloseableThreadContext, Level, LogManager}
import org.apache.logging.log4j.core.{Filter, LifeCycle, LogEvent, Logger => Log4jLogger, LoggerContext}
import org.apache.logging.log4j.core.appender.ConsoleAppender
Expand Down Expand Up @@ -99,7 +100,7 @@ case class MessageWithContext(message: String, context: java.util.HashMap[String
* Companion class for lazy evaluation of the MessageWithContext instance.
*/
class LogEntry(messageWithContext: => MessageWithContext) {
def message: String = messageWithContext.message
def message: String = StringEscapeUtils.unescapeJava(messageWithContext.message)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi, @panbingkun and @gengliangwang .

This seems to break SparkR somehow. Could you take a look at this?

-- Error ('test_basic.R:25:3'): create DataFrame from list or data.frame -------
Error in `handleErrors(returnStatus, conn)`: java.lang.IllegalArgumentException: Unable to parse unicode value: serF
	at org.apache.commons.text.translate.UnicodeUnescaper.translate(UnicodeUnescaper.java:55)
	at org.apache.commons.text.translate.AggregateTranslator.translate(AggregateTranslator.java:58)
	at org.apache.commons.text.translate.CharSequenceTranslator.translate(CharSequenceTranslator.java:101)
	at org.apache.commons.text.translate.CharSequenceTranslator.translate(CharSequenceTranslator.java:63)
	at org.apache.commons.text.StringEscapeUtils.unescapeJava(StringEscapeUtils.java:802)
	at org.apache.spark.internal.LogEntry.message(Logging.scala:103)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, Let me investigate it

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@dongjoon-hyun
I have identified the root cause of this issue and am currently attempting to fix it
#46897 (comment)


def context: java.util.HashMap[String, String] = messageWithContext.context
}
Expand Down
6 changes: 6 additions & 0 deletions common/utils/src/test/java/org/apache/spark/util/PatternSparkLoggerSuite.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,12 @@ String expectedPatternForBasicMsg(Level level) {
return toRegexPattern(level, ".*<level> <className>: This is a log message\n");
}

@Override
String expectedPatternForBasicMsgWithEscapeChar(Level level) {
return toRegexPattern(level,
".*<level> <className>: This is a log message\\nThis is a new line \\t other msg\\n");
}

@Override
String expectedPatternForBasicMsgWithException(Level level) {
return toRegexPattern(level, """
Expand Down
53 changes: 37 additions & 16 deletions common/utils/src/test/java/org/apache/spark/util/SparkLoggerSuiteBase.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -68,16 +68,17 @@ private void checkLogOutput(Level level, Runnable func, ExpectedResult result) {
}
}

private String basicMsg() {
return "This is a log message";
}
private final String basicMsg = "This is a log message";

private final String basicMsgWithEscapeChar =
"This is a log message\nThis is a new line \t other msg";

private final MDC executorIDMDC = MDC.of(LogKeys.EXECUTOR_ID$.MODULE$, "1");
private final String msgWithMDC = "Lost executor {}.";

private final MDC[] mdcs = new MDC[] {
MDC.of(LogKeys.EXECUTOR_ID$.MODULE$, "1"),
MDC.of(LogKeys.REASON$.MODULE$, "the shuffle data is too large")};
MDC.of(LogKeys.EXECUTOR_ID$.MODULE$, "1"),
MDC.of(LogKeys.REASON$.MODULE$, "the shuffle data is too large")};
private final String msgWithMDCs = "Lost executor {}, reason: {}";

private final MDC executorIDMDCValueIsNull = MDC.of(LogKeys.EXECUTOR_ID$.MODULE$, null);
Expand All @@ -91,6 +92,9 @@ private String basicMsg() {
// test for basic message (without any mdc)
abstract String expectedPatternForBasicMsg(Level level);

// test for basic message (with escape char)
abstract String expectedPatternForBasicMsgWithEscapeChar(Level level);

// test for basic message and exception
abstract String expectedPatternForBasicMsgWithException(Level level);

Expand All @@ -113,12 +117,12 @@ private String basicMsg() {
abstract String expectedPatternForJavaCustomLogKey(Level level);

@Test
public void testBasicMsgLogger() {
Runnable errorFn = () -> logger().error(basicMsg());
Runnable warnFn = () -> logger().warn(basicMsg());
Runnable infoFn = () -> logger().info(basicMsg());
Runnable debugFn = () -> logger().debug(basicMsg());
Runnable traceFn = () -> logger().trace(basicMsg());
public void testBasicMsg() {
Runnable errorFn = () -> logger().error(basicMsg);
Runnable warnFn = () -> logger().warn(basicMsg);
Runnable infoFn = () -> logger().info(basicMsg);
Runnable debugFn = () -> logger().debug(basicMsg);
Runnable traceFn = () -> logger().trace(basicMsg);
List.of(
Pair.of(Level.ERROR, errorFn),
Pair.of(Level.WARN, warnFn),
Expand All @@ -128,14 +132,31 @@ public void testBasicMsgLogger() {
checkLogOutput(pair.getLeft(), pair.getRight(), this::expectedPatternForBasicMsg));
}

@Test
public void testBasicMsgWithEscapeChar() {
Runnable errorFn = () -> logger().error(basicMsgWithEscapeChar);
Runnable warnFn = () -> logger().warn(basicMsgWithEscapeChar);
Runnable infoFn = () -> logger().info(basicMsgWithEscapeChar);
Runnable debugFn = () -> logger().debug(basicMsgWithEscapeChar);
Runnable traceFn = () -> logger().trace(basicMsgWithEscapeChar);
List.of(
Pair.of(Level.ERROR, errorFn),
Pair.of(Level.WARN, warnFn),
Pair.of(Level.INFO, infoFn),
Pair.of(Level.DEBUG, debugFn),
Pair.of(Level.TRACE, traceFn)).forEach(pair ->
checkLogOutput(pair.getLeft(), pair.getRight(),
this::expectedPatternForBasicMsgWithEscapeChar));
}

@Test
public void testBasicLoggerWithException() {
Throwable exception = new RuntimeException("OOM");
Runnable errorFn = () -> logger().error(basicMsg(), exception);
Runnable warnFn = () -> logger().warn(basicMsg(), exception);
Runnable infoFn = () -> logger().info(basicMsg(), exception);
Runnable debugFn = () -> logger().debug(basicMsg(), exception);
Runnable traceFn = () -> logger().trace(basicMsg(), exception);
Runnable errorFn = () -> logger().error(basicMsg, exception);
Runnable warnFn = () -> logger().warn(basicMsg, exception);
Runnable infoFn = () -> logger().info(basicMsg, exception);
Runnable debugFn = () -> logger().debug(basicMsg, exception);
Runnable traceFn = () -> logger().trace(basicMsg, exception);
List.of(
Pair.of(Level.ERROR, errorFn),
Pair.of(Level.WARN, warnFn),
Expand Down
11 changes: 11 additions & 0 deletions common/utils/src/test/java/org/apache/spark/util/StructuredSparkLoggerSuite.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -69,6 +69,17 @@ String expectedPatternForBasicMsg(Level level) {
}""");
}

@Override
String expectedPatternForBasicMsgWithEscapeChar(Level level) {
return compactAndToRegexPattern(level, """
{
"ts": "<timestamp>",
"level": "<level>",
"msg": "This is a log message\\\\nThis is a new line \\\\t other msg",
"logger": "<className>"
}""");
}

@Override
String expectedPatternForBasicMsgWithException(Level level) {
return compactAndToRegexPattern(level, """
Expand Down
8 changes: 8 additions & 0 deletions common/utils/src/test/scala/org/apache/spark/util/PatternLoggingSuite.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,14 @@ class PatternLoggingSuite extends LoggingSuiteBase with BeforeAndAfterAll {
s""".*$level $className: This is a log message\n"""
}

override def expectedPatternForBasicMsgWithEscapeChar(level: Level): String = {
s""".*$level $className: This is a log message\nThis is a new line \t other msg\n"""
}

override def expectedPatternForBasicMsgWithEscapeCharMDC(level: Level): String = {
s""".*$level $className: This is a log message\nThis is a new line \t other msg\n"""
}

override def expectedPatternForBasicMsgWithException(level: Level): String = {
s""".*$level $className: This is a log message\n[\\s\\S]*"""
}
Expand Down
57 changes: 57 additions & 0 deletions common/utils/src/test/scala/org/apache/spark/util/StructuredLoggingSuite.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,11 @@ trait LoggingSuiteBase

def basicMsg: String = "This is a log message"

def basicMsgWithEscapeChar: String = "This is a log message\nThis is a new line \t other msg"

def basicMsgWithEscapeCharMDC: LogEntry =
log"This is a log message\nThis is a new line \t other msg"

def msgWithMDC: LogEntry = log"Lost executor ${MDC(LogKeys.EXECUTOR_ID, "1")}."

def msgWithMDCValueIsNull: LogEntry = log"Lost executor ${MDC(LogKeys.EXECUTOR_ID, null)}."
Expand All @@ -66,6 +71,12 @@ trait LoggingSuiteBase
// test for basic message (without any mdc)
def expectedPatternForBasicMsg(level: Level): String

// test for basic message (with escape char)
def expectedPatternForBasicMsgWithEscapeChar(level: Level): String

// test for basic message (with escape char mdc)
def expectedPatternForBasicMsgWithEscapeCharMDC(level: Level): String

// test for basic message and exception
def expectedPatternForBasicMsgWithException(level: Level): String

Expand Down Expand Up @@ -95,6 +106,30 @@ trait LoggingSuiteBase
}
}

test("Basic logging with escape char") {
Seq(
(Level.ERROR, () => logError(basicMsgWithEscapeChar)),
(Level.WARN, () => logWarning(basicMsgWithEscapeChar)),
(Level.INFO, () => logInfo(basicMsgWithEscapeChar)),
(Level.DEBUG, () => logDebug(basicMsgWithEscapeChar)),
(Level.TRACE, () => logTrace(basicMsgWithEscapeChar))).foreach { case (level, logFunc) =>
val logOutput = captureLogOutput(logFunc)
assert(expectedPatternForBasicMsgWithEscapeChar(level).r.matches(logOutput))
}
}

test("Basic logging with escape char MDC") {
Seq(
(Level.ERROR, () => logError(basicMsgWithEscapeCharMDC)),
(Level.WARN, () => logWarning(basicMsgWithEscapeCharMDC)),
(Level.INFO, () => logInfo(basicMsgWithEscapeCharMDC)),
(Level.DEBUG, () => logDebug(basicMsgWithEscapeCharMDC)),
(Level.TRACE, () => logTrace(basicMsgWithEscapeCharMDC))).foreach { case (level, logFunc) =>
val logOutput = captureLogOutput(logFunc)
assert(expectedPatternForBasicMsgWithEscapeCharMDC(level).r.matches(logOutput))
}
}

test("Basic logging with Exception") {
val exception = new RuntimeException("OOM")
Seq(
Expand Down Expand Up @@ -197,6 +232,28 @@ class StructuredLoggingSuite extends LoggingSuiteBase {
}""")
}

override def expectedPatternForBasicMsgWithEscapeChar(level: Level): String = {
compactAndToRegexPattern(
s"""
{
"ts": "<timestamp>",
"level": "$level",
"msg": "This is a log message\\\\nThis is a new line \\\\t other msg",
"logger": "$className"
}""")
}

override def expectedPatternForBasicMsgWithEscapeCharMDC(level: Level): String = {
compactAndToRegexPattern(
s"""
{
"ts": "<timestamp>",
"level": "$level",
"msg": "This is a log message\\\\nThis is a new line \\\\t other msg",
"logger": "$className"
}""")
}

override def expectedPatternForBasicMsgWithException(level: Level): String = {
compactAndToRegexPattern(
s"""
Expand Down