[SPARK-2952] Enable logging actor messages at DEBUG level

[rxin]

Example messages:

14/08/09 21:37:01 DEBUG BlockManagerMasterActor: [actor] received message RegisterBlockManager(BlockManagerId(0, rxin-mbp, 58092, 0),278302556,Actor[akka.tcp://spark@rxin-mbp:58088/user/BlockManagerActor1#-63596539]) from Actor[akka.tcp://spark@rxin-mbp:58088/temp/$c]

14/08/09 21:37:01 DEBUG BlockManagerMasterActor: [actor] handled message (0.279 ms) RegisterBlockManager(BlockManagerId(0, rxin-mbp, 58092, 0),278302556,Actor[akka.tcp://spark@rxin-mbp:58088/user/BlockManagerActor1#-63596539]) from Actor[akka.tcp://spark@rxin-mbp:58088/temp/$c]

cc @mengxr @tdas @pwendell

[SparkQA]

QA tests have started for PR 1870. This patch merges cleanly.
View progress: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder/18268/consoleFull

[SparkQA]

QA results for PR 1870:
- This patch FAILED unit tests.
- This patch merges cleanly
- This patch adds the following public classes (experimental):
class ClientActor extends Actor with ActorLogReceive with Logging {
class DriverActor(sparkProperties: Seq[(String, String)]) extends Actor with ActorLogReceive {
* class BlockManagerMasterActor extends Actor with ActorLogReceive with Logging {

For more information see test ouptut:
https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder/18268/consoleFull

[SparkQA]

QA tests have started for PR 1870. This patch merges cleanly.
View progress: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder/18270/consoleFull

[SparkQA]

QA results for PR 1870:
- This patch FAILED unit tests.
- This patch merges cleanly
- This patch adds the following public classes (experimental):
class ClientActor extends Actor with ActorLogReceive with Logging {
class DriverActor(sparkProperties: Seq[(String, String)]) extends Actor with ActorLogReceive {
* class BlockManagerMasterActor extends Actor with ActorLogReceive with Logging {

For more information see test ouptut:
https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder/18270/consoleFull

[rxin]

@andrewor14 is the SparkSubmit test flaky? I've seen it fail a few times already.

[info] - launch simple application with spark-submit *** FAILED ***
[info]   org.apache.spark.SparkException: Process List(./bin/spark-submit, --class, org.apache.spark.deploy.SimpleApplicationTest, --name, testApp, --master, local, file:/tmp/1407649354658-0/testJar-1407649354658.jar) exited with code 1
[info]   at org.apache.spark.util.Utils$.executeAndGetOutput(Utils.scala:795)
[info]   at org.apache.spark.deploy.SparkSubmitSuite.runSparkSubmit(SparkSubmitSuite.scala:311)
[info]   at org.apache.spark.deploy.SparkSubmitSuite$$anonfun$14.apply$mcV$sp(SparkSubmitSuite.scala:291)
[info]   at org.apache.spark.deploy.SparkSubmitSuite$$anonfun$14.apply(SparkSubmitSuite.scala:284)
[info]   at org.apache.spark.deploy.SparkSubmitSuite$$anonfun$14.apply(SparkSubmitSuite.scala:284)
[info]   at org.scalatest.Transformer$$anonfun$apply$1.apply(Transformer.scala:22)
[info]   at org.scalatest.Transformer$$anonfun$apply$1.apply(Transformer.scala:22)
[info]   at org.scalatest.OutcomeOf$class.outcomeOf(OutcomeOf.scala:85)
[info]   at org.scalatest.OutcomeOf$.outcomeOf(OutcomeOf.scala:104)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:22)
[info]   ...
[info] - spark submit includes jars passed in through --jar *** FAILED ***
[info]   org.apache.spark.SparkException: Process List(./bin/spark-submit, --class, org.apache.spark.deploy.JarCreationTest, --name, testApp, --master, local-cluster[2,1,512], --jars, file:/tmp/1407649358023-0/testJar-1407649358532.jar,file:/tmp/1407649358533-0/testJar-1407649358635.jar, file:/tmp/1407649358022-0/testJar-1407649358023.jar) exited with code 1
[info]   at org.apache.spark.util.Utils$.executeAndGetOutput(Utils.scala:795)
[info]   at org.apache.spark.deploy.SparkSubmitSuite.runSparkSubmit(SparkSubmitSuite.scala:311)
[info]   at org.apache.spark.deploy.SparkSubmitSuite$$anonfun$15.apply$mcV$sp(SparkSubmitSuite.scala:305)
[info]   at org.apache.spark.deploy.SparkSubmitSuite$$anonfun$15.apply(SparkSubmitSuite.scala:294)
[info]   at org.apache.spark.deploy.SparkSubmitSuite$$anonfun$15.apply(SparkSubmitSuite.scala:294)
[info]   at org.scalatest.Transformer$$anonfun$apply$1.apply(Transformer.scala:22)
[info]   at org.scalatest.Transformer$$anonfun$apply$1.apply(Transformer.scala:22)
[info]   at org.scalatest.OutcomeOf$class.outcomeOf(OutcomeOf.scala:85)
[info]   at org.scalatest.OutcomeOf$.outcomeOf(OutcomeOf.scala:104)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:22)
[info]   ...

[rxin]

Jenkins, retest this please.

[andrewor14]

Yeah that and the DriverSuite. Not sure what the reason is yet, but I noticed that it started happening after #1777 went in...

[pwendell]

LGTM - thanks Reynold!

[rxin]

Thanks. Merging in master & branch-1.1

[mridulm]

Just saw this as part of the close, sorry for the late comment.

Also, some of the INFO messages which are useful have now become DEBUG ? Makes it slightly harder to pinpoint an issue (ex: "Stopping BlockManagerMaster").
Spark logs are already hitting 60gig for some of our jobs in DEBUG mode !

Btw, if we are logging all messages, would it not be better to use TRACE instead of DEBUG ?

[rxin]

I thought about that in this PR actually. Since in log4j you can configure what you want, it seems pretty easy to just enable debug logging for a specific package.

[mridulm]

Unfortunately, in most cases, we wont know what the issue is other than bug hunting in the logs.
So debug logging gets enabled for a wide swathe of packages.

[rxin]

Yea I'm fine turning that into trace. Even better, if we can configure what level to log those on, that'd be great. Do you want to submit a pull request?