From e7db7d8b533eb6bdccd17ddaed31cc67cd64602f Mon Sep 17 00:00:00 2001 From: Tomas Kopecek Date: Feb 07 2022 09:01:21 +0000 Subject: [PATCH 1/3] db: logging option for cursor In some cases we expect query to fail (LOCK NOWAIT) but it still clutters the logs. Option for not logging cursor-level errors. Fixes: https://pagure.io/koji/issue/2837 --- diff --git a/hub/kojihub.py b/hub/kojihub.py index 2f0ea42..d8128e6 100644 --- a/hub/kojihub.py +++ b/hub/kojihub.py @@ -5421,10 +5421,13 @@ def _singleValue(query, values=None, strict=True): return None -def _dml(operation, values): - """Run an insert, update, or delete. Return number of rows affected""" +def _dml(operation, values, log=True): + """Run an insert, update, or delete. Return number of rows affected + If log is False, errors will not be logged. It makes sense only for + queries which are expected to fail (LOCK NOWAIT) + """ c = context.cnx.cursor() - c.execute(operation, values) + c.execute(operation, values, log=log) ret = c.rowcount logger.debug("Operation affected %s row(s)", ret) c.close() diff --git a/koji/db.py b/koji/db.py index 31043be..7b21eb7 100644 --- a/koji/db.py +++ b/koji/db.py @@ -132,7 +132,7 @@ class CursorWrapper: params[i] = tuple(item) return sql, params - def execute(self, operation, parameters=()): + def execute(self, operation, parameters=(), log=True): debug = self.logger.isEnabledFor(logging.DEBUG) operation, parameters = self.preformat(operation, parameters) if debug: @@ -141,7 +141,8 @@ class CursorWrapper: try: ret = self.cursor.execute(operation, parameters) except Exception: - self.logger.error('Query failed. Query was: %s', self.quote(operation, parameters)) + if log: + self.logger.error('Query failed. Query was: %s', self.quote(operation, parameters)) raise if debug: self.logger.debug("Execute operation completed in %.4f seconds", time.time() - start) diff --git a/plugins/hub/protonmsg.py b/plugins/hub/protonmsg.py index e415bf0..0975f66 100644 --- a/plugins/hub/protonmsg.py +++ b/plugins/hub/protonmsg.py @@ -356,7 +356,7 @@ def handle_db_msgs(urls, CONFIG): # we're running in postCommit, so we need to handle new transaction c.execute('BEGIN') try: - c.execute('LOCK TABLE proton_queue IN ACCESS EXCLUSIVE MODE NOWAIT') + c.execute('LOCK TABLE proton_queue IN ACCESS EXCLUSIVE MODE NOWAIT', log=False) except psycopg2.OperationalError: LOG.debug('skipping db queue due to lock') return From 0449aa482984461931b3c416603131204ff07a20 Mon Sep 17 00:00:00 2001 From: Tomas Kopecek Date: Feb 07 2022 09:01:21 +0000 Subject: [PATCH 2/3] fix tests --- diff --git a/tests/test_hub/test_insert_processor.py b/tests/test_hub/test_insert_processor.py index 3975052..19ea511 100644 --- a/tests/test_hub/test_insert_processor.py +++ b/tests/test_hub/test_insert_processor.py @@ -6,7 +6,6 @@ import kojihub class TestInsertProcessor(unittest.TestCase): - def test_basic_instantiation(self): proc = kojihub.InsertProcessor('sometable') actual = str(proc) @@ -27,8 +26,7 @@ class TestInsertProcessor(unittest.TestCase): proc.execute() cursor.execute.assert_called_once_with( 'INSERT INTO sometable (foo) VALUES (%(foo)s)', - {'foo': 'bar'}, - ) + {'foo': 'bar'}, log=True) @mock.patch('kojihub.context') def test_make_create(self, context): @@ -117,6 +115,7 @@ class TestBulkInsertProcessor(unittest.TestCase): cursor.execute.assert_called_once_with( 'INSERT INTO sometable (foo) VALUES (%(foo0)s)', {'foo0': 'bar'}, + log=True ) cursor.reset_mock() @@ -126,6 +125,7 @@ class TestBulkInsertProcessor(unittest.TestCase): cursor.execute.assert_called_once_with( 'INSERT INTO sometable (foo) VALUES (%(foo0)s)', {'foo0': 'bar'}, + log=True ) @mock.patch('kojihub.context') @@ -140,6 +140,7 @@ class TestBulkInsertProcessor(unittest.TestCase): cursor.execute.assert_called_once_with( 'INSERT INTO sometable (foo) VALUES (%(foo0)s), (%(foo1)s), (%(foo2)s)', {'foo0': 'bar1', 'foo1': 'bar2', 'foo2': 'bar3'}, + log=True ) def test_missing_values(self): @@ -177,24 +178,27 @@ class TestBulkInsertProcessor(unittest.TestCase): calls = cursor.execute.mock_calls # list of (name, positional args, keyword args) self.assertEqual(len(calls), 2) - self.assertEqual(calls[0][1], - ('INSERT INTO sometable (foo) VALUES (%(foo0)s), (%(foo1)s)', - {'foo0': 'bar1', 'foo1': 'bar2'})) - self.assertEqual(calls[1][1], - ('INSERT INTO sometable (foo) VALUES (%(foo0)s)', {'foo0': 'bar3'})) + self.assertEqual(calls[0], + mock.call('INSERT INTO sometable (foo) VALUES (%(foo0)s), (%(foo1)s)', + {'foo0': 'bar1', 'foo1': 'bar2'}, log=True)) + self.assertEqual(calls[1], + mock.call('INSERT INTO sometable (foo) VALUES (%(foo0)s)', + {'foo0': 'bar3'}, log=True)) @mock.patch('kojihub.context') def test_no_batch_execution(self, context): cursor = mock.MagicMock() context.cnx.cursor.return_value = cursor - proc = kojihub.BulkInsertProcessor('sometable', data=[{'foo': 'bar1'}], batch=None) + proc = kojihub.BulkInsertProcessor('sometable', data=[{'foo': 'bar1'}], batch=0) proc.add_record(foo='bar2') proc.add_record(foo='bar3') proc.execute() calls = cursor.execute.mock_calls # list of (name, positional args, keyword args) self.assertEqual(len(calls), 1) - self.assertEqual(calls[0][1], - ('INSERT INTO sometable (foo) VALUES (%(foo0)s), (%(foo1)s), (%(foo2)s)', - {'foo0': 'bar1', 'foo1': 'bar2', 'foo2': 'bar3'})) + self.assertEqual( + calls[0], + mock.call('INSERT INTO sometable (foo) VALUES (%(foo0)s), (%(foo1)s), (%(foo2)s)', + {'foo0': 'bar1', 'foo1': 'bar2', 'foo2': 'bar3'}, log=True) + ) diff --git a/tests/test_hub/test_update_processor.py b/tests/test_hub/test_update_processor.py index 41f49ab..4d152a9 100644 --- a/tests/test_hub/test_update_processor.py +++ b/tests/test_hub/test_update_processor.py @@ -30,4 +30,5 @@ class TestUpdateProcessor(unittest.TestCase): cursor.execute.assert_called_once_with( 'UPDATE sometable SET foo = %(data.foo)s', {'data.foo': 'bar'}, + log=True, ) From 6aaa6b3248d52a738b7ba5a5c4e72644c8b3409b Mon Sep 17 00:00:00 2001 From: Tomas Kopecek Date: Feb 07 2022 09:07:26 +0000 Subject: [PATCH 3/3] rename option --- diff --git a/hub/kojihub.py b/hub/kojihub.py index d8128e6..26837c4 100644 --- a/hub/kojihub.py +++ b/hub/kojihub.py @@ -5421,13 +5421,13 @@ def _singleValue(query, values=None, strict=True): return None -def _dml(operation, values, log=True): +def _dml(operation, values, log_errors=True): """Run an insert, update, or delete. Return number of rows affected If log is False, errors will not be logged. It makes sense only for queries which are expected to fail (LOCK NOWAIT) """ c = context.cnx.cursor() - c.execute(operation, values, log=log) + c.execute(operation, values, log_errors=log_errors) ret = c.rowcount logger.debug("Operation affected %s row(s)", ret) c.close() diff --git a/koji/db.py b/koji/db.py index 7b21eb7..1391b22 100644 --- a/koji/db.py +++ b/koji/db.py @@ -132,7 +132,7 @@ class CursorWrapper: params[i] = tuple(item) return sql, params - def execute(self, operation, parameters=(), log=True): + def execute(self, operation, parameters=(), log_errors=True): debug = self.logger.isEnabledFor(logging.DEBUG) operation, parameters = self.preformat(operation, parameters) if debug: @@ -141,7 +141,7 @@ class CursorWrapper: try: ret = self.cursor.execute(operation, parameters) except Exception: - if log: + if log_errors: self.logger.error('Query failed. Query was: %s', self.quote(operation, parameters)) raise if debug: diff --git a/plugins/hub/protonmsg.py b/plugins/hub/protonmsg.py index 0975f66..702028e 100644 --- a/plugins/hub/protonmsg.py +++ b/plugins/hub/protonmsg.py @@ -356,7 +356,7 @@ def handle_db_msgs(urls, CONFIG): # we're running in postCommit, so we need to handle new transaction c.execute('BEGIN') try: - c.execute('LOCK TABLE proton_queue IN ACCESS EXCLUSIVE MODE NOWAIT', log=False) + c.execute('LOCK TABLE proton_queue IN ACCESS EXCLUSIVE MODE NOWAIT', log_errors=False) except psycopg2.OperationalError: LOG.debug('skipping db queue due to lock') return diff --git a/tests/test_hub/test_insert_processor.py b/tests/test_hub/test_insert_processor.py index 19ea511..c5745d5 100644 --- a/tests/test_hub/test_insert_processor.py +++ b/tests/test_hub/test_insert_processor.py @@ -26,7 +26,7 @@ class TestInsertProcessor(unittest.TestCase): proc.execute() cursor.execute.assert_called_once_with( 'INSERT INTO sometable (foo) VALUES (%(foo)s)', - {'foo': 'bar'}, log=True) + {'foo': 'bar'}, log_errors=True) @mock.patch('kojihub.context') def test_make_create(self, context): @@ -115,7 +115,7 @@ class TestBulkInsertProcessor(unittest.TestCase): cursor.execute.assert_called_once_with( 'INSERT INTO sometable (foo) VALUES (%(foo0)s)', {'foo0': 'bar'}, - log=True + log_errors=True ) cursor.reset_mock() @@ -125,7 +125,7 @@ class TestBulkInsertProcessor(unittest.TestCase): cursor.execute.assert_called_once_with( 'INSERT INTO sometable (foo) VALUES (%(foo0)s)', {'foo0': 'bar'}, - log=True + log_errors=True ) @mock.patch('kojihub.context') @@ -140,7 +140,7 @@ class TestBulkInsertProcessor(unittest.TestCase): cursor.execute.assert_called_once_with( 'INSERT INTO sometable (foo) VALUES (%(foo0)s), (%(foo1)s), (%(foo2)s)', {'foo0': 'bar1', 'foo1': 'bar2', 'foo2': 'bar3'}, - log=True + log_errors=True ) def test_missing_values(self): @@ -180,10 +180,10 @@ class TestBulkInsertProcessor(unittest.TestCase): self.assertEqual(len(calls), 2) self.assertEqual(calls[0], mock.call('INSERT INTO sometable (foo) VALUES (%(foo0)s), (%(foo1)s)', - {'foo0': 'bar1', 'foo1': 'bar2'}, log=True)) + {'foo0': 'bar1', 'foo1': 'bar2'}, log_errors=True)) self.assertEqual(calls[1], mock.call('INSERT INTO sometable (foo) VALUES (%(foo0)s)', - {'foo0': 'bar3'}, log=True)) + {'foo0': 'bar3'}, log_errors=True)) @mock.patch('kojihub.context') def test_no_batch_execution(self, context): @@ -200,5 +200,5 @@ class TestBulkInsertProcessor(unittest.TestCase): self.assertEqual( calls[0], mock.call('INSERT INTO sometable (foo) VALUES (%(foo0)s), (%(foo1)s), (%(foo2)s)', - {'foo0': 'bar1', 'foo1': 'bar2', 'foo2': 'bar3'}, log=True) + {'foo0': 'bar1', 'foo1': 'bar2', 'foo2': 'bar3'}, log_errors=True) ) diff --git a/tests/test_hub/test_update_processor.py b/tests/test_hub/test_update_processor.py index 4d152a9..1a31bc2 100644 --- a/tests/test_hub/test_update_processor.py +++ b/tests/test_hub/test_update_processor.py @@ -30,5 +30,5 @@ class TestUpdateProcessor(unittest.TestCase): cursor.execute.assert_called_once_with( 'UPDATE sometable SET foo = %(data.foo)s', {'data.foo': 'bar'}, - log=True, + log_errors=True, )