{"id":"IL-0504","org":"Binder Project","date":"2018-07-08","docs":["https://github.com/jupyterhub/mybinder.org-deploy/issues/611","https://github.com/jupyterhub/mybinder.org-deploy/issues/646","https://github.com/jupyterhub/mybinder.org-deploy/issues/655","https://github.com/jupyterhub/kubespawner/pull/208","https://github.com/jupyterhub/kubespawner/issues/209","https://github.com/jupyterhub/kubespawner/issues/210","https://github.com/jupyterhub/jupyterhub/issues/2028"],"title":{"en":"mybinder.org launches failed for about five hours as undeleted user pods piled up and filled the cluster","ko":"mybinder.org 에서 사용자 파드가 지워지지 않고 쌓여 클러스터가 가득 차고 실행이 약 5시간 동안 실패했다"},"domain":["kubernetes"],"impact":{"scope":"mybinder.org: all new launches failed; the cluster filled with almost 1k user pods","users":"all mybinder.org users launching servers","region":"unknown"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":{"en":"The delete-pods.py script was useful for bulk-deleting old pods, and once the problem was noticed the cluster was healthy within a few minutes. The outage lasted five hours before anyone noticed because no downtime notifications existed, and scaling the cluster back down still took several manual steps of cordoning and draining nodes.","ko":"mybinder.org-deploy 의 scripts/delete-pods.py 스크립트로 오래된 파드를 한꺼번에 지울 수 있었고, 문제를 알고 나서는 몇 분 안에 클러스터가 정상으로 돌아왔다. KubeSpawner 의 pod reflector 가 이벤트를 받지 못해 Hub 를 재시작할 때까지 실행이 모두 실패했다. 여기에 pod reflector 가 시작을 알아채지 못한 파드를 처음부터 만들어지지 않은 것으로 보고 지우지 않는 버그가 겹쳤다. 다운타임 알림이 없어서 5시간 동안 알아채지 못했다. 클러스터 스케일 다운에는 노드를 cordon 하고 drain 하는 손 작업이 여러 단계 남아 있었다."},"related":[],"sources":[{"url":"https://github.com/jupyterhub/mybinder.org-deploy/blob/main/docs/source/incident-reports/2018-07-08-podsnips-aplenty.md","kind":"github","archived":null}],"summary":{"en":"At about 18:30 CEST the pod reflector in KubeSpawner stopped receiving events, and every launch failed until the Hub was restarted. A second bug made it worse: pods that had started but were not registered in the reflector had their launch aborted, and KubeSpawner then skipped deleting them because it assumed those pods had never been created. The write-up names this skipped deletion as the direct cause of the runaway pod growth and the reflector that stopped updating as the root cause. Why the reflector stopped is not established; the new event reflectors, a major new KubeSpawner feature, may have been relevant.\n\nThere were no downtime notifications, so the outage ran for hours before anyone noticed. From 23:25 the team deleted pods older than four hours with the delete-pods.py script, culled pods of the most-used images such as ipython-in-depth more aggressively, and restarted the Hub pod; after about 600 pods were culled, launches were back to normal within a few minutes. Some of the nodes added for the flood of pods were cordoned so the autoscaler could reclaim them, and the next morning manual max-age culling let the cluster scale back down to 3 nodes. The total service disruption lasted about five hours.","ko":"2018년 7월 8일 토요일 저녁 18:30 CEST 무렵, KubeSpawner 의 pod reflector 가 쿠버네티스 이벤트를 받지 못하게 됐다. 그 뒤로 실행이 중단되면, 실제로 떠 있는 파드가 pod reflector 에 없다는 이유로 이미 지워진 것으로 처리돼 그대로 남았다. 이 두 번째 버그가 겹치면서 파드가 계속 늘어 클러스터를 채웠고 새 실행이 모두 실패했다. 운영팀은 파드가 늘어난 직접 원인은 지워지지 않은 파드이고, 근본 원인은 pod reflector 가 갱신을 멈춘 것이라고 적었다. KubeSpawner 에 새로 들어간 event reflector 가 관련이 있을 수 있지만 아직 분명하지 않다고 봤다.\n\n22:48 에 gitter 에 이상하다는 신고가 올라왔고 23:25 에 조사를 시작했다. 4시간보다 오래된 파드를 지우고, ipython-in-depth 처럼 많이 쓰는 이미지의 파드는 더 공격적으로 정리했다. 파드 600개쯤을 정리하고 Hub 파드를 재시작하자 실행이 정상으로 돌아왔다. 파드가 몰리면서 늘어난 노드 몇 개는 cordon 해서 오토스케일러가 회수하게 했다. 다음 날 08:00 에 최대 수명을 넘긴 파드를 손으로 정리해 남은 노드 일부를 비웠고, 클러스터는 3개 노드로 줄었다. 서비스 전체 중단은 약 5시간이었다."},"trigger":null,"severity":"unknown","symptoms":["service-unavailable","pod-pending","stale-api-reads"],"timeline":{"detected_after":"4h 18m","resolved_after":"5h"},"date_kind":"incident","detection":{"en":"Suspicious behaviour was reported on Gitter at 22:48 CEST, more than four hours after launch success dropped to zero; no downtime notifications were set up.","ko":"18:30 무렵 시작된 실패를 22:48 에 gitter 에 올라온 신고로 알았다. 다운타임 알림이 아직 없었다."},"components":["jupyterhub"],"root_cause":"software-bug","remediation":[{"text":{"en":"Deleted user pods older than four hours with the delete-pods.py script","ko":"4시간보다 오래된 파드를 지웠다."}},{"text":{"en":"Culled pods of the most-used images, such as ipython-in-depth, more aggressively","ko":"ipython-in-depth 처럼 가장 많이 쓰는 이미지의 파드는 더 공격적으로 정리했다."}},{"text":{"en":"Restarted the Hub pod after about 600 pods were culled, which brought launches back to normal","ko":"파드 600개쯤을 정리하고 Hub 파드를 재시작해 실행을 정상으로 돌렸다."}},{"text":{"en":"Cordoned some of the extra nodes so the autoscaler could reclaim them","ko":"파드가 몰려 새로 할당된 노드 몇 개를 cordon 해서 오토스케일러가 회수하게 했다."}},{"text":{"en":"Ran manual max-age culling the next morning, letting the cluster scale back to 3 nodes","ko":"다음 날 아침 최대 수명을 넘긴 파드를 손으로 정리해 남은 노드 일부를 비웠고, 클러스터는 3개 노드로 줄었다."}}],"action_items":[{"text":{"en":"Set up notifications of downtime","ko":"다운타임 알림을 만든다."}},{"text":{"en":"Automate cluster scale-down","ko":"스케일 다운을 자동화한다."}},{"text":{"en":"Document the downtime recovery steps so every team member knows them","ko":"다운타임 복구 절차를 문서로 남긴다. 이번에는 잘 됐지만 팀원 모두가 그 절차를 아는 것은 아니었다."}},{"text":{"en":"Fix KubeSpawner's failure to delete pods when the pod reflector fails","ko":"pod reflector 가 실패할 때 파드를 지우지 못하는 버그를 고친다."}},{"text":{"en":"Make KubeSpawner more robust to pod reflector failure","ko":"KubeSpawner 가 pod reflector 의 실패에 더 잘 견디게 한다."}},{"text":{"en":"Refactor the event reflector into a single reflector instead of one per pod","ko":"event reflector 를 파드마다 하나씩 두지 않고 하나로 합친다. event reflector 는 KubeSpawner 의 큰 새 기능이었고 이번 실패와 관련이 있을 수 있지만 아직 분명하지 않다."}},{"text":{"en":"Detect a likely unhealthy Hub state and restart the Hub without manual intervention","ko":"Hub 상태가 나빠 보이는 것을 자동으로 찾아 사람 손 없이 Hub 를 재시작하는 방법을 시도한다."}}],"contributing":["no-alert-on-limit"],"recurrence_of":null,"symptoms_text":{"en":"On Saturday 8 July 2018 at about 18:30 CEST, the launch success rate of mybinder.org dropped to zero and stayed there. Suspicious behaviour was first reported on Gitter at 22:48, more than four hours later.\n\nWhen the investigation began at 23:25, the cluster was full and had scaled up to 8 nodes. It held almost 1k user pods: 737 running and 240 waiting to be scheduled.\n\nThe hub logs, read the next morning, showed that the pod reflector had stopped receiving events at about 18:30, with errors such as \"TimeoutError: pod/jupyter-ipython-2dipython-2din-2ddepth-... did not disappear in 300 seconds!\" and \"TimeoutError: pod/jupyter-bokeh-2dbokeh-2dnotebooks-... did not start in 300 seconds!\". Shortly after came warnings that deletion was skipped for pods that had launched: \"No pod jupyter-ipython-2dipython-2din-2ddepth-... to delete. Assuming already deleted.\"","ko":"mybinder.org 의 실행 성공률이 0으로 떨어졌고 새 실행이 모두 실패했다. 다운타임 알림이 없어서, 문제는 4시간쯤 지나 gitter 에 이상하다는 신고가 올라온 뒤에야 알려졌다.\n\n조사를 시작했을 때 클러스터는 가득 차 8개 노드까지 늘어나 있었다. 사용자 파드가 1k 개 가까이 있었고, 그 가운데 737개는 돌고 있었고 240개는 스케줄을 기다리고 있었다.\n\nhub 로그에는 18:30 CEST 무렵부터 pod reflector 가 이벤트를 받지 못한 흔적이 남았다. TimeoutError: pod/jupyter-ipython-2dipython-2din-2ddepth-... did not disappear in 300 seconds! 와 TimeoutError: pod/jupyter-bokeh-2dbokeh-2dnotebooks-... did not start in 300 seconds! 가 찍혔다.\n\n곧이어 hub 는 실행을 중단한 파드를 지우는 단계를 건너뛰었고, 로그에는 [W 2018-07-07 16:38:35.506 JupyterHub spawner:1476] No pod jupyter-ipython-2dipython-2din-2ddepth-... to delete. Assuming already deleted. 가 남았다. 이 파드들은 실제로 떠 있었지만 pod reflector 에 등록되지 않아서 지워지지 않았다."},"updated_at":"2026-11-14T12:34:14.918802Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0504","org_slug":"binder-project"}