Inconsistent logging initialization

[abitrolly]

werkzeug sometimes initializes logging before app import, resulting in double logging entries.

This is app1.py that uses logging_tree to print logging configuration.

from logging_tree import printout as pt
pt()

import logging
logging.warn('------------[app restart]---')

pt()

from flask import Flask

app = Flask(__name__)

@app.route("/")
def heartbeat():
    return "tick"

import werkzeug
print(werkzeug.__version__)

The application is run with flask run in development mode.

FLASK_ENV=development FLASK_APP=bin/app1.py flask run -p 2999

Then, using combination of touch app1.py and curl localhost:2999 it should be easy to catch condition when after `logging`` tree is not empty, and log lines are duplicated. Here is the output. What happens there.

1. werkzeug reloaded app1.py. app1.py found no logging configuration, implicitly installed own root handler through logging.warn. When request from curl arrived, it was logged with this root handler as INFO:werkzeug:127.0.0.1.. line. No other lines with 200 status are printed so far.
2. touch event made werkzeug reload app1.py again. This time the logging configuration appears non-empty, app1.py again adds root handler, and when request arrives, it is printed twice.

INFO:werkzeug: * Detected change in '/root/cheat.sh/bin/app1.py', reloading
 * Restarting with stat
<--""
   Level WARNING
WARNING:root:------------[app restart]---
<--""
   Level WARNING
   Handler Stream <_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>
     Formatter fmt='%(levelname)s:%(name)s:%(message)s' datefmt=None
1.0.1
WARNING:werkzeug: * Debugger is active!
INFO:werkzeug: * Debugger PIN: 770-386-719
INFO:werkzeug:127.0.0.1 - - [16/Nov/2020 16:33:30] "GET / HTTP/1.1" 200 -
INFO:werkzeug: * Detected change in '/root/cheat.sh/bin/app1.py', reloading
 * Restarting with stat
 * Debugger is active!
<--""
   Level WARNING
   |
   o<--"werkzeug"
       Level INFO
       Handler Stream <_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>
WARNING:root:------------[app restart]---
<--""
   Level WARNING
   Handler Stream <_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>
     Formatter fmt='%(levelname)s:%(name)s:%(message)s' datefmt=None
   |
   o<--"werkzeug"
       Level INFO
       Handler Stream <_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>
1.0.1
 * Debugger PIN: 770-386-719
INFO:werkzeug: * Debugger PIN: 770-386-719
127.0.0.1 - - [16/Nov/2020 16:36:06] "GET / HTTP/1.1" 200 -
INFO:werkzeug:127.0.0.1 - - [16/Nov/2020 16:36:06] "GET / HTTP/1.1" 200 -

I expected werkzeug to initialize the logging module after app is imported to prevent double entries in stderr logs.

Environment:

Python 3.9.0
Flask 1.1.2
Werkzeug 1.0.1

[abitrolly]

If werkzeug threading doesn't allow to wait until app is imported, one solution is to explicitly remove the handler after the user app is initialized and before it is served. Explicit means that removal will be accompanied with the notification message.

 * User logging detected, removing `werkzeug` handler

[davidism]

I can't reproduce this with the latest code. Seems likely to have been addressed by #1500.

[abitrolly]

@davidism did you manage to reproduce it with the versions specified? #1500 can not fix it, because its commits 7cf9e37 were merged in 0.15.2 and I used 1.0.1