Why is my log level not being used when using loadapp from paste.deploy?

Question

I want to temporailiy turn on debug messages in a production pyramid web project so I adjusted the production.ini file, pushed it to Heroku and saw only error and warn level messages.

So I thought, that seems odd since if I start the pyramid application like the following on my local PC I get all the log level messages.

env/bin/pserve production.ini

OK, so that's not exactly how it runs on Heroku, it is actually run from a little bit of python that looks like this (in a file called runapp.py):

import os

from paste.deploy import loadapp
from waitress import serve

if __name__ == "__main__":
    port = int(os.environ.get("PORT", 5000))
    app = loadapp('config:production.ini', relative_to='.')

    serve(app, host='0.0.0.0', port=port)

Now, sure enough if I do this on my local PC I get the same behavior as when it is deployed to Heroku (hardly surprising).

 python runapp.py

My question is, what am I missing here? Why does running it the second way result in no log messages other than ERROR and WARN being output to standard out? Surely, since it is using the same production.ini file it should work the same as if I use the pserve process?

Here is my logging section from production.ini:

###
# logging configuration
# http://docs.pylonsproject.org/projects/pyramid/en/latest/narr/logging.html
###

[loggers]
keys = root, test

[handlers]
keys = console

[formatters]
keys = generic

[logger_root]
level = DEBUG
handlers = console

[logger_test]
level = DEBUG
handlers = console
qualname = test

[handler_console]
class = StreamHandler
args = (sys.stderr,)
level = DEBUG
formatter = generic

[formatter_generic]
format = %(asctime)s %(levelname)-5.5s [%(name)s][%(threadName)s] %(message)s

Answer 1

PasteDeploy does not actually assume responsibility for configuring logging. This is a little quirk where the INI file is dual-purposed. There are sections that PasteDeploy cares about, and there are sections that logging.config.fileConfig cares about, and both must be run to fully load an INI file.

If you follow the pyramid wrappers for doing this, you'd do:

pyramid.paster.setup_logging(inipath)
pyramid.paster.get_app(inipath)

The main reason you would use these instead of doing it yourself is that they support doing "the right thing" when inipath contains a section specifier like development.ini#myapp, which fileConfig would crash on.