Repository: spark
Updated Branches:
  refs/heads/master 4dbabb39a -> e5749a134


SPARK-2646. log4j initialization not quite compatible with log4j 2.x

The logging code that handles log4j initialization leads to an stack overflow 
error when used with log4j 2.x, which has just been released. This occurs even 
a downstream project has correctly adjusted SLF4J bindings, and that is the 
right thing to do for log4j 2.x, since it is effectively a separate project 
from 1.x.

Here is the relevant bit of Logging.scala:

```
  private def initializeLogging() {
    // If Log4j is being used, but is not initialized, load a default 
properties file
    val binder = StaticLoggerBinder.getSingleton
    val usingLog4j = 
binder.getLoggerFactoryClassStr.endsWith("Log4jLoggerFactory")
    val log4jInitialized = 
LogManager.getRootLogger.getAllAppenders.hasMoreElements
    if (!log4jInitialized && usingLog4j) {
      val defaultLogProps = "org/apache/spark/log4j-defaults.properties"
      Option(Utils.getSparkClassLoader.getResource(defaultLogProps)) match {
        case Some(url) =>
          PropertyConfigurator.configure(url)
          log.info(s"Using Spark's default log4j profile: $defaultLogProps")
        case None =>
          System.err.println(s"Spark was unable to load $defaultLogProps")
      }
    }
    Logging.initialized = true

    // Force a call into slf4j to initialize it. Avoids this happening from 
mutliple threads
    // and triggering this: 
http://mailman.qos.ch/pipermail/slf4j-dev/2010-April/002956.html
    log
  }
```

The first minor issue is that there is a call to a logger inside this method, 
which is initializing logging. In this situation, it ends up causing the 
initialization to be called recursively until the stack overflow. It would be 
slightly tidier to log this only after Logging.initialized = true. Or not at 
all. But it's not the root problem, or else, it would not work at all now.

The calls to log4j classes here always reference log4j 1.2 no matter what. For 
example, there is not getAllAppenders in log4j 2.x. That's fine. Really, 
"usingLog4j" means "using log4j 1.2" and "log4jInitialized" means "log4j 1.2 is 
initialized".

usingLog4j should be false for log4j 2.x, because the initialization only 
matters for log4j 1.2. But, it's true, and that's the real issue. And 
log4jInitialized is always false, since calls to the log4j 1.2 API are stubs 
and no-ops in this setup, where the caller has swapped in log4j 2.x. Hence the 
loop.

This is fixed, I believe, if "usingLog4j" can be false for log4j 2.x. The SLF4J 
static binding class has the same name for both versions, unfortunately, which 
causes the issue. However they're in different packages. For example, if the 
test included "... and begins with org.slf4j", it should work, as the SLF4J 
binding for log4j 2.x is provided by log4j 2.x at the moment, and is in package 
org.apache.logging.slf4j.

Of course, I assume that SLF4J will eventually offer its own binding. I hope to 
goodness they at least name the binding class differently, or else this will 
again not work. But then some other check can probably be made.

Author: Sean Owen <sro...@gmail.com>

Closes #1547 from srowen/SPARK-2646 and squashes the following commits:

92a9898 [Sean Owen] System.out -> System.err
94be4c7 [Sean Owen] Add back log message as System.out, with informational 
comment
a7f8876 [Sean Owen] Updates from review
6f3c1d3 [Sean Owen] Remove log statement in logging initialization, and 
distinguish log4j 1.2 from 2.0, to avoid stack overflow in initialization


Project: http://git-wip-us.apache.org/repos/asf/spark/repo
Commit: http://git-wip-us.apache.org/repos/asf/spark/commit/e5749a13
Tree: http://git-wip-us.apache.org/repos/asf/spark/tree/e5749a13
Diff: http://git-wip-us.apache.org/repos/asf/spark/diff/e5749a13

Branch: refs/heads/master
Commit: e5749a1342327263dc6b94ba470e392fbea703fa
Parents: 4dbabb3
Author: Sean Owen <sro...@gmail.com>
Authored: Thu Jul 31 12:26:36 2014 -0700
Committer: Patrick Wendell <pwend...@gmail.com>
Committed: Thu Jul 31 12:26:36 2014 -0700

----------------------------------------------------------------------
 .../main/scala/org/apache/spark/Logging.scala   | 23 ++++++++++----------
 1 file changed, 12 insertions(+), 11 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/spark/blob/e5749a13/core/src/main/scala/org/apache/spark/Logging.scala
----------------------------------------------------------------------
diff --git a/core/src/main/scala/org/apache/spark/Logging.scala 
b/core/src/main/scala/org/apache/spark/Logging.scala
index 50d8e93..807ef3e 100644
--- a/core/src/main/scala/org/apache/spark/Logging.scala
+++ b/core/src/main/scala/org/apache/spark/Logging.scala
@@ -45,10 +45,7 @@ trait Logging {
       initializeIfNecessary()
       var className = this.getClass.getName
       // Ignore trailing $'s in the class names for Scala objects
-      if (className.endsWith("$")) {
-        className = className.substring(0, className.length - 1)
-      }
-      log_ = LoggerFactory.getLogger(className)
+      log_ = LoggerFactory.getLogger(className.stripSuffix("$"))
     }
     log_
   }
@@ -110,23 +107,27 @@ trait Logging {
   }
 
   private def initializeLogging() {
-    // If Log4j is being used, but is not initialized, load a default 
properties file
-    val binder = StaticLoggerBinder.getSingleton
-    val usingLog4j = 
binder.getLoggerFactoryClassStr.endsWith("Log4jLoggerFactory")
-    val log4jInitialized = 
LogManager.getRootLogger.getAllAppenders.hasMoreElements
-    if (!log4jInitialized && usingLog4j) {
+    // Don't use a logger in here, as this is itself occurring during 
initialization of a logger
+    // If Log4j 1.2 is being used, but is not initialized, load a default 
properties file
+    val binderClass = StaticLoggerBinder.getSingleton.getLoggerFactoryClassStr
+    // This distinguishes the log4j 1.2 binding, currently
+    // org.slf4j.impl.Log4jLoggerFactory, from the log4j 2.0 binding, currently
+    // org.apache.logging.slf4j.Log4jLoggerFactory
+    val usingLog4j12 = "org.slf4j.impl.Log4jLoggerFactory".equals(binderClass)
+    val log4j12Initialized = 
LogManager.getRootLogger.getAllAppenders.hasMoreElements
+    if (!log4j12Initialized && usingLog4j12) {
       val defaultLogProps = "org/apache/spark/log4j-defaults.properties"
       Option(Utils.getSparkClassLoader.getResource(defaultLogProps)) match {
         case Some(url) =>
           PropertyConfigurator.configure(url)
-          log.info(s"Using Spark's default log4j profile: $defaultLogProps")
+          System.err.println(s"Using Spark's default log4j profile: 
$defaultLogProps")
         case None =>
           System.err.println(s"Spark was unable to load $defaultLogProps")
       }
     }
     Logging.initialized = true
 
-    // Force a call into slf4j to initialize it. Avoids this happening from 
mutliple threads
+    // Force a call into slf4j to initialize it. Avoids this happening from 
multiple threads
     // and triggering this: 
http://mailman.qos.ch/pipermail/slf4j-dev/2010-April/002956.html
     log
   }

Reply via email to