Logging a Spark stream: the job you cannot restart to debug

• Why does a streaming job break the batch logging playbook?
• What does a single micro-batch actually log?
• How do you write a Log4j 2 config for a query with no end?
  • Bound the file before anything else
  • Silence the per-partition bookkeeping
  • Raise a level without restarting the query
  • Get the file to the driver and the executors
• What changes on a Log4j 1 cluster?
  • The syntax and the flag
  • The old flag still works on a current Spark, which is not what you would expect
  • What the bridge costs you
  • Migrating a config
• Where do the logs actually go on a job that never finishes?
• Is there something better than parsing log lines?
• Recommendations
• Frequently asked questions
• References
• Trademarks

TL;DR

• A streaming query’s log volume is driven by spark.sql.shuffle.partitions, not by how much data arrives. Measured on a stateful query below: 65 lines per micro-batch at 4 partitions, 233 at 16, with identical input.
• The loudest loggers are not the ones narrating your query. They are CheckpointFileManager, StateStore and HDFSBackedStateStoreProvider, which log several times per partition per batch.
• A batch job can be resubmitted with DEBUG. A streaming job cannot, so set monitorInterval and Log4j 2 will re-read the file on a running query. Verified below: config edited at 12:16:15, first new line at 12:16:22.
• Console and file appenders on a job with no end need a rollover policy and a retention cap, or the container’s disk is the retention policy. With a date in the file pattern, DefaultRolloverStrategy max caps each period, not the total; a Delete action caps the total.
• StreamingQueryListener gives you one structured line per batch with the batch id, input rows, state rows and watermark, which is what you were grepping the other 150 lines to reconstruct.

Why does a streaming job break the batch logging playbook?

The usual way to debug a Spark job is to resubmit it with a custom Log4j config and DEBUG on two packages. That advice is sound, and it is written up for batch work in a Spark JVM playbook. Three things about a streaming query make it insufficient.

The run has no end. A batch job’s log is bounded by the job. A streaming query writes until someone stops it, so “how big does this file get” has no answer until you impose one.

You cannot resubmit it. Restarting a streaming query to turn on DEBUG means an outage, a checkpoint recovery, and the loss of whatever transient condition you were trying to observe. The interesting failures are the ones that show up after six hours, and they do not survive a restart.

The volume is structural. A batch job logs roughly in proportion to its stages. A streaming query logs the same lines again every trigger interval, and the count of those lines is set by the shape of the query, not by the traffic.

flowchart LR
    T[Trigger fires] --> O[Read offsets]
    O --> P[Plan micro-batch]
    P --> S[Per-partition state store work]
    S --> C[Checkpoint offsets and commit]
    C --> W[Write progress event]
    W --> T
    S -.->|"one set of log lines<br/>per partition, per batch"| L[(Log file)]
    C -.-> L
    W -.-> L

That loop is the whole problem. Everything below is about deciding what it is allowed to write each time round.

What does a single micro-batch actually log?

Rather than guess, measure. The query is a windowed count over a rate source, a five second tumbling window with a ten second watermark, on a two second trigger, run on Spark 4.1.3 and, for contrast, on 3.5.9:

from pyspark.sql import SparkSession
from pyspark.sql.functions import window, col, count

spark = (SparkSession.builder
         .appName("order-events-logging-demo")
         .config("spark.ui.enabled", "false")
         .config("spark.eventLog.enabled", "false")
         .config("spark.sql.shuffle.partitions", "4")
         .getOrCreate())

events = (spark.readStream.format("rate")
          .option("rowsPerSecond", 200)
          .option("numPartitions", 2)
          .load()
          .withColumnRenamed("value", "order_id"))

orders_per_window = (events
                     .withWatermark("timestamp", "10 seconds")
                     .groupBy(window(col("timestamp"), "5 seconds"))
                     .agg(count("order_id").alias("order_count")))

query = (orders_per_window.writeStream
         .format("console")
         .option("truncate", "false")
         .outputMode("update")
         .trigger(processingTime="2 seconds")
         .queryName("orders_per_window")
         .start())

query.awaitTermination(70)
query.stop()
spark.stop()

Run it with the root logger at WARN and only the streaming package at INFO, so nothing but the query’s own narration is counted:

rootLogger.level = warn
rootLogger.appenderRef.stdout.ref = console

appender.console.type = Console
appender.console.name = console
appender.console.target = SYSTEM_ERR
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %d{HH:mm:ss} %-5p %c{1} - %m%n

logger.streaming.name = org.apache.spark.sql.execution.streaming
logger.streaming.level = info

spark-submit \
  --master "local[2]" \
  --conf spark.ui.enabled=false \
  --conf spark.eventLog.enabled=false \
  --driver-java-options "-Dlog4j.configurationFile=/work/log4j2-probe.properties" \
  /work/steady.py

Counting the log lines between the fourth and the ninth committed batch, so startup is excluded, gives this split by logger. The multi-line progress JSON counts as one line. Class names are shortened; the full names follow the table.

The 3.5.9 16-partition run also logged two WARN ProcessingTimeExecutor “falling behind” lines over those five batches, left out of the total because they come from the container being busy, not from the query.

The input was identical in every run. Only spark.sql.shuffle.partitions changed, from 4 to 16, and the per-batch log volume more than tripled on both lines.

Two things changed between the lines. Spark 4.1 moved the streaming engine into subpackages, so the classes above live in different places depending on the version:

And 4.1.3 writes a checksum file next to every state delta file, controlled by spark.sql.streaming.checkpoint.fileChecksum.enabled. Nothing in this run set it, yet every N.delta got an N.delta.crc, which is where the extra CheckpointFileManager and ChecksumCancellableFSDataOutputStream lines come from.

Most of those loggers are per-partition bookkeeping. On 4.1.3, StateStore prints that it resolved the coordinator and that a provider instance is active, twice per partition per batch, once for the restore step and once for the save step. HDFSBackedStateStoreProvider prints the version it retrieved (twice), the cache update and the version it committed. CheckpointFileManager prints a write and a rename for the delta file and again for its checksum file. Its logger name also carries the provider id, which is why the %c{1} pattern prints more than the class name. One partition’s share of one batch, with paths and ids shortened:

INFO  StateStore - Reported that the loaded instance StateStoreProviderId[ storeId=StateStoreId[ operatorId=0, partitionId=1, storeName=default ], ... ] is active
INFO  HDFSBackedStateStoreProvider StateStoreProviderId[ ... partitionId=1 ... ] - Retrieved version 4 of HDFSStateStoreProvider[...]
INFO  CheckpointFileManager - Writing atomically to file:/tmp/temporary-a9ab3903-.../state/0/1/5.delta using temp file .../state/0/1/.5.delta.8126a271-....tmp
INFO  CheckpointFileManager - Writing atomically to file:/tmp/temporary-a9ab3903-.../state/0/1/5.delta.crc using temp file .../state/0/1/.5.delta.crc.c2091f91-....tmp
INFO  ChecksumCancellableFSDataOutputStream - Created checksum for file file:/tmp/temporary-a9ab3903-.../state/0/1/5.delta: {"algorithm":"CRC32C","value":-1612501305,"mainFileSize":91,...}
INFO  CheckpointFileManager - Renamed temp file .../state/0/1/.5.delta.8126a271-....tmp to .../state/0/1/5.delta
INFO  CheckpointFileManager - Renamed temp file .../state/0/1/.5.delta.crc.c2091f91-....tmp to .../state/0/1/5.delta.crc
INFO  HDFSBackedStateStoreProvider StateStoreProviderId[ ... partitionId=1 ... ] - Trying to add version=5 to state cache map with current_size=2 and earliest_loaded_version=3 and max_versions_to_retain_in_memory=2
INFO  HDFSBackedStateStoreProvider StateStoreProviderId[ ... partitionId=1 ... ] - Committed version 5 for HDFSStateStore[...] to file .../state/0/1/5.delta

Only one line per batch comes from MicroBatchExecution on 4.1.3, the offsets commit. The progress JSON, which MicroBatchExecution itself logged on 3.5.9, now comes from ProgressReporter.

The arithmetic from there is unkind. At 233 lines per batch and a two second trigger, a query produces 43,200 batches a day, so roughly 10 million lines. Nothing in that total scales with how much data you are processing.

The first decision, then, is not which level to use. It is whether the per-partition loggers are on at all.

How do you write a Log4j 2 config for a query with no end?

Spark has used Log4j 2 since 3.3.0. The file is log4j2.properties, the flag is -Dlog4j.configurationFile=, and the syntax is logger.<key>.name rather than log4j.logger.<name>. Start from the log4j2.properties.template in the binary distribution’s conf/ directory rather than writing one from memory; the property names are not guessable. The apache/spark container images do not carry that directory (there is no /opt/spark/conf in the 4.1.3 image), so take the template from the release tarball.

Bound the file before anything else

A Console appender on a streaming job writes into whatever the resource manager captured, and that file grows until the disk fills. Use RollingFile with both a triggering policy and a retention cap:

rootLogger.level = warn
rootLogger.appenderRef.rolling.ref = rolling

appender.rolling.type = RollingFile
appender.rolling.name = rolling
appender.rolling.fileName = ${sys:spark.yarn.app.container.log.dir:-/var/log/spark}/streaming.log
appender.rolling.filePattern = ${sys:spark.yarn.app.container.log.dir:-/var/log/spark}/streaming-%d{yyyy-MM-dd}-%i.log.gz
appender.rolling.layout.type = PatternLayout
appender.rolling.layout.pattern = %d{yyyy-MM-dd HH:mm:ss} %-5p %c{1} - %m%n

appender.rolling.policies.type = Policies
appender.rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.rolling.policies.size.size = 64MB
appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
appender.rolling.policies.time.interval = 1

appender.rolling.strategy.type = DefaultRolloverStrategy
appender.rolling.strategy.max = 10
appender.rolling.strategy.delete.type = Delete
appender.rolling.strategy.delete.basePath = ${sys:spark.yarn.app.container.log.dir:-/var/log/spark}
appender.rolling.strategy.delete.maxDepth = 1
appender.rolling.strategy.delete.name.type = IfFileName
appender.rolling.strategy.delete.name.glob = streaming-*.log.gz
appender.rolling.strategy.delete.name.count.type = IfAccumulatedFileCount
appender.rolling.strategy.delete.name.count.exceeds = 10

The retention part is the part people leave out, and it is the part that matters. strategy.max caps the %i counter, so it bounds how many archives are kept for one value of the %d{...} date. It does not bound the total: the next day starts again at -1, and yesterday’s archives stay on disk. The Delete action is what caps the total, by counting every archive that matches the glob and deleting the oldest beyond exceeds.

The .gz suffix on filePattern is not decoration. Log4j 2 compresses on rollover when the pattern ends in .gz, .zip or .xz, and Spark logs compress well.

All three runs below are the demo query on Spark 4.1.3 with size = 64KB and max = 3, shrunk so rollover happens in a short run, the streaming package at INFO so there is enough to roll, and -Dspark.yarn.app.container.log.dir set on the driver to a scratch directory so the ${sys:...} lookup is exercised outside YARN.

Without the Delete action and with the daily pattern, the directory holds exactly the promised set:

-rw-r--r-- 1 root root  4946 Sep 27 08:14 streaming-2026-09-27-1.log.gz
-rw-r--r-- 1 root root  5068 Sep 27 08:15 streaming-2026-09-27-2.log.gz
-rw-r--r-- 1 root root  4927 Sep 27 08:15 streaming-2026-09-27-3.log.gz
-rw-r--r-- 1 root root 47837 Sep 27 08:15 streaming.log

-Dlog4j2.debug=true shows the run rolled ten times. From the fourth rollover on, DefaultRolloverStrategy.purgeAscending renamed -2 over -1 and -3 over -2 before writing the new -3, so three archives is what survived.

That run never crossed a date boundary, so it cannot show the gap. Changing the pattern to %d{yyyy-MM-dd-HH-mm}, a new period every minute, and running across a minute boundary can:

-rw-r--r-- 1 root root  5979 Sep 27 08:15 streaming-2026-09-27-08-15-1.log.gz
-rw-r--r-- 1 root root  4835 Sep 27 08:15 streaming-2026-09-27-08-15-2.log.gz
-rw-r--r-- 1 root root  2096 Sep 27 08:16 streaming-2026-09-27-08-15-3.log.gz
-rw-r--r-- 1 root root  4972 Sep 27 08:16 streaming-2026-09-27-08-16-1.log.gz
-rw-r--r-- 1 root root  4927 Sep 27 08:16 streaming-2026-09-27-08-16-2.log.gz
-rw-r--r-- 1 root root  5124 Sep 27 08:16 streaming-2026-09-27-08-16-3.log.gz
-rw-r--r-- 1 root root 52072 Sep 27 08:16 streaming.log

Six archives with max = 3: three per period. On the daily pattern a query that runs for a month keeps up to max archives for each of thirty days. Adding the Delete action, with exceeds = 3 for the test, brings the per-minute run back to three in total:

-rw-r--r-- 1 root root  4840 Sep 27 08:21 streaming-2026-09-27-08-21-1.log.gz
-rw-r--r-- 1 root root  4973 Sep 27 08:21 streaming-2026-09-27-08-21-2.log.gz
-rw-r--r-- 1 root root  4989 Sep 27 08:21 streaming-2026-09-27-08-21-3.log.gz
-rw-r--r-- 1 root root 17848 Sep 27 08:21 streaming.log

The status log shows the previous minute’s archives going once the count passed three:

TRACE IfAccumulatedFileCount ACCEPTED: streaming-2026-09-27-08-20-1.log.gz count '4' > threshold '3'
TRACE Deleting /work/roll3/streaming-2026-09-27-08-20-1.log.gz

Nest the count condition inside IfFileName, as above. A first attempt put IfAccumulatedFileCount beside IfFileName rather than under it, and the status log showed it counting the active streaming.log as well (IfAccumulatedFileCount REJECTED: streaming.log count '2' <= threshold '3'), so the run finished with two archives instead of three.

One runtime detail from the same status log. The rename and purge ran synchronously on whichever thread wrote the line that crossed the size limit, which in these runs included stream execution thread for orders_per_window, Executor task launch worker for task ... and ChecksumCheckpointFileManager-Thread-1. Only the gzip and the Delete ran on Log4j’s own Log4j2-TF-1-RollingFileManager threads. A rollover is a short stall on a task or on the query’s own thread, which is another reason to keep size in megabytes rather than kilobytes outside a test.

Silence the per-partition bookkeeping

With the file bounded, cut what goes into it. These are the three loggers the measurement identified, plus the one you want to keep:

# the per-partition bookkeeping: one set of lines per partition per batch
logger.statestore.name = org.apache.spark.sql.execution.streaming.state
logger.statestore.level = warn

logger.ckpt.name = org.apache.spark.sql.execution.streaming.checkpointing
logger.ckpt.level = warn

# the query's own narration: one commit line and one progress JSON per batch
logger.micro.name = org.apache.spark.sql.execution.streaming.runtime.MicroBatchExecution
logger.micro.level = info
logger.progress.name = org.apache.spark.sql.execution.streaming.runtime.ProgressReporter
logger.progress.level = info

# the scheduler, which logs per task and not per batch
logger.dag.name = org.apache.spark.scheduler
logger.dag.level = warn
logger.blockmgr.name = org.apache.spark.storage.BlockManagerInfo
logger.blockmgr.level = warn

Those names are for 4.1.x. On 3.5.x the checkpoint and narration loggers are org.apache.spark.sql.execution.streaming.CheckpointFileManager and org.apache.spark.sql.execution.streaming.MicroBatchExecution, and the progress JSON comes from MicroBatchExecution itself. A 3.5 file carried to 4.1 unchanged does not fail: Log4j 2 accepts a logger name that no class uses, so the MicroBatchExecution rule just stops matching anything and the query’s narration goes quiet under a WARN root. Running the 3.5 form of this block on 4.1.3 did exactly that: 35 micro-batches completed and not one MicroBatchExecution INFO line was written. Of the streaming rules above, only the ...streaming.state one works on both lines.

With the root at WARN and this block, the demo query on 4.1.3 wrote two lines per batch: the MicroBatchExecution commit and the ProgressReporter JSON.

The scheduler pair is worth its own note. Leaving rootLogger.level = info and only muting the state and checkpoint loggers is not enough: with the root at INFO, the same query at 4 partitions wrote 92 lines per batch, led by DAGScheduler (20), TaskSetManager (12), Executor (12), and MemoryStore, ShuffleBlockFetcherIterator and DataWritingSparkTask (8 each). The scheduler logs per task, and a streaming query runs a full set of tasks every trigger.

The working rule is to set the root to WARN and name the handful of loggers you want at INFO, rather than the reverse.

Raise a level without restarting the query

This is the setting that only matters on a streaming job, and it is one line:

monitorInterval = 5

Log4j 2 then stats the configuration file every five seconds and reconfigures itself if the timestamp moved. No restart, no checkpoint recovery, no lost state.

The test, on Spark 4.1.3: start the demo query with a WARN root, the console appender from the probe config, and MicroBatchExecution and ProgressReporter both at WARN, wait, then edit the file in place to INFO while the query is running.

# with the query already running
sed -i 's/^logger.micro.level = warn/logger.micro.level = info/; s/^logger.progress.level = warn/logger.progress.level = info/' /work/log4j2-live.properties

query started at                12:15:13
config edited at                12:16:15
12:16:16 WARN  ProcessingTimeExecutor - Current batch is falling behind. The trigger interval is 2000 milliseconds, but spent ...
12:16:18 WARN  ProcessingTimeExecutor - Current batch is falling behind. The trigger interval is 2000 milliseconds, but spent ...
12:16:22 INFO  ProgressReporter - Streaming query made progress: {
12:16:22 INFO  MicroBatchExecution - Committed offsets for batch 15. Metadata OffsetSeqMetadata(...)
12:16:25 INFO  ProgressReporter - Streaming query made progress: {
12:16:25 INFO  MicroBatchExecution - Committed offsets for batch 16. Metadata OffsetSeqMetadata(...)

Not one INFO line from either logger appeared in the minute before the edit, and the first one, the progress report for batch 14, appeared seven seconds after it: up to five seconds for Log4j to notice the new timestamp, then the wait for the running batch to finish and log something. The falling behind warnings are the shared test machine being slow, not part of the mechanism. Turn the levels back down the same way when you have seen enough.

Two caveats. monitorInterval costs a stat on every interval, per JVM, so do not set it to one second across a thousand executors. And the file it watches is the one the JVM resolved at startup, so on a cluster you edit the copy that was shipped to the container, not the one on the submitting machine.

Get the file to the driver and the executors

Nothing here is streaming-specific, and the mechanics are the same as for a batch job. The YARN commands in this section were not run for this post, since the test setup has no cluster; the flags and properties are the standard spark-submit ones. In cluster mode both sides need the file shipped and referenced by its bare name, because --files places it in the container’s working directory:

spark-submit \
  --master yarn \
  --deploy-mode cluster \
  --files /tmp/log4j2-streaming.properties \
  --conf spark.driver.extraJavaOptions="-Dlog4j.configurationFile=log4j2-streaming.properties" \
  --conf spark.executor.extraJavaOptions="-Dlog4j.configurationFile=log4j2-streaming.properties" \
  orders_stream.py

In client mode the driver JVM is already running on the submitting machine, so it takes an absolute local path while the executors still take the bare name:

spark-submit \
  --master yarn \
  --deploy-mode client \
  --files /tmp/log4j2-streaming.properties \
  --driver-java-options "-Dlog4j.configurationFile=/tmp/log4j2-streaming.properties" \
  --conf spark.executor.extraJavaOptions="-Dlog4j.configurationFile=log4j2-streaming.properties" \
  orders_stream.py

Use --driver-java-options rather than spark.driver.extraJavaOptions in client mode. The driver JVM has already been launched by the time the latter is read.

If the two sides need different levels, which is common because the driver runs the query and the executors run the tasks, ship two files and point each side at its own:

spark-submit \
  --master yarn \
  --deploy-mode cluster \
  --files /tmp/log4j2-driver.properties,/tmp/log4j2-executor.properties \
  --conf spark.driver.extraJavaOptions="-Dlog4j.configurationFile=log4j2-driver.properties" \
  --conf spark.executor.extraJavaOptions="-Dlog4j.configurationFile=log4j2-executor.properties" \
  orders_stream.py

What changes on a Log4j 1 cluster?

Spark used Log4j 1.x up to and including 3.2.x. Plenty of streaming jobs are still running there, so the equivalents are worth having, and one detail about how the two versions coexist is worth more than the syntax.

The syntax and the flag

Log4j 1 names a level and an appender list on one property, and configures the appender with dotted sub-properties. The same “root quiet, streaming loud” policy as above looks like this:

log4j.rootLogger=WARN, rolling

log4j.appender.rolling=org.apache.log4j.RollingFileAppender
log4j.appender.rolling.File=/var/log/spark/streaming.log
log4j.appender.rolling.MaxFileSize=64MB
log4j.appender.rolling.MaxBackupIndex=10
log4j.appender.rolling.layout=org.apache.log4j.PatternLayout
log4j.appender.rolling.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1} - %m%n

log4j.logger.org.apache.spark.sql.execution.streaming=INFO
log4j.logger.org.apache.spark.sql.execution.streaming.state=WARN
log4j.logger.org.apache.spark.scheduler=WARN

Two details differ from the Log4j 2 file. Many Log4j 1 files write log4j.rootCategory rather than log4j.rootLogger; both are accepted, because rootCategory is the older alias. And rollover here is two properties on the appender, MaxFileSize and MaxBackupIndex, rather than a separate policy and strategy.

No Log4j 1 Spark was run for this post, so the listing below is not Log4j 1 output. It is what Spark 4.1.3 did with this exact file, MaxFileSize=64KB and MaxBackupIndex=3 for the test, passed as -Dlog4j.configuration=file:/work/legacy-rolling.properties to the demo query:

-rw-r--r-- 1 root root 36704 Sep 27 12:26 streaming.log
-rw-r--r-- 1 root root 65642 Sep 27 12:25 streaming.log.1
-rw-r--r-- 1 root root 65652 Sep 27 12:24 streaming.log.2
-rw-r--r-- 1 root root 65629 Sep 27 12:24 streaming.log.3

The file was not ignored. The log4j-1.2-api bridge, covered in the next section, translated RollingFileAppender into a Log4j 2 rolling file manager: the status log shows nine rollovers, each a DefaultRolloverStrategy.purgeDescending that shifts .2 to .3 and .1 to .2, so Log4j 1’s naming and its cap of three uncompressed backups survive the translation. The bridge also printed WARN RollingFileAppender 'rolling': The bufferSize is set to 8192 but bufferedIO is not true at startup, a warning a Log4j 1 file never produced on Log4j 1. Note too that this file’s ...streaming.state=WARN rule does not touch the 4.1 checkpoint logger, so the archives are full of CheckpointFileManager lines.

The flag is -Dlog4j.configuration=, which accepts either a file: URL or a plain absolute path. Both forms were honoured through the bridge described below, on 3.5.9 and on 4.1.3, and the URL form is the unambiguous one. This cluster-mode command was not run here, because there is no YARN cluster in the test setup; the flags are the same ones the Log4j 2 commands above use:

spark-submit \
  --master yarn \
  --deploy-mode cluster \
  --files /tmp/log4j.properties \
  --conf spark.driver.extraJavaOptions="-Dlog4j.configuration=log4j.properties" \
  --conf spark.executor.extraJavaOptions="-Dlog4j.configuration=log4j.properties" \
  orders_stream.py

The --files and client-versus-cluster rules are identical to the Log4j 2 case, because they are Spark’s rules rather than Log4j’s.

The old flag still works on a current Spark, which is not what you would expect

The reasonable assumption is that a Log4j 1 config on Spark 3.5.x or 4.x is ignored and you fall back to the cluster default. That is not what happens. Spark ships log4j-1.2-api alongside log4j-core (log4j-1.2-api-2.20.0.jar in 3.5.9, log4j-1.2-api-2.24.3.jar in 4.1.3), and that bridge registers a configuration factory which still answers to log4j.configuration and still parses Log4j 1 syntax. The test file is five lines of Log4j 1: log4j.rootCategory=WARN, console, a ConsoleAppender on System.err, and a PatternLayout whose ConversionPattern starts with a marker, LEGACY1 %d{yy/MM/dd HH:mm:ss} %p %c{2}: %m%n. Passing the old flag with that file honours it, including the pattern layout, on both lines:

spark-submit --driver-java-options "-Dlog4j.configuration=file:/work/log4j-legacy.properties" tiny.py

LEGACY1 26/09/27 11:29:04 WARN util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable

That line is from 4.1.3; 3.5.9 printed the same line with its own timestamp. LEGACY1 is the marker, so its presence proves the file was read, and it also shows log4j.rootCategory, the older alias for log4j.rootLogger, still being accepted. -Dlog4j2.debug=true names the factory that won. On 4.1.3, whose status logger prefixes a timestamp and the thread name:

2026-09-27T11:28:54.285406240Z main DEBUG Configuration org.apache.log4j.config.PropertiesConfiguration@416c58f5 initialized
2026-09-27T11:28:54.357563414Z main DEBUG Reconfiguration complete for context[name=5a07e868] at URI /work/log4j-legacy.properties (org.apache.logging.log4j.core.LoggerContext@13526e59) with optional ClassLoader: null

and on 3.5.9:

DEBUG StatusLogger Configuration org.apache.log4j.config.PropertiesConfiguration@4dbb42b7 initialized
DEBUG StatusLogger Reconfiguration complete for context[name=5ffd2b27] at URI /work/log4j-legacy.properties (org.apache.logging.log4j.core.LoggerContext@7c83dc97) with optional ClassLoader: null

org.apache.log4j.config.PropertiesConfiguration is the bridge’s parser, not Log4j 2’s own. The -Dlog4j1.compatibility=true property that the Log4j documentation associates with this path was not set in either run, and was not required on the stock 3.5.9 or 4.1.3 images.

This is a useful thing to know and a bad thing to depend on. It explains why a pre-2022 snippet can still appear to work, which otherwise looks like magic. It also means a team can sit on the bridge for years without noticing what it costs them.

What the bridge costs you

The row that matters for streaming is monitorInterval. On Log4j 1 there is no way to raise a level on a running query, so the only route to more detail is a restart, which is exactly the thing a streaming job makes expensive. If you maintain one long-running streaming job on a 3.2.x cluster, that single capability is a reasonable argument for the upgrade.

Migrating a config

The mapping is mechanical for everything except the appender policies:

The logger.<key> part of a Log4j 2 name is an arbitrary handle. It has to be unique within the file and it has nothing to do with the logger’s actual name, which is what logger.<key>.name sets. Reusing a handle silently overwrites the earlier entry, which is the most common way a migrated file loses a rule.

Where do the logs actually go on a job that never finishes?

This trips people up more than the configuration does.

On YARN, log aggregation copies container logs to HDFS when the container completes. A streaming job’s containers do not complete, so yarn logs -applicationId <id> returns nothing useful for a running query. You read the live logs through the YARN UI’s node manager links, or you go to the node and read the file, or you configure a rolling aggregation interval with yarn.nodemanager.log-aggregation.roll-monitoring-interval-seconds so partial logs are shipped while the application runs.

That last option is the one worth setting up front on a streaming cluster, and it has a Spark-side companion: spark.yarn.rolledLog.includePattern is a Java regex naming which log files get aggregated in a rolling fashion, and the Spark documentation is explicit that it only does anything once the YARN interval above is set in yarn-site.xml. Set one without the other and nothing rolls. Both spark.yarn.rolledLog.includePattern and spark.yarn.app.container.log.dir are present in the 4.1.3 spark-yarn module; their behaviour on a live YARN cluster was not re-tested for this post.

The alternative is discovering during an incident that the logs you want are only on a node you have to go find.

On Kubernetes, the driver and executor pods write to stdout and whatever collects container logs picks them up, which means a RollingFile appender writing inside the pod is usually the wrong choice: the file is invisible to the collector and vanishes with the pod. Prefer the Console appender there and let the platform’s retention apply.

spark.yarn.app.container.log.dir is set by Spark inside a YARN container, and ${sys:spark.yarn.app.container.log.dir} in a Log4j 2 config resolves to it, which is how you write into the directory YARN already knows about.

Is there something better than parsing log lines?

Yes, and for a streaming query it is the right answer more often than not. Every micro-batch produces a StreamingQueryProgress object, and StreamingQueryListener hands it to you as a callback. One line of your own beats reconstructing the same facts from 233 lines of someone else’s:

import logging
from pyspark.sql.streaming import StreamingQueryListener

log = logging.getLogger("orders.progress")

class ProgressLogger(StreamingQueryListener):
    def onQueryStarted(self, event):
        log.warning("query started id=%s name=%s", event.id, event.name)

    def onQueryProgress(self, event):
        p = event.progress
        log.warning(
            "batch=%s input_rows=%s input_rps=%.1f process_rps=%.1f "
            "batch_duration_ms=%s state_rows=%s watermark=%s",
            p.batchId, p.numInputRows, p.inputRowsPerSecond or 0.0,
            p.processedRowsPerSecond or 0.0, p.batchDuration,
            p.stateOperators[0].numRowsTotal if p.stateOperators else None,
            p.eventTime.get("watermark") if p.eventTime else None,
        )

    def onQueryTerminated(self, event):
        log.warning("query terminated id=%s exception=%s", event.id, event.exception)

spark.streams.addListener(ProgressLogger())

Output from the demo query on Spark 4.1.3, one line per batch, with the listener registered before start() and the Log4j root at WARN:

query started id=e0b247c9-0328-45dc-a593-c7ade88337de name=orders_per_window
batch=0 input_rows=0 input_rps=... process_rps=... batch_duration_ms=... state_rows=0 watermark=1970-01-01T00:00:00.000Z
batch=1 input_rows=99800 input_rps=... process_rps=... batch_duration_ms=... state_rows=100 watermark=1970-01-01T00:00:00.000Z
batch=2 input_rows=1800 input_rps=... process_rps=... batch_duration_ms=... state_rows=5 watermark=2026-09-27T12:12:09.178Z
batch=3 input_rows=800 input_rps=... process_rps=... batch_duration_ms=... state_rows=4 watermark=2026-09-27T12:12:18.178Z
...
batch=16 input_rows=600 input_rps=... process_rps=... batch_duration_ms=... state_rows=3 watermark=2026-09-27T12:13:05.178Z
query terminated id=e0b247c9-0328-45dc-a593-c7ade88337de exception=None

The rate and duration values are elided: they came from a container on a busy laptop and say nothing about what your query will do; the point is which fields exist. The row counts are worth reading, though, because this run showed by accident what a stall looks like. The container was starved of CPU while batch 0 ran, and the rate source kept generating rows in the meantime. Batch 1 then picked up the backlog as 99,800 input rows and 100 windows of state, and the next batches settled back to a few hundred rows and a handful of state rows once the watermark moved. Every one of those facts is a field on the progress object.

Two more details in that transcript are worth reading. The watermark is 1970-01-01T00:00:00.000Z for the first two batches, because a watermark is computed from data already seen and there is none yet, so a fresh query is briefly unable to drop anything as late. And state_rows is the number the query fails on eventually: if it climbs without bound, the watermark is not evicting and the job will run out of memory on a schedule you can extrapolate.

Neither fact is easy to see in a log file, and both are one field in the progress object. Log the object, alert on the fields, and keep the Log4j config for the times something throws.

Recommendations

• Set the root logger to WARN and name what you want at INFO. A streaming query at rootLogger.level = info wrote 92 lines per micro-batch in the run above even with the state and checkpoint loggers muted, most of it from the scheduler.
• Mute org.apache.spark.sql.execution.streaming.state and the checkpoint logger unless you are debugging state. The checkpoint logger is ...streaming.checkpointing on 4.1 and ...streaming.CheckpointFileManager on 3.5. They are where the per-partition volume comes from, and they scale with spark.sql.shuffle.partitions.
• Re-check logger names when you move a config between Spark lines. The 4.1 package move leaves a 3.5 rule for MicroBatchExecution matching nothing, without an error.
• Give every file appender a DefaultRolloverStrategy with max and a Delete action. A triggering policy alone bounds each file, max bounds each date period, and only Delete bounds the total.
• Set monitorInterval on every streaming job, even when you never use it. It costs a stat per interval and it is the difference between raising a log level and taking an outage.
• Add a StreamingQueryListener before you tune the Log4j config. Most of what people raise the log level to find is already a field on StreamingQueryProgress.
• On YARN, set a rolling aggregation interval. Otherwise the logs for a running streaming job are only on the node that produced them.

The mental model worth keeping: a batch job’s log describes a thing that happened, and a streaming job’s log describes a loop that is still going. You read the first one afterwards and the second one while it runs. Everything above follows from that, including why the same config that is fine for a batch job fills a disk here, and why the one Log4j 2 feature that matters most is the one that lets you change your mind without stopping.

Frequently asked questions

Why is my streaming log full of StateStore and CheckpointFileManager lines? Both log once per partition per micro-batch, so the volume is set by spark.sql.shuffle.partitions rather than by traffic. Measured on a windowed count on Spark 4.1.3, the per-batch total went from 65 lines at 4 partitions to 233 at 16 with identical input (43 and 151 on 3.5.9). Set logger.statestore.name = org.apache.spark.sql.execution.streaming.state to warn to remove most of it.

Can I change the log level of a running Spark streaming query? Yes, with Log4j 2. Add monitorInterval = 5 to the config and edit the file the container actually resolved; Log4j 2 re-reads it within the interval. There is no equivalent on Log4j 1, so a Spark 3.2.x or earlier cluster requires a restart.

Does spark.sparkContext.setLogLevel() work for this? It sets the root logger’s level, so it is all or nothing. Calling setLogLevel("INFO") on a Spark 4.1.3 run whose config had rootLogger.level = warn, then running one small aggregation, turned on DAGScheduler, CodeGenerator, MemoryStore, TaskSetManager, Executor and SecurityManager along with everything else. It is the right tool for “show me everything for a moment” and the wrong one for raising a single package, which is what monitorInterval and a named logger give you.

Does the old log4j.properties still work on Spark 3.3.0 and later? On the stock 3.5.9 and 4.1.3 images, yes. Spark bundles log4j-1.2-api, whose configuration factory answers to -Dlog4j.configuration and parses Log4j 1 syntax. You give up monitorInterval, rollover compression, retention caps and JSON layout by staying on it, so treat it as a migration aid.

Why is my log file still growing after I set a rollover policy? A triggering policy bounds each file; DefaultRolloverStrategy with max bounds how many are kept. Without strategy.max the appender renames files forever.

Why does yarn logs -applicationId return nothing for my streaming job? Log aggregation runs when a container completes, and a streaming job’s containers do not. Read the live logs through the node manager, or set yarn.nodemanager.log-aggregation.roll-monitoring-interval-seconds so partial logs are aggregated while the application runs.

My executor logging config has no effect but the driver’s works. Either spark.executor.extraJavaOptions is unset, or the file was not listed in --files, or the executor side was given an absolute path from the submitting machine. Executors need the bare filename, because --files places the file in the container’s working directory.

References

• Structured Streaming programming guide for triggers, watermarks, StreamingQueryListener and the progress object’s fields
• Log4j 2 configuration for monitorInterval, the properties syntax, and the RollingFile triggering policies and rollover strategy
• Running Spark on YARN for spark.yarn.app.container.log.dir and container log locations
• A Spark JVM playbook for how a Log4j config reaches the driver and executors on a batch job
• Spark and Hudi logging for the same mechanism applied to a write path rather than a stream

Trademarks

Apache Spark, Apache Log4j, Apache Hadoop, Apache Kafka and Apache are either registered trademarks or trademarks of The Apache Software Foundation in the United States and other countries.