Skip to content

Anchor spark-submit log trail on actual exception instead of lines - #70513

Merged
amoghrajesh merged 2 commits into
apache:mainfrom
astronomer:better-log-buffering
Jul 27, 2026
Merged

Anchor spark-submit log trail on actual exception instead of lines#70513
amoghrajesh merged 2 commits into
apache:mainfrom
astronomer:better-log-buffering

Conversation

@amoghrajesh

Copy link
Copy Markdown
Contributor

Was generative AI tooling used to co-author this PR?
  • Yes (please specify the tool below)

Related to #70178

The previous fix kept a rolling tail of the last 20 lines of spark-submit's own output, but deep JVM stack traces (Fabric8/Vert.x/Netty chains routinely run 70+ lines through nested Caused by: blocks) pushed the real exception
message out of the buffer before the process finished, leaving only bare stack frames with no message text. A live K8s quota rejection test reproduced this exactly: the LLM retry policy saw only Netty I/O frames and misclassified
a permanent quota error as a transient SSL issue.

Anchor capture on the JVM's own uncaught-exception marker (Exception in thread "...") instead of a blind line count. Everything before the marker is noise (banners, WARN logs) and is dropped; everything from the marker onward is kept, with a generous safety-valve cap rather than a tight rolling window. If spark-submit never throws an uncaught exception,
nothing is captured and the failure message carries no log tail, rather than a plain last-N tail of possibly-irrelevant output.

Testing

Error thrown now:

2026-07-27 15:35:25] ERROR - Task failed with exception
AirflowException: Cannot execute: spark-submit --master k8s://https://host.docker.internal:6445 --conf spark.kubernetes.container.image=apache/spark:3.5.3 --conf spark.kubernetes.authenticate.driver.serviceAccountName=spark --conf spark.driver.extraJavaOptions=-Djavax.net.ssl.trustAll=true --conf spark.executor.extraJavaOptions=-Djavax.net.ssl.trustAll=true --conf spark.kubernetes.submission.waitAppCompletion=false --conf spark.kubernetes.namespace=spark --name arrow-spark --class org.apache.spark.examples.SparkPi --deploy-mode cluster local:///opt/spark/examples/jars/spark-examples_2.12-3.5.3.jar 100. Error code is: 1. Kubernetes spark exit code is: None
Last spark-submit output:
Exception in thread "main" io.fabric8.kubernetes.client.KubernetesClientException: Failure executing: POST at: https://host.docker.internal:6445/api/v1/namespaces/spark/pods. Message: pods "arrow-spark-5808b09fa309515b-driver" is forbidden: exceeded quota: spark-demo-quota, requested: count/pods=1, used: count/pods=3, limited: count/pods=3. Received status: Status(apiVersion=v1, code=403, details=StatusDetails(causes=[], group=null, kind=pods, name=arrow-spark-5808b09fa309515b-driver, retryAfterSeconds=null, uid=null, additionalProperties={}), kind=Status, message=pods "arrow-spark-5808b09fa309515b-driver" is forbidden: exceeded quota: spark-demo-quota, requested: count/pods=1, used: count/pods=3, limited: count/pods=3, metadata=ListMeta(_continue=null, remainingItemCount=null, resourceVersion=null, selfLink=null, additionalProperties={}), reason=Forbidden, status=Failure, additionalProperties={}).
at io.fabric8.kubernetes.client.KubernetesClientException.copyAsCause(KubernetesClientException.java:205)
at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.waitForResult(OperationSupport.java:507)
at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.handleResponse(OperationSupport.java:524)
at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.handleCreate(OperationSupport.java:340)
at io.fabric8.kubernetes.client.dsl.internal.BaseOperation.handleCreate(BaseOperation.java:766)
at io.fabric8.kubernetes.client.dsl.internal.BaseOperation.handleCreate(BaseOperation.java:98)
at io.fabric8.kubernetes.client.dsl.internal.CreateOnlyResourceOperation.create(CreateOnlyResourceOperation.java:42)
at io.fabric8.kubernetes.client.dsl.internal.BaseOperation.create(BaseOperation.java:1167)
at io.fabric8.kubernetes.client.dsl.internal.BaseOperation.create(BaseOperation.java:98)
at org.apache.spark.deploy.k8s.submit.Client.run(KubernetesClientApplication.scala:154)
at org.apache.spark.deploy.k8s.submit.KubernetesClientApplication.$anonfun$run$6(KubernetesClientApplication.scala:258)
at org.apache.spark.deploy.k8s.submit.KubernetesClientApplication.$anonfun$run$6$adapted(KubernetesClientApplication.scala:252)
at org.apache.spark.util.SparkErrorUtils.tryWithResource(SparkErrorUtils.scala:51)
at org.apache.spark.util.SparkErrorUtils.tryWithResource$(SparkErrorUtils.scala:48)
at org.apache.spark.util.Utils$.tryWithResource(Utils.scala:97)
at org.apache.spark.deploy.k8s.submit.KubernetesClientApplication.run(KubernetesClientApplication.scala:252)
at org.apache.spark.deploy.k8s.submit.KubernetesClientApplication.start(KubernetesClientApplication.scala:225)
at org.apache.spark.deploy.SparkSubmit.org$apache$spark$deploy$SparkSubmit$$runMain(SparkSubmit.scala:1033)
at org.apache.spark.deploy.SparkSubmit.doRunMain$1(SparkSubmit.scala:203)
at org.apache.spark.deploy.SparkSubmit.submit(SparkSubmit.scala:226)
at org.apache.spark.deploy.SparkSubmit.doSubmit(SparkSubmit.scala:95)
at org.apache.spark.deploy.SparkSubmit$$anon$2.doSubmit(SparkSubmit.scala:1171)
at org.apache.spark.deploy.SparkSubmit$.main(SparkSubmit.scala:1180)
at org.apache.spark.deploy.SparkSubmit.main(SparkSubmit.scala)
Caused by: io.fabric8.kubernetes.client.KubernetesClientException: Failure executing: POST at: https://host.docker.internal:6445/api/v1/namespaces/spark/pods. Message: pods "arrow-spark-5808b09fa309515b-driver" is forbidden: exceeded quota: spark-demo-quota, requested: count/pods=1, used: count/pods=3, limited: count/pods=3. Received status: Status(apiVersion=v1, code=403, details=StatusDetails(causes=[], group=null, kind=pods, name=arrow-spark-5808b09fa309515b-driver, retryAfterSeconds=null, uid=null, additionalProperties={}), kind=Status, message=pods "arrow-spark-5808b09fa309515b-driver" is forbidden: exceeded quota: spark-demo-quota, requested: count/pods=1, used: count/pods=3, limited: count/pods=3, metadata=ListMeta(_continue=null, remainingItemCount=null, resourceVersion=null, selfLink=null, additionalProperties={}), reason=Forbidden, status=Failure, additionalProperties={}).
at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.requestFailure(OperationSupport.java:642)
at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.requestFailure(OperationSupport.java:622)
at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.assertResponseCode(OperationSupport.java:582)
at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.lambda$handleResponse$0(OperationSupport.java:549)
at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:646)
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
at io.fabric8.kubernetes.client.http.StandardHttpClient.lambda$completeOrCancel$10(StandardHttpClient.java:141)
at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
at io.fabric8.kubernetes.client.http.ByteArrayBodyHandler.onBodyDone(ByteArrayBodyHandler.java:51)
at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
at io.fabric8.kubernetes.client.vertx.VertxHttpRequest.lambda$consumeBytes$1(VertxHttpRequest.java:84)
at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:270)
at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:252)
at io.vertx.core.http.impl.HttpEventHandler.handleEnd(HttpEventHandler.java:76)
at io.vertx.core.http.impl.HttpClientResponseImpl.handleEnd(HttpClientResponseImpl.java:250)
at io.vertx.core.http.impl.Http1xClientConnection$StreamImpl.lambda$new$0(Http1xClientConnection.java:448)
at io.vertx.core.streams.impl.InboundBuffer.handleEvent(InboundBuffer.java:279)
at io.vertx.core.streams.impl.InboundBuffer.write(InboundBuffer.java:157)
at io.vertx.core.http.impl.Http1xClientConnection$StreamImpl.handleEnd(Http1xClientConnection.java:758)
at io.vertx.core.impl.ContextImpl.execute(ContextImpl.java:327)
at io.vertx.core.impl.ContextImpl.execute(ContextImpl.java:307)
at io.vertx.core.http.impl.Http1xClientConnection.handleResponseEnd(Http1xClientConnection.java:989)
at io.vertx.core.http.impl.Http1xClientConnection.handleHttpMessage(Http1xClientConnection.java:861)
at io.vertx.core.http.impl.Http1xClientConnection.handleMessage(Http1xClientConnection.java:823)
at io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:159)
at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:153)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:434)
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:361)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:325)
at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:249)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1526)
at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1384)
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1435)
at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:545)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:484)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1429)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:918)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:176)
at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.handle(AbstractNioChannel.java:445)
at io.netty.channel.nio.NioIoHandler$DefaultNioRegistration.handle(NioIoHandler.java:388)
at io.netty.channel.nio.NioIoHandler.processSelectedKey(NioIoHandler.java:596)
at io.netty.channel.nio.NioIoHandler.processSelectedKeysOptimized(NioIoHandler.java:571)
at io.netty.channel.nio.NioIoHandler.processSelectedKeys(NioIoHandler.java:512)
at io.netty.channel.nio.NioIoHandler.run(NioIoHandler.java:484)
at io.netty.channel.SingleThreadIoEventLoop.runIo(SingleThreadIoEventLoop.java:225)
at io.netty.channel.SingleThreadIoEventLoop.run(SingleThreadIoEventLoop.java:196)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:1195)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:840)
File "/opt/airflow/task-sdk/src/airflow/sdk/execution_time/task_runner.py", line 1593 in run

File "/opt/airflow/task-sdk/src/airflow/sdk/execution_time/task_runner.py", line 195 in wrapper

File "/opt/airflow/task-sdk/src/airflow/sdk/execution_time/task_runner.py", line 2178 in _execute_task

File "/opt/airflow/task-sdk/src/airflow/sdk/execution_time/task_runner.py", line 195 in wrapper

File "/opt/airflow/task-sdk/src/airflow/sdk/execution_time/task_runner.py", line 2136 in _run_execute_callable

File "/opt/airflow/task-sdk/src/airflow/sdk/bases/operator.py", line 445 in wrapper

File "/opt/airflow/providers/apache/spark/src/airflow/providers/apache/spark/operators/spark_submit.py", line 292 in execute

File "/opt/airflow/task-sdk/src/airflow/sdk/bases/resumablejobmixin.py", line 200 in execute_resumable

File "/opt/airflow/providers/apache/spark/src/airflow/providers/apache/spark/operators/spark_submit.py", line 309 in submit_job

File "/opt/airflow/providers/apache/spark/src/airflow/providers/apache/spark/hooks/spark_submit.py", line 801 in submit

▶Post Execute

Earlier:

[2026-07-27 15:14:40] ERROR - Task failed with exception
AirflowException: Cannot execute: spark-submit --master k8s://https://host.docker.internal:6445 --conf spark.kubernetes.container.image=apache/spark:3.5.3 --conf spark.kubernetes.authenticate.driver.serviceAccountName=spark --conf spark.driver.extraJavaOptions=-Djavax.net.ssl.trustAll=true --conf spark.executor.extraJavaOptions=-Djavax.net.ssl.trustAll=true --conf spark.kubernetes.submission.waitAppCompletion=false --conf spark.kubernetes.namespace=spark --name arrow-spark --class org.apache.spark.examples.SparkPi --deploy-mode cluster local:///opt/spark/examples/jars/spark-examples_2.12-3.5.3.jar 100. Error code is: 1. Kubernetes spark exit code is: None
Last spark-submit output:
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1435)
at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:545)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:484)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1429)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:918)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:176)
at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.handle(AbstractNioChannel.java:445)
at io.netty.channel.nio.NioIoHandler$DefaultNioRegistration.handle(NioIoHandler.java:388)
at io.netty.channel.nio.NioIoHandler.processSelectedKey(NioIoHandler.java:596)
at io.netty.channel.nio.NioIoHandler.processSelectedKeysOptimized(NioIoHandler.java:571)
at io.netty.channel.nio.NioIoHandler.processSelectedKeys(NioIoHandler.java:512)
at io.netty.channel.nio.NioIoHandler.run(NioIoHandler.java:484)
at io.netty.channel.SingleThreadIoEventLoop.runIo(SingleThreadIoEventLoop.java:225)
at io.netty.channel.SingleThreadIoEventLoop.run(SingleThreadIoEventLoop.java:196)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:1195)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:840)
File "/opt/airflow/task-sdk/src/airflow/sdk/execution_time/task_runner.py", line 1593 in run

File "/opt/airflow/task-sdk/src/airflow/sdk/execution_time/task_runner.py", line 195 in wrapper

File "/opt/airflow/task-sdk/src/airflow/sdk/execution_time/task_runner.py", line 2178 in _execute_task

File "/opt/airflow/task-sdk/src/airflow/sdk/execution_time/task_runner.py", line 195 in wrapper

File "/opt/airflow/task-sdk/src/airflow/sdk/execution_time/task_runner.py", line 2136 in _run_execute_callable

File "/opt/airflow/task-sdk/src/airflow/sdk/bases/operator.py", line 445 in wrapper

File "/opt/airflow/providers/apache/spark/src/airflow/providers/apache/spark/operators/spark_submit.py", line 292 in execute

File "/opt/airflow/task-sdk/src/airflow/sdk/bases/resumablejobmixin.py", line 200 in execute_resumable

File "/opt/airflow/providers/apache/spark/src/airflow/providers/apache/spark/operators/spark_submit.py", line 309 in submit_job

File "/opt/airflow/providers/apache/spark/src/airflow/providers/apache/spark/hooks/spark_submit.py", line 797 in submit

  • Read the Pull Request Guidelines for more information. Note: commit author/co-author name and email in commits become permanently public when merged.
  • For fundamental code changes, an Airflow Improvement Proposal (AIP) is needed.
  • When adding dependency, check compliance with the ASF 3rd Party License Policy.
  • For significant user-facing changes create newsfragment: {pr_number}.significant.rst, in airflow-core/newsfragments. You can add this file in a follow-up commit after the PR is created so you know the PR number.

@shahar1 shahar1 left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The anchor instinct is right — pinning on the JVM's own marker beats guessing at frame counts, and the K8s quota repro in the description is convincing. One thing I'd like to resolve before this lands, though: dropping the rolling fallback entirely means a whole class of spark-submit failures now comes back with no log tail at all.

No uncaught JVM exception → no output at all (spark_submit.py:892)

spark-submit exits non-zero without ever printing Exception in thread "..." in several common cases:

  • A failing PySpark app. SparkSubmit.doSubmit catches SparkUserAppException and calls exitFn(e.exitCode) — the Python traceback goes to stdout, then a bare non-zero exit. No marker.
  • Argument / classpath errorsError: Failed to load class org.example.Main, Error: Missing application resource, Error: Master must either be yarn or start with spark, mesos, k8s.... These go through printErrorAndExit. No marker.

Before this PR those produced a 20-line tail containing the actual error text. After it, _submit_log_tail is "" and the user sees only Error code is: 1 — which is the problem #70178 set out to fix.

The description frames this as a deliberate trade, but I don't think the two behaviours actually conflict — keeping the rolling buffer as the fallback and letting the anchor reset it gets both (suggestion inline on spark_submit.py:892-896):

if not self._exception_anchor_seen and _EXCEPTION_START_RE.search(line):
    # Drop the pre-exception banner noise, keep the whole trace from here on.
    self._exception_anchor_seen = True
    self._last_submit_log_lines = deque(maxlen=500)
self._last_submit_log_lines.append(line)

…with __init__ back to deque(maxlen=20). Full trace when there is an exception, last-20 fallback when there isn't.

Smaller observations

See inline comments on spark_submit.py:61, spark_submit.py:327, and test_spark_submit.py:409.


This review was drafted by an AI-assisted tool and
confirmed by an Airflow maintainer. The findings
below are observations, not blockers; an Airflow
maintainer — a real person — will take the next look at the
PR. If you think a finding is mis-applied, please reply on
the PR and a maintainer will weigh in.

More on how Airflow handles maintainer review:
contributing-docs/05_pull_requests.rst.


Drafted-by: Claude Code (Opus 5); reviewed by @shahar1 before posting

Comment thread providers/apache/spark/src/airflow/providers/apache/spark/hooks/spark_submit.py Outdated
Comment thread providers/apache/spark/src/airflow/providers/apache/spark/hooks/spark_submit.py Outdated
Comment thread providers/apache/spark/tests/unit/apache/spark/hooks/test_spark_submit.py Outdated
Comment thread providers/apache/spark/src/airflow/providers/apache/spark/hooks/spark_submit.py Outdated
@amoghrajesh

Copy link
Copy Markdown
Contributor Author

All handled in 74da146

@amoghrajesh
amoghrajesh merged commit 2c9e099 into apache:main Jul 27, 2026
78 of 79 checks passed
@amoghrajesh
amoghrajesh deleted the better-log-buffering branch July 27, 2026 16:12
@github-project-automation github-project-automation Bot moved this from In progress to Done in Durable / Crash-Safe Execution Jul 27, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

Development

Successfully merging this pull request may close these issues.

3 participants