casper-voltgoed opened a new issue, #31155:
URL: https://github.com/apache/airflow/issues/31155
### Apache Airflow version
2.6.0
### What happened
When adding a StreamHandler to a logger, logging keeps printing the same
message and eventually `RecursionError: maximum recursion depth exceeded` is
shown.
```
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} INFO - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - test
[2023-05-09, 09:50:38 CEST] {taskinstance.py:1847} ERROR - Task failed with
exception
Traceback (most recent call last):
File
"/usr/local/lib/python3.10/site-packages/airflow/operators/python.py", line
181, in execute
return_value = self.execute_callable()
File
"/usr/local/lib/python3.10/site-packages/airflow/operators/python.py", line
198, in execute_callable
return self.python_callable(*self.op_args, **self.op_kwargs)
File "/usr/local/airflow/dags/inf_recursion.py", line 14, in inf_printing
print("test")
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 161, in write
self.flush()
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 168, in flush
self._propagate_log(buf)
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 149, in _propagate_log
self.logger.log(self.level, remove_escape_codes(message))
File "/usr/local/lib/python3.10/logging/__init__.py", line 1547, in log
self._log(level, msg, args, **kwargs)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1624, in _log
self.handle(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1634, in handle
self.callHandlers(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1696, in
callHandlers
hdlr.handle(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 968, in handle
self.emit(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1103, in emit
stream.write(msg + self.terminator)
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 161, in write
self.flush()
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 168, in flush
self._propagate_log(buf)
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 149, in _propagate_log
self.logger.log(self.level, remove_escape_codes(message))
File "/usr/local/lib/python3.10/logging/__init__.py", line 1547, in log
self._log(level, msg, args, **kwargs)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1624, in _log
self.handle(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1634, in handle
self.callHandlers(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1696, in
callHandlers
hdlr.handle(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 968, in handle
self.emit(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1103, in emit
stream.write(msg + self.terminator)
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 161, in write
self.flush()
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 168, in flush
self._propagate_log(buf)
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 149, in _propagate_log
self.logger.log(self.level, remove_escape_codes(message))
File "/usr/local/lib/python3.10/logging/__init__.py", line 1547, in log
self._log(level, msg, args, **kwargs)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1624, in _log
self.handle(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1634, in handle
self.callHandlers(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1696, in
callHandlers
hdlr.handle(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 968, in handle
self.emit(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1103, in emit
stream.write(msg + self.terminator)
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 161, in write
self.flush()
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 168, in flush
self._propagate_log(buf)
```
When adding a StreamHandler and adding a custom format to that
StreamHandler, logging infinitely loops + appends messages to each other.
```
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} INFO - test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom test
[2023-05-09, 09:50:38 CEST] {logging_mixin.py:149} WARNING - something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom something custom something custom something custom something custom
something custom something custom something custom something custom something
custom test
```
also throws after these log messages the same errors as above, I left out
most of the log messages as it just clutters the text:
```
File "/usr/local/lib/python3.10/site-packages/airflow/operators/python.py",
line 181, in execute
return_value = self.execute_callable()
File
"/usr/local/lib/python3.10/site-packages/airflow/operators/python.py", line
198, in execute_callable
return self.python_callable(*self.op_args, **self.op_kwargs)
File "/usr/local/airflow/dags/inf_recursion.py", line 36, in
inf_recursiong_printing
print("test")
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 161, in write
self.flush()
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 168, in flush
self._propagate_log(buf)
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 149, in _propagate_log
self.logger.log(self.level, remove_escape_codes(message))
File "/usr/local/lib/python3.10/logging/__init__.py", line 1547, in log
self._log(level, msg, args, **kwargs)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1624, in _log
self.handle(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1634, in handle
self.callHandlers(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1696, in
callHandlers
hdlr.handle(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 968, in handle
self.emit(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1103, in emit
stream.write(msg + self.terminator)
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 161, in write
self.flush()
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 168, in flush
self._propagate_log(buf)
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 149, in _propagate_log
self.logger.log(self.level, remove_escape_codes(message))
File "/usr/local/lib/python3.10/logging/__init__.py", line 1547, in log
self._log(level, msg, args, **kwargs)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1624, in _log
self.handle(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1634, in handle
self.callHandlers(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1696, in
callHandlers
hdlr.handle(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 968, in handle
self.emit(record)
File "/usr/local/lib/python3.10/logging/__init__.py", line 1103, in emit
stream.write(msg + self.terminator)
File
"/usr/local/lib/python3.10/site-packages/airflow/utils/log/logging_mixin.py",
line 161, in write
self.flush()
```
### What you think should happen instead
For one print/logging statement, only one log message should be added in the
logs.
### How to reproduce
Have the following code:
```
import pytz
from datetime import datetime
from airflow.operators.python import PythonOperator
from airflow import DAG
local_time_zone_name = "UTC"
local_timezone = pytz.timezone(local_time_zone_name)
def inf_printing():
import logging
# create logger with
test_logger = logging.getLogger()
# add streamhandler
test_logger.addHandler(logging.StreamHandler())
print("test")
print("another")
def inf_recursiong_printing():
import logging
class CustomFormatter(logging.Formatter):
def format(self, record):
custom_format = "something custom %(message)s"
formatter = logging.Formatter(custom_format, "%y/%m/%d %H:%M:%S")
return formatter.format(record)
# create voltgoed_logger with
test_logger = logging.getLogger()
# create console handler with a higher log level
console_handler = logging.StreamHandler()
console_handler.setFormatter(CustomFormatter())
test_logger.addHandler(console_handler)
print("test")
print("another")
with DAG(dag_id="infinite_recursion",
start_date=local_timezone.localize(datetime(year=2023, month=5,
day=4, hour=9, minute=30)),
) as dag:
PythonOperator(
task_id=inf_printing.__name__,
python_callable=inf_printing
)
PythonOperator(
task_id=inf_recursiong_printing.__name__,
python_callable=inf_recursiong_printing
)
globals()[dag.dag_id] = dag
```
Then start up airflow and run the dag, both tasks should fail and produce
the logs as shown above.
### Operating System
Docker containers run in Debian 10
### Versions of Apache Airflow Providers
_No response_
### Deployment
Astronomer
### Deployment details
I use Astronomer 8.0.0
### Anything else
The reason I have this problem is that I import another file that uses a
custom logger, that is why I can't easily dodge this problem. I found that when
it is imported at the top of the file instead of inside the function, the bug
does not occur. Of course importing at the top of the file is not desirable, as
said by Airflow documentation. So leavint out the custom logger is not a
solution. The way I found to solve this now is to loop over the handlers of the
logger and remove any StreamHandlers. like so:
### Are you willing to submit PR?
- [ ] 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: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
