Why do different loggers output different logs in spark 3.5.0?

[paulpaul1076]

When I tried running Spark jobs, I got these lines in the logs:

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.

So I tried 3 sets of jars that have org.slf4j.impl.StaticLoggerBinder

Set number 1:

logback-classic-1.2.11.jar
logback-core-1.2.11.jar

Set number 2:
log4j-slf4j-impl-2.22.0.jar
Set number3:
slf4j-log4j12-1.7.30.jar

With set number 1 I get exceptions (non-fatal) that I do not get in set number 2, for example:

java.lang.UnsupportedOperationException: S3A streams are not Syncable. See HADOOP-17597.
        at org.apache.hadoop.fs.s3a.S3ABlockOutputStream.handleSyncableInvocation(S3ABlockOutputStream.java:670)
        at org.apache.hadoop.fs.s3a.S3ABlockOutputStream.hflush(S3ABlockOutputStream.java:657)
        at org.apache.hadoop.fs.FSDataOutputStream.hflush(FSDataOutputStream.java:136)
        at org.apache.spark.deploy.history.EventLogFileWriter.$anonfun$writeLine$3(EventLogFileWriters.scala:122)
        at org.apache.spark.deploy.history.EventLogFileWriter.$anonfun$writeLine$3$adapted(EventLogFileWriters.scala:122)
        at scala.Option.foreach(Option.scala:407)
        at org.apache.spark.deploy.history.EventLogFileWriter.writeLine(EventLogFileWriters.scala:122)
        at org.apache.spark.deploy.history.SingleEventLogFileWriter.writeEvent(EventLogFileWriters.scala:229)
        at org.apache.spark.scheduler.EventLoggingListener.logEvent(EventLoggingListener.scala:97)
        at org.apache.spark.scheduler.EventLoggingListener.onOtherEvent(EventLoggingListener.scala:274)
        at org.apache.spark.scheduler.SparkListenerBus.doPostEvent(SparkListenerBus.scala:100)
        at org.apache.spark.scheduler.SparkListenerBus.doPostEvent$(SparkListenerBus.scala:28)
        at org.apache.spark.scheduler.AsyncEventQueue.doPostEvent(AsyncEventQueue.scala:37)
        at org.apache.spark.scheduler.AsyncEventQueue.doPostEvent(AsyncEventQueue.scala:37)
        at org.apache.spark.util.ListenerBus.postToAll(ListenerBus.scala:117)
        at org.apache.spark.util.ListenerBus.postToAll$(ListenerBus.scala:101)
        at org.apache.spark.scheduler.AsyncEventQueue.super$postToAll(AsyncEventQueue.scala:105)
        at org.apache.spark.scheduler.AsyncEventQueue.$anonfun$dispatch$1(AsyncEventQueue.scala:105)
        at scala.runtime.java8.JFunction0$mcJ$sp.apply(JFunction0$mcJ$sp.java:23)
        at scala.util.DynamicVariable.withValue(DynamicVariable.scala:62)
        at org.apache.spark.scheduler.AsyncEventQueue.org$apache$spark$scheduler$AsyncEventQueue$$dispatch(AsyncEventQueue.scala:100)
        at org.apache.spark.scheduler.AsyncEventQueue$$anon$2.$anonfun$run$1(AsyncEventQueue.scala:96)
        at org.apache.spark.util.Utils$.tryOrStopSparkContext(Utils.scala:1356)
        at org.apache.spark.scheduler.AsyncEventQueue$$anon$2.run(AsyncEventQueue.scala:96)

I do not get any sort of exceptions with set number 2 at all.

With set number 3 my spark app actually crashes because executors get lost for some reason, I don't know how a logger can make a spark job crash, but it happens somehow, so, I guess set number 3 is a no go, and now I have to choose between set 1 and set 2.

But the problem is that either

1. Set 1 is more verbose that's why it prints exceptions that set 2 doesn't print.
   or
2. Set 1 causes these exceptions to happen somehow and set 2 doesn't have these exceptions because it's the most suitable set for spark logging.

Which one is it in your opinion?

[razvan]

Hey,

Spark is both a library and an application therefore it comes bundled with both the slf4j-api and a binding (log4j-slf4j2-impl-2.20.0.jar in the listing below). Adding additional bindings (like logback) will cause trouble as the one you are seeing.

According to the link in the warning , there should be one and only one such jar in the classpath.

My suggestion would be to add the exact same logging dependencies to your application as Spark bundles them.

I hope this helps.

bash-4.4$ ls -l /stackable/spark/jars/ | grep -E 'slf|log'
-rw-r--r-- 1 stackable stackable     62050 Sep  9 02:08 commons-logging-1.1.3.jar
-rw-r--r-- 1 stackable stackable     21143 Sep  9 02:08 jcl-over-slf4j-2.0.7.jar
-rw-r--r-- 1 stackable stackable      5655 Sep  9 02:08 jul-to-slf4j-2.0.7.jar
-rw-r--r-- 1 stackable stackable    344375 Sep  9 02:08 log4j-1.2-api-2.20.0.jar
-rw-r--r-- 1 stackable stackable    313296 Sep  9 02:08 log4j-api-2.20.0.jar
-rw-r--r-- 1 stackable stackable   1845871 Nov 23 15:44 log4j-core-2.20.0.jar
-rw-r--r-- 1 stackable stackable     26430 Sep  9 02:08 log4j-slf4j2-impl-2.20.0.jar
-rw-r--r-- 1 stackable stackable     12483 Sep  9 02:08 logging-interceptor-3.12.12.jar
-rw-r--r-- 1 stackable stackable      5711 Sep  9 02:08 minlog-1.3.0.jar
-rw-r--r-- 1 stackable stackable     63635 Sep  9 02:08 slf4j-api-2.0.7.jar

[paulpaul1076]

Sorry, didn't see this. If stackable spark bundles these dependencies, then why are logs not printed? /stackable/spark/jars is on the classpath.

Why do I need to add these dependencies to my spark application, they should be specified as dependencies of Spark jars and picked up.

[razvan]

Hey, do you happen to have log aggregation turned on in your application spec as documented here ?

If you don't need it, you can remove the enableVectorAgent property or explicitly set it to false as shown below:

  job:
    config:
      logging:
        enableVectorAgent: false
  executor:
    config:
      logging:
        enableVectorAgent: false
  driver:
    config:
      logging:
        enableVectorAgent: false

For more examples on how log aggregation can be configured, have a look at the integration tests.

[paulpaul1076]

Hey @razvan I have been busy testing out other things with apache iceberg, haven't had the time to look into this yet. But I will try to find the time soon, I think it's important to properly configure logging.

No, I do not have logging aggregation turned on (not that I know of), in the yaml files that I supply to kubectl apply I don't write anything like what you mentioned. And there still aren't logs in pods unless I add a logging jar library. Are you sure they're supposed to work without supplying a logging jar?

Also, what you showed is really interesting, so, the logs can be persisted to s3 and other sinks, I think we need to configure that, also. Btw, the article you linked talks about using elastic search to query logs and storing logs in different sinks. Do you think it's possible to configure these logs such that they are stored in s3 and show up in Spark history server? We have a spark history server running, but there's only information about how Spark UI looked during a Spark job run, there are no logs (See picture below. P.S. "Event Log" isn't the text logs produced by driver or executor).

[razvan]

Hey,

the Spark history server is unfortunately only a monitoring tool. It doesn't aggregate log messages from Spark applications. It just provides a UI for application life-cycle events after they are finished.

For application log aggregation, the Stackable Spark Operator installs a vector agent in form of a side car container with every Spark application Pod.

The user is responsible for setting up the vector aggregator and configure the sinks he/she wants. We have documentation on how to do that here and also have examples in the integration tests. We are happy to take feedback if you find something wrong or unclear.

[razvan]

Can you post your application manifests here and any other relevant information like SDP version, Kubernetes platform, what are you expecting to see, etc?

[paulpaul1076]

Sorry, what is an application manifest? Is the yaml file that I supply to kubectl apply -f enough?
Here it is:

apiVersion: spark.stackable.tech/v1alpha1
kind: SparkApplication
metadata:
  name: test-job3

  namespace: spark
spec:
  version: "1.0"
  mainApplicationFile: s3a://obs-zdp-warehouse-stage-mz/test_streaming.jar
  mainClass: org.example.StreamingSparkSimplyPartitioned
  args:
    - "stage.test_simply_partitioned3"
  sparkImage:
    custom: registry.zvq.me/stackable/spark-k8s:3.5.0-stackable23.11.0
    productVersion: 3.5.0
    pullPolicy: IfNotPresent
  mode: cluster
  sparkConf:
    spark.driver.extraClassPath: /dependencies/jars/*:/stackable/spark/extra-jars/*
    spark.driver.extraJavaOptions: -Daws.region=(redacted)
    spark.executor.extraClassPath: /dependencies/jars/*:/stackable/spark/extra-jars/*
    spark.executor.extraJavaOptions: -Daws.region=(redacted)
    spark.hadoop.fs.s3.impl: org.apache.hadoop.fs.s3a.S3AFileSystem
    spark.hadoop.fs.s3a.access.key: (redacted)
    spark.hadoop.fs.s3a.aws.credentials.provider: org.apache.hadoop.fs.s3a.SimpleAWSCredentialsProvider
    spark.hadoop.fs.s3a.bucket.obs-de-cicd-mz.access.key: (redacted)
    spark.hadoop.fs.s3a.bucket.obs-de-cicd-mz.secret.key: (redacted)
    spark.hadoop.fs.s3a.bucket.obs-de-export-mz.access.key: (redacted)
    spark.hadoop.fs.s3a.bucket.obs-de-export-mz.secret.key: (redacted)
    spark.hadoop.fs.s3a.bucket.obs-de-temporary-mz.access.key: (redacted)
    spark.hadoop.fs.s3a.bucket.obs-de-temporary-mz.secret.key: (redacted)
    spark.hadoop.fs.s3a.bucket.obs-zdp-warehouse-stage-mz.access.key: (redacted)
    spark.hadoop.fs.s3a.bucket.obs-zdp-warehouse-stage-mz.secret.key: (redacted)
    spark.hadoop.fs.s3a.endpoint: (redacted)
    spark.hadoop.fs.s3a.impl: org.apache.hadoop.fs.s3a.S3AFileSystem
    spark.hadoop.fs.s3a.secret.key: (redacted)
    spark.kubernetes.memoryOverheadFactor: '0.2'
    spark.sql.ansi.enabled: 'true'
    spark.sql.catalog.iceberg_catalog.io-impl: org.apache.iceberg.aws.s3.S3FileIO
    spark.sql.catalog.iceberg_catalog.s3.access.key: (redacted)
    spark.sql.catalog.iceberg_catalog.s3.delete-enabled: 'false'
    spark.sql.catalog.iceberg_catalog.s3.endpoint: (redacted)
    spark.sql.catalog.iceberg_catalog.s3.path-style-access: 'true'
    spark.sql.catalog.iceberg_catalog.s3.secret.key: (redacted)
    spark.sql.catalog.iceberg_catalog.s3a.path-style-access: 'true'
    spark.sql.catalog.iceberg_catalog.type: hive
    spark.sql.catalog.iceberg_catalog.uri: (redacted)
    spark.sql.catalog.iceberg_catalog.warehouse: s3a://obs-zdp-warehouse-stage-mz/
    spark.sql.catalog.iceberg_catalog: org.apache.iceberg.spark.SparkCatalog
    spark.sql.catalogImplementation: hive
    spark.sql.debug: 'false'
    spark.sql.defaultCatalog: iceberg_catalog
    spark.sql.extensions: org.apache.iceberg.spark.extensions.IcebergSparkSessionExtensions
    spark.sql.storeAssignmentPolicy: ANSI


  logFileDirectory:
    s3:
      prefix: eventlogs/
      bucket:
        inline:
          bucketName: obs-zdp-warehouse-stage-mz
          connection:
            inline:
              host: (redacted)
              tls:
                verification:
                  server:
                    caCert:
                      webPki: {}
              port: 443
              accessStyle: Path
              credentials:
                secretClass: obs-s3-credentials-secret
  volumes:
    - name: job-deps
      persistentVolumeClaim:
        claimName: spark-pvc

  env:
    - name: AWS_ACCESS_KEY_ID
      value: "(redacted)"
    - name: AWS_SECRET_ACCESS_KEY
      value: "(redacted)"

  driver:
    config:
      resources:
        cpu:
          min: '250m'
          max: "1"
        memory:
          limit: '8Gi'
      volumeMounts:
        - name: job-deps
          mountPath: /dependencies/jars
  executor:
    replicas: 2
    config:
      resources:
        cpu:
          min: '500m'
          max: "2"
        memory:
          limit: '24Gi'
      volumeMounts:
        - name: job-deps
          mountPath: /dependencies/jars

I am simply expecting Spark to print out logs, but when I look at the logs of Spark pods I don't see any Spark logs whatsoever.

If I run my spark apps without putting log4j-slf4j-impl-2.22.0.jar into /dependencies/jars (this is a location in another pod with user supplied jars, this location is mounted into Spark pods) there are no Spark logs whatsoever, just this message:

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.

You mentioned in one of the previous messages that there's the location /stackable/spark/jars/* under which there are logging jars, and I can see this when I start my Spark apps:

+ SPARK_CLASSPATH='/opt/spark/conf::/stackable/spark/jars/*'
+ SPARK_CLASSPATH='/opt/spark/conf::/stackable/spark/jars/*:/stackable/spark-3.5.0-bin-hadoop3'

So, this means, that this location does go on the classpath, yet, it is not enough to make Spark write logs. And logs only start showing, like I said, only when I put log4j-slf4j-impl-2.22.0.jar into /dependencies/jars.

[razvan]

Maybe it's just a copy&paste error, but if not, lines like this are not valid Yaml and it might be truncated by the k8s api server (I haven't tested):

spark.executor.extraClassPath: /dependencies/jars/*:/stackable/spark/extra-jars/*

You need to put the value in quotes.

Does the application even run at all?

[paulpaul1076]

@razvan no, this line works perfectly fine and is not truncated. This line is the reason why logging works. Yes, everything works, this is a yaml file from a working example.

[razvan]

Ok, you might be affected by this bug we fixed recently.

If you want to try it out now, you need to install the development version of the Spark operator.