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

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:

"dags_folder" is set correctly in web and scheduler airflow.cfg
AIRFLOW_DAGS_DIR is set correctly in web and scheduler
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

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

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).

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.

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.

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.

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.

@kaxil

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.

@potiuk

@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?

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?

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.

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.

Hi, I upgraded from 2.1.4 to 2.4.2 and got a similar error to this.
I have set AIRFLOW__CORE__DAGS_FOLDER env var but it does not seem to work.
We are using KubernetesExecutor and helm-chart 1.7.0 with Airflow 2.4.2
The log in the worker pod is as below:

[2022-11-02T07:24:45.316+0000] {dagbag.py:537} INFO - Filling up the DagBag from /opt/airflow/dags/prod_dynamic.py
....
[2022-11-02T07:24:47.477+0000] {cli.py:225} WARNING - Dag 'daily_client_updater' not found in path /opt/airflow/dags/prod_dynamic.py; trying path /opt/airflow/dags/prod_dynamic.py
[2022-11-02T07:24:47.478+0000] {dagbag.py:537} INFO - Filling up the DagBag from /opt/airflow/dags/prod_dynamic.py

Traceback (most recent call last):
  File "/opt/app-root/bin/airflow", line 8, in <module>
    sys.exit(main())
  File "/opt/app-root/lib64/python3.8/site-packages/airflow/__main__.py", line 39, in main
    args.func(args)
  File "/opt/app-root/lib64/python3.8/site-packages/airflow/cli/cli_parser.py", line 52, in command
    return func(*args, **kwargs)
  File "/opt/app-root/lib64/python3.8/site-packages/airflow/utils/cli.py", line 103, in wrapper
    return f(*args, **kwargs)
  File "/opt/app-root/lib64/python3.8/site-packages/airflow/cli/commands/task_command.py", line 366, in task_run
    dag = get_dag(args.subdir, args.dag_id, include_examples=False)
  File "/opt/app-root/lib64/python3.8/site-packages/airflow/utils/cli.py", line 228, in get_dag
    raise AirflowException(
airflow.exceptions.AirflowException: Dag 'daily_client_updater' could not be found; either it does not exist or it failed to parse.

Here prod_dynamic.py is where our DAG(s) are generated dynamically, it is something like:

def create_dag(dag_id, service_name, conf):
    dag = DAG(
        dag_id,
        description=conf["description"],
        schedule_interval=conf["schedule"],
        default_args=default_args,
        user_defined_filters=dict(
            hash=lambda str: hashlib.sha256(str.encode("utf-8")).hexdigest()
        ),
    )
    ...

    return dag

path_base = os.getenv('DAG_CONF_PATH')
for service_name in os.listdir(path_base):
    path_service = "{}/{}/conf".format(path_base, service_name)

    for dag_name in os.listdir(path_service):
        conf = {}
        ...
        # Create DAG
        dag_id = "{}__{}".format(service_name, conf["name"])
        globals()[dag_id] = create_dag(dag_id, service_name, conf)

I have around 15 DAG(s) in my test environment and this bug happens randomly on random DAG(s).
And often after some retries, somehow the exception does not happen on the newly-created worker.
Also, if I re-deploy the service (by executing helm upgrade it will fix the error too)
However I find this kind of behavior is quite dangerous as it makes the execution of the task unstable (we have important tasks that are required to finish in time).

Any help or information that you can provide will be greatly appreciated. 🙇

I found that all the error workers failed to mount some configmaps, as the events on all the failed pods is showing as below:

  Type     Reason       Age                    From               Message
  ----     ------       ----                   ----               -------
  Normal   Scheduled    5m                     default-scheduler  Successfully assigned betadailyclientupdater-e2f8afd8a2374d1bab3dbb7485af76f2 to node_xxx
  Normal   Pulled       4m57s                  kubelet            Container image "abc/airflow-core-242:latest" already present on machine
  Normal   Created      4m56s                  kubelet            Created container base
  Normal   Started      4m56s                  kubelet            Started container base
  Warning  FailedMount  4m49s (x2 over 4m50s)  kubelet            MountVolume.SetUp failed for volume "config" : object "airflow-airflow-config" not registered
  Warning  FailedMount  4m49s (x2 over 4m50s)  kubelet            MountVolume.SetUp failed for volume "krb5-keytab-volume" : object "airflow-default-keytab" not registered
  Warning  FailedMount  4m49s (x2 over 4m50s)  kubelet            MountVolume.SetUp failed for volume "kube-api-access-9gsv6" : object "kube-root-ca.crt" not registered
  Warning  FailedMount  4m49s (x2 over 4m50s)  kubelet            MountVolume.SetUp failed for volume "krb5-config-volume" : object "airflow-default-krb5-configmap" not registered
------

and this is happening randomly.
Confirmed that the "airflow-airflow-config" configmap is created and available but somehow can not be mounted.
So I started to think that it is an error related to the k8s cluster on which my Airflow is running, not Airflow 2.4.2 itself.

Agree.

JFYI, in regard to my issue,
it seems that the cause is I was using a same tag for every docker build and the latest docker image sometimes was not pulled to the node.
After creating a new tag for each docker build, now the issue has gone.
And FailedMount errors sometimes still happen but I confirmed with K8S team and they said it seems that finally the mount will be success and does not affected any operations on the pod.

Suggestion is to make date/version part of your TAG. using same tag for an image is a recipe for disaster. If anything else -you completely lose the connection between the source version and image.

converting to discussion in case more is needed.

Navigation Menu

Repository navigation

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

Apache Airflow version

What happened

What you think should happen instead

How to reproduce

Operating System

Versions of Apache Airflow Providers

Deployment

Deployment details

Anything else

Are you willing to submit PR?

Code of Conduct

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Apache Airflow version

What happened

What you think should happen instead

How to reproduce

Operating System

Versions of Apache Airflow Providers

Deployment

Deployment details

Anything else

Are you willing to submit PR?

Code of Conduct

Activity

boring-cyborg commented on Sep 23, 2022

potiuk commented on Sep 23, 2022

malov commented on Sep 26, 2022

potiuk commented on Sep 26, 2022

potiuk commented on Sep 26, 2022

malov commented on Sep 26, 2022

potiuk commented on Oct 2, 2022

malov commented on Oct 3, 2022

malov commented on Oct 3, 2022

malov commented on Oct 7, 2022

potiuk commented on Oct 7, 2022

tanvn commented on Nov 2, 2022

tanvn commented on Nov 3, 2022

potiuk commented on Nov 7, 2022

tanvn commented on Nov 21, 2022

potiuk commented on Nov 25, 2022

potiuk commented on Nov 25, 2022

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions