Propagate logs to stdout when in k8s executor pod #28440

dstandish · 2022-12-18T08:52:26Z

Currently live logging (viewing from webserver while task running) for k8s executor pods doesn't work.

The cause has a few components from things we do during task run:

we remove the console handler from root logger. So any logs that make it to root don't get emitted.
even if we keep console handler at root, it is designed to respect stdout redirection
even if we make it not respect stdout redirection in this context, task logger does not propagate, so anything going through task logger does not make it to root logger

The reason for (3) is we copy the task handler to root logger instead of move, which requires that we disable propagation at the task logger.

This PR fixes all of these things and, ultimately, simplifies the setup.

instead of keeping task handler in two places during execution -- airflow.task and root -- we keep it just in root. This means we can let airflow.task logger propagate. this we now do always.
when running k8s executor pod, we keep the console handler at root and set it to not respect redirection, so that even though stdout gets redirected to task logger, when it makes it to root logger, it is still emitted to stdout.

airflow/cli/commands/task_command.py

malthe · 2022-12-29T12:02:08Z

@dstandish I think an abstraction point in the executor framework would be better rather than the if-statements in this changeset. That is, we should make the executor pluggable in terms of supporting this logging capability.

In terms of actual implementation, rather than adjusting log handlers at runtime, perhaps an internal pub/sub mechanism could be devised.

dstandish · 2022-12-29T16:20:07Z

@dstandish I think an abstraction point in the executor framework would be better rather than the if-statements in this changeset. That is, we should make the executor pluggable in terms of supporting this logging capability.

In terms of actual implementation, rather than adjusting log handlers at runtime, perhaps an internal pub/sub mechanism could be devised.

We already adjust handlers. This fixes a deficiency

This does not add meaningful backcompat surface area, is basically a small adjustment to what we already do. Your suggestion may be a good one, but that's not what this PR does, and this PR does not in any way make your approach more difficult / less likely / less practical to implement. Meanwhile, logging in k8s executor is broken and this fixes it without, as far as I can tell, much in the way of downside.

dstandish · 2022-12-29T16:54:09Z

airflow/cli/commands/task_command.py

-        orig_level = root_logger.level
-        root_logger.setLevel(task_logger.level)
-        orig_handlers = root_logger.handlers.copy()
-        root_logger.handlers[:] = task_logger.handlers


@malthe observe, we already copy (temporarily) to root logger the thandlers from airflow.task

This causes problems because we have to have complicated propagation rules at the airflow.task logger because we leave it there.

While my solution here is a few more lines (and a lot more comments) it's not very complicated. There are two parts.

Instead of copying the handlers to root, I move them to root. We don't need them at task if they are already at root. This could ultimately allow for simplification of our propagation logic.

Previously we remove our console handler from root at run time. Now, if we're in a k8s executor pod, I keep the console handler there.

I didn't quite understand what "stdout redirection" means – is that within Python or is that something happening outside of Python (in a shell script perhaps) – ?

When I think about this problem, it seems that there is an orthogonal concern in the logging setup of Airflow which is whether or not the task logger (during execution) should be emitted to the stdout stream.

That's something you could want in any situation, not just K8S.

I didn't quite understand what "stdout redirection" means – is that within Python or is that something happening outside of Python (in a shell script perhaps) – ?

i am not sure what comment you refer to but, what this means is there are stdlib helpers to take things that would ordinarily go to stdout (e.g. print) and send them to some other stream.

see from contextlib import redirect_stdout. it just monkey patches sys.stdout temporarily.

we use them (for better or worse) to redirect stdout to task logs.

our log read logic when task is running is usually, read from flask log server. most task logging is redirected to log (and therefore file) and our "console" handler respects this redirection. for obvious reasons -- the celery worker log, or local executor log would get unreasonably chatty. but in k8s executor context, there is no log server on the worker, and there is no problem with keeping the stdout, and importantly our log read logic assumes everything will be forwarded to stdout -- and this is what's broken that i am here fixing.

dstandish · 2022-12-29T19:02:58Z

ok updated the description so hopefully it's a little clearer whats going on

dstandish · 2022-12-31T08:39:18Z

Ok @malthe i have simplified the code, if you would like to have another look:
https://github.com/apache/airflow/blob/0ade033eaa9feb52aecbe12d1b91131a27a80b4b/airflow/cli/commands/task_command.py#L322-L326

airflow/cli/commands/task_command.py

airflow/utils/log/file_task_handler.py

airflow/cli/commands/task_command.py

airflow/utils/log/file_task_handler.py

ashb

A few small nits, but looks good to me overall.

ashb · 2023-01-09T11:20:32Z

airflow/cli/commands/task_command.py

+    # processing hundreds of simultaneous tasks.
+    # this should be last thing before running, to reduce likelihood of an open session
+    # which can cause trouble if running process in a fork.
+    settings.reconfigure_orm(disable_connection_pool=True)


Is this related to this logging PR in anyway?

i don't think this will fail if we remove this change. you could call it a drive by and i can remove if you like.

task runner tests failed with this change. then i was like "oh why is it just throwing away whole log config, let's try and not do that". then after leaving the FTH intact for that test, that i discovered there was an extraneous session being created in created in _render_filename. as part of troubleshooting the failures and discovering that though, also saw that this reconfigure is happening earlier than it probably ought to. should be done as late as possible i think.

airflow/utils/log/file_task_handler.py

tests/cli/commands/test_task_command.py

tests/task/task_runner/test_standard_task_runner.py

Co-authored-by: Ash Berlin-Taylor <ash_github@firemirror.com>

…text After apache#28440, instead of having a task logger both at `airflow.task` and root logger, we only have it at root logger. This means we can remove the logic to set propagate to False, because there's no longer a risk of record processed by FTH twice. It also means we can remove the logic to walk up the logger hierarchy and set context because we don't need to hit both airflow.task and root -- there will only ever be one such handler instance. So in effect we deprecate the MAINTAIN_PROPAGATE logic and no longer set propagate=False by default. While we could probably remove the "DISABLE_PROPAGATE" logic too (it's only used by file processor) it doesn't really hurt to leave it. (cherry picked from commit b9ed441f9127503f55e338f728e68f10bc77f3df)

boring-cyborg bot added area:CLI area:logging labels Dec 18, 2022

dstandish mentioned this pull request Dec 18, 2022

Run kubernetes executor tasks in interactive mode for live logs #28238

Closed

dstandish force-pushed the enable-stdout-when-k8s-executor-worker branch 2 times, most recently from 57c260f to a6b0563 Compare December 22, 2022 00:05

uranusjr reviewed Dec 22, 2022

View reviewed changes

airflow/cli/commands/task_command.py Outdated Show resolved Hide resolved

dstandish force-pushed the enable-stdout-when-k8s-executor-worker branch 3 times, most recently from 9195ee5 to c90e631 Compare December 24, 2022 07:21

dstandish mentioned this pull request Dec 24, 2022

Simplify log context setting / propagation handling #28571

Closed

dstandish commented Dec 29, 2022

View reviewed changes

dstandish requested review from ashb, jedcunningham and uranusjr December 29, 2022 17:11

dstandish added this to the Airflow 2.6.0 milestone Dec 29, 2022

dstandish requested review from ephraimbuddy, potiuk and kaxil December 29, 2022 17:14

dstandish force-pushed the enable-stdout-when-k8s-executor-worker branch from 1f50899 to 735a395 Compare December 30, 2022 06:35

dstandish force-pushed the enable-stdout-when-k8s-executor-worker branch from 29239b0 to 2a514f1 Compare December 31, 2022 07:41

uranusjr reviewed Jan 3, 2023

View reviewed changes

airflow/cli/commands/task_command.py Outdated Show resolved Hide resolved

uranusjr reviewed Jan 3, 2023

View reviewed changes

airflow/utils/log/file_task_handler.py Outdated Show resolved Hide resolved

malthe reviewed Jan 3, 2023

View reviewed changes

airflow/cli/commands/task_command.py Show resolved Hide resolved

malthe reviewed Jan 3, 2023

View reviewed changes

airflow/utils/log/file_task_handler.py Show resolved Hide resolved

dstandish added 8 commits January 3, 2023 21:36

typo

486d5b5

simplify

4f8aeea

simplify

67bc6a7

simplify

7e148b5

don't check TI

1a9db65

set private

6b8b153

inline some code

6280275

fix tests

776b819

dstandish force-pushed the enable-stdout-when-k8s-executor-worker branch from 1d8461a to 776b819 Compare January 4, 2023 05:51

dstandish requested a review from uranusjr January 4, 2023 05:57

static check

0d4a208

ashb approved these changes Jan 9, 2023

View reviewed changes

dstandish and others added 6 commits January 9, 2023 09:20

Update tests/cli/commands/test_task_command.py

777dd4e

Co-authored-by: Ash Berlin-Taylor <ash_github@firemirror.com>

remove freeze time

1c1f1c9

Update tests/task/task_runner/test_standard_task_runner.py

49228a2

Co-authored-by: Ash Berlin-Taylor <ash_github@firemirror.com>

Update airflow/utils/log/file_task_handler.py

1695b44

Co-authored-by: Ash Berlin-Taylor <ash_github@firemirror.com>

remove freeze time

da74320

fix whitespace

b7e8d7c

dstandish merged commit 3ececb2 into apache:main Jan 9, 2023

dstandish deleted the enable-stdout-when-k8s-executor-worker branch January 9, 2023 20:27

pierrejeambrun added the type:misc/internal Changelog: Misc changes that should appear in change log label Jan 9, 2023

pierrejeambrun mentioned this pull request Mar 6, 2023

No multiline log entry for bash env vars #28881

Merged

This was referenced Apr 19, 2023

Google Stackdriver logging not working #30740

Open

Can't view running tasks logs using KubernetesExecutor. #16001

Closed

taharah mentioned this pull request Oct 5, 2023

Airflow task log handling broken for non-Kubernetes executors #34783

Open

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Propagate logs to stdout when in k8s executor pod #28440

Propagate logs to stdout when in k8s executor pod #28440

dstandish commented Dec 18, 2022 •

edited

Loading

malthe commented Dec 29, 2022

dstandish commented Dec 29, 2022 •

edited

Loading

dstandish Dec 29, 2022

malthe Jan 3, 2023

dstandish Jan 3, 2023

dstandish commented Dec 29, 2022

dstandish commented Dec 31, 2022

ashb left a comment

ashb Jan 9, 2023

dstandish Jan 9, 2023

Propagate logs to stdout when in k8s executor pod #28440

Propagate logs to stdout when in k8s executor pod #28440

Conversation

dstandish commented Dec 18, 2022 • edited Loading

malthe commented Dec 29, 2022

dstandish commented Dec 29, 2022 • edited Loading

dstandish Dec 29, 2022

Choose a reason for hiding this comment

malthe Jan 3, 2023

Choose a reason for hiding this comment

dstandish Jan 3, 2023

Choose a reason for hiding this comment

dstandish commented Dec 29, 2022

dstandish commented Dec 31, 2022

ashb left a comment

Choose a reason for hiding this comment

ashb Jan 9, 2023

Choose a reason for hiding this comment

dstandish Jan 9, 2023

Choose a reason for hiding this comment

dstandish commented Dec 18, 2022 •

edited

Loading

dstandish commented Dec 29, 2022 •

edited

Loading