Repository navigation
KubernetesJobWatcher failing on HTTP 410 errors, jobs stuck in scheduled state #21087
Description
Apache Airflow version
2.2.3 (latest released)
What happened
After upgrading Airflow to 2.2.3 (from 2.2.2) and cncf.kubernetes provider to 3.0.1 (from 2.0.3) we started to see these errors in the logs:
{"asctime": "2022-01-25 08:19:39", "levelname": "ERROR", "process": 565811, "name": "airflow.executors.kubernetes_executor.KubernetesJobWatcher", "funcName": "run", "lineno": 111, "message": "Unknown error in KubernetesJobWatcher. Failing", "exc_info": "Traceback (most recent call last):\n File \"/usr/local/lib/python3.9/site-packages/airflow/executors/kubernetes_executor.py\", line 102, in run\n self.resource_version = self._run(\n File \"/usr/local/lib/python3.9/site-packages/airflow/executors/kubernetes_executor.py\", line 145, in _run\n for event in list_worker_pods():\n File \"/usr/local/lib/python3.9/site-packages/kubernetes/watch/watch.py\", line 182, in stream\n raise client.rest.ApiException(\nkubernetes.client.exceptions.ApiException: (410)\nReason: Expired: too old resource version: 655595751 (655818065)\n"}
Process KubernetesJobWatcher-6571:
Traceback (most recent call last):
File "/usr/local/lib/python3.9/multiprocessing/process.py", line 315, in _bootstrap
self.run()
File "/usr/local/lib/python3.9/site-packages/airflow/executors/kubernetes_executor.py", line 102, in run
self.resource_version = self._run(
File "/usr/local/lib/python3.9/site-packages/airflow/executors/kubernetes_executor.py", line 145, in _run
for event in list_worker_pods():
File "/usr/local/lib/python3.9/site-packages/kubernetes/watch/watch.py", line 182, in stream
raise client.rest.ApiException(
kubernetes.client.exceptions.ApiException: (410)
Reason: Expired: too old resource version: 655595751 (655818065)
Pods are created and run to completion, but it seems the KubernetesJobWatcher is incapable of seeing that they completed. From there Airflow goes to a complete halt.
What you expected to happen
No errors in the logs and the job watcher does it's job of collecting completed jobs.
How to reproduce
I wish I knew. Trying to downgrade the cncf.kubernetes provider to previous versions to see if it helps.
Operating System
k8s (Airflow images are Debian based)
Versions of Apache Airflow Providers
apache-airflow-providers-amazon 2.6.0
apache-airflow-providers-cncf-kubernetes 3.0.1
apache-airflow-providers-ftp 2.0.1
apache-airflow-providers-http 2.0.2
apache-airflow-providers-imap 2.1.0
apache-airflow-providers-postgres 2.4.0
apache-airflow-providers-sqlite 2.0.1
Deployment
Other
Deployment details
The deployment is on k8s v1.19.16, made with helm3.
Anything else
This, in the symptoms, look a lot like #17629 but happens in a different place.
Redeploying as suggested in that issues seemed to help, but most jobs that were supposed to run last night got stuck again. All jobs use the same pod template, without any customization.
Are you willing to submit PR?
- Yes I am willing to submit a PR!
Code of Conduct
- I agree to follow this project's Code of Conduct
Activity
cansjt commentedon Jan 28, 2022
After downgrading to 2.1.0, logs showed another error (but reported with the log level INFO!)
Giving the missing permission to the scheduler's service account fixed the issue. Still need to upgrade the
cncf.kubernetesprovider again to be sure this was the root cause of the reported error or not.potiuk commentedon Feb 6, 2022
I think this is also similar root cause as #12644 . @dimberman @jedcunningham @kaxil - or maybe somoene else who has some more experiences with K8S deployments in "real life" - this error "Resource too old" is returned by K8S when there are too many changes to a version of K8S resource.
But I am just wondering - it really happens IMHO because we deploy some changes "incrementally" too frequently (and too many times) in the chart/deployment ? Or maybe because we do NOT deploy the "full" deployment where we should?
I am not too experienced in long running K8S deployments, but for me it looks like something that this could be solved by identifiying which resources those are and implement some full "re-deployment" from time to time.
It might be, that this is outside of our control as well, but I've seen some other people complaining about that recently so maybe we could have someone who has more insights there to take a look ?
jedcunningham commentedon Feb 10, 2022
It's not that there are too many changes, at least like you are thinking. The executor is trying to watch from (history) revision n, which has rolled off of history on the k8s side. n+2 might be the oldest available now.
This really isn't related to our deployments, and there isn't anything we can do in that regard to help here. In fact, you could hit this when running the scheduler outside k8s even.
More context here: #15500 (comment)
Bottom line, especially now that we aren't pinned to
kubernetes==11, we can probably handle this more gracefully now on our side.potiuk commentedon Feb 10, 2022
Thanks for the context - now I understand where it comes from! Yeah it isn't an easy one to handle!
arkadiusz-bach commentedon Feb 28, 2022
I have the same issue.
Looks like it is happening, because they are now(don't know from which version) handling 410 error on kubernetes library side, there is one retry and then exception is raised if the event is of type = 'ERROR'
I checked the kubernetes library and it was changed in this pull request:
https://github.com/kubernetes-client/python-base/pull/133/files
On Airflow Kubernetes Executor it is being handled here:
airflow/airflow/executors/kubernetes_executor.py
Line 148 in d726579
By process_error function, but it probably should be now enclosed by try catch ApiException with check for 410 code
cansjt commentedon Feb 28, 2022
To me, per the tickets referenced in #15500, the problem seem more in the Kubernetes Python's API. It does not handle the kind of messages we'd need for Airflow to recover when it's lost track of resources versions.
Last I check there was no bug report there regarding that. So I did open one. I am sadly not the more knowledgeable to provide insight on how to best resolve this. @jedcunningham Maybe you can help?
Until this is resolved on the k8s client side, what is the plan for Airflow? Wait? Resurrect the #15500 PR? (not sure if it fully solves the issue)
Allow deploying latest build again
Allow deploying latest build again
Allow deploying latest build again
Allow deploying latest build again (#114)
gkarg commentedon Apr 4, 2022
I concur with @arkadiusz-bach 's analysis.
The error is simply happening because newer versions of kubernetes lib throw exceptions which airflow fails to handle.
The culprit is here
for event in list_worker_pods():, thus_process_errornever gets a chance to run.So, a simple fix would be to do something like this:
airflow/airflow/executors/kubernetes_executor.py
Line 95 in 2cf1ae3
def run(self) -> None: """Performs watching""" kube_client: client.CoreV1Api = get_kube_client() if not self.scheduler_job_id: raise AirflowException(NOT_STARTED_MESSAGE) while True: try: self.resource_version = self._run( kube_client, self.resource_version, self.scheduler_job_id, self.kube_config ) except ReadTimeoutError: self.log.warning( "There was a timeout error accessing the Kube API. Retrying request.", exc_info=True ) time.sleep(1) + except ApiException as e: + if e.status == 410: + self.resource_version = "0" + else: + raise except Exception: self.log.exception('Unknown error in KubernetesJobWatcher. Failing') raise else: self.log.warning( 'Watch died gracefully, starting back up with: last resource_version: %s', self.resource_version, )I'm not (yet) submitting a PR, as this is probably too much of a hack, but if this looks good, I'll gladly do.
@cansjt I do not see any blockers from lib-kubernets side, this appears to be an airflow-related issue.
14 remaining items
snjypl commentedon May 9, 2022
the code you shared is not really a good way to demonstrate
BOOKMARK.but still:
shouldn't it be
resource_version = last_resource_version.resource_version = 1will mostly always fail.the resource_version in the first loop and the error message is same. again, it has nothing to do with bookmark.
ecerulm commentedon May 9, 2022
@snjypl , let me see if I can address you comments (in no particular order, sorry)
allow_watch_bookmark=True does not prevent 410
The PR kubernetes-client/python#1796 you mention as "the bug" does NOT solve the 410 error, if you do
allow_watch_bookmarkandresource_version=someexpiredresourceversionI still get a 410 GONE using your PR code or am I missing something?:thats the point to simulate an already expired resource version, like it would happen if there was a watch disconnect due to some network issue, there was 5 minutes network disconnect from airflow to k8s api, until the next watch could actually be performed, then the resource_version will be already expired. In order to simulate that quickly I use
resource_version=1This was explicitly mentioned in the example comments :
It demonstrates that today if you use a
allow_watch_bookmarks=Trueandresource_version=some_already_expired_resource_versionyou will still get a 410 GONE.This is true in
kubernetes==20.3.0and also true in your PR kubernetes-client/python#1796 because I tested with your PR codeI don't think that is true, the resourceVersion can be too old by the time you get to use it. Two things to keep in mind:
I fully agree with that statement but I guess that's a hefty change. But I do really thing Airflow kubernetes_executor.py is trying too hard to track resource_version and getting little to nothing by doing so.
snjypl commentedon May 9, 2022
@ecerulm sorry, but it is not how watch works.
if you start a watch with an old resourceVersion it WILL always give you 410 error. that is the expected behaviour.
in short: if you get 410, start a fresh watch. don't bother about the recent resoureVersion, because whatever maybe the resourceVersion that your application is having it would still be old. you can't have a fresher resource version than the kube client watcher.
maybe looking at the unittest for the bookmark events might help:
https://github.com/kubernetes-client/python/blob/f379bbabf33f239f49b0e1b7652b6212f3960910/kubernetes/base/watch/watch_test.py#L170-L204
In this scenario, you need to start a new watch without resourceVersion or resoureVersion="0".
when you pass any other resourceVersion, you can asking to start from that specify version and it does not exist in the case you will get 410 error.
snjypl commentedon May 9, 2022
airflow does not need to track the resoure_version. kube client watcher will do it.
ecerulm commentedon May 9, 2022
I guess we have a language barrier here, because I already knew that
and that's what I've been trying to explain to you all along. I guess I misunderstood what you mean by
it is because of this bug in kubernetes python client that you were getting 410 error even with allow_watch_bookmark enabled.The only thing needed to solve his particular issue #21087 is to handle 410 GONE in kubernetes_executor.py , there is no need for a "bug fix" in kubernetes python client and even with that bug fix we will still get 410. So maybe we should stop talking about watch bookmarks when it comes to this particular issue.
snjypl commentedon May 9, 2022
: ) it's been a long thread.
once that issue is fixed in kube client, you won't be getting 410 errors , at least not so frequently, when you do a watch. in the rare case of a 410 error. you NEED to start with resource_version="0". the last_resource_version is not going to be any help.
like i mentioned in my previous comment. BOOKMARK is required for preventing 410 error.
snjypl commentedon May 9, 2022
for ref: https://github.com/kubernetes/enhancements/tree/master/keps/sig-api-machinery/956-watch-bookmark
ecerulm commentedon May 9, 2022
so like I said, we will still see 410 errors. If we handle 410 in kubernetes_executor.py this issue will be solved regardless of kubernetes python client fixes. So those fixes are inconsequential for this issue
well, it's not that rare and I don't think that supporting watch bookmarks is going to change radically how often we get them, because I think the main source of those 410 is that there is a disconnect between airflow and kuberenetes api and the resource_version will be expired by the time it reconnects.
I thought that we agreed that this is not preventing 410, you will still get it if enough time passed between the disconnect and the when the next watch is goes through because at that time the resource version that kuberentes_executor.py is sending in the watch has already expired. Again, the bookmark thing is not preventing that at all.
I think it's going to be very confusing for people reading this thread and thinking that some fix is required in kubernetes python client , because that fix is not required at all to fix this issue, the only thing needed to fix this issue is to handle 410 properly.
snjypl commentedon May 9, 2022
@ecerulm please go through the docs. it will help you understand why 410 occurs and how BOOKMARK will prevent it.
410 does not happen due to network issues or connectivity issue between airflow and kubeapi server.
it happens when no event of type ADDED, MODIFIED, DELETED happens on the watched resource for a long time [ ~ 5 mins].
it would really help the conversation if you would take the time to go through the KEP and other docs.
ecerulm commentedon May 9, 2022
I have reproduced this locally with minikube and kubernetes python client so I can assure you it CAN happen due to network issues between airflow and the k8s api. Let me explain the setup
("Connection broken: InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got length b'', 0 bytes read))HTTPSConnectionPool(host='127.0.0.1', port=2222): Max retries exceeded with url: /api/v1/namespaces/testns2/pods?resourceVersion=5659&watch=True (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x107b02c40>: Failed to establish a new connection: [Errno 61] Connection refused'))(410) Reason: Expired: too old resource version: 5659 (6859)I've been running a watch with the kubernetes python client to a namespace where there is not new events at all for 1 hours and I did not get an ApiException(410). So, are you sure of this? Have you ever seen this yourself in your kubernetes environment?
I did read all the documents, and I think I understand this ok, also I have actually done testing and try to actually back up what I say by doing it.
I think you mean something else by "prevent".
I hope the scenario I included in this comment will help you understand why 410 occurs in the event of network issues and how BOOKMARK can't prevent that. In principle BOOKMARK will help to get a better "last known resource version " at step 5 but by the time step 8 is reached that resource version won't be valid (if enough time has passed). And this is not theory it's something that you actually do test and reproduce yourself like I did.
snjypl commentedon May 10, 2022
@ecerulm, that is not a valid scenario to test/demostrate bookmark feature.
the bookmark does not work the way you understand it. i wish i could give you a better example.
ecerulm commentedon May 10, 2022
Well, but this is one of the scenarios that is causing KubernetesJobWatcher to get 410 and get stuck in an infinite loop. So again what I'm trying to say is that bookmarks do not help to solve #21087 is this scenario. Just handling 410 properly solves #21087 no need for bookmark at all to solve this github issue.
snjypl commentedon May 10, 2022
@ecerulm , i believe when there is an error there are two parts to it
a.) handling the exception and recovering from it.
b.) finding the cause and trying to fix it so that it won't happen again or atleast reduce the frequency of the error.
what you are suggesting covers part (a). it will allow airflow to recover from 410 and not get stuck in an infinite loop. we both agree on that.
now, using bookmark etc would come in part (b) trying to fix the root cause or try to prevent the 410 error. part (b) requires a bug fix in kubernetes-python client and also some changes in airflow code.
both parts are equally important.
ultimately it is for the airflow maintainers and community members to decide what is best for them. i am just trying to help understand the root cause of 410 and possible ways prevent it from recurring.
i think, we should just leave it here and let others participate in the discussion, and hear their views.
ecerulm commentedon May 10, 2022
@snjypl
Like I said before, my only concern is that someone that reads this thread maybe get the false impression that watch bookmarks are needed to stop the scheduler from getting stuck in an infinite loop and some people may even get the idea that we need a new kubernets python client before we can solve this, which is not the case.
I just tried to explain that watch bookmarks are not needed to solve the infinite loop (which is what this #21087 is about IMHO) . And that watch bookmarks alone will not prevent the 410 at least the scenario that I'm personally experiencing (which I already explained).
One of the root causes would be the one that I explained, which I don't think can't be prevented from recurring.
well, I think a) is more important and that's why I'm so adamant into making sure that a) is done and not delayed waiting for kubernetes client updates, etc. Since just
b) ...reduce the frequency of the error.does not make a big difference, if my scheduler gets into infinite loop every hour or every day it does not matter that much. Both cases are unacceptable for me.I totally agree to leave it here, I think with these two last post is clear what you mean, and what I mean.