Opened 12 years ago

Closed 8 years ago

#2409 defect closed fixed (fixed)

twisted.plugin should be quiet when it can't write cache file

Reported by: jknight Owned by: Jean-Paul Calderone
Priority: high Milestone:
Component: core Keywords: easy
Cc: Thijs Triemstra, jesstess Branch: branches/plugin-cache-2409
branch-diff, diff-cov, branch-cov, buildbot
Author: squiddo, exarkun

Description

The cache file is not important enough to emit a traceback every time you run a program using twisted just because your OS' twisted install doesn't have an up-to-date cache file. It used to log.msg an error if it couldn't write it. I bet that didn't actually write anything because there was no logger initialized yet.

Attachments (4)

plugin.py.diff (2.2 KB) - added by rikyu 12 years ago.
add_warning.diff (2.1 KB) - added by Squiddo 8 years ago.
Patch to add a warning when the plugin cache is not writable.
add-warning-revised.diff (2.2 KB) - added by Squiddo 8 years ago.
Removes log.err() call.
add-warning-rev2.diff (2.2 KB) - added by Squiddo 8 years ago.
Replaced assertRegexpMatches by twisted's assertIn.

Download all attachments as: .zip

Change History (36)

Changed 12 years ago by rikyu

Attachment: plugin.py.diff added

comment:1 Changed 12 years ago by rikyu

I've recently run into this, and would like to see some kind of solution. The current behavior can be confusing, depending on your development environment; since I was doing my own logging to standard out, when I saw the exception logged, I thought it was an actual Exception being raised (i.e., something I could catch).

That said, in the interest of not rocking the boat too much on my first real submission, I have attached a patch that allows you to pass in a callable that defaults to log.err, and which is used in place of those calls in getPlugins and getCache. It was all I needed in my particular use case, but I could see it bothering people for a few reasons.

The only other option I can think of is to just allow the IOError to rise, but this would obviously break compatibility.

Incidentally, I attempted to try to make a unit test for this patch, but I couldn't really figure out an acceptable way to make sure a plugin directory isn't writable. I'd appreciate any pointers.

comment:2 Changed 10 years ago by zooko

#3649 was a duplicate of this, except that #3649 was asking for a more explicit message explaining what is wrong and how it is merely a warning, where this ticket is asking for it to be silent.

You could make a plugin directory unwritable by removing it and replacing it with an unwritable file.

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

#2644 was also a duplicate of this. There's some more discussion about what exactly should be done to resolve this on that ticket. To summarize, we should emit a warning with warnings.warn for this case.

comment:4 Changed 10 years ago by zooko

Someone was just running the unit tests of Tahoe-LAFS, and they got this permission-denied error, and so they re-ran the test with "sudo". Now they probably have root owning some of the automatically generated files that are created by running the tests. :-(

http://allmydata.org/trac/tahoe/ticket/802#comment:1

This is evidence that fixing this ticket would be good. :-)

comment:5 Changed 9 years ago by zooko

Someone else just installed Tahoe-LAFS and opened a bug report saying that the unit tests failed and including the following text in their bug report:

Traceback (most recent call last):
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/python/usage.py", line 241, in parseOptions
    self.postOptions()
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/scripts/trial.py", line 293, in postOptions
    self['reporter'] = self._loadReporterByName(self['reporter'])
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/scripts/trial.py", line 279, in _loadReporterByName
    for p in plugin.getPlugins(itrial.IReporter):
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/plugin.py", line 200, in getPlugins
    allDropins = getCache(package)
--- <exception caught here> ---
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/plugin.py", line 179, in getCache
    dropinPath.setContent(pickle.dumps(dropinDotCache))
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/python/filepath.py", line 623, in setContent
    f = sib.open('w')
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/python/filepath.py", line 433, in open
    return open(self.path, mode+'b')
exceptions.IOError: [Errno 13] Permission denied: '/System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/plugins/dropin.cache.new'

I take this as more evidence that this ticket is important. Here is the Tahoe-LAFS ticket: http://tahoe-lafs.org/trac/tahoe-lafs/ticket/1005

Let's see... So what's the next step on this. Write a unit test? Maybe the unit test just manually makes the dropin.cache.new file untouchable, then tries to list plugins, and the code under test passes if no exception was raised but a warning was logged?

Glyph or exarkun: please tell me if that is an appropriate test.

comment:6 Changed 9 years ago by Jean-Paul Calderone

One thing to do, perhaps, is to file a bug against Apple, since Apple is distributing a misinstalled version of Twisted? And also encourage anyone who encounters this to also file one (it's not like they can become nosy on the existing tickets).

As far as making a unit test goes, it should be easy. Just start from the assumption that global state is bad, and so the Twisted plugins directory isn't the thing you want to be fiddling around with. Make a fake plugins package in the test and fiddle with it, instead.

It should assert that something is logged. If someone was good, then there'd already be a test like this for the current behavior (I don't know if they were or not). The new test would presumably differ only in what exactly it is asserting about what is logged. Sounds like people want a warning of some sort without an accompanying traceback. That's fine, I suppose. From my earlier comment, it sounds like warnings.warn might be the right way to log this. However, I wouldn't object to log.msg either.

comment:7 in reply to:  6 Changed 9 years ago by Glyph

Replying to exarkun:

One thing to do, perhaps, is to file a bug against Apple, since Apple is distributing a misinstalled version of Twisted? And also encourage anyone who encounters this to also file one (it's not like they can become nosy on the existing tickets).

For those of you who may not know the URL to do this, it's bugreport.apple.com; more information is available at developer.apple.com/bugreporter.

As far as making a unit test goes, it should be easy. Just start from the assumption that global state is bad, and so the Twisted plugins directory isn't the thing you want to be fiddling around with. Make a fake plugins package in the test and fiddle with it, instead.

I was going to point at good and bad examples, but apparently therve fixed the plugin tests a couple of years ago to stop mangling global state quite so badly, so most of the tests in test_plugin are actually pretty reasonable examples, except for their unfortunate dalliance with sys.modules.

It should assert that something is logged. If someone was good, then there'd already be a test like this for the current behavior (I don't know if they were or not). The new test would presumably differ only in what exactly it is asserting about what is logged. Sounds like people want a warning of some sort without an accompanying traceback. That's fine, I suppose. From my earlier comment, it sounds like warnings.warn might be the right way to log this. However, I wouldn't object to log.msg either.

I believe the test in question is twisted.test.test_plugin.DeveloperSetupTests.test_newPluginsOnReadOnlyPath. It does a flushLoggedErrors() and makes sure an error was logged, but is unfortunately non-specific about it.

comment:8 Changed 8 years ago by <automation>

Owner: Glyph deleted

comment:9 Changed 8 years ago by Jean-Paul Calderone

Keywords: easy added

The attached patch is a little weird. I'm not sure how parameterizing the err callable helps here. There just needs to be a direct call to either warnings.warn or log.msg that says something about being unable to rewrite the cache.

comment:10 Changed 8 years ago by Squiddo

Owner: set to Squiddo

Changed 8 years ago by Squiddo

Attachment: add_warning.diff added

Patch to add a warning when the plugin cache is not writable.

comment:11 Changed 8 years ago by Squiddo

Keywords: review added
Owner: Squiddo deleted

In my very humble opinion, the original patch parameterizes the error logging for reading plugins as well as writing the plugin cache, when the bug reports seem to indicate that warnings are only needed for errors when writing the plugin cache.

I have therefore simplified the patch to issue a warning in addition to the logging when the plugin cache cannot be written to.

Please review.

comment:12 Changed 8 years ago by lvh

Keywords: easy, revieweasy review

I fixed the tags: you're not supposed to put comments in

comment:13 Changed 8 years ago by lvh

Commas. Sorry: it's 4:30 AM here at the Pycon sprint.

comment:14 Changed 8 years ago by Squiddo

Keywords: review removed
Owner: set to Squiddo

comment:15 Changed 8 years ago by Thijs Triemstra

Cc: Thijs Triemstra added

Also see #2410.

Changed 8 years ago by Squiddo

Attachment: add-warning-revised.diff added

Removes log.err() call.

comment:16 Changed 8 years ago by Squiddo

Keywords: review added
Owner: Squiddo deleted

Following the discussion, which I missed earlier, the revised patch has a warning but removes the log.err() call.

Please review.

comment:17 Changed 8 years ago by Drew Smathers

Owner: set to Drew Smathers
Status: newassigned

comment:18 Changed 8 years ago by Drew Smathers

Keywords: review removed
Owner: changed from Drew Smathers to Squiddo
Status: assignednew

This patch looks good to me but I think the test needs to be changed for backwards compat to not use assertRegexpMatches() which was just added in 2.7.

comment:19 Changed 8 years ago by Tom Davis

How about assertIn()?

Changed 8 years ago by Squiddo

Attachment: add-warning-rev2.diff added

Replaced assertRegexpMatches by twisted's assertIn.

comment:20 Changed 8 years ago by Squiddo

Keywords: review added
Owner: Squiddo deleted

Revised to use assertIn (thanks for the suggestion, binjured).

Please review. Again. Thanks for your patience...

comment:21 Changed 8 years ago by lvh

Author: lvh
Branch: branches/plugin-cache-2409

(In [31061]) Branching to 'plugin-cache-2409'

comment:21 Changed 8 years ago by lvh

Author: lvh
Branch: branches/plugin-cache-2409
Owner: set to lvh
Status: newassigned

comment:22 Changed 8 years ago by lvh

Keywords: review removed

Buildbot: http://buildbot.twistedmatrix.com/boxes-supported?branch=/branches/plugin-cache-2409. There were some bzr failures but ignore those: I forgot the / prefix to force-builds.py so it couldn't find the branch, it appears to build fine. There's one lagging bot, merging. as soon as it wakes up.

comment:23 Changed 8 years ago by Jean-Paul Calderone

Owner: changed from lvh to Jean-Paul Calderone
Status: assignednew

comment:25 Changed 8 years ago by Jean-Paul Calderone

(In [31230]) Use a log message rather than warning

refs #2409

comment:26 Changed 8 years ago by Jean-Paul Calderone

Keywords: review added
Owner: Jean-Paul Calderone deleted

I made a few more changes on this. I switched to log.msg from warnings.warn. The warnings module will insist on including a source line number with the report, which doesn't mean anything in this context, since it's a system problem not a code problem. I also restored the log.err for any exception other than OSError. We're pretty much only expecting EPERM here. If there is some other funky filesystem issue that prevents the file from being written, that will appear as an OSError as well and I guess it's okay to just log those. However, if there is some additional problem that we haven't anticipated, the details of it should be reported so we can fix it.

comment:27 Changed 8 years ago by jesstess

Owner: set to jesstess

comment:28 Changed 8 years ago by jesstess

Cc: jesstess added
Keywords: review removed
Owner: changed from jesstess to Jean-Paul Calderone

The CachedDropin reference in the getCache docstring could use markup, and getCache is missing blank lines above and below it. Other than that, this looks good to merge.

comment:29 Changed 8 years ago by Jean-Paul Calderone

Author: squiddo, exarkun
Branch: branches/plugin-cache-2409

comment:30 Changed 8 years ago by Jean-Paul Calderone

(In [31244]) Small whitespace tweaks and better linkage in the getCache docstring

refs #2409

comment:31 Changed 8 years ago by Jean-Paul Calderone

Thanks for the review! Did one more build and the results look good. Merging.

comment:32 Changed 8 years ago by Jean-Paul Calderone

Resolution: fixed
Status: newclosed

(In [31246]) Merge plugin-cache-2409

Author: squiddo, exarkun Reviewer: djfroofy, lvh, jesstess Fixes: #2409

When there is a filesystem error while the plugin system is writing out a dropin.cache file, only log a simple message, not a full exception with traceback.

Note: See TracTickets for help on using tickets.