From 00546bb2ab6823baf02123db7490a974fef6e939 Mon Sep 17 00:00:00 2001 From: panbingkun Date: Sun, 31 Mar 2024 11:35:47 +0800 Subject: [PATCH 1/2] [SPARK-47659][CORE][TESTS] Improve `*LoggingSuite*` --- .../spark/util/PatternLoggingSuite.scala | 13 ++- .../spark/util/StructuredLoggingSuite.scala | 101 +++++++++++++----- 2 files changed, 80 insertions(+), 34 deletions(-) diff --git a/common/utils/src/test/scala/org/apache/spark/util/PatternLoggingSuite.scala b/common/utils/src/test/scala/org/apache/spark/util/PatternLoggingSuite.scala index ef0aa7050b07..f46661ba2abb 100644 --- a/common/utils/src/test/scala/org/apache/spark/util/PatternLoggingSuite.scala +++ b/common/utils/src/test/scala/org/apache/spark/util/PatternLoggingSuite.scala @@ -16,24 +16,27 @@ */ package org.apache.spark.util +import org.apache.logging.log4j.Level import org.scalatest.BeforeAndAfterAll import org.apache.spark.internal.Logging class PatternLoggingSuite extends LoggingSuiteBase with BeforeAndAfterAll { - override protected def logFilePath: String = "target/pattern.log" + override def className: String = classOf[PatternLoggingSuite].getSimpleName + override def logFilePath: String = "target/pattern.log" override def beforeAll(): Unit = Logging.disableStructuredLogging() override def afterAll(): Unit = Logging.enableStructuredLogging() - override def expectedPatternForBasicMsg(level: String): String = - s""".*$level PatternLoggingSuite: This is a log message\n""" + override def expectedPatternForBasicMsg(level: Level): String = { + s""".*$level $className: This is a log message\n""" + } - override def expectedPatternForMsgWithMDC(level: String): String = + override def expectedPatternForMsgWithMDC(level: Level): String = s""".*$level PatternLoggingSuite: Lost executor 1.\n""" - override def expectedPatternForMsgWithMDCAndException(level: String): String = + override def expectedPatternForMsgWithMDCAndException(level: Level): String = s""".*$level PatternLoggingSuite: Error in executor 1.\njava.lang.RuntimeException: OOM\n.*""" } diff --git a/common/utils/src/test/scala/org/apache/spark/util/StructuredLoggingSuite.scala b/common/utils/src/test/scala/org/apache/spark/util/StructuredLoggingSuite.scala index 5dfd3bb46021..70a4f6aefadb 100644 --- a/common/utils/src/test/scala/org/apache/spark/util/StructuredLoggingSuite.scala +++ b/common/utils/src/test/scala/org/apache/spark/util/StructuredLoggingSuite.scala @@ -19,23 +19,28 @@ package org.apache.spark.util import java.io.File import java.nio.file.Files +import com.fasterxml.jackson.databind.ObjectMapper +import com.fasterxml.jackson.module.scala.DefaultScalaModule +import org.apache.logging.log4j.Level import org.scalatest.funsuite.AnyFunSuite // scalastyle:ignore funsuite import org.apache.spark.internal.{LogEntry, Logging, MDC} import org.apache.spark.internal.LogKey.EXECUTOR_ID -abstract class LoggingSuiteBase extends AnyFunSuite // scalastyle:ignore funsuite - with Logging { +trait LoggingSuiteBase + extends AnyFunSuite // scalastyle:ignore funsuite + with Logging { - protected def logFilePath: String + def className: String + def logFilePath: String - protected lazy val logFile: File = { + private lazy val logFile: File = { val pwd = new File(".").getCanonicalPath new File(pwd + "/" + logFilePath) } // Returns the first line in the log file that contains the given substring. - protected def captureLogOutput(f: () => Unit): String = { + private def captureLogOutput(f: () => Unit): String = { val content = if (logFile.exists()) { Files.readString(logFile.toPath) } else { @@ -52,18 +57,17 @@ abstract class LoggingSuiteBase extends AnyFunSuite // scalastyle:ignore funsuit def msgWithMDCAndException: LogEntry = log"Error in executor ${MDC(EXECUTOR_ID, "1")}." - def expectedPatternForBasicMsg(level: String): String + def expectedPatternForBasicMsg(level: Level): String - def expectedPatternForMsgWithMDC(level: String): String + def expectedPatternForMsgWithMDC(level: Level): String - def expectedPatternForMsgWithMDCAndException(level: String): String + def expectedPatternForMsgWithMDCAndException(level: Level): String test("Basic logging") { - val msg = "This is a log message" Seq( - ("ERROR", () => logError(msg)), - ("WARN", () => logWarning(msg)), - ("INFO", () => logInfo(msg))).foreach { case (level, logFunc) => + (Level.ERROR, () => logError(basicMsg)), + (Level.WARN, () => logWarning(basicMsg)), + (Level.INFO, () => logInfo(basicMsg))).foreach { case (level, logFunc) => val logOutput = captureLogOutput(logFunc) assert(expectedPatternForBasicMsg(level).r.matches(logOutput)) } @@ -71,9 +75,9 @@ abstract class LoggingSuiteBase extends AnyFunSuite // scalastyle:ignore funsuit test("Logging with MDC") { Seq( - ("ERROR", () => logError(msgWithMDC)), - ("WARN", () => logWarning(msgWithMDC)), - ("INFO", () => logInfo(msgWithMDC))).foreach { + (Level.ERROR, () => logError(msgWithMDC)), + (Level.WARN, () => logWarning(msgWithMDC)), + (Level.INFO, () => logInfo(msgWithMDC))).foreach { case (level, logFunc) => val logOutput = captureLogOutput(logFunc) assert(expectedPatternForMsgWithMDC(level).r.matches(logOutput)) @@ -83,9 +87,9 @@ abstract class LoggingSuiteBase extends AnyFunSuite // scalastyle:ignore funsuit test("Logging with MDC and Exception") { val exception = new RuntimeException("OOM") Seq( - ("ERROR", () => logError(msgWithMDCAndException, exception)), - ("WARN", () => logWarning(msgWithMDCAndException, exception)), - ("INFO", () => logInfo(msgWithMDCAndException, exception))).foreach { + (Level.ERROR, () => logError(msgWithMDCAndException, exception)), + (Level.WARN, () => logWarning(msgWithMDCAndException, exception)), + (Level.INFO, () => logInfo(msgWithMDCAndException, exception))).foreach { case (level, logFunc) => val logOutput = captureLogOutput(logFunc) assert(expectedPatternForMsgWithMDCAndException(level).r.findFirstIn(logOutput).isDefined) @@ -94,19 +98,58 @@ abstract class LoggingSuiteBase extends AnyFunSuite // scalastyle:ignore funsuit } class StructuredLoggingSuite extends LoggingSuiteBase { - private val className = this.getClass.getName.stripSuffix("$") + override def className: String = classOf[StructuredLoggingSuite].getName override def logFilePath: String = "target/structured.log" - override def expectedPatternForBasicMsg(level: String): String = - s"""\\{"ts":"[^"]+","level":"$level","msg":"This is a log message","logger":"$className"}\n""" + private val jsonMapper = new ObjectMapper().registerModule(DefaultScalaModule) + private def compactAndToRegexPattern(json: String): String = { + jsonMapper.readTree(json).toString. + replace("", """[^"]+"""). + replace("""""""", """.*"""). + replace("{", """\{""") + "\n" + } - override def expectedPatternForMsgWithMDC(level: String): String = - // scalastyle:off line.size.limit - s"""\\{"ts":"[^"]+","level":"$level","msg":"Lost executor 1.","context":\\{"executor_id":"1"},"logger":"$className"}\n""" - // scalastyle:on + override def expectedPatternForBasicMsg(level: Level): String = { + compactAndToRegexPattern( + s""" + { + "ts": "", + "level": "$level", + "msg": "This is a log message", + "logger": "$className" + }""") + } - override def expectedPatternForMsgWithMDCAndException(level: String): String = - // scalastyle:off line.size.limit - s"""\\{"ts":"[^"]+","level":"$level","msg":"Error in executor 1.","context":\\{"executor_id":"1"},"exception":\\{"class":"java.lang.RuntimeException","msg":"OOM","stacktrace":.*},"logger":"$className"}\n""" - // scalastyle:on + override def expectedPatternForMsgWithMDC(level: Level): String = { + compactAndToRegexPattern( + s""" + { + "ts": "", + "level": "$level", + "msg": "Lost executor 1.", + "context": { + "executor_id": "1" + }, + "logger": "$className" + }""") + } + + override def expectedPatternForMsgWithMDCAndException(level: Level): String = { + compactAndToRegexPattern( + s""" + { + "ts": "", + "level": "$level", + "msg": "Error in executor 1.", + "context": { + "executor_id": "1" + }, + "exception": { + "class": "java.lang.RuntimeException", + "msg": "OOM", + "stacktrace": "" + }, + "logger": "$className" + }""") + } } From 8e4d819c88ac871561945dffd1c3453a032940ab Mon Sep 17 00:00:00 2001 From: panbingkun Date: Sun, 31 Mar 2024 20:14:07 +0800 Subject: [PATCH 2/2] update comments for captureLogOutput --- .../scala/org/apache/spark/util/StructuredLoggingSuite.scala | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/common/utils/src/test/scala/org/apache/spark/util/StructuredLoggingSuite.scala b/common/utils/src/test/scala/org/apache/spark/util/StructuredLoggingSuite.scala index 70a4f6aefadb..211c1c2fe7b4 100644 --- a/common/utils/src/test/scala/org/apache/spark/util/StructuredLoggingSuite.scala +++ b/common/utils/src/test/scala/org/apache/spark/util/StructuredLoggingSuite.scala @@ -39,7 +39,7 @@ trait LoggingSuiteBase new File(pwd + "/" + logFilePath) } - // Returns the first line in the log file that contains the given substring. + // Return the newly added log contents in the log file after executing the function `f` private def captureLogOutput(f: () => Unit): String = { val content = if (logFile.exists()) { Files.readString(logFile.toPath)