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

feat: Added a include_callsite_parameters argument to the builtin log formatters, which adds source path, line number and function name fields to the emitted log #8494

Draft
wants to merge 4 commits into
base: main
Choose a base branch
from
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
1 change: 1 addition & 0 deletions docs/docs/guide/logging.md
Original file line number Diff line number Diff line change
Expand Up @@ -54,6 +54,7 @@ formatters:
sort_keys: False
json: # log format for json formatted logs
(): meltano.core.logging.json_formatter
include_callsite_parameters: true # adds `pathname`, `lineno`, and `func_name` to each log entry

handlers:
console: # log to the console (stderr) using structured_colored formatter, logging everything at DEBUG level and up
Expand Down
4 changes: 2 additions & 2 deletions integration/meltano-run/validate.sh
Original file line number Diff line number Diff line change
Expand Up @@ -7,9 +7,9 @@ LOG_FILE="./integration/example-library/meltano-run/integration-test.log"
# Custom validations for the `meltano-run` guide/test.

# test that meltano run saw dbt:test (set=1) as successfully completed
grep "Block run completed. block_type=InvokerCommand err=None set_number=1 success=True" $LOG_FILE
grep "Block run completed. block_type=InvokerCommand.*err=None.*set_number=1.*success=True" $LOG_FILE
# test that we see dbt:run output
grep "Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1 cmd_type=command name=dbt-postgres stdio=stderr" $LOG_FILE
grep "Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1 cmd_type=command.*name=dbt-postgres.*stdio=stderr" $LOG_FILE

# we could also run psql statements
# check for the existance of files
Expand Down
51 changes: 46 additions & 5 deletions src/meltano/core/logging/formatters.py
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,7 @@

TIMESTAMPER = structlog.processors.TimeStamper(fmt="iso")

LEVELED_TIMESTAMPED_PRE_CHAIN = (
LEVELED_TIMESTAMPED_PRE_CHAIN: t.Sequence[Processor] = (
# Add the log level and a timestamp to the event_dict if the log entry
# is not from structlog.
structlog.stdlib.add_log_level,
Expand Down Expand Up @@ -63,7 +63,11 @@ def _traceback(
return _traceback


def _process_formatter(processor: Processor) -> structlog.stdlib.ProcessorFormatter:
def _process_formatter(
processor: Processor,
*,
include_callsite_parameters: bool = False,
) -> structlog.stdlib.ProcessorFormatter:
"""Use _process_formatter to configure a structlog.stdlib.ProcessFormatter.

It will automatically add log level and timestamp fields to any log entries
Expand All @@ -72,25 +76,46 @@ def _process_formatter(processor: Processor) -> structlog.stdlib.ProcessorFormat
Args:
processor: A structlog message processor such as
`structlog.dev.ConsoleRenderer`.
include_callsite_parameters: Whether to include callsite parameters in
the output.

Returns:
A configured log processor.
"""
foreign_pre_chain = LEVELED_TIMESTAMPED_PRE_CHAIN

if include_callsite_parameters:
foreign_pre_chain = ( # noqa: WPS434
*foreign_pre_chain,
structlog.processors.CallsiteParameterAdder(
# Most folks probably don't need thread and process process IDs, so
# these three should be enough to start with.
parameters=(
structlog.processors.CallsiteParameter.PATHNAME,
structlog.processors.CallsiteParameter.LINENO,
structlog.processors.CallsiteParameter.FUNC_NAME,
),
),
)

return structlog.stdlib.ProcessorFormatter(
processor=processor,
foreign_pre_chain=LEVELED_TIMESTAMPED_PRE_CHAIN,
foreign_pre_chain=foreign_pre_chain,
)


def console_log_formatter(
colors: bool = False,
show_locals: bool = False,
include_callsite_parameters: bool = False,
) -> structlog.stdlib.ProcessorFormatter:
"""Create a logging formatter for console rendering that supports colorization.

Args:
colors: Add color to output.
show_locals: Whether to show local variables in the traceback.
include_callsite_parameters: Whether to include callsite parameters in
the console output.

Returns:
A configured console log formatter.
Expand All @@ -113,13 +138,16 @@ def console_log_formatter(
colors=colors,
exception_formatter=exception_formatter,
),
include_callsite_parameters=include_callsite_parameters,
)


def key_value_formatter(
sort_keys: bool = False,
key_order: t.Sequence[str] | None = None,
drop_missing: bool = False,
*,
include_callsite_parameters: bool = False,
) -> structlog.stdlib.ProcessorFormatter:
"""Create a logging formatter that renders lines in key=value format.

Expand All @@ -130,6 +158,8 @@ def key_value_formatter(
*sort_keys* and the dict class.
drop_missing: When True, extra keys in *key_order* will be dropped
rather than rendered as None.
include_callsite_parameters: Whether to include callsite parameters in
the key=value output.

Returns:
A configured key=value formatter.
Expand All @@ -140,13 +170,24 @@ def key_value_formatter(
key_order=key_order,
drop_missing=drop_missing,
),
include_callsite_parameters=include_callsite_parameters,
)


def json_formatter() -> structlog.stdlib.ProcessorFormatter:
def json_formatter(
*,
include_callsite_parameters: bool = False,
) -> structlog.stdlib.ProcessorFormatter:
"""Create a logging formatter that renders lines in JSON format.

Args:
include_callsite_parameters: Whether to include callsite parameters in
the JSON output.

Returns:
A configured JSON formatter.
"""
return _process_formatter(processor=structlog.processors.JSONRenderer())
return _process_formatter(
processor=structlog.processors.JSONRenderer(),
include_callsite_parameters=include_callsite_parameters,
)
9 changes: 9 additions & 0 deletions src/meltano/core/logging/utils.py
Original file line number Diff line number Diff line change
Expand Up @@ -149,6 +149,15 @@ def setup_logging( # noqa: WPS210
structlog.stdlib.add_log_level,
structlog.stdlib.PositionalArgumentsFormatter(),
TIMESTAMPER,
structlog.processors.CallsiteParameterAdder(
# Most folks probably don't need thread and process process IDs, so
# these three should be enough to start with.
parameters=(
structlog.processors.CallsiteParameter.PATHNAME,
structlog.processors.CallsiteParameter.LINENO,
structlog.processors.CallsiteParameter.FUNC_NAME,
),
),
structlog.processors.StackInfoRenderer(),
structlog.processors.format_exc_info,
structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
Expand Down
14 changes: 12 additions & 2 deletions tests/meltano/core/logging/test_formatters.py
Original file line number Diff line number Diff line change
@@ -1,13 +1,14 @@
from __future__ import annotations

import json
import logging
import re
import typing as t
from types import TracebackType

import pytest

from meltano.core.logging.formatters import console_log_formatter
from meltano.core.logging.formatters import console_log_formatter, json_formatter

if t.TYPE_CHECKING:
from pathlib import Path
Expand Down Expand Up @@ -55,11 +56,12 @@ def record(self):
return logging.LogRecord(
name="test",
level=logging.INFO,
pathname="test",
pathname="/path/to/my_module.py",
lineno=1,
msg="test",
args=None,
exc_info=None,
func="my_func",
)

@pytest.fixture()
Expand Down Expand Up @@ -114,3 +116,11 @@ def test_console_log_formatter_show_locals(self, record_with_exception):
output = formatter.format(record_with_exception)
assert "locals" in output
assert "my_var = 'my_value'" in output

def test_json_formatter_callsite_parameters(self, record):
formatter = json_formatter(include_callsite_parameters=True)
output = formatter.format(record)
message_dict = json.loads(output)
assert message_dict["pathname"] == "/path/to/my_module.py"
assert message_dict["lineno"] == 1
assert message_dict["func_name"] == "my_func"