Exception when session expires

javier-sanz · February 1, 2018, 2:23pm

From time to time when my session expires we get an internal server error. When I see the log I can see the next exception.

[2018-02-01 14:14:58,002] ERROR in app: Exception on /login [GET]
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/flask/app.py", line 1988, in wsgi_app
    response = self.full_dispatch_request()
  File "/usr/local/lib/python2.7/dist-packages/flask/app.py", line 1641, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/usr/local/lib/python2.7/dist-packages/flask_restful/__init__.py", line 271, in error_router
    return original_handler(e)
  File "/usr/local/lib/python2.7/dist-packages/flask/app.py", line 1544, in handle_user_exception
    reraise(exc_type, exc_value, tb)
  File "/usr/local/lib/python2.7/dist-packages/flask/app.py", line 1639, in full_dispatch_request
    rv = self.dispatch_request()
  File "/usr/local/lib/python2.7/dist-packages/flask/app.py", line 1625, in dispatch_request
    return self.view_functions[rule.endpoint](**req.view_args)
  File "/usr/local/lib/python2.7/dist-packages/flask_limiter/extension.py", line 442, in __inner
    return obj(*a, **k)
  File "/app/redash/handlers/authentication.py", line 99, in login
    if current_org == None and not settings.MULTI_ORG:
  File "/usr/local/lib/python2.7/dist-packages/werkzeug/local.py", line 365, in <lambda>
    __eq__ = lambda x, o: x._get_current_object() == o
  File "/usr/local/lib/python2.7/dist-packages/werkzeug/local.py", line 302, in _get_current_object
    return self.__local()
  File "/app/redash/authentication/org_resolving.py", line 14, in _get_current_org
    g.org = Organization.get_by_slug(slug)
  File "/app/redash/models.py", line 293, in get_by_slug
    return cls.query.filter(cls.slug == slug).first()
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2697, in first
    ret = list(self[0:1])
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2489, in __getitem__
    return list(res)
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2797, in __iter__
    return self._execute_and_instances(context)
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2820, in _execute_and_instances
    result = conn.execute(querycontext.statement, self._params)
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 945, in execute
    return meth(self, multiparams, params)
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 263, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1053, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1189, in _execute_context
    context)
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1393, in _handle_dbapi_exception
    exc_info
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 202, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
    context)
  File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 469, in do_execute
    cursor.execute(statement, parameters)
OperationalError: (psycopg2.OperationalError) server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.
 [SQL: 'SELECT organizations.updated_at AS organizations_updated_at, organizations.created_at AS organizations_created_at, organizations.id AS organizations_id, organizations.name AS organizations_name, organizations.slug AS organizations_slug, organizations.settings AS organizations_settings \nFROM organizations \nWHERE organizations.slug = %(slug_1)s \n LIMIT %(param_1)s'] [parameters: {'slug_1': 'default', 'param_1': 1}]

Do you know what might be happening? We are using this week master for our PoC.

ffeng · November 16, 2018, 4:30pm

I got exactly same error messages in the redash.log. Someone can help?

arikfr · November 18, 2018, 9:30am

Check your logs: did the Postgres server restart at any point?

gstaykov · February 22, 2020, 8:55am

I have the exact same problem. From time to time the UI is start getting “internal server error” after a couple of refreshes it is start working again. This happens of evey screen: login, dashboard, queries, etc… I can see in the log that redash-server is trying to make the following SQL query:

[SQL: 'SELECT organizations.updated_at AS organizations_updated_at, organizations.created_at AS organizations_created_at, organizations.id AS organizations_id, organizations.name AS organizations_name, organizations.slug AS organizations_slug, organizations.settings AS organizations_settings \nFROM organizations \nWHERE organizations.slug = %(slug_1)s \n LIMIT %(param_1)s'] [parameters: {'slug_1': 'default', 'param_1': 1}] (Background on this error at: http://sqlalche.me/e/e3q8)

But it fails with OperationalError: (psycopg2.OperationalError) server closed the connection unexpectedly

I have selfhosted redash with the following setup:

standalone postgre machine
standalone redis machine
docker redash-server: redash/redash:8.0.0.b32245
docker redash-scheduler: redash/redash:8.0.0.b32245
docker redash-worker: redash/redash:8.0.0.b32245
docker ad-hoc-worker: redash/redash:8.0.0.b32245

The error stacktrace is:

Feb 22, 2020 @ 10:19:44.908	    cursor.execute(statement, parameters)
redash-server
Feb 22, 2020 @ 10:19:44.908	  File "/usr/local/lib/python2.7/site-packages/flask_login/login_manager.py", line 317, in _load_user
redash-server
Feb 22, 2020 @ 10:19:44.908		This probably means the server terminated abnormally
redash-server
Feb 22, 2020 @ 10:19:44.908		before or while processing the request.
redash-server
Feb 22, 2020 @ 10:19:44.908	 [SQL: 'SELECT organizations.updated_at AS organizations_updated_at, organizations.created_at AS organizations_created_at, organizations.id AS organizations_id, organizations.name AS organizations_name, organizations.slug AS organizations_slug, organizations.settings AS organizations_settings \nFROM organizations \nWHERE organizations.slug = %(slug_1)s \n LIMIT %(param_1)s'] [parameters: {'slug_1': 'default', 'param_1': 1}] (Background on this error at: http://sqlalche.me/e/e3q8)
redash-server
Feb 22, 2020 @ 10:19:44.908	    response = self.full_dispatch_request()
redash-server
Feb 22, 2020 @ 10:19:44.908	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
redash-server
Feb 22, 2020 @ 10:19:44.908	    exc_info
redash-server
Feb 22, 2020 @ 10:19:44.908	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause
redash-server
Feb 22, 2020 @ 10:19:44.908	    context)
redash-server
Feb 22, 2020 @ 10:19:44.908	  File "/usr/local/lib/python2.7/site-packages/flask/app.py", line 1982, in wsgi_app
redash-server
Feb 22, 2020 @ 10:19:44.908	    reraise(type(exception), exception, tb=exc_tb, cause=cause)
redash-server
Feb 22, 2020 @ 10:19:44.908	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
redash-server
Feb 22, 2020 @ 10:19:44.908	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
redash-server
Feb 22, 2020 @ 10:19:44.908	OperationalError: (psycopg2.OperationalError) server closed the connection unexpectedly
redash-server
Feb 22, 2020 @ 10:19:44.907	Traceback (most recent call last):
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/flask/app.py", line 1609, in full_dispatch_request
redash-server
Feb 22, 2020 @ 10:19:44.907	    user = self.user_callback(user_id)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/flask/app.py", line 1614, in full_dispatch_request
redash-server
Feb 22, 2020 @ 10:19:44.907	    request_started.send(self)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/app/redash/authentication/__init__.py", line 48, in load_user
redash-server
Feb 22, 2020 @ 10:19:44.907	    org = current_org._get_current_object()
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/werkzeug/local.py", line 302, in _get_current_object
redash-server
Feb 22, 2020 @ 10:19:44.907	    return self.__local()
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/app/redash/authentication/org_resolving.py", line 18, in _get_current_org
redash-server
Feb 22, 2020 @ 10:19:44.907	    g.org = Organization.get_by_slug(slug)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/app/redash/models/organizations.py", line 33, in get_by_slug
redash-server
Feb 22, 2020 @ 10:19:44.907	    return cls.query.filter(cls.slug == slug).first()
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2895, in first
redash-server
Feb 22, 2020 @ 10:19:44.907	    ret = list(self[0:1])
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2687, in __getitem__
redash-server
Feb 22, 2020 @ 10:19:44.907	    return list(res)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2995, in __iter__
redash-server
Feb 22, 2020 @ 10:19:44.907	    return self._execute_and_instances(context)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3018, in _execute_and_instances
redash-server
Feb 22, 2020 @ 10:19:44.907	    result = conn.execute(querycontext.statement, self._params)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 948, in execute
redash-server
Feb 22, 2020 @ 10:19:44.907	    return meth(self, multiparams, params)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
redash-server
Feb 22, 2020 @ 10:19:44.907	    return connection._execute_clauseelement(self, multiparams, params)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
redash-server
Feb 22, 2020 @ 10:19:44.907	    compiled_sql, distilled_params
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
redash-server
Feb 22, 2020 @ 10:19:44.907	    context)
redash-server
Feb 22, 2020 @ 10:19:44.907	    rv = self.handle_user_exception(e)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/blinker/base.py", line 267, in send
redash-server
Feb 22, 2020 @ 10:19:44.907	    for receiver in self.receivers_for(sender)]
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/app/redash/models/users.py", line 54, in update_user_active_at
redash-server
Feb 22, 2020 @ 10:19:44.907	    if current_user.is_authenticated and not current_user.is_api_user():
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/werkzeug/local.py", line 343, in __getattr__
redash-server
Feb 22, 2020 @ 10:19:44.907	    return getattr(self._get_current_object(), name)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/werkzeug/local.py", line 302, in _get_current_object
redash-server
Feb 22, 2020 @ 10:19:44.907	    return self.__local()
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/flask_login/utils.py", line 26, in <lambda>
redash-server
Feb 22, 2020 @ 10:19:44.907	    current_user = LocalProxy(lambda: _get_user())
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/flask_login/utils.py", line 302, in _get_user
redash-server
Feb 22, 2020 @ 10:19:44.907	    current_app.login_manager._load_user()
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/flask/app.py", line 1517, in handle_user_exception
redash-server
Feb 22, 2020 @ 10:19:44.907	    return self.reload_user()
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/flask_restful/__init__.py", line 271, in error_router
redash-server
Feb 22, 2020 @ 10:19:44.907	    return original_handler(e)
redash-server
Feb 22, 2020 @ 10:19:44.907	[2020-02-22 08:19:44,905] ERROR in app: Exception on /api/organization/status [GET]
redash-server
Feb 22, 2020 @ 10:19:44.907	    reraise(exc_type, exc_value, tb)
redash-server
Feb 22, 2020 @ 10:19:44.907	  File "/usr/local/lib/python2.7/site-packages/flask_login/login_manager.py", line 279, in reload_user
redash-server

However thank you for this great tool ! Appreciate your work

▼Categories

▼Tags

Exception when session expires