vitor-mechanic opened a new pull request, #46056: URL: https://github.com/apache/superset/pull/46056
<!--- Please write the PR title following the conventions at https://www.conventionalcommits.org/en/v1.0.0/ Example: fix(dashboard): load charts correctly --> ### SUMMARY `superset.tasks.celery_app` calls `create_app()`, so Celery worker and beat processes apply `LOGGING_CONFIGURATOR` like every other Superset process. Celery then configures logging a second time when the worker starts (`celery.app.log.Logging.setup_logging_subsystem`, Celery 5.6.3). With its default `worker_hijack_root_logger = True` it throws away the root logger's handlers and installs its own text handler, so `LOG_FORMAT`, `LOG_LEVEL` and `ENABLE_TIME_ROTATE` do not survive the worker start-up. Even with `worker_hijack_root_logger = False` in `CELERY_CONFIG` it still - resets the root logger's level to the worker's `--loglevel` (`WARNING` when the option is omitted, as in the Helm chart's default worker command), so `LOG_LEVEL` is silently ignored; - adds a text handler with Celery's task format to the `celery.task` logger and sets its `propagate` to `0`, so records from every logger created with `celery.utils.log.get_task_logger` (`superset/tasks/cache.py`, `superset/tasks/utils.py`) never reach the configured handlers and come out as `[2026-01-01 00:00:00,000: INFO/ForkPoolWorker-1] cache-warmup[id]: ...`; - adds a text handler to billiard's `multiprocessing` logger; - replaces `sys.stdout`/`sys.stderr` with a proxy into the `celery.redirected` logger (`worker_redirect_stdouts`, on by default). A deployment whose configurator emits structured records, for example JSON for a log aggregator, therefore gets worker output in two formats, and the aggregator turns each text line (tracebacks included) into a separate entry. This is the long-standing celery/celery#1867. Celery's documented escape hatch is the `setup_logging` signal: as soon as it has a receiver, Celery skips its logging setup entirely (https://docs.celeryq.dev/en/stable/userguide/signals.html#setup-logging). A configuration setting for the same thing is only now being added to Celery (celery/celery#10424, unreleased). This PR adds `CELERY_SKIP_LOGGING_SETUP` (default `False`) to `superset/config.py`. When it is enabled, the Celery entrypoint connects an empty receiver to `setup_logging` right after `create_app()`, so the logging configured by `LOGGING_CONFIGURATOR` stays the only logging configuration of worker and beat processes. - `superset/utils/logging_configurator.py`: `keep_configured_logging()`, the receiver, and `configure_celery_logging(app_config)`, which connects it when the setting is on and returns whether it did. - `superset/tasks/celery_app.py`: calls `configure_celery_logging(flask_app.config)` right after `create_app()`, i.e. before the `worker`/`beat` command builds its instance and sends the signal. - `superset/config.py`: the setting, next to the `LOG_*` settings it complements. - `docs/admin_docs/configuration/async-queries-celery.mdx`: a "Worker logging" section. - `tests/unit_tests/utils/test_logging_configurator.py`: unit tests. Design notes: - Opt-in, because a connected receiver also makes Celery skip the stdout/stderr redirection (`Logging.setup()` only redirects when nothing handled the signal, and `Worker.on_start()` checks the same value) and leaves the `--loglevel` and `--logfile` options of `celery worker` / `celery beat` without effect. Nothing changes for existing deployments, including `docker/docker-bootstrap.sh` with `WORKER_LOG_FILE` / `BEAT_LOG_FILE`; the config comment, the docstrings and the docs spell out what the setting switches off. - The receiver deliberately ignores the `loglevel` and `logfile` Celery passes to it. Levels and files belong to `LOG_LEVEL`, `ENABLE_TIME_ROTATE` and the related settings, or to a custom `LoggingConfigurator`, as they do for the web server. Celery hands the receiver its command-line default (`WARNING`) when `-l` is omitted, indistinguishable from an explicit `-l WARNING`, so honouring it would keep overriding `LOG_LEVEL` for every deployment that does not pass the option, which is part of the problem being fixed. - Records from Celery task loggers are then formatted by the configured handlers like every other record, so the task name and id that Celery's `TaskFormatter` adds are only present when the configurator's formatter provides them (for example by using `celery.app.log.TaskFormatter`). - The receiver and the helper that reads the setting live in `superset/utils/logging_configurator.py`, next to the configurator whose work they protect, so they can be unit-tested against Celery's real `Logging.setup()` with a throwaway `Celery()` instance, without importing `superset.tasks.celery_app` (whose module-level `create_app()` would build a second app in the test process). - The receiver is empty and idempotent on purpose: Celery sends the signal again in every prefork child when `--logfile` contains `%i`, and it logs and swallows exceptions raised by receivers while still treating logging as handled. Connecting the same function twice is a no-op in Celery. - With the setting on, Celery's `after_setup_logger` / `after_setup_task_logger` signals are not sent (nothing in Superset uses them), and billiard's `multiprocessing` logger gets no handler, so its rare process-pool messages of level WARNING and above fall through to Python's last-resort stderr handler (prefork children are forked and inherit this state). The setting takes effect wherever Celery runs its logging setup (`worker`, `beat`, prefork children, `celery events` snapshots); `celery inspect ping`, the Helm liveness probe, does not run it, so nothing changes there. - The name mirrors the setting Celery is adding (`worker_skip_logging_setup`); once that ships, the receiver can be replaced by it in `CELERY_CONFIG`. State of the worker process after Celery's `Logging.setup()` when `LOGGING_CONFIGURATOR` configured the root logger (one handler, level INFO) and the worker was started without `-l`: | | setting off, `worker_hijack_root_logger = True` (default) | setting off, `worker_hijack_root_logger = False` | setting on | | ----------------------------- | --------------------------------------------------------- | ----------------------------------------------------- | ----------------------- | | root logger handlers | replaced by Celery's text handler | unchanged | unchanged | | root logger level | WARNING (from the `-l` default) | WARNING (from the `-l` default) | INFO (unchanged) | | `celery.task` logger | Celery's text handler, level WARNING, no propagation | Celery's text handler, level WARNING, no propagation | unchanged, propagates | | `multiprocessing` logger | Celery's text handler | Celery's text handler | unchanged | | `sys.stdout` / `sys.stderr` | proxy into `celery.redirected` | proxy into `celery.redirected` | unchanged | | `--loglevel` / `--logfile` | applied | applied | ignored | ### BEFORE/AFTER SCREENSHOTS OR ANIMATED GIF Worker output instead of screenshots. `superset_config.py` sets `LOG_FORMAT = "CONFIGURED %(levelname)s %(name)s: %(message)s"` and keeps the default `CELERY_CONFIG` (Celery's default `worker_hijack_root_logger = True`); the worker runs as `celery --app=superset.tasks.celery_app:app worker --pool=solo -l INFO` and executes one task that logs through `get_task_logger(__name__)` (as `superset/tasks/cache.py` does) and calls `print()`. Before (setting off): after the start-up banner nothing uses `LOG_FORMAT`; the task logger record is in Celery's task format and the `print()` is wrapped into a WARNING record of `celery.redirected`. ``` [2026-11-05 20:32:40,732: INFO/MainProcess] Connected to sqla+sqlite:///.../broker.db [2026-11-05 20:32:40,742: INFO/MainProcess] celery@host ready. [2026-11-05 20:33:21,136: INFO/MainProcess] Task smoke_tasks.hello[1588f4da-...] received [2026-11-05 20:33:21,136: INFO/MainProcess] smoke_tasks.hello[1588f4da-...]: task logger line [2026-11-05 20:33:21,137: WARNING/MainProcess] print line [2026-11-05 20:33:21,140: INFO/MainProcess] Task smoke_tasks.hello[1588f4da-...] succeeded in 0.0038s: 'ok' ``` After (setting on): every record goes through the configured handler and format, the `get_task_logger` record included; the `print()` goes to the real stdout. ``` CONFIGURED INFO celery.worker.consumer.connection: Connected to sqla+sqlite:///.../broker.db CONFIGURED INFO celery.apps.worker: celery@host ready. CONFIGURED INFO celery.worker.strategy: Task smoke_tasks.hello[2520e0d7-...] received CONFIGURED INFO smoke_tasks: task logger line print line CONFIGURED INFO celery.app.trace: Task smoke_tasks.hello[2520e0d7-...] succeeded in 0.0034s: 'ok' ``` ### TESTING INSTRUCTIONS Automated: `pytest tests/unit_tests/utils/test_logging_configurator.py`. The tests run Celery's real `Logging.setup()` against a throwaway Celery app with `worker_hijack_root_logger = False` and check that, without the setting, Celery still adds a handler to `celery.task` and overrides the root level, while with the setting enabled every logger, `sys.stdout` and `sys.stderr` are left untouched (also on the repeated setup a prefork child runs), no file is opened for `--logfile`, and the receiver reports back to Celery without raising. Manually, with a `superset_config.py` containing ```python LOG_FORMAT = "CONFIGURED %(levelname)s %(name)s: %(message)s" CELERY_SKIP_LOGGING_SETUP = True # run once with False for comparison ``` and the default `CELERY_CONFIG` (plus a broker): 1. `celery --app=superset.tasks.celery_app:app worker -l INFO`. Setting off (current behaviour): everything Celery and the tasks log after start-up comes out in Celery's `[date: LEVEL/MainProcess] ...` format, `LOG_FORMAT` is not used. Setting on: every record uses the `CONFIGURED ...` format. The start-up banner is printed, not logged, so it looks the same either way. 2. `celery --app=superset.tasks.celery_app:app worker -l DEBUG --logfile=/tmp/worker.log`. Setting off: Celery writes its records to `/tmp/worker.log` and `-l DEBUG` turns on debug output from every library. Setting on: the file is not created, records stay on stderr in the `CONFIGURED ...` format and the root level stays at `LOG_LEVEL`. 3. Trigger the cache warm-up task, which logs through a Celery task logger, for example from `superset shell`: `from superset.tasks.cache import cache_warmup; cache_warmup.delay("top_n_dashboards", top_n=5, since="7 days ago")`. Setting off: `Loading strategy` and `Loading TopNDashboardsStrategy` come out in Celery's `[date: INFO/MainProcess] cache-warmup[id]: ...` task format. Setting on: they appear in the `CONFIGURED ...` format like every other record. (The first two lines are enough for the check; the rest of the task needs `SUPERSET_CACHE_WARMUP_USER`, see the caching docs.) 4. `celery --app=superset.tasks.celery_app:app beat -l DEBUG --logfile=/tmp/beat.log` behaves the same way for its options. ### ADDITIONAL INFORMATION <!--- Check any relevant boxes with "x" --> <!--- HINT: Include "Fixes #nnn" if you are fixing an existing issue --> - [ ] Has associated issue: - [ ] Required feature flags: - [ ] Changes UI - [ ] Includes DB Migration (follow approval process in [SIP-59](https://github.com/apache/superset/issues/13351)) - [ ] Migration is atomic, supports rollback & is backwards-compatible - [ ] Confirm DB migration upgrade and downgrade tested - [ ] Runtime estimates and downtime expectations provided - [x] Introduces new feature or API - [ ] Removes existing feature or API -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected] --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
