Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Hub out of sync with k8s cluster #2043

Closed
ryanlovett opened this issue Jul 16, 2018 · 17 comments
Closed

Hub out of sync with k8s cluster #2043

ryanlovett opened this issue Jul 16, 2018 · 17 comments

Comments

@ryanlovett
Copy link
Contributor

ryanlovett commented Jul 16, 2018

Temporary fix


On chart 0.6. Our hub has been periodically having problems where it won't permit current or new user servers to start. Users see 503 errors when visiting /user-redirect/git-sync (their primary entry point). When this happens, the hub's view of users servers at /hub/admin is out of sync with the cluster's view of them via get pods. Killing the hub pod gets users past this problem, though there are lingering issues. For example one user's pod was still up but the hub thought the server wasn't running.

I realize this isn't much to go on. I've asked the instructors to preserve the hub logs the next time this problem comes up.

Server Version: version.Info{Major:"1", Minor:"10+", GitVersion:"v1.10.2-gke.3", GitCommit:"d2c7a2bd41036f9474287579a725dc54c904e92d", GitTreeState:"clean", BuildDate:"2018-05-23T00:19:39Z", GoVersion:"go1.9.3b4", Compiler:"gc", Platform:"linux/amd64"}
@willingc
Copy link
Contributor

willingc commented Aug 2, 2018

Hi @ryanlovett, Have you seen this behavior recently?

@consideRatio
Copy link
Member

consideRatio commented Aug 2, 2018

I have - jupyterhub/kubespawner#223! If it is the same reason for getting out of sync as I have, this is very important to solve I think.

@ellisonbg described in how troublesome it can be if users run out of memory. That happened to a user on my cluster. Their pod got evicted and it led to this state I believe. It has also happened when a user pod was lost because a preemptible node shut down after 24 hours.

A while back, a month perhaps, I think @minrk implemented a fix that cleaned up some routing during hub startup. @minrk does this sound familiar? Perhaps it is the last one of these I was thinking of? I scrambled some PR's that may be related or give a good background.

See jupyterhub/kubespawner#223 for reproduction details and logs of this issue, I'm fairly confident they have the same solution and this issue is probably reproducible using that.

@ryanlovett
Copy link
Contributor Author

@willingc Yes, it happened 7/31, 7/30, 7/16, and 7/6. I'm happy to try out any potential fixes however the class will be over in a week or two.

@willingc
Copy link
Contributor

willingc commented Aug 2, 2018

Thanks folks. @consideRatio, Sounds reasonable.

@ryanlovett
Copy link
Contributor Author

Example hub log entries:

[I 2018-08-02 19:11:05.216 JupyterHub log:122] 302 GET /user/student1/metrics → /hub/user/student1/metrics (@10.138.0.18) 0.79ms
[I 2018-08-02 19:11:05.243 JupyterHub log:122] 302 GET /user/student1/metrics → /hub/user/student1/metrics (@10.138.0.18) 0.71ms
[E 2018-08-02 19:11:05.249 JupyterHub base:711] Preventing implicit spawn for student1 because last spawn failed: pod/jupyter-student1 did not start in 300 seconds!
[E 2018-08-02 19:11:05.249 JupyterHub web:1591] Uncaught exception GET /hub/user/student1/metrics (10.138.0.8)
    HTTPServerRequest(protocol='http', host='our.hub.hostname', method='GET', uri='/hub/user/student1/metrics', version='HTTP/1.1', remote_ip='10.138.0.8', headers={'Cookie': 'jupyter-hub-token="2|1:0|10:1533154153|17:jupyter-hub-token|44:NTRmMWM1MTEzNGM4NGVmZjlkZThmMzlkN2VmMzFkNTM=|3ea9f804375ee7717755d7d29555d2651e44739e0d5ea893fb1e29dd6f7317c1"; __utmc=245566491; __utma=245566491.541953767.1516150214.1518023937.1518044824.10; __utmz=245566491.1518044824.10.10.utmcsr=google|utmccn=(organic)|utmcmd=organic|utmctr=(not%20provided); _ga=GA1.2.541953767.1516150214; __unam=94a0df2-16241e706be-44fd8501-32; _xsrf=2|3c5a1938|6171708ec75e3ffc8390b3a57f0062ce|1532984087', 'Accept-Language': 'en-US,en;q=0.9', 'Accept-Encoding': 'gzip, deflate', 'Referer': 'http://our.hub.hostname/user/student1/notebooks/materials-su18/materials/su18/hw/hw10/hw10.ipynb?redirects=1', 'User-Agent': 'Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36', 'X-Requested-With': 'XMLHttpRequest', 'Accept': 'application/json, text/javascript, */*; q=0.01', 'X-Scheme': 'http', 'X-Original-Uri': '/hub/user/student1/metrics', 'X-Forwarded-Proto': 'http,http', 'X-Forwarded-Port': '80,80', 'X-Forwarded-Host': 'our.hub.hostname', 'X-Forwarded-For': '10.138.0.8,10.36.2.109', 'X-Real-Ip': '10.138.0.8', 'Connection': 'close', 'Host': 'our.hub.hostname'})
    Traceback (most recent call last):
      File "/usr/local/lib/python3.6/dist-packages/tornado/web.py", line 1512, in _execute
        result = yield result
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 713, in get
        raise copy.copy(exc).with_traceback(exc.__traceback__)
      File "/usr/local/lib/python3.6/dist-packages/tornado/web.py", line 1512, in _execute
        result = yield result
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 720, in get
        yield gen.with_timeout(timedelta(seconds=self.slow_spawn_timeout), spawner._spawn_future)
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 445, in finish_user_spawn
        yield spawn_future
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/user.py", line 439, in spawn
        raise e
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/user.py", line 378, in spawn
        ip_port = yield gen.with_timeout(timedelta(seconds=spawner.start_timeout), f)
      File "/etc/jupyterhub/config/hub.extra-config.default.py", line 16, in start
        return (yield super().start())
      File "/usr/local/lib/python3.6/dist-packages/kubespawner/spawner.py", line 995, in start
        timeout=self.start_timeout
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/utils.py", line 135, in exponential_backoff
        raise TimeoutError(fail_message)
    TimeoutError: pod/jupyter-student1 did not start in 300 seconds!

[E 2018-08-02 19:11:05.254 JupyterHub log:114] {
      "Cookie": "jupyter-hub-token=\"2|1:0|10:1533154153|17:jupyter-hub-token|44:NTRmMWM1MTEzNGM4NGVmZjlkZThmMzlkN2VmMzFkNTM=|3ea9f804375ee7717755d7d29555d2651e44739e0d5ea893fb1e29dd6f7317c1\"; __utmc=245566491; __utma=245566491.541953767.1516150214.1518023937.1518044824.10; __utmz=245566491.1518044824.10.10.utmcsr=google|utmccn=(organic)|utmcmd=organic|utmctr=(not%20provided); _ga=GA1.2.541953767.1516150214; __unam=94a0df2-16241e706be-44fd8501-32; _xsrf=2|3c5a1938|6171708ec75e3ffc8390b3a57f0062ce|1532984087",
      "Accept-Language": "en-US,en;q=0.9",
      "Accept-Encoding": "gzip, deflate",
      "Referer": "http://our.hub.hostname/user/student1/notebooks/materials-su18/materials/su18/hw/hw10/hw10.ipynb?redirects=1",
      "User-Agent": "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36",
      "X-Requested-With": "XMLHttpRequest",
      "Accept": "application/json, text/javascript, */*; q=0.01",
      "X-Scheme": "http",
      "X-Original-Uri": "/hub/user/student1/metrics",
      "X-Forwarded-Proto": "http,http",
      "X-Forwarded-Port": "80,80",
      "X-Forwarded-Host": "our.hub.hostname",
      "X-Forwarded-For": "10.138.0.8,10.36.2.109",
      "X-Real-Ip": "10.138.0.8",
      "Connection": "close",
      "Host": "our.hub.hostname"
    }
[E 2018-08-02 19:11:05.254 JupyterHub log:122] 500 GET /hub/user/student1/metrics (student1@10.138.0.8) 7.26ms
[E 2018-08-02 19:11:05.299 JupyterHub base:711] Preventing implicit spawn for student1 because last spawn failed: pod/jupyter-student1 did not start in 300 seconds!
[E 2018-08-02 19:11:05.299 JupyterHub web:1591] Uncaught exception GET /hub/user/student1/metrics (10.138.0.8)
    HTTPServerRequest(protocol='http', host='our.hub.hostname', method='GET', uri='/hub/user/student1/metrics', version='HTTP/1.1', remote_ip='10.138.0.8', headers={'Cookie': 'jupyter-hub-token="2|1:0|10:1533154153|17:jupyter-hub-token|44:NTRmMWM1MTEzNGM4NGVmZjlkZThmMzlkN2VmMzFkNTM=|3ea9f804375ee7717755d7d29555d2651e44739e0d5ea893fb1e29dd6f7317c1"; __utmc=245566491; __utma=245566491.541953767.1516150214.1518023937.1518044824.10; __utmz=245566491.1518044824.10.10.utmcsr=google|utmccn=(organic)|utmcmd=organic|utmctr=(not%20provided); _ga=GA1.2.541953767.1516150214; __unam=94a0df2-16241e706be-44fd8501-32; _xsrf=2|3c5a1938|6171708ec75e3ffc8390b3a57f0062ce|1532984087', 'Accept-Language': 'en-US,en;q=0.9', 'Accept-Encoding': 'gzip, deflate', 'Referer': 'http://our.hub.hostname/user/student1/notebooks/materials-su18/materials/su18/project/project3/project3.ipynb', 'User-Agent': 'Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36', 'X-Requested-With': 'XMLHttpRequest', 'Accept': 'application/json, text/javascript, */*; q=0.01', 'X-Scheme': 'http', 'X-Original-Uri': '/hub/user/student1/metrics', 'X-Forwarded-Proto': 'http,http', 'X-Forwarded-Port': '80,80', 'X-Forwarded-Host': 'our.hub.hostname', 'X-Forwarded-For': '10.138.0.8,10.36.2.109', 'X-Real-Ip': '10.138.0.8', 'Connection': 'close', 'Host': 'our.hub.hostname'})
    Traceback (most recent call last):
      File "/usr/local/lib/python3.6/dist-packages/tornado/web.py", line 1512, in _execute
        result = yield result
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 713, in get
        raise copy.copy(exc).with_traceback(exc.__traceback__)
      File "/usr/local/lib/python3.6/dist-packages/tornado/web.py", line 1512, in _execute
        result = yield result
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 720, in get
        yield gen.with_timeout(timedelta(seconds=self.slow_spawn_timeout), spawner._spawn_future)
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 445, in finish_user_spawn
        yield spawn_future
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/user.py", line 439, in spawn
        raise e
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/user.py", line 378, in spawn
        ip_port = yield gen.with_timeout(timedelta(seconds=spawner.start_timeout), f)
      File "/etc/jupyterhub/config/hub.extra-config.default.py", line 16, in start
        return (yield super().start())
      File "/usr/local/lib/python3.6/dist-packages/kubespawner/spawner.py", line 995, in start
        timeout=self.start_timeout
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/utils.py", line 135, in exponential_backoff
        raise TimeoutError(fail_message)
    TimeoutError: pod/jupyter-student1 did not start in 300 seconds!

[E 2018-08-02 19:11:05.306 JupyterHub log:114] {
      "Cookie": "jupyter-hub-token=\"2|1:0|10:1533154153|17:jupyter-hub-token|44:NTRmMWM1MTEzNGM4NGVmZjlkZThmMzlkN2VmMzFkNTM=|3ea9f804375ee7717755d7d29555d2651e44739e0d5ea893fb1e29dd6f7317c1\"; __utmc=245566491; __utma=245566491.541953767.1516150214.1518023937.1518044824.10; __utmz=245566491.1518044824.10.10.utmcsr=google|utmccn=(organic)|utmcmd=organic|utmctr=(not%20provided); _ga=GA1.2.541953767.1516150214; __unam=94a0df2-16241e706be-44fd8501-32; _xsrf=2|3c5a1938|6171708ec75e3ffc8390b3a57f0062ce|1532984087",
      "Accept-Language": "en-US,en;q=0.9",
      "Accept-Encoding": "gzip, deflate",
      "Referer": "http://our.hub.hostname/user/student1/notebooks/materials-su18/materials/su18/project/project3/project3.ipynb",
      "User-Agent": "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36",
      "X-Requested-With": "XMLHttpRequest",
      "Accept": "application/json, text/javascript, */*; q=0.01",
      "X-Scheme": "http",
      "X-Original-Uri": "/hub/user/student1/metrics",
      "X-Forwarded-Proto": "http,http",
      "X-Forwarded-Port": "80,80",
      "X-Forwarded-Host": "our.hub.hostname",
      "X-Forwarded-For": "10.138.0.8,10.36.2.109",
      "X-Real-Ip": "10.138.0.8",
      "Connection": "close",
      "Host": "our.hub.hostname"
    }
[E 2018-08-02 19:11:05.306 JupyterHub log:122] 500 GET /hub/user/student1/metrics (student1@10.138.0.8) 10.63ms
[I 2018-08-02 19:11:06.215 JupyterHub log:122] 302 GET /user/student1/metrics → /hub/user/student1/metrics (@10.138.0.8) 0.99ms
[E 2018-08-02 19:11:06.250 JupyterHub base:711] Preventing implicit spawn for student1 because last spawn failed: pod/jupyter-student1 did not start in 300 seconds!

[E 2018-08-02 19:11:06.251 JupyterHub web:1591] Uncaught exception GET /hub/user/student1/metrics (10.138.0.8)
    HTTPServerRequest(protocol='http', host='our.hub.hostname', method='GET', uri='/hub/user/student1/metrics', version='HTTP/1.1', remote_ip='10.138.0.8', headers={'Cookie': 'jupyter-hub-token="2|1:0|10:1533154153|17:jupyter-hub-token|44:NTRmMWM1MTEzNGM4NGVmZjlkZThmMzlkN2VmMzFkNTM=|3ea9f804375ee7717755d7d29555d2651e44739e0d5ea893fb1e29dd6f7317c1"; __utmc=245566491; __utma=245566491.541953767.1516150214.1518023937.1518044824.10; __utmz=245566491.1518044824.10.10.utmcsr=google|utmccn=(organic)|utmcmd=organic|utmctr=(not%20provided); _ga=GA1.2.541953767.1516150214; __unam=94a0df2-16241e706be-44fd8501-32; _xsrf=2|3c5a1938|6171708ec75e3ffc8390b3a57f0062ce|1532984087', 'Accept-Language': 'en-US,en;q=0.9', 'Accept-Encoding': 'gzip, deflate', 'Referer': 'http://our.hub.hostname/user/student1/notebooks/materials-su18/materials/su18/project/project3/project3.ipynb', 'User-Agent': 'Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36', 'X-Requested-With': 'XMLHttpRequest', 'Accept': 'application/json, text/javascript, */*; q=0.01', 'X-Scheme': 'http', 'X-Original-Uri': '/hub/user/student1/metrics', 'X-Forwarded-Proto': 'http,http', 'X-Forwarded-Port': '80,80', 'X-Forwarded-Host': 'our.hub.hostname', 'X-Forwarded-For': '10.138.0.8,10.36.2.109', 'X-Real-Ip': '10.138.0.8', 'Connection': 'close', 'Host': 'our.hub.hostname'})
    Traceback (most recent call last):
      File "/usr/local/lib/python3.6/dist-packages/tornado/web.py", line 1512, in _execute
        result = yield result
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 713, in get
        raise copy.copy(exc).with_traceback(exc.__traceback__)
      File "/usr/local/lib/python3.6/dist-packages/tornado/web.py", line 1512, in _execute
        result = yield result
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 720, in get
        yield gen.with_timeout(timedelta(seconds=self.slow_spawn_timeout), spawner._spawn_future)
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 445, in finish_user_spawn
        yield spawn_future
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/user.py", line 439, in spawn
        raise e
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/user.py", line 378, in spawn
        ip_port = yield gen.with_timeout(timedelta(seconds=spawner.start_timeout), f)
      File "/etc/jupyterhub/config/hub.extra-config.default.py", line 16, in start
        return (yield super().start())
      File "/usr/local/lib/python3.6/dist-packages/kubespawner/spawner.py", line 995, in start
        timeout=self.start_timeout
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/utils.py", line 135, in exponential_backoff
        raise TimeoutError(fail_message)
    TimeoutError: pod/jupyter-student1 did not start in 300 seconds!

[E 2018-08-02 19:11:06.256 JupyterHub log:114] {
      "Cookie": "jupyter-hub-token=\"2|1:0|10:1533154153|17:jupyter-hub-token|44:NTRmMWM1MTEzNGM4NGVmZjlkZThmMzlkN2VmMzFkNTM=|3ea9f804375ee7717755d7d29555d2651e44739e0d5ea893fb1e29dd6f7317c1\"; __utmc=245566491; __utma=245566491.541953767.1516150214.1518023937.1518044824.10; __utmz=245566491.1518044824.10.10.utmcsr=google|utmccn=(organic)|utmcmd=organic|utmctr=(not%20provided); _ga=GA1.2.541953767.1516150214; __unam=94a0df2-16241e706be-44fd8501-32; _xsrf=2|3c5a1938|6171708ec75e3ffc8390b3a57f0062ce|1532984087",
      "Accept-Language": "en-US,en;q=0.9",
      "Accept-Encoding": "gzip, deflate",
      "Referer": "http://our.hub.hostname/user/student1/notebooks/materials-su18/materials/su18/project/project3/project3.ipynb",
      "User-Agent": "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36",
      "X-Requested-With": "XMLHttpRequest",
      "Accept": "application/json, text/javascript, */*; q=0.01",
      "X-Scheme": "http",
      "X-Original-Uri": "/hub/user/student1/metrics",
      "X-Forwarded-Proto": "http,http",
      "X-Forwarded-Port": "80,80",
      "X-Forwarded-Host": "our.hub.hostname",
      "X-Forwarded-For": "10.138.0.8,10.36.2.109",
      "X-Real-Ip": "10.138.0.8",
      "Connection": "close",
      "Host": "our.hub.hostname"
    }
[E 2018-08-02 19:11:06.256 JupyterHub log:122] 500 GET /hub/user/student1/metrics (student1@10.138.0.8) 8.45ms
[I 2018-08-02 19:11:06.689 JupyterHub base:722] Pending spawn for student2 didn't finish in 10.0 seconds
[I 2018-08-02 19:11:06.689 JupyterHub base:727] student2 is pending spawn
[E 2018-08-02 19:11:07.975 JupyterHub user:427] Unhandled error starting student2's server: pod/jupyter-student2 did not start in 300 seconds!

@willingc
Copy link
Contributor

willingc commented Aug 2, 2018

From the Gitter discussion:

what does work is

kubectl delete pods -l app=jupyterhub

all necessary pods will be recreated and if a user tries spawning their own one again it will work. it's the radical solution that impacts all users who’re actively using it - but the only one that reliably worked for me so far

@ryanlovett
Copy link
Contributor Author

ryanlovett commented Aug 2, 2018

Thanks @willingc! Found it, https://gitter.im/jupyterhub/jupyterhub?at=5b637310c917d40dc2340997.

That will kill off all pods but the proxy. In our case, killing only the hub pod is mostly effective, though there can be a handful of users who require server restarts.

@betatim
Copy link
Member

betatim commented Aug 3, 2018

@gedankenstuecke could you post the revision of the helm chart you have deployed? Just to make sure everyone knows which version you are on because it is a very recent one, not a stable release. I think that is important compared to Ryan's deployment which might be on a stable release.

@betatim
Copy link
Member

betatim commented Aug 3, 2018

On mybinder.org and @gedankenstuecke's deployment (openhumans.org) we saw this behaviour with revisions of the helm chart newer than the latest stable release. The symptoms were that a user logs in, their pod appears (kubectl get pods ... shows it is running and ready) but the hub does not notice. Eventually giving an error to the user and logging that the user pod never showed up.

We traced this to a problem in kubespawner which uses event reflectors to be notified of events related to pods. This seems to sometimes break and I'd say right now it isn't completely clear why/where the bug is. I think there is another bug because @gedankenstuecke and mybinder.org are both on (very) recent revision of the helm chart that include the first round of fixes to kubespawner.

@ryanlovett
Copy link
Contributor Author

@betatim Yep, 0.6. I tried to upgrade to a 0.7 when we first saw this problem but it didn't go cleanly. I went back to 0.6.

@gedankenstuecke
Copy link

Sorry for the delay in answering (I had my driving test this morning with the DMV ✅ 🚗).

The revision we're using should be v0.7-560a7cd.

@willingc
Copy link
Contributor

willingc commented Aug 9, 2018

A quick update...We're continuing to investigate the behavior of the pod reflectors losing track which we have mitigations in place. The other behavior that we are investigating is what happens after a pod is evicted, and we believe that this will involve modification of kubespawner.

If you run into this issue and can share any relevant logs or behavior information, we would appreciate adding the information here.

cc/@minrk

@yuvipanda
Copy link
Contributor

@minrk @willingc this is happening again now :(

@ryanlovett
Copy link
Contributor Author

We're seeing this on a new hub running v0.7-92ccb36.

@ryanlovett
Copy link
Contributor Author

I've pasted a simple grep of the user's username from the hub logs. I attempted to start and stop their server from /hub/admin on occasion and my user is "rylo":

[I 2018-08-22 17:56:59.382 JupyterHub base:499] User logged in: user1
[I 2018-08-22 17:56:59.444 JupyterHub log:158] 302 GET /hub/user-redirect/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb -> /user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.3) 8.58ms
[I 2018-08-22 17:56:59.498 JupyterHub log:158] 302 GET /user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb -> /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (@10.128.0.3) 0.88ms
[W 2018-08-22 17:57:09.577 JupyterHub base:679] User user1 is slow to start (timeout=10)
[I 2018-08-22 17:57:09.578 JupyterHub base:1016] user1 is pending spawn
[I 2018-08-22 17:57:09.579 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.3) 10028.36ms
[I 2018-08-22 17:58:23.720 JupyterHub base:972] Pending spawn for user1 didn't finish in 10.0 seconds
[I 2018-08-22 17:58:23.721 JupyterHub base:978] user1 is pending spawn
[I 2018-08-22 17:58:23.722 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.3) 10012.78ms
[I 2018-08-22 17:58:40.120 JupyterHub base:972] Pending spawn for user1 didn't finish in 10.0 seconds
[I 2018-08-22 17:58:40.121 JupyterHub base:978] user1 is pending spawn
[I 2018-08-22 17:58:40.122 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.3) 10013.37ms
[E 2018-08-22 18:01:49.202 JupyterHub user:474] Unhandled error starting user1's server: pod/jupyter-user1 did not start in 300 seconds!
[I 2018-08-22 18:01:49.202 JupyterHub spawner:1502] Deleting pod jupyter-user1
[W 2018-08-22 18:01:50.107 JupyterHub web:1667] 400 GET /hub/api/users/user1/server/progress (10.128.0.3): user1 is not starting...
[W 2018-08-22 18:01:50.108 JupyterHub log:158] 400 GET /hub/api/users/user1/server/progress (user1@10.128.0.3) 13.70ms
[W 2018-08-22 18:02:55.644 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:02:55.645 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 13.94ms
[W 2018-08-22 18:03:07.973 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:03:07.974 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.11ms
[I 2018-08-22 18:03:37.439 JupyterHub base:499] User logged in: user1
[I 2018-08-22 18:03:37.593 JupyterHub log:158] 302 GET /hub/user-redirect/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb -> /user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 17.67ms
[I 2018-08-22 18:03:37.649 JupyterHub log:158] 302 GET /user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb -> /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (@10.128.0.7) 0.91ms
[I 2018-08-22 18:03:37.710 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:03:37.711 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 11.73ms
[I 2018-08-22 18:03:42.937 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:03:42.939 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 11.03ms
[I 2018-08-22 18:03:48.396 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:03:48.398 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 10.80ms
[I 2018-08-22 18:03:53.688 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:03:53.690 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 12.33ms
[I 2018-08-22 18:03:58.971 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:03:58.973 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 12.18ms
[I 2018-08-22 18:04:04.276 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:04:04.278 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 12.41ms
[W 180822 18:04:05 cull_idle_servers:128] Not culling server user1 with pending stop
[I 2018-08-22 18:04:10.512 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:04:10.513 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 10.34ms
[I 2018-08-22 18:04:15.824 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:04:15.825 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 11.02ms
[W 2018-08-22 18:04:19.940 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:04:19.941 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.31ms
[I 2018-08-22 18:04:21.108 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:04:21.109 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 11.10ms
[W 2018-08-22 18:04:23.471 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:04:23.472 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.27ms
[I 2018-08-22 18:04:24.964 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:04:24.966 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 11.07ms
[W 2018-08-22 18:04:25.537 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:04:25.538 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 13.95ms
[W 2018-08-22 18:04:29.448 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:04:29.449 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 24.40ms
[I 2018-08-22 18:04:30.279 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:04:30.280 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 11.20ms
[W 2018-08-22 18:04:39.749 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:04:39.750 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.63ms
[W 2018-08-22 18:04:42.229 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:04:42.230 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.94ms
[W 2018-08-22 18:04:46.867 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:04:46.868 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.64ms
[W 2018-08-22 18:04:51.014 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:04:51.015 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.80ms
[I 2018-08-22 18:04:54.756 JupyterHub base:499] User logged in: user1
[I 2018-08-22 18:04:54.819 JupyterHub log:158] 302 GET /hub/user-redirect/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb -> /user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 8.80ms
[I 2018-08-22 18:04:54.872 JupyterHub log:158] 302 GET /user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb -> /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (@10.128.0.6) 0.90ms
[I 2018-08-22 18:04:54.933 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:04:54.935 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 11.50ms
[W 2018-08-22 18:04:55.714 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:04:55.715 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.64ms
[I 2018-08-22 18:05:00.203 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:00.205 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 12.23ms
[I 2018-08-22 18:05:05.463 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:05.464 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 10.55ms
[W 2018-08-22 18:05:06.513 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:06.514 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.60ms
[W 2018-08-22 18:05:10.333 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:10.334 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 13.57ms
[I 2018-08-22 18:05:10.727 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:10.729 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 11.83ms
[W 2018-08-22 18:05:14.247 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:14.248 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 13.61ms
[I 2018-08-22 18:05:16.018 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:16.020 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 11.85ms
[I 2018-08-22 18:05:21.506 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:21.508 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 10.94ms
[W 2018-08-22 18:05:22.740 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:22.741 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.08ms
[I 2018-08-22 18:05:26.864 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:26.866 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 11.78ms
[I 2018-08-22 18:05:32.235 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:32.237 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 11.54ms
[W 2018-08-22 18:05:33.024 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:33.025 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 13.83ms
[I 2018-08-22 18:05:37.586 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:37.588 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 11.40ms
[W 2018-08-22 18:05:38.197 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:38.198 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.31ms
[W 2018-08-22 18:05:40.068 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:40.069 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.69ms
[I 2018-08-22 18:05:42.912 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:42.913 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 11.78ms
[W 2018-08-22 18:05:46.856 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:46.857 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.45ms
[I 2018-08-22 18:05:48.203 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:48.205 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 12.68ms
[W 2018-08-22 18:05:50.197 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:50.198 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.19ms
[I 2018-08-22 18:05:53.496 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:53.497 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 13.43ms
[W 2018-08-22 18:05:53.852 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:53.853 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.90ms
[W 2018-08-22 18:05:58.174 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:05:58.175 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 18.52ms
[I 2018-08-22 18:05:58.785 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:05:58.787 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 13.84ms
[W 2018-08-22 18:06:01.883 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:06:01.884 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 18.46ms
[I 2018-08-22 18:06:04.090 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:06:04.093 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 14.92ms
[W 2018-08-22 18:06:06.963 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:06:06.965 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 19.22ms
[I 2018-08-22 18:06:09.374 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:06:09.376 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 14.25ms
[I 2018-08-22 18:06:14.711 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:06:14.713 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 12.46ms
[I 2018-08-22 18:06:20.372 JupyterHub base:978] user1 is pending stop
[I 2018-08-22 18:06:20.374 JupyterHub log:158] 200 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.6) 11.51ms
[E 2018-08-22 18:06:24.672 JupyterHub user:483] Failed to cleanup user1's server that failed to start
    TimeoutError: pod/jupyter-user1 did not disappear in 300 seconds!
[E 2018-08-22 18:06:24.673 JupyterHub gen:974] Exception in Future <Task finished coro=<BaseHandler.spawn_single_user.<locals>.finish_user_spawn() done, defined at /usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py:619> exception=TimeoutError('pod/jupyter-user1 did not start in 300 seconds!',)> after timeout
    TimeoutError: pod/jupyter-user1 did not start in 300 seconds!
[E 2018-08-22 18:06:24.674 JupyterHub gen:974] Exception in Future <Task finished coro=<BaseHandler.spawn_single_user.<locals>.finish_user_spawn() done, defined at /usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py:619> exception=TimeoutError('pod/jupyter-user1 did not start in 300 seconds!',)> after timeout
    TimeoutError: pod/jupyter-user1 did not start in 300 seconds!
[E 2018-08-22 18:06:24.674 JupyterHub gen:974] Exception in Future <Task finished coro=<BaseHandler.spawn_single_user.<locals>.finish_user_spawn() done, defined at /usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py:619> exception=TimeoutError('pod/jupyter-user1 did not start in 300 seconds!',)> after timeout
    TimeoutError: pod/jupyter-user1 did not start in 300 seconds!
[I 2018-08-22 18:06:24.674 JupyterHub users:510] Server user1 is ready
[W 2018-08-22 18:06:24.675 JupyterHub users:439] Stream closed while handling /hub/api/users/user1/server/progress
[I 2018-08-22 18:06:24.675 JupyterHub users:510] Server user1 is ready
[W 2018-08-22 18:06:24.675 JupyterHub users:439] Stream closed while handling /hub/api/users/user1/server/progress
[I 2018-08-22 18:06:24.675 JupyterHub users:510] Server user1 is ready
[W 2018-08-22 18:06:24.675 JupyterHub users:439] Stream closed while handling /hub/api/users/user1/server/progress
[I 2018-08-22 18:06:24.675 JupyterHub users:510] Server user1 is ready
[W 2018-08-22 18:06:24.675 JupyterHub users:439] Stream closed while handling /hub/api/users/user1/server/progress
[I 2018-08-22 18:06:24.675 JupyterHub users:510] Server user1 is ready
[W 2018-08-22 18:06:24.676 JupyterHub users:439] Stream closed while handling /hub/api/users/user1/server/progress
[I 2018-08-22 18:06:24.676 JupyterHub users:510] Server user1 is ready
[W 2018-08-22 18:06:24.676 JupyterHub users:439] Stream closed while handling /hub/api/users/user1/server/progress
[I 2018-08-22 18:06:24.676 JupyterHub log:158] 200 GET /hub/api/users/user1/server/progress (user1@10.128.0.3) 554800.22ms
[I 2018-08-22 18:06:24.676 JupyterHub log:158] 200 GET /hub/api/users/user1/server/progress (user1@10.128.0.3) 491030.26ms
[I 2018-08-22 18:06:24.677 JupyterHub log:158] 200 GET /hub/api/users/user1/server/progress (user1@10.128.0.3) 480663.36ms
[I 2018-08-22 18:06:24.677 JupyterHub log:158] 200 GET /hub/api/users/user1/server/progress (user1@10.128.0.3) 464108.11ms
[I 2018-08-22 18:06:24.677 JupyterHub log:158] 200 GET /hub/api/users/user1/server/progress (user1@10.128.0.3) 400954.83ms
[I 2018-08-22 18:06:24.677 JupyterHub log:158] 200 GET /hub/api/users/user1/server/progress (user1@10.128.0.3) 337672.95ms
[I 2018-08-22 18:06:25.671 JupyterHub log:158] 302 GET /hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb -> /user/user1/git-sync?repo=https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18&subPath=materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb&redirects=1 (user1@10.128.0.6) 10.80ms
[I 2018-08-22 18:06:25.729 JupyterHub log:158] 302 GET /user/user1/git-sync?repo=https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18&subPath=materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb&redirects=1 -> /hub/user/user1/git-sync?repo=https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18&subPath=materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb&redirects=1 (@10.128.0.6) 1.00ms
[W 2018-08-22 18:06:25.803 JupyterHub base:1061] Redirect loop detected on /hub/user/user1/git-sync?repo=https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18&subPath=materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb&redirects=1
[I 2018-08-22 18:06:27.805 JupyterHub log:158] 302 GET /hub/user/user1/git-sync?repo=https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18&subPath=materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb&redirects=1 -> /user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=2 (user1@10.128.0.6) 2012.86ms
[W 2018-08-22 18:06:27.926 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is already running
[W 2018-08-22 18:06:27.927 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.95ms
[I 2018-08-22 18:06:28.147 JupyterHub log:158] 302 GET /user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=2 -> /hub/user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=2 (@10.128.0.6) 1.01ms
[W 2018-08-22 18:06:28.221 JupyterHub web:1667] 500 GET /hub/user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=2 (10.128.0.6): Redirect loop detected. Notebook has jupyterhub version unknown (likely < 0.8), but the Hub expects 0.9.1. Try installing jupyterhub==0.9.1 in the user environment if you continue to have problems.
      "Referer": "https://datahub.berkeley.edu/hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb",
      "X-Original-Uri": "/hub/user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=2",
[E 2018-08-22 18:06:28.223 JupyterHub log:158] 500 GET /hub/user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=2 (user1@10.128.0.6) 11.64ms
[I 2018-08-22 18:06:54.853 JupyterHub log:158] 302 GET /hub/user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D -> /user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=1 (user1@10.128.0.6) 10.74ms
[I 2018-08-22 18:06:54.913 JupyterHub log:158] 302 GET /user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=1 -> /hub/user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=1 (@10.128.0.6) 0.93ms
[W 2018-08-22 18:06:54.975 JupyterHub base:1061] Redirect loop detected on /hub/user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=1
[I 2018-08-22 18:06:56.977 JupyterHub log:158] 302 GET /hub/user/user1/git-sync?repo=%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D&subPath=%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D&redirects=1 -> /user/user1/git-sync?repo=%5B%22%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D%22%5D&subPath=%5B%22%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D%22%5D&redirects=2 (user1@10.128.0.6) 2012.89ms
[I 2018-08-22 18:06:57.389 JupyterHub log:158] 302 GET /user/user1/git-sync?repo=%5B%22%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D%22%5D&subPath=%5B%22%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D%22%5D&redirects=2 -> /hub/user/user1/git-sync?repo=%5B%22%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D%22%5D&subPath=%5B%22%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D%22%5D&redirects=2 (@10.128.0.6) 0.94ms
[W 2018-08-22 18:06:57.451 JupyterHub web:1667] 500 GET /hub/user/user1/git-sync?repo=%5B%22%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D%22%5D&subPath=%5B%22%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D%22%5D&redirects=2 (10.128.0.6): Redirect loop detected. Notebook has jupyterhub version unknown (likely < 0.8), but the Hub expects 0.9.1. Try installing jupyterhub==0.9.1 in the user environment if you continue to have problems.
      "Referer": "https://datahub.berkeley.edu/hub/user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb",
      "X-Original-Uri": "/hub/user/user1/git-sync?repo=%5B%22%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D%22%5D&subPath=%5B%22%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D%22%5D&redirects=2",
[E 2018-08-22 18:06:57.453 JupyterHub log:158] 500 GET /hub/user/user1/git-sync?repo=%5B%22%5B%27https%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%27%5D%22%5D&subPath=%5B%22%5B%27materials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb%27%5D%22%5D&redirects=2 (user1@10.128.0.6) 12.79ms
[I 2018-08-22 18:07:04.015 JupyterHub log:158] 200 GET /hub/home (user1@10.128.0.6) 11.72ms
[W 2018-08-22 18:07:04.997 JupyterHub proxy:324] Adding missing route for /user/user1/ (<jupyterhub.objects.Server object at 0x7f5a0c2289b0>)
[I 2018-08-22 18:07:04.998 JupyterHub proxy:242] Adding user user1 to proxy /user/user1/ => http://hub-66d67846f9-qlcnh:47097
[I 2018-08-22 18:07:05.132 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 2.13ms
[I 2018-08-22 18:07:07.165 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.65ms
[I 2018-08-22 18:07:17.500 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.78ms
[I 2018-08-22 18:07:24.190 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 2.62ms
[I 2018-08-22 18:07:27.859 JupyterHub proxy:264] Removing user user1 from proxy (/user/user1/)
[I 2018-08-22 18:07:27.862 JupyterHub spawner:1502] Deleting pod jupyter-user1
2018-08-22 18:07:27,865 WARNING Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ProtocolError('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer'))': /api/v1/namespaces/datahub-prod/pods/jupyter-user1?gracePeriodSeconds=1
WARNING:urllib3.connectionpool:Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ProtocolError('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer'))': /api/v1/namespaces/datahub-prod/pods/jupyter-user1?gracePeriodSeconds=1
[W 2018-08-22 18:07:27.884 JupyterHub spawner:1515] No pod jupyter-user1 to delete. Assuming already deleted.
[I 2018-08-22 18:07:33.236 JupyterHub log:158] 200 GET /hub/home (user1@10.128.0.6) 11.83ms
[W 2018-08-22 18:07:37.860 JupyterHub base:751] User user1: server is slow to stop
[I 2018-08-22 18:07:37.861 JupyterHub log:158] 202 DELETE /hub/api/users/user1/server (acheema@10.128.0.3) 10014.07ms
[W 2018-08-22 18:08:35.557 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:08:35.558 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 13.70ms
[W 2018-08-22 18:08:39.527 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:08:39.529 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.86ms
[W 2018-08-22 18:08:43.849 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:08:43.850 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 13.78ms
[W 2018-08-22 18:08:48.074 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:08:48.075 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.51ms
[W 2018-08-22 18:08:57.479 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:08:57.480 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.63ms
[W 2018-08-22 18:09:03.984 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:09:03.985 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.06ms
[W 2018-08-22 18:09:15.796 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:09:15.797 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 13.58ms
[W 2018-08-22 18:09:22.779 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:09:22.780 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 13.97ms
[W 2018-08-22 18:09:28.513 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:09:28.514 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.39ms
[W 2018-08-22 18:09:44.899 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:09:44.900 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.26ms
[W 2018-08-22 18:09:47.536 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:09:47.537 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.68ms
[W 2018-08-22 18:10:01.307 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:10:01.308 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 16.52ms
[W 2018-08-22 18:10:05.103 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:10:05.104 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 22.58ms
[W 2018-08-22 18:10:17.533 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:10:17.534 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.96ms
[W 2018-08-22 18:10:24.988 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:10:24.989 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.10ms
[W 2018-08-22 18:10:28.822 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:10:28.823 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.54ms
[W 2018-08-22 18:10:40.176 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:10:40.177 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 13.74ms
[W 2018-08-22 18:10:45.692 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:10:45.693 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.48ms
[W 2018-08-22 18:11:00.479 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:11:00.480 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.38ms
[W 2018-08-22 18:11:05.783 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:11:05.784 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.21ms
[W 2018-08-22 18:11:23.489 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:11:23.490 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 16.44ms
[W 2018-08-22 18:11:28.744 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:11:28.745 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.01ms
[W 2018-08-22 18:11:45.881 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:11:45.882 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.25ms
[W 2018-08-22 18:11:51.114 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:11:51.115 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 15.38ms
[W 2018-08-22 18:12:10.424 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:12:10.425 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 16.19ms
[E 2018-08-22 18:12:14.374 JupyterHub gen:974] Exception in Future <Task finished coro=<BaseHandler.stop_single_user.<locals>.stop() done, defined at /usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py:730> exception=TimeoutError('pod/jupyter-user1 did not disappear in 300 seconds!',)> after timeout
    TimeoutError: pod/jupyter-user1 did not disappear in 300 seconds!
[I 2018-08-22 18:12:49.020 JupyterHub log:158] 302 GET /user/user1/ -> /hub/user/user1/ (@10.128.0.4) 0.82ms
[I 2018-08-22 18:12:49.085 JupyterHub log:158] 302 GET /hub/user/user1/ -> /user/user1/?redirects=1 (user1@10.128.0.4) 10.99ms
[I 2018-08-22 18:12:49.139 JupyterHub log:158] 302 GET /user/user1/?redirects=1 -> /hub/user/user1/?redirects=1 (@10.128.0.4) 0.96ms
[W 2018-08-22 18:12:49.201 JupyterHub base:1061] Redirect loop detected on /hub/user/user1/?redirects=1
[I 2018-08-22 18:12:51.203 JupyterHub log:158] 302 GET /hub/user/user1/?redirects=1 -> /user/user1/?redirects=2 (user1@10.128.0.4) 2012.25ms
[I 2018-08-22 18:12:51.386 JupyterHub log:158] 302 GET /user/user1/?redirects=2 -> /hub/user/user1/?redirects=2 (@10.128.0.4) 0.77ms
[W 2018-08-22 18:12:51.451 JupyterHub web:1667] 500 GET /hub/user/user1/?redirects=2 (10.128.0.4): Redirect loop detected. Notebook has jupyterhub version unknown (likely < 0.8), but the Hub expects 0.9.1. Try installing jupyterhub==0.9.1 in the user environment if you continue to have problems.
      "X-Original-Uri": "/hub/user/user1/?redirects=2",
[E 2018-08-22 18:12:51.454 JupyterHub log:158] 500 GET /hub/user/user1/?redirects=2 (user1@10.128.0.4) 13.85ms
[W 2018-08-22 18:13:04.994 JupyterHub proxy:324] Adding missing route for /user/user1/ (<jupyterhub.objects.Server object at 0x7f5a0c2289b0>)
[I 2018-08-22 18:13:04.995 JupyterHub proxy:242] Adding user user1 to proxy /user/user1/ => http://hub-66d67846f9-qlcnh:47097
[I 2018-08-22 18:13:34.879 JupyterHub base:499] User logged in: user1
[I 2018-08-22 18:13:34.940 JupyterHub log:158] 302 GET /hub/user-redirect/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb -> /user/user1/git-sync?repo=https://github.com/data-8/materials-fa18&subPath=materials/fa18/lab/lab01/lab01.ipynb (user1@10.128.0.7) 9.15ms
[I 2018-08-22 18:13:35.025 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2Fgit-sync%3Frepo%3Dhttps%3A%2F%2Fgithub.com%2Fdata-8%2Fmaterials-fa18%26subPath%3Dmaterials%2Ffa18%2Flab%2Flab01%2Flab01.ipynb (@10.20.0.88) 1.67ms
[I 2018-08-22 18:13:46.790 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.66ms
[I 2018-08-22 18:14:06.359 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.79ms
[I 2018-08-22 18:14:13.112 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 2.58ms
[I 2018-08-22 18:15:11.260 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.83ms
[I 2018-08-22 18:15:12.181 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.64ms
[I 2018-08-22 18:15:12.714 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 2.47ms
[I 2018-08-22 18:15:13.254 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.72ms
[I 2018-08-22 18:16:26.695 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.88ms
[I 2018-08-22 18:16:28.572 JupyterHub proxy:264] Removing user user1 from proxy (/user/user1/)
[I 2018-08-22 18:16:28.576 JupyterHub spawner:1502] Deleting pod jupyter-user1
[W 2018-08-22 18:16:28.585 JupyterHub spawner:1515] No pod jupyter-user1 to delete. Assuming already deleted.
[W 2018-08-22 18:16:38.573 JupyterHub base:751] User user1: server is slow to stop
[I 2018-08-22 18:16:38.574 JupyterHub log:158] 202 DELETE /hub/api/users/user1/server (acheema@10.128.0.3) 10020.33ms
[W 2018-08-22 18:17:13.653 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:17:13.654 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.58ms
[W 2018-08-22 18:17:21.386 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.3): user1 is pending stop
[W 2018-08-22 18:17:21.387 JupyterHub log:158] 400 POST /hub/api/users/user1/server (acheema@10.128.0.3) 14.48ms
[W 2018-08-22 18:18:06.334 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.4): user1 is pending stop
[W 2018-08-22 18:18:06.335 JupyterHub log:158] 400 POST /hub/api/users/user1/server (rylo@10.128.0.4) 14.96ms
[W 2018-08-22 18:18:49.188 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.4): user1 is pending stop
[W 2018-08-22 18:18:49.188 JupyterHub log:158] 400 POST /hub/api/users/user1/server (rylo@10.128.0.4) 15.41ms
[E 2018-08-22 18:21:06.565 JupyterHub gen:974] Exception in Future <Task finished coro=<BaseHandler.stop_single_user.<locals>.stop() done, defined at /usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py:730> exception=TimeoutError('pod/jupyter-user1 did not disappear in 300 seconds!',)> after timeout
    TimeoutError: pod/jupyter-user1 did not disappear in 300 seconds!
[W 2018-08-22 18:22:04.982 JupyterHub proxy:324] Adding missing route for /user/user1/ (<jupyterhub.objects.Server object at 0x7f5a0c2289b0>)
[I 2018-08-22 18:22:04.983 JupyterHub proxy:242] Adding user user1 to proxy /user/user1/ => http://hub-66d67846f9-qlcnh:47097
[I 2018-08-22 18:22:10.982 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.73ms
[I 2018-08-22 18:22:12.214 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.69ms
[I 2018-08-22 18:22:14.987 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.76ms
[I 2018-08-22 18:23:02.654 JupyterHub log:158] 200 GET /hub/error/503?url=%2Fuser%2Fuser1%2F (@10.20.0.88) 1.60ms
[I 2018-08-22 18:23:17.426 JupyterHub proxy:264] Removing user user1 from proxy (/user/user1/)
[I 2018-08-22 18:23:17.429 JupyterHub spawner:1502] Deleting pod jupyter-user1
[W 2018-08-22 18:23:17.436 JupyterHub spawner:1515] No pod jupyter-user1 to delete. Assuming already deleted.
[W 2018-08-22 18:23:27.427 JupyterHub base:751] User user1: server is slow to stop
[I 2018-08-22 18:23:27.428 JupyterHub log:158] 202 DELETE /hub/api/users/user1/server (rylo@10.128.0.4) 10015.33ms
[W 2018-08-22 18:23:39.847 JupyterHub web:1667] 400 POST /hub/api/users/user1/server (10.128.0.4): user1 is pending stop
[W 2018-08-22 18:23:39.848 JupyterHub log:158] 400 POST /hub/api/users/user1/server (rylo@10.128.0.4) 29.04ms
[I 2018-08-22 18:23:54.457 JupyterHub log:158] 200 GET /hub/home (user1@10.128.0.6) 10.48ms

@minrk
Copy link
Member

minrk commented Apr 16, 2019

I believe this will be fixed by #2297 which verifies that a server is at the right URL during startup. There was a situation where spawners could be listed as running at the wrong URL if the Hub was restarted while the pod was mid-launch.

@consideRatio
Copy link
Member

Closing as outdated or assumed to be fixed by #2297.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

7 participants