Add assertion helpers to test log events #520
Conversation
|
@eeshangarg Hi! Can you resubmit this PR with the Allow edits from maintainers selected? That way we can work together on this. |
|
Hello! @markrwilliams: Yes, I can do that. But I am still having trouble getting tox to work on my system. I'm assuming you were the person who answered my questions on IRC about the problems I am running into? Anyway, I installed tox 2.3.1 in a virtualenv and I still get this error http://pastebin.com/A3f6nRiA, whenever I run Looking forward to working on this with you! Regards, |
|
@eeshangarg Can you run these commands in your Twisted git clone and share the output: And |
|
Hi @markrwilliams! Output of the commands you asked me to run: http://pastebin.com/H6ivULHv Thanks for all the help! I really appreciate it! :-) Regards, |
|
@eeshangarg Thanks for contributing to Twisted! Could you run this command and share its output?
(Note that it should all be on one line) |
|
Hi @markrwilliams! Here's the output: http://pastebin.com/kDzH76dP Also, about contributing to Twisted, I plan on keep going after this. :-) Regards, |
|
Hi @markrwilliams! The build for this PR seems to be failing for Python 3 due to this exception https://travis-ci.org/twisted/twisted/jobs/154622677#L2858. But when I run the Python 3 tests on my branch locally, I can't reproduce the failure that the build exhibits. Instead, one of my tests fails, but it has nothing to do with not being able to import one of my modules. The test that fails on my system is failing due to differences between what Thanks for all the help! Regards, |
|
The version of Twisted you're developing against requires that individual modules be whitelisted in Since The solution is to add the following entries to the
|
Current coverage is 91.33% (diff: 98.96%)@@ trunk #520 diff @@
==========================================
Files 808 810 +2
Lines 143807 143960 +153
Methods 0 0
Messages 0 0
Branches 12632 12636 +4
==========================================
+ Hits 131351 131491 +140
- Misses 10192 10202 +10
- Partials 2264 2267 +3
|
|
Hi @markrwilliams! The tests pass on Python 3.4 and Python 2.7 now. I only got a single failing test on Python 3. It had to do with how The build should pass now, hopefully! I think I kinda messed up with git too. I had to rebase and push -f and I have a feeling that wasn't a good thing. I would appreciate some pointers on how to fix it, if it needs to be fixed. Please let me know what you think! Thanks and regards, |
There was a problem hiding this comment.
The tests and documentation are excellent! There are some issues with the implementation to sort out. That's not surprising, though, because of the trickery involved in Logger's implementation.
Please also note that there's one branch of an if statement that needs coverage
Thanks for all the thoughtful, hard work you've put into this. I look forward to merging this after we sort out the implementation!
| @@ -19,7 +19,10 @@ | |||
| ConsumerToProtocolAdapter) | |||
| from twisted.trial.unittest import TestCase | |||
| from twisted.test.proto_helpers import MemoryReactorClock, StringTransport | |||
| from twisted.logger import LogLevel, globalLogPublisher | |||
| from twisted.logger import LogLevel | |||
| from twisted.logger.test._assertionhelpers import ( | |||
There was a problem hiding this comment.
For posterity: the assertions are private as an answer to point 3 from a previous review, making this a "misc" change. They'll remain so until we've clearer sense of how the API works after making Twisted's own tests use them
| events = [] | ||
| logger.observer = events.append | ||
| if logger.source is not None: | ||
| logger.source._log = logger |
There was a problem hiding this comment.
Is this so tests can confirm that a given event came from this logger? It doesn't seem to be used anywhere in this patch.
Unfortunately this won't work in all cases. Consider a class with a class-level logger that's also defined __slots__:
from twisted.logger import Logger
from twisted.logger.test._assertionhelpers import capturingLogEventsFrom
class HasSlots(object):
__slots__ = ['attribute']
log = Logger()
def __init__(self, attribute):
self.attribute = attribute
def logAttribute(self):
self.log.info("attribute: {attribute!}", attribute=self.attribute)
instance = HasSlots("value")
with capturingLogEventsFrom(instance.log):
instance.logAttribute()It looks like you could wrap the logger's emit so that it always sets log_trace=[], but as mentioned above this is complicated by the binding behavior of Logger.
| @type logger: L{Logger} | ||
| """ | ||
| events = [] | ||
| logger.observer = events.append |
There was a problem hiding this comment.
Logger implements the descriptor protocol so that each access to either enclosing class or instance results in a unique logger instance. That means this assignment won't have any effect on subsequently created loggers. You can verify this in a Python shell:
>>> from twisted.logger.test.test_assertionhelpers import ThingThatLogs
>>> ThingThatLogs._log is ThingThatLogs._log
False
>>> thing = ThingThatLogs()
>>> thing._log is thing._log
False
The next if statement appears to work around this by reassigning the attribute on the thing to which the Logger's bound. Something like this:
>>> thing._log = thing._log
>>> thing._log is thing._log
True
There are several problems with this approach.
- It only works if the instance (
source) has named itsLogger_log. Consider the following:
from twisted.logger import Logger
from twisted.logger.test._assertionhelpers import capturingLogEventsFrom
class SomeClass(object):
log = Logger()
def logSomething(self):
self.log.info("a message")
instance = SomeClass()
with capturingLogEventsFrom(instance.log) as events:
instance.logSomething()
print(events) # []In fact, it will fail loudly if the class has defined slots:
class HasSlots(object):
__slots__ = ['attribute']
log = Logger()
def __init__(self, attribute):
self.attribute = attribute
def logAttribute(self):
self.log.info("attribute: {attribute!}", attribute=self.attribute)
instance = HasSlots("value")
with capturingLogEventsFrom(instance.log) as events: # AttributeError: 'HasSlots' object has no attribute '_log'
instance.logAttribute()- The instance has been permanently modified. Even after the context manager's block completes, the observer will still be the
appendmethod of that particulareventslist! That particular issue can be solved by saving and restoring the original observer, like so:
@contextmanager
def capturingLogEventsFrom(logger):
...
events = []
originalObserver = logger.observer
logger.observer = events.append
if logger.source is not None:
logger.source._log = logger
try:
yield events
finally:
logger.observer = originalObserverThis is still problematic, though, because now logger.source._log is a single static instance instead of one that possesses Logger's binding behavior
- is worse than 2) and has a simpler solution: change the signature of
capturingLogEventsFromto accept the instance and name of logger on that instance. Like so:
def capturingLogEventsFrom(something, loggerName):
logger = getattr(something, loggerName)
...But there's a solution to 2) here as well, though it's a dirty hack. We can circumvent the descriptor protocol by accessing the Logger via the instance, or its class', __dict__:
@contextmanager
def capturingLogEventsFrom(something, loggerName):
logger = something.__dict__.get(
loggerName,
something.__class__.__dict__[loggerName])
events = []
logger.observer = events.append
if logger.source is not None:
logger.source._log = logger
yield eventsI'd prefer if we modified Logger to track is originating instance so that we could set the observer there. I'll let other reviewers comment on this.
| events = [] | ||
| globalLogPublisher.addObserver(events.append) | ||
|
|
||
| yield events |
There was a problem hiding this comment.
This should be:
try:
yield events
finally:
globalLogPublisher.removeObserver(events.append)That way if an exception occurs in the context manager's block, the observer will still be removed.
| if 'log_failure' in event: | ||
| expectedEvent.update(log_failure=event['log_failure']) | ||
|
|
||
| # Since we can't test log_logger, treat it like log_time |
There was a problem hiding this comment.
Is it true that you can't test it because of the binding behavior described above? If so it'd be good to have a comment describing that.
| @type kwargs: L{dict} | ||
| """ | ||
| expectedEvent = { | ||
| 'log_logger': log_logger, 'log_level': log_level, |
There was a problem hiding this comment.
If capturingLogEventsFrom's API changes according to my API suggestions, this can no longer make an assertion about the identity of log_logger, because a new instance will be created on each attribute access.
|
|
||
|
|
||
|
|
||
| def assertLogEvent(testCase, event, log_logger, log_level, log_namespace, |
There was a problem hiding this comment.
This is a very long signature! But I'm not sure if it can be any shorter.
If capturingLogEventsFrom's API changes according to my suggestion above, you can at least remove the log_logger argument.
|
|
||
| @param log_format: The format string provided for use by observers | ||
| that wish to render the event as text. The format string uses | ||
| new-style PEP 3101 formatting and is rendered using the log |
There was a problem hiding this comment.
Nice call out to the "Advanced String Formatting" PEP!
|
Hi @markrwilliams! Thanks for such a detailed review! I have exams this week, so I'll probably be working on this next week. My goal is to get this merged and work on porting Twisted to the new logging system and take on bigger projects as a Twisted contributor in general! Talk to you soon! :-) Regards, |
|
Hey @eeshangarg ! I just wanted to use this today, and was sad to see that this stalled :). Any chance you'll have time to work on it soon? |
|
@glyph: Hey! I know, I am sad I didn't get to finish this. Currently juggling a bunch of things in life and have a lot on my plate, so now might not be a good time. But I can definitely try and come back to this in a couple of weeks! However, if you find someone interested in taking over this before that, feel free to un-assign me! Thanks! :) |
|
Thanks for your contribution to Twisted. This pull request hasn't been updated in quite some time, and has merge conflicts, so I'm going to close it to reduce the clutter in the PR queue. This is not a rejection, just a clean-up; please do not hesitate to re-open a new PR with updated code when you have time. |
Hello everyone!
Sorry for taking so long to work on this (life happened!). This is a rewritten patch for 7934, as per @glyph's feedback in this comment. A few things I would like to say:
_loggerFormeant that since theLoggerthat emits a certain event is created on the fly (i.e. it is not accessible as an attribute of any object) every time something needs to be logged, theLoggerobject in question is not accessible for testing. Therefore, these events needed to be tested by passinglist.appendas an observer toGlobalLogPublisher, see here. So I had to implement a different set of context managers and assertion helpers to test these "global" log events by passing an observer toGlobalLogPublisher. One of the most salient differences from the other general helpers (assertLogEvent,assertLogEvents, etc.) is thatlog_loggeris not tested in the "global" helpers (since its not accessible anywhere but the event being tested against itself). On a different note, it turned out that (I'm not exactly sure why!) when_loggerForis used, the emitted events are modified (byGlobalLogPublishermaybe?) to ensure compatibility with the old logging system, so I refactored some of this existing code to make sure that the relevant helpers (assertGlobalLogEventandassertGlobalLogEvents) modified the arguments passed to them to ensure compatibility with the old-style events before making the final assertion.Apart from all of the above, I discovered that using
_loggerForhas a caveat (I don't know if this is just my code, @hawkowl, I would really appreciate your feedback on this)._loggerForfails when logging failures. Some rough git grepping shows that_loggerForhas not been used to log failures anywhere within Twisted so far, so this could be something that warrants further discussion. For instance,The above code snippet works as expected, the exception is caught and the failure is logged and can be tested using
assertLogEventorassertLogEvent, as you can see here.However, in the event that
_loggerForis used:In this case, the exception isn't caught at all but is still raised (or "reraised" maybe?). No event is emitted or logged, therefore, no event can be tested. The test fails at
1/0. As you'll notice, I have left this unaddressed in my PR, mainly because I couldn't figure out a away around it and partly because I had already implemented so many things that I hadn't anticipated when I submitted the last patch to this ticket approximately 13 months ago. I didn't want to make any more changes without further review. Not to mention that, if this is a bug, it warrants a distinct ticket. :-)Once we are finished with this ticket, I would love to help out with porting Twisted to the new logging system and writing tests for all events that are logged within the Twisted code base. Also, I would be up for working on writing documentation for these helpers and any new features I implement along the way. :-)
The rest, I leave it to you, and your fine sense of judgement! Looking forward to hearing everyone's feedback! Have a great day!
Thanks & regards,
Eeshan Garg