diff --git a/newrelic/common/encoding_utils.py b/newrelic/common/encoding_utils.py index ed7dc3a15..3b7a519a2 100644 --- a/newrelic/common/encoding_utils.py +++ b/newrelic/common/encoding_utils.py @@ -80,7 +80,7 @@ def json_encode(obj, **kwargs): # The third is eliminate white space after separators to trim the # size of the data being sent. - if type(b"") is type(""): # NOQA + if type(b"") is type(""): # noqa, pylint: disable=C0123 _kwargs["encoding"] = "latin-1" def _encode(o): @@ -267,7 +267,7 @@ def generate_path_hash(name, seed): if not isinstance(name, bytes): name = name.encode("UTF-8") - path_hash = rotated ^ int(hashlib.md5(name).hexdigest()[-8:], base=16) + path_hash = rotated ^ int(hashlib.md5(name).hexdigest()[-8:], base=16) # nosec return "%08x" % path_hash diff --git a/newrelic/hooks/logger_logging.py b/newrelic/hooks/logger_logging.py index 80cf0fd24..7b320cd91 100644 --- a/newrelic/hooks/logger_logging.py +++ b/newrelic/hooks/logger_logging.py @@ -12,14 +12,11 @@ # See the License for the specific language governing permissions and # limitations under the License. -from logging import Formatter, LogRecord - from newrelic.api.application import application_instance from newrelic.api.time_trace import get_linking_metadata from newrelic.api.transaction import current_transaction, record_log_event from newrelic.common.object_wrapper import function_wrapper, wrap_function_wrapper from newrelic.core.config import global_settings -from newrelic.packages import six try: from urllib import quote @@ -27,7 +24,7 @@ from urllib.parse import quote -DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(LogRecord("", 0, "", 0, "", (), None))) | {"message"}) +IGNORED_LOG_RECORD_KEYS = set(["message", "msg"]) def add_nr_linking_metadata(message): @@ -52,15 +49,6 @@ def bind_callHandlers(record): return record -def filter_record_attributes(record): - record_attrs = vars(record) - custom_attr_keys = set(record_attrs.keys()) - DEFAULT_LOG_RECORD_KEYS - if custom_attr_keys: - return {k: record_attrs[k] for k in custom_attr_keys if k not in DEFAULT_LOG_RECORD_KEYS} - else: - return None - - def wrap_callHandlers(wrapped, instance, args, kwargs): transaction = current_transaction() record = bind_callHandlers(*args, **kwargs) @@ -89,10 +77,17 @@ def wrap_callHandlers(wrapped, instance, args, kwargs): if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: try: - message = record.getMessage() - attrs = filter_record_attributes(record) + message = record.msg + if not isinstance(message, dict): + # Allow python to convert the message to a string and template it with args. + message = record.getMessage() + + # Grab and filter context attributes from log record + record_attrs = vars(record) + context_attrs = {k: record_attrs[k] for k in record_attrs if k not in IGNORED_LOG_RECORD_KEYS} + record_log_event( - message=message, level=level_name, timestamp=int(record.created * 1000), attributes=attrs + message=message, level=level_name, timestamp=int(record.created * 1000), attributes=context_attrs ) except Exception: pass diff --git a/setup.cfg b/setup.cfg index 006265c36..8a41f1534 100644 --- a/setup.cfg +++ b/setup.cfg @@ -5,4 +5,4 @@ license_files = [flake8] max-line-length = 120 -extend-ignore = E122,E126,E127,E128,E203,E501,E722,F841,W504,E731 +extend-ignore = E122,E126,E127,E128,E203,E501,E722,F841,W504,E731,F811 diff --git a/tests/logger_logging/conftest.py b/tests/logger_logging/conftest.py index 46e8f4ec3..4e308eedf 100644 --- a/tests/logger_logging/conftest.py +++ b/tests/logger_logging/conftest.py @@ -13,10 +13,12 @@ # limitations under the License. import logging -import pytest - -from testing_support.fixtures import collector_agent_registration_fixture, collector_available_fixture # noqa: F401; pylint: disable=W0611 +import pytest +from testing_support.fixtures import ( # noqa: F401; pylint: disable=W0611 + collector_agent_registration_fixture, + collector_available_fixture, +) _default_settings = { "transaction_tracer.explain_threshold": 0.0, @@ -26,6 +28,7 @@ "debug.record_transaction_failure": True, "application_logging.enabled": True, "application_logging.forwarding.enabled": True, + "application_logging.forwarding.context_data.enabled": True, "application_logging.metrics.enabled": True, "application_logging.local_decorating.enabled": True, "event_harvest_config.harvest_limits.log_event_data": 100000, @@ -42,6 +45,7 @@ class CaplogHandler(logging.StreamHandler): To prevent possible issues with pytest's monkey patching use a custom Caplog handler to capture all records """ + def __init__(self, *args, **kwargs): self.records = [] super(CaplogHandler, self).__init__(*args, **kwargs) diff --git a/tests/logger_logging/test_attribute_forwarding.py b/tests/logger_logging/test_attribute_forwarding.py deleted file mode 100644 index eea549e70..000000000 --- a/tests/logger_logging/test_attribute_forwarding.py +++ /dev/null @@ -1,65 +0,0 @@ -# Copyright 2010 New Relic, Inc. -# -# Licensed under the Apache License, Version 2.0 (the "License"); -# you may not use this file except in compliance with the License. -# You may obtain a copy of the License at -# -# http://www.apache.org/licenses/LICENSE-2.0 -# -# Unless required by applicable law or agreed to in writing, software -# distributed under the License is distributed on an "AS IS" BASIS, -# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -# See the License for the specific language governing permissions and -# limitations under the License. - -from testing_support.fixtures import ( - override_application_settings, - reset_core_stats_engine, -) -from testing_support.validators.validate_log_event_count import validate_log_event_count -from testing_support.validators.validate_log_event_count_outside_transaction import ( - validate_log_event_count_outside_transaction, -) -from testing_support.validators.validate_log_events import validate_log_events -from testing_support.validators.validate_log_events_outside_transaction import ( - validate_log_events_outside_transaction, -) - -from newrelic.api.background_task import background_task - -_event_attributes = {"message": "A", "context.key": "value"} - - -def exercise_logging(logger): - logger.error("A", extra={"key": "value"}) - assert len(logger.caplog.records) == 1 - - -@override_application_settings( - { - "application_logging.forwarding.context_data.enabled": True, - } -) -def test_attributes_inside_transaction(logger): - @validate_log_events([_event_attributes]) - @validate_log_event_count(1) - @background_task() - def test(): - exercise_logging(logger) - - test() - - -@reset_core_stats_engine() -@override_application_settings( - { - "application_logging.forwarding.context_data.enabled": True, - } -) -def test_attributes_outside_transaction(logger): - @validate_log_events_outside_transaction([_event_attributes]) - @validate_log_event_count_outside_transaction(1) - def test(): - exercise_logging(logger) - - test() diff --git a/tests/logger_logging/test_attributes.py b/tests/logger_logging/test_attributes.py new file mode 100644 index 000000000..2a8240e12 --- /dev/null +++ b/tests/logger_logging/test_attributes.py @@ -0,0 +1,90 @@ +# Copyright 2010 New Relic, Inc. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import pytest +from testing_support.validators.validate_log_event_count import validate_log_event_count +from testing_support.validators.validate_log_events import validate_log_events + +from newrelic.api.background_task import background_task +from newrelic.packages import six + + +@validate_log_events( + [ + { # Fixed attributes + "message": "context_attrs: arg1", + "context.args": "('arg1',)", + "context.filename": "test_attributes.py", + "context.funcName": "test_logging_default_context_attributes", + "context.levelname": "ERROR", + "context.levelno": 40, + "context.module": "test_attributes", + "context.name": "my_app", + "context.pathname": str(__file__), + "context.processName": "MainProcess", + "context.threadName": "MainThread", + } + ], + required_attrs=[ # Variable attributes + "context.created", + "context.lineno", + "context.msecs", + "context.process", + "context.relativeCreated", + "context.thread", + ], +) +@validate_log_event_count(1) +@background_task() +def test_logging_default_context_attributes(logger): + logger.error("context_attrs: %s", "arg1") + + +@validate_log_events([{"message": "extras", "context.extra_attr": 1}]) +@validate_log_event_count(1) +@background_task() +def test_logging_extra_attributes(logger): + logger.error("extras", extra={"extra_attr": 1}) + + +@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exc_info", "context.exc_text"]) +@validate_log_event_count(1) +@background_task() +def test_logging_exc_info_context_attributes(logger): + try: + raise RuntimeError("Oops") + except Exception: + logger.error("exc_info", exc_info=True) + + +@pytest.mark.skipif(six.PY2, reason="stack_info on log messages not available in Python 2.") +@validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack_info"]) +@validate_log_event_count(1) +@background_task() +def test_logging_stack_info_context_attributes(logger): + logger.error("stack_info", stack_info=True) + + +@validate_log_events([{"message": "A", "message.attr": 1}]) +@validate_log_event_count(1) +@background_task() +def test_logging_dict_message_and_attributes(logger): + logger.error({"message": "A", "attr": 1}) + + +@validate_log_events([{"message.attr": 1}]) +@validate_log_event_count(1) +@background_task() +def test_logging_dict_attributes_only(logger): + logger.error({"attr": 1}) diff --git a/tests/logger_logging/test_local_decorating.py b/tests/logger_logging/test_local_decorating.py index d4917eff5..7b420375c 100644 --- a/tests/logger_logging/test_local_decorating.py +++ b/tests/logger_logging/test_local_decorating.py @@ -35,10 +35,10 @@ def set_trace_ids(): trace.guid = "abcdefgh" -def exercise_logging(logger): +def exercise_logging(logger, message="C"): set_trace_ids() - logger.warning("C") + logger.warning(message) def get_metadata_string(log_message, is_txn): @@ -82,3 +82,14 @@ def test(): assert logger.caplog.records[0] == get_metadata_string("C", False) test() + + +@reset_core_stats_engine() +def test_local_log_decoration_dict_message(logger): + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging(logger, {"message": "dict_message"}) + assert logger.caplog.records[0] == get_metadata_string("{'message': 'dict_message'}", True) + + test() diff --git a/tests/logger_logging/test_log_forwarding.py b/tests/logger_logging/test_log_forwarding.py index ee6c689b7..e9effdee4 100644 --- a/tests/logger_logging/test_log_forwarding.py +++ b/tests/logger_logging/test_log_forwarding.py @@ -14,14 +14,19 @@ import logging -from newrelic.api.background_task import background_task -from newrelic.api.time_trace import current_trace -from newrelic.api.transaction import current_transaction from testing_support.fixtures import reset_core_stats_engine from testing_support.validators.validate_log_event_count import validate_log_event_count -from testing_support.validators.validate_log_event_count_outside_transaction import validate_log_event_count_outside_transaction +from testing_support.validators.validate_log_event_count_outside_transaction import ( + validate_log_event_count_outside_transaction, +) from testing_support.validators.validate_log_events import validate_log_events -from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction +from testing_support.validators.validate_log_events_outside_transaction import ( + validate_log_events_outside_transaction, +) + +from newrelic.api.background_task import background_task +from newrelic.api.time_trace import current_trace +from newrelic.api.transaction import current_transaction def set_trace_ids(): @@ -32,6 +37,7 @@ def set_trace_ids(): if trace: trace.guid = "abcdefgh" + def exercise_logging(logger): set_trace_ids() @@ -39,16 +45,22 @@ def exercise_logging(logger): logger.info("B") logger.warning("C") logger.error("D") - logger.critical("E") - + logger.critical({"message": "E"}) + assert len(logger.caplog.records) == 3 + def update_all(events, attrs): for event in events: event.update(attrs) -_common_attributes_service_linking = {"timestamp": None, "hostname": None, "entity.name": "Python Agent Test (logger_logging)", "entity.guid": None} +_common_attributes_service_linking = { + "timestamp": None, + "hostname": None, + "entity.name": "Python Agent Test (logger_logging)", + "entity.guid": None, +} _common_attributes_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"} _common_attributes_trace_linking.update(_common_attributes_service_linking) @@ -60,14 +72,11 @@ def update_all(events, attrs): update_all(_test_logging_inside_transaction_events, _common_attributes_trace_linking) +@validate_log_events(_test_logging_inside_transaction_events) +@validate_log_event_count(3) +@background_task() def test_logging_inside_transaction(logger): - @validate_log_events(_test_logging_inside_transaction_events) - @validate_log_event_count(3) - @background_task() - def test(): - exercise_logging(logger) - - test() + exercise_logging(logger) _test_logging_outside_transaction_events = [ @@ -79,13 +88,10 @@ def test(): @reset_core_stats_engine() +@validate_log_events_outside_transaction(_test_logging_outside_transaction_events) +@validate_log_event_count_outside_transaction(3) def test_logging_outside_transaction(logger): - @validate_log_events_outside_transaction(_test_logging_outside_transaction_events) - @validate_log_event_count_outside_transaction(3) - def test(): - exercise_logging(logger) - - test() + exercise_logging(logger) @reset_core_stats_engine() diff --git a/tests/logger_logging/test_logging_handler.py b/tests/logger_logging/test_logging_handler.py index dce99f9f8..a9028459f 100644 --- a/tests/logger_logging/test_logging_handler.py +++ b/tests/logger_logging/test_logging_handler.py @@ -15,7 +15,7 @@ import logging import pytest -from conftest import logger as conf_logger +from conftest import logger as conf_logger # noqa, pylint: disable=W0611 from testing_support.fixtures import ( override_application_settings, reset_core_stats_engine, @@ -35,20 +35,12 @@ from newrelic.api.time_trace import current_trace from newrelic.api.transaction import current_transaction -_common_attributes_service_linking = { - "timestamp": None, - "hostname": None, - "entity.name": "Python Agent Test (logger_logging)", - "entity.guid": None, -} -_common_attributes_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"} - @pytest.fixture(scope="function") def uninstrument_logging(): instrumented = logging.Logger.callHandlers while hasattr(logging.Logger.callHandlers, "__wrapped__"): - logging.Logger.callHandlers = logging.Logger.callHandlers.__wrapped__ + logging.Logger.callHandlers = logging.Logger.callHandlers.__wrapped__ # noqa, pylint: disable=E1101 yield logging.Logger.callHandlers = instrumented