Conversation
tarekio
left a comment
There was a problem hiding this comment.
This is better, but the changes have introduced a new issues. Now there seem to be a lot more log entries added to both the app log and and log file when each is active. These log entries don't seem to respect the log level set. Below a snippet:
{"timestamp": 1736874827.8392801, "level": "DEBUG", "message": "Took 0.000s to subset 'hmtx'", "logger": "fontTools.subset.timer", "pathname": "env/lib/python3.12/site-packages/fontTools/misc/loggingTools.py", "lineno": 357}
{"timestamp": 1736874827.8393404, "level": "INFO", "message": "hmtx subsetted", "logger": "fontTools.subset", "pathname": "env/lib/python3.12/site-packages/fontTools/subset/__init__.py", "lineno": 3527}
{"timestamp": 1736874827.8394225, "level": "DEBUG", "message": "Reading 'GDEF' table from disk", "logger": "fontTools.ttLib.ttFont", "pathname": "env/lib/python3.12/site-packages/fontTools/ttLib/ttFont.py", "lineno": 467}
{"timestamp": 1736874827.8395038, "level": "DEBUG", "message": "Decompiling 'GDEF' table", "logger": "fontTools.ttLib.ttFont", "pathname": "env/lib/python3.12/site-packages/fontTools/ttLib/ttFont.py", "lineno": 476}
{"timestamp": 1736874827.839723, "level": "DEBUG", "message": "Took 0.000s to subset 'GDEF'", "logger": "fontTools.subset.timer", "pathname": "env/lib/python3.12/site-packages/fontTools/misc/loggingTools.py", "lineno": 357}
{"timestamp": 1736874827.839787, "level": "INFO", "message": "GDEF subsetted", "logger": "fontTools.subset", "pathname": "env/lib/python3.12/site-packages/fontTools/subset/__init__.py", "lineno": 3527}
{"timestamp": 1736874827.8398619, "level": "INFO", "message": "name subsetting not needed", "logger": "fontTools.subset", "pathname": "env/lib/python3.12/site-packages/fontTools/subset/__init__.py", "lineno": 3516}
{"timestamp": 1736874827.8399282, "level": "DEBUG", "message": "Took 0.000s to subset GlyphOrder", "logger": "fontTools.subset.timer", "pathname": "env/lib/python3.12/site-packages/fontTools/misc/loggingTools.py", "lineno": 357}
{"timestamp": 1736874827.840055, "level": "DEBUG", "message": "Reading 'head' table from disk", "logger": "fontTools.ttLib.ttFont", "pathname": "env/lib/python3.12/site-packages/fontTools/ttLib/ttFont.py", "lineno": 467}
{"timestamp": 1736874827.8401403, "level": "DEBUG", "message": "Decompiling 'head' table", "logger": "fontTools.ttLib.ttFont", "pathname": "env/lib/python3.12/site-packages/fontTools/ttLib/ttFont.py", "lineno": 476}
{"timestamp": 1736874827.8402147, "level": "DEBUG", "message": "Took 0.000s to prune 'head'", "logger": "fontTools.subset.timer", "pathname": "env/lib/python3.12/site-packages/fontTools/misc/loggingTools.py", "lineno": 357}
You can replicate by approving an export request, guessing this is coming from weasyprint but could be wrong.
Couldn't recreate. Restarting app + celery after changing log level in the |
level09
left a comment
There was a problem hiding this comment.
I tried setting APP_LOG_ENABLED to True and False as well as CELERY_LOG_ENABLED but couldn't see any difference. logs are always channeled to the log handler and never show in the stdout.
Did I miss something ? I think the names of the variables is also confusing. unless they suppress the logs when turned to False.
|
If |
level09
left a comment
There was a problem hiding this comment.
Good overall. just found a small issue that could cause race condition /inefficiency
enferno/utils/logging_utils.py
Outdated
|
|
||
| # Only add handler if it doesn't exist to prevent duplicate logging | ||
| if not logger.handlers: | ||
| if cfg.APP_LOG_ENABLED: |
There was a problem hiding this comment.
If two threads call the get_logger method they could overwrite the handlers and cause issues. I suggest this simple check to fix it:
if not logger.handlers:
if cfg.APP_LOG_ENABLED:
enferno/settings.py
Outdated
| LOG_LEVEL = os.environ.get("LOG_LEVEL", "INFO") | ||
| APP_LOG_ENABLED = os.environ.get("APP_LOG_ENABLED", "True").lower() == "true" | ||
| CELERY_LOG_ENABLED = os.environ.get("CELERY_LOG_ENABLED", "True").lower() == "true" | ||
| LOG_LEVEL = os.environ.get("LOG_LEVEL", "ERROR") |
There was a problem hiding this comment.
Since we decided to have info let's default to INFO here for consistency
- Added if not logger.handlers: check before adding handlers to prevent duplicate logging if multiple threads call get_logger simultaneously. - Changed the default from "ERROR" to "INFO" for consistency as mentioned in the PR discussion.
Jira Issue
Description
[Brief description of changes]
Checklist
API Changes (if applicable)
Additional Notes
[Any other relevant information]