rikyu commented

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.

	@zooko commented

[#3649](#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.

	@exarkun commented

#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.

	@zooko commented

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. :-)

	@zooko commented

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.

	@exarkun commented

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.

	@glyph commented

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.

	@exarkun commented

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.

	squiddo removed owner

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.

	@lvh commented

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

	@lvh commented

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

	@thijstriemstra commented

Also see #2410.

	squiddo removed owner

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

Please review.

	@djfroofy set owner to squiddo @djfroofy set status to new

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.

	binjured commented

How about assertIn()?

	squiddo removed owner

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

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

	@lvh commented

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

	@lvh commented

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.

	@exarkun commented

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

refs #2409

	@exarkun removed owner

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.

	@jesstess set owner to @exarkun

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.

	@exarkun commented

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

refs #2409

	@exarkun commented

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

	@exarkun set status to closed

(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.