Merge lp:~nataliabidart/ubuntuone-client/better-info-logs-stable-1-2 into lp:ubuntuone-client/stable-1-2

[Natalia Bidart]

Improving logging when performing delete actions.

Improving logging when performing delete actions.

[Tim Cole (tcole)]

review: Approve

[Rick McBride (rmcbride)]

review: Approve

=== modified file 'tests/syncdaemon/test_eq_inotify.py'
--- tests/syncdaemon/test_eq_inotify.py	2010-03-26 15:58:49 +0000
+++ tests/syncdaemon/test_eq_inotify.py	2010-05-11 20:54:28 +0000
@@ -221,6 +221,12 @@
     def setUp(self):
         """Setup the test."""
         BaseEQTestCase.setUp(self)
+
+        # add a Memento handler to the logger
+        self.handler = testcase.MementoHandler()
+        self.handler.setLevel(logging.INFO)
+        self.eq.log.addHandler(self.handler)
+
         # create the deferred for the tests
         self._deferred = defer.Deferred()
 
@@ -366,8 +372,17 @@
             def handle_FS_FILE_DELETE(innerself, path):
                 if path != testfile:
                     self.finished_error("received a wrong path")
-                else:
-                    self.finished_ok()
+                    return
+
+                check = len(self.handler.records) == 1 and \
+                        'FS_FILE_DELETE' in self.handler.records[0].message and\
+                        testfile in self.handler.records[0].message and \
+                        self.handler.records[0].levelno == logging.INFO
+                if not check:
+                    self.finished_error("FS_FILE_DELETE must appear in INFO.")
+                    return
+
+                self.finished_ok()
 
         self.eq.inotify_add_watch(self.root_dir)
         self.eq.subscribe(HitMe())
@@ -387,8 +402,17 @@
             def handle_FS_DIR_DELETE(innerself, path):
                 if path != testdir:
                     self.finished_error("received a wrong path")
-                else:
-                    self.finished_ok()
+                    return
+
+                check = len(self.handler.records) == 1 and \
+                        'FS_DIR_DELETE' in self.handler.records[0].message and\
+                        testdir in self.handler.records[0].message and \
+                        self.handler.records[0].levelno == logging.INFO
+                if not check:
+                    self.finished_error("FS_DIR_DELETE must appear in INFO.")
+                    return
+
+                self.finished_ok()
 
         self.eq.inotify_add_watch(self.root_dir)
         self.eq.subscribe(HitMe())
 
=== modified file 'tests/syncdaemon/test_sync.py'
--- tests/syncdaemon/test_sync.py	2010-04-23 15:23:09 +0000
+++ tests/syncdaemon/test_sync.py	2010-05-11 20:54:28 +0000
@@ -33,8 +33,10 @@
     MementoHandler, DummyClass
 )
 
+from contrib.testing import testcase
 from ubuntuone.syncdaemon.dbus_interface import DBusInterface
 from ubuntuone.syncdaemon.filesystem_manager import FileSystemManager
+from ubuntuone.syncdaemon.fsm import fsm as fsm_module
 from ubuntuone.syncdaemon.main import Main
 from ubuntuone.syncdaemon.sync import FSKey, Sync, SyncStateMachineRunner
 from ubuntuone.syncdaemon.volume_manager import Share
@@ -303,3 +305,53 @@
 
         self.ssmr.delete_file(event='AQ_DOWNLOAD_ERROR', params=None,
                               server_hash='')
+
+class FakedState(object):
+    """A faked state."""
+
+    def __init__(self, action_func):
+        self.action_func = action_func
+        self.values = []
+
+    def get_transition(self, event_name, parameters):
+        """A fake get_transition."""
+        class A(object): pass
+        result = A()
+        result.action_func = self.action_func
+        result.target = self.values
+        return result
+
+
+class StateMachineRunnerTestCase(BaseTwistedTestCase):
+    """Test suite for StateMachineRunner."""
+
+    def setUp(self):
+        """Init."""
+        BaseTwistedTestCase.setUp(self)
+
+        logger = logging.getLogger('ubuntuone.SyncDaemon.sync')
+        self.smr = fsm_module.StateMachineRunner(None, logger)
+        self.handler = testcase.MementoHandler()
+        self.handler.setLevel(logging.INFO)
+        logger.addHandler(self.handler)
+
+    def test_on_event_logs_info(self):
+        """Test proper logging in on_event."""
+        event_name = 'TEST_EVENT'
+        parameters = object()
+        action_func = 'SOME_ACTION_FUNC'
+        setattr(self.smr, action_func, lambda *_: None)
+        self.patch(self.smr, 'get_state', lambda: FakedState(action_func))
+        self.smr.on_event(event_name=event_name, parameters=parameters)
+
+        # assert over logging
+        self.assertTrue(len(self.handler.records), 1)
+
+        record = self.handler.records[0]
+        self.assertEqual(record.levelno, logging.INFO)
+
+        msg = record.message
+        error = '%s must be in record.message (%s)'
+        self.assertTrue(event_name in msg, error % (event_name, msg))
+        self.assertTrue(str(parameters) in msg, error % (parameters, msg))
+        self.assertTrue(action_func in msg, error % (action_func, msg))
 
=== modified file 'ubuntuone/syncdaemon/event_queue.py'
--- ubuntuone/syncdaemon/event_queue.py	2010-04-12 17:58:20 +0000
+++ ubuntuone/syncdaemon/event_queue.py	2010-05-11 20:54:28 +0000
@@ -577,7 +577,7 @@
         return False
 
     def handle_dir_delete(self, fullpath):
-        """ handle the case of move a dir to a non-watched directory """
+        """Handle the case of move a dir to a non-watched directory."""
         paths = self.eq.fs.get_paths_starting_with(fullpath,
                                                    include_base=False)
         paths.sort(reverse=True)
@@ -739,8 +739,13 @@
         The signature for each event is forced on each method, not in this
         'push' arguments.
         """
-        self.log.debug("push_event: %s, args:%s, kw:%s",
-                     event_name, args, kwargs)
+        log_msg = "push_event: %s, args:%s, kw:%s"
+        if event_name.endswith('DELETE'):
+            # log every DELETE in INFO level
+            self.log.info(log_msg, event_name, args, kwargs)
+        else:
+            self.log.debug(log_msg, event_name, args, kwargs)
+
         # get the event parameters
         try:
             event_params = EVENTS[event_name]
 
=== modified file 'ubuntuone/syncdaemon/fsm/fsm.py'
--- ubuntuone/syncdaemon/fsm/fsm.py	2010-01-22 17:25:09 +0000
+++ ubuntuone/syncdaemon/fsm/fsm.py	2010-05-11 20:54:28 +0000
@@ -131,7 +131,8 @@
             self.log.debug("passing")
         else:
             # pylint: disable-msg=W0703
-            self.log.debug("Calling %s"%action_func_name)
+            self.log.info("Calling %s (got %s:%s)",
+                          action_func_name, event_name, parameters)
             try:
                 af(event_name, parameters, *args)
             except Exception, e:
@@ -158,7 +159,7 @@
                 enter_state.values, event_name, parameters,
                 out_state.values, transition.target))
             raise ValueError("Incorrect out state")
-        self.log.debug("Called %s"%action_func_name)
+        self.log.debug("Called %s", action_func_name)
         return action_func_name
 
     def get_state(self):
@@ -193,8 +194,7 @@
                 # fsm_parser depends on python-uno for reading ods documents
                 # this shouldnt be called with an .ods file on production
                 # environments
-                from ubuntuone.syncdaemon.fsm import \
-                    fsm_parser
+                from ubuntuone.syncdaemon.fsm import fsm_parser
                 spec = fsm_parser.parse(input_data)
             elif input_data.endswith(".py"):
                 result = {}