)]}'
{"/COMMIT_MSG":[{"author":{"_account_id":14070,"name":"Eric Fried","email":"openstack@fried.cc","username":"efried"},"change_message_id":"5e0443866fbc967e3bc05944031a7bcf7f97cc97","unresolved":false,"context_lines":[{"line_number":4,"context_line":"Commit:     Matthew Booth \u003cmbooth@redhat.com\u003e"},{"line_number":5,"context_line":"CommitDate: 2019-10-11 14:18:53 +0100"},{"line_number":6,"context_line":""},{"line_number":7,"context_line":"Don\u0027t take a lock when fetching a cached cell mapping"},{"line_number":8,"context_line":""},{"line_number":9,"context_line":"We call set_target_cell quite a lot. Each invocation generates the"},{"line_number":10,"context_line":"following 2 log messages:"}],"source_content_type":"text/x-gerrit-commit-message","patch_set":1,"id":"3fa7e38b_1fbd3fd7","line":7,"updated":"2019-10-30 17:38:38.000000000","message":"The commit title and message say two totally different things. You\u0027re doing both with the code change. But it reads pretty weird.","commit_id":"d450e8bf5d909f883964415eb44eb5098c8c95e1"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"a19237a514dffabf541979e20a83dd5eaedfc9c0","unresolved":false,"context_lines":[{"line_number":4,"context_line":"Commit:     Matthew Booth \u003cmbooth@redhat.com\u003e"},{"line_number":5,"context_line":"CommitDate: 2019-10-11 14:18:53 +0100"},{"line_number":6,"context_line":""},{"line_number":7,"context_line":"Don\u0027t take a lock when fetching a cached cell mapping"},{"line_number":8,"context_line":""},{"line_number":9,"context_line":"We call set_target_cell quite a lot. Each invocation generates the"},{"line_number":10,"context_line":"following 2 log messages:"}],"source_content_type":"text/x-gerrit-commit-message","patch_set":1,"id":"3fa7e38b_b0d40621","line":7,"in_reply_to":"3fa7e38b_1fbd3fd7","updated":"2019-11-06 22:07:19.000000000","message":"Yeah I thought the same.","commit_id":"d450e8bf5d909f883964415eb44eb5098c8c95e1"},{"author":{"_account_id":14070,"name":"Eric Fried","email":"openstack@fried.cc","username":"efried"},"change_message_id":"5e0443866fbc967e3bc05944031a7bcf7f97cc97","unresolved":false,"context_lines":[{"line_number":14,"context_line":""},{"line_number":15,"context_line":"It\u0027s useful but not entirely obvious that the lock here happens to be"},{"line_number":16,"context_line":"the cell uuid, so I\u0027ve added a shorter, more obvious log message to"},{"line_number":17,"context_line":"replace the above."},{"line_number":18,"context_line":""},{"line_number":19,"context_line":"Change-Id: If47ed9dcb0c1a8278ba87af884351ab9411175af"}],"source_content_type":"text/x-gerrit-commit-message","patch_set":1,"id":"3fa7e38b_df248762","line":17,"range":{"start_line":17,"start_character":0,"end_line":17,"end_character":7},"updated":"2019-10-30 17:38:38.000000000","message":"tbc, it\u0027s only \u0027replaced\u0027 when the cache is warm; otherwise you see all three messages (four including the \u0027untarget\u0027 one).","commit_id":"d450e8bf5d909f883964415eb44eb5098c8c95e1"}],"nova/context.py":[{"author":{"_account_id":14070,"name":"Eric Fried","email":"openstack@fried.cc","username":"efried"},"change_message_id":"5e0443866fbc967e3bc05944031a7bcf7f97cc97","unresolved":false,"context_lines":[{"line_number":349,"context_line":"        @utils.synchronized(cell_mapping.uuid)"},{"line_number":350,"context_line":"        def get_cell_connections():"},{"line_number":351,"context_line":"            try:"},{"line_number":352,"context_line":"                (db_connection, mq_connection) \u003d CELL_CACHE[cell_mapping.uuid]"},{"line_number":353,"context_line":"            except KeyError:"},{"line_number":354,"context_line":"                db_connection_string \u003d cell_mapping.database_connection"},{"line_number":355,"context_line":"                db_connection \u003d db.create_context_manager(db_connection_string)"}],"source_content_type":"text/x-python","patch_set":1,"id":"3fa7e38b_7f131302","line":352,"range":{"start_line":352,"start_character":49,"end_line":352,"end_character":59},"updated":"2019-10-30 17:38:38.000000000","message":"So we check the cache twice: once outside of the lock, and then again inside. Which IIUC is standard practice to avoid races populating the cache. Though it does mean that in such race conditions we could wind up printing the lock/unlock messages even when the cache is warm, which is the thing the commit message claims it\u0027s avoiding.","commit_id":"d450e8bf5d909f883964415eb44eb5098c8c95e1"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"a19237a514dffabf541979e20a83dd5eaedfc9c0","unresolved":false,"context_lines":[{"line_number":373,"context_line":"        except KeyError:"},{"line_number":374,"context_line":"            (db_connection, mq_connection) \u003d get_cell_connections()"},{"line_number":375,"context_line":""},{"line_number":376,"context_line":"        LOG.debug(\u0027Setting context for cell %(cell)s\u0027,"},{"line_number":377,"context_line":"                  {\u0027cell\u0027: cell_mapping.uuid})"},{"line_number":378,"context_line":""},{"line_number":379,"context_line":"        context.db_connection \u003d db_connection"}],"source_content_type":"text/x-python","patch_set":1,"id":"3fa7e38b_70de8e3f","line":376,"updated":"2019-11-06 22:07:19.000000000","message":"Can we drop this...","commit_id":"d450e8bf5d909f883964415eb44eb5098c8c95e1"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"a19237a514dffabf541979e20a83dd5eaedfc9c0","unresolved":false,"context_lines":[{"line_number":380,"context_line":"        context.mq_connection \u003d mq_connection"},{"line_number":381,"context_line":"        context.cell_uuid \u003d cell_mapping.uuid"},{"line_number":382,"context_line":"    else:"},{"line_number":383,"context_line":"        LOG.debug(\u0027Untargetting context\u0027)"},{"line_number":384,"context_line":""},{"line_number":385,"context_line":"        context.db_connection \u003d None"},{"line_number":386,"context_line":"        context.mq_connection \u003d None"}],"source_content_type":"text/x-python","patch_set":1,"id":"3fa7e38b_30e016f9","line":383,"updated":"2019-11-06 22:07:19.000000000","message":"...and this?\n\nThese are new log messages, right?\n\nOr are you adding these because if we pull from the cache and don\u0027t call get_cell_connection we won\u0027t log the entry/exit from synchronized?\n\nIf we\u0027re trying to reduce log noise, I don\u0027t see why we\u0027d need to include these? This is really more like trace-level (lower than debug) level information IMO, though we don\u0027t have something available in oslo.log for easily logging something lower than DEBUG (I tried: https://review.opendev.org/#/c/366422/ ).","commit_id":"d450e8bf5d909f883964415eb44eb5098c8c95e1"},{"author":{"_account_id":6873,"name":"Matt Riedemann","email":"mriedem.os@gmail.com","username":"mriedem"},"change_message_id":"34fc7e582288254184e83570049373345589ea96","unresolved":false,"context_lines":[{"line_number":380,"context_line":"        context.mq_connection \u003d mq_connection"},{"line_number":381,"context_line":"        context.cell_uuid \u003d cell_mapping.uuid"},{"line_number":382,"context_line":"    else:"},{"line_number":383,"context_line":"        LOG.debug(\u0027Untargetting context\u0027)"},{"line_number":384,"context_line":""},{"line_number":385,"context_line":"        context.db_connection \u003d None"},{"line_number":386,"context_line":"        context.mq_connection \u003d None"}],"source_content_type":"text/x-python","patch_set":1,"id":"3fa7e38b_909d4a6e","line":383,"in_reply_to":"3fa7e38b_30e016f9","updated":"2019-11-06 22:12:42.000000000","message":"Looking at the run with this:\n\nhttps://zuul.opendev.org/t/openstack/build/aef828ae4950402ea8c20f6d29fc491f/log/controller/logs/screen-n-api.txt.gz\n\nThis change drops the acquired/released messages to 4 each, which is cool.\n\nBut we still have over 1000 target messages (the untarget one doesn\u0027t show up in the api, superconductor or scheduler logs), which kind of sucks and points out that it should be trace level logging, not even debug IMO.","commit_id":"d450e8bf5d909f883964415eb44eb5098c8c95e1"}]}