{"action":"created","issue":{"url":"https://api.github.com/repos/airbnb/airflow/issues/1225","repository_url":"https://api.github.com/repos/airbnb/airflow","labels_url":"https://api.github.com/repos/airbnb/airflow/issues/1225/labels{/name}","comments_url":"https://api.github.com/repos/airbnb/airflow/issues/1225/comments","events_url":"https://api.github.com/repos/airbnb/airflow/issues/1225/events","html_url":"https://github.com/airbnb/airflow/issues/1225","id":143824561,"number":1225,"title":"SubDag Operator broken when used with pools - infinite retry of tasks","user":{"login":"syvineckruyk","id":335167,"avatar_url":"https://avatars.githubusercontent.com/u/335167?v=3","gravatar_id":"","url":"https://api.github.com/users/syvineckruyk","html_url":"https://github.com/syvineckruyk","followers_url":"https://api.github.com/users/syvineckruyk/followers","following_url":"https://api.github.com/users/syvineckruyk/following{/other_user}","gists_url":"https://api.github.com/users/syvineckruyk/gists{/gist_id}","starred_url":"https://api.github.com/users/syvineckruyk/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/syvineckruyk/subscriptions","organizations_url":"https://api.github.com/users/syvineckruyk/orgs","repos_url":"https://api.github.com/users/syvineckruyk/repos","events_url":"https://api.github.com/users/syvineckruyk/events{/privacy}","received_events_url":"https://api.github.com/users/syvineckruyk/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/airbnb/airflow/labels/bug","name":"bug","color":"fc2929"}],"state":"open","locked":false,"assignee":{"login":"jlowin","id":153965,"avatar_url":"https://avatars.githubusercontent.com/u/153965?v=3","gravatar_id":"","url":"https://api.github.com/users/jlowin","html_url":"https://github.com/jlowin","followers_url":"https://api.github.com/users/jlowin/followers","following_url":"https://api.github.com/users/jlowin/following{/other_user}","gists_url":"https://api.github.com/users/jlowin/gists{/gist_id}","starred_url":"https://api.github.com/users/jlowin/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jlowin/subscriptions","organizations_url":"https://api.github.com/users/jlowin/orgs","repos_url":"https://api.github.com/users/jlowin/repos","events_url":"https://api.github.com/users/jlowin/events{/privacy}","received_events_url":"https://api.github.com/users/jlowin/received_events","type":"User","site_admin":false},"milestone":null,"comments":26,"created_at":"2016-03-27T16:18:02Z","updated_at":"2016-04-01T18:43:14Z","closed_at":null,"body":"Dear Airflow Maintainers,\r\n\r\nBefore I tell you about my issue, let me describe my environment:\r\n\r\n# Environment\r\nCentos 6\r\nCeleryExecutor (redis)\r\nTwo workers, 1 scheduler, 1 webserver\r\nMySql\r\n\r\n* Version of Airflow 1.6.2.10, 1.7.0rc1, HEAD\r\n\r\n* Example code to reproduce the bug (as a code snippet in markdown)\r\n```\r\nfrom datetime import datetime, timedelta\r\nfrom airflow.models import DAG\r\nfrom airflow.operators import BashOperator, SubDagOperator\r\n\r\n\r\n\r\ndag_name = 'test_18'\r\ntest_pool = 'test_pool'\r\nemail_to = 'your@email.com'\r\n\r\nnow = datetime.now()\r\nstart_time = datetime(now.year, now.month, now.day, 12, 0, 0)\r\nstart_time = start_time + timedelta(days=-1)\r\n\r\ndefault_args = {\r\n    'owner': 'Test',\r\n    'depends_on_past': True,\r\n    'start_date': start_time,\r\n    'email': [email_to],\r\n    'email_on_failure': True,\r\n    'email_on_retry': True,\r\n    'wait_for_downstream': False,\r\n}\r\n\r\n# Create the dag object\r\ndag = DAG(dag_name,\r\n          default_args=default_args,\r\n          schedule_interval='0 * * * *')\r\n\r\n\r\ndef get_subdag(dag, sd_id, pool=None):\r\n    subdag = DAG(\r\n        dag_id='{parent_dag}.{sd_id}'.format(\r\n            parent_dag=dag.dag_id,\r\n            sd_id=sd_id),\r\n        params=dag.params,\r\n        default_args=dag.default_args,\r\n        template_searchpath=dag.template_searchpath,\r\n        user_defined_macros=dag.user_defined_macros,\r\n    )\r\n\r\n    t1 = BashOperator(\r\n        task_id='test_task',\r\n        bash_command='echo \"hello\" && sleep 10',\r\n        dag=subdag,\r\n        pool=pool\r\n    )\r\n\r\n    t2 = BashOperator(\r\n        task_id='test_task_2_with_exit_1',\r\n        bash_command='echo \"hello\" && sleep 10 && exit 1',\r\n        dag=subdag,\r\n        pool=pool\r\n    )\r\n\r\n    t2.set_upstream(t1)\r\n\r\n    sdo = SubDagOperator(\r\n        task_id=sd_id,\r\n        subdag=subdag,\r\n        retries=2,\r\n        retry_delay=timedelta(seconds=30),\r\n        dag=dag,\r\n        depends_on_past=True,\r\n    )\r\n\r\n    return sdo\r\n\r\nsd1 = get_subdag(dag, sd_id='test_subdag')\r\nsd2 = get_subdag(dag, sd_id='test_subdag_with_pool', pool=test_pool)\r\n```\r\n\r\n\r\n* Screen shots of your DAG's graph and tree views:\r\n\r\n1. sub-task of non pooled subdag fails\r\n<img width=\"1440\" alt=\"af_issue_1\" src=\"https://cloud.githubusercontent.com/assets/335167/14066258/b40e237c-f3f9-11e5-83e4-416931a92d92.png\">\r\n\r\n2. subdag enters retry state\r\n<img width=\"1440\" alt=\"af_issue_2\" src=\"https://cloud.githubusercontent.com/assets/335167/14066262/c062e8b0-f3f9-11e5-80c9-ef1b09c27c31.png\">\r\n\r\n3. after all retries exhausted non pooled subdag fails\r\n<img width=\"1440\" alt=\"af_issue_6\" src=\"https://cloud.githubusercontent.com/assets/335167/14066269/e1142484-f3f9-11e5-8355-454e0f892f7e.png\">\r\n\r\n3. sub-task of pooled subdag fails\r\n<img width=\"1440\" alt=\"af_issue_3\" src=\"https://cloud.githubusercontent.com/assets/335167/14066263/d0251c8c-f3f9-11e5-9a32-7c92aeb50ced.png\">\r\n\r\n4. pooled subdag remains in running state, sub-task of pooled subdag enters queued state\r\n<img width=\"1440\" alt=\"af_issue_4\" src=\"https://cloud.githubusercontent.com/assets/335167/14066264/d5d88218-f3f9-11e5-9772-e16a9f71bac4.png\">\r\n\r\n5. sub-task of pooled subdag enters running state\r\n<img width=\"1440\" alt=\"af_issue_5\" src=\"https://cloud.githubusercontent.com/assets/335167/14066268/dbaa3b5a-f3f9-11e5-833a-df17e17235cd.png\">\r\n\r\n7. sub-task failures of pooled subdags generate email alerts for all failures\r\n<img width=\"1440\" alt=\"af_issue_7\" src=\"https://cloud.githubusercontent.com/assets/335167/14066271/e7c5a384-f3f9-11e5-9328-19bbffa7337f.png\">\r\n\r\n8. logs (from UI) also show observed behavior\r\n```\r\nId\tDttm\tDag Id \tTask Id\tEvent\tExecution Date\tOwner\tExtra\r\n1910\t03-27T15:37:36\ttest_18.test_subdag\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1911\t03-27T15:37:46\ttest_18.test_subdag\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1916\t03-27T15:39:18\ttest_18.test_subdag\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1918\t03-27T15:39:28\ttest_18.test_subdag\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1924\t03-27T15:41:18\ttest_18.test_subdag\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1930\t03-27T15:41:28\ttest_18.test_subdag\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1912\t03-27T15:37:54\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1914\t03-27T15:38:05\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1917\t03-27T15:39:23\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1920\t03-27T15:39:33\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1921\t03-27T15:40:54\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1922\t03-27T15:41:04\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1925\t03-27T15:41:26\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1926\t03-27T15:41:36\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1927\t03-27T15:41:52\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1928\t03-27T15:42:02\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1929\t03-27T15:42:18\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1931\t03-27T15:42:28\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1933\t03-27T15:43:52\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1934\t03-27T15:44:02\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1935\t03-27T15:44:30\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1936\t03-27T15:44:40\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1937\t03-27T15:44:56\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1938\t03-27T15:45:06\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1939\t03-27T15:46:35\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1940\t03-27T15:46:45\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1941\t03-27T15:47:42\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1942\t03-27T15:47:52\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n1943\t03-27T15:49:20\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\trunning\t03-26T12:00:00\tTest\t\r\n1944\t03-27T15:49:30\ttest_18.test_subdag_with_pool\ttest_task_2_with_exit_1\tfailed\t03-26T12:00:00\tTest\t\r\n...\r\n```\r\n* Operating System: (Windows Version or `$ uname -a`)\r\nLinux **** 2.6.32-431.29.2.el6.x86_64 #1 SMP Tue Sep 9 21:36:05 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux\r\n\r\n* Python Version: `$ python --version`\r\nPython 2.7.10\r\n\r\nNow that you know a little about me, let me tell you about the issue I am having:\r\n\r\n# Description of Issue\r\nWhen subdag operators are used with pools, sub-task failures are not \"bubbled\" up to the subdag operator. The contained failed task will retry indefinitely even when retries is set to 0.\r\n\r\nWhen a subtask failure occurs the subdag operator remains in the running state, the sub-task quickly enters a queued state, and shortly there after re-enters a running state.\r\n\r\n* What did you expect to happen?\r\n1. sub-task fails\r\n2. subdag operator enters retry state\r\n3. subdag operator enters running state when retry_delay has been met\r\n4. sub-tasks get queued\r\n5. sub-tasks enter running state\r\n\r\n* What happened instead?\r\n1. sub-task fails\r\n2. sub-task enters queued state\r\n3. sub-task runs\r\n4. rinse, repeat\r\n\r\n* Here is how you can reproduce this issue on your machine:\r\n## Reproduction Steps\r\n1. create a pool\r\n2. set the email and pool in included DAG code\r\n3. submit to your dags folder\r\n4. observe non pooled subdag handle failure as specified\r\n5. observe pooled subdag enter infinite loop\r\n\r\nThis behavior has been observed on multiple versions. I did the testing for submitting this issue on 1.7.0rc1.\r\n\r\nI also tested on HEAD 2016-03-26. The issue seems to get worst. The subdag which is not pooled (which works as expected on 1.7.0rc1) enters the retry state as it should ..  but then never re-enters a running state. Hanging indefinitely.\r\n"},"comment":{"url":"https://api.github.com/repos/airbnb/airflow/issues/comments/204511933","html_url":"https://github.com/airbnb/airflow/issues/1225#issuecomment-204511933","issue_url":"https://api.github.com/repos/airbnb/airflow/issues/1225","id":204511933,"user":{"login":"syvineckruyk","id":335167,"avatar_url":"https://avatars.githubusercontent.com/u/335167?v=3","gravatar_id":"","url":"https://api.github.com/users/syvineckruyk","html_url":"https://github.com/syvineckruyk","followers_url":"https://api.github.com/users/syvineckruyk/followers","following_url":"https://api.github.com/users/syvineckruyk/following{/other_user}","gists_url":"https://api.github.com/users/syvineckruyk/gists{/gist_id}","starred_url":"https://api.github.com/users/syvineckruyk/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/syvineckruyk/subscriptions","organizations_url":"https://api.github.com/users/syvineckruyk/orgs","repos_url":"https://api.github.com/users/syvineckruyk/repos","events_url":"https://api.github.com/users/syvineckruyk/events{/privacy}","received_events_url":"https://api.github.com/users/syvineckruyk/received_events","type":"User","site_admin":false},"created_at":"2016-04-01T18:43:14Z","updated_at":"2016-04-01T18:43:14Z","body":"@jlowin \r\nSo here are my observations based on your latest commits\r\n\r\nIn the subdag operator logs it appears that every task gets queued twice. Is it normal ?\r\n\r\nThe task instance logs looks fine.\r\n\r\n**Subdag operator log from worker 2 (no log on worker 1)**\r\n```\r\n[root@***02 ~]# cat /home/airflow/airflow/logs/test_35/test_subdag_with_pool/2016-03-28T00\\:00\\:00 \r\n[2016-04-01 18:21:00,748] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:00,748] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:00,811] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:21:00,811] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:21:01,968] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:01,968] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:02,006] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:21:02,006] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:21:02,024] {models.py:1087} INFO - \r\n--------------------------------------------------------------------------------\r\nStarting attempt 1 of 3\r\n--------------------------------------------------------------------------------\r\n\r\n[2016-04-01 18:21:02,044] {models.py:1110} INFO - Executing <Task(SubDagOperator): test_subdag_with_pool> on 2016-03-28 00:00:00\r\n[2016-04-01 18:21:02,089] {base_executor.py:35} INFO - Adding to queue: airflow run test_35.test_subdag_with_pool test_task 2016-03-28T00:00:00 --local --pool test_pool -sd DAGS_FOLDER/steven_test/main.py \r\n[2016-04-01 18:21:07,016] {celery_executor.py:67} INFO - [celery] queuing ('test_35.test_subdag_with_pool', 'test_task', datetime.datetime(2016, 3, 28, 0, 0)) through celery, queue=dc\r\n[2016-04-01 18:21:07,128] {jobs.py:942} INFO - [backfill progress] waiting: 2 | succeeded: 0 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:21:12,046] {jobs.py:942} INFO - [backfill progress] waiting: 2 | succeeded: 0 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:21:17,042] {jobs.py:942} INFO - [backfill progress] waiting: 2 | succeeded: 0 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:21:17,059] {base_executor.py:35} INFO - Adding to queue: airflow run test_35.test_subdag_with_pool test_task 2016-03-28T00:00:00 --local --pool test_pool -sd DAGS_FOLDER/steven_test/main.py \r\n[2016-04-01 18:21:22,015] {celery_executor.py:67} INFO - [celery] queuing ('test_35.test_subdag_with_pool', 'test_task', datetime.datetime(2016, 3, 28, 0, 0)) through celery, queue=dc\r\n[2016-04-01 18:21:22,023] {jobs.py:942} INFO - [backfill progress] waiting: 2 | succeeded: 0 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:21:27,101] {jobs.py:942} INFO - [backfill progress] waiting: 2 | succeeded: 0 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:21:32,077] {jobs.py:942} INFO - [backfill progress] waiting: 2 | succeeded: 0 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:21:32,107] {base_executor.py:35} INFO - Adding to queue: airflow run test_35.test_subdag_with_pool test_task_2_with_exit_1 2016-03-28T00:00:00 --local --pool test_pool -sd DAGS_FOLDER/steven_test/main.py \r\n[2016-04-01 18:21:37,086] {celery_executor.py:67} INFO - [celery] queuing ('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0)) through celery, queue=dc\r\n[2016-04-01 18:21:37,106] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 2 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:21:42,109] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 2 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:21:47,068] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 2 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:21:47,086] {base_executor.py:35} INFO - Adding to queue: airflow run test_35.test_subdag_with_pool test_task_2_with_exit_1 2016-03-28T00:00:00 --local --pool test_pool -sd DAGS_FOLDER/steven_test/main.py \r\n[2016-04-01 18:21:52,016] {celery_executor.py:67} INFO - [celery] queuing ('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0)) through celery, queue=dc\r\n[2016-04-01 18:21:52,026] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 2 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:21:57,055] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 2 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:22:02,074] {jobs.py:883} ERROR - Task instance ('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0)) failed\r\n[2016-04-01 18:22:02,074] {jobs.py:942} INFO - [backfill progress] waiting: 0 | succeeded: 1 | kicked_off: 2 | failed: 1 | wont_run: 0 \r\n[2016-04-01 18:22:02,075] {models.py:1175} ERROR - ------------------------------------------\r\nSome tasks instances failed, here's the list:\r\n[('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0))]\r\nTraceback (most recent call last):\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/models.py\", line 1136, in run\r\n    result = task_copy.execute(context=context)\r\n  File \"/home/airflow/.pyenv/versions/2.7.10/envs/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/operators/subdag_operator.py\", line 45, in execute\r\n    executor=self.executor)\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/models.py\", line 2729, in run\r\n    job.run()\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/jobs.py\", line 175, in run\r\n    self._execute()\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/jobs.py\", line 951, in _execute\r\n    raise AirflowException(msg)\r\nAirflowException: ------------------------------------------\r\nSome tasks instances failed, here's the list:\r\n[('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0))]\r\n[2016-04-01 18:22:02,076] {models.py:1187} INFO - Marking task as UP_FOR_RETRY\r\n[2016-04-01 18:22:02,098] {models.py:1216} ERROR - ------------------------------------------\r\nSome tasks instances failed, here's the list:\r\n[('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0))]\r\n[2016-04-01 18:22:18,834] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:18,834] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:18,877] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:22:18,877] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:22:20,021] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:20,021] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:20,071] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:22:20,071] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:22:20,087] {models.py:1087} INFO - \r\n--------------------------------------------------------------------------------\r\nStarting attempt 2 of 3\r\n--------------------------------------------------------------------------------\r\n\r\n[2016-04-01 18:22:20,105] {models.py:1110} INFO - Executing <Task(SubDagOperator): test_subdag_with_pool> on 2016-03-28 00:00:00\r\n[2016-04-01 18:22:20,143] {base_executor.py:35} INFO - Adding to queue: airflow run test_35.test_subdag_with_pool test_task_2_with_exit_1 2016-03-28T00:00:00 --local --pool test_pool -sd DAGS_FOLDER/steven_test/main.py \r\n[2016-04-01 18:22:25,014] {celery_executor.py:67} INFO - [celery] queuing ('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0)) through celery, queue=dc\r\n[2016-04-01 18:22:25,118] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:22:30,061] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:22:35,046] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:22:35,065] {base_executor.py:35} INFO - Adding to queue: airflow run test_35.test_subdag_with_pool test_task_2_with_exit_1 2016-03-28T00:00:00 --local --pool test_pool -sd DAGS_FOLDER/steven_test/main.py \r\n[2016-04-01 18:22:40,021] {celery_executor.py:67} INFO - [celery] queuing ('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0)) through celery, queue=dc\r\n[2016-04-01 18:22:40,033] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:22:45,061] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:22:50,062] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:22:55,066] {jobs.py:883} ERROR - Task instance ('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0)) failed\r\n[2016-04-01 18:22:55,072] {jobs.py:942} INFO - [backfill progress] waiting: 0 | succeeded: 1 | kicked_off: 1 | failed: 1 | wont_run: 0 \r\n[2016-04-01 18:22:55,072] {models.py:1175} ERROR - ------------------------------------------\r\nSome tasks instances failed, here's the list:\r\n[('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0))]\r\nTraceback (most recent call last):\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/models.py\", line 1136, in run\r\n    result = task_copy.execute(context=context)\r\n  File \"/home/airflow/.pyenv/versions/2.7.10/envs/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/operators/subdag_operator.py\", line 45, in execute\r\n    executor=self.executor)\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/models.py\", line 2729, in run\r\n    job.run()\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/jobs.py\", line 175, in run\r\n    self._execute()\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/jobs.py\", line 951, in _execute\r\n    raise AirflowException(msg)\r\nAirflowException: ------------------------------------------\r\nSome tasks instances failed, here's the list:\r\n[('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0))]\r\n[2016-04-01 18:22:55,073] {models.py:1187} INFO - Marking task as UP_FOR_RETRY\r\n[2016-04-01 18:22:55,087] {models.py:1216} ERROR - ------------------------------------------\r\nSome tasks instances failed, here's the list:\r\n[('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0))]\r\n[2016-04-01 18:23:10,900] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:10,900] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:10,964] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:23:10,964] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:23:12,115] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:12,116] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:12,157] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:23:12,157] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:23:12,174] {models.py:1087} INFO - \r\n--------------------------------------------------------------------------------\r\nStarting attempt 3 of 3\r\n--------------------------------------------------------------------------------\r\n\r\n[2016-04-01 18:23:12,189] {models.py:1110} INFO - Executing <Task(SubDagOperator): test_subdag_with_pool> on 2016-03-28 00:00:00\r\n[2016-04-01 18:23:12,229] {base_executor.py:35} INFO - Adding to queue: airflow run test_35.test_subdag_with_pool test_task_2_with_exit_1 2016-03-28T00:00:00 --local --pool test_pool -sd DAGS_FOLDER/steven_test/main.py \r\n[2016-04-01 18:23:17,013] {celery_executor.py:67} INFO - [celery] queuing ('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0)) through celery, queue=dc\r\n[2016-04-01 18:23:17,162] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:23:22,057] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:23:27,049] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:23:27,067] {base_executor.py:35} INFO - Adding to queue: airflow run test_35.test_subdag_with_pool test_task_2_with_exit_1 2016-03-28T00:00:00 --local --pool test_pool -sd DAGS_FOLDER/steven_test/main.py \r\n[2016-04-01 18:23:32,019] {celery_executor.py:67} INFO - [celery] queuing ('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0)) through celery, queue=dc\r\n[2016-04-01 18:23:32,027] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:23:37,052] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:23:42,067] {jobs.py:942} INFO - [backfill progress] waiting: 1 | succeeded: 1 | kicked_off: 1 | failed: 0 | wont_run: 0 \r\n[2016-04-01 18:23:47,079] {jobs.py:883} ERROR - Task instance ('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0)) failed\r\n[2016-04-01 18:23:47,079] {jobs.py:942} INFO - [backfill progress] waiting: 0 | succeeded: 1 | kicked_off: 1 | failed: 1 | wont_run: 0 \r\n[2016-04-01 18:23:47,079] {models.py:1175} ERROR - ------------------------------------------\r\nSome tasks instances failed, here's the list:\r\n[('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0))]\r\nTraceback (most recent call last):\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/models.py\", line 1136, in run\r\n    result = task_copy.execute(context=context)\r\n  File \"/home/airflow/.pyenv/versions/2.7.10/envs/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/operators/subdag_operator.py\", line 45, in execute\r\n    executor=self.executor)\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/models.py\", line 2729, in run\r\n    job.run()\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/jobs.py\", line 175, in run\r\n    self._execute()\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/jobs.py\", line 951, in _execute\r\n    raise AirflowException(msg)\r\nAirflowException: ------------------------------------------\r\nSome tasks instances failed, here's the list:\r\n[('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0))]\r\n[2016-04-01 18:23:47,081] {models.py:1193} INFO - All retries failed; marking task as FAILED\r\n[2016-04-01 18:23:47,101] {models.py:1216} ERROR - ------------------------------------------\r\nSome tasks instances failed, here's the list:\r\n[('test_35.test_subdag_with_pool', 'test_task_2_with_exit_1', datetime.datetime(2016, 3, 28, 0, 0))]\r\n```\r\n\r\n**Subtask log from worker 1**\r\n```\r\n[root@***01 ~]# cat /home/airflow/airflow/logs/test_35.test_subdag_with_pool/test_task_2_with_exit_1/2016-03-28T00\\:00\\:00 \r\n[2016-04-01 18:21:38,306] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:38,307] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:38,339] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:21:38,339] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:21:39,339] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:39,339] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:39,372] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:21:39,372] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:21:39,387] {models.py:1078} INFO - \r\n--------------------------------------------------------------------------------\r\nQueuing attempt 1 of 1\r\n--------------------------------------------------------------------------------\r\n\r\n[2016-04-01 18:21:39,397] {models.py:1083} INFO - Queuing into pool test_pool\r\n[2016-04-01 18:21:54,182] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:54,182] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:54,215] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:21:54,215] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:21:55,211] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:55,212] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:21:55,247] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:21:55,247] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:21:55,261] {models.py:1087} INFO - \r\n--------------------------------------------------------------------------------\r\nStarting attempt 1 of 1\r\n--------------------------------------------------------------------------------\r\n\r\n[2016-04-01 18:21:55,274] {models.py:1110} INFO - Executing <Task(BashOperator): test_task_2_with_exit_1> on 2016-03-28 00:00:00\r\n[2016-04-01 18:21:55,293] {bash_operator.py:55} INFO - tmp dir root location: \r\n/tmp\r\n[2016-04-01 18:21:55,295] {bash_operator.py:64} INFO - Temporary script location :/tmp/airflowtmphCzdRV//tmp/airflowtmphCzdRV/test_task_2_with_exit_1oD_rdc\r\n[2016-04-01 18:21:55,295] {bash_operator.py:65} INFO - Running command: echo \"hello\" && sleep 0.2 && exit 1\r\n[2016-04-01 18:21:55,298] {bash_operator.py:73} INFO - Output:\r\n[2016-04-01 18:21:55,299] {bash_operator.py:77} INFO - hello\r\n[2016-04-01 18:21:55,501] {bash_operator.py:80} INFO - Command exited with return code 1\r\n[2016-04-01 18:21:55,502] {models.py:1175} ERROR - Bash command failed\r\nTraceback (most recent call last):\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/models.py\", line 1136, in run\r\n    result = task_copy.execute(context=context)\r\n  File \"/home/airflow/.pyenv/versions/2.7.10/envs/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/operators/bash_operator.py\", line 83, in execute\r\n    raise AirflowException(\"Bash command failed\")\r\nAirflowException: Bash command failed\r\n[2016-04-01 18:21:55,503] {models.py:1195} INFO - Marking task as FAILED.\r\n[2016-04-01 18:21:55,516] {models.py:1216} ERROR - Bash command failed\r\n```\r\n\r\n**Subtask log from worker 2**\r\n\r\n```\r\n[root@usw2dcdpag02 ~]# cat /home/airflow/airflow/logs/test_35.test_subdag_with_pool/test_task_2_with_exit_1/2016-03-28T00\\:00\\:00 \r\n[2016-04-01 18:22:29,202] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:29,202] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:29,264] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:22:29,264] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:22:30,440] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:30,440] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:30,477] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:22:30,477] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:22:30,496] {models.py:1078} INFO - \r\n--------------------------------------------------------------------------------\r\nQueuing attempt 1 of 1\r\n--------------------------------------------------------------------------------\r\n\r\n[2016-04-01 18:22:30,507] {models.py:1083} INFO - Queuing into pool test_pool\r\n[2016-04-01 18:22:44,889] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:44,889] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:44,954] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:22:44,954] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:22:46,122] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:46,122] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:22:46,162] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:22:46,162] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:22:46,178] {models.py:1087} INFO - \r\n--------------------------------------------------------------------------------\r\nStarting attempt 1 of 1\r\n--------------------------------------------------------------------------------\r\n\r\n[2016-04-01 18:22:46,193] {models.py:1110} INFO - Executing <Task(BashOperator): test_task_2_with_exit_1> on 2016-03-28 00:00:00\r\n[2016-04-01 18:22:46,210] {bash_operator.py:55} INFO - tmp dir root location: \r\n/tmp\r\n[2016-04-01 18:22:46,211] {bash_operator.py:64} INFO - Temporary script location :/tmp/airflowtmpAafXtN//tmp/airflowtmpAafXtN/test_task_2_with_exit_1QMBYdK\r\n[2016-04-01 18:22:46,211] {bash_operator.py:65} INFO - Running command: echo \"hello\" && sleep 0.2 && exit 1\r\n[2016-04-01 18:22:46,215] {bash_operator.py:73} INFO - Output:\r\n[2016-04-01 18:22:46,216] {bash_operator.py:77} INFO - hello\r\n[2016-04-01 18:22:46,417] {bash_operator.py:80} INFO - Command exited with return code 1\r\n[2016-04-01 18:22:46,417] {models.py:1175} ERROR - Bash command failed\r\nTraceback (most recent call last):\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/models.py\", line 1136, in run\r\n    result = task_copy.execute(context=context)\r\n  File \"/home/airflow/.pyenv/versions/2.7.10/envs/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/operators/bash_operator.py\", line 83, in execute\r\n    raise AirflowException(\"Bash command failed\")\r\nAirflowException: Bash command failed\r\n[2016-04-01 18:22:46,419] {models.py:1195} INFO - Marking task as FAILED.\r\n[2016-04-01 18:22:46,434] {models.py:1216} ERROR - Bash command failed\r\n[2016-04-01 18:23:21,401] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:21,401] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:21,491] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:23:21,491] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:23:22,643] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:22,643] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:22,686] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:23:22,687] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:23:22,705] {models.py:1078} INFO - \r\n--------------------------------------------------------------------------------\r\nQueuing attempt 1 of 1\r\n--------------------------------------------------------------------------------\r\n\r\n[2016-04-01 18:23:22,716] {models.py:1083} INFO - Queuing into pool test_pool\r\n[2016-04-01 18:23:37,244] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:37,244] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:37,280] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:23:37,280] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:23:38,435] {models.py:147} INFO - Filling up the DagBag from /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:38,436] {models.py:225} INFO - Importing /home/airflow/airflow/dags/steven_test/main.py\r\n[2016-04-01 18:23:38,474] {models.py:317} INFO - Loaded DAG <DAG: test_35.test_subdag_with_pool>\r\n[2016-04-01 18:23:38,474] {models.py:317} INFO - Loaded DAG <DAG: test_35>\r\n[2016-04-01 18:23:38,490] {models.py:1087} INFO - \r\n--------------------------------------------------------------------------------\r\nStarting attempt 1 of 1\r\n--------------------------------------------------------------------------------\r\n\r\n[2016-04-01 18:23:38,505] {models.py:1110} INFO - Executing <Task(BashOperator): test_task_2_with_exit_1> on 2016-03-28 00:00:00\r\n[2016-04-01 18:23:38,524] {bash_operator.py:55} INFO - tmp dir root location: \r\n/tmp\r\n[2016-04-01 18:23:38,525] {bash_operator.py:64} INFO - Temporary script location :/tmp/airflowtmpnU0bjL//tmp/airflowtmpnU0bjL/test_task_2_with_exit_1kAx8gd\r\n[2016-04-01 18:23:38,525] {bash_operator.py:65} INFO - Running command: echo \"hello\" && sleep 0.2 && exit 1\r\n[2016-04-01 18:23:38,529] {bash_operator.py:73} INFO - Output:\r\n[2016-04-01 18:23:38,530] {bash_operator.py:77} INFO - hello\r\n[2016-04-01 18:23:38,732] {bash_operator.py:80} INFO - Command exited with return code 1\r\n[2016-04-01 18:23:38,732] {models.py:1175} ERROR - Bash command failed\r\nTraceback (most recent call last):\r\n  File \"/home/airflow/.pyenv/versions/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/models.py\", line 1136, in run\r\n    result = task_copy.execute(context=context)\r\n  File \"/home/airflow/.pyenv/versions/2.7.10/envs/airflow/lib/python2.7/site-packages/airflow-1.6.2-py2.7.egg/airflow/operators/bash_operator.py\", line 83, in execute\r\n    raise AirflowException(\"Bash command failed\")\r\nAirflowException: Bash command failed\r\n[2016-04-01 18:23:38,733] {models.py:1195} INFO - Marking task as FAILED.\r\n[2016-04-01 18:23:38,748] {models.py:1216} ERROR - Bash command failed\r\n```"}}