The GitHub Actions job "Tests" on airflow.git has failed. Run started by GitHub user dimberman (triggered by dimberman).
Head commit for run: 71c64de96248694017897fdb3d9d241e7c980825 / Daniel Imberman <[email protected]> Create a more efficient airflow dag test command that also has better local logging (#26400) The current `airflow dag test` command is insufficient for an iterative local workflow when developing dags. The current system relies on running a backfill job which a) is extremely slow and b) only shows scheduler-level logs, so the user would need to search for log files to see how their tasks actually ran! This new system ## Speed With this new system, we see a notable speedup in between-task speed. The new airflow dag test command can load tasks immediately and not wait for a scheduler heartbeat or other irrelevant airflow processes. ### Before: example bash operator: 13 seconds example python operator: 26 seconds ### After example bash operator: 6 seconds example python operator: 16 seconds ## Logging Previously, the `airflow dag test` command would pass on scheduler-level logs. This gives essentially 0 useful information for a DAG writer, and would force them to seek out task.log files in their filesystem every time they run a test dag. To improve this, we now surface task-level logs to the command line. We also no longer have any scheduler-level logs as we are no longer using a scheduler! ### Before ``` [2022-09-14 14:37:48,310] {dagbag.py:522} INFO - Filling up the DagBag from /files/dags [2022-09-14 14:37:48,967] {base_executor.py:93} INFO - Adding to queue: ['<TaskInstance: example_bash_operator.runme_0 backfill__2022-01-02T00:00:00+00:00 [queued]>'] [2022-09-14 14:37:48,973] {base_executor.py:93} INFO - Adding to queue: ['<TaskInstance: example_bash_operator.runme_1 backfill__2022-01-02T00:00:00+00:00 [queued]>'] [2022-09-14 14:37:48,979] {base_executor.py:93} INFO - Adding to queue: ['<TaskInstance: example_bash_operator.runme_2 backfill__2022-01-02T00:00:00+00:00 [queued]>'] [2022-09-14 14:37:48,985] {base_executor.py:93} INFO - Adding to queue: ['<TaskInstance: example_bash_operator.also_run_this backfill__2022-01-02T00:00:00+00:00 [queued]>'] [2022-09-14 14:37:48,991] {base_executor.py:93} INFO - Adding to queue: ['<TaskInstance: example_bash_operator.this_will_skip backfill__2022-01-02T00:00:00+00:00 [queued]>'] [2022-09-14 14:37:54,045] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:37:54,045] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo "example_bash_operator__runme_0__20220102" && sleep 1'] [2022-09-14 14:37:54,053] {subprocess.py:85} INFO - Output: [2022-09-14 14:37:54,055] {subprocess.py:92} INFO - example_bash_operator__runme_0__20220102 [2022-09-14 14:37:55,061] {subprocess.py:96} INFO - Command exited with return code 0 [2022-09-14 14:37:55,117] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:37:55,117] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo "example_bash_operator__runme_1__20220102" && sleep 1'] [2022-09-14 14:37:55,124] {subprocess.py:85} INFO - Output: [2022-09-14 14:37:55,125] {subprocess.py:92} INFO - example_bash_operator__runme_1__20220102 [2022-09-14 14:37:56,131] {subprocess.py:96} INFO - Command exited with return code 0 [2022-09-14 14:37:56,186] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:37:56,186] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo "example_bash_operator__runme_2__20220102" && sleep 1'] [2022-09-14 14:37:56,193] {subprocess.py:85} INFO - Output: [2022-09-14 14:37:56,194] {subprocess.py:92} INFO - example_bash_operator__runme_2__20220102 [2022-09-14 14:37:57,199] {subprocess.py:96} INFO - Command exited with return code 0 [2022-09-14 14:37:57,257] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:37:57,257] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo "ti_key=example_bash_operator__also_run_this__20220102"'] [2022-09-14 14:37:57,265] {subprocess.py:85} INFO - Output: [2022-09-14 14:37:57,266] {subprocess.py:92} INFO - ti_key=example_bash_operator__also_run_this__20220102 [2022-09-14 14:37:57,266] {subprocess.py:96} INFO - Command exited with return code 0 [2022-09-14 14:37:57,307] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:37:57,308] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo "hello world"; exit 99;'] [2022-09-14 14:37:57,316] {subprocess.py:85} INFO - Output: [2022-09-14 14:37:57,317] {subprocess.py:92} INFO - hello world [2022-09-14 14:37:57,317] {subprocess.py:96} INFO - Command exited with return code 99 [2022-09-14 14:37:57,340] {backfill_job.py:381} INFO - [backfill progress] | finished run 0 of 1 | tasks waiting: 2 | succeeded: 4 | running: 0 | failed: 0 | skipped: 1 | deadlocked: 0 | not ready: 2 [2022-09-14 14:37:57,351] {base_executor.py:93} INFO - Adding to queue: ['<TaskInstance: example_bash_operator.run_after_loop backfill__2022-01-02T00:00:00+00:00 [queued]>'] [2022-09-14 14:37:58,918] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:37:58,918] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo 1'] [2022-09-14 14:37:58,925] {subprocess.py:85} INFO - Output: [2022-09-14 14:37:58,926] {subprocess.py:92} INFO - 1 [2022-09-14 14:37:58,927] {subprocess.py:96} INFO - Command exited with return code 0 [2022-09-14 14:37:58,945] {dagrun.py:595} INFO - Marking run <DagRun example_bash_operator @ 2022-01-02T00:00:00+00:00: backfill__2022-01-02T00:00:00+00:00, state:running, queued_at: None. externally triggered: False> successful [2022-09-14 14:37:58,946] {dagrun.py:657} INFO - DagRun Finished: dag_id=example_bash_operator, execution_date=2022-01-02T00:00:00+00:00, run_id=backfill__2022-01-02T00:00:00+00:00, run_start_date=2022-09-14 14:37:48.865989+00:00, run_end_date=2022-09-14 14:37:58.946180+00:00, run_duration=10.080191, state=success, external_trigger=False, run_type=backfill, data_interval_start=2022-01-02T00:00:00+00:00, data_interval_end=2022-01-03T00:00:00+00:00, dag_hash=None [2022-09-14 14:37:58,946] {backfill_job.py:381} INFO - [backfill progress] | finished run 1 of 1 | tasks waiting: 0 | succeeded: 5 | running: 0 | failed: 0 | skipped: 2 | deadlocked: 0 | not ready: 0 [2022-09-14 14:37:58,949] {backfill_job.py:875} INFO - Backfill done for DAG <DAG: example_bash_operator>. Exiting. ``` ### After: ``` root@613d334d9c9d:/opt/airflow# airflow dags test example_bash_operator 2022-01-03 [2022-09-14 14:43:45,232] {dagbag.py:522} INFO - Filling up the DagBag from /files/dags [2022-09-14 14:43:45,997] {dag_command.py:556} INFO - dagrun id:example_bash_operator /opt/airflow/airflow/cli/commands/dag_command.py:573 RemovedInAirflow3Warning: Calling `DAG.create_dagrun()` without an explicit data interval is deprecated created dagrun <DagRun example_bash_operator @ 2022-01-03T00:00:00+00:00: manual__2022-01-03T00:00:00+00:00, state:running, queued_at: None. externally triggered: False> [2022-09-14 14:43:46,013] {dag_command.py:496} INFO - starting dagrun [2022-09-14 14:43:46,138] {dag_command.py:542} INFO - ***************************************************** [2022-09-14 14:43:46,138] {dag_command.py:543} INFO - Running task runme_0 [2022-09-14 14:43:46,144] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:43:46,145] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo "example_bash_operator__runme_0__20220103" && sleep 1'] [2022-09-14 14:43:46,152] {subprocess.py:85} INFO - Output: [2022-09-14 14:43:46,154] {subprocess.py:92} INFO - example_bash_operator__runme_0__20220103 [2022-09-14 14:43:47,158] {subprocess.py:96} INFO - Command exited with return code 0 [2022-09-14 14:43:47,179] {dag_command.py:547} INFO - runme_0 ran successfully! [2022-09-14 14:43:47,180] {dag_command.py:550} INFO - ***************************************************** [2022-09-14 14:43:47,197] {dag_command.py:542} INFO - ***************************************************** [2022-09-14 14:43:47,197] {dag_command.py:543} INFO - Running task runme_1 [2022-09-14 14:43:47,203] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:43:47,204] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo "example_bash_operator__runme_1__20220103" && sleep 1'] [2022-09-14 14:43:47,211] {subprocess.py:85} INFO - Output: [2022-09-14 14:43:47,213] {subprocess.py:92} INFO - example_bash_operator__runme_1__20220103 [2022-09-14 14:43:48,219] {subprocess.py:96} INFO - Command exited with return code 0 [2022-09-14 14:43:48,239] {dag_command.py:547} INFO - runme_1 ran successfully! [2022-09-14 14:43:48,239] {dag_command.py:550} INFO - ***************************************************** [2022-09-14 14:43:48,253] {dag_command.py:542} INFO - ***************************************************** [2022-09-14 14:43:48,253] {dag_command.py:543} INFO - Running task runme_2 [2022-09-14 14:43:48,259] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:43:48,259] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo "example_bash_operator__runme_2__20220103" && sleep 1'] [2022-09-14 14:43:48,266] {subprocess.py:85} INFO - Output: [2022-09-14 14:43:48,267] {subprocess.py:92} INFO - example_bash_operator__runme_2__20220103 [2022-09-14 14:43:49,273] {subprocess.py:96} INFO - Command exited with return code 0 [2022-09-14 14:43:49,294] {dag_command.py:547} INFO - runme_2 ran successfully! [2022-09-14 14:43:49,295] {dag_command.py:550} INFO - ***************************************************** [2022-09-14 14:43:49,374] {dag_command.py:542} INFO - ***************************************************** [2022-09-14 14:43:49,374] {dag_command.py:543} INFO - Running task also_run_this [2022-09-14 14:43:49,380] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:43:49,380] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo "ti_key=example_bash_operator__also_run_this__20220103"'] [2022-09-14 14:43:49,389] {subprocess.py:85} INFO - Output: [2022-09-14 14:43:49,390] {subprocess.py:92} INFO - ti_key=example_bash_operator__also_run_this__20220103 [2022-09-14 14:43:49,390] {subprocess.py:96} INFO - Command exited with return code 0 [2022-09-14 14:43:49,395] {dag_command.py:547} INFO - also_run_this ran successfully! [2022-09-14 14:43:49,395] {dag_command.py:550} INFO - ***************************************************** [2022-09-14 14:43:49,406] {dag_command.py:542} INFO - ***************************************************** [2022-09-14 14:43:49,407] {dag_command.py:543} INFO - Running task this_will_skip [2022-09-14 14:43:49,412] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:43:49,413] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo "hello world"; exit 99;'] [2022-09-14 14:43:49,420] {subprocess.py:85} INFO - Output: [2022-09-14 14:43:49,421] {subprocess.py:92} INFO - hello world [2022-09-14 14:43:49,422] {subprocess.py:96} INFO - Command exited with return code 99 [2022-09-14 14:43:49,422] {dag_command.py:549} INFO - Task Skipped, continuing [2022-09-14 14:43:49,422] {dag_command.py:550} INFO - ***************************************************** [2022-09-14 14:43:49,440] {dag_command.py:542} INFO - ***************************************************** [2022-09-14 14:43:49,440] {dag_command.py:543} INFO - Running task run_after_loop [2022-09-14 14:43:49,445] {subprocess.py:62} INFO - Tmp dir root location: /tmp [2022-09-14 14:43:49,446] {subprocess.py:74} INFO - Running command: ['/bin/bash', '-c', 'echo 1'] [2022-09-14 14:43:49,453] {subprocess.py:85} INFO - Output: [2022-09-14 14:43:49,454] {subprocess.py:92} INFO - 1 [2022-09-14 14:43:49,454] {subprocess.py:96} INFO - Command exited with return code 0 [2022-09-14 14:43:49,458] {dag_command.py:547} INFO - run_after_loop ran successfully! [2022-09-14 14:43:49,458] {dag_command.py:550} INFO - ***************************************************** [2022-09-14 14:43:49,471] {dag_command.py:542} INFO - ***************************************************** [2022-09-14 14:43:49,471] {dag_command.py:543} INFO - Running task run_this_last [2022-09-14 14:43:49,475] {dag_command.py:547} INFO - run_this_last ran successfully! [2022-09-14 14:43:49,475] {dag_command.py:550} INFO - ***************************************************** [2022-09-14 14:43:49,480] {dagrun.py:595} INFO - Marking run <DagRun example_bash_operator @ 2022-01-03T00:00:00+00:00: manual__2022-01-03T00:00:00+00:00, state:running, queued_at: None. externally triggered: False> successful [2022-09-14 14:43:49,480] {dagrun.py:657} INFO - DagRun Finished: dag_id=example_bash_operator, execution_date=2022-01-03T00:00:00+00:00, run_id=manual__2022-01-03T00:00:00+00:00, run_start_date=2022-01-03T00:00:00+00:00, run_end_date=2022-09-14 14:43:49.480895+00:00, run_duration=21998629.480895, state=success, external_trigger=False, run_type=manual, data_interval_start=2022-01-03T00:00:00+00:00, data_interval_end=2022-01-04T00:00:00+00:00, dag_hash=None ``` --- **^ Add meaningful description above** Read the **[Pull Request Guidelines](https://github.com/apache/airflow/blob/main/CONTRIBUTING.rst#pull-request-guidelines)** for more information. In case of fundamental code changes, an Airflow Improvement Proposal ([AIP](https://cwiki.apache.org/confluence/display/AIRFLOW/Airflow+Improvement+Proposals)) is needed. In case of a new dependency, check compliance with the [ASF 3rd Party License Policy](https://www.apache.org/legal/resolved.html#category-x). In case of backwards incompatible changes please leave a note in a newsfragment file, named `{pr_number}.significant.rst` or `{issue_number}.significant.rst`, in [newsfragments](https://github.com/apache/airflow/tree/main/newsfragments). Report URL: https://github.com/apache/airflow/actions/runs/3107042564 With regards, GitHub Actions via GitBox --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
