Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix: configure root logger #146

Merged
merged 3 commits into from
Sep 7, 2022
Merged

Fix: configure root logger #146

merged 3 commits into from
Sep 7, 2022

Conversation

angela-tran
Copy link
Member

@angela-tran angela-tran commented Sep 7, 2022

Related to #139

This PR makes sure that in addition to configuring Flask's logger (which Flask uses internally), we also configure the root logger. This is so that loggers we create from the standard logging module are configured correctly.

Our code doesn't need to use app.logger because I believe there is nothing to be gained from using it over just a normal logger, and I think we'd rather use not have to import current_app everywhere that needs logging. We still configure it though for internal Flask logging messages.

Steps to Reproduce

  1. Launch the server with default settings
  2. Go to the /verify endpoint, e.g. in a browser
  3. Look at the logs
  4. Do steps 2-3 for /healthcheck and /publickey as well

Expected behavior

Since the log level in default settings is INFO, you should see at least that level.
Something like:

* Tip: There are .env or .flaskenv files present. Do "pip install python-dotenv" to use them.
[2022-09-07 15:27:33,742] WARNING werkzeug:224  * Debugger is active!
[2022-09-07 15:27:33,742] INFO werkzeug:224  * Debugger PIN: 575-180-751
[2022-09-07 15:28:02,697] INFO eligibility_server.keypair:33 Reading client key file: ./keys/client.pub
[2022-09-07 15:28:02,715] INFO eligibility_server.keypair:39 Reading server private key file: ./keys/server.key
[2022-09-07 15:28:02,759] INFO eligibility_server.hash:22 Input hash algorithm set to: sha256
[2022-09-07 15:28:04,762] ERROR eligibility_server.verify:125 Forbidden
[2022-09-07 15:28:04,765] INFO werkzeug:224 172.24.0.1 - - [07/Sep/2022 15:28:04] "GET /verify HTTP/1.1" 403 -

Actual behavior

Not seeing any INFO logs, and also not seeing formatted log messages. It is as if the logger is not configured.

* Tip: There are .env or .flaskenv files present. Do "pip install python-dotenv" to use them.
* Debugger is active!
* Debugger PIN: 575-180-751
Forbidden
172.24.0.1 - - [07/Sep/2022 15:29:46] "GET /verify HTTP/1.1" 403 -

@angela-tran angela-tran added the bug Something isn't working label Sep 7, 2022
@angela-tran angela-tran added this to the Courtesy Cards milestone Sep 7, 2022
@angela-tran angela-tran requested a review from a team as a code owner September 7, 2022 15:40
@angela-tran angela-tran self-assigned this Sep 7, 2022
Copy link
Member

@thekaveman thekaveman left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks great.

Any idea why we are getting duplicate entries for the messages that do come from app.logger? E.g. /healthcheck and /publickey:

image

@angela-tran
Copy link
Member Author

This looks great.

Any idea why we are getting duplicate entries for the messages that do come from app.logger? E.g. /healthcheck and /publickey

Oof, thank you for catching that. Looks like we need to configure the root logger first so that the app.logger doesn't add its own handler.
(If app.logger is called first, it triggers create_logger() which checks for existing handlers.)

@angela-tran
Copy link
Member Author

After switching the order, I don't see duplicate logging anymore:

* Tip: There are .env or .flaskenv files present. Do "pip install python-dotenv" to use them.
[2022-09-07 16:46:53,016] WARNING werkzeug:224 * Debugger is active!
[2022-09-07 16:46:53,017] INFO werkzeug:224 * Debugger PIN: 575-180-751
[2022-09-07 16:46:57,722] INFO eligibility_server.app:38 Request healthcheck
[2022-09-07 16:46:57,723] INFO werkzeug:224 172.24.0.1 - - [07/Sep/2022 16:46:57] "GET /healthcheck HTTP/1.1" 200 -
[2022-09-07 16:47:30,671] INFO eligibility_server.app:44 Request public key
[2022-09-07 16:47:30,671] INFO eligibility_server.keypair:45 Reading server public key file: ./keys/server.pub
[2022-09-07 16:47:30,677] INFO werkzeug:224 172.24.0.1 - - [07/Sep/2022 16:47:30] "GET /publickey HTTP/1.1" 200 -

eligibility_server/app.py Outdated Show resolved Hide resolved
@angela-tran angela-tran merged commit ac6d520 into main Sep 7, 2022
@angela-tran angela-tran deleted the fix/non-flask-logging branch September 7, 2022 17:16
@angela-tran angela-tran mentioned this pull request Nov 14, 2022
10 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
Archived in project
Development

Successfully merging this pull request may close these issues.

2 participants