← Back to team overview

yahoo-eng-team team mailing list archive

[Bug 1960020] Re: Duplicated request ids in the logs

 

It's even easier to check just running multiple times (in devstack 4
times is enough) the curl command to query the root endpoint.

For Nova:
 curl -v http://<IP>/compute

For Cinder:
 curl -v http://<IP>/volume

** Also affects: nova
   Importance: Undecided
       Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1960020

Title:
  Duplicated request ids in the logs

Status in Cinder:
  New
Status in OpenStack Compute (nova):
  New

Bug description:
  In the cinder-api logs we can find duplicated request ids, which may
  confound people.

  Running the following 2 commands:

   $ cinder list
   $ cinder api-version

  Will result in log entries with duplicated request ids.

  In the following log entries, after running those 2 commands, we can
  see that there are 4 REST API requests but there are only 2 different
  request ids, as req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 and
  req-8a27dec8-63de-400b-b955-04d459c104df appear twice each.

  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536608]: INFO cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] GET http://192.168.1.89/volume//
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536608]: DEBUG cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] Empty body provided in request {{(pid=536608) tid=140407477474816 get_body /opt/remote_cinder/cinder/api/openstack/wsgi.py:715}}
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536608]: DEBUG cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] Calling method 'all' {{(pid=536608) tid=140407477474816 _process_stack /opt/remote_cinder/cinder/api/openstack/wsgi.py:869}}
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536608]: INFO cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] http://192.168.1.89/volume// returned with HTTP 300
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536608]: [pid: 536608|app: 0|req: 8/15] 192.168.1.89 () {64 vars in 1176 bytes} [Fri Feb  4 12:13:55 2022] GET /volume/ => generated 387 bytes in 2 msecs (HTTP/1.1 300) 5 headers in 170 bytes (1 switches on core 0)
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: INFO cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] GET http://192.168.1.89/volume/v3/9233eaa83fb944cb8fc984ed273db227/volumes/detail
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: DEBUG cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] Empty body provided in request {{(pid=536607) tid=140407477474816 get_body /opt/remote_cinder/cinder/api/openstack/wsgi.py:715}}
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: DEBUG cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] Calling method 'detail' {{(pid=536607) tid=140407477474816 _process_stack /opt/remote_cinder/cinder/api/openstack/wsgi.py:869}}
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: INFO cinder.volume.api [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] Get all volumes completed successfully.
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: /usr/local/lib/python3.6/site-packages/oslo_context/context.py:108: DeprecationWarning: Policy enforcement is depending on the value of is_admin. This key is deprecated. Please update your policy file to use the standard policy values.
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]:   DeprecationWarning)
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: INFO cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] http://192.168.1.89/volume/v3/9233eaa83fb944cb8fc984ed273db227/volumes/detail returned with HTTP 200
  Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: [pid: 536607|app: 0|req: 8/16] 192.168.1.89 () {62 vars in 1284 bytes} [Fri Feb  4 12:13:55 2022] GET /volume/v3/9233eaa83fb944cb8fc984ed273db227/volumes/detail => generated 2093 bytes in 36 msecs (HTTP/1.1 200) 7 headers in 286 bytes (1 switches on core 0)
  Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536608]: INFO cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] GET http://192.168.1.89/volume//
  Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536608]: DEBUG cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] Empty body provided in request {{(pid=536608) tid=140407477474816 get_body /opt/remote_cinder/cinder/api/openstack/wsgi.py:715}}
  Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536608]: DEBUG cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] Calling method 'all' {{(pid=536608) tid=140407477474816 _process_stack /opt/remote_cinder/cinder/api/openstack/wsgi.py:869}}
  Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536608]: INFO cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] http://192.168.1.89/volume// returned with HTTP 300
  Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536608]: [pid: 536608|app: 0|req: 9/17] 192.168.1.89 () {64 vars in 1176 bytes} [Fri Feb  4 12:13:58 2022] GET /volume/ => generated 387 bytes in 1 msecs (HTTP/1.1 300) 5 headers in 170 bytes (1 switches on core 0)
  Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536607]: INFO cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] GET http://192.168.1.89/volume//
  Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536607]: DEBUG cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] Empty body provided in request {{(pid=536607) tid=140407477474816 get_body /opt/remote_cinder/cinder/api/openstack/wsgi.py:715}}
  Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536607]: DEBUG cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] Calling method 'all' {{(pid=536607) tid=140407477474816 _process_stack /opt/remote_cinder/cinder/api/openstack/wsgi.py:869}}
  Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536607]: INFO cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] http://192.168.1.89/volume// returned with HTTP 300
  Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536607]: [pid: 536607|app: 0|req: 9/18] 192.168.1.89 () {62 vars in 1135 bytes} [Fri Feb  4 12:13:58 2022] GET /volume/ => generated 387 bytes in 1 msecs (HTTP/1.1 300) 5 headers in 169 bytes (1 switches on core 0)

  Something similar happens in nova, though an additional call to "nova
  version-list" is necessary to see it.

To manage notifications about this bug go to:
https://bugs.launchpad.net/cinder/+bug/1960020/+subscriptions