Double logging flask with CLI

[fmdaboville]

Hello,

When running my app withh the flask CLI I have an issue with logging, which is printed twice :

flask run                                 
 * Serving Flask app "app" (lazy loading)
 * Environment: development
 * Debug mode: on
 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
 * Restarting with stat
 * Debugger is active!
 * Debugger PIN: 582-652-287
127.0.0.1 - - [11/Dec/2021 00:36:32] "GET /hello HTTP/1.1" 200 -
2021-12-11 00:36:32: 127.0.0.1 - - [11/Dec/2021 00:36:32] "GET /hello HTTP/1.1" 200 -

Log lines are transformed like this but when I use python to run the app :

python3 /home/ubuntu/workspace/app.py
 * Serving Flask app "app" (lazy loading)
 * Environment: development
 * Debug mode: on
2021-12-11 00:29:46:  * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
2021-12-11 00:29:46:  * Restarting with stat
2021-12-11 00:30:46:  * Debugger is active!
2021-12-11 00:30:46:  * Debugger PIN: 118-580-155
2021-12-11 00:30:47: 127.0.0.1 - - [11/Dec/2021 00:30:47] "GET /hello HTTP/1.1" 200 -

The code is almost the same, I only add this when running without CLI :

if __name__ == '__main__':
     app.run()

Do you know how is configured the logger ?
Is the application aim to work with flask CLI ?

Thank you for your support !

[breqdev]

Hi!

Flask-Discord-Interactions doesn't do any extra logging configuration itself--it looks like this has to do with how Flask itself handles logging.

I just took a look at this with a simple Flask app (both with and without Flask-Discord-Interactions involved), and I'm not able to reproduce the behavior you describe--both python3 app.py and flask run give me the exact same logging output.

Without seeing the issue myself, it's hard for me to know what might be causing it, but here are some things I'd suggest:

• Make sure your flask CLI version matches your Python version. This is pretty easy to check, just run flask --version and python3 --version and see if they match up. Otherwise, you might be running an older version of Flask for one of the two scenarios.
• Are you using the logging module yourself, or are you using some other Flask extension that could be changing how the logging works? You could try running one of the Flask-Discord-Interactions examples to check if something in your code is causing the double logging.
• The way that some lines are prefixed with a timestamp (e.g. 2021-12-11 00:29:46) is interesting to me; I don't think I've seen Flask logging output like that before. Are you using Docker to run your code? Are you deploying it to Heroku or a similar site? Something about how containers handle logging output could be causing inconsistencies here; try running the code directly on your computer if you aren't already.

[fmdaboville]

I tried to make some updates and I see that it is only happening when I set the FLASK_ENV to development. There is only one line when using production :

flask run 
 * Serving Flask app "app"
 * Environment: production
   WARNING: This is a development server. Do not use it in a production deployment.
   Use a production WSGI server instead.
 * Debug mode: off
2021-12-12 00:19:53:  * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
2021-12-12 00:19:56: 127.0.0.1 - - [12/Dec/2021 00:19:56] "GET /hello HTTP/1.1" 200 -

But you can see that the line is prefixed with a timestamp. So I don't use Docker or anything to run my code, I run it directly from my Rasberry Pi with Ubuntu installed on it. Using VS Code SSH the port is forwarded to my local computer. I'm also using ngrok to forward my discord commands to my code.
What is also strange is that when running my app with the development environment, tha app is starting fast but my first request is handled like 30 seconds after.

I don't use the logging module myself and for the moment the code look likes one of your example.

My python and flask versions are giving the same output.

EDIT:
Another thing, when running without flask-discord-interactions, I don't have any double logging.

[breqdev]

That's weird. I've been thinking this over for a few days, and I honestly can't think of what might be causing it.

A couple more things you could try:

• Are there any other environment variables set that could be affecting how flask run works? Try running env | grep FLASK -- it will print all of the FLASK_ENV, FLASK_APP, etc. that are set.
• Does the double logging occur when you are running the code locally on your computer, instead of on the Raspberry Pi? I'm not sure if some of the forwarding chain could be causing issues here, or there might be some quirk in how the Ubuntu distro is set up for the Pi.
• Does the double logging happen when you get a command from Discord, or does it happen when you access a route locally? For instance, if you open http://127.0.0.1:5000/foo in your browser, is it logged twice? When you receive a command from Discord, is that logged twice?
• Is there any difference between your Discord Interactions route and any other arbitrary route? For instance, does /interactions (or whatever you have it set to) give the double logging? Does /? Or for a route that doesn't exist, is the 404 logged twice?
• Not to "blame" your code specifically, but could you also try running one of the library examples? This would really help narrow down any differences--even if your code isn't doing anything wrong, there could be a library bug involved that I can't reproduce with the examples.

[breqdev]

I'm going to close this for inactivity for now. Feel free to reopen this if you still want to track this down.