Spark 1.5.2 and SLF4J StaticLoggerBinder

Question

While this doesn't stop my code from functioning, I am going insane just trying to understand why this warning occurs. I'm using Scala 2.11.7, ScalaIDE, SBT 0.13.9.

15/11/20 12:17:05 INFO akka.event.slf4j.Slf4jLogger: Slf4jLogger started
15/11/20 12:17:06 INFO Remoting: Starting remoting
15/11/20 12:17:06 INFO Remoting: Remoting started; listening on addresses :[akka.tcp://[email protected]:36509]
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

[Stage 0:=======================================================> (31 + 1) / 32]
[Stage 0:=========================================================(32 + 0) / 32]

Now I understand normally why this error occurs, but the problem that I haven't messed with Spark's logging at all. Now if I add say slf4j-simple to my project, it complains of multiple SLF4j bindings, but not this warning. I cannot for the life of me figure out a way to make both of these things play nice. My code itself is using log4j 2.4 for my own logging.

I have attempted, but to not avail

1. Excluding Spark's Logging and including my own.
2. Using log4j2 to route the SLF4j calls to log4j2 and excluding Spark's SLF4j
3. Including literally every SLF4j binding in an attempt to make one pick it up.
4. Adding the SLF4j jars, to my classpath, spark's drive and executor classpath

If I try and exclude the Spark logging I will get ClassNotFound issues from Spark, but for the life of me I can't figure out what the hell is doing this.

Just some more details, I am using Spark, but I am excluding and including my own version of Hadoop (2.7.1)

Here is my are the jars I think are relevant that are provided according to the system classloader.

~/.ivy2/cache/org.slf4j/slf4j-api/jars/slf4j-api-1.7.10.jar
~/.ivy2/cache/org.slf4j/slf4j-log4j12/jars/slf4j-log4j12-1.7.10.jar
~/.ivy2/cache/log4j/log4j/bundles/log4j-1.2.17.jar
~/.ivy2/cache/org.slf4j/jul-to-slf4j/jars/jul-to-slf4j-1.7.10.jar
~/.ivy2/cache/org.slf4j/jcl-over-slf4j/jars/jcl-over-slf4j-1.7.10.jar
~/.ivy2/cache/com.typesafe.akka/akka-slf4j_2.11/jars/akka-slf4j_2.11-2.3.11.jar
~/.ivy2/cache/org.apache.logging.log4j/log4j-api/jars/log4j-api-2.4.1.jar
~/.ivy2/cache/org.apache.logging.log4j/log4j-core/jars/log4j-core-2.4.1.jar
~/.ivy2/cache/com.typesafe.akka/akka-slf4j_2.11/jars/akka-slf4j_2.11-2.4.0.jar

Does anyone have any insight into this? I appreciate it.

log4j: Trying to find [log4j.xml] using context classloader sun.misc.Launcher$AppClassLoader@42a57993.
log4j: Trying to find [log4j.xml] using sun.misc.Launcher$AppClassLoader@42a57993 class loader.
log4j: Trying to find [log4j.xml] using ClassLoader.getSystemResource().
log4j: Trying to find [log4j.properties] using context classloader sun.misc.Launcher$AppClassLoader@42a57993.
log4j: Using URL [file:/home/scarman/workspace-scala/Ingestions/ingestion/bin/log4j.properties] for automatic log4j configuration.
log4j: Reading configuration from URL file:/home/scarman/workspace-scala/Ingestions/ingestion/bin/log4j.properties
log4j: Parsing for [root] with value=[INFO, console].
log4j: Level token is [INFO].
log4j: Category root set to INFO
log4j: Parsing appender named "console".
log4j: Parsing layout options for "console".
log4j: Setting property [conversionPattern] to [%d{yy/MM/dd HH:mm:ss} %p %c: %m%n].
log4j: End of parsing for "console".
log4j: Setting property [target] to [System.err].
log4j: Parsed "console" options.
log4j: Parsing for [org.spark-project.jetty] with value=[WARN].
log4j: Level token is [WARN].
log4j: Category org.spark-project.jetty set to WARN
log4j: Handling log4j.additivity.org.spark-project.jetty=[null]
log4j: Parsing for [org.spark-project.jetty.util.component.AbstractLifeCycle] with value=[ERROR].
log4j: Level token is [ERROR].
log4j: Category org.spark-project.jetty.util.component.AbstractLifeCycle set to ERROR
log4j: Handling log4j.additivity.org.spark-project.jetty.util.component.AbstractLifeCycle=[null]
log4j: Parsing for [org.apache.spark] with value=[WARN].
log4j: Level token is [WARN].
log4j: Category org.apache.spark set to WARN
log4j: Handling log4j.additivity.org.apache.spark=[null]
log4j: Parsing for [org.apache.hadoop.hive.metastore.RetryingHMSHandler] with value=[FATAL].
log4j: Level token is [FATAL].
log4j: Category org.apache.hadoop.hive.metastore.RetryingHMSHandler set to FATAL
log4j: Handling log4j.additivity.org.apache.hadoop.hive.metastore.RetryingHMSHandler=[null]
log4j: Parsing for [parquet] with value=[INFO].
log4j: Level token is [INFO].
log4j: Category parquet set to INFO
log4j: Handling log4j.additivity.parquet=[null]
log4j: Parsing for [org.apache.hadoop] with value=[WARN].
log4j: Level token is [WARN].
log4j: Category org.apache.hadoop set to WARN
log4j: Handling log4j.additivity.org.apache.hadoop=[null]
log4j: Parsing for [org.apache.spark.repl.SparkILoop$SparkILoopInterpreter] with value=[INFO].
log4j: Level token is [INFO].
log4j: Category org.apache.spark.repl.SparkILoop$SparkILoopInterpreter set to INFO
log4j: Handling log4j.additivity.org.apache.spark.repl.SparkILoop$SparkILoopInterpreter=[null]
log4j: Parsing for [org.apache.spark.repl.SparkIMain$exprTyper] with value=[INFO].
log4j: Level token is [INFO].
log4j: Category org.apache.spark.repl.SparkIMain$exprTyper set to INFO
log4j: Handling log4j.additivity.org.apache.spark.repl.SparkIMain$exprTyper=[null]
log4j: Parsing for [org.apache.parquet] with value=[ERROR].
log4j: Level token is [ERROR].
log4j: Category org.apache.parquet set to ERROR
log4j: Handling log4j.additivity.org.apache.parquet=[null]
log4j: Parsing for [org.apache.hadoop.hive.ql.exec.FunctionRegistry] with value=[ERROR].
log4j: Level token is [ERROR].
log4j: Category org.apache.hadoop.hive.ql.exec.FunctionRegistry set to ERROR
log4j: Handling log4j.additivity.org.apache.hadoop.hive.ql.exec.FunctionRegistry=[null]
log4j: Finished configuring

Adding my class bindings that slf4j locates when loading...

jar:file:/home/scarman/.ivy2/cache/org.slf4j/slf4j-log4j12/jars/slf4j-log4j12-1.7.10.jar!/org/slf4j/impl/Log4jLoggerFactory.class
org.slf4j.impl.Log4jLoggerFactory@7cef4e59
org.slf4j.impl.Log4jLoggerFactory

Answer 1

Update: This still applies to Spark 1.6.1

Just a follow up and answer to this in case anyone else was wondering. So I noticed that this warning was only happening during the use of Spark's parquet interfaces. I tested this out to confirm it and also found someone had already written about it in SPARK-10057. The problem with that issue was that the other developers could not replicate it, but in all fairness the original reporter was rather vague when describing the problem.

Either way, I decided to track it down for no reason other than to satisfy my OCD-ness about these issues.

So I tested using both files in S3 and on my local disk. Text and JSON files did not trigger this warning, but parquet usage triggered this warning whether the files were local or in S3. This was for both reading and writing parquet files. Looking at ParquetRelation.scala we see the only reference to SLF4j there.

  // Parquet initializes its own JUL logger in a static block which always prints to stdout.  Here
  // we redirect the JUL logger via SLF4J JUL bridge handler.
  val redirectParquetLogsViaSLF4J: Unit = {
    def redirect(logger: JLogger): Unit = {
      logger.getHandlers.foreach(logger.removeHandler)
      logger.setUseParentHandlers(false)
      logger.addHandler(new SLF4JBridgeHandler)
    }

So it seems reasonable to me to assert that the bridge between Parquet's JUL logging and the SLF4j bridge is causing this warning to appear. I suppose it initializes the bridge and something happens where it can't load the proper Static Logger binder. I'd have to dig a bit more into Spark's code and test to find out, but that's at least what is causing it. I'll try and get a fix together if time permits.

Finally, here is a code sample for local reproduction of the warning.

scala> sc.setLogLevel("WARN")

scala> val d = sc.parallelize(Array[Int](1,2,3,4,5))
d: org.apache.spark.rdd.RDD[Int] = ParallelCollectionRDD[0] at parallelize at <console>:21

scala> val ddf = d.toDF()
ddf: org.apache.spark.sql.DataFrame = [_1: int]

scala> ddf.write.parquet("/home/scarman/data/test.parquet")
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.