You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by "hterik (via GitHub)" <gi...@apache.org> on 2023/09/11 10:35:14 UTC
[GitHub] [airflow] hterik opened a new issue, #31810: Improve log messages of heartbeat connection errors and recovery
hterik opened a new issue, #31810:
URL: https://github.com/apache/airflow/issues/31810
### Description
Occasionally when running a task (with CeleryExecutor), the log produces following error and then the task continues executing to completion without any problem:
```
2023-05-31 18:52:16 E/LocalTaskJob LocalTaskJob heartbeat got an exception exc_info=Traceback (most recent call last):
File "sqlalchemy/engine/base.py", line 3361, in _wrap_pool_connect
return fn()
File "sqlalchemy/pool/base.py", line 325, in connect
return _ConnectionFairy._checkout(self)
File "sqlalchemy/pool/base.py", line 888, in _checkout
fairy = _ConnectionRecord.checkout(pool)
File "sqlalchemy/pool/base.py", line 491, in checkout
rec = pool._do_get()
File "sqlalchemy/pool/impl.py", line 256, in _do_get
return self._create_connection()
File "sqlalchemy/pool/base.py", line 271, in _create_connection
return _ConnectionRecord(self)
File "sqlalchemy/pool/base.py", line 386, in __init__
self.__connect()
File "sqlalchemy/pool/base.py", line 684, in __connect
with util.safe_reraise():
File "sqlalchemy/util/langhelpers.py", line 70, in __exit__
compat.raise_(
File "sqlalchemy/util/compat.py", line 210, in raise_
raise exception
File "sqlalchemy/pool/base.py", line 680, in __connect
self.dbapi_connection = connection = pool._invoke_creator(self)
File "sqlalchemy/engine/create.py", line 578, in connect
return dialect.connect(*cargs, **cparams)
File "sqlalchemy/engine/default.py", line 598, in connect
return self.dbapi.connect(*cargs, **cparams)
File "psycopg2/__init__.py", line 122, in connect
conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
psycopg2.OperationalError: connection to server at "xxxxxx" (xxxxxxxx), port 5432 failed: SSL SYSCALL error: EOF detected
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "airflow/jobs/base_job.py", line 204, in heartbeat
session.merge(self)
File "sqlalchemy/orm/session.py", line 3051, in merge
return self._merge(
File "sqlalchemy/orm/session.py", line 3131, in _merge
merged = self.get(
File "sqlalchemy/orm/session.py", line 2848, in get
return self._get_impl(
File "sqlalchemy/orm/session.py", line 2970, in _get_impl
return db_load_fn(
File "sqlalchemy/orm/loading.py", line 530, in load_on_pk_identity
session.execute(
File "sqlalchemy/orm/session.py", line 1713, in execute
conn = self._connection_for_bind(bind)
File "sqlalchemy/orm/session.py", line 1552, in _connection_for_bind
return self._transaction._connection_for_bind(
File "sqlalchemy/orm/session.py", line 747, in _connection_for_bind
conn = bind.connect()
File "sqlalchemy/engine/base.py", line 3315, in connect
return self._connection_cls(self, close_with_result=close_with_result)
File "sqlalchemy/engine/base.py", line 96, in __init__
else engine.raw_connection()
File "sqlalchemy/engine/base.py", line 3394, in raw_connection
return self._wrap_pool_connect(self.pool.connect, _connection)
File "sqlalchemy/engine/base.py", line 3364, in _wrap_pool_connect
Connection._handle_dbapi_exception_noconnection(
File "sqlalchemy/engine/base.py", line 2198, in _handle_dbapi_exception_noconnection
util.raise_(
File "sqlalchemy/util/compat.py", line 210, in raise_
raise exception
File "sqlalchemy/engine/base.py", line 3361, in _wrap_pool_connect
return fn()
File "sqlalchemy/pool/base.py", line 325, in connect
return _ConnectionFairy._checkout(self)
File "sqlalchemy/pool/base.py", line 888, in _checkout
fairy = _ConnectionRecord.checkout(pool)
File "sqlalchemy/pool/base.py", line 491, in checkout
rec = pool._do_get()
File "sqlalchemy/pool/impl.py", line 256, in _do_get
return self._create_connection()
File "sqlalchemy/pool/base.py", line 271, in _create_connection
return _ConnectionRecord(self)
File "sqlalchemy/pool/base.py", line 386, in __init__
self.__connect()
File "sqlalchemy/pool/base.py", line 684, in __connect
with util.safe_reraise():
File "sqlalchemy/util/langhelpers.py", line 70, in __exit__
compat.raise_(
File "sqlalchemy/util/compat.py", line 210, in raise_
raise exception
File "sqlalchemy/pool/base.py", line 680, in __connect
self.dbapi_connection = connection = pool._invoke_creator(self)
File "sqlalchemy/engine/create.py", line 578, in connect
return dialect.connect(*cargs, **cparams)
File "sqlalchemy/engine/default.py", line 598, in connect
return self.dbapi.connect(*cargs, **cparams)
File "psycopg2/__init__.py", line 122, in connect
conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
sqlalchemy.exc.OperationalError: (psycopg2.OperationalError) connection to server at "xxxxxxx" (xxxxxxx), port 5432 failed: SSL SYSCALL error: EOF detected
(Background on this error at: https://sqlalche.me/e/14/e3q8)
```
(Above is from Airflow 2.5.0)
### Use case/motivation
Users are "trained" to scan for stacktraces in log files and think this is may be cause of the DAG failing, when it in fact is just a transient error that got recovered on next hearbeat. Leading to lots of unnecessary support activities and explanations that this error can often be ignored.
A few suggestions that would help:
**A:** Don't log the whole stack trace, instead just log this as an error message.
**B:** Include a descriptive message of the consequence of this error in the log.
**C:** When heartbeat recovers, log it.
**D:** If heartbeat was recovered after `scheduler_health_check_threshold,` log another more severe error message including descriptive message of the consequences.
### Related issues
-
### Are you willing to submit a 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: commits-unsubscribe@airflow.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] Bowrna commented on issue #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "Bowrna (via GitHub)" <gi...@apache.org>.
Bowrna commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1586246942
I could pick it up if its ok for you @hterik
--
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] hterik commented on issue #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "hterik (via GitHub)" <gi...@apache.org>.
hterik commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1586716564
> I could pick it up if its ok for you @hterik
Please, feel free :slightly_smiling_face:
--
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] Improve log messages of heartbeat connection errors and recovery [airflow]
Posted by "potiuk (via GitHub)" <gi...@apache.org>.
potiuk closed issue #31810: Improve log messages of heartbeat connection errors and recovery
URL: https://github.com/apache/airflow/issues/31810
--
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] amolsr commented on issue #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "amolsr (via GitHub)" <gi...@apache.org>.
amolsr commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1590984836
we are also facing this in LocalExecutor configuration.
--
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 closed issue #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "potiuk (via GitHub)" <gi...@apache.org>.
potiuk closed issue #31810: Improve log messages of heartbeat connection errors and recovery
URL: https://github.com/apache/airflow/issues/31810
--
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] hterik commented on issue #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "hterik (via GitHub)" <gi...@apache.org>.
hterik commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1711097820
Sorry, I'm a bit unsure if #34160 really closes this completely. It touches suggestion A above, which is good, but i think one or all of B,C,D are also needed.
In fact i think the change makes the log message even more confusing than before. By saying "_Scheduler is in unhealthy state_", when the error is most of the time caused by **Executor** not having connection to the database, this is going to mislead people into debugging **scheduler**-issues, instead of connectivity issues.
I think its important operators can understand and act on log messages, without having intricate knowledge of the airflow internals.
I may give this a another go myself but quite busy with other things so don't want to promise anything.
--
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 #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "potiuk (via GitHub)" <gi...@apache.org>.
potiuk commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1713617847
I think it's difficult to give clear instructions on what to do in this case :(. We just know that
a) some warning occurs intermittently (because for example DB connection was flaky) and it might go away if it happens rarely - then likely we do not have to do much
b) when eventually scheduler goes down, we will see a trace of those intermittent errors
I am not sure if we can do much more and give more descriptive message as it is hard to guess the root cause and possible remediations from just DBAPI failure. But I will reopen it as "partially fixed" and maybe you could come up with some better diagnostics ?
--
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 #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "potiuk (via GitHub)" <gi...@apache.org>.
potiuk commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1715646466
I think you are quite right. The message **should** depend on which JobRunner runs the heartbeat:
* LocalTaskJobRunner, SchedulerJobRunner, TriggerJob Runner, DagProcessorJobRunner should likely produce a different set of messages.
I was focusing on SchedulerJobRunner only, but the other cases should produce different set of messages.
--
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] hterik commented on issue #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "hterik (via GitHub)" <gi...@apache.org>.
hterik commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1715095320
Keeping track of previous_heartbeat sounds like a good idea.
I'd be wary of using the term "_Scheduler_" here, Maybe it's a terminology thing with each Worker/Executor having a little scheduler in itself or when running in standalone mode.
For me, scheduler is the central deamon here:
https://airflow.apache.org/docs/apache-airflow/stable/core-concepts/overview.html
Where we observe this error the most is _between the **Workers** and the DB._. This error category can be identified as `psycopg2.OperationalError`.
While the **Scheduler**<->DB or Scheduler itself is having no issues.
The scheduler only get involved if the scheduler observes that a worker has not sent a heartbeat for a long time.
I would suggest phrasing it something like
* **First failure:** WARNING: "Worker failed to write heartbeat to database, this will retry and is not harmful if recovery happens within $scheduler_health_check_threshold seconds. + $reason_without_stacktrace
* **Failure after scheduler_health_check_threshold :** ERROR: "Worker failed to write hearbeat to database for $scheduler_health_check_threshold seconds. The Scheduler may mark this task as failed without the worker being informed of it. The task could potentially continue running but the result is going to be ignored by the scheduler. + $reason_without_stacktrace
* **Recovery after failure:** "INFO: Heartbeat recovered after XXX seconds"
Note that I may be mixing up some of the heartbeat timeout parameters, i haven't looked at the details of this for a long time. (`local_task_job_heartbeat_sec` vs `scheduler_health_check_threshold` vs `scheduler_zombie_task_threshold` vs `job_heartbeat_sec`). Another reason for good logs, understanding all the interaction of all these parameters is not obvious :)
--
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 #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "potiuk (via GitHub)" <gi...@apache.org>.
potiuk commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1584201590
Any of the suggestions is good. Marked is as "good first issue" - maybe you would like to implement it @hterik ?
--
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] Bowrna commented on issue #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "Bowrna (via GitHub)" <gi...@apache.org>.
Bowrna commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1587314804
I will pick this issue and start working on it @potiuk @hterik
--
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] Bowrna commented on issue #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "Bowrna (via GitHub)" <gi...@apache.org>.
Bowrna commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1711174286
> Sorry, I'm a bit unsure if #34160 really closes this completely. It touches suggestion A above, which is good, but i think one or all of B,C,D are also needed.
>
> In fact i think the change makes the log message even more confusing than before. By saying "_Scheduler is in unhealthy state_", when the error is most of the time caused by **Executor** not having connection to the database, this is going to mislead people into debugging **scheduler**-issues, instead of connectivity issues. I think its important operators can understand and act on log messages, without having intricate knowledge of the airflow internals.
>
> I may give this a another go myself but quite busy with other things so don't want to promise anything.
hi @hterik .. Its an error due to DBAPI error but when the Scheduler health check threshold is beyond the configured time then wouldn't it be right to mark the scheduler is in unhealthy state? Maybe we can phrase it like "DB not reachable to update for long time leading to unhealthy scheduler state". Please share your views on this. cc: @potiuk
--
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] Bowrna commented on issue #31810: Improve log messages of heartbeat connection errors and recovery
Posted by "Bowrna (via GitHub)" <gi...@apache.org>.
Bowrna commented on issue #31810:
URL: https://github.com/apache/airflow/issues/31810#issuecomment-1715009711
@potiuk with previous_heartbeat variable I think we could tell after it recovers. I will give that a try. Also, can you tell by rephrasing saying "DB not reachable to update for a long time leading to unhealthy scheduler state", Would it be more useful than simply saying scheduler is in unhealthy state? But as you said, finding the root cause of this DBAPI failure is hard.
@hterik please share your views too
--
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