Sporadic 500 error (spawn fails and empty JSON)

[YannBrrd]

Hi,

We have from times to times empty responses from mediator leading to 500 error for end user. It's hard to get the root cause now. Seems user can not spawn a process.

Anyone having the same issue ?

sudospawner/sudospawner/spawner.py

Line 80 in c291a89

data_str = data_str[data_str.index('{'):data_str.rindex('}')+1]

[E 2018-02-22 10:23:41.609 JupyterHub spawner:54] args: '{\'args\': [\'--user="XXXXX"\', \'--cookie-name="jupyter-hub-token-XXXX"\', \'--base-url="/user/XXXXX"\', \'--hub-host=""\', \'--hub-prefix="/hub/"\', \'--hub-api-url="http://127.0.0.1:8081/hub/api"\', \'--ip="127.0.0.1"\', \'--port=12345\', \'--debug\'], \'env\': {\'PATH\': \'/applis/anaconda/4.3/bin:/usr/lib64/qt-3.3/bin:/usr/local/bin:/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/applis/jupyterhub/.local/bin:/applis/jupyterhub/bin:/applis/anaconda/4.3/envs/py36_jupyter/bin\', \'LANG\': \'en_US.UTF-8\', \'JUPYTERHUB_API_TOKEN\': \'9fe54affb6c0424ab947d247ffea3d09\', \'JPY_API_TOKEN\': \'9fe54affb6c0424ab947d247ffea3d09\', \'USER\': \'XXXXXX\', \'HOME\': \'/home/XXXXX\', \'SHELL\': \'/bin/bash\'}, \'action\': \'spawn\'}'
[E 2018-02-22 10:23:41.609 JupyterHub spawner:55] user: 'XXXXXX'
[D 2018-02-22 10:23:41.609 JupyterHub spawner:62] Spawning ['sudo', '-u', 'XXXXXX', '-nH', '/applis/anaconda/4.3/envs/py36_jupyter/bin/sudospawner']
[E 2018-02-22 10:23:41.617 JupyterHub spawner:84] Failed to get JSON result from mediator: ''
[E 2018-02-22 10:23:41.620 JupyterHub user:251] Unhandled error starting XXXXXXX's server: substring not found
[E 2018-02-22 10:23:41.632 JupyterHub web:1590] Uncaught exception POST /hub/login?next= (175.128.8.46)
    HTTPServerRequest(protocol='https', host='phadlx205.haas.socgen:8788', method='POST', uri='/hub/login?next=', version='HTTP/1.1', remote_ip='175.128.8.46', headers={'X-Forwarded-Host': 'phadlx205.haas.socgen:8788', 'X-Forwarded-Proto': 'https', 'X-Forwarded-Port': '8788', 'X-Forwarded-For': '175.128.8.46', 'Accept-Language': 'fr-FR,fr;q=0.9,en-US;q=0.8,en;q=0.7', 'Accept-Encoding': 'gzip, deflate, br', 'Referer': 'https://phadlx205.haas.socgen:8788/hub/login', 'Accept': 'text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8', 'User-Agent': 'Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.108 Safari/537.36', 'Content-Type': 'application/x-www-form-urlencoded', 'Upgrade-Insecure-Requests': '1', 'Origin': 'https://phadlx205.haas.socgen:8788', 'Cache-Control': 'max-age=0', 'Content-Length': '46', 'Connection': 'close', 'Host': 'phadlx205.haas.socgen:8788'})
    Traceback (most recent call last):
      File "/applis/anaconda/4.3/envs/py36_jupyter/lib/python3.6/site-packages/tornado/web.py", line 1511, in _execute
        result = yield result
      File "/applis/anaconda/4.3/envs/py36_jupyter/lib/python3.6/site-packages/jupyterhub/handlers/login.py", line 84, in post
        yield self.spawn_single_user(user)
      File "/applis/anaconda/4.3/envs/py36_jupyter/lib/python3.6/site-packages/jupyterhub/handlers/base.py", line 328, in spawn_single_user
        yield gen.with_timeout(timedelta(seconds=self.slow_spawn_timeout), f)
      File "/applis/anaconda/4.3/envs/py36_jupyter/lib/python3.6/site-packages/jupyterhub/user.py", line 261, in spawn
        raise e
      File "/applis/anaconda/4.3/envs/py36_jupyter/lib/python3.6/site-packages/jupyterhub/user.py", line 229, in spawn
        ip_port = yield gen.with_timeout(timedelta(seconds=spawner.start_timeout), f)
      File "/applis/anaconda/4.3/envs/py36_jupyter/lib/python3.6/site-packages/sudospawner/spawner.py", line 92, in start
        yield self.do(action='spawn', args=self.get_args(), env=self.get_env())
      File "/applis/anaconda/4.3/envs/py36_jupyter/lib/python3.6/site-packages/sudospawner/spawner.py", line 81, in do
        data_str = data_str[data_str.index('{'):data_str.rindex('}')+1]
    ValueError: substring not found

[D 2018-02-22 10:23:41.636 JupyterHub base:462] No template for 500

Regards,
Yann

[trimdot]

A bit late to the party but I'm having that exact same issue after upgrading the jupyterhub packages to py36 via conda.

Anyone have any thoughts?

[radumas]

All of my non-admin users get this error when they login successfully.

EDIT

Figured out the problem: I forgot to add the user to the jupyterhub group and also forgot to change the last line in the sudoers configuration per this

Strangely enough I'm still getting some errors below.

[I 2018-12-17 12:55:18.439 JupyterHub log:158] 302 GET /user/username/ -> /hub/user/username/ (@137.15.35.177) 0.66ms
sh: 1: cannot create /run/motd.dynamic.new: Permission denied
Welcome to Ubuntu 16.04.5 LTS (GNU/Linux 4.4.0-137-generic x86_64)

 
[W 2018-12-17 12:55:18.517 JupyterHub auth:642] Failed to open PAM session for username: [PAM Error 14] Cannot make/remove an entry for the specified session
[W 2018-12-17 12:55:18.518 JupyterHub auth:643] Disabling PAM sessions from now on.
[I 181217 12:55:18 mediator:89] Spawning /usr/local/bin/jupyterhub-singleuser --port=41026
[I 2018-12-17 12:55:19.481 SingleUserNotebookApp singleuser:406] Starting jupyterhub-singleuser server version 0.9.4

[consideRatio]

This happened to me when testing/updating the outdated examples/Dockerfile. I think aiming for a more informative and guiding error message could be relevant here.