Fix excessive logging from db.sqlalchemy.session

A message about the MySQL server mode was logged at the info level
every time a connection was checked out. This happens often, and
logging every time is unnecessary.

Here's an example of the message when using the default
configuration:

 MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,...

The fix is to send the message once per engine creation. Also,
this message is now logged the debug level since there's a warning
logged if the mode isn't a "safe" one already.

Closes-Bug: #1288443
Co-Authored-By: Ben Nemec <bnemec@redhat.com>

Change-Id: I13b24d04c28e69a8534aaa8d3a4463ca1d65570f

2 files changed, 170 insertions, 82 deletions

diff --git a/openstack/common/db/sqlalchemy/session.py b/openstack/common/db/sqlalchemy/session.py
index 802ea5f..98939b3 100644
--- a/openstack/common/db/sqlalchemy/session.py
+++ b/openstack/common/db/sqlalchemy/session.py
@@ -291,7 +291,7 @@ from sqlalchemy.pool import NullPool, StaticPool
 from sqlalchemy.sql.expression import literal_column
 
 from openstack.common.db import exception
-from openstack.common.gettextutils import _LE, _LW, _LI
+from openstack.common.gettextutils import _LE, _LW
 from openstack.common import timeutils
 
 
@@ -520,30 +520,54 @@ def _set_session_sql_mode(dbapi_con, connection_rec,
 
     Note: passing in '' (empty string) for sql_mode clears
     the SQL mode for the session, overriding a potentially set
-    server default. Passing in None (the default) makes this
-    a no-op, meaning if a server-side SQL mode is set, it still applies.
+    server default.
     """
+
     cursor = dbapi_con.cursor()
-    if sql_mode is not None:
-        cursor.execute("SET SESSION sql_mode = %s", [sql_mode])
+    cursor.execute("SET SESSION sql_mode = %s", [sql_mode])
+
+
+def _mysql_get_effective_sql_mode(engine):
+    """Returns the effective SQL mode for connections from the engine pool.
 
-    # Check against the real effective SQL mode. Even when unset by
+    Returns ``None`` if the mode isn't available, otherwise returns the mode.
+
+    """
+    # Get the real effective SQL mode. Even when unset by
     # our own config, the server may still be operating in a specific
-    # SQL mode as set by the server configuration
-    cursor.execute("SHOW VARIABLES LIKE 'sql_mode'")
-    row = cursor.fetchone()
+    # SQL mode as set by the server configuration.
+    # Also note that the checkout listener will be called on execute to
+    # set the mode if it's registered.
+    row = engine.execute("SHOW VARIABLES LIKE 'sql_mode'").fetchone()
     if row is None:
+        return
+    return row[1]
+
+
+def _mysql_check_effective_sql_mode(engine):
+    """Logs a message based on the effective SQL mode for MySQL connections."""
+    realmode = _mysql_get_effective_sql_mode(engine)
+
+    if realmode is None:
         LOG.warning(_LW('Unable to detect effective SQL mode'))
         return
-    realmode = row[1]
-    LOG.info(_LI('MySQL server mode set to %s') % realmode)
+
+    LOG.debug('MySQL server mode set to %s', realmode)
     # 'TRADITIONAL' mode enables several other modes, so
     # we need a substring match here
     if not ('TRADITIONAL' in realmode.upper() or
             'STRICT_ALL_TABLES' in realmode.upper()):
         LOG.warning(_LW("MySQL SQL mode is '%s', "
-                        "consider enabling TRADITIONAL or STRICT_ALL_TABLES")
-                    % realmode)
+                        "consider enabling TRADITIONAL or STRICT_ALL_TABLES"),
+                    realmode)
+
+
+def _mysql_set_mode_callback(engine, sql_mode):
+    if sql_mode is not None:
+        mode_callback = functools.partial(_set_session_sql_mode,
+                                          sql_mode=sql_mode)
+        sqlalchemy.event.listen(engine, 'checkout', mode_callback)
+    _mysql_check_effective_sql_mode(engine)
 
 
 def _is_db_connection_error(args):
@@ -619,9 +643,7 @@ def create_engine(sql_connection, sqlite_fk=False, mysql_sql_mode=None,
         sqlalchemy.event.listen(engine, 'checkout', ping_callback)
         if engine.name == 'mysql':
             if mysql_sql_mode:
-                mode_callback = functools.partial(_set_session_sql_mode,
-                                                  sql_mode=mysql_sql_mode)
-                sqlalchemy.event.listen(engine, 'checkout', mode_callback)
+                _mysql_set_mode_callback(engine, mysql_sql_mode)
     elif 'sqlite' in connection_dict.drivername:
         if not sqlite_synchronous:
             sqlalchemy.event.listen(engine, 'connect',
diff --git a/tests/unit/db/sqlalchemy/test_sqlalchemy.py b/tests/unit/db/sqlalchemy/test_sqlalchemy.py
index f7de80c..fbe8c69 100644
--- a/tests/unit/db/sqlalchemy/test_sqlalchemy.py
+++ b/tests/unit/db/sqlalchemy/test_sqlalchemy.py
@@ -17,6 +17,8 @@
 
 """Unit tests for SQLAlchemy specific code."""
 
+import logging
+
 import _mysql_exceptions
 import mock
 import sqlalchemy
@@ -32,7 +34,6 @@ from openstack.common.db.sqlalchemy import session
 from openstack.common.db.sqlalchemy import test_base
 from openstack.common import log
 from openstack.common import test
-from openstack.common.gettextutils import _LW, _LI
 from tests.unit import test_log
 
 
@@ -379,72 +380,137 @@ class EngineFacadeTestCase(test.BaseTestCase):
                                           expire_on_commit=True)
 
 
-class SetSQLModeTestCase(test_log.LogTestBase):
-    def setUp(self):
-        super(SetSQLModeTestCase, self).setUp()
-        self.dbapi_mock = mock.Mock()
-        self.cursor = mock.Mock()
-        self.dbapi_mock.cursor.return_value = self.cursor
-        # Add fake logger so we can verify log messages
-        self.logger = log.getLogger('openstack.common.db.sqlalchemy.session')
-        self._add_handler_with_cleanup(self.logger)
-
-    def _assert_calls(self, test_mode, recommended):
-        self.cursor.execute.assert_any_call("SET SESSION sql_mode = %s",
-                                            [test_mode])
-        self.cursor.execute.assert_called_with(
-            "SHOW VARIABLES LIKE 'sql_mode'")
-        self.assertIn(_LI('MySQL server mode set to %s') % test_mode,
+class MysqlSetCallbackTest(test_log.LogTestBase):
+
+    class FakeCursor(object):
+        def __init__(self, execs):
+            self._execs = execs
+
+        def execute(self, sql, arg):
+            self._execs.append(sql % arg)
+
+    class FakeDbapiCon(object):
+        def __init__(self, execs):
+            self._execs = execs
+
+        def cursor(self):
+            return MysqlSetCallbackTest.FakeCursor(self._execs)
+
+    class FakeResultSet(object):
+        def __init__(self, realmode):
+            self._realmode = realmode
+
+        def fetchone(self):
+            return ['ignored', self._realmode]
+
+    class FakeEngine(object):
+        def __init__(self, realmode=None):
+            self._cbs = {}
+            self._execs = []
+            self._realmode = realmode
+
+        def set_callback(self, name, cb):
+            self._cbs[name] = cb
+
+        def execute(self, sql):
+            cb = self._cbs.get('checkout', lambda *x, **y: None)
+            dbapi_con = MysqlSetCallbackTest.FakeDbapiCon(self._execs)
+            connection_rec = None  # Not used.
+            connection_proxy = None  # Not used.
+            cb(dbapi_con, connection_rec, connection_proxy)
+            self._execs.append(sql)
+            return MysqlSetCallbackTest.FakeResultSet(self._realmode)
+
+    def stub_listen(engine, name, cb):
+        engine.set_callback(name, cb)
+
+    @mock.patch.object(sqlalchemy.event, 'listen', side_effect=stub_listen)
+    def _call_set_callback(self, listen_mock, sql_mode=None, realmode=None):
+        engine = self.FakeEngine(realmode=realmode)
+
+        logger = log.getLogger('openstack.common.db.sqlalchemy.session')
+        self._set_log_level_with_cleanup(logger, logging.DEBUG)
+        self._add_handler_with_cleanup(logger)
+
+        session._mysql_set_mode_callback(engine, sql_mode=sql_mode)
+        return engine
+
+    def test_set_mode_traditional(self):
+        # If _mysql_set_mode_callback is called with an sql_mode, then the SQL
+        # mode is set on the connection.
+
+        engine = self._call_set_callback(sql_mode='TRADITIONAL')
+
+        exp_calls = [
+            "SET SESSION sql_mode = ['TRADITIONAL']",
+            "SHOW VARIABLES LIKE 'sql_mode'"
+        ]
+        self.assertEqual(exp_calls, engine._execs)
+
+    def test_set_mode_ansi(self):
+        # If _mysql_set_mode_callback is called with an sql_mode, then the SQL
+        # mode is set on the connection.
+
+        engine = self._call_set_callback(sql_mode='ANSI')
+
+        exp_calls = [
+            "SET SESSION sql_mode = ['ANSI']",
+            "SHOW VARIABLES LIKE 'sql_mode'"
+        ]
+        self.assertEqual(exp_calls, engine._execs)
+
+    def test_set_mode_no_mode(self):
+        # If _mysql_set_mode_callback is called with sql_mode=None, then
+        # the SQL mode is NOT set on the connection.
+
+        engine = self._call_set_callback()
+
+        exp_calls = [
+            "SHOW VARIABLES LIKE 'sql_mode'"
+        ]
+        self.assertEqual(exp_calls, engine._execs)
+
+    def test_fail_detect_mode(self):
+        # If "SHOW VARIABLES LIKE 'sql_mode'" results in no row, then
+        # we get a log indicating can't detect the mode.
+
+        self._call_set_callback()
+
+        self.assertIn('Unable to detect effective SQL mode',
                       self.stream.getvalue())
-        if not recommended:
-            self.assertIn(_LW("MySQL SQL mode is '%s', "
-                              "consider enabling TRADITIONAL or "
-                              "STRICT_ALL_TABLES")
-                          % test_mode,
-                          self.stream.getvalue())
-
-    def _set_cursor_retval(self, test_mode):
-        retval = mock.MagicMock()
-        retval.__getitem__.return_value = test_mode
-        self.cursor.fetchone.return_value = retval
-
-    def test_set_mode_not_recommended(self):
-        test_mode = 'foo'
-        self._set_cursor_retval(test_mode)
-        session._set_session_sql_mode(self.dbapi_mock, None, None,
-                                      sql_mode=test_mode)
-        self._assert_calls(test_mode, recommended=False)
-
-    def test_set_mode_none(self):
-        test_mode = None
-        self._set_cursor_retval('')
-        session._set_session_sql_mode(self.dbapi_mock, None, None,
-                                      sql_mode=test_mode)
-        self.cursor.execute.assert_called_with(
-            "SHOW VARIABLES LIKE 'sql_mode'")
-        self.assertIn(_LW("MySQL SQL mode is '', "
-                          "consider enabling TRADITIONAL or "
-                          "STRICT_ALL_TABLES"),
+
+    def test_logs_real_mode(self):
+        # If "SHOW VARIABLES LIKE 'sql_mode'" results in a value, then
+        # we get a log with the value.
+
+        self._call_set_callback(realmode='SOMETHING')
+
+        self.assertIn('MySQL server mode set to SOMETHING',
                       self.stream.getvalue())
 
-    def test_set_mode_traditional(self):
-        test_mode = 'traditional'
-        self._set_cursor_retval(test_mode)
-        session._set_session_sql_mode(self.dbapi_mock, None, None,
-                                      sql_mode=test_mode)
-        self._assert_calls(test_mode, True)
-
-    def test_set_mode_strict_all_tables(self):
-        test_mode = 'STRICT_ALL_TABLES'
-        self._set_cursor_retval(test_mode)
-        session._set_session_sql_mode(self.dbapi_mock, None, None,
-                                      sql_mode=test_mode)
-        self._assert_calls(test_mode, True)
-
-    def test_read_mode_fail(self):
-        test_mode = None
-        self.cursor.fetchone.return_value = None
-        session._set_session_sql_mode(self.dbapi_mock, None, None,
-                                      sql_mode=test_mode)
-        self.assertIn(_LW('Unable to detect effective SQL mode'),
+    def test_warning_when_not_traditional(self):
+        # If "SHOW VARIABLES LIKE 'sql_mode'" results in a value that doesn't
+        # include 'TRADITIONAL', then a warning is logged.
+
+        self._call_set_callback(realmode='NOT_TRADIT')
+
+        self.assertIn("consider enabling TRADITIONAL or STRICT_ALL_TABLES",
                       self.stream.getvalue())
+
+    def test_no_warning_when_traditional(self):
+        # If "SHOW VARIABLES LIKE 'sql_mode'" results in a value that includes
+        # 'TRADITIONAL', then no warning is logged.
+
+        self._call_set_callback(realmode='TRADITIONAL')
+
+        self.assertNotIn("consider enabling TRADITIONAL or STRICT_ALL_TABLES",
+                         self.stream.getvalue())
+
+    def test_no_warning_when_strict_all_tables(self):
+        # If "SHOW VARIABLES LIKE 'sql_mode'" results in a value that includes
+        # 'STRICT_ALL_TABLES', then no warning is logged.
+
+        self._call_set_callback(realmode='STRICT_ALL_TABLES')
+
+        self.assertNotIn("consider enabling TRADITIONAL or STRICT_ALL_TABLES",
+                         self.stream.getvalue())