Adjust logging levels and usage to follow standards

A few of our logging levels and messages should be
updated to better reflect the oslo logging standards
created at https://wiki.openstack.org/LoggingStandards
so update some of them to not report error when its really
warning level and not report warning when debug is better.

Change-Id: I8abdb1bcfa2893c6b97eda7e85ac779e456966b8

taskflow/jobs/backends/impl_zookeeper.py

@@ -224,19 +224,20 @@ class ZookeeperJobBoard(jobboard.JobBoard):
                                        details=job_data.get("details", {}))
                     self._known_jobs[path] = (job, _READY)
         except (ValueError, TypeError, KeyError):
-            LOG.exception("Incorrectly formatted job data found"
-                          " at path: %s", path)
+            LOG.warn("Incorrectly formatted job data found at path: %s",
+                     path, exc_info=True)
         except self._client.handler.timeout_exception:
-            LOG.warn("Connection timed out fetching job data"
-                     " from path: %s", path)
+            LOG.warn("Connection timed out fetching job data from path: %s",
+                     path, exc_info=True)
         except k_exceptions.SessionExpiredError:
-            LOG.warn("Session expired fetching job data from path: %s", path)
+            LOG.warn("Session expired fetching job data from path: %s", path,
+                     exc_info=True)
         except k_exceptions.NoNodeError:
-            LOG.warn("No job node found at path: %s, it must have"
-                     " disappeared or was removed", path)
+            LOG.debug("No job node found at path: %s, it must have"
+                      " disappeared or was removed", path)
         except k_exceptions.KazooException:
-            LOG.exception("Internal error fetching job data from"
-                          " path: %s", path)
+            LOG.warn("Internal error fetching job data from path: %s",
+                     path, exc_info=True)
 
     def _on_job_posting(self, children):
         LOG.debug("Got children %s under path %s", children, self.path)

taskflow/listeners/base.py

@@ -106,8 +106,8 @@ class ListenerBase(object):
             self.deregister()
         except Exception:
             # Don't let deregistering throw exceptions
-            LOG.exception("Failed deregistering listeners from engine %s",
-                          self._engine)
+            LOG.warn("Failed deregistering listeners from engine %s",
+                     self._engine, exc_info=True)
 
 
 @six.add_metaclass(abc.ABCMeta)

taskflow/listeners/timing.py

@@ -50,8 +50,8 @@ class TimingListener(base.ListenerBase):
             # Don't let storage failures throw exceptions in a listener method.
             self._engine.storage.update_task_metadata(task_name, meta_update)
         except excp.StorageError:
-            LOG.exception("Failure to store duration update %s for task %s",
-                          meta_update, task_name)
+            LOG.warn("Failure to store duration update %s for task %s",
+                     meta_update, task_name, exc_info=True)
 
     def _task_receiver(self, state, details):
         task_name = details['task_name']

taskflow/persistence/backends/impl_sqlalchemy.py

@@ -142,10 +142,10 @@ def _ping_listener(dbapi_conn, connection_rec, connection_proxy):
         dbapi_conn.cursor().execute('select 1')
     except dbapi_conn.OperationalError as ex:
         if _in_any(six.text_type(ex.args[0]), MY_SQL_GONE_WAY_AWAY_ERRORS):
-            LOG.warn('Got mysql server has gone away: %s', ex)
+            LOG.warn('Got mysql server has gone away', exc_info=True)
             raise sa_exc.DisconnectionError("Database server went away")
         elif _in_any(six.text_type(ex.args[0]), POSTGRES_GONE_WAY_AWAY_ERRORS):
-            LOG.warn('Got postgres server has gone away: %s', ex)
+            LOG.warn('Got postgres server has gone away', exc_info=True)
             raise sa_exc.DisconnectionError("Database server went away")
         else:
             raise

taskflow/task.py

@@ -95,8 +95,9 @@ class BaseTask(atom.Atom):
             try:
                 handler(self, event_data, *args, **kwargs)
             except Exception:
-                LOG.exception("Failed calling `%s` on event '%s'",
-                              reflection.get_callable_name(handler), event)
+                LOG.warn("Failed calling `%s` on event '%s'",
+                         reflection.get_callable_name(handler), event,
+                         exc_info=True)
 
     @contextlib.contextmanager
     def autobind(self, event_name, handler_func, **kwargs):
@@ -109,9 +110,9 @@ class BaseTask(atom.Atom):
                 self.bind(event_name, handler_func, **kwargs)
                 bound = True
             except ValueError:
-                LOG.exception("Failed binding functor `%s` as a receiver of"
-                              " event '%s' notifications emitted from task %s",
-                              handler_func, event_name, self)
+                LOG.warn("Failed binding functor `%s` as a receiver of"
+                         " event '%s' notifications emitted from task %s",
+                         handler_func, event_name, self, exc_info=True)
         try:
             yield self
         finally:

taskflow/tests/unit/test_task.py

@@ -225,27 +225,27 @@ class TaskTest(test.TestCase):
         self.assertEqual(result, [1.0, 1.0, 1.0])
         self.assertEqual(mocked_warn.call_count, 2)
 
-    @mock.patch.object(task.LOG, 'exception')
-    def test_update_progress_handler_failure(self, mocked_exception):
+    @mock.patch.object(task.LOG, 'warn')
+    def test_update_progress_handler_failure(self, mocked_warn):
         def progress_callback(*args, **kwargs):
             raise Exception('Woot!')
 
         task = ProgressTask()
         with task.autobind('update_progress', progress_callback):
             task.execute([0.5])
-        mocked_exception.assert_called_once_with(
+        mocked_warn.assert_called_once_with(
             mock.ANY, reflection.get_callable_name(progress_callback),
-            'update_progress')
+            'update_progress', exc_info=mock.ANY)
 
-    @mock.patch.object(task.LOG, 'exception')
-    def test_autobind_non_existent_event(self, mocked_exception):
+    @mock.patch.object(task.LOG, 'warn')
+    def test_autobind_non_existent_event(self, mocked_warn):
         event = 'test-event'
         handler = lambda: None
         task = MyTask()
         with task.autobind(event, handler):
             self.assertEqual(len(task._events_listeners), 0)
-            mocked_exception.assert_called_once_with(
-                mock.ANY, handler, event, task)
+            mocked_warn.assert_called_once_with(
+                mock.ANY, handler, event, task, exc_info=mock.ANY)
 
     def test_autobind_handler_is_none(self):
         task = MyTask()

taskflow/utils/lock_utils.py

@@ -331,7 +331,7 @@ class _InterProcessLock(object):
 
         if not os.path.exists(basedir):
             misc.ensure_tree(basedir)
-            LOG.info('Created lock path: %s', basedir)
+            LOG.debug('Created lock path: %s', basedir)
 
         self.lockfile = open(self.fname, 'w')
 

taskflow/utils/misc.py

@@ -395,8 +395,8 @@ class TransitionNotifier(object):
             try:
                 callback(state, *args, **kwargs)
             except Exception:
-                LOG.exception(("Failure calling callback %s to notify about"
-                               " state transition %s"), callback, state)
+                LOG.warn("Failure calling callback %s to notify about state"
+                         " transition %s", callback, state, exc_info=True)
 
     def register(self, state, callback, args=None, kwargs=None):
         assert six.callable(callback), "Callback must be callable"