Opened 3 years ago

Closed 3 years ago

Last modified 13 months ago

#7596 release blocker: regression closed duplicate (duplicate)

twisted.python.log.FileLogObserver no longer outputs timestamps

Reported by: ralphm Owned by: Wilfredo Sánchez Vega
Priority: high Milestone: New Logging System
Component: logger Keywords:
Cc: Branch: branches/log-timestamps-7596
branch-diff, diff-cov, branch-cov, buildbot
Author: wsanchez

Description

When using (old-style) FileLogObserver, like through twistd, log events a formatted with a dash (-) instead of a timestamp.

Since #6750, this uses twisted.python.logger._legacy.publishToNewObserver, which doesn't convert the time key to the new-style log_time key. When formatting such an event in the new-style FileLogObserver, the missing timestamp is then rendered as a dash (-).

Change History (35)

comment:1 Changed 3 years ago by ralphm

Milestone: Twisted 14.1.0
Type: enhancementregression

While working on a patch for this problem, I noticed a few more issues:

  • publishToNewObserver doesn't have tests of its own. However, because of the way trial interacts with the logging system this is not obvious when merely observing code coverage.
  • (old-style) FileLogObserver.formatTime is dead code.
  • (old-style) FileLogObserver.timeFormat is not used anymore, while it could be passed on to newFileLogObserver (really textFileLogObserver) as the timeFormat argument while creating _newObserver.
  • (old-style) PythonLoggingObserver doesn't emit anything if there is no log_format key in the event. It seems to me that this is undesirable for backwards compatibility.

Marking this for the new release as I think not having any timestamps in the output is a blocker.

comment:2 Changed 3 years ago by Wilfredo Sánchez Vega

FYI, I'm at Burning man through next week, so won't be able to dig into it for a bit.

comment:3 Changed 3 years ago by Wilfredo Sánchez Vega

Author: wsanchez
Branch: branches/log-timestamps-7596

(In [43049]) Branch for #7596

comment:4 Changed 3 years ago by Wilfredo Sánchez Vega

Actually, looks like publishToNewObserver is being tested indirectly (and incompletely) by TestOldLogPublisher.

I'll replace TestOldLogPublisher with something that directly tests publishToNewObserver.

comment:5 Changed 3 years ago by Wilfredo Sánchez Vega

r43053 switches to direct testing of publishToNewObserver

comment:6 Changed 3 years ago by Wilfredo Sánchez Vega

r43054 copies time to log_time.

comment:7 Changed 3 years ago by Wilfredo Sánchez Vega

FileLogObserver.formatTime and FileLogObserver.timeFormat were left in place because they are existing API and removing them would create a compatibility problem if you happen to be using them directly.

I'm hesitant to pass timeFormat to newFileLogObserver as you suggest because the timeFormat argument to textFileLogObserver is then passed to _format.formatTime, which is not the same as FileLogObserver.formatTime, so a format intended for one isn't necessarily going to give you the results you expect when used with the other.

In particular, there is no code in _format.formatTime to try to emulate the behavior of FileLogObserver.formatTime when timeFormat is None.

comment:8 Changed 3 years ago by Wilfredo Sánchez Vega

twisted.test.test_log.PythonLoggingObserverTestCase.test_strangeEventDict tests that no output is emitted when the message is empty, which is ensured by the check for log_format.

comment:9 Changed 3 years ago by Wilfredo Sánchez Vega

I see timestamps when I run twistd web:

2014-09-12T15:12:15-0700 [-] Log opened.
2014-09-12T15:12:15-0700 [-] twistd 14.0.0 (/usr/bin/python 2.7.6) starting up.
...

comment:10 Changed 3 years ago by Wilfredo Sánchez Vega

Keywords: review added

comment:11 Changed 3 years ago by Jean-Paul Calderone

Owner: changed from Wilfredo Sánchez Vega to Jean-Paul Calderone

comment:12 Changed 3 years ago by Jean-Paul Calderone

Keywords: review removed
Owner: changed from Jean-Paul Calderone to Wilfredo Sánchez Vega

Thanks.

  1. A couple general observations about the tests (these are mostly pre-existing, though this change does include some use of non-coding-standard-compliant patterns - the new instances of these added by this change should be fixed before merging this; the pre-existing instances should be fixed too but they don't need to be fixed to resolve this ticket):
    1. assertIs (stdlib unittest spelling) is preferred over assertIdentical.
    2. assertEqual is preferred over assertEquals (the latter is deprecated in the stdlib unittest module).
    3. test_fooBar is preferred over test_foo_bar (_ means "dynamic dispatch here" in the Twisted coding standard).
    4. Many test method docstrings say "should". The preferred style is "X does y" rather than "X should do y".
  2. The actual fix for the misbehavior seems good to me, though this is my first look at the new logging system.
  3. It looks like test_time is the test that exercises the previously unspecified behavior. This would have been slightly easier to figure out if the test suite refactoring had been contributed separately.
  4. It looks like this change is removing some coverage of the integration between the old logging API (twisted.python.log.LogPublisher) and the new logging system. Does another part of the test suite exercise that integration? I see that LegacyLoggerTests exists and tests the integration between twisted.python.logger.LegacyLogger which is close but not quite the same. Relatedly, I wonder why there's both twisted.python.logger.LegacyLogger and twisted.python.log.LogPublisher (probably if I understood this I'd also understand why their implementations of msg are so different, too). Is twisted.python.log on its way to being deprecated?

Please re-submit after addressing those points and either adding the extra test coverage or pointing out where it already exists. Thanks again.

comment:13 Changed 3 years ago by Wilfredo Sánchez Vega

OK:

  1. Seems like twisted checker should complain about #1.1 and #1.2. r43085 and r43086 fix those. r43087 fixes #1.3.
  2. Cool.
  3. Also easier if you note that r43054, which contains the fix, also contains the associated test. (Comment 6 could be more explicit about that.)
  4. I don't think we need "integration tests". I think that the tests for the old logging system should test that the old logging system works. As to why there are both twisted.python.logger.LegacyLogger and twisted.python.logger.LegacyLogger: the former is a class in the new system meant to be API compatible with the old system, so that you can switch to using the new module explicitly without changing code. This provided a transition mechanism. The latter exists because it always has and we don't want to break existing API. I do think that twisted.python.log should be deprecated eventually.

comment:14 Changed 3 years ago by Wilfredo Sánchez Vega

Status: newassigned

comment:15 Changed 3 years ago by Wilfredo Sánchez Vega

Looks like twisted.python.log has no tests to verify that it's output is as expected. Adding a test to make sure the timestamp prefix is added and correct.

comment:16 Changed 3 years ago by Wilfredo Sánchez Vega

Tests added in r43088 to ensure that the old FileLogObserver adds a prefix (timestamp plus system) and suffix (newline). The former test shows we aren't formatting the timestamp properly.

At some point, glyph decided to make the old FileLogObserver rely on the new one in order to remove some code. In the process, we lost the wiring to the formatTime machinery in the old class, which is why ralph is noticing there is is 'dead code' here. I think the best course of action is to revert the implementation back to how it was in 14.0.0 to make sure the behavior is as it was.

Last edited 3 years ago by Wilfredo Sánchez Vega (previous) (diff)

comment:17 Changed 3 years ago by Wilfredo Sánchez Vega

LegacyLogObserverWrapper should also provide the time and system keys; this is the inverse of this bug. Fixed in r43091.

comment:18 Changed 3 years ago by Wilfredo Sánchez Vega

r43092 restores the timestamp formatting behavior of the legacy FileLogObserver.

The tests added in r43088 now pass. Also: FileLogObserver.formatTime is no longer dead code, as it's in use again.

Last edited 3 years ago by Wilfredo Sánchez Vega (previous) (diff)

comment:19 Changed 3 years ago by Wilfredo Sánchez Vega

Finally, I should address exarkun's #1.4 about how I should not say should so much. r43093 should fix that.

comment:20 Changed 3 years ago by Wilfredo Sánchez Vega

Whoops r43088 had a copy/paste error. r43095 commits the actual test_emitNewline.

comment:21 Changed 3 years ago by Wilfredo Sánchez Vega

Keywords: review added
Status: assignednew

Back to review.

comment:22 Changed 3 years ago by Glyph

Owner: Wilfredo Sánchez Vega deleted

comment:23 Changed 3 years ago by Glyph

Keywords: review removed
Owner: set to Wilfredo Sánchez Vega
  1. The python 3 buildbot is failing on these changes, so they'll need another pass to make sure that they work.
  2. in your response to exarkun's review point 1.2, you seem to have fixed all instances of coding-standard violations. It would be a lot easier to review these changes if you could split the changes into two patches, one to address coding-standard compliance issues in the tests and the other to just fix the issue here (but not to introduce any new coding standard violations).

Since I'm the one responsible for the slightly idiosyncratic test names, I should point out that it intentionally evoked the "dynamic dispatch" implication; the tests with two underscores in their names were named test_<method under test>_<property being verified>. Personally, I think that this is an acceptable interpretation of the coding standard, and it does exist in a few other places (although I'm not sure if it is in Divmod projects or in Twisted proper, off the top of my head).

The test failures in point 1 do necessitate a re-review; it's up to you how to address the second point, but it will definitely be possible for me to review a lot faster if those changes are in a separate ticket.

comment:24 Changed 3 years ago by Jean-Paul Calderone

Since I'm the one responsible for the slightly idiosyncratic test names, I should point out that it intentionally evoked the "dynamic dispatch" implication; the tests with two underscores in their names were named test_<method under test>_<property being verified>. Personally, I think that this is an acceptable interpretation of the coding standard, and it does exist in a few other places (although I'm not sure if it is in Divmod projects or in Twisted proper, off the top of my head).

The coding standard should be updated then, since it isn't actually dynamic dispatch. Personally, I think this is a bad idea - underscores should be reserved for actual dynamic dispatch. Instead, for this pattern, it's usually better to make a new TestCase subclass that is dedicated to "method under test" and give its test methods names like "test_<property verified>".

Either way, the change was made already. It seems unreasonable to ask wsanchez to change it back. Since you didn't number this comment, I think you weren't making this change a requirement for a passing review but it seems like the comment could probably be interpreted either way. Please add another comment saying whether you think this is a required change or not.

comment:25 in reply to:  24 Changed 3 years ago by Glyph

Replying to exarkun:

Since I'm the one responsible for the slightly idiosyncratic test names, I should point out that it intentionally evoked the "dynamic dispatch" implication; the tests with two underscores in their names were named test_<method under test>_<property being verified>. Personally, I think that this is an acceptable interpretation of the coding standard, and it does exist in a few other places (although I'm not sure if it is in Divmod projects or in Twisted proper, off the top of my head).

The coding standard should be updated then, since it isn't actually dynamic dispatch. Personally, I think this is a bad idea - underscores should be reserved for actual dynamic dispatch. Instead, for this pattern, it's usually better to make a new TestCase subclass that is dedicated to "method under test" and give its test methods names like "test_<property verified>".

Either way, the change was made already. It seems unreasonable to ask wsanchez to change it back.

In point 2, I asked wsanchez to "change it back" (remove those changes from this ticket) so that future reviews could be faster; provoking large numbers of nearby unrelated "cleanups" are a review antipattern we have. This was just an explanation.

Since you didn't number this comment, I think you weren't making this change a requirement for a passing review but it seems like the comment could probably be interpreted either way. Please add another comment saying whether you think this is a required change or not.

This change is definitely not required; it was just a clarification on point 2, which, as I described, is up to the author's discretion.

Last edited 3 years ago by Glyph (previous) (diff)

comment:26 Changed 3 years ago by Wilfredo Sánchez Vega

OK let's start with this:

  File "/home/buildslave/run/python-3.3-tests/Twisted/twisted/python/log.py", line 535, in emit
    util.untilConcludes(self.write, timeStr + " " + msgStr)
builtins.TypeError: Can't convert 'bytes' object to str implicitly

Try the code for FileLogObserver.emit() in py3.4's interpreter:

  • text is a str
  • timeStr is a str
  • msgStr is a bytes

So _safeFormat returned bytes… and that looks pretty intentional; if it would return unicode, it encodes to UTF-8 bytes.

comment:27 Changed 3 years ago by Glyph

If you're calling write with it you need a bytes, so encode timeStr the same way.

comment:28 Changed 3 years ago by Wilfredo Sánchez Vega

Py3 disagrees:

>>> f
<_io.TextIOWrapper name='/tmp/log.txt' mode='w' encoding='UTF-8'>
>>> f.write(b"123")
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: must be str, not bytes
>>> 

Seems write() wants unicode in Py3.

comment:29 Changed 3 years ago by Wilfredo Sánchez Vega

Status: newassigned

comment:30 Changed 3 years ago by hawkowl

Milestone: Twisted 14.1.0New Logging System

comment:31 Changed 3 years ago by Wilfredo Sánchez Vega

Breaking this up into separate tickets:

  • #7710 publishToNewObserver doesn't have tests of its own ✓
  • #7711 twisted.python.log.FileLogObserver no longer outputs timestamps
  • #7712 non-coding-standard-compliant patterns in twisted.python.logger
Last edited 3 years ago by Wilfredo Sánchez Vega (previous) (diff)

comment:32 Changed 3 years ago by Wilfredo Sánchez Vega

(Split is so we can merge reviewed work up to the change that effected Py3 tests and isolate that.)

comment:33 Changed 3 years ago by Wilfredo Sánchez Vega

#7710 (source:branches/log-publishToNewObserver-tests-7710) merged to source:branches/log-booyah-6750-5 in r43463.

comment:34 Changed 3 years ago by Wilfredo Sánchez Vega

Resolution: duplicate
Status: assignedclosed

Closing this as duplicate of the three new tickets, since they are merging directly into the logging branch.

comment:35 Changed 13 months ago by Wilfredo Sánchez Vega

Component: corelogger
Note: See TracTickets for help on using tickets.