Arvados

Reviewing eedc160

This patch could muck with our users' Crunch scripts. When ARVADOS_DEBUG is set, it loads the root logging object and changes its debug level. This could mess with the logging behavior of any Crunch scripts that also use the logging module (which seems reasonably likely).

As an SDK, we should try to avoid messing with the state of other components if we can help it. The Pythonic way to fix this would be:

• arvados/__init__.py makes a logger object named 'arvados'. When ARVADOS_DEBUG is set, it adds the usual StreamHandler to it with level=DEBUG. Otherwise, it adds a NullHandler.
• When SDK things want to log, they should call .warning(), .debug(), etc. on a logger object: either this Arvados logger, or one created by calling .getChild() on it.

In addition to the separation benefits I just cited, this would also get us nicer-looking logs (they'll actually say "arvados" in them), and a single place to do logging configuration for all Arvados Python tools to promote consistency.

Yes, I'm volunteering if you'd like.

Tom Clegg wrote:

Brett Smith wrote:

• arvados/__init__.py makes a logger object named 'arvados'. When ARVADOS_DEBUG is set, it adds the usual StreamHandler to it with level=DEBUG. Otherwise, it adds a NullHandler.
• When SDK things want to log, they should call .warning(), .debug(), etc. on a logger object: either this Arvados logger, or one created by calling .getChild() on it.

Yes, this sounds better.

I've done this in 3457-pysdk-logging-wip. Instead of calling .getChild(), I call logging.getLogger() with a name under the arvados hierarchy (e.g., 'arvados.submodule'), which has the same effect. The branch is ready for review.

At 7653275

Much cleaner, as anticipated.

Just a couple of problems/questions:

• Would it be too bikeshedly (or too verbose) to ask for a process ID in the log formatter? %(process)d
• In arvados/__init__.py we use logging.NullHandler() unless ARVADOS_DEBUG is set. Doesn't that mute all logs? I'd think we would still want _logger.error("foo") to produce something on stderr even if ARVADOS_DEBUG is turned off.
• I still think we need to sprinkle some logging.basicConfig() around. My approach above was to call basicConfig immediately before any call to getLogger. This seems reasonable (given the circumstances) since basicConfig is a no-op after it has already been called (which is documented), and until it does get called, the logger returned by getLogger is useless (which I couldn't find documented in the logging module docs and seems like a bit of an API mishap but is easy to demonstrate).

1. Exercising the 'arv-mount: exception during exec %s' log:

$ arv-mount /tmp/keep --exec blergh
No handlers could be found for logger "arvados.arv-mount" 

2. Python shell:

>>> import logging
>>> foo = logging.getLogger('foo')
>>> foo.error('No foo for you')
No handlers could be found for logger "foo" 
>>> logging.basicConfig()
>>> foo.error('All better')
ERROR:foo:All better

Thanks.

Tom Clegg wrote:

• Would it be too bikeshedly (or too verbose) to ask for a process ID in the log formatter? %(process)d

Not at all, I'll add that.

• In arvados/__init__.py we use logging.NullHandler() unless ARVADOS_DEBUG is set. Doesn't that mute all logs? I'd think we would still want _logger.error("foo") to produce something on stderr even if ARVADOS_DEBUG is turned off.

I went back and forth on this. You're right about the logs being muted. That more closely approximates behavior before my branch (where logging.basicConfig() usually rarely gets called unless ARVADOS_DEBUG is set), and that's why I went with it. However, in the long run I agree that it'd make more sense to have a StreamHandler with level WARNING or ERROR by default. If you're comfortable with it, I'll make that change.

• I still think we need to sprinkle some logging.basicConfig() around. My approach above was to call basicConfig immediately before any call to getLogger. This seems reasonable (given the circumstances) since basicConfig is a no-op after it has already been called (which is documented), and until it does get called, the logger returned by getLogger is useless (which I couldn't find documented in the logging module docs and seems like a bit of an API mishap but is easy to demonstrate).

basicConfig sets a default handler and formatter for the "root" logger (the one that's a parent to all others in the hierarchy). It's a convenience method to provide some basic setup with simple customization options. If you build your own formatter and handler, as we do for the arvados logger, it's redundant. And one of the main goals of my branch is to stop touching the root logger at all, to avoid interfering with SDK users who use it.

To put it another way, the branch proposes replacing the rule "call basicConfig before getLogger" with a new rule: all Arvados tools log under the arvados hierarchy. They can trust the arvados module to set up a usable baseline configuration.

1. Exercising the 'arv-mount: exception during exec %s' log:

This is definitely a bug. Is your environment set up so that arv-mount would use the SDK from the checked out branch, or was it possibly using a version that didn't have the new log setup? I'm interested in dealing with it either way; just wondering about likely/possible causes.

2. Python shell:

This is expected because the branch only sets up logging for the arvados hierarchy. foo is not under there, so there's no configuration for it.

I also realized belatedly that arv-get uses the logger to provide basic UI messages. I'll need to deal with that too.

Brett Smith wrote:

I went back and forth on this. You're right about the logs being muted. That more closely approximates behavior before my branch (where logging.basicConfig() usually rarely gets called unless ARVADOS_DEBUG is set), and that's why I went with it. However, in the long run I agree that it'd make more sense to have a StreamHandler with level WARNING or ERROR by default. If you're comfortable with it, I'll make that change.

Yes, that sounds good. The existing logging is more or less aimed at "WARNING or worse = normal users care; INFO/DEBUG = normal users don't care" which is convenient with the logging module's default log level being WARNING. (If our logging is too verbose, we should probably tweak the categories being used, rather than depart from the "users care at or above WARNING" convention...?)

To put it another way, the branch proposes replacing the rule "call basicConfig before getLogger" with a new rule: all Arvados tools log under the arvados hierarchy. They can trust the arvados module to set up a usable baseline configuration.

OK, I think I'm finally starting to get it. "No handlers" means something used a getLogger('arvados.*') without configuring the 'arvados' node, which now means "before importing the arvados module".

This is definitely a bug. Is your environment set up so that arv-mount would use the SDK from the checked out branch, or was it possibly using a version that didn't have the new log setup? I'm interested in dealing with it either way; just wondering about likely/possible causes.

Honestly I wish I knew a better way to confirm that I'm using the right SDK. I suspected that sort of problem, and (apparently unsuccessfully) tried to confirm that setup.py had actually installed stuff in my virtualenv and that I was using that version. But I just did another round of "setup.py install" and running arv-mount the same way, and now it works fine, so that was all a red herring. Sorry.

So, for next time... I can do this:

$ /tmp/ve/bin/pip freeze | grep arvados
arvados-fuse==0.1
arvados-python-client==0.1

But is there any way to get at the 0.1.1406213925.7223231 string? This

>>> arvados.__file__
'/tmp/ve/local/lib/python2.7/site-packages/arvados_python_client-0.1-py2.7.egg/arvados/__init__.pyc'

is a little more helpful, because I can "ls -l" it... but what's the reasonable way?

Tom Clegg wrote:

Yes, that sounds good. The existing logging is more or less aimed at "WARNING or worse = normal users care; INFO/DEBUG = normal users don't care" which is convenient with the logging module's default log level being WARNING. (If our logging is too verbose, we should probably tweak the categories being used, rather than depart from the "users care at or above WARNING" convention...?)

We're on the same page. I'll make these changes.

OK, I think I'm finally starting to get it. "No handlers" means something used a getLogger('arvados.*') without configuring the 'arvados' node, which now means "before importing the arvados module".

Speaking very generally: the logging module imagines a hierarchy of loggers. The levels of the hierarchy are separated by dots in the logger names. When a message is sent to a logger, the module checks if that logger has a handler for messages. If none is found, it goes a level up the hierarchy, and repeats the process until a handler is found. The "No handlers" message means the module looked all the way through the root of the hierarchy and never found a handler for the message.

After my branch, this message coming from Arvados tools should mean that the tool is not using the arvados logging infrastructure correctly. Either it's not sending messages to a logger under the arvados hierarchy, or (like you said) it's doing that without loading the arvados module to set that up.

Honestly I wish I knew a better way to confirm that I'm using the right SDK.

I installed both of our Python modules this way, from their respective source directories:

$ pip install --user -e .

(Inside virtualenv, omit --user.) This installs an "editable" version of the library in your Python path. It's functionally equivalent to putting the right symlinks in your Python path to the source code in git. This ensures you're always working with the very latest version—for all the good and bad that entails. If you want to have separate "stable" and "development" installs on your host, well, that's exactly what virtualenv is for. :) Your personal convenience and preferences should decide which one you install in your default path (and "neither" is a possible answer).

But is there any way to get at the 0.1.1406213925.7223231 string?

It will show up in the pip freeze output if you build and install our module exactly the way we do it in Jenkins, passing all the necessary git information to python setup.py egg_info. That's the only place where we set the string, so if you don't do it on your own box, you'll never see it.

Hope this helps.

I pushed all the changes discussed. The branch is ready for another look at c7118f6.

Looks great, thank you. Just noticed one thing:

-                    logger.warning(
+                    logger.debug(
                         "API lookup failed for collection %s (%s: %s)",
                         collection, type(e), str(e))
                     manifest = arvados.Keep.get(collection)

This was warning instead of debug because the fall-back to arvados.Keep.get will not work when keepstore's permission checks are enabled. Even if you somehow succeed in getting your data anyway by fetching the manifest from Keep, the loophole you're using is expected to go away, and your data will become inaccessible (e.g., permission system turned on, permission signature expires in 2 weeks, data gets garbage-collected because you never told API server about the collection in the first place). Granted, the warning message doesn't communicate this situation very well. But I think if a user gets to this code path, we should emit a (better?) warning.

"Collection %s not found. Trying to fetch directly from Keep -- but this might mean the data is not stored safely!"

(Suggestions?)