9280 web remove legacy log #919
Conversation
Currently, capturing log events during test to verify their properties is accomplished by defining a provider of ILogObserver (see test_endpoints), but this is unnecessary boilerplate for test authors. Existing classes, such as LimitedHistoryLogObserver are ill suited as their internal buffers are private. The new class stores events and implements the sequence protocol to allow later inspection.
Instead of twisted.python.log.err, use the failure API of Logger.
Replace the use of twisted.python.log.err with twisted.logger.
Modify Request object to have a Logger instance and use that for logging.
The subject method had no existing docstrings, which makes it harder than necessary to approach any modifications.
Use a module level logger instead of the module logger.
Eliminate the use of the twisted.python.log module in favor of twisted.logger.
Add a class Logger instance to capture log messages instead of the legacy log API.
Add a class attribute Logger instance and replace all existing calls to the legacy log subsystem.
Add newsfragment for the feature to remove use of legacy log subsystem.
Add class attribute for _WSGIResponse and use the Logger's failure method to log the error.
Ensure compatibility with existing interface by passing a message kwarg whose value is a tuple. Add a comment at the site explaining why this is necessary as it isn't immediately obvious.
The wsgi module no longer uses the legacy log system, update the docstring to reflect the change.
The legacy log system is no longer used by either wsgi or the module's tests.
Use a class attribute for logging instead of twisted.python.log.err.
Replace all occurrences with the failure method of a class logger attribute. Additionally, add test cases for previously uncovered code paths.
Use a tuple when formatting strings as per style guidelines.
Replace all instances with usage of a Logger() class attribute.
Add docs for the private attribute primarily for the benefit of the various request subclasses.
Eliminate the legacy log system and replace with class _log attributes for each affected class.
Use a module scope logger to handle the logging if element rendering fails.
Replace use of twisted.python.log in XMLRPC with a class instance logger.
Replace with a Logger() instance for the test and log at info level.
The previous commit assumed that the failures would appear in a specific order in the observer. This is not a valid assumption and caused the tests to fail on Windows.
Replace the use with a class logger and use its failure method to capture the logged errors.
|
The last two build errors are a bit strange as neither is directly related to any changes I've made in twisted.web. As I assume review will take a while, I'm still putting the ticket in review and will monitor this as I periodically merge trunk. |
Codecov Report
@@ Coverage Diff @@
## trunk #919 +/- ##
==========================================
- Coverage 91.87% 91.51% -0.37%
==========================================
Files 840 840
Lines 148691 148919 +228
Branches 13053 13061 +8
==========================================
- Hits 136616 136282 -334
- Misses 9981 10521 +540
- Partials 2094 2116 +22 |
|
There are two failures in the above code coverage, both in test code. The first is in a new helper I added in proto_helpers, and the other is a modified line of code in test_wsgi.py that wasn't covered in the first place (I verified coverage on trunk). I know the policy is 100% coverage, but how does that apply to test code, especially if it wasn't covered in the first place? |
src/twisted/test/proto_helpers.py
Outdated
| observer implements the sequence protocol to ease iteration of the events. | ||
|
|
||
| @ivar _events: The events captured by this observer | ||
| @type _events: C{list} |
There was a problem hiding this comment.
This should be L{list} as specified in the coding standard: http://twistedmatrix.com/documents/current/core/development/policy/coding-standard.html#docstrings
There was a problem hiding this comment.
Yep, will do, sorry for the miss.
| @@ -49,7 +52,9 @@ def callInThread(self, f, *a, **kw): | |||
| # callInThread doesn't let exceptions propagate to the caller. | |||
| # None is always returned and any exception raised gets logged | |||
| # later on. | |||
| err(None, "Callable passed to SynchronousThreadPool.callInThread failed") | |||
| self._log.failure( | |||
There was a problem hiding this comment.
Can you add a new test to this file which creates a SynchronousThreadPool and passes it a function which throws an exception? That will cover this line which is uncovered.
There was a problem hiding this comment.
I can, and will worst case, but let me see if I can get anything more relevant to the context under test that'll cover this line.
This was caught during review. There was logging in the test that had never been covered because it is extremely unlikely that any existing code path would lead to it. However, the combination of a poorly implemented third party reactor and a WSGI application that throws an exception could lead to the exception making its way back to the threadpool.
This was caught during review, C{} was used where L{} should have been
used.
src/twisted/test/proto_helpers.py
Outdated
| return self._events[index] | ||
|
|
||
|
|
||
| def __contains__(self, value): |
There was a problem hiding this comment.
This contains function is not getting covered. Can you add unit test which exercises this function?
There was a problem hiding this comment.
@rodrigc I knew that last night but hadn't decided on the best approach before my internet went out. In thinking it over, since Sequence already has contains in terms of getitem, (and since this isn't doing anything special), there is really no value in this code. If you have no objections I'll just remove it, thoughts?
There was a problem hiding this comment.
Removing it would be easier, go ahead
This method wasn't used, and wasn't doing anything particularly useful or special, so removing it is appropriate.
|
Landed since @rodrigc approved but I don't believe @jlitzingerdev is a project member :) |
|
@jlitzingerdev thanks again for your contributions to Twisted. You put a lot of work into this patch. |
|
@rodrigc No problem, happy to help, I enjoy working with and on Twisted! I mentioned on IRC that I plan to go after the remaining uses, assuming no objections when I file each ticket, on a package by package basis. |
|
@glyph @rodrigc In looking at twisted/treq#185 I found that changes made in this PR suppress the stack trace. Unless that is an intention of the new log system for cases like this then I may have introduced a regression. The change that supresses the trace is: I'm going to dive into why later, but I wanted to give both of you as reviewer/merger a heads up. Note that the error still occurs, but now, instead of a trace, one sees: |
|
As near as I can tell, the visible stack trace is a feature of the legacy log system provided by twisted.python.log.py:textFromEventDict(). The same information can be obtained by processing the failure included with the event in a similar manner, but doesn't happen by default. So the question -- is a regression? |
This is the branch for 9280. The ticket is located here:
https://twistedmatrix.com/trac/ticket/9280
Some items of note:
The following uses of twisted.python.log were not changed:
The strategy I took was to validate that either the existing log messages (for info level) or failures, are still available to observers registered with the global publisher using the new loggers. The assumption was that the existing code was "correct", and I wanted to prove I didn't break anything.
Unfortunately, this means that existing tests that didn't care about logging now care. This may not be ideal, as it means changes in messages could break the tests. However, rather than assume it didn't matter, I took the opposite approach. If the new code validating logging in the tests should be removed, I'm happy to do so.
There is one simple test I added in test_distrib. I added it to verify that the failure was logged appropriately because it wasn't previously covered by any tests. A better test would be to actually exercise the failure of the component a bit better, but the work looked significant enough that I took the easy approach first. As above, I can change if desired.