Jupyterhub: Jupyterhub is not resilient with external MySQL database

[ckbhatt]

We are using Jupyterhub with an external mariadb(open source fork of mysql) database. In the event of a temporary network failure, Jupyterhub gets stuck and do not recover.

How to reproduce the issue on mac

1. Install Mariadb locally
   brew install mariadb
2. Remove from launchctl for ease of stop and start
   launchctl unload -w ~/Library/LaunchAgents/homebrew.mxcl.mariadb.plist
3. Start mariadb
   brew services start mariadb
4. Create a database named jh_test
5. Create a user test/test in mac.
6. Run jupyter hub locally with following config file.

c = get_config()
c.Authenticator.whitelist = {'test'}
c.Authenticator.admin_users = {'test'}
c.JupyterHub.db_url = 'mysql+mysqlconnector://{}:{}@{}/{}{}'.format("root","","localhost","jh_test","")

1. Login using test/test and start jupyter server.
2. Stop mysql
   brew services stop mariadb
3. Go to browser and click on Control Panel button. You'll get following exception:

[E 2018-01-19 04:14:19.920 JupyterHub web:1518] Exception in exception handler
    Traceback (most recent call last):
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/tornado/web.py", line 1516, in _execute
        self._handle_request_exception(e)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/tornado/web.py", line 1570, in _handle_request_exception
        self.send_error(500, exc_info=sys.exc_info())
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/tornado/web.py", line 1040, in send_error
        self.finish()
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/jupyterhub/handlers/base.py", line 105, in finish
        super().finish(*args, **kwargs)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/tornado/web.py", line 993, in finish
        self._log()
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/tornado/web.py", line 1540, in _log
        self.application.log_request(self)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/tornado/web.py", line 2053, in log_request
        self.settings["log_function"](handler)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/jupyterhub/log.py", line 90, in log_request
        user = handler.get_current_user()
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/jupyterhub/handlers/base.py", line 229, in get_current_user
        return self.get_current_user_cookie()
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/jupyterhub/handlers/base.py", line 222, in get_current_user_cookie
        return self._user_for_cookie(self.hub.cookie_name)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/jupyterhub/handlers/base.py", line 206, in _user_for_cookie
        u = self.db.query(orm.User).filter(orm.User.cookie_id==cookie_id).first()
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2755, in first
        ret = list(self[0:1])
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2547, in __getitem__
        return list(res)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2855, in __iter__
        return self._execute_and_instances(context)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2878, in _execute_and_instances
        result = conn.execute(querycontext.statement, self._params)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 945, in execute
        return meth(self, multiparams, params)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/sql/elements.py", line 263, in _execute_on_connection
        return connection._execute_clauseelement(self, multiparams, params)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1053, in _execute_clauseelement
        compiled_sql, distilled_params
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1121, in _execute_context
        None, None)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1402, in _handle_dbapi_exception
        exc_info
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
        reraise(type(exception), exception, tb=exc_tb, cause=cause)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 186, in reraise
        raise value.with_traceback(tb)
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1114, in _execute_context
        conn = self._revalidate_connection()
      File "/Users/bhatt/anaconda3/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 424, in _revalidate_connection
        "Can't reconnect until invalid "
    sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back [SQL: 'SELECT users.id AS users_id, users.name AS users_name, users.`admin` AS users_admin, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state \nFROM users \nWHERE users.cookie_id = %(cookie_id_1)s \n LIMIT %(param_1)s'] [parameters: [{}]]

1. Start mariadb again
   brew services start mariadb
2. Refresh Jupyterhub page.
   What you expected to happen
   Jupyterhub should reconnect with DB and work normally as network interruptions are common scenarios. In above case DB was shutdown to mimic network interruption. Results are same with a remote DB and actual n/w interruption.
   What actually happens
   Jupyter hub keeps giving above exception and we need to restart hub for bringing it back to normal state.
   Share what version of JupyterHub you are using
   0.8.1

[willingc]

Thanks @ckbhatt for the report.

Results are same with a remote DB and actual n/w interruption.

Just to clarify your above statement. You are seeing the same results, as the tests, in a deployed JupyterHub with a network interruption. Correct?

[ckbhatt]

That is correct.

[ckbhatt]

This issue is still labelled as question. @willingc is there any other info that you need from me?

[ichasepucks]

@willingc, @minrk

I'm not an expert in this so forgive me if I'm just not understanding things correctly. However, all the SQLAlchemy docs with regard to executing a session transaction indicate they should be wrapped in a try/except block and rolled back in case of error. See http://docs.sqlalchemy.org/en/latest/orm/session_transaction.html.

However, that does not seem to be the practice in the code. See https://github.com/jupyterhub/jupyterhub/blob/master/jupyterhub/oauth/store.py#L199-L217 for one of dozens of examples where the self.db.commit() is not wrapped in a try/except block.

A google search reveals this as a general problem in any app using SQLAlchemy. Would you agree that the right fix here is to find all db commits and surround them with a try/except block? We might be willing to make that PR if you agree that's the issue here.

[minrk]

That would be great! We don't need to put every commit in a try/except, though, and we shouldn't try to do it that way. As long as we let the error raise and ensure that the rollback happens at the end of the Handler, we should be set. We already attempt to do that here, but it may not be firing in all cases. Some testing to ensure that rollback occurs correctly in one of these scenarios would be very helpful.

[ichasepucks]

That his helpful and makes a lot of sense. I will dig into that some more to understand how finish gets called. I would hope there is some high level except block which will catch all errors and then call finish.

[minrk]

There definitely is at the tornado level, we just need to make sure that it's finish that always gets called or something else. It's also possible that the dirty check is causing us to not rollback sometimes when we should.

[ichasepucks]

@minrk moving from gitter to here.
I think the right thing to do here is to call finish at the end of write_error https://github.com/jupyterhub/jupyterhub/blob/master/jupyterhub/handlers/base.py#L723. I've got that implemented. However, within finish, the self.db.dirty returns the IdentitySet. I don't understand why. Because of that, it doesn't do any rollbacks. If I call self.db.rollback() at the end of write_error it actually fixes the issue and when I bring the DB back online, there is no pending transaction and it's able to continue. Thoughts on the fact that dirty isn't returning anything?

[ichasepucks]

@minrk please see https://github.com/ckbhatt/jupyterhub/pull/3/files for what I'm testing on our internal fork. Once I'm happy with these and you are, I'll get them into a formal PR.

I'm not quite sure how to handle orm.py usages that may fail. For example https://github.com/jupyterhub/jupyterhub/blob/master/jupyterhub/app.py#L1226. I was able to fix update_last_activity which had been a problem for us as well.

Also, @willingc I can't see how this can be characterized as anything other than a bug?

[willingc]

Thanks for the follow-up. @ichasepucks, I'm cool with adding a bug label as well. I labeled it as enhancement since we will likely look at further improvements for dependability beyond things suggested here, and that will require incremental work. I hope you now can see why ;-)

[minrk]

.finish() is a special tornado method, so I'd like to not call it an additional time, in case it gets messed up. Instead, if finish is indeed not called after write_error (we should check that), then putting the rollback check in a place we can call from both finish and other places would be ideal.

We used to have an unconditional rollback on every request, but it turned out to be a major performance problem. So we need to call rollback only when it's actually required, which should be rare (i.e. only unhandled errors). Right now, I believe the dirty check is correctly catching uncommitted changes, but apparently not the commit error case.

BTW, feel free to open a PR with a work in progress. It doesn't need to be mergeable to get started, and we can discuss/iterate in the PR. That lets us comment on the code in-place, which can be useful.

It would be super useful if an error like this could be triggered synthetically in our tests. I haven't been able to do that, though. We do run our tests with mysql, if that helps.

[ichasepucks]

@minrk were you able to look at the PR I linked above? Here it is again, https://github.com/ckbhatt/jupyterhub/pull/3/files.

[ichasepucks]

@minrk bump for your initial thoughts on https://github.com/ckbhatt/jupyterhub/pull/3/files

[willingc]

Just an FYI @ichasepucks, @minrk has been teaching workshops at a conference in Europe this week.

[ichasepucks]

@willingc thanks for the update. It's no problem. I will be patient. :)

[ichasepucks]

@minrk any comments on this PR?

[minrk]

@ichasepucks please feel free to make a pull request to this repo and we can finish it up. I think those changes look about right.

[mak-aravind]

jupyterhub version used : 0.8.1
ERROR trigger point: The Postgres DB to which hub got connected went down. When Postgres resumes and when start my server button clicked after logged in to jupytehub, it tries to connect to Postgres and below error arises.

I am getting a similar error as mentioned by @ckbhatt but this time its for Postgres. The error got triggered when hub re-established its connection with a postgres instance. To this postgres it has written some data and its reporting those are invalid data and kept on looping with below error:

_sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back [SQL: 'SELECT users.id AS users_id, users.name AS users_name, users.admin AS users_admin, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state \nFROM users \nWHERE users.name = %(name_1)s \n LIMIT %(param_1)s'] [parameters: [{}]]_

Basically, the UI error is 500 internal server error.
More information

• hub is running on k8s and got connected to an instance of stolon - PostgreSQL cloud-native.
• The stolon postgresql also running on the same k8s cluster.
• Hub is resuming the connection only when all the entries in the users table got deleted. Just wondering what could be the root cause. Restarting hub also not helping

@minrk @ichasepucks does this PR got committed and pushed to repo.
@ckbhatt are you able to do any workaround to overcome this issue

The entire stack trace during this error:

[E 2018-05-06 17:35:28.851 JupyterHub ioloop:792] Exception in callback functools.partial(<function wrap.<locals>.null_wrapper at 0x7f114d8ce7b8>, <Future finished exception=StatementError("(sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back",)>)
    Traceback (most recent call last):
      File "/usr/local/lib/python3.6/dist-packages/tornado/ioloop.py", line 759, in _run_callback
        ret = callback()
      File "/usr/local/lib/python3.6/dist-packages/tornado/stack_context.py", line 276, in null_wrapper
        return fn(*args, **kwargs)
      File "/usr/local/lib/python3.6/dist-packages/tornado/ioloop.py", line 780, in _discard_future_result
        future.result()
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/app.py", line 1482, in update_last_activity
        user = orm.User.find(self.db, route_data['user'])
      File "/usr/local/lib/python3.6/dist-packages/jupyterhub/orm.py", line 170, in find
        return db.query(cls).filter(cls.name == name).first()
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 2825, in first
        ret = list(self[0:1])
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 2617, in __getitem__
        return list(res)
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 2925, in __iter__
        return self._execute_and_instances(context)
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 2948, in _execute_and_instances
        result = conn.execute(querycontext.statement, self._params)
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 948, in execute
        return meth(self, multiparams, params)
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
        return connection._execute_clauseelement(self, multiparams, params)
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
        compiled_sql, distilled_params
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1132, in _execute_context
        None, None)
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
        exc_info
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
        reraise(type(exception), exception, tb=exc_tb, cause=cause)
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 186, in reraise
        raise value.with_traceback(tb)
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1125, in _execute_context
        conn = self._revalidate_connection()
      File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 427, in _revalidate_connection
        "Can't reconnect until invalid "
    sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back [SQL: 'SELECT users.id AS users_id, users.name AS users_name, users.admin AS users_admin, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state \nFROM users \nWHERE users.name = %(name_1)s \n LIMIT %(param_1)s'] [parameters: [{}]]

[ichasepucks]

Hi @mak-aravind. No, I still have an open task to clean up and submit a PR for this. We are using a fork of the repo and the changes are working pretty well for us. I'm not 100% sure we've captured all cases, but it's markedly better. I don't foresee me being able to do a PR for a few weeks more. So feel free to fork and patch if you need it sooner.

[serlina]

@mak-aravind.@@ichasepucks , recentlly we met this problem using jupyterhub+k8s+kubespawner+singleuser. once we restart postgres container, the jupyterhub didn't work, it return 500. the only work round solution is to restart the jupyterhub container,but as you know, it's not a good way in production env, especially it is conflict with the concept of K8S

So could you please deliver the fix for this ,thank you very much, I'm looking forward to your reply

[mak-aravind]

@ichasepucks Thank you very much for a quick turn around. I hope you are mentioning the changes in https://github.com/ckbhatt/jupyterhub/pull/3/files.

@serlina I totally agree with you. The issue is a showstopper in our implementation as well. We are overriding the k8s self-healing capability by restarting the hub.

[serlina]

@mak-aravind, I've met the same problem as you mentioned in jupyterhub 0.8.1 with connection with a external postgres database in the same k8s cluster.
according to your suggestion, https://github.com/ckbhatt/jupyterhub/pull/3/files. I tried this, but it didn't work, after postgres restarted, I logined into jupyterhub with a new user test, it returned me 500 : Internal Server Error.
the last error trace is :
2018-05-14 07:06:44,694 WARNING Connection pool is full, discarding connection: 10.247.0.1
WARNING:urllib3.connectionpool:Connection pool is full, discarding connection: 10.247.0.1
[I 2018-05-14 07:06:44.694 JupyterHub reflector:129] watching for pods with label selector component=singleuser-server,heritage=jupyterhub in namespace default
[D 2018-05-14 07:10:17.728 JupyterHub proxy:557] Proxy: Fetching GET http://proxy-8001internal.default.svc.cluster.local:38001/api/routes
2018-05-14 07:10:17,735 INFO sqlalchemy.engine.base.Engine SELECT users.id AS users_id, users.name AS users_name, users.admin AS users_admin, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state
FROM users
WHERE users.name = %(name_1)s
LIMIT %(param_1)s
INFO:sqlalchemy.engine.base.Engine:SELECT users.id AS users_id, users.name AS users_name, users.admin AS users_admin, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state
FROM users
WHERE users.name = %(name_1)s
LIMIT %(param_1)s
2018-05-14 07:10:17,735 INFO sqlalchemy.engine.base.Engine {'name_1': 'testtest', 'param_1': 1}
INFO:sqlalchemy.engine.base.Engine:{'name_1': 'testtest', 'param_1': 1}
[E 2018-05-14 07:10:17.740 JupyterHub ioloop:638] Exception in callback functools.partial(.null_wrapper at 0x7f7b6c3ad730>, )
Traceback (most recent call last):
File "/opt/conda/lib/python3.5/site-packages/tornado/ioloop.py", line 605, in _run_callback
ret = callback()
File "/opt/conda/lib/python3.5/site-packages/tornado/stack_context.py", line 277, in null_wrapper
return fn(args, *kwargs)
File "/opt/conda/lib/python3.5/site-packages/tornado/ioloop.py", line 626, in _discard_future_result
future.result()
File "/opt/conda/lib/python3.5/site-packages/jupyterhub/app.py", line 1483, in update_last_activity
user = orm.User.find(self.db, route_data['user'])
File "/opt/conda/lib/python3.5/site-packages/jupyterhub/orm.py", line 170, in find
return db.query(cls).filter(cls.name == name).first()
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/orm/query.py", line 2755, in first
ret = list(self[0:1])
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/orm/query.py", line 2547, in __getitem__
return list(res)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/orm/query.py", line 2855, in __iter__
return self._execute_and_instances(context)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/orm/query.py", line 2878, in _execute_and_instances
result = conn.execute(querycontext.statement, self._params)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 945, in execute
return meth(self, multiparams, params)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/sql/elements.py", line 263, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1053, in _execute_clauseelement
compiled_sql, distilled_params
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1189, in _execute_context
context)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1402, in _handle_dbapi_exception
exc_info
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
reraise(type(exception), exception, tb=exc_tb, cause=cause)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/util/compat.py", line 186, in reraise
raise value.with_traceback(tb)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
context)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/default.py", line 470, in do_execute
cursor.execute(statement, parameters)
sqlalchemy.exc.InternalError: (psycopg2.InternalError) current transaction is aborted, commands ignored until end of transaction block
[SQL: 'SELECT users.id AS users_id, users.name AS users_name, users.admin AS users_admin, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state \nFROM users \nWHERE users.name = %(name_1)s \n LIMIT %(param_1)s'] [parameters: {'name_1': 'testtest', 'param_1': 1}]

after I restart the jupyterhub container, I can login to jupyterhub correctly.
@mak-aravind.@ichasepucks , So could you please deliver the fix for this ,thank you very much, I'm looking forward to your reply

[serlina]

File "/opt/conda/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 427, in _revalidate_connection
"Can't reconnect until invalid "
sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back [SQL: 'SELECT users.id AS users_id, users.name AS users_name, users.admin AS users_admin, users.created AS users_created, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state \nFROM users \nWHERE users.name = %(name_1)s \n LIMIT %(param_1)s'] [parameters: [{}]]

jupyterhub0.9 + singleuser 0.9 also failed in such case, could you please help me about this
https://github.com/ckbhatt/jupyterhub/pull/3/files, the fix only related to 2 files ? jupyterhub/app.py and jupyterhub/handlers/base.py , anything I'm missing ?

[serlina]

the issue # jupyterhub#1626 is still open, any update ?

[minrk]

@serlina there hasn't been a pull request based on the proposed changes yet, so it is not yet fixed in 0.9. I just opened #1894 with fixes from the related links here, which appears to fix the issue for me.

[mak-aravind]

@minrk Thank you very much for the fixes. I got a chance to test your changes from the implementation we are doing for jupyter.

The fix # 1894 helps the hub to resume from looping and kept reporting below error:

_sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back [SQL: 'SELECT users.id AS users_id, users.name AS users_name, users.admin AS users_admin, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state \nFROM users \nWHERE users.name = %(name_1)s \n LIMIT %(param_1)s'] [parameters: [{}]]_

With this fix # 1894, After bringing down postgres and resuming its service there are some observations I collated below :

when I open a browser and access the jupyterhub it immediately shows up a login page. For Dev I am using https://github.com/yuvipanda/jupyterhub-dummy-authenticator. When I login with a username its throwing 500: Internal Server Error. With below logs from hub and the URL used is

http://192.168.39.45:31212/hub/login?next=

When I relaunch the jupyter from new browser window or tab the login happens without 500 : Internal Server Error. Or otherwise clicking the top left corner jupyterhub dashboard icon also brings back to login page and when I login from there it goes through without error.

I hope we should show a proper customized error message for this system error. Since the next route is missing on first launch after database resumes

Please let me know your thoughts

`[E 2018-05-16 19:51:24.218 JupyterHub web:1621] Uncaught exception POST /hub/login?next= (172.17.0.1)
HTTPServerRequest(protocol='http', host='192.168.39.45:31212', method='POST', uri='/hub/login?next=', version='HTTP/1.1', remote_ip='172.17.0.1')
Traceback (most recent call last):
File "/usr/local/lib/python3.6/dist-packages/tornado/web.py", line 1543, in _execute
result = yield result
File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/login.py", line 81, in post
user = await self.login_user(data)
File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 469, in login_user
user = self.user_from_username(username)
File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 290, in user_from_username
user = self.find_user(username)
File "/usr/local/lib/python3.6/dist-packages/jupyterhub/handlers/base.py", line 285, in find_user
orm_user = orm.User.find(db=self.db, name=name)
File "/usr/local/lib/python3.6/dist-packages/jupyterhub/orm.py", line 194, in find
return db.query(cls).filter(cls.name == name).first()
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 2825, in first
ret = list(self[0:1])
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 2617, in __getitem__
return list(res)
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 2925, in __iter__
return self._execute_and_instances(context)
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 2948, in _execute_and_instances
result = conn.execute(querycontext.statement, self._params)
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 948, in execute
return meth(self, multiparams, params)
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
compiled_sql, distilled_params
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1132, in _execute_context
None, None)
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
exc_info
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
reraise(type(exception), exception, tb=exc_tb, cause=cause)
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 186, in reraise
raise value.with_traceback(tb)
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1125, in _execute_context
conn = self._revalidate_connection()
File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 427, in _revalidate_connection
"Can't reconnect until invalid "
sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back [SQL: 'SELECT users.id AS users_id, users.name AS users_name, users.admin AS users_admin, users.created AS users_created, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state \nFROM users \nWHERE users.name = %(name_1)s \n LIMIT %(param_1)s'] [parameters: [{}]]

[W 2018-05-16 19:51:24.219 JupyterHub base:806] Rolling back session due to database error (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back [SQL: 'SELECT users.id AS users_id, users.name AS users_name, users.admin AS users_admin, users.created AS users_created, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state \nFROM users \nWHERE users.name = %(name_1)s \n LIMIT %(param_1)s'] [parameters: [{}]]
[E 2018-05-16 19:51:24.222 JupyterHub log:150] {
"Cookie": "_xsrf=2|1bd0a1a1|12ed2a834fe070b00759531eeda7f0f9|1526446758",
"Accept-Language": "en-US,en;q=0.9",
"Accept-Encoding": "gzip, deflate",
"Referer": "http://192.168.39.45:31212/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 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.139 Safari/537.36",
"Content-Type": "application/x-www-form-urlencoded",
"Upgrade-Insecure-Requests": "1",
"Origin": "http://192.168.39.45:31212",
"Cache-Control": "max-age=0",
"Content-Length": "22",
"X-Scheme": "http",
"X-Original-Uri": "/hub/login?next=",
"X-Forwarded-Proto": "http,http",
"X-Forwarded-Port": "80,31212",
"X-Forwarded-Host": "192.168.39.45:31212",
"X-Forwarded-For": "172.17.0.1,172.17.0.5",
"X-Real-Ip": "172.17.0.1",
"Connection": "close",
"Host": "192.168.39.45:31212"
}
[E 2018-05-16 19:51:24.223 JupyterHub log:158] 500 POST /hub/login?next= (@172.17.0.1) 6.79ms
[I 2018-05-16 19:52:20.019 JupyterHub proxy:299] Checking routes
[I 2018-05-16 19:53:19.953 JupyterHub proxy:299] Checking routes
[I 2018-05-16 19:54:19.956 JupyterHub proxy:299] Checking routes
[I 2018-05-16 19:55:19.953 JupyterHub proxy:299] Checking routes
[I 2018-05-16 19:56:19.982 JupyterHub proxy:299] Checking routes
[I 2018-05-16 19:57:19.957 JupyterHub proxy:299] Checking routes
[I 2018-05-16 19:58:19.956 JupyterHub proxy:299] Checking routes
[I 2018-05-16 19:59:19.958 JupyterHub proxy:299] Checking routes
`

[serlina]

@ mak-aravind, as you said several days ago
""""
@minrk With this fix # 1894, After bringing down postgres and resuming its service there are some observations I collated below :

when I open a browser and access the jupyterhub it immediately shows up a login page. For Dev I am using https://github.com/yuvipanda/jupyterhub-dummy-authenticator. When I login with a username its throwing 500: Internal Server Error. With below logs from hub and the URL used is

http://192.168.39.45:31212/hub/login?next=

When I relaunch the jupyter from new browser window or tab the login happens without 500 : Internal Server Error. Or otherwise clicking the top left corner jupyterhub dashboard icon also brings back to login page and when I login from there it goes through without error.
"""
but I can't go through the 500:Internal Server Error after click login in.

[serlina]

@minrk,@ mak-aravind, using your fix mentioned above (commit b232633 into jupyterhub:master 29 days ago), I met another error when postgres stop. with the fix I can open the jupyterhub login page, the username is "ww", and after click login button, I reach out to a 500 error page, and there are some error log below:

2018-06-21 13:17:39,116 INFO sqlalchemy.engine.base.Engine {'name_1': 'ww', 'param_1': 1}
INFO:sqlalchemy.engine.base.Engine:{'name_1': 'ww', 'param_1': 1}
[E 2018-06-21 13:17:39.116 JupyterHub ioloop:638] Exception in callback functools.partial(, )
Traceback (most recent call last):
File "/opt/conda/lib/python3.5/site-packages/tornado/ioloop.py", line 605, in _run_callback
ret = callback()
File "/opt/conda/lib/python3.5/site-packages/tornado/stack_context.py", line 277, in null_wrapper
return fn(args, *kwargs)
File "/opt/conda/lib/python3.5/site-packages/tornado/ioloop.py", line 626, in _discard_future_result
future.result()
File "/opt/conda/lib/python3.5/site-packages/jupyterhub/app.py", line 1482, in update_last_activity
user = orm.User.find(self.db, route_data['user'])
File "/opt/conda/lib/python3.5/site-packages/jupyterhub/orm.py", line 170, in find
return db.query(cls).filter(cls.name == name).first()
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/orm/query.py", line 2755, in first
ret = list(self[0:1])
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/orm/query.py", line 2547, in getitem
return list(res)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/orm/query.py", line 2855, in iter
return self._execute_and_instances(context)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/orm/query.py", line 2878, in _execute_and_instances
result = conn.execute(querycontext.statement, self._params)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 945, in execute
return meth(self, multiparams, params)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/sql/elements.py", line 263, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1053, in _execute_clauseelement
compiled_sql, distilled_params
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1189, in _execute_context
context)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1402, in _handle_dbapi_exception
exc_info
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
reraise(type(exception), exception, tb=exc_tb, cause=cause)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/util/compat.py", line 186, in reraise
raise value.with_traceback(tb)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
context)
File "/opt/conda/lib/python3.5/site-packages/sqlalchemy/engine/default.py", line 470, in do_execute
cursor.execute(statement, parameters)
sqlalchemy.exc.ProgrammingError: (psycopg2.ProgrammingError) relation "users" does not exist
LINE 2: FROM users
^
[SQL: 'SELECT users.id AS users_id, users.name AS users_name, users.admin AS users_admin, users.last_activity AS users_last_activity, users.cookie_id AS users_cookie_id, users.state AS users_state, users.encrypted_auth_state AS users_encrypted_auth_state \nFROM users \nWHERE users.name = %(name_1)s \n LIMIT %(param_1)s'] [parameters: {'name_1': 'ww', 'param_1': 1}]

background: I used jupyterhub 0.8.1 from https://hub.docker.com/r/jupyterhub/jupyterhub/tags/

### For some specify reason, we must use jupyterhub 0.8.1, instead of jupyterhub 0.9. could you please help me with the issue. thanks