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.

Sign up for GitHub

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

Jump to bottom

Check a dict passed to ProcessorFormatter actually came from structlog. #188

Closed
wants to merge 2 commits into from
Closed

Check a dict passed to ProcessorFormatter actually came from structlog. #188

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
4ef6fc0
Add a failing test for when a dictionary is passed to Python logging.
wrouesnel Nov 23, 2018
08aad10
Check a dict passed to ProcessorFormatter actually came from structlog.
wrouesnel Nov 23, 2018
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
6 changes: 5 additions & 1 deletion src/structlog/stdlib.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -451,7 +451,11 @@ def format(self, record):
# Make a shallow copy of the record to let other handlers/formatters
# process the original one
record = logging.makeLogRecord(record.__dict__)
if isinstance(record.msg, dict):
if (
isinstance(record.msg, dict)
and hasattr(record, "_logger")
Copy link
Owner

Choose a reason for hiding this comment

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

Please meet: https://hynek.me/articles/hasattr/ :)

If we pile on checks and assume that dicts are predominant, why don't we invert the whole thing and make it an try:…except (KeyError, AttributeError)? I reckon that’s considered more pythonic too.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I would argue when you have the ProcessorLogger in the mix, dicts and strs aren't predominant one way or the other, so a try...except seems unnecessarily slow.

I wonder if instead the wrapper should convert LogRecord into WrappedLogRecord and just do a type-check since ultimately what we're looking for is a different object type.

Copy link
Owner

Choose a reason for hiding this comment

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

try...except seems unnecessarily slow.

Hm, do you really think it's slower than multiple checks on each record? I think I'd like to see a benchmark on that since this is is hot code. If you have some spare it would be great if you could compare it using https://pypi.org/project/perf/ . I only care about modern Python versions FWIW.

I wonder if instead the wrapper should convert LogRecord into WrappedLogRecord and just do a type-check since ultimately what we're looking for is a different object type.

That sound clean, but really slow? 🤔

Sorry I'm being so anal about performance here but I take great pride that structlog isn't a handbrake like logging and I'd like it to stay that way. 😇

Copy link
Contributor Author

Choose a reason for hiding this comment

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

No I agree about keeping it quick. I'll setup some tests.

Copy link
Owner

Choose a reason for hiding this comment

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

Awesome thank you and sorry for the delay. My original plan was to run them myself but just didn't get around to it.

and hasattr(record, "_name")
):
# Both attached by wrap_for_formatter
logger = record._logger
meth_name = record._name
Expand Down
21 changes: 21 additions & 0 deletions tests/test_stdlib.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -479,6 +479,27 @@ class TestProcessorFormatter(object):
These are all integration tests because they're all about integration.
"""

def test_foreign_chain_can_pass_dictionaries_without_excepting(
self, configure_for_pf, capsys
):
"""
If a foreign logger passes a dictionary to a logging function,
check we correctly identify that it did not come from structlog.
"""
configure_logging(None)
configure(
processors=[ProcessorFormatter.wrap_for_formatter],
logger_factory=LoggerFactory(),
wrapper_class=BoundLogger,
)

logging.getLogger().warning({"foo": "bar"})

assert (
"",
"{'foo': 'bar'} [in test_foreign_chain_can_pass_dictionaries_without_excepting]\n",
) == capsys.readouterr()

def test_foreign_delegate(self, configure_for_pf, capsys):
"""
If foreign_pre_chain is None, non-structlog log entries are delegated
Expand Down