+++ 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.
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
Verified on: openstack-cinder-9.1.4-24.el7ost.noarch See comment 3
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
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.