chore(amber): reduce engine log verbosity and pin the CI log-level backstop#6797
Conversation
…ine logs
Amber engine loggers are named "<actorId>] [<ClassName>" by AmberLogging so
the pattern renders both the actor id and the class. A side effect is that
these logger names start with the actor id, not "org.apache", so the
`org.apache=WARN` rule in logback.xml never matches them and every one of
these statements emits at the root INFO level. In loop/integration tests
workers are recreated each iteration, so per-ECM, per-worker, per-region
lines fire dozens of times and flood the CI console.
Demote the chatty per-message / per-worker-lifecycle / per-region logs to
DEBUG so they no longer print at the default INFO level (CI, local, and
prod), and demote three misleading WARNs that fire on normal operation:
* receive/process/send ECM (DataProcessor.scala, main_loop.py)
* register->Actor / "unknown identifier" / "might have crashed"
(PekkoActorRefMappingService.scala)
* replay-log conf, DP thread start/exit, "Starting the worker",
"Region N successfully terminated", operator completion
* ClientActor "cannot handle" fallthrough
Genuine fault paths are untouched (DP-thread ERROR, "Failed to fetch
actorRef" WARN, "Error when terminating region" WARN). As a CI backstop,
pin TEXERA_SERVICE_LOG_LEVEL and UDF_PYTHON_LOG_STREAMHANDLER_LEVEL to WARN
on the amber unit and integration test steps.
There was a problem hiding this comment.
Pull request overview
Note
Copilot couldn't run its full agentic review because it didn't start before the timeout. Make sure your repository has a runner available, or add a copilot-code-review.yml file specifying one with the runs-on attribute. See the docs for more details.
Reduces CI console log volume by demoting high-frequency Amber engine logs (Scala + Python) from INFO/WARN to DEBUG and pinning CI log levels to WARN as a backstop.
Changes:
- Demoted hot-path per-worker/per-message engine logs from INFO/WARN to DEBUG across Amber Scala and Python runtime paths.
- Demoted selected WARN logs that occur during normal teardown/races to DEBUG to avoid noisy CI output.
- Added CI workflow environment overrides to force JVM/Python worker logs to WARN in unit/integration steps.
Reviewed changes
Copilot reviewed 9 out of 9 changed files in this pull request and generated 7 comments.
Show a summary per file
| File | Description |
|---|---|
| amber/src/main/scala/org/apache/texera/amber/engine/common/client/ClientActor.scala | Demotes “cannot handle” log from WARN to DEBUG. |
| amber/src/main/scala/org/apache/texera/amber/engine/architecture/worker/promisehandlers/StartHandler.scala | Demotes worker start log to DEBUG. |
| amber/src/main/scala/org/apache/texera/amber/engine/architecture/worker/DataProcessor.scala | Demotes ECM receive/process/send and completion summary logs to DEBUG. |
| amber/src/main/scala/org/apache/texera/amber/engine/architecture/worker/DPThread.scala | Demotes DP thread lifecycle logs to DEBUG. |
| amber/src/main/scala/org/apache/texera/amber/engine/architecture/scheduling/RegionExecutionManager.scala | Demotes “successfully terminated” log to DEBUG. |
| amber/src/main/scala/org/apache/texera/amber/engine/architecture/common/WorkflowActor.scala | Demotes replay-log config log to DEBUG. |
| amber/src/main/scala/org/apache/texera/amber/engine/architecture/common/PekkoActorRefMappingService.scala | Demotes registration / normal teardown race logs to DEBUG. |
| amber/src/main/python/core/runnables/main_loop.py | Demotes ECM receive/process/send logs to DEBUG. |
| .github/workflows/build.yml | Pins CI log level env vars to WARN for unit/integration steps. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
Automated Reviewer SuggestionsBased on the
|
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #6797 +/- ##
============================================
- Coverage 77.97% 77.42% -0.56%
+ Complexity 3661 3520 -141
============================================
Files 1161 1161
Lines 46059 46046 -13
Branches 5105 5095 -10
============================================
- Hits 35915 35649 -266
- Misses 8521 8827 +306
+ Partials 1623 1570 -53
*This pull request uses carry forward flags. Click here to find out more. ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
|
| config | throughput | MB/s | latency | max Δ latest / 7d | |
|---|---|---|---|---|---|
| 🔴 | bs=10 sw=10 sl=64 | 385 | 0.235 | 26,090/30,979/30,979 us | 🟢 -45.9% / 🔴 +103.6% |
| 🔴 | bs=100 sw=10 sl=64 | 781 | 0.477 | 122,780/169,146/169,146 us | 🔴 +18.2% / 🔴 +55.0% |
| ⚪ | bs=1000 sw=10 sl=64 | 928 | 0.566 | 1,079,324/1,130,830/1,130,830 us | ⚪ within ±5% / 🔴 +8.1% |
Baseline details
Latest main 7e4a9b4 from same runner
| config | metric | PR | latest main | 7d avg | Δ latest | Δ 7d |
|---|---|---|---|---|---|---|
| bs=10 sw=10 sl=64 | throughput | 385 tuples/sec | 345 tuples/sec | 754.55 tuples/sec | +11.6% | -49.0% |
| bs=10 sw=10 sl=64 | MB/s | 0.235 MB/s | 0.211 MB/s | 0.461 MB/s | +11.4% | -49.0% |
| bs=10 sw=10 sl=64 | p50 | 26,090 us | 24,614 us | 12,816 us | +6.0% | +103.6% |
| bs=10 sw=10 sl=64 | p95 | 30,979 us | 57,229 us | 16,594 us | -45.9% | +86.7% |
| bs=10 sw=10 sl=64 | p99 | 30,979 us | 57,229 us | 19,806 us | -45.9% | +56.4% |
| bs=100 sw=10 sl=64 | throughput | 781 tuples/sec | 840 tuples/sec | 969.38 tuples/sec | -7.0% | -19.4% |
| bs=100 sw=10 sl=64 | MB/s | 0.477 MB/s | 0.512 MB/s | 0.592 MB/s | -6.8% | -19.4% |
| bs=100 sw=10 sl=64 | p50 | 122,780 us | 116,173 us | 103,584 us | +5.7% | +18.5% |
| bs=100 sw=10 sl=64 | p95 | 169,146 us | 143,150 us | 109,097 us | +18.2% | +55.0% |
| bs=100 sw=10 sl=64 | p99 | 169,146 us | 143,150 us | 117,304 us | +18.2% | +44.2% |
| bs=1000 sw=10 sl=64 | throughput | 928 tuples/sec | 917 tuples/sec | 1,004 tuples/sec | +1.2% | -7.5% |
| bs=1000 sw=10 sl=64 | MB/s | 0.566 MB/s | 0.56 MB/s | 0.613 MB/s | +1.1% | -7.6% |
| bs=1000 sw=10 sl=64 | p50 | 1,079,324 us | 1,090,493 us | 1,002,357 us | -1.0% | +7.7% |
| bs=1000 sw=10 sl=64 | p95 | 1,130,830 us | 1,141,667 us | 1,046,463 us | -0.9% | +8.1% |
| bs=1000 sw=10 sl=64 | p99 | 1,130,830 us | 1,141,667 us | 1,073,661 us | -0.9% | +5.3% |
Raw CSV
config_idx,batch_size,schema_width,string_len,num_batches,total_ms,total_tuples,total_bytes,tuples_per_sec,mb_per_sec,lat_p50_us,lat_p95_us,lat_p99_us
0,10,10,64,20,520.00,200,128000,385,0.235,26090.08,30978.84,30978.84
1,100,10,64,20,2560.37,2000,1280000,781,0.477,122779.93,169145.69,169145.69
2,1000,10,64,20,21556.77,20000,12800000,928,0.566,1079323.64,1130829.83,1130829.83- main_loop.py: switch the three per-ECM debug logs from eager f-strings
to loguru's lazy `{}`-placeholder form. loguru's _log short-circuits on
core.min_level before formatting, so the ChannelIdentity/command string
building is now skipped entirely when DEBUG is disabled (the default).
- PekkoActorRefMappingService: reword the demoted teardown log to a neutral
"removed actor ref for <id>" — removeActorRef also runs on normal graceful
region teardown, so the old "might have crashed" wording was misleading.
The Scala interpolated debug logs are left as-is: com.typesafe.scala-logging
3.9.6 Logger methods are macros that guard the message with isDebugEnabled,
so `s"..."` is not built when the level is disabled.
|
Let me review this. I may need some time |
loguru has no WARN level (only WARNING), so UDF_PYTHON_LOG_STREAMHANDLER_LEVEL=WARN made every spawned Python UDF worker raise `ValueError: Level 'WARN' does not exist` at startup, before it connected back to the JVM. PythonProxyClient then blocked forever on the port promise (Await.result, no timeout), so the amber-integration job hung until GitHub's 6h cap. logback (TEXERA_SERVICE_LOG_LEVEL) keeps WARN, which is its correct spelling. Also add a 40-min timeout to the amber-integration job so a worker-startup failure fails fast instead of burning a 6h runner.
aglinxinyuan
changed the title
|
Pushed 35203dc to fix a self-inflicted hang in this PR's own CI backstop. The Fix:
|
- build.yml: the WARN/WARNING pins on the two amber test steps now flip to DEBUG when the run has "Enable debug logging" set (runner.debug == '1'), so the demoted engine logs come back on demand without editing the workflow. - build.yml: lower the amber-integration job timeout from 40 to 25 minutes; the last 38 green runs on main took 9.0-16.4 min (avg 12.1), so 25 keeps cold-cache headroom while still failing ~14x faster than the 6h cap. - PekkoActorRefMappingService: reword the teardown log to "actor <id> is not reachable anymore. old ref = <ref>" per review - the mapping service cannot tell a graceful stop from a crash, so the message now infers neither.
The CI backstop sets TEXERA_SERVICE_LOG_LEVEL=WARN, which cluster.conf forwards into pekko.loglevel. Pekko only accepts OFF/ERROR/WARNING/INFO/ DEBUG (Logging.levelFor), so every ActorSystem creation printed "unknown pekko.loglevel WARN" with a LoggerException stack trace and fell back to ERROR - one per spec in the amber unit and integration jobs, the very noise this PR is meant to remove. The env knob cannot simply switch to WARNING: the same variable drives the logback root level in logback.xml, and logback silently falls back to DEBUG on names it does not know - flooding instead of quieting. Normalize at the single choke point instead: PekkoConfig.pekkoConfig (which every ActorSystem, prod and test, receives via AmberRuntime.pekkoConfig) now rewrites pekko.loglevel through normalizePekkoLogLevel (WARN -> WARNING, TRACE/ALL -> DEBUG), so one env knob drives both systems in either spelling. Covered by a new invariant test - the resolved loglevel must be pekko-valid whatever the env holds, red on WARN before this fix - plus unit tests for the mapping.
|
Pushed b67bf3a to fix a noise regression the WARN backstop itself introduced — the CI logs were full of this on every Root cause: Why not just set Fix: normalize at the single choke point. Test-first: added an invariant test to |
Review follow-up on the amber-only scoping: the WARN backstop wired to "Enable debug logging" now covers every CI step that runs or boots a component with a log-level configuration, keeping one consistent level across the board: - platform test step: all six platform services read TEXERA_SERVICE_LOG_LEVEL into their Dropwizard logging config (logback vocabulary, WARN); - platform-integration + amber-integration boot smoke steps: same env for the packaged services; safe because smoke-boot's verdict is LISTEN-based, never log-scraping (apache#6332); - pyamber unit + Python integration pytest steps: LOGURU_LEVEL=WARNING (loguru vocabulary) for loguru's default stderr sink, which prints straight into the CI log because pytest runs with -s; test-local sinks with an explicit level are unaffected; - agent-service unit tests: TEXERA_SERVICE_LOG_LEVEL=WARN - env.ts validates ["ERROR","WARN","INFO","DEBUG"] before mapping to pino's lowercase levels, so the logback spelling is correct there too. Components with no log-level configuration (frontend, infra, pyright-language-service) are left alone.
|
Extended the backstop beyond amber in d7982b0 — every CI step that runs or boots a component with a log-level knob now carries the same wiring (
Left alone per the "no log config → skip" rule: frontend, infra, pyright-language-service (none of them read a log-level variable). pekko is already covered everywhere via |
Yicong-Huang
left a comment
Yicong-Huang
left a comment
There was a problem hiding this comment.
🟡 0 must-fix · 2 advisory · 0 polish — solid, well-verified noise reduction; two small accuracy nits.
Correctness (1)
PekkoConfigSpec.scala:80— the "whatever spelling" invariant test is env-sensitive: an unknown local value likeFATALpasses throughnormalizePekkoLogLeveland fails the assertion (advisory, see inline)
Conventions (1)
- Description: still says
timeout-minutes: 40(the diff sets 25) and describes the CI backstop as amber-only, while the head pins platform / pyamber / agent-service / smoke-boot steps too — refresh to match d7982b0 (advisory)
Verification trace
Traced the WARN/WARNING split end to end: every ActorSystem (prod, test, bench) receives PekkoConfig.pekkoConfig via AmberRuntime — the master/worker parseString overrides never touch pekko.loglevel — so the normalization covers all creations, and cluster.conf has no other reader. Each CI-pinned spelling was checked against its consumer's vocabulary: Dropwizard/logback accepts WARN, agent-service env.ts's enum includes WARN, loguru and pekko get WARNING. Also confirmed the fault-path logs (DP-thread crash ERROR, actorRef-fetch failure WARN, region-termination failure WARN) are untouched, and no test asserts on a demoted message (ReplayLogGeneratorSpec's "cannot handle" matches an unrelated RuntimeException).
Review follow-up: the invariant test asserted the RESOLVED pekko.loglevel is in pekko's accepted set, which fails for any env spelling outside the translated vocabulary (e.g. TEXERA_SERVICE_LOG_LEVEL=FATAL passes through normalizePekkoLogLevel unchanged) - an env-sensitive assertion in a file whose convention is to guard exactly that. Replace it with: - the pure-function invariant: every spelling in the combined logback + pekko vocabulary (OFF/ERROR/WARN/WARNING/INFO/DEBUG/ TRACE/ALL) normalizes into pekko's accepted set; - an env-insensitive plumbing check: whatever the env supplied, the exposed pekko.loglevel equals its normalized form (identity for unknown spellings, so it can never false-positive) - exercised for real by CI, which sets WARN. Verified locally: 8/8 with the env unset, with WARN (the CI condition), and with FATAL (the reviewer's counterexample, which failed before this change).
What changes were proposed in this PR?
Root cause.
AmberLoggingnames each logger"<actorId>] [<ClassName>"so the logback pattern[%logger]renders both the actor id and the class. The side effect is that these logger names start with the actor id (WF6-…,COORDINATOR), notorg.apache…, so the<logger name="org.apache" level="WARN"/>rule inamber/src/main/resources/logback.xmlnever matches the engine classes. They all fall through to the root logger and emit atINFO. In loop/integration tests, workers are recreated every iteration, so per-ECM / per-worker / per-region lines fire dozens of times and flood the CI console.This PR demotes those statements to
DEBUGso they no longer print at the defaultINFOlevel (CI, local, and prod), and demotes threeWARNs that fire on normal operation:receive/process/send ECM(2–3× per control message, fullChannelIdentitydump)DataProcessor.scala,main_loop.pyregister <id> -> Actor[…]PekkoActorRefMappingService.scala…is not reachable anymore, it might have crashed— fires on graceful teardownPekkoActorRefMappingService.scalaunknown identifier— registration racePekkoActorRefMappingService.scalaworker replay log writing conf,DP thread started/exits,Starting the worker.WorkflowActor,DPThread,StartHandlerRegion N successfully terminated.RegionExecutionManager.scala…completed, # of input ports…DataProcessor.scalaclient actor cannot handle …—//skipfallthroughClientActor.scalaGenuine fault paths are untouched:
DP Thread exists unexpectedly(ERROR),Failed to fetch actorRef(WARN), andError when terminating region(WARN, the failure branch — distinct from the demotedsuccessfully terminatedsuccess branch).As a CI backstop, the amber unit and integration test steps in
build.ymlpin the log level so any remainingINFOchatter is suppressed there even before the source demotions take effect. The two logging stacks spell the level differently, which is a trap worth calling out: logback takesTEXERA_SERVICE_LOG_LEVEL=WARN, but the spawned Python UDF worker uses loguru, whose only warning level isWARNING. Feeding loguruWARNraisesValueError: Level 'WARN' does not existat worker startup — before the worker hands its Flight port back to the JVM — and the JVM then blocks on the proxy handshake with no internal timeout, hangingamber-integrationuntil GitHub's 6 h runner cap. So the Python var is pinned toUDF_PYTHON_LOG_STREAMHANDLER_LEVEL=WARNING, and, symmetrically, logback keepsWARN(it falls back toDEBUGon an unknown level likeWARNING, which would flood logs instead).amber-integrationadditionally getstimeout-minutes: 40so any future worker-startup deadlock fails fast instead of burning a full runner.Net effect: the bulk of the per-iteration output from loop/integration specs disappears from the default-level log, while
DEBUGkeeps it available on demand.Any related issues, documentation, discussions?
Closes #6796
How was this PR tested?
The source demotions are a log-level-only change — no behavior changes — so they rely on the existing test suites run in CI. Verified additionally by inspection and by the CI backstop's own behavior:
ReplayLogGeneratorSpecmatches"cannot handle", but against an unrelatedRuntimeExceptionfromReplayLogGenerator, not theClientActorlog.)WARN/WARNINGenv does not break config specs.UdfConfigSpec's andPekkoConfigSpec's default-value assertions are guarded (ifUnset/!sys.env.contains(...)), andpekko.stdout-loglevelis hardcodedINFOincluster.conf(onlypekko.loglevelis env-driven), so its unguarded assertion still passes.logger.add(sys.stderr, level="WARN")raisesValueError: Level 'WARN' does not existwhilelevel="WARNING"succeeds (loguru's levels areTRACE/DEBUG/INFO/SUCCESS/WARNING/ERROR/CRITICAL); logback acceptsWARN. WithWARNING,amber-integrationruns green again — the ubuntu leg finishes the integration step in ~8.5 min, versus the earlierWARNruns that sat in that step ~3 h until cancelled.scalafixAll --checkis unaffected); the longest changed Scala line is 96 columns (< the 100maxColumn), soscalafmtCheckAllstays green.A follow-up sweep for other hot-path
INFO/WARNlogs (e.g.AsyncRPCClientnull control-reply, the range-shuffle partitioner,Tuplecast warnings) is captured in #6796 rather than expanded here.Was this PR authored or co-authored using generative AI tooling?
Generated-by: Claude Code (Opus 4.8 [1M context])