Drive the task handler log level from the airflow.task logger - #829
Drive the task handler log level from the airflow.task logger#829Churi12 wants to merge 1 commit into
Conversation
|
|
|
Heads up that I rewrote this PR: it started out only reworking a TODO comment, and it now implements the feature. The description above is current, this is just the one thing that is easy to get wrong. The CRD loggers field can already override the level of the airflow.task logger, and I confirmed that works by running the generated config through logging.config.dictConfig. But that is the logger level, not the handler level, so it turns DEBUG on or off for every destination at once. Reading #646 made the difference concrete: the task handler is the one that feeds the UI, so only a handler level lets someone emit DEBUG to the log files and to Vector while showing INFO in the UI. That is what #650 asks for and what this now does. Kept in draft until stackabletech/operator-rs#1255 lands, since the CRD field comes from there. |
Churi12
changed the title
e2ca9c9 to
5c62190
Compare
Churi12
changed the title
|
Thanks for raising this PR! I'm not very knowledgeable about Airflow logging, so I'm really helpful reviewing the actual implementation. There are ways to achieve that (using Rust generics), but they are rather complicated and ugly. From the top of my head there could be two different ways of doing this:
What do you think about the two options? For transparency: At Stackable we have a decision process for all CRD changes before they go in (it's our public API after all). |
|
Thanks, that is really useful, and I think option 2 is clearly the better idea. I will rework this PR to that. Agreed on not adding a field that only Airflow uses. I went to the shared struct because loggers felt like it was for logger levels and this is a handler level, but you are right that the magic key buys more than the purity costs: no CRD change, no operator-rs dependency, and it can go in on its own rather than waiting on a release. And since airflow.task is what you expected from reading the docs, it is probably what other people would guess too. One thing I would push back on is option 1, tying the task level to the file level. The use case in #646 is DEBUG in the log files and in Vector while the UI stays at INFO, and coupling the two makes exactly that impossible. It would also change behaviour quietly: anyone who has file set to DEBUG today would suddenly start seeing DEBUG in the UI, which is the thing the current forced INFO is there to prevent. On the docs confusing you, that is on me for not saying so earlier: that paragraph is stale. The task handler level genuinely could not be specified when it was written, but the airflow.task loggers entry has worked for a while, and the sentence still says it cannot. This PR already rewrites that section, and with option 2 it gets simpler to explain, because there is only one knob instead of a logger level that sort of does the job. Worth flagging one behaviour change that comes with option 2, since it is a change and not just an addition. Today an airflow.task entry sets the logger level, so setting it to ERROR also stops the files and Vector from getting anything below ERROR. Under option 2 it would set the handler level and leave the logger at INFO, so the files keep getting INFO and only the UI goes quiet. I think that is the behaviour people actually want, and it is what makes the DEBUG to files, INFO to UI case work, but anyone raising the level today would notice. The docs example uses DEBUG rather than a raise, so I would guess the blast radius is small. The mechanics are close to what is here already. The level comes from the loggers entry instead of a new field, the handler gets it, and the logger is set to the lower of INFO and that level, because a logger drops records before any handler can filter them, so a DEBUG handler behind an INFO logger would do nothing, while a raised level must not pull the logger up and starve the file and console handlers. I also need to keep airflow.task out of the generic loggers loop so it does not overwrite that. Understood on the CRD process, and good to know regardless. Option 2 sidesteps it entirely, so I will close the operator-rs PR. |
5c62190 to
2236813
Compare
Churi12
changed the title
|
Reworked to option 2, this is ready for another look. The airflow.task level now sets the task handler level rather than the logger level. No CRD change, no operator-rs dependency, and stackabletech/operator-rs#1255 is closed. The diff is down to three files. The logger is set to the lower of INFO and the configured level, because a logger drops records before any handler sees them. So DEBUG opens the logger up too, and ERROR leaves the logger at INFO and lets the handler do the filtering, which is what keeps the file and console handlers fed. Verified through dictConfig for both templates: with ERROR the handler is at 40, the logger stays at 20, and only ERROR reaches the task handler. Two things I would flag for the review rather than bury in the description. Raising the level is now a behaviour change, since today it also suppresses records for the files and Vector and after this it only quietens the UI. And the airflow.task entry had to be excluded from the generic loggers block, or that block would assign the level to the logger directly and undo the clamping, so there is a test per template for that. Also fixed the docs NOTE you quoted. It was simply out of date. |
Closes stackabletech#650. The task handler is what feeds the log view in the Airflow web UI, and its level was pinned to INFO. Setting the airflow.task logger level was the only knob available, but a logger threshold applies to every destination at once, so the UI could not be quietened on its own. Take the level configured for the airflow.task logger and apply it to the task handler instead. No CRD change is needed, and the key is the one the docs already point people at. The two levels are not symmetric, which is the part worth knowing about. At or above INFO only the handler moves, so the UI goes quiet while the console and file handlers keep receiving the records it drops. Below INFO the logger has to be opened up as well, because a logger discards records before any of its handlers can filter them, and that means the extra records reach every destination rather than only the UI. Lowering the UI alone is therefore not possible, whichever way this is implemented. This does change behaviour for anyone raising the level today: it now quietens only the UI rather than every destination. The airflow.task entry is also excluded from the generic loggers block, so it cannot overwrite the level that block would otherwise assign directly. Both templates are covered, the stdlib one used by 2.x and 3.0.x and the structlog one used by 3.1 and later, with a table per template that lists the handler and logger level for every configurable level side by side.
2236813 to
bb8ee1b
Compare
3 participants
Description
Closes #650.
The task handler is what feeds the log view in the Airflow web UI, and its level was pinned to INFO, so there was no way to quieten the UI without also quietening the log files and Vector.
This takes the level configured for the airflow.task logger and applies it to the task handler instead. No CRD change is needed, and the key is the one the logging docs already point people at, which is where this landed after the discussion below.
The logger itself is set to the lower of INFO and that level, which makes the two directions behave differently. At or above INFO only the handler moves, so the UI goes quiet while the console and file handlers keep receiving the records it drops. Below INFO the logger has to be opened up as well, because a logger discards records before any of its handlers can filter them, so the extra records reach every destination rather than only the UI.
Both templates are covered: the stdlib one used by 2.x and 3.0.x, and the structlog one used by 3.1 and later.
Release note
The log level configured for the airflow.task logger now sets the level of the task handler, which is what the Airflow web UI displays, rather than the level of the logger itself.
Raising it above INFO now quietens only the UI. Previously it also stopped the log files and the Vector aggregator from receiving records below that level, so anyone who raised airflow.task to reduce log volume everywhere will see the other destinations keep receiving what the UI no longer shows.
Lowering it below INFO still affects every destination, because a logger discards records before any of its handlers can filter them, so the UI cannot be given a lower level on its own.
The default is unchanged at INFO, matching Airflow.
Notes for the reviewer
A correction from the first round, since it changed what the docs claim. I had documented file at DEBUG with airflow.task at INFO as writing DEBUG to the log files and Vector while the UI stayed at INFO. That does not work: the logger is clamped to min(INFO, requested), so the DEBUG records are discarded at the logger before the file handler sees them. The asymmetry is real but it only runs one way, and the docs, the changelog and the tests now say so. Thanks to @adwk67 for catching it.
Lowering the UI on its own is not possible in this design, and not because of how it is implemented here: a handler cannot filter what its logger already threw away. The only way to decouple the two directions would be a separate task appender, which is the CRD change that was declined earlier in this PR.
The airflow.task entry is also excluded from the generic loggers block. Otherwise that block would assign the requested level straight to the logger and undo the clamping. There is a test per template for that specifically.
On the tests, each template has a table, TASK_LEVELS, listing the requested level next to the resulting task handler level and airflow.task logger level for all seven configurable levels, so the asymmetry is visible in one place rather than spread across single-level cases. Two further tests pin each direction on its own. I checked the table is not vacuous by removing the clamp: five tests fail, both tables among them. Four older single-level tests became redundant once the table covered them and were removed. 46 tests pass.
Beyond the rendered-template assertions I ran the generated config through logging.config.dictConfig, against a stub of the Airflow handler shape, because a template assertion does not prove the level takes effect. Both templates give identical results:
The WARN case is the one the docs example now uses, since it is the direction that actually works.
One thing worth flagging that this PR does not change. At runtime Airflow calls set_context on the task logger when a task starts, and FileTaskHandler returns None there unless maintain_propagate is set, so logging_mixin.set_context sets propagate to False on airflow.task. From that point task records do not reach the root console and file handlers at all. That is existing Airflow behaviour, but it does mean the file and Vector levels have limited say over task logs regardless of the logger threshold, so I kept the docs to claims I could verify.
The docs NOTE is also updated. It previously said the task handler log level cannot be specified, which had been stale for a while.
No CRD change, so extra/crds.yaml is untouched and there is no operator-rs dependency. stackabletech/operator-rs#1255 is closed.
Rebased onto main, the only conflict was the changelog.
Definition of Done Checklist
Author
Reviewer