Skip to content

Print configuration on scheduler startup. - #22588

Merged
potiuk merged 6 commits into
apache:mainfrom
tirkarthi:print-conf-scheduler-startup
Apr 4, 2022
Merged

potiuk merged 6 commits into
apache:mainfrom
tirkarthi:print-conf-scheduler-startup

Conversation

@tirkarthi

Copy link
Copy Markdown
Contributor

This PR prints the configuration used during scheduler startup. The sensitive values are masked so that they are not captured by mistake in log files.

closes: #22141
related: #22141

@jedcunningham

Copy link
Copy Markdown
Member

Couple things: I think we should only show non-default config (I'm not sure if this is already the case, but I don't think it is) and should we do this for other components also?

@potiuk

potiuk commented Mar 31, 2022 •

Copy link
Copy Markdown
Member

Couple things: I think we should only show non-default config (I'm not sure if this is already the case, but I don't think it is) and should we do this for other components also?

I fully agree we should have it for all components. However I think showing complete config is a bit better. Ideally it should also show where the config came from =- default, config file, variable, secret. And this might need a bit modification of the conf code. But I tink it is crucial part of this change - knowing where each configuration variable came from would make it infintely easier to diagnose problems of people who - for example - have systemd and do not realize their AIRFLOW___ variable is not set when their server is started but they have it set when the login interactively and their .bashrc is actually sourced then.

Not seeing the config values currently is the major source of problems (I've seen multiple issues about it) for people who do not realize that airflow info can actually produce different set of configuration than whan their webserver or scheduler observes.

Such misconfigurations are next to impossible to diagnose currently, they rely mostly on guessing.

Note that gunicorn makes it a bit difficult for webserver because it will print logs every time gunicorn restarts the process which makes it rather annoying - so this information shoudl only be printed in the main process of webserver.

@potiuk

potiuk commented Mar 31, 2022

Copy link
Copy Markdown
Member

Another option is to "query" or send signal to runing webserver/scheduler/triggerer (traditionally SIGUSR1 is used for similar feature) to know what configuration it sees, but I think dumping it to the logs at startup is far easier for diagnostic purposes (if it is written only once at startup).

@jedcunningham

Copy link
Copy Markdown
Member

Also showing the source makes perfect sense to me, so +1 on that.

I still think we should only show the non-defaults, however. Way less noise, and makes my typical first question of "what config have you changed" much easier to answer 🤷‍♂️. Maybe we send the non-defaults to logs, and let SIGURS1 dump it all? Best of both worlds?

@potiuk

potiuk commented Mar 31, 2022

Copy link
Copy Markdown
Member

Also showing the source makes perfect sense to me, so +1 on that.

I still think we should only show the non-defaults, however. Way less noise, and makes my typical first question of "what config have you changed" much easier to answer man_shrugging. Maybe we send the non-defaults to logs, and let SIGURS1 dump it all? Best of both worlds?

Yeah. less noise for sure. And yeah. You are right it shows "changes" - I like it more :). SIGUSR1 woudl be a bonus I think ;)

@tirkarthi

tirkarthi commented Mar 31, 2022 •

Copy link
Copy Markdown
Contributor Author

Thanks @jedcunningham and @potiuk for the feedback. I have modified the PR so that non-default configuration is displayed along with source in [] as below indicating whether it's from environment variable / airflow.cfg / cmd. For signal SIGUSR1 in non-daemon mode I have added a handler that prints all configuration including default. I have added tests to ensure "default" is filtered by default :)

I have used print since airflow config list also used print. Let me know if this needs to be changed to logger and using log.info. I have also not added syntax highlighting. Let me know your feedback on the format so that I can modify accordingly.

$ airflow scheduler
  ____________       _____________
 ____    |__( )_________  __/__  /________      __
____  /| |_  /__  ___/_  /_ __  /_  __ \_ | /| / /
___  ___ |  / _  /   _  __/ _  / / /_/ /_ |/ |/ /
 _/_/  |_/_/  /_/    /_/    /_/  \____/____/|__/
[core]
dags_folder = < hidden > [env var]
hostname_callable = socket.getfqdn [airflow.cfg]
default_timezone = utc [airflow.cfg]
executor = < hidden > [env var]
sql_alchemy_conn = < hidden > [env var]
sql_engine_encoding = utf-8 [airflow.cfg]
sql_alchemy_pool_enabled = True [airflow.cfg]

@potiuk

potiuk commented Mar 31, 2022

Copy link
Copy Markdown
Member

Oh wow. That looks cool. I think adding syntax highliting/rich colors would be fantastic in the print() but then also logging it to the log (without syntax) migh tbe useful. The first one wiell be great for casual users for testing and seeing that their specifc values are used, the second would be for diagnosticts (sometimes stuiff printed on stdout might be silently swallowed.

Comment thread airflow/utils/cli.py Resolved
@potiuk

potiuk commented Mar 31, 2022

Copy link
Copy Markdown
Member

NICE! @jedcunningham - WDYT? I think this one is cool.

@potiuk

potiuk commented Mar 31, 2022 •

Copy link
Copy Markdown
Member

I'd say that one qualifies as PR of the month ;) (pity the newsletter is out).

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Hmm, why is parallelism hidden 🤔

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

I have display_sensitive=False (default value is False) which hides all values from env, vars and command. I don't want to pass display_sensitive=True since that might dump sensitive values to logs in case of starting as daemon or systemd. I guess we can try filtering for sensitive values in the for loop similar to how "default" values are filtered out so that other values from env/cmd are shown. Thoughts?

:param display_sensitive: If True, the values of options set by env
vars and bash commands will be displayed. If False, those options
are shown as '< hidden >'

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

That was what I was fearing it might be. I guess let's not worry about it now for now. This does make this less comprehensive than I was initially imaging as it's not uncommon to use env vars for non-sensitive config as well.

@potiuk potiuk Apr 2, 2022 •

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Ough. I did not know display_sensitive is "so sensitive" :) .

I thin what we could do though is to implement a new flag in the dict less_sensitive_config :) (?) and do few things there:

  • hide anything coming from secret (I think there is flag that just shows path rather than value for that already and it is on by default)
  • We already have the list of sensitive configs - we could hide them by default:
    sensitive_config_values = {
        ('core', 'sql_alchemy_conn'),
        ('core', 'fernet_key'),
        ('celery', 'broker_url'),
        ('celery', 'flower_basic_auth'),
        ('celery', 'result_backend'),
        ('atlas', 'password'),
        ('smtp', 'smtp_password'),
        ('webserver', 'secret_key'),
    }
  • we can pass config through "redact()" - and we could extend the semantics of sensitive_var_conn_names to also cover key names of sensitive data (or we could even add another config sensitive_configuration_names where user could specify which of the config they want to hide).

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Thanks @potiuk , I would like to have this as a separate issue since it might need more discussion on what and how to filter out items.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Thanks @potiuk , I would like to have this as a separate issue since it might need more discussion on what and how to filter out items.

Sure. Works for me :)

Comment thread airflow/utils/cli.py Resolved
Comment thread airflow/utils/cli.py Resolved
@potiuk

potiuk commented Apr 1, 2022

Copy link
Copy Markdown
Member

One more last comment since there is also static check to fix (I promise it's the last one :).

It would be great to write a paragraph or two about this behaviour (including the SIGUSR1 option) in https://airflow.apache.org/docs/apache-airflow/stable/howto/set-config.html . This is so tht we do not need to explain it to the users, but just send them the link.

@tirkarthi
tirkarthi requested a review from kaxil as a code owner April 1, 2022 09:25
@tirkarthi

Copy link
Copy Markdown
Contributor Author

Thanks @jedcunningham I have fixed comments except for the value for env, cmd. Thanks @potiuk, there is a note in the docs about configuration being different across webserver and worker can cause issue. I have added a note there since I felt it's appropriate. Feel free to suggest other wording if it can be explained better.

Use the same configuration across all the Airflow components. While each component does not require all, some configurations need to be same otherwise they would not work as expected. A good example for that is secret_key which should be same on the Webserver and Worker to allow Webserver to fetch logs from Worker.

@potiuk potiuk left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Looks great. I think we should also add it for other components (separate PR). I think we should also encourage users to use the same configuation everywhere even if it s not technically needed - simply because it makes diagnostics and investigations better. Having the same output in all components might help with that.

@github-actions github-actions Bot added the full tests needed We need to run full set of tests for this PR to merge label Apr 1, 2022
@github-actions

github-actions Bot commented Apr 1, 2022

Copy link
Copy Markdown
Contributor

The PR most likely needs to run full matrix of tests because it modifies parts of the core of Airflow. However, committers might decide to merge it quickly and take the risk. If they don't merge it quickly - please rebase it to the latest main at your convenience, or amend the last commit of the PR, and push it with --force-with-lease.

@tirkarthi
tirkarthi force-pushed the print-conf-scheduler-startup branch from f586895 to 46d21cf Compare April 1, 2022 11:14
@tirkarthi
tirkarthi force-pushed the print-conf-scheduler-startup branch from 92e4b4f to 19ef2c8 Compare April 2, 2022 02:15
@potiuk
potiuk merged commit 78586b4 into apache:main Apr 4, 2022
@tirkarthi

Copy link
Copy Markdown
Contributor Author

Thanks @potiuk and @jedcunningham for the feedback :)

@ashb

ashb commented Apr 5, 2022 •

Copy link
Copy Markdown
Member

This PR needs fixing -- the current behaviour is a) noisy and b) useless when using env vars to configure things.

dags_folder = < hidden > [env var]
default_timezone = utc [airflow.cfg]
executor = < hidden > [env var]

Those dag_folder and executor should be shown. Coming form an env var does not mean it should be hidden.

Please fix this today or else I'll have to revert it before the release.

Secondly it should be possible to turn this off (I'd possibly even argue it should be off by default)

Thirdly there should be some message about "running config" -- when I first saw this happen I thought someone had left in a debug print somewhere in the code!

@ashb

ashb commented Apr 5, 2022

Copy link
Copy Markdown
Member

Looks great. I think we should also add it for other components (separate PR). I think we should also encourage users to use the same configuation everywhere even if it s not technically needed - simply because it makes diagnostics and investigations better. Having the same output in all components might help with that.

This should not happen for task commands -- it would show up in task logs (twice, for Reasons) and make viewing the actual task logs harder.

@ashb

ashb commented Apr 5, 2022

Copy link
Copy Markdown
Member

Having this config display as a airflow config <something> sub-command would be good too!

@potiuk

potiuk commented Apr 5, 2022

Copy link
Copy Markdown
Member

Having this config display as a airflow config <something> sub-command would be good too!

We already have airflow info :)

@ashb

ashb commented Apr 5, 2022

Copy link
Copy Markdown
Member

I was thinking specifically "here is the non-default config you are running with" which info doesn't show (and to me at least feels like it belongs in info, but I don't mind where it lives)

@potiuk

potiuk commented Apr 5, 2022

Copy link
Copy Markdown
Member

I was thinking specifically "here is the non-default config you are running with" which info doesn't show (and to me at least feels like it belongs in info, but I don't mind where it lives)

Right. Yeah.

@kaxil

kaxil commented Apr 5, 2022

Copy link
Copy Markdown
Member

+1 for having it in airflow config list with a flag for showing/hiding defaults only. Feels out of place in logs

@tirkarthi

Copy link
Copy Markdown
Contributor Author

I am fine with the reversion if this needs more time to discuss on the what and how things should be displayed along with the appropriate subcommand it should come under.

jedcunningham added a commit to astronomer/airflow that referenced this pull request Apr 8, 2022
ashb pushed a commit that referenced this pull request Apr 8, 2022
@ephraimbuddy ephraimbuddy added the changelog:skip Changes that should be skipped from the changelog (CI, tests, etc..) label Apr 11, 2022
@potiuk

potiuk commented Apr 12, 2022 •

Copy link
Copy Markdown
Member

I think it's worth to revive it @tirkarthi

+1 for having it in airflow config list with a flag for showing/hiding defaults only. Feels out of place in logs

Hey @kaxil - I think you do not fully grasp the problem we are trying to solve. Both should be there - logs and CLI. As stated elsewhere CLI might give DIFFERENT results than what airflow sees, especially when you use systemd.

Many people (even those who are tasked with installing Airlfow) are not aware that setting configuration and variables in .bashrc or .zshrc will not work when they run airflow via systemd - simply because those files are not sourced and variables not set.
Yet you can find plenty of guides on setting the variables all over the internet asking you to add them to .bashrc or similar.

And if you do it for "airflow" user, ti all looks COOL. airflow config shows the right setting, airflow scheduler run manually works flawlessly, but then when you run it via systemd, suddenly the default "sqlite" database is used as this is default fallback of airflow if SQLALCHEMY variable is not set (but it was in .bashrc).

And we only find out because the user sends us a stacktrace that indicates that sqlite database has not been initialized (and we only know that this is sqlite because you see deep in the stactrace that sqlite driver is used).

And those users claim that "no we are not using sqlite - we are using Postgres - look, this is output of my arflow config command). But they do not realize their airflow config is different because their variables are not set via systemd.

Those are true stories which I experienced (and mutliple times). The only way to check what REALLLY airlfow sees is to print it in the logs together with the source where they came from. There is no other certain way.

@potiuk

potiuk commented Apr 12, 2022

Copy link
Copy Markdown
Member

So if we have this feature - we will just ask the user "send us the first lines of the log containing the configuration" when in doubt.

@potiuk

potiuk commented Apr 25, 2022 •

Copy link
Copy Markdown
Member

I am fine with the reversion if this needs more time to discuss on the what and how things should be displayed along with the appropriate subcommand it should come under.

@tirkarthi - can you please re-start working on this feature :) ? I think this is the best way to conclude the discussion.

@potiuk

potiuk commented May 9, 2022

Copy link
Copy Markdown
Member

@tirkarthi (also @ashb and @kaxil and @jedcunningham ) - here is an exact example of why I think displaying configuration with source of it in the logs makes perfect sense and we need it:

#23586 (comment)

  1. The user had XCOM backend set in configuration
  2. Unknowingly they also had the XCOM backend set as ENV variable in systemd
  3. They changed the backend in config and it worked everywhere except the webserver
  4. The user opened an issue
  5. Involved maintainer
  6. maintainer had to boldly guess that there MUST be a configuration somewhere else
  7. they user - after going crazy finally found the systemd variable set

If we printed the source of configuration in the logs, at step 5) we could ask for it or possibly user would have noticed it on their own and never opened an issue.

@ashb

ashb commented May 9, 2022

Copy link
Copy Markdown
Member

@tirkarthi (also @ashb and @kaxil and @jedcunningham ) - here is an exact example of why I think displaying configuration with source of it in the logs makes perfect sense and we need it:

#23586 (comment)

  1. The user had XCOM backend set in configuration
  2. Unknowingly they also had the XCOM backend set as ENV variable in systemd
  3. They changed the backend in config and it worked everywhere except the webserver
  4. The user opened an issue
  5. Involved maintainer
  6. maintainer had to boldly guess that there MUST be a configuration somewhere else
  7. they user - after going crazy finally found the systemd variable set

If we printed the source of configuration in the logs, at step 5) we could ask for it or possibly user would have noticed it on their own and never opened an issue.

Doesn't the UI already show that information if you go to Admin -> Config?

@tirkarthi

Copy link
Copy Markdown
Contributor Author

@potiuk I had similar thoughts reading the issue that there should be some configuration difference between using the cli to print configuration and the actual scheduler process. I guess we can have the configuration part to be dumped only when we send a signal sent to scheduler process since there is no consensus on cli option to print or printing by default during startup etc.

@potiuk

potiuk commented May 9, 2022 •

Copy link
Copy Markdown
Member

Doesn't the UI already show that information if you go to Admin -> Config?

Webserver could (I am not sure if it shows source of variable -likely yes) . But not for scheduler. The example here was with Webserver but this issue would have been exactly the same if the variable was set for scheduler's systemd. (and that's what this PR was about :).

@potiuk

potiuk commented May 9, 2022

Copy link
Copy Markdown
Member

@potiuk I had similar thoughts reading the issue that there should be some configuration difference between using the cli to print configuration and the actual scheduler process. I guess we can have the configuration part to be dumped only when we send a signal sent to scheduler process since there is no consensus on cli option to print or printing by default during startup etc.

The signal is nice, but I think many people do not even know how to send a signal to their process when it runs on a remote system or they might not have enough permissions to do so, but they can see the logs:

https://man7.org/linux/man-pages/man2/kill.2.html

For a process to have permission to send a signal it must either be privileged
(under Linux: have the CAP_KILL capability), or the real or effective user ID
of the sending process must equal the real or saved set-user-ID of the target
process. In the case of SIGCONT it suffices when the sending and receiving
processes belong to the same session.

@potiuk

potiuk commented May 12, 2022

Copy link
Copy Markdown
Member

Doesn't the UI already show that information if you go to Admin -> Config?

Also one more comment for that -> I recalled that config is disabled by default for security in most installations. So even for webserver, the only place you can see the "effective" configuration of webserver are logs.

@kaxil

kaxil commented May 13, 2022

Copy link
Copy Markdown
Member

We can still have a flag on the scheduler and webserver commands, --display-conf-at-startup/--do-display-conf-at-startup (mouthful name I know -- but that's an example) that allows controlling the behaviour as there are many who would not want to see the those conf at starttup.

@potiuk

potiuk commented May 17, 2022 •

Copy link
Copy Markdown
Member

We can still have a flag on the scheduler and webserver commands, --display-conf-at-startup/--do-display-conf-at-startup (mouthful name I know -- but that's an example) that allows controlling the behaviour as there are many who would not want to see the those conf at starttup.

The problem is that those who need it (and come to use with issues), have usually no good idea nor control on how to change their systemd or similar configuration. Asking those people to modify their deployment configuration to add their options when they have really vague idea how their airflow is started in teh first place is pretty counter-productive. The idea is to get good answers on what configuration is used - without them having to understand that first.

I think (as long as we do it once at startup) - there is literally 0 overhead to print configuration (especially the non-default one) to the logs.

We are really talking about the case where:

a) there is an "admin" of airflow who vaguely knows how their system is configured (happens when you have a new person which is tasked with Airflow maintenance)

b) that persons sees a strange behaviour and is not able to diagnose it so it runs cli to send and it shows some configuration which is reported to us ("yes I have it configured this way").

I simply want to have a way to tell the user "are you 100% sure this is what your webserver does" - can you open your logs and show the "startup" logs of the webserver?

In many cases showing the logs will be far easier to ask the user for rather than "check whatever configuration your deployment starts airflow with" - because then we might not get authoritative answer, we might guess ourselves and the admin might guess it too without knowing exactly the systemd configuration. Been there, done that many times.

Yeah. Those poople should know better. But by seing the configuration we can actually tell them that because we will see what they think about their configuration is wrong - before that we can just guess it, and we might guess wrongly.

@potiuk

potiuk commented Jun 3, 2022 •

Copy link
Copy Markdown
Member

Just as further "real life" example (yes I know I am pretty stubborn and persisten)

From https://apache-airflow.slack.com/archives/CCQ7EGB1P/p1654267866780949

I literally wildely guessed that the user has wrongly set their config. They did not even use systemd but their own helm chart. And despite all the evidence (config variables were OK) I based my assumptions on "16" being default value for the "max_tasks_per_dagrun" value that the configuration is wrongly applied.

Screenshot 2022-06-04 at 00 58 11

This was a wild guess and a leap of faith. If we print configuration in Airflow logs, I would not have to guess and make very bold statements, I would just have to ask the user to send me the logs.

The "You are right! Thank you" is a bitter-sweet for me. On one hand feels good I could help our user on the other I feel bad that I know we have no good way to diagnose similar issues and we will have to revert to "leap of faith" rather than real data multiple times in the future when others will have similar problems.

If that does not convince you @kaxil @ash then I am a bit lost why we are opposing it. This is extremely low effort, extremely low overhead and yet (by opposing it) we managed to make somoene who wanted to contribute it to abandon the idea as they saw "no consensus".

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area:CLI changelog:skip Changes that should be skipped from the changelog (CI, tests, etc..) full tests needed We need to run full set of tests for this PR to merge

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Dump configurations in airflow scheduler logs based on the config it reads

6 participants