No traceback on 400 "sequence item 0: expected str instance, bytes found" (TypeError)

[Grzegorz Grasza]

I have an error in keystone logs, with debug turned on:

2022-03-06 19:32:32.502 173 WARNING keystone.server.flask.application [req-cb061f74-f48a-4c71-be47-6dda08f65c96 b731e56863e44d3e985aab70f01b054c 2722b2f6760745ab902d73de100b0ef4 - default default] sequence item 0: expected str instance, bytes found

There is no traceback, which means I can't get any more information to fix it.

I believe this is because unknown errors are logged as a warning instead of an exception in _handle_keystone_exception function in the flask application.

[Grzegorz Grasza (xek)]

This is the stack trace from the client:

testtools.testresult.real._StringException: Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/tempest/test.py", line 236, in tearDownClass
    six.reraise(etype, value, trace)
  File "/usr/lib/python3.6/site-packages/six.py", line 693, in reraise
    raise value
  File "/usr/lib/python3.6/site-packages/tempest/test.py", line 208, in tearDownClass
    teardown()
  File "/usr/lib/python3.6/site-packages/tempest/test.py", line 719, in clear_credentials
    cls._creds_provider.clear_creds()
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/dynamic_creds.py", line 561, in clear_creds
    self.creds_client.delete_user(creds.user_id)
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/cred_client.py", line 55, in delete_user
    self.users_client.delete_user(user_id)
  File "/usr/lib/python3.6/site-packages/tempest/lib/services/identity/v3/users_client.py", line 104, in delete_user
    resp, body = self.delete("users/%s" % user_id)
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/rest_client.py", line 331, in delete
    return self.request('DELETE', url, extra_headers, headers, body)
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/rest_client.py", line 704, in request
    self._error_checker(resp, resp_body)
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/rest_client.py", line 815, in _error_checker
    raise exceptions.BadRequest(resp_body, resp=resp)
tempest.lib.exceptions.BadRequest: Bad request
Details: {'code': 400, 'message': 'sequence item 0: expected str instance, bytes found', 'title': 'Bad Request'}

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/keystone/+/834181

[Grzegorz Grasza (xek)]

After applying the related patch we were able to get the full traceback:

2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application [req-8a8f118c-206a-4e0a-88f1-a19b0a2d03d3 03b5810d4623462eab851e07eec21075 ade92f05c1d84ce0888c011e7a677480 - default default] sequence item 0: expected str instance, bytes found: TypeError: sequence item 0: expected str instance, bytes found
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application Traceback (most recent call last):
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application File "/usr/lib/python3.6/site-packages/flask/app.py", line 1813, in full_dispatch_request
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application rv = self.dispatch_request()
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application File "/usr/lib/python3.6/site-packages/flask/app.py", line 1799, in dispatch_request
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application return self.view_functions[rule.endpoint](**req.view_args)
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application File "/usr/lib/python3.6/site-packages/flask_restful/__init__.py", line 480, in wrapper
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application resp = resource(*args, **kwargs)
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application File "/usr/lib/python3.6/site-packages/flask/views.py", line 88, in view
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application return self.dispatch_request(*args, **kwargs)
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application File "/usr/lib/python3.6/site-packages/flask_restful/__init__.py", line 595, in dispatch_request
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application resp = meth(*args, **kwargs)
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application File "/usr/lib/python3.6/site-packages/keystone/api/users.py", line 275, in delete
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application PROVIDERS.identity_api.delete_user(user_id)
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application File "/usr/lib/python3.6/site-packages/keystone/common/manager.py", line 116, in wrapped
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application __ret_val = __f(*args, **kwargs)
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application File "/usr/lib/python3.6/site-packages/keystone/identity/core.py", line 414, in wrapper
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application return f(self, *args, **kwargs)
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application File "/usr/lib/python3.6/site-packages/keystone/identity/core.py", line 424, in wrapper
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application return f(self, *args, **kwargs)
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application File "/usr/lib/python3.6/site-packages/keystone/identity/core.py", line 1144, in delete_user
2022-03-18 10:13:05.245 199 ERROR keystone.server.flask.application PROVIDERS.id_mapping_api.delete_id_mapping(user_id)
2022-03-18 10:13:05.245 199 ...

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/keystone/+/834181
Committed: https://opendev.org/openstack/keystone/commit/3f628a9ae4857e3c48b7228ad77ea980ec824ef9
Submitter: "Zuul (22348)"
Branch: master

commit 3f628a9ae4857e3c48b7228ad77ea980ec824ef9
Author: Grzegorz Grasza <email address hidden>
Date: Thu Mar 17 15:58:44 2022 +0100

    Log the traceback in _handle_keystone_exception

    Some errors were logged without a traceback because they were
    logged as a warning instead.

    Change-Id: I68595e4e2c37279585f0434a173596e43e047004
    Related-Bug: #1965316