Skip to content

Commit 836f24b

Browse files
ehighamehigham
authored
[query] use log4j2 (#15176)
I believe the spark version bump switched the runtime logging implementation to log4j core v2. This broke our py4j logging configuration tacitly. After switching over to v2 I discovered that we don't need things like the `StringSocketAppender`​ because we're redirecting the jvm's stderr to python. We use the hail jar in a few situations with slightly different requirements - tests, py4j, py4j in batch and qob: - For qob we want log4j to append to stdout as that'll appear in the job logs. - For tests, we want low verbosity lest we're driven to madness searching for failure logs in the test output - For py4j in batch, we want the job log to contain what we usually log to the hail log file as that's lost after a job terminated. - For py4j in an ipython session, we probably only want warnings or errors or our users will hate us. This is what `Py4jUtils.configureLogging`​ attempts to address: when binging to a`py4j`​ gateway, we need to reconfigure the logging configuration so we can forward logs to stderr and write to our logfile. Note that the configuration contains a spark logger - the logs are quite noisy and adding this allows us to control how much noise we want from spark. This change cannot impact the Hail Batch instance as deployed by Broad Institute in GCP
1 parent ce6ac5e commit 836f24b

14 files changed

Lines changed: 93 additions & 337 deletions

File tree

‎hail/build.mill‎

Lines changed: 12 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -52,6 +52,14 @@ object Deps {
5252
def core: Task[Dep] = Task.Anon(mvn"org.apache.spark::spark-core:${Env.sparkVersion()}")
5353
def mllib: Task[Dep] = Task.Anon(mvn"org.apache.spark::spark-mllib:${Env.sparkVersion()}")
5454
}
55+
56+
object Log4j {
57+
// have to forceVersion for reasons unknown?
58+
val bom = mvn"org.apache.logging.log4j:log4j-bom:2.25.2".forceVersion()
59+
val api = mvn"org.apache.logging.log4j:log4j-api"
60+
val core = mvn"org.apache.logging.log4j:log4j-core"
61+
val slf4j = mvn"org.apache.logging.log4j:log4j-slf4j2-impl"
62+
}
5563

5664
val samtools = mvn"com.github.samtools:htsjdk:3.0.5"
5765
val jdistlib = mvn"net.sourceforge.jdistlib:jdistlib:0.4.5"
@@ -65,8 +73,6 @@ object Deps {
6573
val netlib = mvn"com.github.fommil.netlib:all:1.1.2"
6674
val avro = mvn"org.apache.avro:avro:1.11.2"
6775
val junixsocket = mvn"com.kohlschutter.junixsocket:junixsocket-core:2.6.1"
68-
val log4jApi = mvn"org.apache.logging.log4j:log4j-api:2.20.0"
69-
val sfl4jNop = mvn"org.slf4j:slf4j-nop:1.7.36"
7076
val hadoopClient = mvn"org.apache.hadoop:hadoop-client:3.4.2"
7177
val jackson = mvn"com.fasterxml.jackson.core:jackson-core:2.15.2"
7278
val sourcecode = mvn"com.lihaoyi::sourcecode:0.4.2"
@@ -254,6 +260,7 @@ trait RootHailModule extends CrossScalaModule with HailModule { outer =>
254260

255261
override def bomMvnDeps: T[Seq[Dep]] = Seq(
256262
Deps.Asm.bom,
263+
Deps.Log4j.bom,
257264
)
258265

259266
override def mvnDeps: T[Seq[Dep]] = Seq(
@@ -262,6 +269,7 @@ trait RootHailModule extends CrossScalaModule with HailModule { outer =>
262269
Deps.Asm.core,
263270
Deps.Asm.analysis,
264271
Deps.Asm.util,
272+
Deps.Log4j.core,
265273
Deps.samtools.excludeOrg("*"),
266274
Deps.jdistlib.excludeOrg("*"),
267275
Deps.freemarker,
@@ -283,11 +291,11 @@ trait RootHailModule extends CrossScalaModule with HailModule { outer =>
283291
Deps.netlib,
284292
Deps.avro.excludeOrg("com.fasterxml.jackson.core"),
285293
Deps.junixsocket,
286-
Deps.sfl4jNop,
294+
Deps.Log4j.slf4j,
287295
)
288296

289297
override def compileMvnDeps: T[Seq[Dep]] = Seq(
290-
Deps.log4jApi,
298+
Deps.Log4j.api,
291299
Deps.hadoopClient,
292300
Deps.Spark.core().excludeOrg("org.scalanlp"), // Hail has an explicit dependency on Breeze 1.1
293301
Deps.Spark.mllib().excludeOrg("org.scalanlp"), // Hail has an explicit dependency on Breeze 1.1
@@ -357,8 +365,6 @@ trait RootHailModule extends CrossScalaModule with HailModule { outer =>
357365
}
358366

359367
object test extends HailTests {
360-
override def resources: T[Seq[PathRef]] = outer.resources() ++ super.resources()
361-
362368
override def assemblyRules: Seq[Rule] = outer.assemblyRules ++ Seq(
363369
Rule.Relocate("org.codehaus.jackson.**", "is.hail.relocated.@0")
364370
)

‎hail/hail/resources/log4j.properties‎

Lines changed: 0 additions & 8 deletions
This file was deleted.

‎hail/hail/resources/log4j2.properties‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,7 @@
1+
appender.0.type = Console
2+
appender.0.name = CONSOLE
3+
appender.0.layout.type = PatternLayout
4+
appender.0.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} %-5p %c{1}:%L - %m%n
5+
6+
rootLogger.level = INFO
7+
rootLogger.appenderRef.0.ref = CONSOLE

‎hail/hail/src/is/hail/io/vcf/LoadVCF.scala‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1308,11 +1308,13 @@ object LoadVCF {
13081308
def warnDuplicates(ids: Array[String]): Unit = {
13091309
val duplicates = ids.counter().filter(_._2 > 1)
13101310
if (duplicates.nonEmpty) {
1311-
warn(
1312-
s"Found ${duplicates.size} duplicate ${plural(duplicates.size, "sample ID")}:\n @1",
1311+
log.warn(
1312+
"Found {} duplicate {}:\n {}",
1313+
duplicates.size,
1314+
plural(duplicates.size, "sample ID"),
13131315
duplicates.toArray.sortBy(-_._2).map { case (id, count) =>
13141316
s"""($count) "$id""""
1315-
}.truncatable("\n "),
1317+
}.mkString("\n "),
13161318
)
13171319
}
13181320
}

‎hail/hail/src/is/hail/utils/LoggerOutputStream.scala‎

Lines changed: 0 additions & 25 deletions
This file was deleted.

‎hail/hail/src/is/hail/utils/Logging.scala‎

Lines changed: 7 additions & 41 deletions
Original file line numberDiff line numberDiff line change
@@ -1,58 +1,24 @@
11
package is.hail.utils
22

3-
import org.apache.log4j.{LogManager, Logger}
3+
import org.apache.logging.log4j.{LogManager, Logger}
44

55
object LogHelper {
66
// exposed more directly for generated code
77
def logInfo(msg: String): Unit = log.info(msg)
8-
def warning(msg: String): Unit = consoleLog.warn(msg)
8+
def warning(msg: String): Unit = log.warn(msg)
99
def consoleInfo(msg: String): Unit = info(msg)
1010
}
1111

1212
trait Logging {
13-
@transient private var logger: Logger = _
14-
@transient private var consoleLogger: Logger = _
15-
16-
def log: Logger = {
17-
if (logger == null)
18-
logger = LogManager.getRootLogger
19-
logger
20-
}
21-
22-
def consoleLog: Logger = {
23-
if (consoleLogger == null)
24-
consoleLogger = LogManager.getLogger("Hail")
25-
consoleLogger
26-
}
13+
@transient lazy val log: Logger =
14+
LogManager.getLogger(getClass.getName.stripSuffix("$"))
2715

2816
def info(msg: String): Unit =
29-
consoleLog.info(msg)
30-
31-
def info(msg: String, t: Truncatable): Unit = {
32-
val (screen, logged) = t.strings
33-
if (screen == logged)
34-
consoleLog.info(format(msg, screen))
35-
else {
36-
// writes twice to the log file, but this isn't a big problem
37-
consoleLog.info(format(msg, screen))
38-
log.info(format(msg, logged))
39-
}
40-
}
17+
log.info(msg)
4118

4219
def warn(msg: String): Unit =
43-
consoleLog.warn(msg)
44-
45-
def warn(msg: String, t: Truncatable): Unit = {
46-
val (screen, logged) = t.strings
47-
if (screen == logged)
48-
consoleLog.warn(format(msg, screen))
49-
else {
50-
// writes twice to the log file, but this isn't a big problem
51-
consoleLog.warn(format(msg, screen))
52-
log.warn(format(msg, logged))
53-
}
54-
}
20+
log.warn(msg)
5521

5622
def error(msg: String): Unit =
57-
consoleLog.error(msg)
23+
log.error(msg)
5824
}

‎hail/hail/src/is/hail/utils/Py4jUtils.scala‎

Lines changed: 54 additions & 32 deletions
Original file line numberDiff line numberDiff line change
@@ -7,9 +7,11 @@ import is.hail.types.virtual.Type
77
import scala.jdk.CollectionConverters._
88

99
import java.io.{InputStream, OutputStream}
10-
import java.util.Properties
1110

12-
import org.apache.log4j.{LogManager, PropertyConfigurator}
11+
import org.apache.logging.log4j.Level
12+
import org.apache.logging.log4j.core.appender.ConsoleAppender
13+
import org.apache.logging.log4j.core.config.Configurator
14+
import org.apache.logging.log4j.core.config.builder.api.ConfigurationBuilderFactory
1315
import org.json4s.JsonAST._
1416
import org.json4s.jackson.JsonMethods
1517

@@ -137,38 +139,58 @@ trait Py4jUtils extends Logging {
137139
"%d{yyyy-MM-dd HH:mm:ss.SSS} %c{1}: %p: %m%n"
138140

139141
def configureLogging(logFile: String, quiet: Boolean, append: Boolean): Unit = {
140-
org.apache.log4j.helpers.LogLog.setInternalDebugging(true)
141-
org.apache.log4j.helpers.LogLog.setQuietMode(false)
142-
val logProps = new Properties()
143-
144-
// uncomment to see log4j LogLog output:
145-
// logProps.put("log4j.debug", "true")
146-
logProps.put("log4j.rootLogger", "INFO, logfile")
147-
logProps.put("log4j.appender.logfile", "org.apache.log4j.FileAppender")
148-
logProps.put("log4j.appender.logfile.append", append.toString)
149-
logProps.put("log4j.appender.logfile.file", logFile)
150-
logProps.put("log4j.appender.logfile.threshold", "INFO")
151-
logProps.put("log4j.appender.logfile.layout", "org.apache.log4j.PatternLayout")
152-
logProps.put("log4j.appender.logfile.layout.ConversionPattern", LogFormat)
153-
154-
if (!quiet) {
155-
logProps.put("log4j.logger.Hail", "INFO, HailConsoleAppender, HailSocketAppender")
156-
logProps.put("log4j.appender.HailConsoleAppender", "org.apache.log4j.ConsoleAppender")
157-
logProps.put("log4j.appender.HailConsoleAppender.target", "System.err")
158-
logProps.put("log4j.appender.HailConsoleAppender.layout", "org.apache.log4j.PatternLayout")
159-
} else
160-
logProps.put("log4j.logger.Hail", "INFO, HailSocketAppender")
161-
162-
logProps.put("log4j.appender.HailSocketAppender", "is.hail.utils.StringSocketAppender")
163-
logProps.put("log4j.appender.HailSocketAppender.layout", "org.apache.log4j.PatternLayout")
164-
165-
LogManager.resetConfiguration()
166-
PropertyConfigurator.configure(logProps)
142+
val configBuilder =
143+
ConfigurationBuilderFactory
144+
.newConfigurationBuilder()
145+
.setConfigurationName("Hail")
146+
147+
val layout =
148+
configBuilder
149+
.newLayout("PatternLayout")
150+
.addAttribute("pattern", LogFormat)
151+
152+
val fileAppender =
153+
configBuilder
154+
.newAppender("LOGFILE", "File")
155+
.addAttribute("append", append.toString)
156+
.addAttribute("fileName", logFile)
157+
.add(layout)
158+
159+
val consoleAppender =
160+
configBuilder
161+
.newAppender("CONSOLE", "Console")
162+
.addAttribute("target", ConsoleAppender.Target.SYSTEM_ERR)
163+
.add(layout)
164+
165+
val rootLogger =
166+
configBuilder
167+
.newRootLogger(Level.INFO)
168+
.add(
169+
configBuilder
170+
.newAppenderRef(fileAppender.getName)
171+
.addAttribute("level", Level.INFO)
172+
)
173+
.add(
174+
configBuilder
175+
.newAppenderRef(consoleAppender.getName)
176+
.addAttribute("level", if (!quiet) Level.WARN else Level.OFF)
177+
)
178+
179+
val sparkLogger =
180+
configBuilder
181+
.newLogger("org.apache.spark", Level.WARN)
182+
.add(configBuilder.newAppenderRef(fileAppender.getName))
183+
184+
Configurator.reconfigure(
185+
configBuilder
186+
.add(fileAppender)
187+
.add(consoleAppender)
188+
.add(rootLogger)
189+
.add(sparkLogger)
190+
.build(false)
191+
)
167192
}
168193

169-
def addSocketAppender(hostname: String, port: Int): Unit =
170-
StringSocketAppender.get().connect(hostname, port, LogFormat)
171-
172194
def logWarn(msg: String): Unit =
173195
warn(msg)
174196

0 commit comments

Comments
 (0)