fix: default logging #27777

jessie-ross · 2024-03-29T07:13:49Z

SUMMARY

This PR makes default logging work as expected:

Fixes duplicate logging.
Allows DEBUG level logging in production.
Makes logging respect LOG_LEVEL and LOG_FORMAT in config.
~~Sets the LOG_LEVEL to INFO to match what we currently hardcode (theoretically a breaking change.)~~

I'm not sure what the initial goals were but by default we are logging DEBUG level everything but superset, which is set to INFO level (without regard to LOG_LEVEL,) and logging superset a second time without regard to the LOG_FORMAT config setting. This doesn't seem desirable for anybody.

This change makes default logging work as expected.

Resolves #21646
I think also resolves #4785

Cause of duplicate logging:

Python loggers output via handlers, the issue is we are adding handlers twice, once here:

superset/superset/utils/logging_configurator.py

Line 50 in c0f8dfc

superset_logger.addHandler(logging.StreamHandler())

And unintuitively also when we call logging.basicConfig() which by default adds a StreamHandler on root:

superset/superset/utils/logging_configurator.py

Line 55 in c0f8dfc

logging.basicConfig(format=app_config["LOG_FORMAT"])

Minimum reproduction of the bug:

>>> import logging
>>> # No need to set BasicConfig, as logging.lastResort will be used by default
>>> logging.basicConfig()
>>> logging.warning('test')
WARNING:root:test
>>> sublogger = logging.getLogger('sublogger')
>>> sublogger.addHandler(logging.StreamHandler())
>>> sublogger.warning('test')
test
WARNING:sublogger:test
>>>

TESTING INSTRUCTIONS

Inspect startup log messages, trigger a log if need be.

ADDITIONAL INFORMATION

Has associated issue:
- Duplicate log messages #21646
- Not able to get the debug logs or python stacktrace on errors even after LOG_LEVEL is set to 'DEBUG' #4785
Required feature flags:
Changes UI
Includes DB Migration (follow approval process in SIP-59)
- Migration is atomic, supports rollback & is backwards-compatible
- Confirm DB migration upgrade and downgrade tested
- Runtime estimates and downtime expectations provided
Introduces new feature or API
Removes existing feature or API

superset/utils/logging_configurator.py

superset/config.py

jessie-ross · 2024-05-22T13:20:33Z

@dpgaspar Just a friendly reminder this PR is waiting for review

jessie-ross · 2024-06-20T08:13:27Z

Looks like the default log level was changed in #28134, so there should hopefully be no more points of contention.

mistercrunch · 2024-06-20T19:39:46Z

Looks like the changes from my PR aren't into this PR (more specifically this line for instance https://github.com/apache/superset/pull/28134/files#diff-c99ae4b2b09b756ab2189a99a9685229f9d12633fc2616c368ea869770f603bfR849), mind rebasing?

UPDATING.md

superset/config.py

mistercrunch · 2024-06-20T19:50:41Z

superset/utils/logging_configurator.py

@@ -41,19 +41,11 @@ def configure_logging(
        if app_config["SILENCE_FAB"]:
            logging.getLogger("flask_appbuilder").setLevel(logging.ERROR)

-        # configure superset app logger
-        superset_logger = logging.getLogger("superset")


I have to admit I don't like this section that ties a bunch of behaviors to "debug_mode" potentially overriding LOG_LEVEL. It's like some configuration flags influence one another in a way that admins can't control.

I feel this needs more thinking/refactoring.

One option would be to move the DEBUG/LOG_LEVEL entanglement into superset/config.py so people can see that day LOG_LEVEL = logging.DEBUG if DEBUG else logging.INFO and choose to override it in their superset_config.py.

Yes, I think that's a very good idea. It is technically a breaking change, but only for debug-level environments so should be acceptable.

(I can move this addition to a separate PR if it requires further discussion.)

mistercrunch · 2024-06-20T19:52:04Z

superset/utils/logging_configurator.py

-            superset_logger.setLevel(logging.DEBUG)
-        else:
-            # In production mode, add log handler to sys.stderr.
-            superset_logger.addHandler(logging.StreamHandler())


I'm unclear on what this does ^^^, but if it does anything that's not the default behavior, removing this line could affect people's production env and is a breaking change

See the PR description under "Cause of duplicate logging" - by default logging.basicConfig triggers this, so this line causes logging duplication.

jessie-ross · 2024-06-21T05:17:15Z

@mistercrunch Thanks for the quick review! I've rebased and addressed your comments.

rusackas · 2024-06-21T15:39:00Z

Re-running CI 🤞

mistercrunch · 2024-06-21T20:26:32Z

superset/config.py

@@ -1180,7 +1180,7 @@ def CSV_TO_HIVE_UPLOAD_DIRECTORY_FUNC(  # pylint: disable=invalid-name
 # Whether to bump the logging level to ERROR on the flask_appbuilder package
 # Set to False if/when debugging FAB related issues like
 # permission management
-SILENCE_FAB = True
+SILENCE_FAB = not DEBUG


Not sure if we want this, do we? I think I put that in originally because it was littering the CLI with very verbose output...

I just tried setting it to False and got hundreds of lines like:

$ superset Loaded your LOCAL configuration at [/Users/max/pythonpath/superset_config.py] 2024-06-21 13:25:21,890:WARNING:flask_appbuilder.security.manager:No user yet created, use flask fab command to do it. 2024-06-21 13:25:21,890:INFO:flask_appbuilder.base:Registering class SupersetIndexView on menu 2024-06-21 13:25:21,891:INFO:flask_appbuilder.baseviews:Registering route / ('GET',) 2024-06-21 13:25:21,891:INFO:flask_appbuilder.base:Registering class UtilView on menu 2024-06-21 13:25:21,891:INFO:flask_appbuilder.baseviews:Registering route /back ('GET',) 2024-06-21 13:25:21,891:INFO:flask_appbuilder.base:Registering class LocaleView on menu 2024-06-21 13:25:21,891:INFO:flask_appbuilder.baseviews:Registering route /lang/<string:locale> ('GET',) 2024-06-21 13:25:21,892:INFO:flask_appbuilder.base:Registering class SecurityApi on menu 2024-06-21 13:25:21,892:INFO:flask_appbuilder.api:Registering route /api/v1/security/login ['POST'] 2024-06-21 13:25:21,892:INFO:flask_appbuilder.api:Registering route /api/v1/security/refresh ['POST'] 2024-06-21 13:25:21,893:INFO:flask_appbuilder.base:Registering class ResetPasswordView on menu 2024-06-21 13:25:21,893:INFO:flask_appbuilder.baseviews:Registering route /resetpassword/form ['GET'] 2024-06-21 13:25:21,893:INFO:flask_appbuilder.baseviews:Registering route /resetpassword/form ['POST'] 2024-06-21 13:25:21,893:INFO:flask_appbuilder.base:Registering class ResetMyPasswordView on menu 2024-06-21 13:25:21,893:INFO:flask_appbuilder.baseviews:Registering route /resetmypassword/form ['GET'] 2024-06-21 13:25:21,893:INFO:flask_appbuilder.baseviews:Registering route /resetmypassword/form ['POST'] 2024-06-21 13:25:21,894:INFO:flask_appbuilder.base:Registering class UserInfoEditView on menu 2024-06-21 13:25:21,894:INFO:flask_appbuilder.baseviews:Registering route /userinfoeditview/form ['GET'] 2024-06-21 13:25:21,894:INFO:flask_appbuilder.baseviews:Registering route /userinfoeditview/form ['POST'] 2024-06-21 13:25:21,894:INFO:flask_appbuilder.base:Registering class AuthDBView on menu 2024-06-21 13:25:21,894:INFO:flask_appbuilder.baseviews:Registering route /login/ ['GET', 'POST'] 2024-06-21 13:25:21,894:INFO:flask_appbuilder.baseviews:Registering route /logout/ ('GET',) 2024-06-21 13:25:21,896:INFO:flask_appbuilder.base:Registering class UserDBModelView on menu List Users 2024-06-21 13:25:21,896:INFO:flask_appbuilder.baseviews:Registering route /users/action/<string:name>/<pk> ['GET', 'POST'] 2024-06-21 13:25:21,896:INFO:flask_appbuilder.baseviews:Registering route /users/action_post ['POST'] 2024-06-21 13:25:21,896:INFO:flask_appbuilder.baseviews:Registering route /users/add ['GET', 'POST'] 2024-06-21 13:25:21,896:INFO:flask_appbuilder.baseviews:Registering route /users/api/read ['GET'] 2024-06-21 13:25:21,896:INFO:flask_appbuilder.baseviews:Registering route /users/delete/<pk> ['GET', 'POST'] 2024-06-21 13:25:21,896:INFO:flask_appbuilder.baseviews:Registering route /users/edit/<pk> ['GET', 'POST'] 2024-06-21 13:25:21,896:INFO:flask_appbuilder.baseviews:Registering route /users/list/ ('GET',) 2024-06-21 13:25:21,896:INFO:flask_appbuilder.baseviews:Registering route /users/show/<pk> ['GET'] 2024-06-21 13:25:21,896:INFO:flask_appbuilder.baseviews:Registering route /users/userinfo/ ('GET',) 2024-06-21 13:25:21,899:INFO:flask_appbuilder.base:Registering class RoleModelView on menu List Roles 2024-06-21 13:25:21,899:INFO:flask_appbuilder.baseviews:Registering route /roles/action_post ['POST'] 2024-06-21 13:25:21,899:INFO:flask_appbuilder.baseviews:Registering route /roles/add ['GET', 'POST'] 2024-06-21 13:25:21,899:INFO:flask_appbuilder.baseviews:Registering route /roles/delete/<pk> ['GET', 'POST'] 2024-06-21 13:25:21,899:INFO:flask_appbuilder.baseviews:Registering route /roles/edit/<pk> ['GET', 'POST'] 2024-06-21 13:25:21,899:INFO:flask_appbuilder.baseviews:Registering route /roles/list/ ('GET',) 2024-06-21 13:25:21,899:INFO:flask_appbuilder.baseviews:Registering route /roles/show/<pk> ['GET']

mistercrunch

LGTM outside of the SILENCE_FAB change, let's keep it False!

codecov · 2024-06-25T09:52:56Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 83.75%. Comparing base (76d897e) to head (34007cc).
Report is 357 commits behind head on master.

Additional details and impacted files

@@             Coverage Diff             @@
##           master   #27777       +/-   ##
===========================================
+ Coverage   60.48%   83.75%   +23.26%     
===========================================
  Files        1931      518     -1413     
  Lines       76236    37617    -38619     
  Branches     8568        0     -8568     
===========================================
- Hits        46114    31505    -14609     
+ Misses      28017     6112    -21905     
+ Partials     2105        0     -2105

Flag	Coverage Δ
hive	`48.90% <ø> (-0.27%)`	⬇️
javascript	`?`
mysql	`77.29% <ø> (?)`
postgres	`77.40% <ø> (?)`
presto	`53.50% <ø> (-0.30%)`	⬇️
python	`83.75% <ø> (+20.26%)`	⬆️
sqlite	`76.85% <ø> (?)`
unit	`59.20% <ø> (+1.57%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

mistercrunch

Awesome, thanks for the contribution!

pull-request-size bot added the size/S label Mar 29, 2024

jessie-ross changed the title ~~fix: Duplicate logging~~ fix: Fix default logging Mar 29, 2024

jessie-ross commented Mar 29, 2024

View reviewed changes

superset/utils/logging_configurator.py Show resolved Hide resolved

jessie-ross changed the title ~~fix: Fix default logging~~ fix: default logging Mar 29, 2024

john-bodley reviewed Mar 29, 2024

View reviewed changes

superset/utils/logging_configurator.py Show resolved Hide resolved

superset/config.py Outdated Show resolved Hide resolved

drummerwolli mentioned this pull request Apr 17, 2024

Duplicate log messages #21646

Closed

rusackas requested a review from dpgaspar April 18, 2024 15:34

jessie-ross mentioned this pull request Jun 20, 2024

chore: clean up console upon firing up the CLI #28134

Merged

mistercrunch reviewed Jun 20, 2024

View reviewed changes

UPDATING.md Outdated Show resolved Hide resolved

mistercrunch reviewed Jun 20, 2024

View reviewed changes

superset/config.py Outdated Show resolved Hide resolved

mistercrunch reviewed Jun 20, 2024

View reviewed changes

jessie-ross added 2 commits June 21, 2024 11:57

Simplify logging

ed26bf1

Remove unneeded logging.setLevel for pyhive.presto

527aa05

jessie-ross force-pushed the fix/duplicate-log-messages branch 2 times, most recently from 15ff439 to 527aa05 Compare June 21, 2024 05:03

Move debug logging logic to config.py

1f808f3

jessie-ross force-pushed the fix/duplicate-log-messages branch from 0bc54dc to 1f808f3 Compare June 21, 2024 05:14

Add UPDATING instruction.

22ae88f

mistercrunch reviewed Jun 21, 2024

View reviewed changes

mistercrunch requested changes Jun 21, 2024

View reviewed changes

Silence FAB logging

34007cc

jessie-ross requested a review from mistercrunch June 25, 2024 10:01

mistercrunch approved these changes Jun 25, 2024

View reviewed changes

mistercrunch merged commit d74d3a8 into apache:master Jun 25, 2024
37 checks passed

eschutho pushed a commit that referenced this pull request Jul 24, 2024

fix: default logging (#27777)

6e63b45

eschutho mentioned this pull request Sep 7, 2024

logger superset in production mode writing logs to stderr confuses logging service in Google Cloud #30135

Open

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: default logging #27777

fix: default logging #27777

jessie-ross commented Mar 29, 2024 •

edited

Loading

jessie-ross commented May 22, 2024

jessie-ross commented Jun 20, 2024

mistercrunch commented Jun 20, 2024

mistercrunch Jun 20, 2024

jessie-ross Jun 21, 2024

jessie-ross Jun 21, 2024

mistercrunch Jun 20, 2024

jessie-ross Jun 21, 2024

jessie-ross commented Jun 21, 2024

rusackas commented Jun 21, 2024

mistercrunch Jun 21, 2024

mistercrunch left a comment

codecov bot commented Jun 25, 2024 •

edited

Loading

mistercrunch left a comment

fix: default logging #27777

fix: default logging #27777

Conversation

jessie-ross commented Mar 29, 2024 • edited Loading

SUMMARY

Cause of duplicate logging:

TESTING INSTRUCTIONS

ADDITIONAL INFORMATION

jessie-ross commented May 22, 2024

jessie-ross commented Jun 20, 2024

mistercrunch commented Jun 20, 2024

mistercrunch Jun 20, 2024

Choose a reason for hiding this comment

jessie-ross Jun 21, 2024

Choose a reason for hiding this comment

jessie-ross Jun 21, 2024

Choose a reason for hiding this comment

mistercrunch Jun 20, 2024

Choose a reason for hiding this comment

jessie-ross Jun 21, 2024

Choose a reason for hiding this comment

jessie-ross commented Jun 21, 2024

rusackas commented Jun 21, 2024

mistercrunch Jun 21, 2024

Choose a reason for hiding this comment

mistercrunch left a comment

Choose a reason for hiding this comment

codecov bot commented Jun 25, 2024 • edited Loading

Codecov Report

mistercrunch left a comment

Choose a reason for hiding this comment

jessie-ross commented Mar 29, 2024 •

edited

Loading

codecov bot commented Jun 25, 2024 •

edited

Loading