Don't trace DB errors when we're retrying

This is a two-part change that is squashed for stable, as the original
commit to master introduced undesirable behaviour of logging an
unexpected exception before re-raising it.

---

Don't trace DB errors when we're retrying

If we know we're retrying on DB failures, let's be smarter and not trace
an exception at ERROR level while looping, since this clutters up the
logs and causes confusion when trying to track down failures.

DBDeadlock errors show up quite a bit in q-svc and n-api logs in gate
runs but when you check logstash for those, they are primarily in jobs
that are successful, so the trace is on the first try in the loop and
then we pass on the second try - but the trace itself is confusing while
debugging gate failures.

So let's just be smarter and log at debug level between retries, and if
we hit an unexpected exception, log that error (as before), and raise it
up to the caller.

Closes-Bug: #1523990

Change-Id: I15b4a9b5c7ec9bfede9ec9989de02c1da46eac81
(cherry picked from commit 838e314a21fef9ca6cf99140b2400e0d3b68b109)

*** This is the 2nd commit message:

Don't log non-db error in retry wrapper

838e314a21fef9ca6cf99140b2400e0d3b68b109 changed the retry wrapper
code to not log exception traces for expected errors, like when
retrying on a DBDeadlock. It did, however, log an unexpected exception
but was not checking the type, like in the case of a nova OverQuota
exception.

Since _is_exception_expected already logs at debug level an expected
DB error, like DBDeadlock, during a retry loop, we don't need to log
it again. And if the exception is unexpected, like OverQuota from nova,
then we shouldn't trace that exception in the retry loop before
reraising but instead just let the caller handle it.

Adds a unit test to make sure that nothing is logged in the unexpected
exception case during the retry loop.

Co-Authored-By: Sean Dague <sean@dague.net>

Change-Id: Ic3e45029378dc96ce01398d9b55f51e20ef08189
Closes-Bug: #1532880

2 files changed, 13 insertions, 1 deletions

diff --git a/oslo_db/api.py b/oslo_db/api.py
index ef840a4..a609487 100644
--- a/oslo_db/api.py
+++ b/oslo_db/api.py
@@ -163,7 +163,7 @@ class wrap_db_retry(object):
             # and not an error condition in case retries are
             # not exceeded
             if not isinstance(exc, exception.RetryRequest):
-                LOG.exception(_LE('DB error.'))
+                LOG.debug('DB error: %s', exc)
             return True
         return self.exception_checker(exc)
 
diff --git a/oslo_db/tests/test_api.py b/oslo_db/tests/test_api.py
index 56d5529..d3e9834 100644
--- a/oslo_db/tests/test_api.py
+++ b/oslo_db/tests/test_api.py
@@ -220,3 +220,15 @@ class DBRetryRequestCase(DBAPITestCase):
         dbapi.api_class_call1()
 
         self.assertFalse(mocked_wrap.called)
+
+    @mock.patch('oslo_db.api.LOG')
+    def test_retry_wrapper_non_db_error_not_logged(self, mock_log):
+        # Tests that if the retry wrapper hits a non-db error (raised from the
+        # wrapped function), then that exception is reraised but not logged.
+
+        @api.wrap_db_retry(max_retries=5, retry_on_deadlock=True)
+        def some_method():
+            raise AttributeError('test')
+
+        self.assertRaises(AttributeError, some_method)
+        self.assertFalse(mock_log.called)