ValueError: not enough values to unpack during Tempest execution

We have a CI job for checking rally verification component. It never faced such issue. strange:(

May I ask to modify code of rally to print additional debug information? https://github.com/openstack/rally/blob/master/rally/common/io/subunit_v2.py#L39 it would be nice to print mime_type before this line, so we can understand was is the root cause.

Hello, thank you for your answer.
I have added debug log before indicated line with mime_type and test_id values and attached new rally.log. Another strange thing - this bug seems to break down Rally's process, but not Testr's.

I also provide steps we do to run tests (maybe there is something wrong):
- Rally installation:
git clone https://github.com/openstack/rally.git rally_repo
cd rally_repo
git checkout 3.0.0
rally db create
pip3 install -I . && pip3 install rally-openstack
- create Rally deployment:
source /root/openrc && rally deployment create --fromenv --name=deployment_tempest
- create Rally verifier:
rally verify create-verifier --type tempest --name tempest_verifier --source /root/tempest && rally verify configure-verifier --extend /root/extra_options.conf
(also we have problems with Testr, Rally not returns any results for Ocata - it seems like Testr isn't initialized in proper way, so we are using workaround and initial it with command before we run tests)
cd /root/.rally/verification/verifier-<verifier_id>/repo/ && . ../.venv/bin/activate && testr init
- run tests:
rally verify start --concurrency 2 --pattern api --skip-list /root/skiplist

Thanks for an additional data. Can you verify that the following fix works (I cannot reproduce the issue locally) https://review.opendev.org/#/c/721628/ ?

I have run our Jenkins job about 20 times over the night - problem wasn't occurred (previously it occurred once at 3 - 4 runs), so I think issue is fixed. :) Thank you so much. I added +1 on your change in Gerrit.

I still do not know what is subunit.parser test_id means...

Reviewed: https://review.opendev.org/721628
Committed: https://git.openstack.org/cgit/openstack/rally/commit/?id=b9c303c2f47b4cf38393372bb0310fbf87147b50
Submitter: Zuul
Branch: master

commit b9c303c2f47b4cf38393372bb0310fbf87147b50
Author: Andrey Kurilin <email address hidden>
Date: Tue Apr 21 17:23:31 2020 +0300

    Fix parsing of mime-type at subunit-v2-parser

    + ignore unwanted test id with strange data
    + do not try to split charset from mime-type. we do not use it.

    Change-Id: I374c45008dcdfb910d34868df795e6dbf5b962a3
    Closes-Bug: #1871406

I don't exactly know what subunit.parser is, but it seems to be related with tearDown or tearDownClass. For example this test:

tempest.api.compute.admin.test_create_server.ServersWithSpecificFlavorTestJSON.test_verify_created_server_ephemeral_disk

failed 3 times at row and it has in its code:

    self.addCleanup(test_utils.call_and_ignore_notfound_exc,
                    self.servers_client.delete_server,
                    server_no_eph_disk['id'])

It seems to be a problem when NotFound error is ignored. Part of tempest.log (with debug set to true in tempest.conf):

2020-04-22 09:04:07.698 899 INFO tempest.lib.common.rest_client [req-c724ed29-d1ba-4e04-bc5f-e8a5b011f626 ] Request (ServersWithSpecificFlavorTestJSON:tearDownClass): 404 GET https://106.120.122.121:8774/v2.1/bc23b2b6e71d4ea68da8280da24b2070/servers/4e9764d5-a6ae-4461-868c-e4b01d72fd64 0.086s
2020-04-22 09:04:07.698 899 DEBUG tempest.lib.common.rest_client [req-c724ed29-d1ba-4e04-bc5f-e8a5b011f626 ] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'X-OpenStack-Nova-API-Version', 'content-type': 'application/json; charset=UTF-8', 'content-length': '111', 'x-openstack-request-id': 'req-c724ed29-d1ba-4e04-bc5f-e8a5b011f626', 'x-compute-request-id': 'req-c724ed29-d1ba-4e04-bc5f-e8a5b011f626', 'date': 'Wed, 22 Apr 2020 09:04:07 GMT', 'connection': 'close', 'status': '404', 'content-location': 'https://106.120.122.121:8774/v2.1/bc23b2b6e71d4ea68da8280da24b2070/servers/4e9764d5-a6ae-4461-868c-e4b01d72fd64'}
        Body: b'{"itemNotFound": {"message": "Instance 4e9764d5-a6ae-4461-868c-e4b01d72fd64 could not be found.", "code": 404}}' _log_request_full /root/.rally/verification/verifier-7b84d403-5be7-4aa5-a5b1-f93136c5e3a3/repo/tempest/lib/common/rest_client.py:425
2020-04-22 09:04:08.041 899 INFO tempest.lib.common.rest_client [req-5475139c-8fcd-47b3-a02d-efc32b742305 ] Request (ServersWithSpecificFlavorTestJSON:tearDownClass): 200 GET https://106.120.122.121:8774/v2.1/bc23b2b6e71d4ea68da8280da24b2070/servers/05af61fb-6cc0-4fc0-868d-d19e43ff955a 0.341s

and part of rally.log about the same time:

2020-04-22 09:04:07.167 891 INFO rally.task.context [-] Verification 7b84d403-5be7-4aa5-a5b1-f93136c5e3a3 | Context tempest@default cleanup() started
2020-04-22 09:04:07.980 891 INFO rally.task.context [-] Verification 7b84d403-5be7-4aa5-a5b1-f93136c5e3a3 | Context tempest@default cleanup() finished in 0.81 sec
2020-04-22 09:04:07.998 891 ERROR rally.cli.cliutils [-] Unexpected exception in CLI: ValueError: not enough values to unpack (expected 2, got 1)

both files in attachment.

One more thing - when run of our job is ok requests from cleanup aren't parsed. But I don't know why once they are parse and once not. I also attached rally.log and tempest.log from run, which passed.