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

correcting logic to discern the lowest logging level #71

Merged
merged 5 commits into from
Jan 27, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
129 changes: 98 additions & 31 deletions thespian/system/multiprocCommon.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,24 +2,20 @@
python 'multiprocess' module. Intended as a base class, not for
direct usage."""

import signal
import sys
from functools import partial

import logging
from thespian.actors import *
from thespian.system.systemBase import systemBase
from thespian.system.systemCommon import actorStartupFailed
from thespian.system.utilis import thesplog, checkActorCapabilities, partition
from thespian.system.transport import *
from thespian.system.logdirector import *
from thespian.system.utilis import setProcName, StatsManager
from thespian.system.addressManager import ActorLocalAddress, CannotPickleAddress
from thespian.system.logdirector import *
from thespian.system.messages.multiproc import *
from thespian.system.sourceLoader import loadModuleFromHashSource
from functools import partial
import multiprocessing
import signal
from datetime import timedelta
import sys

from thespian.system.systemBase import systemBase
from thespian.system.systemCommon import actorStartupFailed
from thespian.system.transport import *
from thespian.system.utilis import checkActorCapabilities, partition
from thespian.system.utilis import setProcName, _name_to_level

MAX_ADMIN_STARTUP_DELAY = timedelta(seconds=5)

Expand Down Expand Up @@ -512,6 +508,94 @@ def shutdown_signal_detected(signum, frame):
return shutdown_signal_detected


def get_min_log_level(logDefs):
"""
Determine the minimum logging level based on the rules in:
https://docs.python.org/3/library/logging.config.html#logging.config.dictConfig

Note: The level and handlers entries are interpreted as for the root logger,
except that if a non-root logger's level is specified as NOTSET, the system
consults loggers higher up the hierarchy to determine the effective
level of the logger.

:param logDefs: a logging configuration dictionary object
:return: integer value of the lowest log level, or the default level: logging.WARNING.

>>> import logging
>>> import logging.config
>>> logDefs = {'version': 1, 'handlers': {
... 'h1': {'class': 'logging.FileHandler', 'filename': 'example.log', 'filters': [],
... 'level': "INFO"},
... 'h2': {'class': 'logging.FileHandler', 'filename': 'example.log', 'filters': [],
... 'level': "INFO"}}, 'loggers': {'': {'handlers': ['h1', 'h2'], 'level': "DEBUG"}}}
>>> logging.config.dictConfig(logDefs) # prove the config is considered valid
>>> get_min_log_level(logDefs) # logging.DEBUG
10

>>> logDefs = {'version': 1, 'root': {'level': 10}, 'loggers': {'one': {'level': 20}}}
>>> logging.config.dictConfig(logDefs)
>>> min1 = get_min_log_level(logDefs)
>>> logDefs = {'version': 1, 'root': {'level': 20}, 'loggers': {'one': {'level': 10}}}
>>> logging.config.dictConfig(logDefs)
>>> min2 = get_min_log_level(logDefs)
>>> min1 == min2 == 10
True

>>> get_min_log_level({'version' : 1}) # logging.WARNING is default log level
30

>>> logDefs = {'version': 1,
... 'loggers': {'root': {'level': "INFO"}, 'handler2': {'level': logging.NOTSET}}}
>>> logging.config.dictConfig(logDefs)
>>> get_min_log_level(logDefs) # logging.INFO
20

>>> logDefs = {'version': 1, 'loggers': {'one': {'level': logging.NOTSET}}}
>>> logging.config.dictConfig(logDefs)
>>> get_min_log_level(logDefs) # logging.WARNING
30

>>> logDefs = {'version': 1,
... 'root': {'level': None},
... 'loggers': {'one': {'level': logging.NOTSET}}}
>>> logging.config.dictConfig(logDefs)
>>> get_min_log_level(logDefs) # logging.WARNING
30

"""

levels = []
root_data = logDefs.get('root')
if root_data and root_data.get('level'):
if isinstance( root_data.get('level'), str):
root_val = _name_to_level.get(root_data.get('level'). upper())
else:
root_val = root_data.get('level')
else:
loggers = logDefs.get('loggers', {})
root_val_empty = loggers.get("", {}).get("level")
root_val_named = loggers.get("root", {}).get("level")
root_val = root_val_empty if root_val_empty else root_val_named
if root_val:
root_val = _name_to_level.get(root_val, root_val)

def dfs(mapping):
"""Traverse and collect"""
for key, val in mapping.items():
if isinstance(val, dict):
dfs(val)
if key == 'level':
if isinstance(val, str):
val = _name_to_level[val.upper()]
if val == logging.NOTSET and root_val and root_val > logging.NOTSET:
Copy link
Owner

Choose a reason for hiding this comment

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

It seems to me that this should exclude all NOTSET values, irrespective of root_val, since allowing any NOTSET would result in a return value of 0 if there was no root_val specified.

Also, the code for setting root_val does not ensure that root_val is numeric: it could be None, or it could be an unrecognized string like "MyLevel", which would cause the > comparison to throw a TypeError exception.

If there's no comparison to root_val here, then the reduction would lead to removing root_val as a variable and just putting the result of the corresponding expression in the levels array.

Let me know if you disagree with my analysis here or if there's something I've missed.

Copy link
Author

Choose a reason for hiding this comment

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

NOTSET is useful because the default logging level is warning. If somebody writes some library code and configs the logs somewhere and specifies NOTSET, it does log everything, but if a root logger specifies a level then it supercedes the NOTSET value. But if a logging config had all NOTSET values, and we discarded them, then the configured logging level would default to WARNING, which seems to violate the principle of least surprise.

Also, it looks like root value can be none:

logDefs = {'version': 1, 'root': {'level': 10}, 'loggers': {'one': {'level': 20}}}
logDefs2 = {'version': 1, 'root': None, 'loggers': {'one': {'level': 20}}}
logging.config.dictConfig(logDefs)
logging.config.dictConfig(logDefs2)

I like this validation, so I added it to the doctests.

Copy link
Author

Choose a reason for hiding this comment

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

I've adjusted the logic. Invalid strings blow up the underlying Python API, so I think that error is fair game.

Copy link
Owner

Choose a reason for hiding this comment

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

I like those two logDefs as well, although I don't see that you added them to the doctests.

I agree on the unrecognized strings issue, it's reasonable to have similar behavior.

I'm not seeing behavior where NOTSET logs everything. See https://gist.github.com/kquick/d554a8b4de5541eb48c0bc1b14080fff which is careful to run a separate python for each configuration. I believe the last output set is the case you indicated should log everything but I see only WARNING and ERROR logging from that output (shown in this gist: https://gist.github.com/kquick/98eac6e6c55fa14fe3fbb19d671ed4b2)

These are the two cases that will still fail:

>>> logDefs = {'version': 1,
...             'root': {'level': None},
...            'loggers': {'one': {'level': logging.NOTSET}}}
>>> logging.config.dictConfig(logDefs)
>>> get_min_log_level(logDefs) == logging.WARNING
True

>>> logDefs = {'version': 1,
...            'loggers': {'one': {'level': logging.NOTSET}}}
>>> logging.config.dictConfig(logDefs)
>>> get_min_log_level(logDefs) == logging.WARNING
True

Copy link
Author

Choose a reason for hiding this comment

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

NOTSET on the root level logs everything, but NOTSET on another level besides root, logs at the root level, and if unintialized the logging level goes to WARNING.
I added a 6th test case to your gist that I co-opted.
https://gist.github.com/todd-cook/883662ba19eb5a3bb8b372733ec7f6a4

Copy link
Author

Choose a reason for hiding this comment

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

Copy link
Owner

Choose a reason for hiding this comment

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

So many different combinations and effects! The latest get_min_log_level in this PR will return the wrong value for case 4 and case 5 if you add those to the doctests.

Also, you can change the doctests from:

>>> get_min_log_level(logDevs) == logging.WARNING
True

to the following which will provide more information for when the tests fail:

>>> get_min_log_level(logDefs)
30

continue
levels.append(val)

dfs(logDefs)
levels = [tmp for tmp in levels if tmp] # swallow None values
return min(levels) if levels else logging.WARNING


def startChild(childClass, globalName, endpoint, transportClass,
sourceHash, sourceToLoad,
parentAddr, adminAddr, notifyAddr, loggerAddr,
Expand Down Expand Up @@ -544,24 +628,7 @@ def startChild(childClass, globalName, endpoint, transportClass,
# logging.shutdown() because (a) that does not do enough to reset,
# and (b) it shuts down handlers, but we want to leave the parent's
# handlers alone.
if logDefs:
levelIn = lambda d: d.get('level', 0)
minLevelIn = lambda l: min(list(l)) if list(l) else 0
levels = list(
filter(None,
([ minLevelIn([levelIn(logDefs[key][subkey])
for subkey in logDefs[key]
# if subkey in [ 'loggers', 'handlers'
if isinstance(logDefs[key][subkey], dict)
])
if key in ['loggers', 'handlers'] and isinstance(logDefs[key], dict)
else (levelIn(logDefs[key]) if key == 'root'
else (logDefs[key] if key == 'level'
else None))
todd-cook marked this conversation as resolved.
Show resolved Hide resolved
for key in logDefs ])))
lowestLevel = minLevelIn(levels)
else:
lowestLevel = 0
lowestLevel = get_min_log_level(logDefs)
logging.root = ThespianLogForwarder(loggerAddr, transport, logLevel=lowestLevel)
logging.Logger.root = logging.root
logging.Logger.manager = logging.Manager(logging.Logger.root)
Expand Down
3 changes: 2 additions & 1 deletion thespian/system/utilis.py
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,8 @@
"ERROR": logging.ERROR,
"WARNING": logging.WARNING,
"INFO": logging.INFO,
"DEBUG": logging.DEBUG
"DEBUG": logging.DEBUG,
"NOTSET": logging.NOTSET
}

# Default/current logging controls
Expand Down