Janus: expired token results in 500 when calling generate_task_token

[coleshaw]

It seems like when I use an expired token to call the Janus "generate task token" API, I get a 500 server error. It might be nice to have a more descriptive error message or response sent, and to have this handled more gracefully, instead.

[coleshaw]

Stack trace from when this happens:

[2022-07-26, 12:23:06 PDT] {taskinstance.py:1718} ERROR - Task failed with exception
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.8/site-packages/airflow/models/taskinstance.py", line 1334, in _run_raw_task
    self._execute_task_with_callbacks(context)
  File "/home/airflow/.local/lib/python3.8/site-packages/airflow/models/taskinstance.py", line 1460, in _execute_task_with_callbacks
    result = self._execute_task(context, self.task)
  File "/home/airflow/.local/lib/python3.8/site-packages/airflow/models/taskinstance.py", line 1516, in _execute_task
    result = execute_callable(context=context)
  File "/home/airflow/.local/lib/python3.8/site-packages/airflow/decorators/base.py", line 134, in execute
    return_value = super().execute(context)
  File "/home/airflow/.local/lib/python3.8/site-packages/airflow/operators/python.py", line 174, in execute
    return_value = self.execute_callable()
  File "/home/airflow/.local/lib/python3.8/site-packages/airflow/operators/python.py", line 188, in execute_callable
    return self.python_callable(*self.op_args, **self.op_kwargs)
  File "/home/airflow/.local/lib/python3.8/site-packages/etna/etls/cat.py", line 135, in ingest
    with etna_hook.metis(project_name, read_only=False) as metis, self.hook.cat() as cat:
  File "/usr/local/lib/python3.8/contextlib.py", line 113, in __enter__
    return next(self.gen)
  File "/home/airflow/.local/lib/python3.8/site-packages/etna/hooks/etna.py", line 125, in metis
    auth = self.get_task_auth(project_name, read_only)
  File "/home/airflow/.local/lib/python3.8/site-packages/etna/hooks/etna.py", line 113, in get_task_auth
    token = Janus(token_auth, self.get_hostname("janus"), session=self.get_session()).generate_token(
  File "/home/airflow/.local/lib/python3.8/site-packages/mountetna/janus.py", line 7, in generate_token
    response = self.session.post(
  File "/home/airflow/.local/lib/python3.8/site-packages/requests/sessions.py", line 577, in post
    return self.request('POST', url, data=data, json=json, **kwargs)
  File "/home/airflow/.local/lib/python3.8/site-packages/requests/sessions.py", line 529, in request
    resp = self.send(prep, **send_kwargs)
  File "/home/airflow/.local/lib/python3.8/site-packages/requests/sessions.py", line 652, in send
    r = dispatch_hook('response', hooks, r, **kwargs)
  File "/home/airflow/.local/lib/python3.8/site-packages/requests/hooks.py", line 31, in dispatch_hook
    _hook_data = hook(hook_data, **kwargs)
  File "/home/airflow/.local/lib/python3.8/site-packages/mountetna/etna_base.py", line 38, in assert_status
    raise HTTPError(error_message, response=response)
requests.exceptions.HTTPError: Request failed with 500: Server error.

Have not been able to reproduce it locally, and do not see any logs for it in Portainer (though given the volume of Janus hits due to things like validate_task_token, maybe I'm just too slow).

[coleshaw]

Hm, I think this is a rollbar config error, where the key might not be set in Janus?

E, [2022-07-26T19:30:00.983636 #1] ERROR -- : [Rollbar] Error processing the item: Net::OpenTimeout, execution expired. Item: {"data"=>{:level=>"error", .... blah blah blah
E, [2022-07-26T19:30:00.983808 #1] ERROR -- : [Rollbar] Item has already failed. Not re-raising

E, [2022-07-26T19:30:00.983985 #1] ERROR -- : [Rollbar] Item: #<Rollbar::Item:0x0000560ee3094d98>

ERROR:2022-07-26T19:30:00+00:00 unl7eg Exiting with 422, Token is invalid!

Should be a 422, except that Rollbar tries to report but cannot, so times out.

[coleshaw]

Not Rollbar, rather looks like an issue with RefreshToken middleware not handling the exception gracefully:

ERROR:2022-07-26T19:53:06+00:00 fnh80f Caught unspecified error

ERROR:2022-07-26T19:53:06+00:00 fnh80f Signature has expired

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/jwt-2.4.1/lib/jwt/verify.rb:42:in `verify_expiration'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/jwt-2.4.1/lib/jwt/verify.rb:15:in `block (2 levels) in singleton class'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/jwt-2.4.1/lib/jwt/verify.rb:23:in `block in verify_claims'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/jwt-2.4.1/lib/jwt/verify.rb:20:in `each'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/jwt-2.4.1/lib/jwt/verify.rb:20:in `verify_claims'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/jwt-2.4.1/lib/jwt/decode.rb:99:in `verify_claims'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/jwt-2.4.1/lib/jwt/decode.rb:31:in `decode_segments'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/jwt-2.4.1/lib/jwt.rb:28:in `decode'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/sign_service.rb:39:in `jwt_decode'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /app/lib/models/user.rb:34:in `from_token'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /app/lib/server/controllers/authorization_controller.rb:74:in `generate'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/controller.rb:42:in `response'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/route.rb:149:in `process_call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/route.rb:74:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/server.rb:77:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /app/lib/server/refresh_token.rb:18:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/rack-throttle-0.7.0/lib/rack/throttle/limiter.rb:35:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/describe_routes.rb:10:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/auth.rb:22:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/rack-2.2.3.1/lib/rack/static.rb:161:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/symbolize_params.rb:10:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/parse_body.rb:38:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/metrics.rb:22:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/cross_origin.rb:34:in `actual_response'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /etna/lib/etna/cross_origin.rb:11:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/puma-5.6.4/lib/puma/configuration.rb:252:in `call'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/puma-5.6.4/lib/puma/request.rb:77:in `block in handle_request'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/puma-5.6.4/lib/puma/thread_pool.rb:340:in `with_force_shutdown'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/puma-5.6.4/lib/puma/request.rb:76:in `handle_request'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/puma-5.6.4/lib/puma/server.rb:441:in `process_client'

ERROR:2022-07-26T19:53:06+00:00 fnh80f /bundle/ruby/2.7.0/gems/puma-5.6.4/lib/puma/thread_pool.rb:147:in `block in spawn_thread'