Merge lp:~frankban/python-fixtures/fakelogger-getdetails into lp:~python-fixtures/python-fixtures/trunk

[Francesco Banconi]

Following Robert suggestion in his comment to bug 1001520, I've used the FakeLogger fixture to capture Memcached logs in tests generating warnings. This branch implements FakeLogger.getDetails, so that we can still retrieve logging info if one of those tests fails.
I was confused about what name to use for the detail, I ended up using the FakeLogger instance class name, but I am open to suggestions.

[Robert Collins (lifeless)]

Thanks for this patch.

There seem to be a lot of whitespace changes in the diff? Possibly
harmless, but confusing.

Rather than implementing getDetails, the normal mechanism is to call
self.addDetail with a detail that will return the appropriate content
when evaluated. This is cheaper than evaluating when getDetails is
called, and means you only need to test that an appropriate detail is
added, rather than that the getDetails method still Does The Right
Thing. The UTF8_TEXT helper is probably revelant here too, for
brevity.

Finally, on the naming of things, I'd describe the attachment - think
of it as an email attachment.

So, in summary - something like:

E.g.:

=== modified file 'lib/fixtures/_fixtures/logger.py'
--- lib/fixtures/_fixtures/logger.py 2011-11-25 17:37:36 +0000
+++ lib/fixtures/_fixtures/logger.py 2012-06-04 20:16:20 +0000
@@ -18,6 +18,10 @@

 from fixtures import Fixture

+from testtools.content import Content
+from testtools.content_type import UTF8_TEXT
+
 __all__ = [
     'FakeLogger',
     'LoggerFixture',
@@ -52,7 +56,10 @@

     def setUp(self):
         super(FakeLogger, self).setUp()
- self._output = StringIO()
+ output = StringIO()
+ self._output = output
+ self.addDetail(u"pythonlogging:'%s'" % self._name,
+ Content(UTF8_TEXT, lambda: [output]))
         logger = getLogger(self._name)
         if self._level:
             self.addCleanup(logger.setLevel, logger.level)

Note the use of a closure here so that d = f.getDetails(),
f.cleanUp(), f.setUp(), d.items()[0].itertext() will not return the
new (empty) state of the fixture.

HTH,
Rob

[lp:~frankban/python-fixtures/fakelogger-getdetails]

52. By Francesco Banconi on 2012-06-05

Fixes from review.

[Francesco Banconi (frankban)]

> There seem to be a lot of whitespace changes in the diff? Possibly
> harmless, but confusing.

My editor is set up to strip spaces at the end of lines when I save a file.
I can revert changes in fixture.py if you like, I should have mentioned this earlier, sorry.

> Rather than implementing getDetails, the normal mechanism is to call
> self.addDetail with a detail that will return the appropriate content
> when evaluated. This is cheaper than evaluating when getDetails is
> called, and means you only need to test that an appropriate detail is
> added, rather than that the getDetails method still Does The Right
> Thing. The UTF8_TEXT helper is probably revelant here too, for
> brevity.

Great! I've changed the branch following this suggestion, and deleted a test.

> Finally, on the naming of things, I'd describe the attachment - think
> of it as an email attachment.

Now the detail name is an instance attribute: if you don't like this, I can just
format the string in setUp and find another way (e.g. .values()[0]) to get the
content in the test.

> Note the use of a closure here so that d = f.getDetails(),
> f.cleanUp(), f.setUp(), d.items()[0].itertext() will not return the
> new (empty) state of the fixture.

Yes, I was using a closure in the previous revision too. It's cool and, AFAICT,
lazy evaluation is the only option here, since details are gathered early in useFixture:
http://bazaar.launchpad.net/~testtools-committers/testtools/trunk/view/head:/testtools/testcase.py#L585

Thanks Robert.

[Robert Collins (lifeless)]

On Tue, Jun 5, 2012 at 10:14 PM, Francesco Banconi
<email address hidden> wrote:
>> There seem to be a lot of whitespace changes in the diff? Possibly
>> harmless, but confusing.
>
> My editor is set up to strip spaces at the end of lines when I save a file.
> I can revert changes in fixture.py if you like, I should have mentioned this earlier, sorry.

No probs, thanks for clarifying.

>> Rather than implementing getDetails, the normal mechanism is to call
>> self.addDetail with a detail that will return the appropriate content
>> when evaluated. This is cheaper than evaluating when getDetails is
>> called, and means you only need to test that an appropriate detail is
>> added, rather than that the getDetails method still Does The Right
>> Thing. The UTF8_TEXT helper is probably revelant here too, for
>> brevity.
>
> Great! I've changed the branch following this suggestion, and deleted a test.
>
>> Finally, on the naming of things, I'd describe the attachment - think
>> of it as an email attachment.
>
> Now the detail name is an instance attribute: if you don't like this, I can just
> format the string in setUp and find another way (e.g. .values()[0]) to get the
> content in the test.

I don't, because with name merging the and subordinate fixtures folk
will generally be unable to rely on such an instance attribute being
correct. Documenting how the name is ordinarily calculated, and then
using a literal string in the test would be fine, I think.

>> Note the use of a closure here so that d = f.getDetails(),
>> f.cleanUp(), f.setUp(), d.items()[0].itertext() will not return the
>> new (empty) state of the fixture.
>
> Yes, I was using a closure in the previous revision too. It's cool and, AFAICT,
> lazy evaluation is the only option here, since details are gathered early in useFixture:
> http://bazaar.launchpad.net/~testtools-committers/testtools/trunk/view/head:/testtools/testcase.py#L585

I'll look at the exact changes when I'm less sick :(. The previous
version used a closure of lambda: [self.output], but self.output is a
property, so it does not have the behaviour I described. When
evaluated it would get the current valuation from self, not the
valuation of the log output for the time when the fixture was first
setup.

-Rob

[lp:~frankban/python-fixtures/fakelogger-getdetails]

53. By Francesco Banconi on 2012-06-06

Updated the way the detail name is added.

[Francesco Banconi (frankban)]

Code updated.

[Jonathan Lange (jml)]

testtools.content.content_from_stream might be slightly better than Content(UTF8_TEXT, ...) for verbose logs, as it reads the content in chunks. If not t.c.text_content does almost the same thing as the current code and is briefer.

It's not clear to me *when* you want to do the read. Presumably it's when getDetails is called, which seems to be what the current version does (and what content_from_stream would do). I don't really understand Robert's last paragraph.

[lp:~frankban/python-fixtures/fakelogger-getdetails]

54. By Francesco Banconi on 2012-06-07

Removed unused text_content import.

[Francesco Banconi (frankban)]

> testtools.content.content_from_stream might be slightly better than
> Content(UTF8_TEXT, ...) for verbose logs, as it reads the content in chunks.
> If not t.c.text_content does almost the same thing as the current code and is
> briefer.

I think we want lazy evaluation of content: we don't want to read the stream when getDetails() is called.
As written above, useFixture() gathers details early, and does it by calling fixture.getDetails(), and at this point I expect the stream to be empty. So, if I am not wrong, `text_content` is not an option here, since it requires a string. content_from_stream is a great suggestion, thanks, and evaluates the content later, when `_iter_chunks` is called. Unfortunately to obtain something useful form the StringIO we should also call seek(0) on the stream before generating chunks. That's the reason why I am using `StringIO.getvalue` to get the content.

> It's not clear to me *when* you want to do the read.

I hope I explained the *when* above.

> Presumably it's when
> getDetails is called, which seems to be what the current version does (and
> what content_from_stream would do). I don't really understand Robert's last
> paragraph.

The current version uses a clusure:
lambda: [self.output]
That is the same as:
lambda: [self._output.getvalue()]

The test in this branch should demonstrate that the evaluation returns the current log content, and not the one from when getDetails was called.

[Robert Collins (lifeless)]

This should demonstrate the problem. There is no need to iterate on
your branch - I will adjust as I merge:

    def test_no_state_confusion_when_reusing_logging_fixture(self):
        fixture = FakeLogger()
        detailname = "pythonlogging:''"
        with fixture:
            content = fixture.getDetails()[detailname]
            logging.info('some message')
            orig_result = content.as_text()
            self.assertEqual(fixture.output, orig_result)
        with fixture:
            self.assertEqual(orig_result, content.as_text())

[Francesco Banconi (frankban)]

Ah! I see, thank you Robert.

=== modified file 'lib/fixtures/_fixtures/logger.py'
--- lib/fixtures/_fixtures/logger.py	2011-11-25 17:37:36 +0000
+++ lib/fixtures/_fixtures/logger.py	2012-06-07 13:10:51 +0000
@@ -1,12 +1,12 @@
 #  fixtures: Fixtures with cleanups for testing and convenience.
 #
 # Copyright (c) 2011, Robert Collins <[e-mail]>
-# 
+#
 # Licensed under either the Apache License, Version 2.0 or the BSD 3-clause
 # license at the users choice. A copy of both licenses are available in the
 # project source as Apache-2.0 and BSD. You may not use this file except in
 # compliance with one of these two licences.
-# 
+#
 # Unless required by applicable law or agreed to in writing, software
 # distributed under these licenses is distributed on an "AS IS" BASIS, WITHOUT
 # WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.  See the
@@ -16,6 +16,9 @@
 from logging import StreamHandler, getLogger, INFO, Formatter
 from cStringIO import StringIO
 
+from testtools.content import Content
+from testtools.content_type import UTF8_TEXT
+
 from fixtures import Fixture
 
 __all__ = [
@@ -53,7 +56,10 @@
     def setUp(self):
         super(FakeLogger, self).setUp()
         self._output = StringIO()
-        logger = getLogger(self._name) 
+        self.addDetail(
+            u"pythonlogging:'%s'" % self._name,
+            Content(UTF8_TEXT, lambda: [self.output]))
+        logger = getLogger(self._name)
         if self._level:
             self.addCleanup(logger.setLevel, logger.level)
             logger.setLevel(self._level)

=== modified file 'lib/fixtures/fixture.py'
--- lib/fixtures/fixture.py	2011-11-25 17:55:19 +0000
+++ lib/fixtures/fixture.py	2012-06-07 13:10:51 +0000
@@ -1,12 +1,12 @@
 #  fixtures: Fixtures with cleanups for testing and convenience.
 #
 # Copyright (c) 2010, Robert Collins <[e-mail]>
-# 
+#
 # Licensed under either the Apache License, Version 2.0 or the BSD 3-clause
 # license at the users choice. A copy of both licenses are available in the
 # project source as Apache-2.0 and BSD. You may not use this file except in
 # compliance with one of these two licences.
-# 
+#
 # Unless required by applicable law or agreed to in writing, software
 # distributed under these licenses is distributed on an "AS IS" BASIS, WITHOUT
 # WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.  See the
@@ -151,7 +151,7 @@
 
         This does not return the internal dictionary: mutating it will have no
         effect. If you need to mutate it, just do so directly.
-        
+
         :return: Dict from name -> content_object.
         """
         result = dict(self._details)
@@ -163,7 +163,7 @@
         """Prepare the Fixture for use.
 
         This should be overridden by most concrete fixtures. When overriding
-        be sure to include self.addCleanup calls to restore the fixture to 
+        be sure to include self.addCleanup calls to restore the fixture to
         an un-setUp state, so that a single Fixture instance can be reused.
 
         After setUp is called, the fixture will have one or more attributes
@@ -218,7 +218,7 @@
 
     Typically used when an existing object or function interface exists but you
     wish to use it as a Fixture (e.g. because fixtures are in use in your test
-    suite and this will fit in better). 
+    suite and this will fit in better).
 
     To adapt an object with differently named setUp and cleanUp methods:
     fixture = FunctionFixture(object.install, object.__class__.remove)

=== modified file 'lib/fixtures/tests/_fixtures/test_logger.py'
--- lib/fixtures/tests/_fixtures/test_logger.py	2011-11-25 17:37:36 +0000
+++ lib/fixtures/tests/_fixtures/test_logger.py	2012-06-07 13:10:51 +0000
@@ -1,12 +1,12 @@
 #  fixtures: Fixtures with cleanups for testing and convenience.
 #
 # Copyright (c) 2011, Robert Collins <[e-mail]>
-# 
+#
 # Licensed under either the Apache License, Version 2.0 or the BSD 3-clause
 # license at the users choice. A copy of both licenses are available in the
 # project source as Apache-2.0 and BSD. You may not use this file except in
 # compliance with one of these two licences.
-# 
+#
 # Unless required by applicable law or agreed to in writing, software
 # distributed under these licenses is distributed on an "AS IS" BASIS, WITHOUT
 # WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.  See the
@@ -76,3 +76,11 @@
         self.useFixture(fixture)
         logging.info("message")
         self.assertEqual("test_logger\n", fixture.output)
+
+    def test_logs_returned_as_details(self):
+        # Ensure logs are correctly returned as fixture details.
+        fixture = self.useFixture(FakeLogger())
+        details =  fixture.getDetails()
+        logging.info('some message')
+        content = details["pythonlogging:''"]
+        self.assertEqual(fixture.output, content.as_text())