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

Bug #1965316 reported by Grzegorz Grasza
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
In Progress
Undecided
Grzegorz Grasza

Bug Description

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.

Revision history for this message
Grzegorz Grasza (xek) wrote :

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'}

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix proposed to keystone (master)

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

Revision history for this message
Grzegorz Grasza (xek) wrote :
Download full text (5.3 KiB)

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 ...

Read more...

Changed in keystone:
status: New → In Progress
Grzegorz Grasza (xek)
Changed in keystone:
assignee: nobody → Grzegorz Grasza (xek)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to keystone (master)

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.