Intermitent log on deferrable operator

[ecodina]

Apache Airflow version

Other Airflow 2 version (please specify below)

What happened

On Airflow 2.4.3

When using a deferrable operator the log disappears from the webpage while the operator is deferred and appears when it is running/finished. This doesn't happen consistently over all DAG runs.

The error has been reproduced in the new log panel on the grid page & the "standalone" log page.

As an example, I've tried running a simple DAG (just executes sleep 10). The logs are for the 3rd retry and I am using the "Auto-refresh" button on the grid page.

There are no visible errors on the web console when this happens, but the web server logs look like Airflow doesn't know it is the 3rd try while the operator is deferred and gets the 2nd try.

What you think should happen instead

No response

How to reproduce

Use a deferrable operator. We use this custom one: https://gist.github.com/ecodina/157b5dc44b79b13fe296b1275b4f0967

Trigger it from the webpage and see how the log appears intermittently.

Operating System

CentOS Linux 8

Versions of Apache Airflow Providers

apache-airflow-providers-cncf-kubernetes | 4.4.0 | Kubernetes
apache-airflow-providers-common-sql | 1.2.0 | Common SQL Provider
apache-airflow-providers-ftp | 3.1.0 | File Transfer Protocol (FTP)
apache-airflow-providers-http | 4.0.0 | Hypertext Transfer Protocol (HTTP)
apache-airflow-providers-imap | 3.0.0 | Internet Message Access Protocol (IMAP)
apache-airflow-providers-postgres | 5.2.2 | PostgreSQL
apache-airflow-providers-sqlite | 3.2.1 | SQLite
apache-airflow-providers-ssh | 3.2.0 | Secure Shell (SSH)

Deployment

Other

Deployment details

Installed using PIP in a conda environment (as if it was a virtualenv).

Using postgresql .

Anything else

Relevant lines of the webserver's log:

--> the log doesn't appear
Dec 30 08:53:52 bright01 webserver.sh[1915713]: 192.168.253.76 - - [30/Dec/2022:08:53:52 +0000] "GET /object/grid_data?dag_id=dag.testing&num_runs=25 HTTP/1.1" 200 1800 "http://airflow.local/dags/dag.testing/grid?root=&dag_run_id=scheduled__2022-12-30T07%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Dec 30 08:53:52 bright01 webserver.sh[1915713]: 192.168.253.76 - - [30/Dec/2022:08:53:52 +0000] "GET /api/v1/dags/dag.testing/dagRuns/scheduled__2022-12-30T07:00:00+00:00/taskInstances/prova/logs/2?full_content=false HTTP/1.1" 200 14349 "http://airflow.local/dags/dag.testing/grid?root=&dag_run_id=scheduled__2022-12-30T07%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Dec 30 08:53:55 bright01 webserver.sh[1915713]: 192.168.253.76 - - [30/Dec/2022:08:53:55 +0000] "GET /object/grid_data?dag_id=dag.testing&num_runs=25 HTTP/1.1" 200 1800 "http://airflow.local/dags/dag.testing/grid?root=&dag_run_id=scheduled__2022-12-30T07%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Dec 30 08:53:55 bright01 webserver.sh[1915713]: 192.168.253.76 - - [30/Dec/2022:08:53:55 +0000] "GET /api/v1/dags/dag.testing/dagRuns/scheduled__2022-12-30T07:00:00+00:00/taskInstances/prova/logs/2?full_content=false HTTP/1.1" 200 14349 "http://airflow.local/dags/dag.testing/grid?root=&dag_run_id=scheduled__2022-12-30T07%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Dec 30 08:53:58 bright01 webserver.sh[1915713]: 192.168.253.76 - - [30/Dec/2022:08:53:58 +0000] "GET /object/grid_data?dag_id=dag.testing&num_runs=25 HTTP/1.1" 200 1801 "http://airflow.local/dags/dag.testing/grid?root=&dag_run_id=scheduled__2022-12-30T07%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Dec 30 08:53:58 bright01 webserver.sh[1915713]: 192.168.253.76 - - [30/Dec/2022:08:53:58 +0000] "GET /api/v1/dags/dag.testing/dagRuns/scheduled__2022-12-30T07:00:00+00:00/taskInstances/prova/logs/2?full_content=false HTTP/1.1" 200 14349 "http://airflow.local/dags/dag.testing/grid?root=&dag_run_id=scheduled__2022-12-30T07%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Dec 30 08:53:58 bright01 webserver.sh[1915713]: 192.168.253.76 - - [30/Dec/2022:08:53:58 +0000] "GET /api/v1/dags/dag.testing/dagRuns/scheduled__2022-12-30T07:00:00+00:00/taskInstances/prova/logs/3?full_content=false HTTP/1.1" 200 7804 "http://airflow.local/dags/dag.testing/grid?root=&dag_run_id=scheduled__2022-12-30T07%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"

-> the log starts appearing
Dec 30 08:54:01 bright01 webserver.sh[1915713]: 192.168.253.76 - - [30/Dec/2022:08:54:01 +0000] "GET /object/grid_data?dag_id=dag.testing&num_runs=25 HTTP/1.1" 200 1802 "http://airflow.local/dags/dag.testing/grid?root=&dag_run_id=scheduled__2022-12-30T07%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Dec 30 08:54:02 bright01 webserver.sh[1915713]: 192.168.253.76 - - [30/Dec/2022:08:54:02 +0000] "GET /api/v1/dags/dag.testing/dagRuns/scheduled__2022-12-30T07:00:00+00:00/taskInstances/prova/logs/3?full_content=false HTTP/1.1" 200 8198 "http://airflow.local/dags/dag.testing/grid?root=&dag_run_id=scheduled__2022-12-30T07%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"

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

[pankajastro]

you maybe have some logs on the trigger since once the task is deferred the execution happens on the trigger.

[ecodina]

Hi @pankajastro

We use SLURM to distribute tasks in different nodes of our cluster. The Airflow operator we use submits a job to SLURM. The workflow is as follows:

Operator: log a few things & submit job & defer itself -> Trigger: check the SLURM log. When a few lines have been added, yield a TriggerEvent -> Operator: receive the new SLURM log lines in the TriggerEvent and log them in Airflow & defer itself again

Therefore, all the logging happens inside the Operator, and not in the trigger.

It looks like a frontend bug: when the operator is deferred (the trigger "runs point"), the website loses count of what try is happening and defaults to the last one.

On Monday I'll try to write a simpler operator+triggerer (same structure but without using SLURM) to see if this keeps happening.

[tanelk]

Looks like duplicate of #27955

[ecodina]

Hello @tanelk

It looks similar, but I've reproduced the same issue with the "old standalone" log page as well. Here are some logs, that correspond to the retry=2

--> the task is in the deferred state. I refresh the log page & the log doesn't appear
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1 HTTP/1.1" 200 44841 "http://airflow.local/dags/dag.testing/grid?dag_run_id=scheduled__2023-01-02T05%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/css/bootstrap.min.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/select2/select2.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/css/font-awesome.min.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/datepicker/bootstrap-datepicker.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/css/flags/flags16.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/css/ab.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/airflowDefaultTheme.731e57571b52cca4350d.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/materialIcons.f9559e4953177b8b9a4a.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/main.a53ccbaa4ca384c91837.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/loadingDots.5da42d00b5455806e709.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/bootstrap-datetimepicker.min.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/switch.0e45299d29df3c0c8282.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/js/jquery-latest.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/js/ab_filters.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/js/ab_actions.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/flash.2b1a873e0aabc828a165.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/js/bootstrap.min.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/datepicker/bootstrap-datepicker.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/select2/select2.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/appbuilder/js/ab.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/moment.197a6f3cab42e240f8bd.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/main.a53ccbaa4ca384c91837.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/bootstrap-datetimepicker.min.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/bootstrap3-typeahead.min.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/dag.a9efcc271e92a9bdc654.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/dist/tiLog.7864c61b0b31ef37f084.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /static/loading.gif HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:20 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:20 +0000] "GET /object/next_run_datasets/dag.testing HTTP/1.1" 200 2 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:21 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:21 +0000] "GET /get_logs_with_metadata?dag_id=dag.testing&task_id=prova&map_index=-1&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&try_number=1&metadata=null HTTP/1.1" 200 16370 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"


--> the task is in the running state. I refresh the log page & the log appears
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1 HTTP/1.1" 200 45311 "http://airflow.local/dags/dag.testing/grid?dag_run_id=scheduled__2023-01-02T05%3A00%3A00%2B00%3A00&task_id=prova" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/select2/select2.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/css/font-awesome.min.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/datepicker/bootstrap-datepicker.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/css/bootstrap.min.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/css/flags/flags16.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/css/ab.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/airflowDefaultTheme.731e57571b52cca4350d.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/materialIcons.f9559e4953177b8b9a4a.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/main.a53ccbaa4ca384c91837.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/bootstrap-datetimepicker.min.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/loadingDots.5da42d00b5455806e709.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/switch.0e45299d29df3c0c8282.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/js/jquery-latest.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/js/ab_filters.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/js/ab_actions.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/flash.2b1a873e0aabc828a165.css HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/datepicker/bootstrap-datepicker.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/js/bootstrap.min.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/select2/select2.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/appbuilder/js/ab.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/moment.197a6f3cab42e240f8bd.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/main.a53ccbaa4ca384c91837.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/bootstrap-datetimepicker.min.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/bootstrap3-typeahead.min.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/dag.a9efcc271e92a9bdc654.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/dist/tiLog.7864c61b0b31ef37f084.js HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /static/loading.gif HTTP/1.1" 304 0 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /object/next_run_datasets/dag.testing HTTP/1.1" 200 2 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /get_logs_with_metadata?dag_id=dag.testing&task_id=prova&map_index=-1&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&try_number=1&metadata=null HTTP/1.1" 200 16370 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"
Jan 02 06:17:25 bright01 webserver.sh[1915713]: 192.168.253.76 - - [02/Jan/2023:06:17:25 +0000] "GET /get_logs_with_metadata?dag_id=dag.testing&task_id=prova&map_index=-1&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&try_number=2&metadata=null HTTP/1.1" 200 7468 "http://airflow.local/log?dag_id=dag.testing&task_id=prova&execution_date=2023-01-02T05%3A00%3A00%2B00%3A00&map_index=-1" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:108.0) Gecko/20100101 Firefox/108.0"

[potiuk]

cc: @andrewgodwin maybe that rings a bell for you ?

[andrewgodwin]

The logging web frontend definitely does have some weird behaviour depending on if the task is in RUNNING state or not, mostly as a result of the code that tries to go get live logs from the node directly if it's in RUNNING. If you've written a custom log backend, maybe that bit isn't working well?

I've worked on a couple of logging things around this for our hosted solution, and we had to do especially fun things to turn that mode off and make Airflow just read from the same place for logs all the time.

[ecodina]

Hi,

We have not written any custom log backend: we use self.log from within the custom operator and the only related configuration we've changed from airflow.cfg is base_log_folder.

In the following weeks we'll upgrade to the latest version of Airflow, to check whether it is still happening.

[ecodina]

Today I updated to Airflow 2.5.3. The new log view works as expected, but the old log web page still shows and hides the latest log.

[potiuk]

Today I updated to Airflow 2.5.3. The new log view works as expected, but the old log web page still shows and hides the latest log.

I think that changes in 2.6.0 (or maybe we discussed that we should remove the old log page @dstandish ?)

[ecodina]

Great! I'll wait for 2.6 then. Thanks.

[ecodina]

Since we upgraded to Airflow 2.6.2, this issue does not appear anymore. Closing it.