)]}'
{"/COMMIT_MSG":[{"author":{"_account_id":4393,"name":"Dan Smith","email":"dms@danplanet.com","username":"danms"},"change_message_id":"00f86eefd44531f9cb01cec59a0898f97b1978c6","unresolved":true,"context_lines":[{"line_number":13,"context_line":""},{"line_number":14,"context_line":"This patch moves the warning log into wait_for_instance_event itself and"},{"line_number":15,"context_line":"extends the log with the name of the event nova waited for when the"},{"line_number":16,"context_line":"timeout happens."},{"line_number":17,"context_line":""},{"line_number":18,"context_line":"Change-Id: I91c42af8226dc8607d86c52413924351ba0586ac"}],"source_content_type":"text/x-gerrit-commit-message","patch_set":2,"id":"c8011ef2_b5688e21","line":16,"updated":"2022-01-10 16:12:43.000000000","message":"This is not really wrong, but a lot more has changed about what you\u0027re logging than just adding the name of the timed out event :)","commit_id":"4af845f0675e68426b05070db3844bdbca66de9f"}],"/PATCHSET_LEVEL":[{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"3a29998f0032db4a9575977922ba156f44b529a9","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":1,"id":"a6e4fff1_ff57fed7","updated":"2021-11-30 13:05:31.000000000","message":"As a continuation of I1be011f4dbcace78a698f9700170b8884e98a49b and a reaction of the recent ML threads about vif plug timeout...","commit_id":"efb615819db095152ea8b5b24a9c28eaa636adcf"},{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"2813c3a3becdf6088ca937d249843db5f551c353","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":1,"id":"22d3ffcd_d5940c40","updated":"2021-12-09 17:50:19.000000000","message":"Made it better :)","commit_id":"efb615819db095152ea8b5b24a9c28eaa636adcf"},{"author":{"_account_id":15334,"name":"Stephen Finucane","display_name":"stephenfin","email":"stephenfin@redhat.com","username":"sfinucan"},"change_message_id":"7b0ab9ab336be9bba6cb0ded37aba8d30a0985a1","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":2,"id":"d1dcf6a0_d83ebfee","updated":"2022-01-14 18:14:27.000000000","message":"Nicely done","commit_id":"4af845f0675e68426b05070db3844bdbca66de9f"},{"author":{"_account_id":7634,"name":"Takashi Natsume","email":"takanattie@gmail.com","username":"natsumet"},"change_message_id":"714f2534d7f7abfe59fe17c6a47e4a4db1f4d731","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":2,"id":"2ff2e919_98d2a8f5","updated":"2022-02-25 16:03:24.000000000","message":"recheck","commit_id":"4af845f0675e68426b05070db3844bdbca66de9f"},{"author":{"_account_id":7634,"name":"Takashi Natsume","email":"takanattie@gmail.com","username":"natsumet"},"change_message_id":"7093729e3c06dbd4e82eb31153b7bb00f911e7a9","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":2,"id":"8ded5ac7_7529c653","updated":"2022-02-22 18:44:18.000000000","message":"recheck","commit_id":"4af845f0675e68426b05070db3844bdbca66de9f"},{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"6c1d2deb37717bf85699b251bed8f255e0de23c2","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":2,"id":"d766ca34_86a752bd","updated":"2021-12-13 11:12:40.000000000","message":"recheck bug 1954427 (fix already landed)","commit_id":"4af845f0675e68426b05070db3844bdbca66de9f"},{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"e92ac03fa06de687de49a07794a3d1270a557526","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":2,"id":"ad65afe6_85a9adbf","updated":"2021-12-10 10:25:44.000000000","message":"recheck vif timeout [1] (it already shows the new LOG in action :D)\n\n[1] https://zuul.opendev.org/t/openstack/build/337497d72f4142ecae5662d366482a12/log/compute1/logs/screen-n-cpu.txt#34329","commit_id":"4af845f0675e68426b05070db3844bdbca66de9f"}],"nova/compute/manager.py":[{"author":{"_account_id":4393,"name":"Dan Smith","email":"dms@danplanet.com","username":"danms"},"change_message_id":"d8b77202f7772f2db5f6ac4876b2e55b6c4e6d41","unresolved":true,"context_lines":[{"line_number":479,"context_line":"                    if event_name in early_events:"},{"line_number":480,"context_line":"                        continue"},{"line_number":481,"context_line":"                    else:"},{"line_number":482,"context_line":"                        actual_event \u003d event.wait()"},{"line_number":483,"context_line":"                        if actual_event.status \u003d\u003d \u0027completed\u0027:"},{"line_number":484,"context_line":"                            continue"},{"line_number":485,"context_line":"                    # If we get here, we have an event that was not completed,"}],"source_content_type":"text/x-python","patch_set":1,"id":"45e8ee5d_45872dfa","line":482,"updated":"2021-11-30 14:56:27.000000000","message":"This is getting pretty deeply nested. It was deep before, but this is the point at which I\u0027d be breaking out something, like the event loop, into a separate method so that this just looks like:\n\n try:\n     with timeout:\n         self.do_events()\n     except timeout:\n         ...\n\nBut just MHO.","commit_id":"efb615819db095152ea8b5b24a9c28eaa636adcf"},{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"2813c3a3becdf6088ca937d249843db5f551c353","unresolved":false,"context_lines":[{"line_number":479,"context_line":"                    if event_name in early_events:"},{"line_number":480,"context_line":"                        continue"},{"line_number":481,"context_line":"                    else:"},{"line_number":482,"context_line":"                        actual_event \u003d event.wait()"},{"line_number":483,"context_line":"                        if actual_event.status \u003d\u003d \u0027completed\u0027:"},{"line_number":484,"context_line":"                            continue"},{"line_number":485,"context_line":"                    # If we get here, we have an event that was not completed,"}],"source_content_type":"text/x-python","patch_set":1,"id":"508058e0_a9f1aa84","line":482,"in_reply_to":"45e8ee5d_45872dfa","updated":"2021-12-09 17:50:19.000000000","message":"sure, that make sense.\n\n//later\n\nI ended up doing more refactoring than that as pulling the for loop alone was not enough","commit_id":"efb615819db095152ea8b5b24a9c28eaa636adcf"},{"author":{"_account_id":4393,"name":"Dan Smith","email":"dms@danplanet.com","username":"danms"},"change_message_id":"d8b77202f7772f2db5f6ac4876b2e55b6c4e6d41","unresolved":true,"context_lines":[{"line_number":494,"context_line":"                \u0027vm_state %(vm_state)s and task_state %(task_state)s. \u0027"},{"line_number":495,"context_line":"                \u0027Event %(missing_event)s was expected but never received.\u0027,"},{"line_number":496,"context_line":"                {"},{"line_number":497,"context_line":"                    \u0027events\u0027: events,"},{"line_number":498,"context_line":"                    \u0027vm_state\u0027: instance.vm_state,"},{"line_number":499,"context_line":"                    \u0027task_state\u0027: instance.task_state,"},{"line_number":500,"context_line":"                    \u0027missing_event\u0027: event_name,"}],"source_content_type":"text/x-python","patch_set":1,"id":"c3f73788_40e7bc81","line":497,"range":{"start_line":497,"start_character":30,"end_line":497,"end_character":36},"updated":"2021-11-30 14:56:27.000000000","message":"Is there some reason to log events and not just event_names here? It will be a dict of name: Event() right? Seems like event_names would be easier to read.","commit_id":"efb615819db095152ea8b5b24a9c28eaa636adcf"},{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"2813c3a3becdf6088ca937d249843db5f551c353","unresolved":false,"context_lines":[{"line_number":494,"context_line":"                \u0027vm_state %(vm_state)s and task_state %(task_state)s. \u0027"},{"line_number":495,"context_line":"                \u0027Event %(missing_event)s was expected but never received.\u0027,"},{"line_number":496,"context_line":"                {"},{"line_number":497,"context_line":"                    \u0027events\u0027: events,"},{"line_number":498,"context_line":"                    \u0027vm_state\u0027: instance.vm_state,"},{"line_number":499,"context_line":"                    \u0027task_state\u0027: instance.task_state,"},{"line_number":500,"context_line":"                    \u0027missing_event\u0027: event_name,"}],"source_content_type":"text/x-python","patch_set":1,"id":"a17f825a_3177f1ea","line":497,"range":{"start_line":497,"start_character":30,"end_line":497,"end_character":36},"in_reply_to":"c3f73788_40e7bc81","updated":"2021-12-09 17:50:19.000000000","message":"You are right, a list of event_names is enough","commit_id":"efb615819db095152ea8b5b24a9c28eaa636adcf"},{"author":{"_account_id":4393,"name":"Dan Smith","email":"dms@danplanet.com","username":"danms"},"change_message_id":"d8b77202f7772f2db5f6ac4876b2e55b6c4e6d41","unresolved":true,"context_lines":[{"line_number":497,"context_line":"                    \u0027events\u0027: events,"},{"line_number":498,"context_line":"                    \u0027vm_state\u0027: instance.vm_state,"},{"line_number":499,"context_line":"                    \u0027task_state\u0027: instance.task_state,"},{"line_number":500,"context_line":"                    \u0027missing_event\u0027: event_name,"},{"line_number":501,"context_line":"                },"},{"line_number":502,"context_line":"                instance\u003dinstance)"},{"line_number":503,"context_line":""}],"source_content_type":"text/x-python","patch_set":1,"id":"de30843c_11b008be","line":500,"updated":"2021-11-30 14:56:27.000000000","message":"I\u0027m a little worried that this might mislead someone about what has happened here. I think that if you see this:\n\n events: vif-1, vif-2\n missing-event: vif-2\n\nyou are going to assume it\u0027s vif-2 that was the problem. However, if vif-1 took 299 seconds, you might go chasing vif-2 problems that aren\u0027t really there.\n\nMaybe that doesn\u0027t make sense for the current situation, where we expect it\u0027s one vif that never gets the callback, but I wonder if it might be better to report the events we received and how long we waited for each, instead of just assuming the current one after the timeout was the problematic one?","commit_id":"efb615819db095152ea8b5b24a9c28eaa636adcf"},{"author":{"_account_id":9708,"name":"Balazs Gibizer","display_name":"gibi","email":"gibizer@gmail.com","username":"gibi"},"change_message_id":"2813c3a3becdf6088ca937d249843db5f551c353","unresolved":false,"context_lines":[{"line_number":497,"context_line":"                    \u0027events\u0027: events,"},{"line_number":498,"context_line":"                    \u0027vm_state\u0027: instance.vm_state,"},{"line_number":499,"context_line":"                    \u0027task_state\u0027: instance.task_state,"},{"line_number":500,"context_line":"                    \u0027missing_event\u0027: event_name,"},{"line_number":501,"context_line":"                },"},{"line_number":502,"context_line":"                instance\u003dinstance)"},{"line_number":503,"context_line":""}],"source_content_type":"text/x-python","patch_set":1,"id":"1495373b_14526edc","line":500,"in_reply_to":"de30843c_11b008be","updated":"2021-12-09 17:50:19.000000000","message":"Hm. My intention was that when nova times out there will be one log message that clearly states the reason as I\u0027m lazy collecting the log messages \"Instance event wait completed in %i seconds for\" and the correlating that with the list of expected messages from \"Preparing to wait for external event\" log. \n\nAs we did all the plugs in parallel if vif-1 take 299 seconds but vif-2 only takes 10 seconds then still after wait() returned with vif-1 the vif-2 will already been received and the next wait() call will return immediately without timing out. \n\nI think the more problematic case is when there are 3 events, second times out and therefore we never call wait() on the 3rd event so we don\u0027t know here if it is received or not. (We have a separate log about receiving events so from a wider log analysis this can be seen properly)\n\nAnyhow I can combine the timing values into this LOG.warning message so at least the log reader has all pieces of available information in a single log.","commit_id":"efb615819db095152ea8b5b24a9c28eaa636adcf"},{"author":{"_account_id":4393,"name":"Dan Smith","email":"dms@danplanet.com","username":"danms"},"change_message_id":"00f86eefd44531f9cb01cec59a0898f97b1978c6","unresolved":true,"context_lines":[{"line_number":473,"context_line":"            # keep waiting by calling the error_callback() hook."},{"line_number":474,"context_line":"            decision \u003d error_callback(event_name, instance)"},{"line_number":475,"context_line":"            if decision is False:"},{"line_number":476,"context_line":"                break"},{"line_number":477,"context_line":""},{"line_number":478,"context_line":"    @contextlib.contextmanager"},{"line_number":479,"context_line":"    def wait_for_instance_event(self, instance, event_names, deadline\u003d300,"}],"source_content_type":"text/x-python","patch_set":2,"id":"e5b58673_47e9e73f","line":476,"updated":"2022-01-10 16:12:43.000000000","message":"Man, this is a lot of refactor to get the log message better :)\n\nI _think_ it all looks right though...","commit_id":"4af845f0675e68426b05070db3844bdbca66de9f"}],"nova/tests/unit/compute/test_virtapi.py":[{"author":{"_account_id":4393,"name":"Dan Smith","email":"dms@danplanet.com","username":"danms"},"change_message_id":"00f86eefd44531f9cb01cec59a0898f97b1978c6","unresolved":true,"context_lines":[{"line_number":318,"context_line":"                        \u0027early-event\u0027,"},{"line_number":319,"context_line":"                        \u0027missing-event\u0027,"},{"line_number":320,"context_line":"                        \u0027received-but-not-waited-event\u0027,"},{"line_number":321,"context_line":"                        \u0027missing-but-not-waited-event\u0027"},{"line_number":322,"context_line":"                     ],"},{"line_number":323,"context_line":"                \u0027vm_state\u0027: mock.sentinel.vm_state,"},{"line_number":324,"context_line":"                \u0027task_state\u0027: mock.sentinel.task_state,"}],"source_content_type":"text/x-python","patch_set":2,"id":"54f18699_3c41752c","line":321,"updated":"2022-01-10 16:12:43.000000000","message":"I wonder if this ends up just making this very long and hard to read. It\u0027s all duplicate information that is in the event_states dump right?","commit_id":"4af845f0675e68426b05070db3844bdbca66de9f"},{"author":{"_account_id":4393,"name":"Dan Smith","email":"dms@danplanet.com","username":"danms"},"change_message_id":"00f86eefd44531f9cb01cec59a0898f97b1978c6","unresolved":true,"context_lines":[{"line_number":324,"context_line":"                \u0027task_state\u0027: mock.sentinel.task_state,"},{"line_number":325,"context_line":"                \u0027event_states\u0027:"},{"line_number":326,"context_line":"                    \u0027received-event: received after waiting 0.00 seconds, \u0027"},{"line_number":327,"context_line":"                    \u0027early-event: received early, \u0027"},{"line_number":328,"context_line":"                    \u0027missing-event: timed out after 0.00 seconds, \u0027"},{"line_number":329,"context_line":"                    \u0027received-but-not-waited-event: received but not \u0027"},{"line_number":330,"context_line":"                    \u0027processed, \u0027"}],"source_content_type":"text/x-python","patch_set":2,"id":"90f5218d_c596b3a0","line":327,"range":{"start_line":327,"start_character":34,"end_line":327,"end_character":48},"updated":"2022-01-10 16:12:43.000000000","message":"This might be perceived as a problem by someone looking at this now very long list of things and trying to figure out what the actual failure is. Like \"does early mean TOO early?\". It\u0027s maybe useful for debugging for us, but not really relevant to the analysis of a failure by an operator.\n\nThat said, I don\u0027t think it\u0027s worth changing on my account, I just wanted to point it out in case anyone else thinks it might be misleading.","commit_id":"4af845f0675e68426b05070db3844bdbca66de9f"}]}