search

datopian / datahub-qa

:package: Bugs, issues and suggestions for datahub.io
https://datahub.io/
32 stars 6 forks source link

Exception in auth service #126

Closed akariv closed 6 years ago

akariv commented 6 years ago

Tried to push a file to testing and got an 'internal server error' message.

From inspecting the logs, this is the exception:

[auth-1]2018-02-20T13:57:57.488636639Z [2018-02-20 13:57:57,474] ERROR in app: Exception on /auth/authorize [GET]
[auth-1]2018-02-20T13:57:57.488689025Z Traceback (most recent call last):
[auth-1]2018-02-20T13:57:57.488695458Z   File "/usr/lib/python3.6/site-packages/flask/app.py", line 1982, in wsgi_app
[auth-1]2018-02-20T13:57:57.488701297Z     response = self.full_dispatch_request()
[auth-1]2018-02-20T13:57:57.488707267Z   File "/usr/lib/python3.6/site-packages/flask/app.py", line 1614, in full_dispatch_request
[auth-1]2018-02-20T13:57:57.488712764Z     rv = self.handle_user_exception(e)
[auth-1]2018-02-20T13:57:57.488719483Z   File "/usr/lib/python3.6/site-packages/flask_cors/extension.py", line 161, in wrapped_function
[auth-1]2018-02-20T13:57:57.488724867Z     return cors_after_request(app.make_response(f(*args, **kwargs)))
[auth-1]2018-02-20T13:57:57.488730219Z   File "/usr/lib/python3.6/site-packages/flask/app.py", line 1517, in handle_user_exception
[auth-1]2018-02-20T13:57:57.488735459Z     reraise(exc_type, exc_value, tb)
[auth-1]2018-02-20T13:57:57.488740462Z   File "/usr/lib/python3.6/site-packages/flask/_compat.py", line 33, in reraise
[auth-1]2018-02-20T13:57:57.488745888Z     raise value
[auth-1]2018-02-20T13:57:57.488753738Z   File "/usr/lib/python3.6/site-packages/flask/app.py", line 1612, in full_dispatch_request
[auth-1]2018-02-20T13:57:57.488762387Z     rv = self.dispatch_request()
[auth-1]2018-02-20T13:57:57.488772877Z   File "/usr/lib/python3.6/site-packages/flask/app.py", line 1598, in dispatch_request
[auth-1]2018-02-20T13:57:57.488795174Z     return self.view_functions[rule.endpoint](**req.view_args)
[auth-1]2018-02-20T13:57:57.488804497Z   File "/opt/app/auth/blueprint.py", line 43, in authorize_
[auth-1]2018-02-20T13:57:57.488811699Z     return jsonpify(authorize_controller(token, service, private_key))
[auth-1]2018-02-20T13:57:57.488819082Z   File "/opt/app/auth/controllers.py", line 277, in authorize
[auth-1]2018-02-20T13:57:57.488826437Z     permissions = get_token(service, userid)
[auth-1]2018-02-20T13:57:57.488833217Z   File "/opt/app/auth/permissions.py", line 26, in get_token
[auth-1]2018-02-20T13:57:57.488840627Z     return get_permissions(service, userid)
[auth-1]2018-02-20T13:57:57.488848282Z   File "/usr/lib/python3.6/site-packages/plans/api.py", line 6, in get_permissions
[auth-1]2018-02-20T13:57:57.488855147Z     user = next(u_)
[auth-1]2018-02-20T13:57:57.488862353Z   File "/usr/lib/python3.6/site-packages/plans/models.py", line 64, in get_user
[auth-1]2018-02-20T13:57:57.488870827Z     user = session.query(UserPlan).filter_by(userid=userid_).first()
[auth-1]2018-02-20T13:57:57.488878307Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2778, in first
[auth-1]2018-02-20T13:57:57.488885982Z     ret = list(self[0:1])
[auth-1]2018-02-20T13:57:57.488893648Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2570, in __getitem__
[auth-1]2018-02-20T13:57:57.488902073Z     return list(res)
[auth-1]2018-02-20T13:57:57.488909925Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2878, in __iter__
[auth-1]2018-02-20T13:57:57.488917685Z     return self._execute_and_instances(context)
[auth-1]2018-02-20T13:57:57.488925380Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2899, in _execute_and_instances
[auth-1]2018-02-20T13:57:57.488933413Z     close_with_result=True)
[auth-1]2018-02-20T13:57:57.488941198Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2908, in _get_bind_args
[auth-1]2018-02-20T13:57:57.488950163Z     **kw
[auth-1]2018-02-20T13:57:57.488956687Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2890, in _connection_from_session
[auth-1]2018-02-20T13:57:57.488964844Z     conn = self.session.connection(**kw)
[auth-1]2018-02-20T13:57:57.488970800Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 1035, in connection
[auth-1]2018-02-20T13:57:57.488977702Z     execution_options=execution_options)
[auth-1]2018-02-20T13:57:57.488984637Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 1040, in _connection_for_bind
[auth-1]2018-02-20T13:57:57.488992638Z     engine, execution_options)
[auth-1]2018-02-20T13:57:57.488999345Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 409, in _connection_for_bind
[auth-1]2018-02-20T13:57:57.489006135Z     conn = bind.contextual_connect()
[auth-1]2018-02-20T13:57:57.489012740Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2123, in contextual_connect
[auth-1]2018-02-20T13:57:57.489029605Z     self._wrap_pool_connect(self.pool.connect, None),
[auth-1]2018-02-20T13:57:57.489041737Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2158, in _wrap_pool_connect
[auth-1]2018-02-20T13:57:57.489049707Z     return fn()
[auth-1]2018-02-20T13:57:57.489057642Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/pool.py", line 403, in connect
[auth-1]2018-02-20T13:57:57.489065768Z     return _ConnectionFairy._checkout(self)
[auth-1]2018-02-20T13:57:57.489073620Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/pool.py", line 782, in _checkout
[auth-1]2018-02-20T13:57:57.489082015Z     fairy = _ConnectionRecord.checkout(pool)
[auth-1]2018-02-20T13:57:57.489093815Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/pool.py", line 532, in checkout
[auth-1]2018-02-20T13:57:57.489102203Z     rec = pool._do_get()
[auth-1]2018-02-20T13:57:57.489109685Z   File "/usr/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1179, in _do_get
[auth-1]2018-02-20T13:57:57.489118075Z     (self.size(), self.overflow(), self._timeout), code="3o7r")
[auth-1]2018-02-20T13:57:57.489248918Z sqlalchemy.exc.TimeoutError: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30 (Background on this error at: http://sqlalche.me/e/3o7r)

Retrying the upload succeeded (so this was a temporary issue it seems).

anuveyatsu commented 6 years ago

@akariv seems like it throws that exception when you hit authz api several times within some short period of time. E.g., I've experienced it while doing multiple "push"s in parallel in the tests - https://travis-ci.org/datahq/data-cli/jobs/344397536#L675 /cc @zelima

AcckiyGerman commented 6 years ago

TESTED by pushing a lot of datasets in a short period of time:

$ npm test test/push/push.test.js

> data-cli@0.7.9 test /home/user/work/datahq/data-cli
> ava -v "test/push/push.test.js"

  ✔ push command succeeds with regular CSV file (3.5s)
  ✔ push command succeeds for valid dataset (3.4s)
  ✔ push command succeeds for valid dataset with path to dp.json (3.6s)
  ✔ push command succeeds with regular CSV file from URL (4.1s)
  ✔ push command succeeds with packaged invalid CSV (4.3s)
  ✔ push command succeeds for CSV with wrong ext but force formatting (7.7s)
  ✔ push command succeeds for Excel with wrong ext but force formatting (10.5s)
  ✔ push command succeeds for simple Excel with 1 sheet (10.8s)
  ✔ push command succeeds for Excel with selected sheet (20.9s)
AcckiyGerman commented 6 years ago

oh, sorry, I see now here https://github.com/datahq/auth/issues/24