[autotest] Clarify MySQL OperationalError message

The previous message was very misleading, being blamed even when the
error was expected and successfully retried.

BUG=chromium:666070
TEST=Run unit tests

Change-Id: Iba36400abb9a0de1aa37ab596af44329ff5a5967
Reviewed-on: https://chromium-review.googlesource.com/414614
Commit-Ready: Allen Li <ayatane@chromium.org>
Tested-by: Allen Li <ayatane@chromium.org>
Reviewed-by: Dan Shi <dshi@google.com>
diff --git a/tko/db.py b/tko/db.py
index 450c40a..9da76e7 100644
--- a/tko/db.py
+++ b/tko/db.py
@@ -17,6 +17,24 @@
 from autotest_lib.tko import utils
 
 
+def _log_error(msg):
+    """Log an error message.
+
+    @param msg: Message string
+    """
+    print >> sys.stderr, msg
+    sys.stderr.flush()  # we want these msgs to show up immediately
+
+
+def _format_operational_error(e):
+    """Format OperationalError.
+
+    @param e: OperationalError instance.
+    """
+    return ("%s: An operational error occurred during a database "
+            "operation: %s" % (time.strftime("%X %x"), str(e)))
+
+
 class MySQLTooManyRows(Exception):
     """Too many records."""
     pass
@@ -151,7 +169,8 @@
             try:
                 result = function(*args, **dargs)
             except OperationalError, e:
-                self._log_operational_error(e)
+                _log_error("%s; retrying, don't panic yet"
+                           % _format_operational_error(e))
                 stop_time = time.time()
                 elapsed_time = stop_time - start_time
                 if elapsed_time > self.query_timeout:
@@ -162,19 +181,13 @@
                         self._init_db()
                         autotest_stats.Counter('tko_db_error').increment()
                     except OperationalError, e:
-                        self._log_operational_error(e)
+                        _log_error('%s; panic now'
+                                   % _format_operational_error(e))
             else:
                 success = True
         return result
 
 
-    def _log_operational_error(self, e):
-        msg = ("%s: An operational error occured during a database "
-               "operation: %s" % (time.strftime("%X %x"), str(e)))
-        print >> sys.stderr, msg
-        sys.stderr.flush() # we want these msgs to show up immediately
-
-
     def dprint(self, value):
         """Print out debug value.
 
diff --git a/tko/db_unittest.py b/tko/db_unittest.py
new file mode 100755
index 0000000..557f32e
--- /dev/null
+++ b/tko/db_unittest.py
@@ -0,0 +1,40 @@
+#!/usr/bin/python
+
+import sys
+import unittest
+
+from cStringIO import StringIO
+
+import common
+from autotest_lib.tko import db
+
+
+class LogErrorTestCase(unittest.TestCase):
+    """Tests for _log_error()."""
+
+    def setUp(self):
+        self._old_stderr = sys.stderr
+        sys.stderr = self.stderr = StringIO()
+
+
+    def tearDown(self):
+        sys.stderr = self._old_stderr
+
+
+    def test_log_error(self):
+        """Test _log_error()."""
+        db._log_error('error message')
+        self.assertEqual(self.stderr.getvalue(), 'error message\n')
+
+
+class FormatOperationalErrorTestCase(unittest.TestCase):
+    """Tests for _format_operational_error()."""
+
+    def test_format_operational_error(self):
+        """Test _format_operational_error()."""
+        got = db._format_operational_error(Exception())
+        self.assertIn('An operational error occurred', got)
+
+
+if __name__ == "__main__":
+    unittest.main()