Fix SPARK-1413: Parquet messes up stdout and stdin when used in Spark REPL

[witgo]

No description provided.

[AmplabJenkins]

Can one of the admins verify this patch?

[marmbrus]

ok to test

[mateiz]

We should probably just call this enabledLogForwarding. Thanks for the fix though!

[mateiz]

Jenkins, test this please

[AmplabJenkins]

Merged build triggered.

[AmplabJenkins]

Merged build started.

[witgo]

There is a problem I do not know what the reason is cause

import org.apache.spark.SparkContext
import org.apache.spark.sql.SQLContext
case class Record(key: Int, value: String)
val sqlContext = new SQLContext(sc)
import sqlContext._
val rdd = sc.parallelize((1 to 100).map(i => Record(i, s"val_$i")))
rdd.registerAsTable("records")
rdd.saveAsParquetFile("records.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.

[marmbrus]

@AndreSchumacher, any thoughts?

[AndreSchumacher]

Ouch. OK, I'll have a look at this. The default j.u.l. logger writes to stdout. Maybe the log forwarding doesn't work as intended.

[AmplabJenkins]

Merged build finished. All automated tests passed.

[AmplabJenkins]

All automated tests passed.
Refer to this link for build results: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder/13762/

[witgo]

class parquet.Log has a static block ( add a default handler in case there is none )

[AndreSchumacher]

@witgo that alone would not explain a deadlock if the forwarding is initialized multiple times? Unless maybe the log forwarding is called before parquet.Log is fully initialized I guess. Maybe that is why it did not show up in the tests that don't use the console. Great that you found it and thanks a lot for the fix. I tried it and it works fine here. For completeness let's run the Travis checks once more.

Could you still remove my now misleading comment about the parent loggers?

[witgo]

LogManager.getLogManager.reset () call twice seems to cause some problems
Seq("parquet.hadoop.ColumnChunkPageWriteStore", ... parent logger is Logger.getLogger("parquet"). only need to set the Logger.getLogger("parquet") .

[pwendell]

So is the main problem here that parquet should not use a static block like this to do initialization? If so, @witgo do you mind documenting this in the code to explain that it's a work around. Also, should we reach out to the parquet team and @julienledem about removing this static initialization? It seems this initialization code breaks the use case where JUL is being routed to SLF4j via a bridge. Or maybe it's sensitive to the order in which the SLF4J bridge and the Parquet Log class do static initialization.

[pwendell]

Btw @julienledem in Spark we also add some default initialization, but we do it lazily instead of statically because this allows re-routing packages to statically initialize before we try to detect whether any logging has been configured:

https://github.com/apache/spark/blob/master/core/src/main/scala/org/apache/spark/Logging.scala#L106

[AndreSchumacher]

@witgo Good idea to move the forwarding setup out of there but in the process it seems that edd9630 broke the forwarding again.

Also: I think it is confusing to set the log level to null (root level). Parquet hides most log statements behind if (level >= WARN) etc. and relies on the compiler to remove these for performance reasons. So we should just do the same as parquet.Log does and do parquetLogger.setLevel(parquet.Log.LEVEL) so we won't confuse users. Note that the actual level can be still set via Log4J (assuming it's not finer than that).

[witgo]

@AndreSchumacher
parquet.Log has a static block ( add a default handler in case there is none )
The following code unset Logger.getLogger("parquet")

val parquetLogger = java.util.logging.Logger.getLogger("parquet")
parquetLogger.getHandlers.foreach(parquetLogger.removeHandler)
if(parquetLogger.getLevel != null) parquetLogger.setLevel(null)
if(!parquetLogger.getUseParentHandlers) parquetLogger.setUseParentHandlers(true)

[AndreSchumacher]

@witgo yes, it seems the parent handlers need to be set for the forwarding to work. My only remaining suggestion is to the log level. I still think setting it to anything else than the pre-compiled one would be confusing (see my comment above).

@pwendell are you OK with having the initialization code there where it is now?

[pwendell]

Is this line not actually necessary?

If it turns out we need to directly call SLF4JBrigeHandler let's change the call to just use reflection and fail gracefully if it's not found on the classpath. It's not pretty but will be friendlier to downstream users. And we can drop it if Parquet ditches static initializers.

[pwendell]

Specifically, I'd first check if the class can be loaded, then if it can, use java reflection to access and call the class methods.

[witgo]

You are right,I don't understand the scala reflection, an example?

[pwendell]

For static methods it looks like this:

try {
  // We use reflection here to handle the case where users remove the 
  // slf4j-to-jul bridge order to route their logs to JUL.
  val bridgeClass = Class.forName("org.slf4j.bridge.SLF4JBridgeHandler")
  bridgeClass.getMethod("removeHandlersForRootLogger").invoke(null)
  val installed = bridgeClass.getMethod("isInstalled").invoke(null).asInstanceOf[Boolean]
  if (!installed) {
    bridgeClass.getMethod("install").invoke(null)
  }
} catch {
  case e: Exception => // can't log anything yet so just fail silently
}

[pwendell]

@witgo I gave an example of using reflection - mind adjusting your patch and checking if this works?

[witgo]

@pwendell
Thank you, this patch works

But this only solve one problem. The Spark dependence is fixed, we can only use log4j.

In SparkBuild.scala file:

    "log4j"                      % "log4j"            % "1.2.17",
    "org.slf4j"                  % "slf4j-api"        % slf4jVersion,
    "org.slf4j"                  % "slf4j-log4j12"    % slf4jVersion,
    "org.slf4j"                  % "jul-to-slf4j"     % slf4jVersion,
    "org.slf4j"                  % "jcl-over-slf4j"   % slf4jVersion,

To become a configurable logging system?

[pwendell]

no we don't need to change the dependencies. The case I wanted to handle was if users downstream remove the dependencies (e.g. they remove "jul-to-slf4j") and do a custom spark build. This is something people actually do.

[pwendell]

Jenkins, test this please.

[AmplabJenkins]

Merged build triggered.

[AmplabJenkins]

Merged build started.

[AmplabJenkins]

Merged build finished.

[AmplabJenkins]

Refer to this link for build results: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder/13996/

[pwendell]

Jenkins, test this please.

[AmplabJenkins]

Merged build triggered.

[AmplabJenkins]

Merged build started.

[AmplabJenkins]

Merged build finished. All automated tests passed.

[AmplabJenkins]

All automated tests passed.
Refer to this link for build results: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder/13998/

[AndreSchumacher]

I'm seeing some Akka related problems in my local build but nothing that would seem related to this PR. The log forwarding seems to work.

@pwendell thanks a lot for the help on this. I think in the interest of getting the saveAsParquetFile working inside the console that should be merged soon.

[pwendell]

@AndreSchumacher it's likely related to an accidental merge of a buggy patch into master... try rebasing to the latest master which includes a reversion of the bug.

[pwendell]

Okay thanks, merged!