)]}'
{"nova/compute/resource_tracker.py":[{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"f36a5821da647c808a759ebb5210eb5dda24b852","unresolved":false,"context_lines":[{"line_number":1178,"context_line":"                # and fully archived before we got a chance to run this. The"},{"line_number":1179,"context_line":"                # former is far more likely than the latter. Avoid deleting"},{"line_number":1180,"context_line":"                # allocations for a building instance here."},{"line_number":1181,"context_line":"                LOG.warning(\"Instance %(uuid)s has allocations against this \""},{"line_number":1182,"context_line":"                            \"compute host but is not found in the database.\","},{"line_number":1183,"context_line":"                            {\u0027uuid\u0027: instance_uuid},"},{"line_number":1184,"context_line":"                            exc_info\u003dFalse)"},{"line_number":1185,"context_line":"                continue"},{"line_number":1186,"context_line":"            if instance.deleted:"},{"line_number":1187,"context_line":"                # The instance is gone, so we definitely want to remove"}],"source_content_type":"text/x-python","patch_set":3,"id":"3f4b6375_e9c0dce2","line":1184,"range":{"start_line":1181,"start_character":16,"end_line":1184,"end_character":43},"updated":"2017-11-01 20:40:39.000000000","message":"This is showing up a ton:\n\nhttp://logs.openstack.org/09/517009/3/check/legacy-tempest-dsvm-full-devstack-plugin-ceph/19d800c/logs/screen-n-cpu.txt.gz#_Nov_01_19_34_57_360853\n\nThe exc_info\u003dFalse doesn\u0027t seem to fix the stacktrace issue either, but that\u0027s less concerning to me right now.\n\nI don\u0027t think we\u0027re archiving records in Tempest runs so I\u0027m not sure what\u0027s going on here.","commit_id":"5044b615c7882209c6e8169331d9e319e7e5c80d"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"8ac70c46a25406a572e79e8859944fc6c5e99787","unresolved":false,"context_lines":[{"line_number":1178,"context_line":"                # and fully archived before we got a chance to run this. The"},{"line_number":1179,"context_line":"                # former is far more likely than the latter. Avoid deleting"},{"line_number":1180,"context_line":"                # allocations for a building instance here."},{"line_number":1181,"context_line":"                LOG.warning(\"Instance %(uuid)s has allocations against this \""},{"line_number":1182,"context_line":"                            \"compute host but is not found in the database.\","},{"line_number":1183,"context_line":"                            {\u0027uuid\u0027: instance_uuid},"},{"line_number":1184,"context_line":"                            exc_info\u003dFalse)"},{"line_number":1185,"context_line":"                continue"},{"line_number":1186,"context_line":"            if instance.deleted:"},{"line_number":1187,"context_line":"                # The instance is gone, so we definitely want to remove"}],"source_content_type":"text/x-python","patch_set":3,"id":"3f4b6375_2c7ba2be","line":1184,"range":{"start_line":1181,"start_character":16,"end_line":1184,"end_character":43},"in_reply_to":"3f4b6375_0c37c6b2","updated":"2017-11-01 21:18:33.000000000","message":"I looked for \"Deleting allocations that remained for this\" in n-cpu logs in 3 jobs for an ocata and pike patch. For the ocata patch, I didn\u0027t see it show up at all, which is not surprising and just confirms the race was introduced with creating allocations in the scheduler in pike.\n\nIn the logs for the pike patch, with 3 different jobs, I see the debug message show up 1, 3 and 4 times. That\u0027s more realistic to what I\u0027d expect with a busy scheduler and a single-node CI job where we only have one host to pick and the update_available_resource periodic is running every 60 seconds.\n\nSo we need to figure out why we\u0027d be hitting this so much more often in master. What I\u0027m thinking is maybe the alternate hosts stuff in the scheduler is making it just slow enough that it makes the window big enough to hit the race a lot of on slow CI nodes. I\u0027m going to see if I can test that theory with this debug patch:\n\nhttps://review.openstack.org/#/c/517108/\n\nI\u0027ll put a change on top of that to remove the alternate hosts logic in the scheduler and see what the relative difference is in time spent during select_destinations. Note this would be worse if we\u0027re doing a multi-create request since we spend more time in the scheduler.","commit_id":"5044b615c7882209c6e8169331d9e319e7e5c80d"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"0e8b4bb0c1da20283fe44490ea59b4994ceb5bd4","unresolved":false,"context_lines":[{"line_number":1178,"context_line":"                # and fully archived before we got a chance to run this. The"},{"line_number":1179,"context_line":"                # former is far more likely than the latter. Avoid deleting"},{"line_number":1180,"context_line":"                # allocations for a building instance here."},{"line_number":1181,"context_line":"                LOG.warning(\"Instance %(uuid)s has allocations against this \""},{"line_number":1182,"context_line":"                            \"compute host but is not found in the database.\","},{"line_number":1183,"context_line":"                            {\u0027uuid\u0027: instance_uuid},"},{"line_number":1184,"context_line":"                            exc_info\u003dFalse)"},{"line_number":1185,"context_line":"                continue"},{"line_number":1186,"context_line":"            if instance.deleted:"},{"line_number":1187,"context_line":"                # The instance is gone, so we definitely want to remove"}],"source_content_type":"text/x-python","patch_set":3,"id":"3f4b6375_dd7b96f1","line":1184,"range":{"start_line":1181,"start_character":16,"end_line":1184,"end_character":43},"in_reply_to":"3f4b6375_2c7ba2be","updated":"2017-11-01 23:35:08.000000000","message":"The alternate hosts stuff in the scheduler isn\u0027t adding much time to select_destinations, at least with 2 hosts. I checked the logs before and after https://review.openstack.org/#/c/517111/ and it\u0027s all around .30 seconds on average for select_destinations().","commit_id":"5044b615c7882209c6e8169331d9e319e7e5c80d"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"7e6f55ffe206497a470c786f1be49764b81d6080","unresolved":false,"context_lines":[{"line_number":1178,"context_line":"                # and fully archived before we got a chance to run this. The"},{"line_number":1179,"context_line":"                # former is far more likely than the latter. Avoid deleting"},{"line_number":1180,"context_line":"                # allocations for a building instance here."},{"line_number":1181,"context_line":"                LOG.warning(\"Instance %(uuid)s has allocations against this \""},{"line_number":1182,"context_line":"                            \"compute host but is not found in the database.\","},{"line_number":1183,"context_line":"                            {\u0027uuid\u0027: instance_uuid},"},{"line_number":1184,"context_line":"                            exc_info\u003dFalse)"},{"line_number":1185,"context_line":"                continue"},{"line_number":1186,"context_line":"            if instance.deleted:"},{"line_number":1187,"context_line":"                # The instance is gone, so we definitely want to remove"}],"source_content_type":"text/x-python","patch_set":3,"id":"3f4b6375_035bc5f5","line":1184,"range":{"start_line":1181,"start_character":16,"end_line":1184,"end_character":43},"in_reply_to":"3f4b6375_dd7b96f1","updated":"2017-11-05 23:23:12.000000000","message":"Looking at one of these for a single instance:\n\nhttp://logs.openstack.org/09/517009/3/check/legacy-tempest-dsvm-neutron-full/ed771bc/logs/screen-n-cpu.txt.gz?level\u003dTRACE#_Nov_01_19_44_27_342386\n\nIf you search for \"Instance a4a86303-c375-40b5-b418-5caab30d1dad has allocations against this compute host but is not found in the database\" it shows up 35 times, once every minute, so it\u0027s in the periodic and it\u0027s an instance that had allocations created by the scheduler but was deleted before it was created in a cell (there is a tempest test that deletes an instance while it\u0027s building). So this is a known bug we have where we don\u0027t cleanup allocations when an instance is deleted (local delete in the API) because it\u0027s not yet on a compute:\n\nhttps://bugs.launchpad.net/nova/+bug/1679750\n\nThat would also explain why we see this a bunch in some CI job results but not others - it\u0027s a result of that race.","commit_id":"5044b615c7882209c6e8169331d9e319e7e5c80d"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"59fa0bd9c7a10ecd9284de8561758c77d951e698","unresolved":false,"context_lines":[{"line_number":1178,"context_line":"                # and fully archived before we got a chance to run this. The"},{"line_number":1179,"context_line":"                # former is far more likely than the latter. Avoid deleting"},{"line_number":1180,"context_line":"                # allocations for a building instance here."},{"line_number":1181,"context_line":"                LOG.warning(\"Instance %(uuid)s has allocations against this \""},{"line_number":1182,"context_line":"                            \"compute host but is not found in the database.\","},{"line_number":1183,"context_line":"                            {\u0027uuid\u0027: instance_uuid},"},{"line_number":1184,"context_line":"                            exc_info\u003dFalse)"},{"line_number":1185,"context_line":"                continue"},{"line_number":1186,"context_line":"            if instance.deleted:"},{"line_number":1187,"context_line":"                # The instance is gone, so we definitely want to remove"}],"source_content_type":"text/x-python","patch_set":3,"id":"3f4b6375_0c37c6b2","line":1184,"range":{"start_line":1181,"start_character":16,"end_line":1184,"end_character":43},"in_reply_to":"3f4b6375_e9c0dce2","updated":"2017-11-01 20:53:33.000000000","message":"I compared with the old log message showing up in another patch and in three different jobs the \"Deleting allocations that remained for this\" message shows up but 3, 4, and 6 times in 3 different jobs, so far less than what I\u0027m seeing in the ceph job logs above.\n\nShows up 103 times in this job:\n\nhttp://logs.openstack.org/09/517009/3/check/legacy-tempest-dsvm-neutron-full/ed771bc/logs/screen-n-cpu.txt.gz","commit_id":"5044b615c7882209c6e8169331d9e319e7e5c80d"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"da9eb7646dc675601e37146b656504569812d57d","unresolved":false,"context_lines":[{"line_number":1186,"context_line":"                # and fully archived before we got a chance to run this. The"},{"line_number":1187,"context_line":"                # former is far more likely than the latter. Avoid deleting"},{"line_number":1188,"context_line":"                # allocations for a building instance here."},{"line_number":1189,"context_line":"                LOG.warning(\"Instance %(uuid)s has allocations against this \""},{"line_number":1190,"context_line":"                            \"compute host but is not found in the database.\","},{"line_number":1191,"context_line":"                            {\u0027uuid\u0027: instance_uuid},"},{"line_number":1192,"context_line":"                            exc_info\u003dFalse)"}],"source_content_type":"text/x-python","patch_set":4,"id":"3f4b6375_033ce5de","line":1189,"updated":"2017-11-06 01:02:44.000000000","message":"I don\u0027t know why but the traceback is still getting logged:\n\nhttp://logs.openstack.org/09/517009/4/check/legacy-tempest-dsvm-full-devstack-plugin-ceph/1a45b97/logs/screen-n-cpu.txt.gz?level\u003dTRACE#_Nov_06_00_15_18_737823\n\nMy guess is something in oslo.messaging is logging it:\n\nhttps://github.com/openstack/nova/blob/f3c1db09b71c8087f4967d87b2eb55f065a196e3/nova/conductor/manager.py#L125","commit_id":"456147d57d9bad0657f35fa07cd7f8e3801125b9"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"2f31239bc469d4f5ca831156ec52d7af883da7a9","unresolved":false,"context_lines":[{"line_number":1181,"context_line":"                LOG.info(\"Instance %(uuid)s has allocations against this \""},{"line_number":1182,"context_line":"                         \"compute host but is not found in the database.\","},{"line_number":1183,"context_line":"                         {\u0027uuid\u0027: instance_uuid},"},{"line_number":1184,"context_line":"                         exc_info\u003dFalse)"},{"line_number":1185,"context_line":"                continue"},{"line_number":1186,"context_line":""},{"line_number":1187,"context_line":"            if instance.deleted:"}],"source_content_type":"text/x-python","patch_set":5,"id":"3f4b6375_4668abf3","line":1184,"range":{"start_line":1184,"start_character":25,"end_line":1184,"end_character":39},"updated":"2017-11-06 02:15:42.000000000","message":"nit: we could drop this now that we\u0027re not logging at warning level.","commit_id":"d176175db456e4a312eed37ed4f5adcc06292fd5"}],"nova/tests/unit/compute/test_resource_tracker.py":[{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"24bb87126e16aaa8f7e1330d2541b7dd4b58dde0","unresolved":false,"context_lines":[{"line_number":481,"context_line":"        # parameter that update_available_resource() eventually passes"},{"line_number":482,"context_line":"        # to _update()."},{"line_number":483,"context_line":"        with mock.patch.object(self.rt, \u0027_update\u0027) as update_mock:"},{"line_number":484,"context_line":"            self.rt.update_available_resource(mock.MagicMock(), _NODENAME)"},{"line_number":485,"context_line":"        return update_mock"},{"line_number":486,"context_line":""},{"line_number":487,"context_line":"    @mock.patch(\u0027nova.objects.InstancePCIRequests.get_by_instance\u0027,"}],"source_content_type":"text/x-python","patch_set":3,"id":"3f4b6375_f764344b","line":484,"range":{"start_line":484,"start_character":46,"end_line":484,"end_character":62},"updated":"2017-11-01 19:54:37.000000000","message":"nit: would probably be better to use context.get_admin_context() here, since that\u0027s how the periodic does it:\n\nhttps://github.com/openstack/nova/blob/f974e3c3566f379211d7fdc790d07b5680925584/nova/service.py#L294","commit_id":"5044b615c7882209c6e8169331d9e319e7e5c80d"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"24bb87126e16aaa8f7e1330d2541b7dd4b58dde0","unresolved":false,"context_lines":[{"line_number":537,"context_line":""},{"line_number":538,"context_line":"        vd \u003d self.driver_mock"},{"line_number":539,"context_line":"        vd.get_available_resource.assert_called_once_with(_NODENAME)"},{"line_number":540,"context_line":"        get_mock.assert_called_once_with(mock.ANY, _HOSTNAME,"},{"line_number":541,"context_line":"                                         _NODENAME,"},{"line_number":542,"context_line":"                                         expected_attrs\u003d["},{"line_number":543,"context_line":"                                             \u0027system_metadata\u0027,"}],"source_content_type":"text/x-python","patch_set":3,"id":"3f4b6375_f7c9d424","line":540,"range":{"start_line":540,"start_character":41,"end_line":540,"end_character":49},"updated":"2017-11-01 19:54:37.000000000","message":"Then we could use test.MatchType(context.RequestContext) here.","commit_id":"5044b615c7882209c6e8169331d9e319e7e5c80d"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"24bb87126e16aaa8f7e1330d2541b7dd4b58dde0","unresolved":false,"context_lines":[{"line_number":2491,"context_line":"        ctx.elevated.assert_called_once_with(read_deleted\u003d\u0027yes\u0027)"},{"line_number":2492,"context_line":""},{"line_number":2493,"context_line":"    @mock.patch(\u0027nova.objects.Instance.get_by_uuid\u0027)"},{"line_number":2494,"context_line":"    def test_remove_deleted_instances_allocations_building_instance(self,"},{"line_number":2495,"context_line":"            mock_inst_get):"},{"line_number":2496,"context_line":"        rc \u003d self.rt.reportclient"},{"line_number":2497,"context_line":"        self.rt.tracked_instances \u003d {}"}],"source_content_type":"text/x-python","patch_set":3,"id":"3f4b6375_77fe0439","line":2494,"updated":"2017-11-01 19:54:37.000000000","message":"Could have the same assertions in this test:\n\nmock_inst_get.assert_called_once_with(\n            ctx.elevated.return_value,\n            uuids.deleted,\n            expected_attrs\u003d[])\nctx.elevated.assert_called_once_with(read_deleted\u003d\u0027yes\u0027)","commit_id":"5044b615c7882209c6e8169331d9e319e7e5c80d"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"24bb87126e16aaa8f7e1330d2541b7dd4b58dde0","unresolved":false,"context_lines":[{"line_number":2507,"context_line":"        self.rt._remove_deleted_instances_allocations(ctx, cn, [])"},{"line_number":2508,"context_line":"        # Instance wasn\u0027t found in the database at all, so the allocation"},{"line_number":2509,"context_line":"        # should not have been deleted"},{"line_number":2510,"context_line":"        self.assertFalse(rc.delete_allocation_for_instance.called)"},{"line_number":2511,"context_line":""},{"line_number":2512,"context_line":"    @mock.patch(\u0027nova.objects.Instance.get_by_uuid\u0027)"},{"line_number":2513,"context_line":"    def test_remove_deleted_instances_allocations_ignores_migrations(self,"}],"source_content_type":"text/x-python","patch_set":3,"id":"3f4b6375_179590e4","line":2510,"updated":"2017-11-01 19:54:37.000000000","message":"nit: rc.delete_allocation_for_instance.assert_not_called()","commit_id":"5044b615c7882209c6e8169331d9e319e7e5c80d"}]}