You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by GitBox <gi...@apache.org> on 2022/10/12 11:58:34 UTC
[GitHub] [airflow] juraa14 opened a new issue, #27012: External python operator logging
juraa14 opened a new issue, #27012:
URL: https://github.com/apache/airflow/issues/27012
### Apache Airflow version
2.4.1
### What happened
When using the external python operator for running tasks inside a different environment, logs do not appear for the task instance.
The log files are always empty if the task is successful.
If the task fails, one gets very rudimentary logs about the process command failing.
Both environments use the same Python version (3.9.10) and Airflow uses Celery executor
### What you think should happen instead
The External Operator is great for cases where you might have multiple environments that require other packages and versions, so they don't mix up with the airflow environment and so other teams could potentially use their own environments inside DAGs. Unfortunately, the External Python Operator does not provide any meaningful logs when the task fails or succeeds.
An example of a successful task without logs:
In case a task fails, the following log will appear (regardless of the actual error):
```[2022-10-12, 11:23:05 CEST] {taskinstance.py:1851} ERROR - Task failed with exception
Traceback (most recent call last):
File "/usr/local/airflow_env/lib/python3.9/site-packages/airflow/decorators/base.py", line 188, in execute
return_value = super().execute(context)
File "/usr/local/airflow_env/lib/python3.9/site-packages/airflow/operators/python.py", line 370, in execute
return super().execute(context=serializable_context)
File "/usr/local/airflow_env/lib/python3.9/site-packages/airflow/operators/python.py", line 175, in execute
return_value = self.execute_callable()
File "/usr/local/airflow_env/lib/python3.9/site-packages/airflow/operators/python.py", line 678, in execute_callable
return self._execute_python_callable_in_subprocess(python_path, tmp_path)
File "/usr/local/airflow_env/lib/python3.9/site-packages/airflow/operators/python.py", line 426, in _execute_python_callable_in_subprocess
execute_in_subprocess(
File "/usr/local/airflow_env/lib/python3.9/site-packages/airflow/utils/process_utils.py", line 168, in execute_in_subprocess
execute_in_subprocess_with_kwargs(cmd, cwd=cwd)
File "/usr/local/airflow_env/lib/python3.9/site-packages/airflow/utils/process_utils.py", line 191, in execute_in_subprocess_with_kwargs
raise subprocess.CalledProcessError(exit_code, cmd)
subprocess.CalledProcessError: Command '['/usr/local/aiops_env/bin/python', '/tmp/tmdclodljc4/script.py', '/tmp/tmdclodljc4/script.in', '/tmp/tmdclodljc4/script.out', '/tmp/tmdclodljc4/string_args.txt']' returned non-zero exit status 1.
[2022-10-12, 11:23:05 CEST] {standard_task_runner.py:102} ERROR - Failed to execute job 1976894 for task external_python_pipeline (Command '['/usr/local/aiops_env/bin/python', '/tmp/tmdclodljc4/script.py', '/tmp/tmdclodljc4/script.in', '/tmp/tmdclodljc4/script.out', '/tmp/tmdclodljc4/string_args.txt']' returned non-zero exit status 1.; 23728)```
### How to reproduce
Using celery executor, so the task is ran on another machine. Simply run a DAG that uses the External Python Operator. A simple hello world will reproduce the issue
### Operating System
CentOS 7
### Versions of Apache Airflow Providers
apache-airflow-providers-celery==3.0.0
apache-airflow-providers-common-sql==1.2.0
apache-airflow-providers-ftp==3.1.0
apache-airflow-providers-http==4.0.0
apache-airflow-providers-imap==3.0.0
apache-airflow-providers-postgres==5.2.2
### Deployment
Virtualenv installation
### Deployment details
_No response_
### Anything else
I have not yet gone into the details, but am willing to contribute!
### Are you willing to submit PR?
- [X] Yes I am willing to submit a PR!
### Code of Conduct
- [X] I agree to follow this project's [Code of Conduct](https://github.com/apache/airflow/blob/main/CODE_OF_CONDUCT.md)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] pierrejeambrun commented on issue #27012: External python operator logging
Posted by GitBox <gi...@apache.org>.
pierrejeambrun commented on issue #27012:
URL: https://github.com/apache/airflow/issues/27012#issuecomment-1279712362
@juraa14 Thank you for being willing to help on this one.
I just assigned you :)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] External python operator logging [airflow]
Posted by "potiuk (via GitHub)" <gi...@apache.org>.
potiuk commented on issue #27012:
URL: https://github.com/apache/airflow/issues/27012#issuecomment-3092377175
> I'm surprised that there is no common handler to pretty parse the logs of the subprocess output at this time.
You can always contribute one. This is how things work here - there are more than 3300 contributors here - many of them contributed something they needed. I am actually quite surprised you have not done it yet @Docdez
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] juraa14 commented on issue #27012: External python operator logging
Posted by GitBox <gi...@apache.org>.
juraa14 commented on issue #27012:
URL: https://github.com/apache/airflow/issues/27012#issuecomment-1385084998
No, we can only capture the STDOUT and STDERR output from a subprocess and the comment above shows that, but we cannot control the way subprocesses work in Python.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] External python operator logging [airflow]
Posted by "Docdez (via GitHub)" <gi...@apache.org>.
Docdez commented on issue #27012:
URL: https://github.com/apache/airflow/issues/27012#issuecomment-3089367742
I'm surprised that there is no common handler to pretty parse the logs of the subprocess output at this time.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] potiuk commented on issue #27012: External python operator logging
Posted by GitBox <gi...@apache.org>.
potiuk commented on issue #27012:
URL: https://github.com/apache/airflow/issues/27012#issuecomment-1384609843
Are there any actions form that?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] juraa14 commented on issue #27012: External python operator logging
Posted by GitBox <gi...@apache.org>.
juraa14 commented on issue #27012:
URL: https://github.com/apache/airflow/issues/27012#issuecomment-1361342168
Been a while
I've looked into the issue a little bit to find out what is happening.
Long story short: the task is run using python's _subprocess_ module. It uses _Popen_ which executes a child program in a new process. Now, we can capture STDOUT and STDERR from such a subprocess and output that once the program is finished. So I'll explain what is happening first inside the operator:
```
with subprocess.Popen(
cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, bufsize=0, close_fds=True, **kwargs
) as proc:
log.info("Output:")
if proc.stdout:
with proc.stdout:
for line in iter(proc.stdout.readline, b""):
log.info("%s", line.decode().rstrip())
exit_code = proc.wait()
if exit_code != 0:
raise subprocess.CalledProcessError(exit_code, cmd)
```
The external task is run using _subprocess.Popen_ and all the output is logged at INFO level. If your Airflow logging level is set to WARNING or higher, you will not see the output of the subprocess. So using _print()_ and _return_ statements will output to Airflow logging at INFO level.
You can also output other logs by using `handler = logging.StreamHandler(sys.stdout)` and then all logs are output to stdout.
Here is a sample DAG that output using _print_, _logging_ and _return_:
```
from datetime import datetime
from airflow.decorators import dag, task
from airflow.operators.empty import EmptyOperator
@dag(dag_id="test_external_op_py_logging",
schedule=None,
description="Testing external python logging",
catchup=False,
start_date=datetime(2021, 1, 1),
max_active_runs=1,
tags=["TEST"])
def test():
start = EmptyOperator(
task_id="start"
)
@task.external_python(task_id="external_op", python="/path/to/python/bin/python")
def test_logging():
import pandas as pd
import logging
import sys
root_logger = logging.getLogger()
handler = logging.StreamHandler(sys.stdout)
root_logger.addHandler(handler)
print("PRNT:starting task")
logging.info("LOG:starting task")
ret_str = "RET:starting task\n"
data = {"id": [1, 2],
"name": ["Arnold", "Schwarzenegger"]
}
df = pd.DataFrame(data)
print("PRNT: " + df.to_string())
logging.debug("LOG: " + df.to_string())
logging.error("LOG_ERROR: " + df.to_string())
ret_str += "RET_ " + df.to_string() + "\n"
return ret_str
end = EmptyOperator(
task_id="end"
)
start >> test_logging() >> end
dag = test()
```
This DAG outputs the following:
```
[2022-12-14, 14:50:29 UTC] {python.py:711} WARNING - When checking for Airflow installed in venv got The version of Airflow installed for the /dataregistry/CROZ/AI/aiops_env/bin/python(2.4.1) is different than the runtime Airflow version: 2.5.0. Make sure your environment has the same Airflow version installed as the Airflow runtime.
[2022-12-14, 14:50:29 UTC] {python.py:712} WARNING - This means that Airflow is not properly installed by /dataregistry/CROZ/AI/aiops_env/bin/python. Airflow context keys will not be available. Please Install Airflow 2.5.0 in your environment to access them.
[2022-12-14, 14:50:29 UTC] {process_utils.py:179} INFO - Executing cmd: /dataregistry/CROZ/AI/aiops_env/bin/python /tmp/tmdyokq8x9g/script.py /tmp/tmdyokq8x9g/script.in /tmp/tmdyokq8x9g/script.out /tmp/tmdyokq8x9g/string_args.txt
[2022-12-14, 14:50:29 UTC] {process_utils.py:183} INFO - Output:
[2022-12-14, 14:50:30 UTC] {process_utils.py:187} INFO - [[34m2022-12-14 15:50:30,333[0m] {[34mstats.py:[0m349} ERROR[0m - Could not configure StatsClient: No module named 'statsd', using DummyStatsLogger instead.[0m
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - PRNT:starting task
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - [[34m2022-12-14 15:50:31,363[0m] {[34mscript.py:[0m36} INFO[0m - LOG:starting task[0m
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - LOG:starting task
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - PRNT: id name
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - 0 1 Arnold
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - 1 2 Schwarzenegger
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - [[34m2022-12-14 15:50:31,370[0m] {[34mscript.py:[0m47} ERROR[0m - LOG_ERROR: id name
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - 0 1 Arnold
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - 1 2 Schwarzenegger[0m
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - LOG_ERROR: id name
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - 0 1 Arnold
[2022-12-14, 14:50:31 UTC] {process_utils.py:187} INFO - 1 2 Schwarzenegger
[2022-12-14, 14:50:31 UTC] {python.py:177} INFO - Done. Returned value was: RET:starting task
RET_ id name
0 1 Arnold
1 2 Schwarzenegger
```
The logs are pretty ugly and there are some encoding issues using _logger_, but it seems to be sort of a hack around this. Changing this would require changes in the subprocess module, which I guess wouldn't be possible
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] juraa14 closed issue #27012: External python operator logging
Posted by GitBox <gi...@apache.org>.
juraa14 closed issue #27012: External python operator logging
URL: https://github.com/apache/airflow/issues/27012
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] potiuk commented on issue #27012: External python operator logging
Posted by GitBox <gi...@apache.org>.
potiuk commented on issue #27012:
URL: https://github.com/apache/airflow/issues/27012#issuecomment-1385086718
So should we close it ? Is that the suggestion?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] potiuk commented on issue #27012: External python operator logging
Posted by GitBox <gi...@apache.org>.
potiuk commented on issue #27012:
URL: https://github.com/apache/airflow/issues/27012#issuecomment-1385089444
(asking because you are the author - I would simply close it).
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] boring-cyborg[bot] commented on issue #27012: External python operator logging
Posted by GitBox <gi...@apache.org>.
boring-cyborg[bot] commented on issue #27012:
URL: https://github.com/apache/airflow/issues/27012#issuecomment-1276042846
Thanks for opening your first issue here! Be sure to follow the issue template!
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] potiuk commented on issue #27012: External python operator logging
Posted by GitBox <gi...@apache.org>.
potiuk commented on issue #27012:
URL: https://github.com/apache/airflow/issues/27012#issuecomment-1288293746
And that should also fix the same case for Python Virtualenv Operator (which should have the same problem).
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org