Merge lp:~mandel/ubuntuone-client/improve-fs-notifications-logging into lp:ubuntuone-client

[Manuel de la Peña]

Fixes: lp:872254

* Improves the logging used in the fs events on Windows.
* Adds a logging assertion in the tests to ensure that things are done correctly.

Fixes: lp:872254

* Improves the logging used in the fs events on Windows.
* Adds a logging assertion in the tests to ensure that things are done correctly.

[Diego Sarmentero (diegosarmentero)]

+1

review: Approve

[Natalia Bidart (nataliabidart)]

* The following code is not needed since the memento handler accepts multiple strings in one single call:

119 + def _assert_logs(self, events):
120 + """Assert the debug logs."""
121 + logs = self._get_fs_logs(events)
122 + for msg in logs:
123 + self.assertTrue(self.memento.check_debug(msg))

you just have to do:

        self.assertTrue(self.memento.check_debug(*self._get_fs_logs(events)))

* I also think that all the new helper functions could be improve using list comprehensions, for example:

86 + def _get_event_msgs(self, events):
87 + """Return the pushing event logs."""
88 + logs = []
89 + for e in events:
90 + logs.append('Pushing event %s to processor.' % e)
91 + return logs

can be better read as:

86 + def _get_event_msgs(self, events):
87 + """Return the pushing event logs."""
88 + msg = 'Pushing event %s to processor.'
89 + return [msg % e for e in events]

Anyways, if we use the former to create generators instead of lists in memory, we can improve all the helpers having only one like this:

def _assert_logs(self, events):
    logs = []

    msg = 'Pushing event %r to processor.'
    logs.extend(msg % e for e in events)

    msg = 'Got from ReadDirectoryChangesW %r.'
    logs.extend(msg % [(WINDOWS_ACTIONS_NAMES[a], p) for a, p in actions]
            for actions in self.raw_events)

    msg = 'Is path %r a dir? %r'
    logs.extend(is_dir % data for data in self.paths_checked)

    self.assertTrue(self.memento.check_debug(*logs))

* Also, always user %r to log variables, not %s, since the latter can fail for non-ascii strings.

* For every addHanlder, you need to queue a removeHandler cleanup function.

* The rest looks good!

review: Needs Fixing

[lp:~mandel/ubuntuone-client/improve-fs-notifications-logging]

1152. By Manuel de la Peña on 2011-10-13

Done hte follwing:
* use %r for logging.
* simplify the use of helper functions to list comprehentions.

[Manuel de la Peña (mandel)]

> * The following code is not needed since the memento handler accepts multiple
> strings in one single call:
>
> 119 + def _assert_logs(self, events):
> 120 + """Assert the debug logs."""
> 121 + logs = self._get_fs_logs(events)
> 122 + for msg in logs:
> 123 + self.assertTrue(self.memento.check_debug(msg))
>
> you just have to do:
>
> self.assertTrue(self.memento.check_debug(*self._get_fs_logs(events)))
>
> * I also think that all the new helper functions could be improve using list
> comprehensions, for example:
>
> 86 + def _get_event_msgs(self, events):
> 87 + """Return the pushing event logs."""
> 88 + logs = []
> 89 + for e in events:
> 90 + logs.append('Pushing event %s to processor.' % e)
> 91 + return logs
>
> can be better read as:
>
> 86 + def _get_event_msgs(self, events):
> 87 + """Return the pushing event logs."""
> 88 + msg = 'Pushing event %s to processor.'
> 89 + return [msg % e for e in events]
>
> Anyways, if we use the former to create generators instead of lists in memory,
> we can improve all the helpers having only one like this:
>
> def _assert_logs(self, events):
> logs = []
>
> msg = 'Pushing event %r to processor.'
> logs.extend(msg % e for e in events)
>
> msg = 'Got from ReadDirectoryChangesW %r.'
> logs.extend(msg % [(WINDOWS_ACTIONS_NAMES[a], p) for a, p in actions]
> for actions in self.raw_events)
>
> msg = 'Is path %r a dir? %r'
> logs.extend(is_dir % data for data in self.paths_checked)
>
> self.assertTrue(self.memento.check_debug(*logs))
>
> * Also, always user %r to log variables, not %s, since the latter can fail for
> non-ascii strings.
>
> * For every addHanlder, you need to queue a removeHandler cleanup function.
>
> * The rest looks good!

All comments make sense and therefore I have removed all the helper functions, the only issue I found with the comments it he one regarding 'self.assertTrue(self.memento.check_debug(*logs))'. From a conversation in #chicharra with facu:

facundobatista> mandel, pong
 <mandel> facundobatista, can you give me a hand with the memento handler?
 <mandel> facundobatista, there is something I quite not get
 <facundobatista> mandel, yes
 <mandel> facundobatista, what does check_debug do when I pass a collection of expected logs messages?
 <facundobatista> mandel, it checks that *all* those messages are included in a single log line with debug level
 <mandel> facundobatista, ok, is there a method to check that all those logs messages have been added, but not in a single line?
 <mandel> or should I loop though them and do a check_dbug per message?
 <facundobatista> mandel, there's no method... the idea behind those multiple messages, is that you care to "some stuff being logged" (like the word "Starting", and the share id, etc), but you don't care the exact log wording
 <facundobatista> mandel, give me one example of what you're wanting
 <mandel> facundobatista, let me past the example
 <mandel> facundobatista, here: http://paste.ubuntu.com/707372/
 <mandel> facundobatista, I want to ensure that what I passed is indeed present ...

[Natalia Bidart (nataliabidart)]

This code will not be executed if something fails before it runs:

        # clean logger
        manager._wdm[0].log.removeHandler(self.memento)

should be:

        # clean logger
        self.addCleanup(manager._wdm[0].log.removeHandler, self.memento)

(you need to move it up right after the log adding)

* While you're at it, can you please change this call:

        # clean behind us by removing the file
        os.remove(file_name)

to be

        # clean behind us by removing the file
        self.addCleanup(os.remove, file_name)

(you need to move it up right after the file creation)

* The proper styling for this:

# a map of the actions to names so that we have better logs.
WINDOWS_ACTIONS_NAMES = {
  1: 'IN_CREATE',
  2: 'IN_DELETE',
  3: 'IN_MODIFY',
  4: 'IN_MOVED_FROM',
  5: 'IN_MOVED_TO'}

should be:

# a map of the actions to names so that we have better logs.
WINDOWS_ACTIONS_NAMES = {
    1: 'IN_CREATE',
    2: 'IN_DELETE',
    3: 'IN_MODIFY',
    4: 'IN_MOVED_FROM',
    5: 'IN_MOVED_TO',
}

You have my +1 with those changes!

review: Needs Fixing

[lp:~mandel/ubuntuone-client/improve-fs-notifications-logging]

1153. By Manuel de la Peña on 2011-10-17

Made changes according to code review.

1154. By Manuel de la Peña on 2011-10-17

Move the cleanup as close as possible to the file creation.

[Natalia Bidart (nataliabidart)]

The adding of:

        # clean logger
        self.addCleanup(manager._wdm[0].log.removeHandler, self.memento)

needs to be done right after the addHandler, since if the actions() calls fails, the logger is not removed.

The rest looks good!

review: Approve

[Manuel de la Peña (mandel)]

> The adding of:
>
> # clean logger
> self.addCleanup(manager._wdm[0].log.removeHandler, self.memento)
>
> needs to be done right after the addHandler, since if the actions() calls
> fails, the logger is not removed.
>

True, and sorted out!!

> The rest looks good!

[lp:~mandel/ubuntuone-client/improve-fs-notifications-logging]

1155. By Manuel de la Peña on 2011-10-18

Add the clean up just after the things that we need to clean.

=== modified file 'tests/platform/windows/test_filesystem_notifications.py'
--- tests/platform/windows/test_filesystem_notifications.py	2011-10-07 13:53:28 +0000
+++ tests/platform/windows/test_filesystem_notifications.py	2011-10-18 13:36:35 +0000
@@ -17,6 +17,7 @@
 # with this program.  If not, see <http://www.gnu.org/licenses/>.
 """Test the filesystem notifications on windows."""
 
+import logging
 import os
 import tempfile
 import thread
@@ -24,8 +25,10 @@
 import itertools
 
 from twisted.internet import defer
+from win32file import FILE_NOTIFY_INFORMATION
 
 from contrib.testing.testcase import BaseTwistedTestCase
+from ubuntuone.devtools.handlers import MementoHandler
 from ubuntuone.platform.windows import os_helper
 from ubuntuone.platform.windows.pyinotify import (
     ProcessEvent,
@@ -47,6 +50,7 @@
     FILE_NOTIFY_CHANGE_LAST_WRITE,
     FILE_NOTIFY_CHANGE_SECURITY,
     FILE_NOTIFY_CHANGE_LAST_ACCESS,
+    WINDOWS_ACTIONS_NAMES,
 )
 
 #create a rever mapping to use it in the tests.
@@ -114,6 +118,34 @@
             FILE_NOTIFY_CHANGE_LAST_WRITE | \
             FILE_NOTIFY_CHANGE_SECURITY | \
             FILE_NOTIFY_CHANGE_LAST_ACCESS
+        self.memento = MementoHandler()
+        self.memento.setLevel(logging.DEBUG)
+        self.raw_events = []
+        self.paths_checked = []
+        old_is_dir = Watch._path_is_dir
+
+        def file_notify_information_wrapper(buf, data):
+            """Wrapper that gets the events and adds them to the list."""
+            events = FILE_NOTIFY_INFORMATION(buf, data)
+            # we want to append the list because that is what will be logged.
+            # If we use extend we wont have the same logging because it will
+            # group all events in a single lists which is not what the COM API
+            # does.
+            str_events = [(WINDOWS_ACTIONS_NAMES[action], path) for action, path in
+                          events]
+            self.raw_events.append(str_events)
+            return events
+
+        def path_is_dir_wrapper(watch, path):
+            """Wrapper that gets the checked paths."""
+            result = old_is_dir(watch, path)
+            self.paths_checked.append((path, result))
+            return result
+
+        self.patch(filesystem_notifications, 'FILE_NOTIFY_INFORMATION',
+                   file_notify_information_wrapper)
+        self.patch(filesystem_notifications.Watch, '_path_is_dir',
+                   path_is_dir_wrapper)
 
     @defer.inlineCallbacks
     def _perform_operations(self, path, mask, auto_add, actions,
@@ -123,6 +155,10 @@
         manager = WatchManager(handler)
         yield manager.add_watch(os_helper.get_windows_valid_path(path), mask,
                           auto_add=auto_add)
+        # change the logger so that we can check the logs if we wanted
+        manager._wdm[0].log.addHandler(self.memento)
+        # clean logger later
+        self.addCleanup(manager._wdm[0].log.removeHandler, self.memento)
         # execution the actions
         actions()
         # process the recorded events
@@ -136,6 +172,10 @@
         manager = WatchManager()
         manager.add_watch(os_helper.get_windows_valid_path(path), mask,
                           auto_add=auto_add)
+        # change the logger so that we can check the logs if we wanted
+        manager._wdm[0].log.addHandler(self.memento)
+        # clean logger later
+        self.addCleanup(manager._wdm[0].log.removeHandler, self.memento)
         # execution the actions
         actions()
         # process the recorded events
@@ -143,6 +183,18 @@
         events = self.handler.processed_events
         return events
 
+    def _assert_logs(self, events):
+        """Assert the debug logs."""
+        logs = []
+        msg = 'Is path %r a dir? %s'
+        logs.extend([msg % data for data in self.paths_checked])
+        msg = 'Got from ReadDirectoryChangesW %r.'
+        logs.extend([msg % actions for actions in self.raw_events])
+        msg = 'Pushing event %r to processor.'
+        logs.extend([msg % e for e in events])
+        for msg in logs:
+            self.assertTrue(self.memento.check_debug(msg))
+
     @defer.inlineCallbacks
     def test_file_create(self):
         """Test that the correct event is returned on a file create."""
@@ -166,6 +218,8 @@
         self.assertEqual('.', event.path)
         self.assertEqual(os.path.join(self.basedir, file_name), event.pathname)
         self.assertEqual(0, event.wd)
+        # assert the logging
+        self._assert_logs(events)
 
     @defer.inlineCallbacks
     def test_dir_create(self):
@@ -186,6 +240,8 @@
         self.assertEqual('.', event.path)
         self.assertEqual(os.path.join(self.basedir, dir_name), event.pathname)
         self.assertEqual(0, event.wd)
+        # assert the logging
+        self._assert_logs(events)
 
     @defer.inlineCallbacks
     def test_file_remove(self):
@@ -208,6 +264,8 @@
         self.assertEqual('.', event.path)
         self.assertEqual(os.path.join(self.basedir, file_name), event.pathname)
         self.assertEqual(0, event.wd)
+        # assert the logging
+        self._assert_logs(events)
 
     @defer.inlineCallbacks
     def test_dir_remove(self):
@@ -229,6 +287,8 @@
         self.assertEqual('.', event.path)
         self.assertEqual(os.path.join(self.basedir, dir_name), event.pathname)
         self.assertEqual(0, event.wd)
+        # assert the logging
+        self._assert_logs(events)
 
     @defer.inlineCallbacks
     def test_file_write(self):
@@ -236,6 +296,8 @@
         file_name = os.path.join(self.basedir, 'test_file_write')
         # create the file before recording
         fd = open(file_name, 'w')
+        # clean behind us by removing the file
+        self.addCleanup(os.remove, file_name)
 
         def write_file():
             """Action for the test."""
@@ -252,8 +314,8 @@
         self.assertEqual('.', event.path)
         self.assertEqual(os.path.join(self.basedir, file_name), event.pathname)
         self.assertEqual(0, event.wd)
-        # clean behind us by removeing the file
-        os.remove(file_name)
+        # assert the logging
+        self._assert_logs(events)
 
     @defer.inlineCallbacks
     def test_file_moved_to_watched_dir_same_watcher(self):
@@ -296,6 +358,8 @@
         self.assertEqual(0, move_to_event.wd)
         # assert that both cookies are the same
         self.assertEqual(move_from_event.cookie, move_to_event.cookie)
+        # assert the logging
+        self._assert_logs(events)
 
     @defer.inlineCallbacks
     def test_file_moved_to_not_watched_dir(self):
@@ -323,6 +387,8 @@
         self.assertEqual(os.path.join(self.basedir, from_file_name),
                          event.pathname)
         self.assertEqual(0, event.wd)
+        # assert the logging
+        self._assert_logs(events)
 
     @defer.inlineCallbacks
     def test_file_move_from_not_watched_dir(self):
@@ -351,6 +417,8 @@
         self.assertEqual(os.path.join(self.basedir, to_file_name),
             event.pathname)
         self.assertEqual(0, event.wd)
+        # assert the logging
+        self._assert_logs(events)
 
     @defer.inlineCallbacks
     def test_dir_moved_to_watched_dir_same_watcher(self):
@@ -391,6 +459,8 @@
         self.assertEqual(0, move_to_event.wd)
         # assert that both cookies are the same
         self.assertEqual(move_from_event.cookie, move_to_event.cookie)
+        # assert the logging
+        self._assert_logs(events)
 
     @defer.inlineCallbacks
     def test_dir_moved_to_not_watched_dir(self):
@@ -414,6 +484,8 @@
         self.assertEqual('.', event.path)
         self.assertEqual(os.path.join(self.basedir, dir_name), event.pathname)
         self.assertEqual(0, event.wd)
+        # assert the logging
+        self._assert_logs(events)
 
     @defer.inlineCallbacks
     def test_dir_move_from_not_watched_dir(self):

=== modified file 'ubuntuone/platform/windows/filesystem_notifications.py'
--- ubuntuone/platform/windows/filesystem_notifications.py	2011-10-14 20:02:23 +0000
+++ ubuntuone/platform/windows/filesystem_notifications.py	2011-10-18 13:36:35 +0000
@@ -90,7 +90,17 @@
   2: IN_DELETE,
   3: IN_MODIFY,
   4: IN_MOVED_FROM,
-  5: IN_MOVED_TO}
+  5: IN_MOVED_TO,
+}
+
+# a map of the actions to names so that we have better logs.
+WINDOWS_ACTIONS_NAMES = {
+  1: 'IN_CREATE',
+  2: 'IN_DELETE',
+  3: 'IN_MODIFY',
+  4: 'IN_MOVED_FROM',
+  5: 'IN_MOVED_TO',
+}
 
 # translates quickly the event and it's is_dir state to our standard events
 NAME_TRANSLATIONS = {
@@ -188,7 +198,7 @@
         else:
             # path does not exists, was it in the internal list?
             is_dir = path in self._subdirs
-        self.log.debug('is path %r a dir? %s', path, is_dir)
+        self.log.debug('Is path %r a dir? %s', path, is_dir)
         return is_dir
 
     def _process_events(self, events):
@@ -239,7 +249,7 @@
             # add the event only if we do not have an exclude filter or
             # the exclude filter returns False, that is, the event will not
             # be excluded
-            self.log.debug('Event is %s.', event)
+            self.log.debug('Pushing event %r to processor.', event)
             self._processor(event)
 
     def _call_deferred(self, f, *args):
@@ -310,7 +320,9 @@
             data = GetOverlappedResult(handle, self._overlapped, True)
             # lets ead the data and store it in the results
             events = FILE_NOTIFY_INFORMATION(buf, data)
-            self.log.debug('Events from ReadDirectoryChangesW are %s', events)
+            self.log.debug('Got from ReadDirectoryChangesW %r.',
+                    [(WINDOWS_ACTIONS_NAMES[action], path) for action, path in
+                        events])
             reactor.callFromThread(self._process_events, events)
 
     @is_valid_windows_path(path_indexes=[1])