)]}'
{"/PATCHSET_LEVEL":[{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"322149c362033ebaeb54c3cb756ef63180e6ad42","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":1,"id":"7fb2cff1_1c5ba5ce","updated":"2021-10-13 06:51:26.000000000","message":"recheck try to reproduce","commit_id":"459a6b9d6d4b7973e24a6ee232039ebf8cba333c"}],"nova/compute/manager.py":[{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"a61ebed6cd9ac7350cb7b56fc0434ca2620ed6a0","unresolved":true,"context_lines":[{"line_number":2263,"context_line":"            LOG.error("},{"line_number":2264,"context_line":"                \u0027!!! Reschedule triggered from %s due to %s, %s\u0027,"},{"line_number":2265,"context_line":"                self.host, e, retry"},{"line_number":2266,"context_line":"            )"},{"line_number":2267,"context_line":"            self.compute_task_api.build_instances(context, [instance],"},{"line_number":2268,"context_line":"                    image, filter_properties, admin_password,"},{"line_number":2269,"context_line":"                    injected_files, requested_networks, security_groups,"}],"source_content_type":"text/x-python","patch_set":1,"id":"c4fc8512_f2650082","line":2266,"updated":"2021-10-13 08:04:55.000000000","message":"Could somebody explain why this log is not visible in the output. The stack trace of a reproduction shows this: \n\nTraceback (most recent call last):\n  File \"/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py\", line 200, in decorated_function\n    return function(self, context, *args, **kwargs)\n  File \"/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py\", line 2271, in _do_build_and_run_instance\n\nIf line 2271 was run then I think L2266 should have been run too. But the log I added is not visible. :/","commit_id":"459a6b9d6d4b7973e24a6ee232039ebf8cba333c"},{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"e58a4a7ceeaa2c1170445cfea9de677152c74406","unresolved":true,"context_lines":[{"line_number":2263,"context_line":"            LOG.error("},{"line_number":2264,"context_line":"                \u0027!!! Reschedule triggered from %s due to %s, %s\u0027,"},{"line_number":2265,"context_line":"                self.host, e, retry"},{"line_number":2266,"context_line":"            )"},{"line_number":2267,"context_line":"            self.compute_task_api.build_instances(context, [instance],"},{"line_number":2268,"context_line":"                    image, filter_properties, admin_password,"},{"line_number":2269,"context_line":"                    injected_files, requested_networks, security_groups,"}],"source_content_type":"text/x-python","patch_set":1,"id":"5fe0c31c_fe53a0c3","line":2266,"in_reply_to":"08245e50_0dd94371","updated":"2021-10-13 11:23:16.000000000","message":"OK the subunit output is more complete[1]. The uuid(2a29987a-4208-4cc0-a783-2f82f7b3b3ae) from the test failure in [2] matches with the uuid in the log from the subunit file (see below). It is the LOG I added to catch the reschedule. \n\nBut it does not match with the instance uuid (4015fe98-0877-4b41-bb46-c8baf4835f08) the failed test actually building at [3]. Also the failed test uses host1 and host2. But the error talks about \u0027hosts\u0027: [[\u0027compute\u0027, \u0027fake-mini\u0027]]. So it really feels we somehow hit a leaked instance from another testcase. \n\n[1]https://d437e0d32270502deecd-bae68f4f9acafcdb88c180c1d5a48439.ssl.cf5.rackcdn.com/813674/1/check/nova-tox-functional-centos8-py36/bbb5a82/testrepository.subunit\n[2]https://zuul.opendev.org/t/openstack/build/bbb5a822e5724af7b81b96e01e933a29\n[3] https://zuul.opendev.org/t/openstack/build/bbb5a822e5724af7b81b96e01e933a29/log/job-output.txt#4965\n\n\n2021-10-13 07:30:04,262 ERROR [nova.compute.manager] !!! Reschedule triggered from compute due to Build of instance 2a29987a-4208-4cc0-a783-2f82f7b3b3ae was re-scheduled: Compute host 1 could not be found., {\u0027num_attempts\u0027: 1, \u0027hosts\u0027: [[\u0027compute\u0027, \u0027fake-mini\u0027]], \u0027exc\u0027: [\u0027Traceback (most recent call last):\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py\", line 2377, in _build_and_run_instance\\n    limits):\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_concurrency/lockutils.py\", line 360, in inner\\n    return f(*args, **kwargs)\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/compute/resource_tracker.py\", line 196, in instance_claim\\n    self._update(elevated, cn)\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/compute/resource_tracker.py\", line 1225, in _update\\n    self.old_resources[nodename] \u003d old_compute\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_utils/excutils.py\", line 227, in __exit__\\n    self.force_reraise()\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_utils/excutils.py\", line 200, in force_reraise\\n    raise self.value\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/compute/resource_tracker.py\", line 1219, in _update\\n    compute_node.save()\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_versionedobjects/base.py\", line 226, in wrapper\\n    return fn(self, *args, **kwargs)\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/objects/compute_node.py\", line 356, in save\\n    db_compute \u003d db.compute_node_update(self._context, self.id, updates)\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_db/api.py\", line 154, in wrapper\\n    ectxt.value \u003d e.inner_exc\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_utils/excutils.py\", line 227, in __exit__\\n    self.force_reraise()\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_utils/excutils.py\", line 200, in force_reraise\\n    raise self.value\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_db/api.py\", line 142, in wrapper\\n    return f(*args, **kwargs)\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/db/main/api.py\", line 190, in wrapper\\n    return f(context, *args, **kwargs)\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/db/main/api.py\", line 859, in compute_node_update\\n    compute_ref \u003d compute_node_get_model(context, compute_id)\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/db/main/api.py\", line 207, in wrapper\\n    return f(context, *args, **kwargs)\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/db/main/api.py\", line 642, in compute_node_get_model\\n    raise exception.ComputeHostNotFound(host\u003dcompute_id)\\n\u0027, \u0027nova.exception.ComputeHostNotFound: Compute host 1 could not be found.\\n\u0027, \u0027\\nDuring handling of the above exception, another exception occurred:\\n\\n\u0027, \u0027Traceback (most recent call last):\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py\", line 2224, in _do_build_and_run_instance\\n    filter_properties, request_spec, accel_uuids)\\n\u0027, \u0027  File \"/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py\", line 2499, in _build_and_run_instance\\n    instance_uuid\u003dinstance.uuid, reason\u003dstr(e))\\n\u0027, \u0027nova.exception.RescheduledException: Build of instance 2a29987a-4208-4cc0-a783-2f82f7b3b3ae was re-scheduled: Compute host 1 could not be found.\\n\u0027], \u0027exc_reason\u0027: \u0027Compute host 1 could not be found.\u0027}","commit_id":"459a6b9d6d4b7973e24a6ee232039ebf8cba333c"},{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"352824b69ef85f9983e013a8a0b6af42b0d80305","unresolved":true,"context_lines":[{"line_number":2263,"context_line":"            LOG.error("},{"line_number":2264,"context_line":"                \u0027!!! Reschedule triggered from %s due to %s, %s\u0027,"},{"line_number":2265,"context_line":"                self.host, e, retry"},{"line_number":2266,"context_line":"            )"},{"line_number":2267,"context_line":"            self.compute_task_api.build_instances(context, [instance],"},{"line_number":2268,"context_line":"                    image, filter_properties, admin_password,"},{"line_number":2269,"context_line":"                    injected_files, requested_networks, security_groups,"}],"source_content_type":"text/x-python","patch_set":1,"id":"6ed7dc85_aac8ca81","line":2266,"in_reply_to":"5fe0c31c_fe53a0c3","updated":"2021-10-13 11:35:52.000000000","message":"After I extracted the subunit file to individual test logs with subunit2disk I grepped for the uuid that logged as timeoud out booting. It is mentioned in two test case logs https://paste.opendev.org/show/809961/ So this is an interaction between two test cases somehow","commit_id":"459a6b9d6d4b7973e24a6ee232039ebf8cba333c"},{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"483fbfd3c97df15e6c1063b42943a3c65263e6c3","unresolved":true,"context_lines":[{"line_number":2263,"context_line":"            LOG.error("},{"line_number":2264,"context_line":"                \u0027!!! Reschedule triggered from %s due to %s, %s\u0027,"},{"line_number":2265,"context_line":"                self.host, e, retry"},{"line_number":2266,"context_line":"            )"},{"line_number":2267,"context_line":"            self.compute_task_api.build_instances(context, [instance],"},{"line_number":2268,"context_line":"                    image, filter_properties, admin_password,"},{"line_number":2269,"context_line":"                    injected_files, requested_networks, security_groups,"}],"source_content_type":"text/x-python","patch_set":1,"id":"08245e50_0dd94371","line":2266,"in_reply_to":"c4fc8512_f2650082","updated":"2021-10-13 08:05:58.000000000","message":"See: https://zuul.opendev.org/t/openstack/build/bbb5a822e5724af7b81b96e01e933a29/log/job-output.txt#4068","commit_id":"459a6b9d6d4b7973e24a6ee232039ebf8cba333c"}]}