Bug 1538089

Summary:	Backup logs: All requests share the same ID
Product:	Red Hat OpenStack	Reporter:	Gorka Eguileor <geguileo>
Component:	openstack-cinder	Assignee:	Gorka Eguileor <geguileo>
Status:	CLOSED ERRATA	QA Contact:	Avi Avraham <aavraham>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	10.0 (Newton)	CC:	aavraham, geguileo, marjones, pgrist, srevivo, tshefi
Target Milestone:	z7	Keywords:	Triaged, ZStream
Target Release:	10.0 (Newton)
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	openstack-cinder-9.1.4-23.el7ost	Doc Type:	Bug Fix
Doc Text:	Prior to this update, the logging library was not properly monkey patched by eventlet. Consequently, all log entries would have the request ID of the latest request that was received in the backup service. With this update, eventlet correctly monkey patches the logging library, and log entries will have the expected request ID.	Story Points:	---
Clone Of:	1538085
Clones:	1538093 (view as bug list)		Environment:
Last Closed:	2018-02-27 16:40:58 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:	1538085
Bug Blocks:	1538093, 1538095

Description Gorka Eguileor 2018-01-24 13:00:56 UTC

+++ This bug was initially created as a clone of Bug #1538085 +++

Currently all log entries will have the request ID of the latest request that was received in the Backup service.

So you would receive a request with ID 1 and you would start logging that thread log calls with its ID, but as soon as you receive another request, let's say with ID 2, you will have both request logging with ID 2 instead of each one logging with its own request ID.

Comment 3 Tzach Shefi 2018-02-11 08:59:36 UTC

Gorka, let me know if steps below are sufficient to verify.  
Tested on: openstack-cinder-9.1.4-24.el7ost.noarch

1. Created two Cinder volumes
2, Created backup of each one, gave same command immediately, volumes are filled backup take a few minutes. 

Backup.log reports two separate requests IDs:

req-2f688d8d-10d1-4c30-a2b0-4eb587884efc 8dab91fb867549249d6c90ffde60e926 b0bf0514c3484817b915bd0da3b47375

req-c952c516-b9b4-4cc3-b22b-a0a7be674522 8dab91fb867549249d6c90ffde60e926 b0bf0514c3484817b915bd0da3b47375


grep req- /var/log/cinder/backup.log

2018-02-11 08:55:27.336 1997 DEBUG cinder.backup.chunkeddriver [req-2f688d8d-10d1-4c30-a2b0-4eb587884efc 8dab91fb867549249d6c90ffde60e926 b0bf0514c3484817b915bd0da3b47375 - default default] Calling eventlet.sleep(0) _backup_chunk /usr/lib/python2.7/site-packages/cinder/backup/chunkeddriver.py:370
2018-02-11 08:55:27.441 1997 DEBUG cinder.backup.chunkeddriver [req-c952c516-b9b4-4cc3-b22b-a0a7be674522 8dab91fb867549249d6c90ffde60e926 b0bf0514c3484817b915bd0da3b47375 - default default] Compressed 52428800 bytes of data to 52179675 bytes using zlib. _prepare_output_data /usr/lib/python2.7/site-packages/cinder/backup/chunkeddriver.py:393
2018-02-11 08:55:27.441 1997 DEBUG cinder.backup.chunkeddriver [req-c952c516-b9b4-4cc3-b22b-a0a7be674522 8dab91fb867549249d6c90ffde60e926 b0bf0514c3484817b915bd0da3b47375 - default default] About to put_object _backup_chunk /usr/lib/python2.7/site-packages/cinder/backup/chunkeddriver.py:356
2018-02-11 08:55:27.935 1997 DEBUG cinder.backup.chunkeddriver [req-c952c516-b9b4-4cc3-b22b-a0a7be674522 8dab91fb867549249d6c90ffde60e926 b0bf0514c3484817b915bd0da3b47375 - default default] backup MD5 for volume_19767d79-78d2-460b-97c6-4f6fa3d48a4e/20180211085519/az_nova_backup_ef916682-20cb-4e81-a424-fd32e3d36376-00003: 924685e642a757d1838814744d3771ca _backup_chunk /usr/lib/python2.7/site-packages/cinder/backup/chunkeddriver.py:364
2018-02-11 08:55:27.936 1997 DEBUG cinder.backup.chunkeddriver [req-c952c516-b9b4-4cc3-b22b-a0a7be674522 8dab91fb867549249d6c90ffde60e926 b0bf0514c3484817b915bd0da3b47375 - default default] Calling eventlet.sleep(0) _backup_chunk /usr/lib/python2.7/site-packages/cinder/backup/chunkeddriver.py:370
2018-02-11 08:55:28.821 1997 DEBUG cinder.backup.chunkeddriver [req-2f688d8d-10d1-4c30-a2b0-4eb587884efc 8dab91fb867549249d6c90ffde60e926 b0bf0514c3484817b915bd0da3b47375 - default default] Backing up chunk of data from volume. _backup_chunk /usr/lib/python2.7/site-packages/cinder/backup/chunkeddriver.py:353
2018-02-11 08:55:29.006 1997 DEBUG cinder.backup.chunkeddriver [req-c952c516-b9b4-4cc3-b22b-a0a7be674522 8dab91fb867549249d6c90ffde60e926 b0bf0514c3484817b915bd0da3b47375 - default default] Backing up chunk of data from volume. _backup_chunk /usr/lib/python2.7/site-packages/cinder/backup/chunkeddriver.py:353

Comment 4 Tzach Shefi 2018-02-15 12:08:35 UTC

Verified on: openstack-cinder-9.1.4-24.el7ost.noarch
See comment 3

Comment 6 errata-xmlrpc 2018-02-27 16:40:58 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2018:0360

Comment 7 Gorka Eguileor 2018-05-03 10:21:52 UTC

I believe we discussed this on IRC, but to leave a record of the answer, yes, it is enough to do create to simultaneous backups and see in the logs that they have different requests and that these request IDs are interleaved when logging the chunks being backed up for each of the 2 backups, as the issue we fixed was that once the second backup comes in all log entries use the last request ID.