{"id":"IL-0500","org":"2i2c","date":"2022-10-31","docs":["https://github.com/2i2c-org/infrastructure/pull/886/commits/9c30396a46202de639f12f5b924cd9fe03a8f086","https://github.com/2i2c-org/infrastructure/blob/1f916f8851fa636af065d427ba70267c55c8c1de/config/clusters/utoronto/common.values.yaml#L89","https://kubernetes.io/blog/2018/07/12/resizing-persistent-volumes-using-kubernetes/","https://github.com/2i2c-org/infrastructure/pull/1847","https://github.com/jupyterhub/grafana-dashboards/pull/49","https://github.com/2i2c-org/infrastructure/issues/1804"],"title":{"en":"UToronto JupyterHub logins and server starts returned 500 errors when the hub's sqlite database disk filled up","ko":"UToronto JupyterHub 의 데이터베이스 디스크가 가득 차서 로그인과 서버 시작이 500 오류로 실패했다"},"domain":["kubernetes","database"],"impact":{"scope":"UToronto JupyterHub: new logins and server starts failed with 500 errors; users already logged in kept working","users":"UToronto JupyterHub users who were not already logged in","region":"unknown"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":{"en":"Kubernetes dynamic volume resizing let the hub database disk grow from 10G to 60G without much effort. The risk of keeping logs on the database disk had been identified during the earlier migration, but the team had no solid process for following it through, and because no alert existed the team had to wait for a person to report the outage.","ko":"쿠버네티스의 동적 볼륨 크기 조정은 손을 많이 대지 않고도 바로 동작했다. 이 위험은 마이그레이션 때 이미 짚었지만 끝까지 챙기는 절차가 없었다. 2i2c 는 그 뒤로 절차가 많이 나아졌다고 적었다. 경보가 없어서 사람이 알려 줄 때까지 기다려야 했다."},"related":[],"sources":[{"url":"https://github.com/2i2c-org/incident-reports/blob/main/reports/2022-10-31-utoronto-500-errors-db-full.pdf","kind":"github","archived":null}],"summary":{"en":"The UToronto JupyterHub stored its hub logs on the same 10G disk as the hub's sqlite database. It was the only hub run by 2i2c with this layout. The commit that set it up during an earlier migration noted that the layout was not ideal and only copied the hub's prior configuration; the write-up says the likely reason was that the hub did not use Azure for logging at all and the team wanted to keep detailed logs for analytics. The risk had been identified during that migration, but there was no process to follow it through. The log file eventually filled the disk, database operations could no longer succeed, and hub logins and server starts failed from 6:27 PM until about 9:00 PM Pacific time, 2 hours 33 minutes in all.\n\nOnce the issue was acknowledged, the hub logs made the cause clear. The log file could not be compressed in place on the full disk, so an engineer opened a shell in the hub pod with kubectl exec and gzipped jupyterhub.log into /tmp, which cut its size by about ten times; the log was kept rather than deleted in case it was needed for analytics. Deleting the uncompressed file would not free space while the JupyterHub process still held it open, so the hub process had to restart, and because a pod restart would also lose /tmp, the compressed file was first copied to a local machine with kubectl cp. While the copy ran, the hub-db-dir PVC was edited from 10G to 60G, so that a single pod restart applied the resize too. The hub pod restarted at 8:59 PM with the larger disk and service came back. The compressed log was copied back to the hub disk at 10:01 PM, and the hub kept writing its logs to that disk after the incident.","ko":"UToronto JupyterHub 는 2i2c 가 관리하는 허브 가운데 유일하게 hub 로그를 hub 데이터베이스와 같은 디스크에 두었다. 이 설정은 마이그레이션 때 예전 UToronto 설정을 그대로 옮긴 것이었고, 그 커밋 메시지도 바람직하지 않다고 적어 두었다. 2i2c 는 이렇게 둔 이유가 로깅에 Azure 를 전혀 쓰지 않는다는 점과 분석용으로 자세한 로그를 남겨 두려 한 데 있었을 것으로 봤다. 태평양 시간으로 2022년 10월 31일 오후 6:27 에 용량 10G 의 디스크가 가득 찼고, 데이터베이스 작업이 실패하면서 로그인과 서버 시작이 500 오류를 냈다.\n\n오후 7:13 에 사용자가 지원 메일로 알렸고 오후 8:33 에 문제를 접수했다. 엔지니어는 hub 파드 안에서 로그 파일을 /tmp/jupyterhub.log.gz 로 압축해 크기를 10분의 1로 줄였다. 디스크가 가득 차 제자리에서 압축할 수 없었고, 나중에 분석에 쓸 수도 있어서 지우지 않았다. JupyterHub 프로세스가 원래 파일을 열어 두고 있어서 공간을 되찾으려면 재시작해야 했다. 그래서 압축 파일을 먼저 로컬로 복사했다. 같은 재시작에 맞춰 PVC hub-db-dir 를 10G 에서 60G 로 늘렸다. 오후 8:59 에 hub 파드를 재시작하자 서비스가 돌아왔고, 오후 10:01 에 압축 로그를 hub 디스크로 되돌려 놓았다. 영향 시간은 2시간 33분이었다."},"trigger":{"en":"The JupyterHub log file, written to the same 10G disk as the hub's sqlite database, grew until the disk was completely full.","ko":"hub 로그가 hub 의 sqlite 데이터베이스와 같은 10G 디스크에 쌓였고, 아주 커진 로그 파일이 디스크를 다 채웠다."},"severity":"unknown","symptoms":["high-error-rate","volume-full"],"timeline":{"detected_after":"46m","resolved_after":"2h 33m"},"date_kind":"incident","detection":{"en":"A user emailed 2i2c support at 7:13 PM that users could not log in; the team acknowledged the issue at 8:33 PM. There was no alert for the problem.","ko":"경보가 없었다. 사용자가 오후 7:13 에 support@2i2c.org 로 로그인이 안 된다는 메일을 보내 알게 됐다."},"components":["database","persistent-volume","jupyterhub"],"root_cause":"capacity","remediation":[{"text":{"en":"Compressed the hub log file into /tmp from a shell in the hub pod, because it could not be compressed in place on the full disk","ko":"디스크가 가득 차 로그 파일을 제자리에서 압축할 수 없어서, hub 파드 안에서 gzip < jupyterhub.log > /tmp/jupyterhub.log.gz 로 /tmp 에 압축했다."}},{"text":{"en":"Copied the compressed log to a local machine so the hub pod could be restarted without losing it","ko":"파드를 재시작하면 /tmp 의 압축 파일도 사라지므로 kubectl cp 로 압축 파일을 로컬에 먼저 복사했다."}},{"text":{"en":"Resized the hub database disk (the hub-db-dir PVC) from 10G to 60G","ko":"로그를 어떻게 할지 정할 시간을 벌려고 kubectl -n prod edit pvc hub-db-dir 로 hub 데이터베이스 디스크를 10G 에서 60G 로 늘렸다. 크기 조정에도 파드 재시작이 필요해서 로그를 복사한 뒤의 재시작 한 번으로 함께 반영했다."}},{"text":{"en":"Restarted the hub pod, which came back with the larger disk and restored service","ko":"hub 파드를 재시작했다. hub 가 더 큰 디스크로 다시 뜨면서 서비스가 돌아왔다."}}],"action_items":[{"text":{"en":"Stop keeping hub logs on the same disk as the hub database","ko":"hub 로그를 hub 데이터베이스와 같은 디스크에 두지 않는다."}},{"text":{"en":"Add a Grafana graph of free space on the JupyterHub database disk","ko":"Grafana 에 JupyterHub 데이터베이스 디스크의 남은 공간을 보여 주는 그래프를 더한다."}},{"text":{"en":"Alert on elevated error rates","ko":"오류율이 오르면 경보를 보낸다. 이 작업은 진행 중이고 2i2c 의 4분기 목표다."}}],"contributing":["no-alert-on-limit"],"recurrence_of":null,"symptoms_text":{"en":"On 31 October 2022 at 6:27 PM Pacific time, users of the UToronto JupyterHub run by 2i2c could no longer log in or start their servers, and the hub answered with 500 errors. Users who were already logged in could keep using the hub.\n\nThe hub pod's logs contained \"Rolling back session due to database error\" from JupyterHub, followed by a SQLAlchemy traceback that ended in \"sqlite3.OperationalError: database or disk is full\".\n\nNothing alerted on the problem. A user emailed 2i2c support at 7:13 PM, the team acknowledged the issue at 8:33 PM, and at 8:47 PM the hub logs and the hub configuration showed that the hub's log file and its sqlite database shared one disk, and that the disk was full. The start time was worked out later from Grafana logs of the last successful login.","ko":"UToronto JupyterHub 에서 새로 로그인하거나 서버를 시작하려는 사용자가 500 오류를 받았다. 이미 로그인해 있던 사용자는 계속 허브를 쓸 수 있었다.\n\nhub 파드 로그에는 [E 2022-11-01 03:39:39.905 JupyterHub base:97] Rolling back session due to database error 줄과 함께 SQLAlchemy 트레이스백이 남았고, 마지막 줄은 sqlite3.OperationalError: database or disk is full 이었다.\n\n태평양 시간 오후 6:27 에 디스크가 가득 찼고 그 뒤로 새 로그인이 하나도 성공하지 못했다. 이 시각은 나중에 Grafana 로그에서 마지막으로 성공한 로그인을 보고 정했다. 운영팀은 오후 7:13 에 지원 메일을 받았고 오후 8:33 에 문제를 접수했다.\n\n엔지니어는 설정을 보고 hub 로그가 hub 데이터베이스와 같은 디스크에 쌓이고 있다는 것을 알았다. 커다란 로그 파일을 지워도 JupyterHub 프로세스가 그 파일을 열어 두고 있어서 공간이 돌아오지 않았다. 공간을 되찾으려면 hub 프로세스를 재시작해야 했다."},"updated_at":"2026-11-14T12:34:14.553319Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0500","org_slug":"2i2c"}