Logging re-initialized in make_app()

[Mads Kiilerich]

On 12/12/19 12:34 AM, Wolfgang Scherer wrote:
>
> I finished the analysis of logging initialization (http://sw-amt.ws/kallithea-deploy/html/overview.html#bug-logging-re-initialized-in-make-app). Since I don't think that all the packages will be updated any time soon, I will stay with the minimum required corrections in Kallithea (see attached patch).
>
> The initialization schema is generally
>
> 1. Initialize logging (each toolkit rolls their own, but defaults
>     :attr:`__file__` and :attr:`here` are always set)
> 2. Load WSGI application (:func:`paste.deploy.loadapp`)


To make sure we all are aligned on the bigger picture, let me try to 
phrase it. Please correct me if you think I got it wrong:


The basic architecture of the web part of Kallithea is that the web 
server create the TurboGears based Kallithea app instance using 
paste.deploy. The web server then use the app instance to serve WSGI 
requests.

Paste.deploy reads the .ini file using loadwsgi.NicerConfigParser, which 
is based on standard ConfigParser. Among other things, it also introduce 
the convention of passing "here" and "__file__" as "defaults" to 
ConfigParser, so these variables can be used for %()s string 
interpolation when paste.deploy reads the .ini file. Paste.deploy will 
pass the content of the app:main section as parameters to 
kallithea.config.middleware:make_app (as specified in setup.py 
paste.app_factory). We make sure Kallithea command line tools get the 
same values by using `paste.deploy.appconfig`. Kallithea will use the 
config values from paste.deploy, and will "not really" read the .ini 
file directly. It works fine for example for the default config 
`sqlalchemy.url = sqlite:///%(here)s/kallithea.db`.

Paste.deploy and TurboGears doesn't interfere with logging. They might 
use it, but they do not configure it. That must be taken care of 
elsewhere. Also when logging is configured in the same .ini file that 
paste.deploy use, but in other sections.

It is common for "WSGI servers" (such as gearbox) to run some boiler 
plate like `logging.config.fileConfig(config_file, 
dict(__file__=config_file, here=os.path.dirname(config_file))` right 
before `paste.deploy.loadapp('config:' + config_file)`. The 
here/__file__ convention that was fully contained inside paste.deploy is 
thus spreading, and it could seem like *all* "WSGI servers" now must 
initialize logging this way to ensure consistency.

mod_wsgi gives/requires full control over these details and their 
"configuration" by just launching a WSGI dispatch python script provided 
by the user. Kallithea docs/setup.rst provide some sample scripts. They 
initialize logging, but will apparently have to be extended with the 
here/__file__ boilerplate.

Also, Kallithea must make sure to follow the same here/__file__ 
convention in *all* code paths, also command line tools that has to 
invoke fileConfig directly. (That would all have been easy if it was 
built into ConfigParser (and fileConfig) - now it is just annoying 
boilerplate and tech debt.)

(We can get a ConfigParser instance like paste.deploy does by using 
`paste.deploy.loadwsgi.ConfigLoader('my.ini').parser` ... but even 
though it contains the logging config sections, there is no simple way 
to use that to initialize the logging module in py2.)

It is pointless to configure logging multiple times with the same .ini 
file. Especially if they use different conventions. That is the case 
now, when Kallithea middleware.py runs 
`fileConfig(global_conf['__file__'])` and will overwrite any `%(here)s` 
expansion that the WSGI server might have done. It seems like the 
Kallithea shouldn't mess with logging configuration, but assume it 
already has been configured. The fileConfig in make_app solved a problem 
when it was introduced in 0d4dd9380a45, but it is evidently no longer 
relevant.


/Mads