TLJH: Failure setting up Development Environment: "Failed to start jupyterhub.service."

JupyterHub The Littlest JupyterHub
,
1

Hello,
since last week, I am unable to set up a TLJH Development Environment as described here:
https://tljh.jupyter.org/en/latest/contributing/dev-setup.html.

Up until January 23 2023 the process went smoothly, but after rebuilding the image last Friday (27 January), after running bootstrap.py in the container, the server doesn’t spawn. Browsing to my localhost:12000 I just see the message “404 page not found”.

I am running TLJH in a container in an Ubuntu 22.04 host, running Docker version 20.10.21.
On the same host, when using the image I build before January 23 with the same method I can spawn the server ok. There were no new commits on the TLJH repo since, so the issue should not be there.

Here is the output of journalctl -u jupyterhub -f ran inside the container:

-- Logs begin at Mon 2023-01-30 12:44:34 UTC. --
Jan 30 12:44:41 87f857896c91 python3[64]:         raise exc.ArgumentError(msg, code=code) from err
Jan 30 12:44:41 87f857896c91 python3[64]:     sqlalchemy.exc.ArgumentError: Column expression, FROM clause, or other columns clause element expected, got [1]. Did you mean to say select(1)?
Jan 30 12:44:41 87f857896c91 python3[64]:     
Jan 30 12:44:41 87f857896c91 systemd[1]: jupyterhub.service: Main process exited, code=exited, status=1/FAILURE
Jan 30 12:44:41 87f857896c91 systemd[1]: jupyterhub.service: Failed with result 'exit-code'.
Jan 30 12:44:41 87f857896c91 systemd[1]: jupyterhub.service: Scheduled restart job, restart counter is at 5.
Jan 30 12:44:41 87f857896c91 systemd[1]: Stopped jupyterhub.service.
Jan 30 12:44:41 87f857896c91 systemd[1]: jupyterhub.service: Start request repeated too quickly.
Jan 30 12:44:41 87f857896c91 systemd[1]: jupyterhub.service: Failed with result 'exit-code'.
Jan 30 12:44:41 87f857896c91 systemd[1]: Failed to start jupyterhub.service.

Is anyone else experiancing the same issue? Any ideas for further troubleshooting?

Thanks!

2

I just followd the tljh dev setup and the full traceback from the systemd journnal is below showing it’s failing in initdb. I suspect this is a sqlalchemy 2.0 issue which was released on 1/26 per SQLAlchemy Documentation — SQLAlchemy 2.0 Documentation

Jan 30 15:05:51 1a4911f9df26 python3[2771]: [I 2023-01-30 15:05:51.650 JupyterHub app:2480] Running JupyterHub version 1.5.1
Jan 30 15:05:51 1a4911f9df26 python3[2771]: [I 2023-01-30 15:05:51.650 JupyterHub app:2510] Using Authenticator: firstuseauthenticator.firstuseauthenticator.FirstUseAuthenticator
Jan 30 15:05:51 1a4911f9df26 python3[2771]: [I 2023-01-30 15:05:51.650 JupyterHub app:2510] Using Spawner: traitlets.traitlets.UserCreatingSpawner-5.9.0
Jan 30 15:05:51 1a4911f9df26 python3[2771]: [I 2023-01-30 15:05:51.650 JupyterHub app:2510] Using Proxy: jupyterhub_traefik_proxy.toml.TraefikTomlProxy-0+unknown
Jan 30 15:05:51 1a4911f9df26 python3[2771]: [I 2023-01-30 15:05:51.660 JupyterHub app:1554] Loading cookie_secret from /opt/tljh/state/jupyterhub_cookie_secret
Jan 30 15:05:51 1a4911f9df26 python3[2771]: [I 2023-01-30 15:05:51.735 alembic.runtime.migration migration:205] Context impl SQLiteImpl.
Jan 30 15:05:51 1a4911f9df26 python3[2771]: [I 2023-01-30 15:05:51.735 alembic.runtime.migration migration:208] Will assume non-transactional DDL.
Jan 30 15:05:51 1a4911f9df26 python3[2771]: [E 2023-01-30 15:05:51.744 JupyterHub app:2991]
Jan 30 15:05:51 1a4911f9df26 python3[2771]:     Traceback (most recent call last):
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/jupyterhub/app.py", line 2988, in launch_instance_async
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         await self.initialize(argv)
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/jupyterhub/app.py", line 2522, in initialize
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         self.init_db()
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/jupyterhub/app.py", line 1726, in init_db
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         self.session_factory = orm.new_session_factory(
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/jupyterhub/orm.py", line 880, in new_session_factory
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         check_db_revision(engine)
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/jupyterhub/orm.py", line 771, in check_db_revision
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         current_table_names = set(inspect(engine).get_table_names())
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/inspection.py", line 111, in inspect
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         ret = reg(subject)
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/engine/reflection.py", line 304, in _engine_insp
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         return Inspector._construct(Inspector._init_engine, bind)
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/engine/reflection.py", line 237, in _construct
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         init(self, bind)
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/engine/reflection.py", line 248, in _init_engine
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         engine.connect().close()
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 3245, in connect
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         return self._connection_cls(self)
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 174, in __init__
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         self.dispatch.engine_connect(self)
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/event/attr.py", line 487, in __call__
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         fn(*args, **kw)
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/event/legacy.py", line 100, in wrap_leg
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         return fn(*conv(*args))
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/jupyterhub/orm.py", line 737, in ping_connection
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         connection.scalar(select([1]))
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/sql/_selectable_constructors.py", line 493, in select
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         return Select(*entities)
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/sql/selectable.py", line 5219, in __init__
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         self._raw_columns = [
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/sql/selectable.py", line 5220, in <listcomp>
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         coercions.expect(
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/sql/coercions.py", line 413, in expect
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         resolved = impl._literal_coercion(
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/sql/coercions.py", line 652, in _literal_coercion
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         self._raise_for_expected(element, argname)
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/sql/coercions.py", line 1143, in _raise_for_expected
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         return super()._raise_for_expected(
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/sql/coercions.py", line 711, in _raise_for_expected
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         super()._raise_for_expected(
Jan 30 15:05:51 1a4911f9df26 python3[2771]:       File "/opt/tljh/hub/lib/python3.8/site-packages/sqlalchemy/sql/coercions.py", line 536, in _raise_for_expected
Jan 30 15:05:51 1a4911f9df26 python3[2771]:         raise exc.ArgumentError(msg, code=code) from err
Jan 30 15:05:51 1a4911f9df26 python3[2771]:     sqlalchemy.exc.ArgumentError: Column expression, FROM clause, or other columns clause element expected, got [1]. Did you mean to say select(1)?
Jan 30 15:05:51 1a4911f9df26 python3[2771]:
3

Downgrading in the container and the hub virtualenv works for me

/opt/tljh/hub/bin/pip3 install --upgrade 'SQLAlchemy<2.0.0'

Jan 30 15:13:44 1a4911f9df26 systemd[1]: Started jupyterhub.service.
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.611 JupyterHub app:2480] Running JupyterHub version 1.5.1
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.611 JupyterHub app:2510] Using Authenticator: firstuseauthenticator.firstuseauthenticator.FirstUseAuthenticator
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.611 JupyterHub app:2510] Using Spawner: traitlets.traitlets.UserCreatingSpawner-5.9.0
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.611 JupyterHub app:2510] Using Proxy: jupyterhub_traefik_proxy.toml.TraefikTomlProxy-0+unknown
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.618 JupyterHub app:1554] Loading cookie_secret from /opt/tljh/state/jupyterhub_cookie_secret
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.680 alembic.runtime.migration migration:205] Context impl SQLiteImpl.
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.680 alembic.runtime.migration migration:208] Will assume non-transactional DDL.
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.694 alembic.runtime.migration migration:205] Context impl SQLiteImpl.
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.694 alembic.runtime.migration migration:208] Will assume non-transactional DDL.
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.796 JupyterHub app:1858] Not using allowed_users. Any authenticated user will be allowed.
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.889 JupyterHub app:2547] Initialized 0 spawners in 0.003 seconds
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.892 JupyterHub app:2760] Not starting proxy
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.893 JupyterHub app:2796] Hub API listening on http://127.0.0.1:15001/hub/
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.893 JupyterHub app:2811] Starting managed service cull-idle
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.893 JupyterHub service:339] Starting service 'cull-idle': ['/opt/tljh/hub/bin/python3', '-m', 'jupyterhub_idle_culler', '--timeout=600', '--cull-every=60', '--concurrency=5', '--max-age=0']
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.897 JupyterHub service:121] Spawning /opt/tljh/hub/bin/python3 -m jupyterhub_idle_culler --timeout=600 --cull-every=60 --concurrency=5 --max-age=0
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.904 JupyterHub proxy:347] Checking routes
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.904 JupyterHub proxy:432] Adding route for Hub: / => http://127.0.0.1:15001
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.906 JupyterHub proxy:135] Waiting for / to register with traefik
Jan 30 15:13:45 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:45.914 JupyterHub app:2871] JupyterHub is now running at http://:8000
Jan 30 15:13:46 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:46.054 JupyterHub log:189] 200 GET /hub/api/ (cull-idle@127.0.0.1) 13.34ms
Jan 30 15:13:46 1a4911f9df26 python3[2829]: [I 2023-01-30 15:13:46.064 JupyterHub log:189] 200 GET /hub/api/users?state=[secret] (cull-idle@127.0.0.1) 7.59ms
4

Thank you! I tried before with /opt/tljh/hub/bin/pip install --force-reinstall -v "SQLAlchemy==1.4.46" but it didn’t work.

Your solution worked, after an extra sudo tljh-config reload hub

5

Great I’ll file a bug and and a PR to pin the version below 2.0.0

6

You can follow the issue here `jupyterhub.service` process exits on `ubuntu-2004-lts` on initial installation · Issue #846 · jupyterhub/the-littlest-jupyterhub · GitHub

7

There is an excellent youtube video how to install TLJH on small arm based device
[The “The Little JupyterHub (tljh)” installation - YouTube]