500 Error after logging in on k8s 1.16

[michitaro]

I got 500 error after logging in to JupyterHub.

1. Log in to JupyterHub
2. 500 error occured

How I installed z2jh

I have installed z2jh onto self-hosted cluster (set up by kubeadm) with commands below.

$ RELEASE=jhub
$ NAMESPACE=jhub

$ helm upgrade --install $RELEASE jupyterhub/jupyterhub \
  --namespace $NAMESPACE  \
  --version=0.8.2 \
  --values config.yaml

$ cat config.yaml
proxy:
  secretToken: "--randomnumber--"

Because I don't have external IP provider, I have changed spec.type of service/public-proxy to NodePort.

Environments

kubectl version
Client Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.1", GitCommit:"d647ddbd755faf07169599a625faf302ffc34458", GitTreeState:"clean", BuildDate:"2019-10-02T17:01:15Z", GoVersion:"go1.12.10", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.1", GitCommit:"d647ddbd755faf07169599a625faf302ffc34458", GitTreeState:"clean", BuildDate:"2019-10-02T16:51:36Z", GoVersion:"go1.12.10", Compiler:"gc", Platform:"linux/amd64"}

Inspections

$ kubectl logs hub-d59bc9d4f-48c5l

[E 2019-10-03 23:55:52.553 JupyterHub base:1011] Preventing implicit spawn for test because last spawn failed: '<' not supported between instances of 'NoneType' and 'NoneType'
[E 2019-10-03 23:55:52.554 JupyterHub web:1788] Uncaught exception GET /hub/user/test/ (133.40.210.189)
    HTTPServerRequest(protocol='http', host='localhost:30080', method='GET', uri='/hub/user/test/', version='HTTP/1.1', remote_ip='133.40.210.189')
    Traceback (most recent call last):
      File "/usr/local/lib/python3.6/dist-packages/tornado/web.py", line 1699, in _execute
        result = await result
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 1013, in get
        raise copy.copy(exc).with_traceback(exc.__traceback__)
      File "/usr/local/lib/python3.6/dist-packages/tornado/gen.py", line 589, in error_callback
        future.result()
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 636, in finish_user_spawn
        await spawn_future
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/user.py", line 489, in spawn
        raise e
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/user.py", line 409, in spawn
        url = await gen.with_timeout(timedelta(seconds=spawner.start_timeout), f)
      File "/usr/local/lib/python3.6/dist-packages/kubespawner/spawner.py", line 1637, in _start
        if events:
      File "/usr/local/lib/python3.6/dist-packages/kubespawner/spawner.py", line 1492, in events
        if event.involved_object.name != self.pod_name:
      File "/usr/local/lib/python3.6/dist-packages/kubespawner/spawner.py", line 73, in events
        )
    TypeError: '<' not supported between instances of 'NoneType' and 'NoneType'

[E 2019-10-03 23:55:52.562 JupyterHub log:150] {
      "X-Forwarded-Host": "localhost:30080",
      "X-Forwarded-Proto": "http",
      "X-Forwarded-Port": "30080",
      "X-Forwarded-For": "133.40.210.189",
      "Accept-Language": "en-us",
      "Accept-Encoding": "gzip, deflate",
      "Referer": "http://localhost:30080/hub/login",
      "User-Agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/13.0.1 Safari/605.1.15",
      "Accept": "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8",
      "Upgrade-Insecure-Requests": "1",
      "Connection": "close",
      "Cookie": "$some_secret_values",
      "Origin": "http://localhost:30080",
      "Host": "localhost:30080"
    }
[E 2019-10-03 23:55:52.562 JupyterHub log:158] 500 GET /hub/user/test/ (test@133.40.210.189) 43.97ms

The top of stack (File "/usr/local/lib/python3.6/dist-packages/kubespawner/spawner.py", line 73, in events) is here. The code assumes that every event objects always have non null last_timestamp, but sometimes event objects have null value for their last_timestamp (at least on my environment). While the spec doesn't mention either required or optional, actually I got such event from kubectl get events.

$ kubectl get events -ojsonpath="{range .items[*]}{.lastTimestamp}{'\t'}{.message}{'\n'}{end}" | expand -t 24
2019-10-04T00:03:52Z    waiting for a volume to be created, either by external provisioner "rook-ceph.rbd.csi.ceph.com" or manually created by system administrator
2019-10-04T00:03:52Z    External provisioner is provisioning volume for claim "jhub/claim-test"
<nil>                   pod has unbound immediate PersistentVolumeClaims
<nil>                   pod has unbound immediate PersistentVolumeClaims
<nil>                   Successfully assigned jhub/jupyter-test to niu.mtk.nao.ac.jp
2019-10-04T00:03:57Z    AttachVolume.Attach succeeded for volume "pvc-06076af8-529e-4e0b-a9af-d366c9e99f61"
2019-10-04T00:04:10Z    Container image "jupyterhub/k8s-network-tools:0.8.2" already present on machine
2019-10-04T00:04:10Z    Created container block-cloud-metadata
2019-10-04T00:04:10Z    Started container block-cloud-metadata
2019-10-04T00:04:11Z    Container image "jupyterhub/k8s-singleuser-sample:0.8.2" already present on machine
2019-10-04T00:04:12Z    Created container notebook
2019-10-04T00:04:12Z    Started container notebook
2019-10-04T00:04:15Z    Stopping container notebook
2019-10-04T00:02:34Z    No matching pods found
2019-10-04T00:02:34Z    No matching pods found

I can bypass the problem with this patch for kubespawner/spawner.py.

root@hub-d59bc9d4f-48c5l:/srv/jupyterhub# diff -c a b
*** a   2019-10-04 00:14:01.892597740 +0000
--- b   2019-10-04 00:13:46.252338190 +0000
***************
*** 69,75 ****
      def events(self):
          return sorted(
              self.resources.values(),
!             key=lambda x: x.last_timestamp,
          )

--- 69,75 ----
      def events(self):
          return sorted(
              self.resources.values(),
!             key=lambda x: x.last_timestamp and x.last_timestamp.timestamp() or 0.,
          )

The cause of the problem might be due to some my misconfiguration, but I'd like any comments on this.

[michitaro]

I found that this issue is also reported at #1433 and here

[betatim]

Thanks for reporting this with all the details and finding related tickets.

Should we close this in favour of https://github.com/jupyterhub/kubespawner/issues/354#issue-498060336? The best place to discuss kubespawner is probably in its repo.

[michitaro]

OK. I'll close this. Thanks.