Upgrade Airflow 2.1.4 -> 2.2.0 : Kubernetes executor worker pod can't resolve dag folder

[malov]

Apache Airflow version

Other Airflow 2 version

What happened

Using Bitnami Airflow image, I'm upgrading Airflow from 2.1.4 to 2.2.0, running on Kubernetes cluster. During upgrade no changes to environment is made: kubernets cluster is the same, database is the same, Helm chart used is the same. Docker images are custom build due to company's restrictions, but the only change in build process is what Airflow version is used.

What happened:
– DB upgrade initially generated errors due to different schema (task_instantses and dug_runs tables), but upon examining, they were harmless: records were apparantly from some test some months ago
– scheduler and web containers started without errors, found all dags and parsed them correctly
– attmept to start test dag (which uses Bash operator and prints hello world) failed with errors:

[2022-09-19 18:03:26,111] {dagbag.py:500} INFO - Filling up the DagBag from /opt/bitnami/***/dags/test_dag.py
Traceback (most recent call last):
  File "/opt/bitnami/airflow/venv/bin/airflow", line 8, in <module>
    sys.exit(main())
  File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/__main__.py", line 48, in main
    args.func(args)
  File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/cli/cli_parser.py", line 48, in command
    return func(*args, **kwargs)
  File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/utils/cli.py", line 92, in wrapper
    return f(*args, **kwargs)
  File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/cli/commands/task_command.py", line 276, in task_run
    dag = get_dag(args.subdir, args.dag_id)
  File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/utils/cli.py", line 192, in get_dag
    raise AirflowException(
airflow.exceptions.AirflowException: Dag 'test_dag' could not be found; either it does not exist or it failed to parse.

So, apparently worker pod found a dag, as it is indicated by first line, but then failed to find it again.

From the scheduler log:

[2022-09-22 12:28:54,476] {kubernetes_executor.py:531} INFO - Add task TaskInstanceKey(dag_id='test_dag', task_id='print_current_date', run_id='scheduled__2022-09-21T15:35:00+00:00', try_number=1) with command ['airflow', 'tasks', 'run', 'test_dag', 'print_current_date', 'scheduled__2022-09-21T15:35:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/test_dag.py'] with executor_config {}

Checking currently running instance of 2.1.4 Airflow, I see that corresponding line there is

[2022-09-22 12:28:54,476] {kubernetes_executor.py:531} INFO - Add task TaskInstanceKey(dag_id='test_dag', task_id='print_current_date', run_id='scheduled__2022-09-21T15:35:00+00:00', try_number=1) with command ['airflow', 'tasks', 'run', 'test_dag', 'print_current_date', 'scheduled__2022-09-21T15:35:00+00:00', '--local', '--subdir', '/airflow-workflow/dags/test_dag.py'] with executor_config {}

So, subdirs argument is resolved correctly, and test_dag runs fine.

I think this is a reason for a failure - that command to run test_dag doesn't resolve "subdirs" parameter correctly, but I don't know how to fix it:

1. "dags_folder" is set correctly in web and scheduler airflow.cfg
2. AIRFLOW_DAGS_DIR is set correctly in web and scheduler
3. It's difficult to get information from crashed worker pods, but they are built using same scripts, so I assume they are have the same settings.

What you think should happen instead

Test dag should be run by worker pod and print "hellow world" as it does in setup with Airflow 2.1.4

How to reproduce

No response

Operating System

Docker image uses:

PRETTY_NAME="Debian GNU/Linux 10 (buster)"
NAME="Debian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

Versions of Apache Airflow Providers

No response

Deployment

Other 3rd-party Helm chart

Deployment details

• Use Bitnami images: ugrade from 2.1.4-debian-10-r0 to 2.2.0-debian-10-r0
• Use Bitnami Helm chart 11.4.2 in both cases
• Bitnami images are custom-built due to company requirement to have dags mounted from a separate volume. Dag directory is custom, but the same for 2.1.4 and 2.2.0. Scripts building images with custom dag folder is the same for 2.1.4 and 2.2.0

Anything else

No response

Are you willing to submit PR?

• Yes I am willing to submit a PR!

Code of Conduct

• I agree to follow this project's Code of Conduct

[boring-cyborg]

Thanks for opening your first issue here! Be sure to follow the issue template!

[potiuk]

Pleaase see if the problem persist if you upgrade to latest 2.2.* (or even upgrade to 2.3* or 2.4*. It makes virtually no sense to upgrade to 2.2.0 - because almost by definition it has bugs. Even if you do not want to upgrade to 2.3 or 2.4 (which you should) there are likely tens of bugs fixed between 2.2.0 and 2.2.2 (but probably hundreds of others fixeed in 2.3 and 2.4)

Airflow follows SemVer - so you can be quite sure that a) any 2.* version should be backwards compatible in general b) 2.2.0 has bugs 100% (because 2.2.1 and 2.2.2 are bugfix releases).

I do recal problems fixed with relative directories (you can look up changelog if you want to make sure), but likely trying to find what can be reason will take more than just upgrading to latest version of Airlfow (either in 2.2.* line or in general).

[malov]

Thanks for suggestion, but I did this already: initially I upgraded from 2.1.0 to 2.2.2 directly, that's where I encounter this problem first. Then I started doing a gradual upgrade 2.1.0 -> 2.1.4 -> 2.2.0 -> 2.2.2. First change was successful, during second I saw this bug.
I couldn't find anything resembling my problem in changelog - maybe I didn't look hard enough - but I'l try versions other 2.2.* versions to see if it was fixed. Can't go past 2.2.* unfortunately, due to other restrictions.

[potiuk]

OK. Thanks for the explanation.

I think the reason why it has changed in 2.2.0 is this chage: #16860 but I think the root cause is that chart / K8S executor configuration you use does not properly set DAGS_FOLDER variable.

This change in 2.2.0 fixed the behaviour that has been accidentally broken in 2.2.0 - namely possibility of using different path in Scheduler and worker/K8S pod that executed it. This has been broken in 2.0.0 and it was fixed in 2.2.0, and it relied on the fact that DAGS_FOLDER variable is properly set in each of the components - and rather than passing the "absolute" path it passed DAGS_FOLDER/<relative_path> which uses this configuration to figure out where the DAGs are:

https://airflow.apache.org/docs/apache-airflow/stable/configurations-ref.html#dags-folder

So the root problem of yours is that you have missing or wrongly set AIRFLOW__CORE__DAGS_FOLDER in the POD that executes the task. And this is likely because you can have hard-coded AIRFLOW__CORE__DAGS_FOLDER pointing to /opt/bitnami/airflow/ or similar settings.

[potiuk]

BTW. This is probably a good reason why you should switch to community image and chart rather than bitnami related chart and image (you do not have to, but you are most likely to have similar problems). Those charts and images are maintained and supported by Bitnami - and it's them who technially you should raise such issues to (if you are uysing bitnami image/chart, you see the link to their issue tracker). We do not know if they have "correctly" configured and working chart and images as we only verify automatically and thoroughly our image and chart - so if they have any mistakes in any versions in their charts/images/harcoded values etc, or maybe you made some custom modifications to those we do not know.

I highly recommend to switch to the official Airlfow community chart/image instead if you want to have a tested and fufure-proof maintenance path.

[malov]

Thanks for the thoughtful response.
I don't use environment, but I do set dags_folder in [core] section of airflow.cfg to a value "/workflow/dags" for all three pods - web, scheduler, and worker. It is getting set up correctly for web and scheduler, but I can't check it for worker as it runs for a fraction of a second. The script which sets it is the same as for two other pods.

Regarding moving out of Bitnami - yes, I'd like to, and probably will do at a later day, but currently I inherited this setup and have to maintain it for a while. And they basically told be to go away when I raised this issue with them.

[potiuk]

My guess is that your setting in config is not effective and overwritten by some other setting - can't guess what it is but you need to check airflow info run in all your images and see if it shows what you expect it there, but you have to make sure you run it with the same environment you run it.

You likely have some bad configuration and difference between different components, but what it I cannot tell.

Unfortunatley my idea to dump airflow configuration in the logs when you start any airflow component (#22588 (comment)) has not been well received in (@kaxil - this is I think very good case where it would have been helpful) - so I can't help any more I am afraid.

If we had it implemented, you would see the differences looking at the logs of your components and comparing what you see there, but now, the only way is I think you make sure you run airflow info in exactly the same environment each component is executed now - with all the variablesm image, configuration etc.

[malov]

@potiuk any idea how I could get to worker configuration? Web and schedulet seems to have identical (and correct) configuration. Or any hint how I can trace it?

[malov]

Attempting to trace error back to its source:
In scheduler log I'm getting:

[2022-09-22 13:06:57,791] {base_executor.py:82} INFO - Adding to queue: ['airflow', 'tasks', 'run', 'test_dag', 'print_current_date', 'scheduled__2022-09-21T22:35:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/test_dag.py']
[2022-09-22 13:06:57,819] {kubernetes_executor.py:531} INFO - Add task TaskInstanceKey(dag_id='test_dag', task_id='print_current_date', run_id='scheduled__2022-09-21T22:35:00+00:00', try_number=1) with command ['airflow', 'tasks', 'run', 'test_dag', 'print_current_date', 'scheduled__2022-09-21T22:35:00+00:00', '--local', '--subdir', 'DAGS_FOLDER/test_dag.py'] with executor_config {}

First log message apparently comes from this line of the code (using 2.2 stable branch which I'm running now).
Method queue_command() is only called in queue_task_instance() method, and command for task to run is being built by command_as_list() method here.

Specific place where path to the dag is set is this:

        should_pass_filepath = not pickle_id and dag
        path = None
        if should_pass_filepath:
            if dag.is_subdag:
                path = dag.parent_dag.relative_fileloc
            else:
                path = dag.relative_fileloc

            if path:
                if not path.is_absolute():
                    path = 'DAGS_FOLDER' / path
                path = str(path)

If I'm reading this code correctly: for non-subdag case (which is mine), first we define path = relative_fileloc, which strips path from dag settings from inital / or more - whatever is left doesn't have / at the beginning. Then it is checked that this value is not absolute - which it is - then I'm getting what I'm getting - string "DAGS_FOLDER" prefixed to dag file name, which is a source of error.

Am I not correct?

[malov]

All right guys, I see that you don't have resources or interest to investigate it further.
I found the workaround - setting AIRFLOW__CORE__DAGS_FOLDER directly in the image, as it was suggested, and not going to spend more time digging into it.
Still hope you're going to fix it one day.

[potiuk]

Indeed, it seems a low priority and since it has an easy workaround, it's not blocking anyone. Hopefully someone will take in on, investigate and fix. There are probably hundreds of other things that's it's more important to spend time on.