Re: 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`)

Wolfgang



Thanks for the report, analysis and proposals.

We fixed it on the stable branch with 
https://kallithea-scm.org/repos/kallithea/changeset/f9c55f700ad9f3eb81bb88ac44f11d4713d5e17a 
and 
https://kallithea-scm.org/repos/kallithea/changeset/488b52cad8905eac29645b8dad77117bfd73184d 
.


Where we ended up, deciding to support the paste convention, I don't see 
how things can change / be fixed elsewhere. For example paste.deploy and 
TurboGears are right in not touching logging configuration at all. Paste 
& other high WSGI servers are right in configuring logging ... and seem 
to consistently follow the the paste.script convention. We now also use 
that convention when not using paste.script - and all other web-ish apps 
should probably do the same. It would be nice if standard fileConfig got 
something similar built-in and everybody started using that instead ... 
but that doesn't seem feasible. And it barely seems justified to to use 
some other library just for this.


/Mads
___
kallithea-general mailing list
kallithea-general@sfconservancy.org
https://lists.sfconservancy.org/mailman/listinfo/kallithea-general

Re: 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

___
kallithea-general mailing list
kallithea-general@sfconservancy.org
https://lists.sfconservancy.org/mailman/listinfo/kallithea-general

Re: Logging re-initialized in make_app()

[Mads Kiilerich]

On 12/4/19 1:36 AM, Wolfgang Scherer wrote:

When following the instructions for WSGI dispatch at 
https://kallithea.readthedocs.io/en/latest/setup.html#apache-with-mod-wsgi any 
attempt to pass defaults to the logging initialization fails later, when 
logging is initialized again in :func:`make_app` of 
|kallithea/config/middleware.py|.

See 
http://sw-amt.ws/kallithea-deploy/html/overview.html#bug-logging-re-initialized-in-make-app
 for a full description of the bug.

Attached is a patch, that works for me.



Thanks. That's a lot of text. Please help clarify what are the main 
points and what are additional information / supportive evidence?


First, what do you mean with "pass defaults to the logging 
initialization"? Exactly how do you do that?


When you say "fails later" - exactly how does it fail?


I do agree this area looks very dirty. So much is happening in all the 
middle layers, all trying to make it simple, but ending up making it 
much more complex.


Python logging is generally not proper namespaced. Multiple attempts at 
controlling logging doesn't merge well, and there must thus be one place 
that controls it. It is thus essentially like a global variable. As 
https://flask.palletsprojects.com/en/1.1.x/logging/ says "When you want 
to configure logging for your project, you should do it as soon as 
possible when the program starts". For kallithea-cli we do that (even if 
perhaps not entirely correctly). For use as WSGI application, it gets 
more complicated as applications can be combined in the same process. 
Logging must essentially be configured by the top level entry point ... 
which must be the WSGI server or the top level WSGI application. It is 
thus kind of wrong to initialize logging in the WSGI dispatch script ... 
but more correct than to do it in the Kallithea application. Yet, to 
support different setups, I guess we still have to do it in the 
application if it hasn't been done before.


I find it essential for understanding middleware-logging.patch that it 
is guarding the initialization similar to how logging.basicConfig does. 
This is thus kind of to establish our own basicConfig, for the same reasons.


Also, the patch is establishing a wrapper around fileConfig that provide 
the `__file__` and `here` values (which seems to be a convention in this 
stack). Do you agree that we should use this wrapper in *all* places, 
instead of using fileConfig directly? If so, I will rework the patch to 
do that and clarify the back story in the commit message.



/Mads

___
kallithea-general mailing list
kallithea-general@sfconservancy.org
https://lists.sfconservancy.org/mailman/listinfo/kallithea-general

Re: Logging re-initialized in make_app()

[Wolfgang Scherer]

Hi,

Am 08.12.19 um 20:20 schrieb Thomas De Schampheleire:
> Hi Wolfgang,
>
> El mié., 4 dic. 2019 a las 2:11, Mads Kiilerich () 
> escribió:
>> On 12/4/19 1:36 AM, Wolfgang Scherer wrote:
>>> When following the instructions for WSGI dispatch at 
>>> https://kallithea.readthedocs.io/en/latest/setup.html#apache-with-mod-wsgi 
>>> any attempt to pass defaults to the logging initialization fails later, 
>>> when logging is initialized again in :func:`make_app` of 
>>> |kallithea/config/middleware.py|.
>>>
>>> See 
>>> http://sw-amt.ws/kallithea-deploy/html/overview.html#bug-logging-re-initialized-in-make-app
>>>  for a full description of the bug.
>>>
>>> Attached is a patch, that works for me.
>>
>> Thanks for the report and patch!
>>
>> It seems like some different strategies could be:
>>
>> 1. don't initialize logging in the WSGI script - just rely on what is
>> happening in make_app.
This is not a good idea, since the administrator may wish to specify run-time 
configuration defaults.
>>
>> 2. don't initialize logging in make_app - make sure it is initialized in
>> all code paths that end up in make_app ... such as WSGI script and
>> kallithea-cli.
This is the correct solution. I have checked all initialization pathes: gearbox 
serve, kallithea-cli, kallithea mod_wsgi (and pserve, paster serve).
>>
>> Do you have any experience with these alternative approaches ... or
>> thoughts about why they might be good or bad?
> Any feedback on this?

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`)

Wolfgang

diff --git a/docs/setup.rst b/docs/setup.rst
--- a/docs/setup.rst
+++ b/docs/setup.rst
@@ -562,7 +562,7 @@

   ini = '/srv/kallithea/my.ini'
   from logging.config import fileConfig
-  fileConfig(ini)
+  fileConfig(ini, {'__file__': ini, 'here': '/srv/kallithea'})
   from paste.deploy import loadapp
   application = loadapp('config:' + ini)

@@ -578,7 +578,7 @@

   ini = '/srv/kallithea/kallithea.ini'
   from logging.config import fileConfig
-  fileConfig(ini)
+  fileConfig(ini, {'__file__': ini, 'here': '/srv/kallithea'})
   from paste.deploy import loadapp
   application = loadapp('config:' + ini)

diff --git a/kallithea/bin/kallithea_cli_base.py b/kallithea/bin/kallithea_cli_base.py
--- a/kallithea/bin/kallithea_cli_base.py
+++ b/kallithea/bin/kallithea_cli_base.py
@@ -72,7 +72,11 @@
 path_to_ini_file = os.path.realpath(config_file)
 kallithea.CONFIG = paste.deploy.appconfig('config:' + path_to_ini_file)
 config_bytes = read_config(path_to_ini_file, strip_section_prefix=annotated.__name__)
-logging.config.fileConfig(cStringIO.StringIO(config_bytes))
+defaults = {
+'here': os.path.dirname(os.path.abspath(path_to_ini_file)),
+'__file__': os.path.abspath(path_to_ini_file)
+}
+logging.config.fileConfig(cStringIO.StringIO(config_bytes), defaults, disable_existing_loggers=False)
 if config_file_initialize_app:
 kallithea.config.middleware.make_app_without_logging(kallithea.CONFIG.global_conf, **kallithea.CONFIG.local_conf)
 kallithea.lib.utils.setup_cache_regions(kallithea.CONFIG)
diff --git a/kallithea/config/middleware.py b/kallithea/config/middleware.py
--- a/kallithea/config/middleware.py
+++ b/kallithea/config/middleware.py
@@ -49,5 +49,4 @@
 ``app_conf`` contains all the application-specific settings (those defined
 under ``[app:main]``.
 """
-logging.config.fileConfig(global_conf['__file__'])
 return make_app_without_logging(global_conf, full_stack=full_stack, **app_conf)
___
kallithea-general mailing list
kallithea-general@sfconservancy.org
https://lists.sfconservancy.org/mailman/listinfo/kallithea-general

Re: Logging re-initialized in make_app()

[Wolfgang Scherer]

Hello Thomas,

Am 08.12.19 um 20:20 schrieb Thomas De Schampheleire:
> El mié., 4 dic. 2019 a las 2:11, Mads Kiilerich () 
> escribió:
>> On 12/4/19 1:36 AM, Wolfgang Scherer wrote:
>>> When following the instructions for WSGI dispatch at 
>>> https://kallithea.readthedocs.io/en/latest/setup.html#apache-with-mod-wsgi 
>>> any attempt to pass defaults to the logging initialization fails later, 
>>> when logging is initialized again in :func:`make_app` of 
>>> |kallithea/config/middleware.py|.
>>>
>>> See 
>>> http://sw-amt.ws/kallithea-deploy/html/overview.html#bug-logging-re-initialized-in-make-app
>>>  for a full description of the bug.
>>>
>>> Attached is a patch, that works for me.
>>
>> Thanks for the report and patch!
>>
>> It seems like some different strategies could be:
>>
>> 1. don't initialize logging in the WSGI script - just rely on what is
>> happening in make_app.
>>
>> 2. don't initialize logging in make_app - make sure it is initialized in
>> all code paths that end up in make_app ... such as WSGI script and
>> kallithea-cli.
>>
>> Do you have any experience with these alternative approaches ... or
>> thoughts about why they might be good or bad?
> Any feedback on this?

Since I stumbled over this problem previously in a Pyramid application, I 
finally started a thorough analysis of the logging configuration situation, 
which is only partially specific to Kallithea. The implementation is actually 
incorrect in all of Paste.Script, Gearbox, Kallithea (and Pyramid).

A satisfactory implementation does require modifications in Paste.Script, 
Gearbox, Kallithea (and Pyramid). Therefore I do not expect it to happen 
anytime soon. Especially, since it seems to bother no one enough to rectify it 
;-)

The short of it for Kallithea is, that logging should not be initialized in the 
entry point used by loadapp. I.e. middleware.make_app can effectively become an 
alias for middleware.make_app_without_logging. This avoids double 
initialization for "gearbox serve" and Apache WSGI dispatch.

kallithea-cli already uses middleware.make_app_without_logging and initializes 
logging separately. However, the initialization is omitting the defaults 
"__file__" and "here" as provided by the other logging clients, which should be 
adjusted.

If you wish, I can prepare such a minimal workaround, as the complete report 
will take a couple more days.

If you are interested, you can watch the progress at 
http://sw-amt.ws/kallithea/_mnt/kallithea-deploy/html/overview.html#bug-logging-re-initialized-in-make-app

Wolfgang
___
kallithea-general mailing list
kallithea-general@sfconservancy.org
https://lists.sfconservancy.org/mailman/listinfo/kallithea-general

Re: Logging re-initialized in make_app()

[Thomas De Schampheleire]

Hi Wolfgang,

El mié., 4 dic. 2019 a las 2:11, Mads Kiilerich () escribió:
>
> On 12/4/19 1:36 AM, Wolfgang Scherer wrote:
> > When following the instructions for WSGI dispatch at 
> > https://kallithea.readthedocs.io/en/latest/setup.html#apache-with-mod-wsgi 
> > any attempt to pass defaults to the logging initialization fails later, 
> > when logging is initialized again in :func:`make_app` of 
> > |kallithea/config/middleware.py|.
> >
> > See 
> > http://sw-amt.ws/kallithea-deploy/html/overview.html#bug-logging-re-initialized-in-make-app
> >  for a full description of the bug.
> >
> > Attached is a patch, that works for me.
>
>
> Thanks for the report and patch!
>
> It seems like some different strategies could be:
>
> 1. don't initialize logging in the WSGI script - just rely on what is
> happening in make_app.
>
> 2. don't initialize logging in make_app - make sure it is initialized in
> all code paths that end up in make_app ... such as WSGI script and
> kallithea-cli.
>
> Do you have any experience with these alternative approaches ... or
> thoughts about why they might be good or bad?

Any feedback on this?

Thanks,
Thomas
___
kallithea-general mailing list
kallithea-general@sfconservancy.org
https://lists.sfconservancy.org/mailman/listinfo/kallithea-general

Re: Logging re-initialized in make_app()

[Mads Kiilerich]

On 12/4/19 1:36 AM, Wolfgang Scherer wrote:

When following the instructions for WSGI dispatch at 
https://kallithea.readthedocs.io/en/latest/setup.html#apache-with-mod-wsgi any 
attempt to pass defaults to the logging initialization fails later, when 
logging is initialized again in :func:`make_app` of 
|kallithea/config/middleware.py|.

See 
http://sw-amt.ws/kallithea-deploy/html/overview.html#bug-logging-re-initialized-in-make-app
 for a full description of the bug.

Attached is a patch, that works for me.



Thanks for the report and patch!

It seems like some different strategies could be:

1. don't initialize logging in the WSGI script - just rely on what is 
happening in make_app.


2. don't initialize logging in make_app - make sure it is initialized in 
all code paths that end up in make_app ... such as WSGI script and 
kallithea-cli.


Do you have any experience with these alternative approaches ... or 
thoughts about why they might be good or bad?


/Mads

___
kallithea-general mailing list
kallithea-general@sfconservancy.org
https://lists.sfconservancy.org/mailman/listinfo/kallithea-general