Unable to see the output of echo command in bash operator

dusadv · October 31, 2023, 11:13pm

I am using this tutorial code from Marc Lamberti. Here is the code:

from airflow import DAG
from airflow.decorators import task
from airflow.operators.bash import BashOperator

from datetime import datetime

with DAG("new_dag", start_date=datetime(2021, 1, 1), 
    schedule="@daily", catchup=False):

        @task
        def training_model(accuracy):
            return accuracy

        @task.branch
        def choose_best_model(accuracies):
            best_accuracy = max(accuracies)
            if best_accuracy > 8:
                return 'accurate'
            return 'inaccurate'

        accurate = BashOperator(
            task_id="accurate",
            bash_command="echo 'accurate'"
        )

        inaccurate = BashOperator(
            task_id="inaccurate",
            bash_command="echo 'inaccurate'"
        )

        choose_best_model(training_model.expand(accuracy=[3, 9, 2])) >> [accurate, inaccurate]

But when I run the dag from terminal the output I see is this:

Loading DAGs...
[2023-10-31T23:03:50.762+0000] {plugin.py:31} WARNING - Astro managed secrets backend is disabled
Running task training_model[0]... [2023-10-31T23:03:51.170+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=training_model, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=0, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.decorators.python._PythonDecoratedOperator, airflow.decorators.base.DecoratedOperator, airflow.operators.python.PythonOperator
SUCCESS ✅
Running task training_model[1]... [2023-10-31T23:03:51.227+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=training_model, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.decorators.python._PythonDecoratedOperator, airflow.decorators.base.DecoratedOperator, airflow.operators.python.PythonOperator
[2023-10-31T23:03:51.227+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=training_model, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.decorators.python._PythonDecoratedOperator, airflow.decorators.base.DecoratedOperator, airflow.operators.python.PythonOperator
SUCCESS ✅
Running task training_model[2]... [2023-10-31T23:03:51.305+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=training_model, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=2, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.decorators.python._PythonDecoratedOperator, airflow.decorators.base.DecoratedOperator, airflow.operators.python.PythonOperator
[2023-10-31T23:03:51.305+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=training_model, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=2, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.decorators.python._PythonDecoratedOperator, airflow.decorators.base.DecoratedOperator, airflow.operators.python.PythonOperator
[2023-10-31T23:03:51.305+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=training_model, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=2, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.decorators.python._PythonDecoratedOperator, airflow.decorators.base.DecoratedOperator, airflow.operators.python.PythonOperator
SUCCESS ✅
Running choose_best_model... [2023-10-31T23:03:51.438+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=choose_best_model, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=-1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.decorators.branch_python._BranchPythonDecoratedOperator, airflow.decorators.python._PythonDecoratedOperator, airflow.decorators.base.DecoratedOperator, airflow.operators.python.BranchPythonOperator, airflow.operators.python.PythonOperator, airflow.models.skipmixin.SkipMixin
[2023-10-31T23:03:51.438+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=choose_best_model, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=-1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.decorators.branch_python._BranchPythonDecoratedOperator, airflow.decorators.python._PythonDecoratedOperator, airflow.decorators.base.DecoratedOperator, airflow.operators.python.BranchPythonOperator, airflow.operators.python.PythonOperator, airflow.models.skipmixin.SkipMixin
[2023-10-31T23:03:51.438+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=choose_best_model, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=-1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.decorators.branch_python._BranchPythonDecoratedOperator, airflow.decorators.python._PythonDecoratedOperator, airflow.decorators.base.DecoratedOperator, airflow.operators.python.BranchPythonOperator, airflow.operators.python.PythonOperator, airflow.models.skipmixin.SkipMixin
[2023-10-31T23:03:51.438+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=choose_best_model, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=-1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.decorators.branch_python._BranchPythonDecoratedOperator, airflow.decorators.python._PythonDecoratedOperator, airflow.decorators.base.DecoratedOperator, airflow.operators.python.BranchPythonOperator, airflow.operators.python.PythonOperator, airflow.models.skipmixin.SkipMixin
SUCCESS ✅
Running accurate... [2023-10-31T23:03:51.601+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=accurate, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=-1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.operators.bash.BashOperator
[2023-10-31T23:03:51.601+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=accurate, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=-1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.operators.bash.BashOperator
[2023-10-31T23:03:51.601+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=accurate, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=-1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.operators.bash.BashOperator
[2023-10-31T23:03:51.601+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=accurate, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=-1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.operators.bash.BashOperator
[2023-10-31T23:03:51.601+0000] {listener.py:32} INFO - TaskInstance Details: dag_id=accurate, task_id=accurate, dagrun_id=manual__2023-10-31T23:03:51.022743+00:00, map_index=-1, run_start_date=None, try_number=0, job_id=None, op_classpath=airflow.operators.bash.BashOperator
SUCCESS ✅
Completed running the DAG accurate. 🚀
Total elapsed time: 0.63s

As you can see, no output from echo command is visible here. Compared this with print from python operator (in other codes), I am able to clearly see the output.

PS, running dag from UI is not much help, as I am unable to see the logs at all. Here is what see for every task:

fe446e389477
*** Could not read served logs: Client error '404 NOT FOUND' for url 'http://fe446e389477:8793/log/dag_id=accurate/run_id=manual__2023-10-31T22:45:45.727814+00:00/task_id=choose_best_model/attempt=1.log'
For more information check: https://httpstatuses.com/404

Please advice, thanks.

iamakashladdha · November 1, 2023, 10:32am

Hi @dusadv, Thanks for sharing the details.

I triggered the same DAG from Airflow UI and it works for me, I believe there is some issue in reading the tasks logs on your local Airflow i.e. why you are getting 404 i.e. logs are not found. Do you get the logs for any other tasks in the UI?

So, Here’s the output of the task_id=“accurate” using BashOperator to echo accurate.

Hope this helps

dusadv · November 1, 2023, 10:52am

Hi @iamakashladdha.
Thanks for taking time to reply this.

No I am unable to see log for any task. I am not sure why that is the case. Because before astrocli, I experimented with native airflow installation and I was able to see the logs for exact same code.

My preliminary search suggests it might have to do something with logs being inside the docker container. Because I can see the log files when I enter the container with command astro dev bash.

I have installed astrocli just this week and all my settings are on default as they come from pre-packaged from astronomer.

iamakashladdha · November 1, 2023, 10:59am

Hi @dusadv, Could you please share the following

Astro CLI version (astro version)
Astro Runtime Version
Docker Version

It looks to be something else wherein the issue is with fetching the task logs. Logs inside the docker container should be okay and expected, it is same for Astro CLI installation on my system.

Thanks, Akash

dusadv · November 1, 2023, 11:36am

Hi @iamakashladdha

Here you go:

Astro CLI Version: 1.19.3
Astro-runtime:9.4.0
Docker version 19.03.13, build 4484c46d9d

iamakashladdha · November 2, 2023, 4:06am

@dusadv, Thank you for sharing the details, I have the same version of Astro CLI and Astro Runtime on my local setup, while my Docker Desktop version, which is as below

Client (Engine) Version: 24.0.6
Server: Docker Desktop 4.25.0 (126437)

Would you mind updating your Docker Version to the Latest Release, I am not sure but worth a try.
Further if needed would suggest killing the containers using astro dev kill and starting the new containers using astro dev start. Let me know how it goes

Now regarding your second question, You can use the command astro dev run dags test <dag-id>, This command is used to run the Airflow CLI commands in the local Airflow Environment using Astro CLI.

I am able to get the required DAG output for BashOperator using this. PFB Snap

Hope this helps!

dusadv · November 3, 2023, 1:10am

Thanks @iamakashladdha , I will experiment with updating docker.

Meanwhile, I didn’t posted in this question but for some reason whenever I run any airflow command using astro dev run, I end up with the same error.
For example, I ran the command
sudo astro dev run dags test accurate

and I see the error:

Running: airflow dags test accurate
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x28 pc=0x521986]

goroutine 34 [running]:
bufio.(*Reader).Read(0x0, {0xc0003b0000?, 0xc00004f270?, 0xc0000c8fb8?})
	/usr/local/go/src/bufio/bufio.go:216 +0x86
github.com/docker/docker/pkg/stdcopy.StdCopy({0x1727c20, 0xc000116008}, {0x1727c20, 0xc000116010}, {0x1724f40, 0x0})
	/go/pkg/mod/github.com/docker/docker@v20.10.7+incompatible/pkg/stdcopy/stdcopy.go:108 +0x444
github.com/astronomer/astro-cli/docker.ExecPipe.func1()
	/go/src/github.com/astronomer/astro-cli/docker/docker.go:42 +0x54
created by github.com/astronomer/astro-cli/docker.ExecPipe
	/go/src/github.com/astronomer/astro-cli/docker/docker.go:40 +0x1d8

This doesn’t happen with just dags test but with every command I run using astro dev run.
For example, when I run sudo astro dev run connections list
I see the same error again:

Running: airflow dags test accurate
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x28 pc=0x521986]

goroutine 34 [running]:
bufio.(*Reader).Read(0x0, {0xc0003b0000?, 0xc00004f270?, 0xc0000c8fb8?})
	/usr/local/go/src/bufio/bufio.go:216 +0x86
github.com/docker/docker/pkg/stdcopy.StdCopy({0x1727c20, 0xc000116008}, {0x1727c20, 0xc000116010}, {0x1724f40, 0x0})
	/go/pkg/mod/github.com/docker/docker@v20.10.7+incompatible/pkg/stdcopy/stdcopy.go:108 +0x444
github.com/astronomer/astro-cli/docker.ExecPipe.func1()
	/go/src/github.com/astronomer/astro-cli/docker/docker.go:42 +0x54
created by github.com/astronomer/astro-cli/docker.ExecPipe
	/go/src/github.com/astronomer/astro-cli/docker/docker.go:40 +0x1d8
(mlops_zoomcamp) ubuntu@ip-172-31-41-248:~/astrocli/dummmy_1$ sudo astro dev run connections list
Running: airflow connections list
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x28 pc=0x521986]

goroutine 30 [running]:
bufio.(*Reader).Read(0x0, {0xc0002aa000?, 0xc0003863a0?, 0xc00002d7b8?})
	/usr/local/go/src/bufio/bufio.go:216 +0x86
github.com/docker/docker/pkg/stdcopy.StdCopy({0x1727c20, 0xc000114008}, {0x1727c20, 0xc000114010}, {0x1724f40, 0x0})
	/go/pkg/mod/github.com/docker/docker@v20.10.7+incompatible/pkg/stdcopy/stdcopy.go:108 +0x444
github.com/astronomer/astro-cli/docker.ExecPipe.func1()
	/go/src/github.com/astronomer/astro-cli/docker/docker.go:42 +0x54
created by github.com/astronomer/astro-cli/docker.ExecPipe
	/go/src/github.com/astronomer/astro-cli/docker/docker.go:40 +0x1d8

PS, JUST TO CLARIFY, I AM ABLE TO RUN OTHER ASTRO CLI COMMANDS LIKE START, STOP, KILL, and RUN (but not dev run).
This means:
this command works: sudo astro run accurate
BUT, this command fails: sudo astro dev run dags test accurate

dusadv · November 3, 2023, 1:43am

UPDATE AFTER UPGRADING DOCKER

Now I am on Docker version 24.0.2, build cb74dfc

But, I still fail to see logs in airflow webserver, the run command still doesn’t print echo output to terminal and anything with “dev run” command still fails.

PS, if it’s relevant.
OS: Ubuntu - 18.04 (Server hosted on ec2 and not a desktop system)

iamakashladdha · November 3, 2023, 9:45am

Hi @dusadv, I am sorry to hear about the issues you are experiencing.

Error [signal SIGSEGV: segmentation violation code=0x1 addr=0x28 pc=0x521986] was reported earlier with astro dev run * - astro dev run fails with SIGSEGV signal error · Issue #1364 · astronomer/astro-cli · GitHub and resolved in v1.19.2, looks like it has surfaced again.

Can you please install the v 1.19.2 → curl -sSL install.astronomer.io | sudo bash -s -- v1.19.2 and let us know.

Meanwhile, I will consolidate the issues you are fetching and take it with the development team.

Regards,
Akash

dusadv · November 3, 2023, 10:23am

Thanks @iamakashladdha
The change to astro-cli version 1.19.2 worked. The dev run command is running. I confirm that I am also able to see the output of echo command in bash terminal.

However, the logs on UI are still inaccessible. However, the error has changed. New error is:

de1712798d87
*** Could not read served logs: [Errno 111] Connection refused

If you can help me fix this - it would be awesome

iamakashladdha · November 3, 2023, 1:54pm

Hi @dusadv, Thank you for confirming that astro dev run * command execution worked for you, Glad to know that!

Regarding the Connection refused Error while accessing the logs in UI, Do you want to check any network policies/settings that may be blocking accessing the logs from Astro CLI running on an EC2 instance?

Please execute the command [astro dev logs](https://docs.astronomer.io/astro/cli/astro-dev-logs) for the webserver and scheduler to observe any error in the logs which could provide more helpful info.

Hope this helps!

dusadv · November 3, 2023, 3:09pm

Hi @iamakashladdha
I will try to look into networking policy. It will be great if you can share some initial direction on it.

But, I would be surprised if it did - after all everything is on the server and being accessed by localhost.
Also, it’s just logs that are inaccessible - I am able to access connections, xcoms, dag statistics etc. with no issues whatsover.

iamakashladdha · November 6, 2023, 8:35am

Hi @dusadv, Per the details you shared looks like your localhost can access all other Airflow components except logs running on an EC2 container.

Please execute the command astro dev logs for the webserver and scheduler to observe any error which could provide more helpful info to debug this particular case.

Btw, By any chance you tried running Astro CLI on your local system?

Regards,
Akash Laddha

Topic		Replies	Views
New to Airflow- Need help with BashOperator Airflow	1	3878	April 29, 2020
Call a Bashoperator which is inside a function from a python operator Airflow	1	7102	October 12, 2020
Airflow BashOperator - cannot create directory Airflow	4	4456	April 7, 2022
Bash Operator exiting with error code 137 Airflow	3	3042	August 19, 2021
"Permission denied" when running dag to create new directory Astro CLI	3	5044	March 6, 2023

Unable to see the output of echo command in bash operator

Related topics