diff --git a/newrelic/api/application.py b/newrelic/api/application.py index 3928dd4cf6..41a1b0cd3e 100644 --- a/newrelic/api/application.py +++ b/newrelic/api/application.py @@ -29,7 +29,7 @@ class Application(object): _delayed_callables = {} @staticmethod - def _instance(name): + def _instance(name, activate=True): if name is None: name = newrelic.core.config.global_settings().app_name @@ -44,7 +44,7 @@ def _instance(name): instance = Application._instances.get(name, None) - if not instance: + if not instance and activate: with Application._lock: # Now try again with lock so that only one gets # to create and add it. @@ -150,6 +150,10 @@ def record_transaction(self, data): if self.active: self._agent.record_transaction(self._name, data) + def record_log_event(self, message, level=None, timestamp=None, priority=None): + if self.active: + self._agent.record_log_event(self._name, message, level, timestamp, priority=priority) + def normalize_name(self, name, rule_type="url"): if self.active: return self._agent.normalize_name(self._name, name, rule_type) @@ -162,8 +166,8 @@ def compute_sampled(self): return self._agent.compute_sampled(self._name) -def application_instance(name=None): - return Application._instance(name) +def application_instance(name=None, activate=True): + return Application._instance(name, activate=activate) def register_application(name=None, timeout=None): diff --git a/newrelic/api/import_hook.py b/newrelic/api/import_hook.py index f4303b9b86..b36262afc3 100644 --- a/newrelic/api/import_hook.py +++ b/newrelic/api/import_hook.py @@ -40,6 +40,7 @@ # These modules should not be added to the _uninstrumented_modules set # because they have been deemed okay to import before initialization by # the customer. + "logging", "gunicorn.app.base", "wsgiref.simple_server", "gevent.wsgi", diff --git a/newrelic/api/log.py b/newrelic/api/log.py index 5394ca3f1f..846ef275ab 100644 --- a/newrelic/api/log.py +++ b/newrelic/api/log.py @@ -15,10 +15,11 @@ import json import logging import re +import warnings from logging import Formatter, LogRecord from newrelic.api.time_trace import get_linking_metadata -from newrelic.api.transaction import current_transaction +from newrelic.api.transaction import current_transaction, record_log_event from newrelic.common import agent_http from newrelic.common.object_names import parse_exc_info from newrelic.core.attribute import truncate @@ -85,8 +86,25 @@ def safe_str(object, *args, **kwargs): return json.dumps(self.log_record_to_dict(record), default=safe_str, separators=(",", ":")) +class NewRelicLogForwardingHandler(logging.Handler): + def emit(self, record): + try: + # Avoid getting local log decorated message + if hasattr(record, "_nr_original_message"): + message = record._nr_original_message() + else: + message = record.getMessage() + + record_log_event(message, record.levelname, int(record.created * 1000)) + except Exception: + self.handleError(record) + + class NewRelicLogHandler(logging.Handler): - """This is an experimental log handler provided by the community. Use with caution.""" + """ + Deprecated: Please use NewRelicLogForwardingHandler instead. + This is an experimental log handler provided by the community. Use with caution. + """ PATH = "/log/v1" @@ -104,6 +122,13 @@ def __init__( ca_bundle_path=None, disable_certificate_validation=False, ): + warnings.warn( + "The contributed NewRelicLogHandler has been superseded by automatic instrumentation for " + "logging in the standard lib. If for some reason you need to manually configure a handler, " + "please use newrelic.api.log.NewRelicLogForwardingHandler to take advantage of all the " + "features included in application log forwarding such as proper batching.", + DeprecationWarning + ) super(NewRelicLogHandler, self).__init__(level=level) self.license_key = license_key or self.settings.license_key self.host = host or self.settings.host or self.default_host(self.license_key) diff --git a/newrelic/api/time_trace.py b/newrelic/api/time_trace.py index cef7ae40ad..dc010674cb 100644 --- a/newrelic/api/time_trace.py +++ b/newrelic/api/time_trace.py @@ -13,6 +13,7 @@ # limitations under the License. import logging +import platform import random import sys import time @@ -574,20 +575,26 @@ def increment_child_count(self): else: self.has_async_children = False - def get_linking_metadata(self): - metadata = { - "entity.type": "SERVICE", - } + def _get_service_linking_metadata(self, application=None): + if application is not None: + return get_service_linking_metadata(application) + elif self.transaction is not None: + return get_service_linking_metadata(settings=self.transaction.settings) + else: + return get_service_linking_metadata() + + def _get_trace_linking_metadata(self): + metadata = {} txn = self.transaction if txn: metadata["span.id"] = self.guid metadata["trace.id"] = txn.trace_id - settings = txn.settings - if settings: - metadata["entity.name"] = settings.app_name - entity_guid = settings.entity_guid - if entity_guid: - metadata["entity.guid"] = entity_guid + + return metadata + + def get_linking_metadata(self, application=None): + metadata = self._get_service_linking_metadata(application) + metadata.update(self._get_trace_linking_metadata()) return metadata @@ -601,14 +608,49 @@ def current_trace(): return trace_cache().current_trace() -def get_linking_metadata(): +def get_trace_linking_metadata(): trace = current_trace() if trace: - return trace.get_linking_metadata() + return trace._get_trace_linking_metadata() else: - return { - "entity.type": "SERVICE", - } + return {} + + +def get_service_linking_metadata(application=None, settings=None): + metadata = { + "entity.type": "SERVICE", + } + + trace = current_trace() + if settings is None and trace: + txn = trace.transaction + if txn: + settings = txn.settings + + if not settings: + if application is None: + from newrelic.api.application import application_instance + application = application_instance(activate=False) + + if application is not None: + settings = application.settings + + if settings: + metadata["entity.name"] = settings.app_name + entity_guid = settings.entity_guid + if entity_guid: + metadata["entity.guid"] = entity_guid + metadata["hostname"] = platform.uname()[1] + + return metadata + + +def get_linking_metadata(application=None): + metadata = get_service_linking_metadata() + trace = current_trace() + if trace: + metadata.update(trace._get_trace_linking_metadata()) + return metadata def record_exception(exc=None, value=None, tb=None, params=None, ignore_errors=None, application=None): diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index 2533c9b3b4..4111080a33 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -25,12 +25,14 @@ import weakref from collections import OrderedDict +from newrelic.api.application import application_instance import newrelic.core.database_node import newrelic.core.error_node +from newrelic.core.log_event_node import LogEventNode import newrelic.core.root_node import newrelic.core.transaction_node import newrelic.packages.six as six -from newrelic.api.time_trace import TimeTrace +from newrelic.api.time_trace import TimeTrace, get_linking_metadata from newrelic.common.encoding_utils import ( DistributedTracePayload, NrTraceState, @@ -46,18 +48,20 @@ obfuscate, ) from newrelic.core.attribute import ( + MAX_LOG_MESSAGE_LENGTH, MAX_NUM_USER_ATTRIBUTES, create_agent_attributes, create_attributes, create_user_attributes, process_user_attribute, + truncate, ) from newrelic.core.attribute_filter import ( DST_ERROR_COLLECTOR, DST_NONE, DST_TRANSACTION_TRACER, ) -from newrelic.core.config import DEFAULT_RESERVOIR_SIZE +from newrelic.core.config import DEFAULT_RESERVOIR_SIZE, LOG_EVENT_RESERVOIR_SIZE from newrelic.core.custom_event import create_custom_event from newrelic.core.stack_trace import exception_stack from newrelic.core.stats_engine import CustomMetrics, SampledDataSet @@ -204,7 +208,6 @@ def __init__(self, application, enabled=None, source=None): self._errors = [] self._slow_sql = [] - self._custom_events = SampledDataSet(capacity=DEFAULT_RESERVOIR_SIZE) self._stack_trace_count = 0 self._explain_plan_count = 0 @@ -320,6 +323,13 @@ def __init__(self, application, enabled=None, source=None): if self._settings: self.enabled = True + if self._settings: + self._custom_events = SampledDataSet(capacity=self._settings.event_harvest_config.harvest_limits.custom_event_data) + self._log_events = SampledDataSet(capacity=self._settings.event_harvest_config.harvest_limits.log_event_data) + else: + self._custom_events = SampledDataSet(capacity=DEFAULT_RESERVOIR_SIZE) + self._log_events = SampledDataSet(capacity=LOG_EVENT_RESERVOIR_SIZE) + def __del__(self): self._dead = True if self._state == self.STATE_RUNNING: @@ -562,6 +572,7 @@ def __exit__(self, exc, value, tb): errors=tuple(self._errors), slow_sql=tuple(self._slow_sql), custom_events=self._custom_events, + log_events=self._log_events, apdex_t=self.apdex, suppress_apdex=self.suppress_apdex, custom_metrics=self._custom_metrics, @@ -1465,6 +1476,31 @@ def set_transaction_name(self, name, group=None, priority=None): self._group = group self._name = name + + def record_log_event(self, message, level=None, timestamp=None, priority=None): + settings = self.settings + if not (settings and settings.application_logging and settings.application_logging.enabled and settings.application_logging.forwarding and settings.application_logging.forwarding.enabled): + return + + timestamp = timestamp if timestamp is not None else time.time() + level = str(level) if level is not None else "UNKNOWN" + + if not message or message.isspace(): + _logger.debug("record_log_event called where message was missing. No log event will be sent.") + return + + message = truncate(message, MAX_LOG_MESSAGE_LENGTH) + + event = LogEventNode( + timestamp=timestamp, + level=level, + message=message, + attributes=get_linking_metadata(), + ) + + self._log_events.add(event, priority=priority) + + def record_exception(self, exc=None, value=None, tb=None, params=None, ignore_errors=None): # Deprecation Warning warnings.warn( @@ -1814,6 +1850,34 @@ def record_custom_event(event_type, params, application=None): application.record_custom_event(event_type, params) +def record_log_event(message, level=None, timestamp=None, application=None, priority=None): + """Record a log event. + + Args: + record (logging.Record): + application (newrelic.api.Application): Application instance. + """ + + if application is None: + transaction = current_transaction() + if transaction: + transaction.record_log_event(message, level, timestamp) + else: + application = application_instance(activate=False) + + if application and application.enabled: + application.record_log_event(message, level, timestamp, priority=priority) + else: + _logger.debug( + "record_log_event has been called but no transaction or application was running. As a result, " + "the following event has not been recorded. message: %r level: %r timestamp %r. To correct " + "this problem, supply an application object as a parameter to this record_log_event call.", + message, level, timestamp, + ) + elif application.enabled: + application.record_log_event(message, level, timestamp, priority=priority) + + def accept_distributed_trace_payload(payload, transport_type="HTTP"): transaction = current_transaction() if transaction: diff --git a/newrelic/common/agent_http.py b/newrelic/common/agent_http.py index 73367d18d8..2398920007 100644 --- a/newrelic/common/agent_http.py +++ b/newrelic/common/agent_http.py @@ -609,6 +609,7 @@ class DeveloperModeClient(SupportabilityMixin, BaseClient): "error_event_data": None, "span_event_data": None, "custom_event_data": None, + "log_event_data": None, "shutdown": [], } diff --git a/newrelic/config.py b/newrelic/config.py index c4a70d5bf4..11601551c2 100644 --- a/newrelic/config.py +++ b/newrelic/config.py @@ -527,11 +527,18 @@ def _process_configuration(section): _process_setting(section, "event_harvest_config.harvest_limits.custom_event_data", "getint", None) _process_setting(section, "event_harvest_config.harvest_limits.span_event_data", "getint", None) _process_setting(section, "event_harvest_config.harvest_limits.error_event_data", "getint", None) + _process_setting(section, "event_harvest_config.harvest_limits.log_event_data", "getint", None) _process_setting(section, "infinite_tracing.trace_observer_host", "get", None) _process_setting(section, "infinite_tracing.trace_observer_port", "getint", None) _process_setting(section, "infinite_tracing.span_queue_size", "getint", None) _process_setting(section, "code_level_metrics.enabled", "getboolean", None) + _process_setting(section, "application_logging.enabled", "getboolean", None) + _process_setting(section, "application_logging.forwarding.max_samples_stored", "getint", None) + _process_setting(section, "application_logging.forwarding.enabled", "getboolean", None) + _process_setting(section, "application_logging.metrics.enabled", "getboolean", None) + _process_setting(section, "application_logging.local_decorating.enabled", "getboolean", None) + # Loading of configuration from specified file and for specified # deployment environment. Can also indicate whether configuration @@ -707,6 +714,10 @@ def translate_deprecated_settings(settings, cached_settings): "custom_insights_events.max_samples_stored", "event_harvest_config.harvest_limits.custom_event_data", ), + ( + "application_logging.forwarding.max_samples_stored", + "event_harvest_config.harvest_limits.log_event_data", + ), ( "error_collector.ignore_errors", "error_collector.ignore_classes", @@ -860,6 +871,10 @@ def apply_local_high_security_mode_setting(settings): settings.message_tracer.segment_parameters_enabled = False _logger.info(log_template, "message_tracer.segment_parameters_enabled", True, False) + if settings.application_logging.forwarding.enabled: + settings.application_logging.forwarding.enabled = False + _logger.info(log_template, "application_logging.forwarding.enabled", True, False) + return settings @@ -2292,6 +2307,23 @@ def _process_module_builtin_defaults(): "instrument_cherrypy__cptree", ) + _process_module_definition( + "logging", + "newrelic.hooks.logger_logging", + "instrument_logging", + ) + + _process_module_definition( + "loguru", + "newrelic.hooks.logger_loguru", + "instrument_loguru", + ) + _process_module_definition( + "loguru._logger", + "newrelic.hooks.logger_loguru", + "instrument_loguru_logger", + ) + _process_module_definition( "paste.httpserver", "newrelic.hooks.adapter_paste", diff --git a/newrelic/core/agent.py b/newrelic/core/agent.py index fba8ca50be..6ab9571a45 100644 --- a/newrelic/core/agent.py +++ b/newrelic/core/agent.py @@ -531,6 +531,13 @@ def record_custom_event(self, app_name, event_type, params): application.record_custom_event(event_type, params) + def record_log_event(self, app_name, message, level=None, timestamp=None, priority=None): + application = self._applications.get(app_name, None) + if application is None or not application.active: + return + + application.record_log_event(message, level, timestamp, priority=priority) + def record_transaction(self, app_name, data): """Processes the raw transaction data, generating and recording appropriate metrics against the named application. If there has diff --git a/newrelic/core/agent_protocol.py b/newrelic/core/agent_protocol.py index e0d63962dd..ba277d4de1 100644 --- a/newrelic/core/agent_protocol.py +++ b/newrelic/core/agent_protocol.py @@ -143,6 +143,7 @@ class AgentProtocol(object): "transaction_tracer.record_sql", "strip_exception_messages.enabled", "custom_insights_events.enabled", + "application_logging.forwarding.enabled", ) LOGGER_FUNC_MAPPING = { diff --git a/newrelic/core/application.py b/newrelic/core/application.py index 08fbcd78da..419211a358 100644 --- a/newrelic/core/application.py +++ b/newrelic/core/application.py @@ -537,6 +537,14 @@ def connect_to_data_collector(self, activate_agent): ) internal_metric("Supportability/Python/Application/Registration/Attempts", connect_attempts) + # Logging feature toggle supportability metrics + application_logging_metrics = configuration.application_logging.enabled and configuration.application_logging.metrics.enabled + application_logging_forwarding = configuration.application_logging.enabled and configuration.application_logging.forwarding.enabled + application_logging_local_decorating = configuration.application_logging.enabled and configuration.application_logging.local_decorating.enabled + internal_metric("Supportability/Logging/Forwarding/Python/%s" % ("enabled" if application_logging_forwarding else "disabled"), 1) + internal_metric("Supportability/Logging/LocalDecorating/Python/%s" % ("enabled" if application_logging_local_decorating else "disabled"), 1) + internal_metric("Supportability/Logging/Metrics/Python/%s" % ("enabled" if application_logging_metrics else "disabled"), 1) + self._stats_engine.merge_custom_metrics(internal_metrics.metrics()) # Update the active session in this object. This will the @@ -836,6 +844,16 @@ def record_custom_event(self, event_type, params): self._global_events_account += 1 self._stats_engine.record_custom_event(event) + def record_log_event(self, message, level=None, timestamp=None, priority=None): + if not self._active_session: + return + + if message: + with self._stats_custom_lock: + event = self._stats_engine.record_log_event(message, level, timestamp, priority=priority) + if event: + self._global_events_account += 1 + def record_transaction(self, data): """Record a single transaction against this application.""" @@ -1289,6 +1307,28 @@ def harvest(self, shutdown=False, flexible=False): stats.reset_custom_events() + # Send log events + + if configuration and configuration.application_logging and configuration.application_logging.enabled and configuration.application_logging.forwarding and configuration.application_logging.forwarding.enabled: + + logs = stats.log_events + + if logs: + if logs.num_samples > 0: + log_samples = list(logs) + + _logger.debug("Sending log event data for harvest of %r.", self._app_name) + + self._active_session.send_log_events(logs.sampling_info, log_samples) + log_samples = None + + # As per spec + internal_count_metric("Supportability/Logging/Forwarding/Seen", logs.num_seen) + internal_count_metric("Supportability/Logging/Forwarding/Sent", logs.num_samples) + internal_count_metric("Logging/Forwarding/Dropped", logs.num_seen - logs.num_samples) + + stats.reset_log_events() + # Send the accumulated error data. if configuration.collect_errors: diff --git a/newrelic/core/attribute.py b/newrelic/core/attribute.py index d09eb9e5d7..37f0afac9c 100644 --- a/newrelic/core/attribute.py +++ b/newrelic/core/attribute.py @@ -88,6 +88,7 @@ MAX_NUM_USER_ATTRIBUTES = 128 MAX_ATTRIBUTE_LENGTH = 255 MAX_64_BIT_INT = 2 ** 63 - 1 +MAX_LOG_MESSAGE_LENGTH = 32768 class NameTooLongException(Exception): diff --git a/newrelic/core/config.py b/newrelic/core/config.py index 853cf19a30..57f408b872 100644 --- a/newrelic/core/config.py +++ b/newrelic/core/config.py @@ -54,6 +54,7 @@ DEFAULT_RESERVOIR_SIZE = 1200 ERROR_EVENT_RESERVOIR_SIZE = 100 SPAN_EVENT_RESERVOIR_SIZE = 2000 +LOG_EVENT_RESERVOIR_SIZE = 10000 # settings that should be completely ignored if set server side IGNORED_SERVER_SIDE_SETTINGS = [ @@ -259,6 +260,22 @@ class EventLoopVisibilitySettings(Settings): pass +class ApplicationLoggingSettings(Settings): + pass + + +class ApplicationLoggingForwardingSettings(Settings): + pass + + +class ApplicationLoggingMetricsSettings(Settings): + pass + + +class ApplicationLoggingLocalDecoratingSettings(Settings): + pass + + class InfiniteTracingSettings(Settings): _trace_observer_host = None @@ -337,6 +354,10 @@ class EventHarvestConfigHarvestLimitSettings(Settings): _settings = TopLevelSettings() +_settings.application_logging = ApplicationLoggingSettings() +_settings.application_logging.forwarding = ApplicationLoggingForwardingSettings() +_settings.application_logging.metrics = ApplicationLoggingMetricsSettings() +_settings.application_logging.local_decorating = ApplicationLoggingLocalDecoratingSettings() _settings.attributes = AttributesSettings() _settings.gc_runtime_metrics = GCRuntimeMetricsSettings() _settings.code_level_metrics = CodeLevelMetricsSettings() @@ -728,6 +749,10 @@ def default_host(license_key): "NEW_RELIC_ERROR_COLLECTOR_MAX_EVENT_SAMPLES_STORED", ERROR_EVENT_RESERVOIR_SIZE ) +_settings.event_harvest_config.harvest_limits.log_event_data = _environ_as_int( + "NEW_RELIC_APPLICATION_LOGGING_FORWARDING_MAX_SAMPLES_STORED", LOG_EVENT_RESERVOIR_SIZE +) + _settings.console.listener_socket = None _settings.console.allow_interpreter_cmd = False @@ -785,6 +810,17 @@ def default_host(license_key): _settings.event_loop_visibility.blocking_threshold = 0.1 _settings.code_level_metrics.enabled = True +_settings.application_logging.enabled = _environ_as_bool("NEW_RELIC_APPLICATION_LOGGING_ENABLED", default=True) +_settings.application_logging.forwarding.enabled = _environ_as_bool( + "NEW_RELIC_APPLICATION_LOGGING_FORWARDING_ENABLED", default=False +) +_settings.application_logging.metrics.enabled = _environ_as_bool( + "NEW_RELIC_APPLICATION_LOGGING_METRICS_ENABLED", default=True +) +_settings.application_logging.local_decorating.enabled = _environ_as_bool( + "NEW_RELIC_APPLICATION_LOGGING_LOCAL_DECORATING_ENABLED", default=False +) + def global_settings(): """This returns the default global settings. Generally only used diff --git a/newrelic/core/data_collector.py b/newrelic/core/data_collector.py index fec1069989..f8947927d4 100644 --- a/newrelic/core/data_collector.py +++ b/newrelic/core/data_collector.py @@ -128,6 +128,12 @@ def send_metric_data(self, start_time, end_time, metric_data): payload = (self.agent_run_id, start_time, end_time, metric_data) return self._protocol.send("metric_data", payload) + def send_log_events(self, sampling_info, log_event_data): + """Called to submit sample set for log events.""" + + payload = ({"logs": tuple(log._asdict() for log in log_event_data)},) + return self._protocol.send("log_event_data", payload) + def get_agent_commands(self): """Receive agent commands from the data collector. diff --git a/newrelic/core/log_event_node.py b/newrelic/core/log_event_node.py new file mode 100644 index 0000000000..52117edca2 --- /dev/null +++ b/newrelic/core/log_event_node.py @@ -0,0 +1,17 @@ +# 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 collections import namedtuple + +LogEventNode = namedtuple('LogEventNode', ['timestamp', 'level', 'message', 'attributes']) diff --git a/newrelic/core/stats_engine.py b/newrelic/core/stats_engine.py index 555a86b76b..0e8e745465 100644 --- a/newrelic/core/stats_engine.py +++ b/newrelic/core/stats_engine.py @@ -32,10 +32,11 @@ import newrelic.packages.six as six from newrelic.api.settings import STRIP_EXCEPTION_MESSAGE +from newrelic.api.time_trace import get_linking_metadata from newrelic.common.encoding_utils import json_encode from newrelic.common.object_names import parse_exc_info from newrelic.common.streaming_utils import StreamBuffer -from newrelic.core.attribute import create_user_attributes, process_user_attribute +from newrelic.core.attribute import create_user_attributes, process_user_attribute, truncate, MAX_LOG_MESSAGE_LENGTH from newrelic.core.attribute_filter import DST_ERROR_COLLECTOR from newrelic.core.code_level_metrics import extract_code_from_traceback from newrelic.core.config import is_expected_error, should_ignore_error @@ -43,6 +44,7 @@ from newrelic.core.error_collector import TracedError from newrelic.core.metric import TimeMetric from newrelic.core.stack_trace import exception_stack +from newrelic.core.log_event_node import LogEventNode _logger = logging.getLogger(__name__) @@ -54,6 +56,7 @@ "span_event_data": ("reset_span_events",), "custom_event_data": ("reset_custom_events",), "error_event_data": ("reset_error_events",), + "log_event_data": ("reset_log_events",), } @@ -331,9 +334,12 @@ def add(self, sample, priority=None): # pylint: disable=E0202 return heapreplace(self.pq, entry) - def merge(self, other_data_set): - for priority, seen_at, sample in other_data_set.pq: - self.add(sample, priority) + def merge(self, other_data_set, priority=None): + if priority is None: + priority = -1 + + for original_priority, seen_at, sample in other_data_set.pq: + self.add(sample, max(priority, original_priority)) # Merge the num_seen from the other_data_set, but take care not to # double-count the actual samples of other_data_set since the .add @@ -424,6 +430,7 @@ def __init__(self): self._error_events = SampledDataSet() self._custom_events = SampledDataSet() self._span_events = SampledDataSet() + self._log_events = SampledDataSet() self._span_stream = None self.__sql_stats_table = {} self.__slow_transaction = None @@ -454,6 +461,10 @@ def custom_events(self): def span_events(self): return self._span_events + @property + def log_events(self): + return self._log_events + @property def span_stream(self): return self._span_stream @@ -995,6 +1006,42 @@ def record_transaction(self, transaction): for event in transaction.span_events(self.__settings): self._span_events.add(event, priority=transaction.priority) + # Merge in log events + + if settings and settings.application_logging and settings.application_logging.enabled and settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: + self._log_events.merge(transaction.log_events, priority=transaction.priority) + + + def record_log_event(self, message, level=None, timestamp=None, priority=None): + settings = self.__settings + if not (settings and settings.application_logging and settings.application_logging.enabled and settings.application_logging.forwarding and settings.application_logging.forwarding.enabled): + return + + timestamp = timestamp if timestamp is not None else time.time() + level = str(level) if level is not None else "UNKNOWN" + + if not message or message.isspace(): + _logger.debug("record_log_event called where message was missing. No log event will be sent.") + return + + message = truncate(message, MAX_LOG_MESSAGE_LENGTH) + + event = LogEventNode( + timestamp=timestamp, + level=level, + message=message, + attributes=get_linking_metadata(), + ) + + if priority is None: + # Base priority for log events outside transactions is below those inside transactions + priority = random.random() - 1 + + self._log_events.add(event, priority=priority) + + return event + + def metric_data(self, normalizer=None): """Returns a list containing the low level metric data for sending to the core application pertaining to the reporting @@ -1347,6 +1394,7 @@ def reset_stats(self, settings, reset_stream=False): self.reset_error_events() self.reset_custom_events() self.reset_span_events() + self.reset_log_events() self.reset_synthetics_events() # streams are never reset after instantiation if reset_stream: @@ -1391,6 +1439,12 @@ def reset_span_events(self): else: self._span_events = SampledDataSet() + def reset_log_events(self): + if self.__settings is not None: + self._log_events = SampledDataSet(self.__settings.event_harvest_config.harvest_limits.log_event_data) + else: + self._log_events = SampledDataSet() + def reset_synthetics_events(self): """Resets the accumulated statistics back to initial state for Synthetics events data. @@ -1513,6 +1567,7 @@ def merge(self, snapshot): self._merge_error_traces(snapshot) self._merge_custom_events(snapshot) self._merge_span_events(snapshot) + self._merge_log_events(snapshot) self._merge_sql(snapshot) self._merge_traces(snapshot) @@ -1537,6 +1592,7 @@ def rollback(self, snapshot): self._merge_error_events(snapshot) self._merge_custom_events(snapshot, rollback=True) self._merge_span_events(snapshot, rollback=True) + self._merge_log_events(snapshot, rollback=True) def merge_metric_stats(self, snapshot): """Merges metric data from a snapshot. This is used both when merging @@ -1613,6 +1669,12 @@ def _merge_span_events(self, snapshot, rollback=False): return self._span_events.merge(events) + def _merge_log_events(self, snapshot, rollback=False): + events = snapshot.log_events + if not events: + return + self._log_events.merge(events) + def _merge_error_traces(self, snapshot): # Append snapshot error details at end to maintain time @@ -1689,6 +1751,9 @@ def reset_custom_events(self): def reset_span_events(self): self._span_events = None + def reset_log_events(self): + self._log_events = None + def reset_synthetics_events(self): self._synthetics_events = None diff --git a/newrelic/core/transaction_node.py b/newrelic/core/transaction_node.py index 638e5444d6..97f6f3ebb5 100644 --- a/newrelic/core/transaction_node.py +++ b/newrelic/core/transaction_node.py @@ -41,8 +41,8 @@ 'port', 'request_uri', 'queue_start', 'start_time', 'end_time', 'last_byte_time', 'response_time', 'total_time', 'duration', 'exclusive', 'root', 'errors', 'slow_sql', - 'custom_events', 'apdex_t', 'suppress_apdex', 'custom_metrics', 'guid', - 'cpu_time', 'suppress_transaction_trace', 'client_cross_process_id', + 'custom_events', 'log_events', 'apdex_t', 'suppress_apdex', 'custom_metrics', + 'guid', 'cpu_time', 'suppress_transaction_trace', 'client_cross_process_id', 'referring_transaction_guid', 'record_tt', 'synthetics_resource_id', 'synthetics_job_id', 'synthetics_monitor_id', 'synthetics_header', 'is_part_of_cat', 'trip_id', 'path_hash', 'referring_path_hash', diff --git a/newrelic/hooks/logger_logging.py b/newrelic/hooks/logger_logging.py new file mode 100644 index 0000000000..22cdc8c786 --- /dev/null +++ b/newrelic/hooks/logger_logging.py @@ -0,0 +1,93 @@ +# 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 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 wrap_function_wrapper, function_wrapper +from newrelic.core.config import global_settings + + +try: + from urllib import quote +except ImportError: + from urllib.parse import quote + + +def add_nr_linking_metadata(message): + available_metadata = get_linking_metadata() + entity_name = quote(available_metadata.get("entity.name", "")) + entity_guid = available_metadata.get("entity.guid", "") + span_id = available_metadata.get("span.id", "") + trace_id = available_metadata.get("trace.id", "") + hostname = available_metadata.get("hostname", "") + + nr_linking_str = "|".join(("NR-LINKING", entity_guid, hostname, trace_id, span_id, entity_name)) + return "%s %s|" % (message, nr_linking_str) + + +@function_wrapper +def wrap_getMessage(wrapped, instance, args, kwargs): + message = wrapped(*args, **kwargs) + return add_nr_linking_metadata(message) + + +def bind_callHandlers(record): + return record + + +def wrap_callHandlers(wrapped, instance, args, kwargs): + transaction = current_transaction() + record = bind_callHandlers(*args, **kwargs) + + logger_name = getattr(instance, "name", None) + if logger_name and logger_name.split(".")[0] == "newrelic": + return wrapped(*args, **kwargs) + + if transaction: + settings = transaction.settings + else: + settings = global_settings() + + # Return early if application logging not enabled + if settings and settings.application_logging and settings.application_logging.enabled: + level_name = str(getattr(record, "levelname", "UNKNOWN")) + if settings.application_logging.metrics and settings.application_logging.metrics.enabled: + if transaction: + transaction.record_custom_metric("Logging/lines", {"count": 1}) + transaction.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1}) + else: + application = application_instance(activate=False) + if application and application.enabled: + application.record_custom_metric("Logging/lines", {"count": 1}) + application.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1}) + + if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: + try: + message = record.getMessage() + record_log_event(message, level_name, int(record.created * 1000)) + except Exception: + pass + + if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled: + record._nr_original_message = record.getMessage + record.getMessage = wrap_getMessage(record.getMessage) + + return wrapped(*args, **kwargs) + + +def instrument_logging(module): + if hasattr(module, "Logger"): + if hasattr(module.Logger, "callHandlers"): + wrap_function_wrapper(module, "Logger.callHandlers", wrap_callHandlers) diff --git a/newrelic/hooks/logger_loguru.py b/newrelic/hooks/logger_loguru.py new file mode 100644 index 0000000000..65eadb1c46 --- /dev/null +++ b/newrelic/hooks/logger_loguru.py @@ -0,0 +1,142 @@ +# 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 logging + +from newrelic.api.application import application_instance +from newrelic.api.transaction import current_transaction, record_log_event +from newrelic.common.object_wrapper import wrap_function_wrapper +from newrelic.core.config import global_settings +from newrelic.hooks.logger_logging import add_nr_linking_metadata +from newrelic.packages import six + +_logger = logging.getLogger(__name__) + +def loguru_version(): + from loguru import __version__ + return tuple(int(x) for x in __version__.split(".")) + + +def _nr_log_forwarder(message_instance): + transaction = current_transaction() + record = message_instance.record + message = record.get("_nr_original_message", record["message"]) + + if transaction: + settings = transaction.settings + else: + settings = global_settings() + + # Return early if application logging not enabled + if settings and settings.application_logging and settings.application_logging.enabled: + level = record["level"] + level_name = "UNKNOWN" if not level else (level.name or "UNKNOWN") + + if settings.application_logging.metrics and settings.application_logging.metrics.enabled: + if transaction: + transaction.record_custom_metric("Logging/lines", {"count": 1}) + transaction.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1}) + else: + application = application_instance(activate=False) + if application and application.enabled: + application.record_custom_metric("Logging/lines", {"count": 1}) + application.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1}) + + if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: + try: + record_log_event(message, level_name, int(record["time"].timestamp())) + except Exception: + pass + + +ALLOWED_LOGURU_OPTIONS_LENGTHS = frozenset((8, 9)) + +def bind_log(level_id, static_level_no, from_decorator, options, message, args, kwargs): + assert len(options) in ALLOWED_LOGURU_OPTIONS_LENGTHS # Assert the options signature we expect + return level_id, static_level_no, from_decorator, list(options), message, args, kwargs + + +def wrap_log(wrapped, instance, args, kwargs): + try: + level_id, static_level_no, from_decorator, options, message, subargs, subkwargs = bind_log(*args, **kwargs) + options[-2] = nr_log_patcher(options[-2]) + except Exception as e: + _logger.debug("Exception in loguru handling: %s" % str(e)) + return wrapped(*args, **kwargs) + else: + return wrapped(level_id, static_level_no, from_decorator, options, message, subargs, subkwargs) + + +def nr_log_patcher(original_patcher=None): + def _nr_log_patcher(record): + if original_patcher: + record = original_patcher(record) + + transaction = current_transaction() + + if transaction: + settings = transaction.settings + else: + settings = global_settings() + + if settings and settings.application_logging and settings.application_logging.enabled: + if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled: + record["_nr_original_message"] = message = record["message"] + record["message"] = add_nr_linking_metadata(message) + + if loguru_version() > (0, 6, 0): + if original_patcher is not None: + patchers = [p for p in original_patcher] # Consumer iterable into list so we can modify + # Wipe out reference so patchers aren't called twice, as the framework will handle calling other patchers. + original_patcher = None + else: + patchers = [] + + patchers.append(_nr_log_patcher) + return patchers + else: + return _nr_log_patcher + + +def wrap_Logger_init(wrapped, instance, args, kwargs): + result = wrapped(*args, **kwargs) + patch_loguru_logger(instance) + return result + + +def patch_loguru_logger(logger): + if hasattr(logger, "_core"): + if not hasattr(logger._core, "_nr_instrumented"): + logger.add(_nr_log_forwarder, format="{message}") + logger._core._nr_instrumented = True + elif not hasattr(logger, "_nr_instrumented"): + for _, handler in six.iteritems(logger._handlers): + if handler._writer is _nr_log_forwarder: + logger._nr_instrumented = True + return + + logger.add(_nr_log_forwarder, format="{message}") + logger._nr_instrumented = True + + +def instrument_loguru_logger(module): + if hasattr(module, "Logger"): + wrap_function_wrapper(module, "Logger.__init__", wrap_Logger_init) + if hasattr(module.Logger, "_log"): + wrap_function_wrapper(module, "Logger._log", wrap_log) + + +def instrument_loguru(module): + if hasattr(module, "logger"): + patch_loguru_logger(module.logger) diff --git a/newrelic/newrelic.ini b/newrelic/newrelic.ini index 7234986a4b..d06d8a2926 100644 --- a/newrelic/newrelic.ini +++ b/newrelic/newrelic.ini @@ -200,6 +200,35 @@ thread_profiler.enabled = true # https://docs.newrelic.com/docs/transition-guide-distributed-tracing distributed_tracing.enabled = true +# This setting enables log decoration, the forwarding of log events, +# and the collection of logging metrics if these sub-feature +# configurations are also enabled. If this setting is false, no +# logging instrumentation features are enabled. This can also be +# set using the NEW_RELIC_APPLICATION_LOGGING_ENABLED environment +# variable. +# application_logging.enabled = true + +# If true, the agent captures log records emitted by your application +# and forwards them to New Relic. `application_logging.enabled` must +# also be true for this setting to take effect. You can also set +# this using the NEW_RELIC_APPLICATION_LOGGING_FORWARDING_ENABLED +# environment variable. +# application_logging.forwarding.enabled = true + +# If true, the agent decorates logs with metadata to link to entities, +# hosts, traces, and spans. `application_logging.enabled` must also +# be true for this setting to take effect. This can also be set +# using the NEW_RELIC_APPLICATION_LOGGING_LOCAL_DECORATING_ENABLED +# environment variable. +# application_logging.local_decorating.enabled = true + +# If true, the agent captures metrics related to the log lines +# being sent up by your application. This can also be set +# using the NEW_RELIC_APPLICATION_LOGGING_METRICS_ENABLED +# environment variable. +# application_logging.metrics.enabled = true + + # --------------------------------------------------------------------------- # diff --git a/tests/agent_features/test_collector_payloads.py b/tests/agent_features/test_collector_payloads.py index 867b603099..17b46ce49a 100644 --- a/tests/agent_features/test_collector_payloads.py +++ b/tests/agent_features/test_collector_payloads.py @@ -12,6 +12,7 @@ # See the License for the specific language governing permissions and # limitations under the License. +import pytest import webtest from testing_support.fixtures import (validate_error_trace_collector_json, @@ -22,6 +23,8 @@ from testing_support.sample_applications import (simple_app, simple_exceptional_app, simple_custom_event_app) +from testing_support.validators.validate_log_event_collector_json import validate_log_event_collector_json + exceptional_application = webtest.TestApp(simple_exceptional_app) normal_application = webtest.TestApp(simple_app) @@ -63,3 +66,10 @@ def test_transaction_event_json(): @validate_custom_event_collector_json() def test_custom_event_json(): custom_event_application.get('/') + + +@pytest.mark.xfail(reason="Unwritten validator") +@validate_log_event_collector_json +def test_log_event_json(): + normal_application.get('/') + raise NotImplementedError("Fix my validator") diff --git a/tests/agent_features/test_configuration.py b/tests/agent_features/test_configuration.py index a6772a54f2..5846e38080 100644 --- a/tests/agent_features/test_configuration.py +++ b/tests/agent_features/test_configuration.py @@ -50,7 +50,12 @@ def parameterize_local_config(settings_list): { "request_headers_map": {"NR-SESSION": "BLANK"}, "event_harvest_config": { - "harvest_limits": {"analytic_event_data": 100, "custom_event_data": 100, "error_event_data": 8}, + "harvest_limits": { + "analytic_event_data": 100, + "custom_event_data": 100, + "error_event_data": 8, + "log_event_data": 100, + }, "report_period_ms": 5000, }, } @@ -270,6 +275,7 @@ def test_dict_parse(settings): assert "analytic_event_data" in limits assert "custom_event_data" in limits assert "error_event_data" in limits + assert "log_event_data" in limits @parameterize_local_config(_test_strip_proxy_details_local_configs) @@ -440,9 +446,21 @@ def test_delete_setting_parent(): TSetting("event_harvest_config.harvest_limits.custom_event_data", 1200, 1200), ), ( - TSetting("error_collector.ignore_errors", callable_name(ValueError), []), + TSetting("application_logging.forwarding.max_samples_stored", 10000, 10000), + TSetting("event_harvest_config.harvest_limits.log_event_data", 99999, 10000), + ), + ( + TSetting("application_logging.forwarding.max_samples_stored", 99999, 10000), + TSetting("event_harvest_config.harvest_limits.log_event_data", 10000, 10000), + ), + ( + TSetting("error_collector.ignore_errors", [], []), TSetting("error_collector.ignore_classes", callable_name(ValueError), []), ), + ( + TSetting("error_collector.ignore_errors", callable_name(ValueError), []), + TSetting("error_collector.ignore_classes", [], []), + ), ] diff --git a/tests/agent_features/test_high_security_mode.py b/tests/agent_features/test_high_security_mode.py index c738e838cf..89499d3658 100644 --- a/tests/agent_features/test_high_security_mode.py +++ b/tests/agent_features/test_high_security_mode.py @@ -13,138 +13,159 @@ # limitations under the License. import os -import pytest import time + +import pytest import webtest +from testing_support.fixtures import ( + override_application_settings, + override_generic_settings, + reset_core_stats_engine, + validate_attributes_complete, + validate_custom_event_count, + validate_custom_event_in_application_stats_engine, + validate_custom_parameters, + validate_non_transaction_error_event, + validate_request_params_omitted, + validate_transaction_errors, + validate_tt_segment_params, +) from newrelic.api.application import application_instance as application from newrelic.api.background_task import background_task -from newrelic.api.time_trace import notice_error from newrelic.api.function_trace import FunctionTrace from newrelic.api.message_trace import MessageTrace from newrelic.api.settings import STRIP_EXCEPTION_MESSAGE -from newrelic.api.transaction import (capture_request_params, - add_custom_parameter, current_transaction, record_custom_event) +from newrelic.api.time_trace import notice_error +from newrelic.api.transaction import ( + add_custom_parameter, + capture_request_params, + current_transaction, + record_custom_event, +) from newrelic.api.wsgi_application import wsgi_application - from newrelic.common.object_names import callable_name - from newrelic.config import apply_local_high_security_mode_setting - -from newrelic.core.attribute import (Attribute, DST_TRANSACTION_TRACER, - DST_ERROR_COLLECTOR, DST_ALL) -from newrelic.core.config import (global_settings, Settings, - apply_config_setting) from newrelic.core.agent_protocol import AgentProtocol - -from testing_support.fixtures import (override_application_settings, - override_generic_settings, - validate_custom_parameters, validate_transaction_errors, - validate_request_params_omitted, validate_attributes_complete, - validate_non_transaction_error_event, reset_core_stats_engine, - validate_custom_event_in_application_stats_engine, - validate_custom_event_count, validate_tt_segment_params) +from newrelic.core.attribute import ( + DST_ALL, + DST_ERROR_COLLECTOR, + DST_TRANSACTION_TRACER, + Attribute, +) +from newrelic.core.config import Settings, apply_config_setting, global_settings def test_hsm_configuration_default(): # Global default should always be off. settings = global_settings() - assert 'NEW_RELIC_HIGH_SECURITY_MODE' not in os.environ + assert "NEW_RELIC_HIGH_SECURITY_MODE" not in os.environ assert settings.high_security is False _hsm_local_config_file_settings_disabled = [ { - 'high_security': False, - 'capture_params': True, - 'transaction_tracer.record_sql': 'raw', - 'strip_exception_messages.enabled': False, - 'custom_insights_events.enabled': True, - 'message_tracer.segment_parameters_enabled': True, + "high_security": False, + "capture_params": True, + "transaction_tracer.record_sql": "raw", + "strip_exception_messages.enabled": False, + "custom_insights_events.enabled": True, + "message_tracer.segment_parameters_enabled": True, + "application_logging.forwarding.enabled": True, }, { - 'high_security': False, - 'capture_params': False, - 'transaction_tracer.record_sql': 'raw', - 'strip_exception_messages.enabled': False, - 'custom_insights_events.enabled': False, - 'message_tracer.segment_parameters_enabled': True, + "high_security": False, + "capture_params": False, + "transaction_tracer.record_sql": "raw", + "strip_exception_messages.enabled": False, + "custom_insights_events.enabled": False, + "message_tracer.segment_parameters_enabled": True, + "application_logging.forwarding.enabled": True, }, { - 'high_security': False, - 'capture_params': False, - 'transaction_tracer.record_sql': 'obfuscated', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': True, - 'message_tracer.segment_parameters_enabled': False, + "high_security": False, + "capture_params": False, + "transaction_tracer.record_sql": "obfuscated", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": True, + "message_tracer.segment_parameters_enabled": False, + "application_logging.forwarding.enabled": False, }, { - 'high_security': False, - 'capture_params': False, - 'transaction_tracer.record_sql': 'off', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': False, - 'message_tracer.segment_parameters_enabled': False, + "high_security": False, + "capture_params": False, + "transaction_tracer.record_sql": "off", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": False, + "message_tracer.segment_parameters_enabled": False, + "application_logging.forwarding.enabled": False, }, ] _hsm_local_config_file_settings_enabled = [ { - 'high_security': True, - 'capture_params': True, - 'transaction_tracer.record_sql': 'raw', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': True, - 'message_tracer.segment_parameters_enabled': True, + "high_security": True, + "capture_params": True, + "transaction_tracer.record_sql": "raw", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": True, + "message_tracer.segment_parameters_enabled": True, + "application_logging.forwarding.enabled": False, }, { - 'high_security': True, - 'capture_params': None, - 'transaction_tracer.record_sql': 'raw', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': True, - 'message_tracer.segment_parameters_enabled': True, + "high_security": True, + "capture_params": None, + "transaction_tracer.record_sql": "raw", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": True, + "message_tracer.segment_parameters_enabled": True, + "application_logging.forwarding.enabled": False, }, { - 'high_security': True, - 'capture_params': True, - 'transaction_tracer.record_sql': 'raw', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': True, - 'message_tracer.segment_parameters_enabled': True, + "high_security": True, + "capture_params": True, + "transaction_tracer.record_sql": "raw", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": True, + "message_tracer.segment_parameters_enabled": True, + "application_logging.forwarding.enabled": False, }, { - 'high_security': True, - 'capture_params': False, - 'transaction_tracer.record_sql': 'raw', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': True, - 'message_tracer.segment_parameters_enabled': True, + "high_security": True, + "capture_params": False, + "transaction_tracer.record_sql": "raw", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": True, + "message_tracer.segment_parameters_enabled": True, + "application_logging.forwarding.enabled": True, }, { - 'high_security': True, - 'capture_params': True, - 'transaction_tracer.record_sql': 'obfuscated', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': True, - 'message_tracer.segment_parameters_enabled': True, + "high_security": True, + "capture_params": True, + "transaction_tracer.record_sql": "obfuscated", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": True, + "message_tracer.segment_parameters_enabled": True, + "application_logging.forwarding.enabled": True, }, { - 'high_security': True, - 'capture_params': True, - 'transaction_tracer.record_sql': 'off', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': True, - 'message_tracer.segment_parameters_enabled': False, + "high_security": True, + "capture_params": True, + "transaction_tracer.record_sql": "off", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": True, + "message_tracer.segment_parameters_enabled": False, + "application_logging.forwarding.enabled": True, }, { - 'high_security': True, - 'capture_params': True, - 'transaction_tracer.record_sql': 'raw', - 'strip_exception_messages.enabled': False, - 'custom_insights_events.enabled': False, - 'message_tracer.segment_parameters_enabled': False, + "high_security": True, + "capture_params": True, + "transaction_tracer.record_sql": "raw", + "strip_exception_messages.enabled": False, + "custom_insights_events.enabled": False, + "message_tracer.segment_parameters_enabled": False, + "application_logging.forwarding.enabled": True, }, ] @@ -158,7 +179,7 @@ def parameterize_hsm_local_config(settings_list): apply_config_setting(settings_object, name, value) settings_object_list.append(settings_object) - return pytest.mark.parametrize('settings', settings_object_list) + return pytest.mark.parametrize("settings", settings_object_list) @parameterize_hsm_local_config(_hsm_local_config_file_settings_disabled) @@ -167,8 +188,8 @@ def test_local_config_file_override_hsm_disabled(settings): original_record_sql = settings.transaction_tracer.record_sql original_strip_messages = settings.strip_exception_messages.enabled original_custom_events = settings.custom_insights_events.enabled - original_message_segment_params_enabled = ( - settings.message_tracer.segment_parameters_enabled) + original_message_segment_params_enabled = settings.message_tracer.segment_parameters_enabled + original_application_logging_forwarding_enabled = settings.application_logging.forwarding.enabled apply_local_high_security_mode_setting(settings) @@ -176,8 +197,8 @@ def test_local_config_file_override_hsm_disabled(settings): assert settings.transaction_tracer.record_sql == original_record_sql assert settings.strip_exception_messages.enabled == original_strip_messages assert settings.custom_insights_events.enabled == original_custom_events - assert (settings.message_tracer.segment_parameters_enabled == - original_message_segment_params_enabled) + assert settings.message_tracer.segment_parameters_enabled == original_message_segment_params_enabled + assert settings.application_logging.forwarding.enabled == original_application_logging_forwarding_enabled @parameterize_hsm_local_config(_hsm_local_config_file_settings_enabled) @@ -185,44 +206,49 @@ def test_local_config_file_override_hsm_enabled(settings): apply_local_high_security_mode_setting(settings) assert settings.capture_params not in (True, None) - assert settings.transaction_tracer.record_sql in ('off', 'obfuscated') + assert settings.transaction_tracer.record_sql in ("off", "obfuscated") assert settings.strip_exception_messages.enabled assert settings.custom_insights_events.enabled is False assert settings.message_tracer.segment_parameters_enabled is False + assert settings.application_logging.forwarding.enabled is False _server_side_config_settings_hsm_disabled = [ ( { - 'high_security': False, - 'capture_params': False, - 'transaction_tracer.record_sql': 'obfuscated', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': False, + "high_security": False, + "capture_params": False, + "transaction_tracer.record_sql": "obfuscated", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": False, + "application_logging.forwarding.enabled": False, }, { - u'agent_config': { - u'capture_params': True, - u'transaction_tracer.record_sql': u'raw', - u'strip_exception_messages.enabled': False, - u'custom_insights_events.enabled': True, + "agent_config": { + "capture_params": True, + "transaction_tracer.record_sql": "raw", + "strip_exception_messages.enabled": False, + "custom_insights_events.enabled": True, + "application_logging.forwarding.enabled": True, }, }, ), ( { - 'high_security': False, - 'capture_params': True, - 'transaction_tracer.record_sql': 'raw', - 'strip_exception_messages.enabled': False, - 'custom_insights_events.enabled': True, + "high_security": False, + "capture_params": True, + "transaction_tracer.record_sql": "raw", + "strip_exception_messages.enabled": False, + "custom_insights_events.enabled": True, + "application_logging.forwarding.enabled": True, }, { - u'agent_config': { - u'capture_params': False, - u'transaction_tracer.record_sql': u'off', - u'strip_exception_messages.enabled': True, - u'custom_insights_events.enabled': False, + "agent_config": { + "capture_params": False, + "transaction_tracer.record_sql": "off", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": False, + "application_logging.forwarding.enabled": False, }, }, ), @@ -231,242 +257,247 @@ def test_local_config_file_override_hsm_enabled(settings): _server_side_config_settings_hsm_enabled = [ ( { - 'high_security': True, - 'capture_params': False, - 'transaction_tracer.record_sql': 'obfuscated', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': False, + "high_security": True, + "capture_params": False, + "transaction_tracer.record_sql": "obfuscated", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": False, + "application_logging.forwarding.enabled": False, }, { - u'high_security': True, - u'capture_params': False, - u'transaction_tracer.record_sql': u'obfuscated', - u'strip_exception_messages.enabled': True, - u'custom_insights_events.enabled': False, - u'agent_config': { - u'capture_params': False, - u'transaction_tracer.record_sql': u'obfuscated', - u'strip_exception_messages.enabled': True, - u'custom_insights_events.enabled': False, + "high_security": True, + "capture_params": False, + "transaction_tracer.record_sql": "obfuscated", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": False, + "application_logging.forwarding.enabled": False, + "agent_config": { + "capture_params": False, + "transaction_tracer.record_sql": "obfuscated", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": False, + "application_logging.forwarding.enabled": False, }, }, ), ( { - 'high_security': True, - 'capture_params': False, - 'transaction_tracer.record_sql': 'obfuscated', - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': False, + "high_security": True, + "capture_params": False, + "transaction_tracer.record_sql": "obfuscated", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": False, + "application_logging.forwarding.enabled": False, }, { - u'high_security': True, - u'capture_params': False, - u'transaction_tracer.record_sql': u'obfuscated', - u'strip_exception_messages.enabled': True, - u'custom_insights_events.enabled': False, - u'agent_config': { - u'capture_params': True, - u'transaction_tracer.record_sql': u'raw', - u'strip_exception_messages.enabled': False, - u'custom_insights_events.enabled': True, + "high_security": True, + "capture_params": False, + "transaction_tracer.record_sql": "obfuscated", + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": False, + "application_logging.forwarding.enabled": False, + "agent_config": { + "capture_params": True, + "transaction_tracer.record_sql": "raw", + "strip_exception_messages.enabled": False, + "custom_insights_events.enabled": True, + "application_logging.forwarding.enabled": True, }, }, ), ] -@pytest.mark.parametrize('local_settings,server_settings', - _server_side_config_settings_hsm_disabled) +@pytest.mark.parametrize("local_settings,server_settings", _server_side_config_settings_hsm_disabled) def test_remote_config_fixups_hsm_disabled(local_settings, server_settings): - assert 'high_security' in local_settings - assert local_settings['high_security'] is False + assert "high_security" in local_settings + assert local_settings["high_security"] is False - assert u'high_security' not in server_settings + assert "high_security" not in server_settings - agent_config = server_settings['agent_config'] + agent_config = server_settings["agent_config"] - original_capture_params = agent_config['capture_params'] - original_record_sql = agent_config['transaction_tracer.record_sql'] - original_strip_messages = agent_config['strip_exception_messages.enabled'] - original_custom_events = agent_config['custom_insights_events.enabled'] + original_capture_params = agent_config["capture_params"] + original_record_sql = agent_config["transaction_tracer.record_sql"] + original_strip_messages = agent_config["strip_exception_messages.enabled"] + original_custom_events = agent_config["custom_insights_events.enabled"] + original_log_forwarding = agent_config["application_logging.forwarding.enabled"] _settings = global_settings() - settings = override_generic_settings(_settings, local_settings)( - AgentProtocol._apply_high_security_mode_fixups - )(server_settings, _settings) + settings = override_generic_settings(_settings, local_settings)(AgentProtocol._apply_high_security_mode_fixups)( + server_settings, _settings + ) - agent_config = settings['agent_config'] + agent_config = settings["agent_config"] - assert u'high_security' not in settings + assert "high_security" not in settings - assert agent_config['capture_params'] == original_capture_params - assert agent_config['transaction_tracer.record_sql'] == original_record_sql - assert agent_config['strip_exception_messages.enabled'] == \ - original_strip_messages - assert agent_config['custom_insights_events.enabled'] == \ - original_custom_events + assert agent_config["capture_params"] == original_capture_params + assert agent_config["transaction_tracer.record_sql"] == original_record_sql + assert agent_config["strip_exception_messages.enabled"] == original_strip_messages + assert agent_config["custom_insights_events.enabled"] == original_custom_events + assert agent_config["application_logging.forwarding.enabled"] == original_log_forwarding -@pytest.mark.parametrize('local_settings,server_settings', - _server_side_config_settings_hsm_enabled) +@pytest.mark.parametrize("local_settings,server_settings", _server_side_config_settings_hsm_enabled) def test_remote_config_fixups_hsm_enabled(local_settings, server_settings): - assert 'high_security' in local_settings - assert local_settings['high_security'] is True + assert "high_security" in local_settings + assert local_settings["high_security"] is True - assert u'high_security' in server_settings + assert "high_security" in server_settings _settings = global_settings() - settings = override_generic_settings(_settings, local_settings)( - AgentProtocol._apply_high_security_mode_fixups - )(server_settings, _settings) + settings = override_generic_settings(_settings, local_settings)(AgentProtocol._apply_high_security_mode_fixups)( + server_settings, _settings + ) - agent_config = settings['agent_config'] + agent_config = settings["agent_config"] - assert u'high_security' not in settings - assert u'capture_params' not in settings - assert u'transaction_tracer.record_sql' not in settings - assert u'strip_exception_messages.enabled' not in settings - assert u'custom_insights_events.enabled' not in settings + assert "high_security" not in settings + assert "capture_params" not in settings + assert "transaction_tracer.record_sql" not in settings + assert "strip_exception_messages.enabled" not in settings + assert "custom_insights_events.enabled" not in settings + assert "application_logging.forwarding.enabled" not in settings - assert u'capture_params' not in agent_config - assert u'transaction_tracer.record_sql' not in agent_config - assert u'strip_exception_messages.enabled' not in agent_config - assert u'custom_insights_events.enabled' not in agent_config + assert "capture_params" not in agent_config + assert "transaction_tracer.record_sql" not in agent_config + assert "strip_exception_messages.enabled" not in agent_config + assert "custom_insights_events.enabled" not in agent_config + assert "application_logging.forwarding.enabled" not in agent_config def test_remote_config_hsm_fixups_server_side_disabled(): - local_settings = {'high_security': True} - server_settings = {'high_security': True} + local_settings = {"high_security": True} + server_settings = {"high_security": True} _settings = global_settings() - settings = override_generic_settings(_settings, local_settings)( - AgentProtocol._apply_high_security_mode_fixups - )(server_settings, _settings) + settings = override_generic_settings(_settings, local_settings)(AgentProtocol._apply_high_security_mode_fixups)( + server_settings, _settings + ) - assert 'high_security' not in settings + assert "high_security" not in settings -_test_transaction_settings_hsm_disabled = {'high_security': False} +_test_transaction_settings_hsm_disabled = {"high_security": False} # Normally, in HSM the exception message would be stripped just by turning on # high_security. However, these tests (like all of our tests) overrides the # settings after agent initialization where this setting is fixed up. -_test_transaction_settings_hsm_enabled = {'high_security': True, - 'strip_exception_messages.enabled': True, - 'custom_insights_events.enabled': False} +_test_transaction_settings_hsm_enabled = { + "high_security": True, + "strip_exception_messages.enabled": True, + "custom_insights_events.enabled": False, +} @override_application_settings(_test_transaction_settings_hsm_disabled) -@validate_custom_parameters(required_params=[('key', 'value')]) +@validate_custom_parameters(required_params=[("key", "value")]) @background_task() def test_other_transaction_custom_parameters_hsm_disabled(): - add_custom_parameter('key', 'value') + add_custom_parameter("key", "value") @override_application_settings(_test_transaction_settings_hsm_disabled) -@validate_custom_parameters(required_params=[('key-1', 'value-1'), - ('key-2', 'value-2')]) +@validate_custom_parameters(required_params=[("key-1", "value-1"), ("key-2", "value-2")]) @background_task() def test_other_transaction_multiple_custom_parameters_hsm_disabled(): transaction = current_transaction() - transaction.add_custom_parameters([('key-1', 'value-1'), - ('key-2', 'value-2')]) + transaction.add_custom_parameters([("key-1", "value-1"), ("key-2", "value-2")]) @override_application_settings(_test_transaction_settings_hsm_enabled) -@validate_custom_parameters(forgone_params=[('key', 'value')]) +@validate_custom_parameters(forgone_params=[("key", "value")]) @background_task() def test_other_transaction_custom_parameters_hsm_enabled(): - add_custom_parameter('key', 'value') + add_custom_parameter("key", "value") @override_application_settings(_test_transaction_settings_hsm_enabled) -@validate_custom_parameters(forgone_params=[('key-1', 'value-1'), - ('key-2', 'value-2')]) +@validate_custom_parameters(forgone_params=[("key-1", "value-1"), ("key-2", "value-2")]) @background_task() def test_other_transaction_multiple_custom_parameters_hsm_enabled(): transaction = current_transaction() - transaction.add_custom_parameters([('key-1', 'value-1'), - ('key-2', 'value-2')]) + transaction.add_custom_parameters([("key-1", "value-1"), ("key-2", "value-2")]) class TestException(Exception): pass -_test_exception_name = '%s:%s' % (__name__, TestException.__name__) +_test_exception_name = "%s:%s" % (__name__, TestException.__name__) @override_application_settings(_test_transaction_settings_hsm_disabled) -@validate_transaction_errors(errors=[(_test_exception_name, 'test message')], - required_params=[('key-2', 'value-2')]) -@validate_custom_parameters(required_params=[('key-1', 'value-1')]) +@validate_transaction_errors(errors=[(_test_exception_name, "test message")], required_params=[("key-2", "value-2")]) +@validate_custom_parameters(required_params=[("key-1", "value-1")]) @background_task() def test_other_transaction_error_parameters_hsm_disabled(): - add_custom_parameter('key-1', 'value-1') + add_custom_parameter("key-1", "value-1") try: - raise TestException('test message') + raise TestException("test message") except Exception: - notice_error(attributes={'key-2': 'value-2'}) + notice_error(attributes={"key-2": "value-2"}) @override_application_settings(_test_transaction_settings_hsm_enabled) -@validate_transaction_errors(errors=[(_test_exception_name, - STRIP_EXCEPTION_MESSAGE)], forgone_params=[('key-2', 'value-2')]) -@validate_custom_parameters(forgone_params=[('key-1', 'value-1')]) +@validate_transaction_errors( + errors=[(_test_exception_name, STRIP_EXCEPTION_MESSAGE)], forgone_params=[("key-2", "value-2")] +) +@validate_custom_parameters(forgone_params=[("key-1", "value-1")]) @background_task() def test_other_transaction_error_parameters_hsm_enabled(): - add_custom_parameter('key-1', 'value-1') + add_custom_parameter("key-1", "value-1") try: - raise TestException('test message') + raise TestException("test message") except Exception: - notice_error(attributes={'key-2': 'value-2'}) + notice_error(attributes={"key-2": "value-2"}) _err_message = "Error! :(" -_intrinsic_attributes = {'error.class': callable_name(TestException), - 'error.message': _err_message, "error.expected": False} +_intrinsic_attributes = { + "error.class": callable_name(TestException), + "error.message": _err_message, + "error.expected": False, +} @reset_core_stats_engine() @override_application_settings(_test_transaction_settings_hsm_disabled) -@validate_non_transaction_error_event( - required_intrinsics=_intrinsic_attributes, - required_user={'key-1': 'value-1'}) +@validate_non_transaction_error_event(required_intrinsics=_intrinsic_attributes, required_user={"key-1": "value-1"}) def test_non_transaction_error_parameters_hsm_disabled(): try: raise TestException(_err_message) except Exception: app = application() - notice_error(attributes={'key-1': 'value-1'}, application=app) + notice_error(attributes={"key-1": "value-1"}, application=app) -_intrinsic_attributes = {'error.class': callable_name(TestException), - 'error.message': STRIP_EXCEPTION_MESSAGE, "error.expected": False} +_intrinsic_attributes = { + "error.class": callable_name(TestException), + "error.message": STRIP_EXCEPTION_MESSAGE, + "error.expected": False, +} @reset_core_stats_engine() @override_application_settings(_test_transaction_settings_hsm_enabled) -@validate_non_transaction_error_event( - required_intrinsics=_intrinsic_attributes, - forgone_user={'key-1': 'value-1'}) +@validate_non_transaction_error_event(required_intrinsics=_intrinsic_attributes, forgone_user={"key-1": "value-1"}) def test_non_transaction_error_parameters_hsm_enabled(): try: raise TestException(_err_message) except Exception: app = application() - notice_error(attributes={'key-1': 'value-1'}, application=app) + notice_error(attributes={"key-1": "value-1"}, application=app) @wsgi_application() def target_wsgi_application_capture_params(environ, start_response): - status = '200 OK' - output = b'Hello World!' + status = "200 OK" + output = b"Hello World!" - response_headers = [('Content-Type', 'text/plain; charset=utf-8'), - ('Content-Length', str(len(output)))] + response_headers = [("Content-Type", "text/plain; charset=utf-8"), ("Content-Length", str(len(output)))] start_response(status, response_headers) return [output] @@ -474,81 +505,71 @@ def target_wsgi_application_capture_params(environ, start_response): @wsgi_application() def target_wsgi_application_capture_params_api_called(environ, start_response): - status = '200 OK' - output = b'Hello World!' + status = "200 OK" + output = b"Hello World!" capture_request_params(True) - response_headers = [('Content-Type', 'text/plain; charset=utf-8'), - ('Content-Length', str(len(output)))] + response_headers = [("Content-Type", "text/plain; charset=utf-8"), ("Content-Length", str(len(output)))] start_response(status, response_headers) return [output] -_test_transaction_settings_hsm_enabled_capture_params = {'high_security': True, - 'capture_params': False} +_test_transaction_settings_hsm_enabled_capture_params = {"high_security": True, "capture_params": False} -@override_application_settings( - _test_transaction_settings_hsm_enabled_capture_params) +@override_application_settings(_test_transaction_settings_hsm_enabled_capture_params) @validate_request_params_omitted() def test_transaction_hsm_enabled_environ_capture_request_params(): - target_application = webtest.TestApp( - target_wsgi_application_capture_params) + target_application = webtest.TestApp(target_wsgi_application_capture_params) - target_application.get('/', params='key-1=value-1') + target_application.get("/", params="key-1=value-1") -@override_application_settings( - _test_transaction_settings_hsm_enabled_capture_params) +@override_application_settings(_test_transaction_settings_hsm_enabled_capture_params) @validate_request_params_omitted() def test_transaction_hsm_enabled_environ_capture_request_params_disabled(): - target_application = webtest.TestApp( - target_wsgi_application_capture_params) + target_application = webtest.TestApp(target_wsgi_application_capture_params) environ = {} - environ['newrelic.capture_request_params'] = False + environ["newrelic.capture_request_params"] = False - target_application.get('/', params='key-1=value-1', extra_environ=environ) + target_application.get("/", params="key-1=value-1", extra_environ=environ) -@override_application_settings( - _test_transaction_settings_hsm_enabled_capture_params) +@override_application_settings(_test_transaction_settings_hsm_enabled_capture_params) @validate_request_params_omitted() def test_transaction_hsm_enabled_environ_capture_request_params_enabled(): - target_application = webtest.TestApp( - target_wsgi_application_capture_params) + target_application = webtest.TestApp(target_wsgi_application_capture_params) environ = {} - environ['newrelic.capture_request_params'] = True + environ["newrelic.capture_request_params"] = True - target_application.get('/', params='key-1=value-1', extra_environ=environ) + target_application.get("/", params="key-1=value-1", extra_environ=environ) -@override_application_settings( - _test_transaction_settings_hsm_enabled_capture_params) +@override_application_settings(_test_transaction_settings_hsm_enabled_capture_params) @validate_request_params_omitted() def test_transaction_hsm_enabled_environ_capture_request_params_api_called(): - target_application = webtest.TestApp( - target_wsgi_application_capture_params_api_called) + target_application = webtest.TestApp(target_wsgi_application_capture_params_api_called) - target_application.get('/', params='key-1=value-1') + target_application.get("/", params="key-1=value-1") # Custom events -_event_type = 'SimpleAppEvent' -_params = {'snowman': u'\u2603', 'foo': 'bar'} +_event_type = "SimpleAppEvent" +_params = {"snowman": "\u2603", "foo": "bar"} @wsgi_application() def simple_custom_event_app(environ, start_response): record_custom_event(_event_type, _params) - start_response(status='200 OK', response_headers=[]) + start_response(status="200 OK", response_headers=[]) return [] -_intrinsics = {'type': _event_type, 'timestamp': time.time()} +_intrinsics = {"type": _event_type, "timestamp": time.time()} _required_event = [_intrinsics, _params] @@ -558,7 +579,7 @@ def simple_custom_event_app(environ, start_response): @override_application_settings(_test_transaction_settings_hsm_disabled) def test_custom_event_hsm_disabled(): target_application = webtest.TestApp(simple_custom_event_app) - target_application.get('/') + target_application.get("/") @reset_core_stats_engine() @@ -566,77 +587,69 @@ def test_custom_event_hsm_disabled(): @override_application_settings(_test_transaction_settings_hsm_enabled) def test_custom_event_hsm_enabled(): target_application = webtest.TestApp(simple_custom_event_app) - target_application.get('/') + target_application.get("/") # Make sure we don't display the query string in 'request.headers.referer' # Attribute will exist, and value will have query string stripped off. _required_attr = Attribute( - name='request.headers.referer', - value='http://example.com/blah', - destinations=DST_TRANSACTION_TRACER | DST_ERROR_COLLECTOR) + name="request.headers.referer", + value="http://example.com/blah", + destinations=DST_TRANSACTION_TRACER | DST_ERROR_COLLECTOR, +) # Check that the unsanitized version isn't present either, for any # destinations. _forgone_attr = Attribute( - name='request.headers.referer', - value='http://example.com/blah?query=value', - destinations=DST_ALL) + name="request.headers.referer", value="http://example.com/blah?query=value", destinations=DST_ALL +) _required_attrs = [_required_attr] _foregone_attrs = [_forgone_attr] -@override_application_settings( - _test_transaction_settings_hsm_enabled_capture_params) -@validate_attributes_complete('agent', _required_attrs, _foregone_attrs) +@override_application_settings(_test_transaction_settings_hsm_enabled_capture_params) +@validate_attributes_complete("agent", _required_attrs, _foregone_attrs) def test_http_referrer_url_is_sanitized_in_hsm(): - target_application = webtest.TestApp( - target_wsgi_application_capture_params) + target_application = webtest.TestApp(target_wsgi_application_capture_params) environ = {} - environ['HTTP_REFERER'] = 'http://example.com/blah?query=value' + environ["HTTP_REFERER"] = "http://example.com/blah?query=value" - target_application.get('/', extra_environ=environ) + target_application.get("/", extra_environ=environ) -@pytest.mark.parametrize('hsm_enabled', [True, False]) +@pytest.mark.parametrize("hsm_enabled", [True, False]) def test_function_trace_params_dropped_in_hsm(hsm_enabled): @background_task() def _test(): - with FunctionTrace('trace', - params={'secret': 'super secret'}): + with FunctionTrace("trace", params={"secret": "super secret"}): pass if hsm_enabled: - _test = override_application_settings( - _test_transaction_settings_hsm_enabled_capture_params)(_test) - _test = validate_tt_segment_params(forgone_params=('secret',))(_test) + _test = override_application_settings(_test_transaction_settings_hsm_enabled_capture_params)(_test) + _test = validate_tt_segment_params(forgone_params=("secret",))(_test) else: - _test = override_application_settings( - _test_transaction_settings_hsm_disabled)(_test) - _test = validate_tt_segment_params(present_params=('secret',))(_test) + _test = override_application_settings(_test_transaction_settings_hsm_disabled)(_test) + _test = validate_tt_segment_params(present_params=("secret",))(_test) _test() -@pytest.mark.parametrize('hsm_enabled', [True, False]) +@pytest.mark.parametrize("hsm_enabled", [True, False]) def test_message_trace_params_dropped_in_hsm(hsm_enabled): @background_task() def _test(): - with MessageTrace('library', 'operation', - 'dest_type', 'dest_name', params={'secret': 'super secret'}): + with MessageTrace("library", "operation", "dest_type", "dest_name", params={"secret": "super secret"}): pass if hsm_enabled: - _test = override_application_settings( - _test_transaction_settings_hsm_enabled_capture_params)(_test) - _test = validate_tt_segment_params(forgone_params=('secret',))(_test) + _test = override_application_settings(_test_transaction_settings_hsm_enabled_capture_params)(_test) + _test = validate_tt_segment_params(forgone_params=("secret",))(_test) else: - _test = override_application_settings( - _test_transaction_settings_hsm_disabled)(_test) - _test = validate_tt_segment_params(present_params=('secret',))(_test) + _test = override_application_settings(_test_transaction_settings_hsm_disabled)(_test) + _test = validate_tt_segment_params(present_params=("secret",))(_test) _test() diff --git a/tests/agent_features/test_log_events.py b/tests/agent_features/test_log_events.py new file mode 100644 index 0000000000..bb173d6c4e --- /dev/null +++ b/tests/agent_features/test_log_events.py @@ -0,0 +1,185 @@ +# 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 newrelic.api.background_task import background_task +from newrelic.api.time_trace import current_trace +from newrelic.api.transaction import current_transaction, record_log_event, ignore_transaction +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 + + +def set_trace_ids(): + txn = current_transaction() + if txn: + txn._trace_id = "abcdefgh12345678" + trace = current_trace() + if trace: + trace.guid = "abcdefgh" + + +def exercise_record_log_event(message="A"): + set_trace_ids() + + record_log_event(message, "ERROR") + +enable_log_forwarding = override_application_settings({"application_logging.forwarding.enabled": True}) +disable_log_forwarding = override_application_settings({"application_logging.forwarding.enabled": False}) + +_common_attributes_service_linking = {"timestamp": None, "hostname": None, "entity.name": "Python Agent Test (agent_features)", "entity.guid": None} +_common_attributes_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"} +_common_attributes_trace_linking.update(_common_attributes_service_linking) +_test_record_log_event_inside_transaction_events = [{"message": "A", "level": "ERROR"}] +_test_record_log_event_inside_transaction_events[0].update(_common_attributes_trace_linking) + +@enable_log_forwarding +def test_record_log_event_inside_transaction(): + @validate_log_events(_test_record_log_event_inside_transaction_events) + @validate_log_event_count(1) + @background_task() + def test(): + exercise_record_log_event() + + test() + + +_test_record_log_event_outside_transaction_events = [{"message": "A", "level": "ERROR"}] +_test_record_log_event_outside_transaction_events[0].update(_common_attributes_service_linking) + +@enable_log_forwarding +@reset_core_stats_engine() +def test_record_log_event_outside_transaction(): + @validate_log_events_outside_transaction(_test_record_log_event_outside_transaction_events) + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_record_log_event() + + test() + + +_test_record_log_event_unknown_level_inside_transaction_events = [{"message": "A", "level": "UNKNOWN"}] +_test_record_log_event_unknown_level_inside_transaction_events[0].update(_common_attributes_trace_linking) + +@enable_log_forwarding +def test_record_log_event_unknown_level_inside_transaction(): + @validate_log_events(_test_record_log_event_unknown_level_inside_transaction_events) + @validate_log_event_count(1) + @background_task() + def test(): + set_trace_ids() + record_log_event("A") + + test() + + +_test_record_log_event_unknown_level_outside_transaction_events = [{"message": "A", "level": "UNKNOWN"}] +_test_record_log_event_unknown_level_outside_transaction_events[0].update(_common_attributes_service_linking) + +@enable_log_forwarding +@reset_core_stats_engine() +def test_record_log_event_unknown_level_outside_transaction(): + @validate_log_events_outside_transaction(_test_record_log_event_unknown_level_outside_transaction_events) + @validate_log_event_count_outside_transaction(1) + def test(): + set_trace_ids() + record_log_event("A") + + test() + + +@enable_log_forwarding +def test_record_log_event_empty_message_inside_transaction(): + @validate_log_event_count(0) + @background_task() + def test(): + exercise_record_log_event("") + + test() + + +@enable_log_forwarding +@reset_core_stats_engine() +def test_record_log_event_empty_message_outside_transaction(): + @validate_log_event_count_outside_transaction(0) + def test(): + exercise_record_log_event("") + + test() + + +@enable_log_forwarding +def test_record_log_event_whitespace_inside_transaction(): + @validate_log_event_count(0) + @background_task() + def test(): + exercise_record_log_event(" ") + + test() + + +@enable_log_forwarding +@reset_core_stats_engine() +def test_record_log_event_whitespace_outside_transaction(): + @validate_log_event_count_outside_transaction(0) + def test(): + exercise_record_log_event(" ") + + test() + + +@enable_log_forwarding +def test_ignored_transaction_logs_not_forwarded(): + @validate_log_event_count(0) + @background_task() + def test(): + ignore_transaction() + exercise_record_log_event() + + test() + + +_test_log_event_truncation_events = [{"message": "A" * 32768, "level": "ERROR"}] +_test_log_event_truncation_events[0].update(_common_attributes_trace_linking) + +@enable_log_forwarding +def test_log_event_truncation(): + @validate_log_events(_test_log_event_truncation_events) + @validate_log_event_count(1) + @background_task() + def test(): + exercise_record_log_event("A" * 33000) + + test() + + +@disable_log_forwarding +def test_record_log_event_inside_transaction(): + @validate_log_event_count(0) + @background_task() + def test(): + exercise_record_log_event() + + test() + + +@disable_log_forwarding +@reset_core_stats_engine() +def test_record_log_event_outside_transaction(): + @validate_log_event_count_outside_transaction(0) + def test(): + exercise_record_log_event() + + test() diff --git a/tests/agent_features/test_logs_in_context.py b/tests/agent_features/test_logs_in_context.py index 83b0eadcc5..90b6c92672 100644 --- a/tests/agent_features/test_logs_in_context.py +++ b/tests/agent_features/test_logs_in_context.py @@ -87,7 +87,8 @@ def test_newrelic_logger_no_error(log_buffer): assert filename.endswith("/test_logs_in_context.py") assert isinstance(line_number, int) - assert message == { + expected = { + u"entity.name": u"Python Agent Test (agent_features)", u"entity.type": u"SERVICE", u"message": u"Hello World", u"log.level": u"INFO", @@ -107,6 +108,16 @@ def test_newrelic_logger_no_error(log_buffer): u"second": u"baz", }, } + expected_extra_txn_keys = ( + "entity.guid", + "hostname", + ) + + for k, v in expected.items(): + assert message.pop(k) == v + + assert set(message.keys()) == set(expected_extra_txn_keys) + class ExceptionForTest(ValueError): @@ -151,6 +162,7 @@ def test_newrelic_logger_error_inside_transaction(log_buffer): "trace.id", "span.id", "entity.guid", + "hostname", ) for k, v in expected.items(): @@ -180,7 +192,8 @@ def test_newrelic_logger_error_outside_transaction(log_buffer): assert filename.endswith("/test_logs_in_context.py") assert isinstance(line_number, int) - assert message == { + expected = { + u"entity.name": u"Python Agent Test (agent_features)", u"entity.type": u"SERVICE", u"message": u"oops", u"log.level": u"ERROR", @@ -190,6 +203,16 @@ def test_newrelic_logger_error_outside_transaction(log_buffer): u"error.class": u"test_logs_in_context:ExceptionForTest", u"error.message": u"", } + expected_extra_txn_keys = ( + "entity.guid", + "hostname", + ) + + for k, v in expected.items(): + assert message.pop(k) == v + + assert set(message.keys()) == set(expected_extra_txn_keys) + EXPECTED_KEYS_TXN = ( @@ -198,9 +221,15 @@ def test_newrelic_logger_error_outside_transaction(log_buffer): "entity.name", "entity.type", "entity.guid", + "hostname", ) -EXPECTED_KEYS_NO_TXN = EXPECTED_KEYS_TRACE_ENDED = ("entity.type",) +EXPECTED_KEYS_NO_TXN = EXPECTED_KEYS_TRACE_ENDED = ( + "entity.name", + "entity.type", + "entity.guid", + "hostname", +) def validate_metadata(metadata, expected): diff --git a/tests/agent_unittests/test_agent_connect.py b/tests/agent_unittests/test_agent_connect.py index abbd7d2f7c..46c4edf446 100644 --- a/tests/agent_unittests/test_agent_connect.py +++ b/tests/agent_unittests/test_agent_connect.py @@ -12,12 +12,17 @@ # See the License for the specific language governing permissions and # limitations under the License. +import pytest from newrelic.core.application import Application from newrelic.core.config import global_settings from newrelic.network.exceptions import ForceAgentDisconnect -from testing_support.fixtures import (override_generic_settings, - failing_endpoint) +from testing_support.fixtures import ( + override_generic_settings, + validate_internal_metrics, + failing_endpoint +) + SETTINGS = global_settings() @@ -34,3 +39,38 @@ def test_http_gone_stops_connect(): # The agent must not reattempt a connection after a ForceAgentDisconnect. # If it does, we'll end up with a session here. assert not app._active_session + + +_logging_settings_matrix = [ + (True, True), + (True, False), + (False, True), + (False, False), +] + + +@override_generic_settings(SETTINGS, { + 'developer_mode': True, +}) +@pytest.mark.parametrize("feature_setting,subfeature_setting", _logging_settings_matrix) +def test_logging_connect_supportability_metrics(feature_setting, subfeature_setting): + metric_value = "enabled" if feature_setting and subfeature_setting else "disabled" + + @override_generic_settings(SETTINGS, { + "application_logging.enabled": feature_setting, + "application_logging.forwarding.enabled": subfeature_setting, + "application_logging.metrics.enabled": subfeature_setting, + "application_logging.local_decorating.enabled": subfeature_setting, + }) + @validate_internal_metrics([ + ("Supportability/Logging/Forwarding/Python/%s" % metric_value, 1), + ("Supportability/Logging/LocalDecorating/Python/%s" % metric_value, 1), + ("Supportability/Logging/Metrics/Python/%s" % metric_value, 1), + ]) + def test(): + app = Application('Python Agent Test (agent_unittests-connect)') + app.connect_to_data_collector(None) + + assert app._active_session + + test() diff --git a/tests/agent_unittests/test_harvest_loop.py b/tests/agent_unittests/test_harvest_loop.py index a5e6b67b57..7a1f1702d0 100644 --- a/tests/agent_unittests/test_harvest_loop.py +++ b/tests/agent_unittests/test_harvest_loop.py @@ -30,6 +30,7 @@ from newrelic.core.custom_event import create_custom_event from newrelic.core.error_node import ErrorNode from newrelic.core.function_node import FunctionNode +from newrelic.core.log_event_node import LogEventNode from newrelic.core.root_node import RootNode from newrelic.core.stats_engine import CustomMetrics, SampledDataSet from newrelic.core.transaction_node import TransactionNode @@ -48,6 +49,11 @@ def transaction_node(request): event = create_custom_event("Custom", {}) custom_events.add(event) + log_events = SampledDataSet(capacity=num_events) + for _ in range(num_events): + event = LogEventNode(1653609717, "WARNING", "A", {}) + log_events.add(event) + error = ErrorNode( timestamp=0, type="foo:bar", @@ -117,6 +123,7 @@ def transaction_node(request): errors=errors, slow_sql=(), custom_events=custom_events, + log_events=log_events, apdex_t=0.5, suppress_apdex=False, custom_metrics=CustomMetrics(), @@ -438,6 +445,7 @@ def _test(): "license_key": "**NOT A LICENSE KEY**", "feature_flag": set(), "collect_custom_events": False, + "application_logging.forwarding.enabled": False, }, ) def test_transaction_count(transaction_node): @@ -509,9 +517,11 @@ def test_adaptive_sampling(transaction_node, monkeypatch): "license_key": "**NOT A LICENSE KEY**", "feature_flag": set(), "distributed_tracing.enabled": True, + "application_logging.forwarding.enabled": True, "event_harvest_config.harvest_limits.error_event_data": 1000, "event_harvest_config.harvest_limits.span_event_data": 1000, "event_harvest_config.harvest_limits.custom_event_data": 1000, + "event_harvest_config.harvest_limits.log_event_data": 1000, }, ) def test_reservoir_sizes(transaction_node): @@ -524,6 +534,7 @@ def test_reservoir_sizes(transaction_node): # Test that the samples have been recorded assert app._stats_engine.custom_events.num_samples == 101 assert app._stats_engine.error_events.num_samples == 101 + assert app._stats_engine.log_events.num_samples == 101 # Add 1 for the root span assert app._stats_engine.span_events.num_samples == 102 @@ -535,6 +546,7 @@ def test_reservoir_sizes(transaction_node): ("analytic_event_data", "transaction_events"), ("error_event_data", "error_events"), ("custom_event_data", "custom_events"), + ("log_event_data", "log_events"), ("span_event_data", "span_events"), ], ) @@ -558,14 +570,16 @@ def test_reservoir_size_zeros(harvest_name, event_name): app._stats_engine.transaction_events.add("transaction event") app._stats_engine.error_events.add("error event") app._stats_engine.custom_events.add("custom event") + app._stats_engine.log_events.add(LogEventNode(1653609717, "WARNING", "A", {})) app._stats_engine.span_events.add("span event") assert app._stats_engine.transaction_events.num_seen == 1 assert app._stats_engine.error_events.num_seen == 1 assert app._stats_engine.custom_events.num_seen == 1 + assert app._stats_engine.log_events.num_seen == 1 assert app._stats_engine.span_events.num_seen == 1 - stat_events = set(("transaction_events", "error_events", "custom_events", "span_events")) + stat_events = set(("transaction_events", "error_events", "custom_events", "log_events", "span_events")) for stat_event in stat_events: event = getattr(app._stats_engine, stat_event) @@ -580,6 +594,7 @@ def test_reservoir_size_zeros(harvest_name, event_name): assert app._stats_engine.transaction_events.num_seen == 0 assert app._stats_engine.error_events.num_seen == 0 assert app._stats_engine.custom_events.num_seen == 0 + assert app._stats_engine.log_events.num_seen == 0 assert app._stats_engine.span_events.num_seen == 0 @@ -783,7 +798,7 @@ def test_reset_synthetics_events(): @pytest.mark.parametrize( - "allowlist_event", ("analytic_event_data", "custom_event_data", "error_event_data", "span_event_data") + "allowlist_event", ("analytic_event_data", "custom_event_data", "log_event_data", "error_event_data", "span_event_data") ) @override_generic_settings( settings, @@ -802,12 +817,14 @@ def test_flexible_events_harvested(allowlist_event): app._stats_engine.transaction_events.add("transaction event") app._stats_engine.error_events.add("error event") app._stats_engine.custom_events.add("custom event") + app._stats_engine.log_events.add(LogEventNode(1653609717, "WARNING", "A", {})) app._stats_engine.span_events.add("span event") app._stats_engine.record_custom_metric("CustomMetric/Int", 1) assert app._stats_engine.transaction_events.num_seen == 1 assert app._stats_engine.error_events.num_seen == 1 assert app._stats_engine.custom_events.num_seen == 1 + assert app._stats_engine.log_events.num_seen == 1 assert app._stats_engine.span_events.num_seen == 1 assert app._stats_engine.record_custom_metric("CustomMetric/Int", 1) @@ -822,6 +839,9 @@ def test_flexible_events_harvested(allowlist_event): num_seen = 0 if (allowlist_event == "custom_event_data") else 1 assert app._stats_engine.custom_events.num_seen == num_seen + num_seen = 0 if (allowlist_event == "log_event_data") else 1 + assert app._stats_engine.log_events.num_seen == num_seen + num_seen = 0 if (allowlist_event == "span_event_data") else 1 assert app._stats_engine.span_events.num_seen == num_seen @@ -830,7 +850,7 @@ def test_flexible_events_harvested(allowlist_event): @pytest.mark.parametrize( - "allowlist_event", ("analytic_event_data", "custom_event_data", "error_event_data", "span_event_data") + "allowlist_event", ("analytic_event_data", "custom_event_data", "log_event_data", "error_event_data", "span_event_data") ) @override_generic_settings( settings, @@ -849,11 +869,13 @@ def test_default_events_harvested(allowlist_event): app._stats_engine.transaction_events.add("transaction event") app._stats_engine.error_events.add("error event") app._stats_engine.custom_events.add("custom event") + app._stats_engine.log_events.add(LogEventNode(1653609717, "WARNING", "A", {})) app._stats_engine.span_events.add("span event") assert app._stats_engine.transaction_events.num_seen == 1 assert app._stats_engine.error_events.num_seen == 1 assert app._stats_engine.custom_events.num_seen == 1 + assert app._stats_engine.log_events.num_seen == 1 assert app._stats_engine.span_events.num_seen == 1 assert app._stats_engine.metrics_count() == 0 @@ -868,6 +890,9 @@ def test_default_events_harvested(allowlist_event): num_seen = 0 if (allowlist_event != "custom_event_data") else 1 assert app._stats_engine.custom_events.num_seen == num_seen + num_seen = 0 if (allowlist_event != "log_event_data") else 1 + assert app._stats_engine.log_events.num_seen == num_seen + num_seen = 0 if (allowlist_event != "span_event_data") else 1 assert app._stats_engine.span_events.num_seen == num_seen diff --git a/tests/logger_logging/conftest.py b/tests/logger_logging/conftest.py new file mode 100644 index 0000000000..514a145959 --- /dev/null +++ b/tests/logger_logging/conftest.py @@ -0,0 +1,71 @@ +# 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 logging +import pytest + +from testing_support.fixtures import ( + code_coverage_fixture, + collector_agent_registration_fixture, + collector_available_fixture, +) + +_coverage_source = [ + "newrelic.hooks.logger_logging", +] + +code_coverage = code_coverage_fixture(source=_coverage_source) + +_default_settings = { + "transaction_tracer.explain_threshold": 0.0, + "transaction_tracer.transaction_threshold": 0.0, + "transaction_tracer.stack_trace_threshold": 0.0, + "debug.log_data_collector_payloads": True, + "debug.record_transaction_failure": True, + "application_logging.enabled": True, + "application_logging.forwarding.enabled": True, + "application_logging.metrics.enabled": True, + "application_logging.local_decorating.enabled": True, + "event_harvest_config.harvest_limits.log_event_data": 100000, +} + +collector_agent_registration = collector_agent_registration_fixture( + app_name="Python Agent Test (logger_logging)", + default_settings=_default_settings, +) + + +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) + + def emit(self, record): + self.records.append(self.format(record)) + + +@pytest.fixture(scope="function") +def logger(): + _logger = logging.getLogger("my_app") + caplog = CaplogHandler() + _logger.addHandler(caplog) + _logger.caplog = caplog + _logger.setLevel(logging.WARNING) + yield _logger + del caplog.records[:] + _logger.removeHandler(caplog) diff --git a/tests/logger_logging/test_local_decorating.py b/tests/logger_logging/test_local_decorating.py new file mode 100644 index 0000000000..32a47e9045 --- /dev/null +++ b/tests/logger_logging/test_local_decorating.py @@ -0,0 +1,70 @@ +# 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 platform + +from newrelic.api.application import application_settings +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 + + +def set_trace_ids(): + txn = current_transaction() + if txn: + txn._trace_id = "abcdefgh12345678" + trace = current_trace() + if trace: + trace.guid = "abcdefgh" + +def exercise_logging(logger): + set_trace_ids() + + logger.warning("C") + + +def get_metadata_string(log_message, is_txn): + host = platform.uname()[1] + assert host + entity_guid = application_settings().entity_guid + if is_txn: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|abcdefgh12345678|abcdefgh|Python%20Agent%20Test%20%28logger_logging%29|')) + else: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|||Python%20Agent%20Test%20%28logger_logging%29|')) + formatted_string = log_message + " " + metadata_string + return formatted_string + + +@reset_core_stats_engine() +def test_local_log_decoration_inside_transaction(logger): + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging(logger) + assert logger.caplog.records[0] == get_metadata_string('C', True) + + test() + + +@reset_core_stats_engine() +def test_local_log_decoration_outside_transaction(logger): + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_logging(logger) + assert logger.caplog.records[0] == get_metadata_string('C', False) + + test() diff --git a/tests/logger_logging/test_log_forwarding.py b/tests/logger_logging/test_log_forwarding.py new file mode 100644 index 0000000000..ee6c689b76 --- /dev/null +++ b/tests/logger_logging/test_log_forwarding.py @@ -0,0 +1,101 @@ +# 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 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_events import validate_log_events +from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction + + +def set_trace_ids(): + txn = current_transaction() + if txn: + txn._trace_id = "abcdefgh12345678" + trace = current_trace() + if trace: + trace.guid = "abcdefgh" + +def exercise_logging(logger): + set_trace_ids() + + logger.debug("A") + logger.info("B") + logger.warning("C") + logger.error("D") + logger.critical("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_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"} +_common_attributes_trace_linking.update(_common_attributes_service_linking) + +_test_logging_inside_transaction_events = [ + {"message": "C", "level": "WARNING"}, + {"message": "D", "level": "ERROR"}, + {"message": "E", "level": "CRITICAL"}, +] +update_all(_test_logging_inside_transaction_events, _common_attributes_trace_linking) + + +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() + + +_test_logging_outside_transaction_events = [ + {"message": "C", "level": "WARNING"}, + {"message": "D", "level": "ERROR"}, + {"message": "E", "level": "CRITICAL"}, +] +update_all(_test_logging_outside_transaction_events, _common_attributes_service_linking) + + +@reset_core_stats_engine() +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() + + +@reset_core_stats_engine() +def test_logging_newrelic_logs_not_forwarded(logger): + @validate_log_event_count(0) + @background_task() + def test(): + nr_logger = logging.getLogger("newrelic") + nr_logger.addHandler(logger.caplog) + nr_logger.error("A") + assert len(logger.caplog.records) == 1 + + test() diff --git a/tests/logger_logging/test_logging_handler.py b/tests/logger_logging/test_logging_handler.py new file mode 100644 index 0000000000..9bf488582e --- /dev/null +++ b/tests/logger_logging/test_logging_handler.py @@ -0,0 +1,68 @@ +# 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 conftest import logger as conf_logger +import logging +import pytest + +from newrelic.api.background_task import background_task +from newrelic.api.log import NewRelicLogForwardingHandler +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_function_called import validate_function_called + + + + +@pytest.fixture(scope="function") +def uninstrument_logging(): + instrumented = logging.Logger.callHandlers + while hasattr(logging.Logger.callHandlers, "__wrapped__"): + logging.Logger.callHandlers = logging.Logger.callHandlers.__wrapped__ + yield + logging.Logger.callHandlers = instrumented + + +@pytest.fixture(scope="function") +def logger(conf_logger, uninstrument_logging): + handler = NewRelicLogForwardingHandler() + conf_logger.addHandler(handler) + yield conf_logger + conf_logger.removeHandler(handler) + + +def exercise_logging(logger): + logger.warning("C") + assert len(logger.caplog.records) == 1 + + +def test_handler_inside_transaction(logger): + @validate_log_event_count(1) + @validate_function_called("newrelic.api.log", "NewRelicLogForwardingHandler.emit") + @background_task() + def test(): + exercise_logging(logger) + + test() + + +@reset_core_stats_engine() +def test_handler_outside_transaction(logger): + @validate_log_event_count_outside_transaction(1) + @validate_function_called("newrelic.api.log", "NewRelicLogForwardingHandler.emit") + def test(): + exercise_logging(logger) + + test() diff --git a/tests/logger_logging/test_metrics.py b/tests/logger_logging/test_metrics.py new file mode 100644 index 0000000000..eb9419daff --- /dev/null +++ b/tests/logger_logging/test_metrics.py @@ -0,0 +1,62 @@ +# 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 newrelic.packages import six +from newrelic.api.background_task import background_task +from testing_support.fixtures import reset_core_stats_engine +from testing_support.validators.validate_custom_metrics_outside_transaction import validate_custom_metrics_outside_transaction +from testing_support.fixtures import ( + validate_transaction_metrics, +) + + +def exercise_logging(logger): + logger.debug("A") + logger.info("B") + logger.warning("C") + logger.error("D") + logger.critical("E") + + assert len(logger.caplog.records) == 3 + + +_test_logging_unscoped_metrics = [ + ("Logging/lines", 3), + ("Logging/lines/WARNING", 1), + ("Logging/lines/ERROR", 1), + ("Logging/lines/CRITICAL", 1), +] + +@reset_core_stats_engine() +def test_logging_metrics_inside_transaction(logger): + txn_name = "test_metrics:test_logging_metrics_inside_transaction..test" if six.PY3 else "test_metrics:test" + @validate_transaction_metrics( + txn_name, + custom_metrics=_test_logging_unscoped_metrics, + background_task=True, + ) + @background_task() + def test(): + exercise_logging(logger) + + test() + + +@reset_core_stats_engine() +def test_logging_metrics_outside_transaction(logger): + @validate_custom_metrics_outside_transaction(_test_logging_unscoped_metrics) + def test(): + exercise_logging(logger) + + test() diff --git a/tests/logger_logging/test_settings.py b/tests/logger_logging/test_settings.py new file mode 100644 index 0000000000..2406d87c0b --- /dev/null +++ b/tests/logger_logging/test_settings.py @@ -0,0 +1,98 @@ +# 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 newrelic.packages import six +from newrelic.api.background_task import background_task +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.fixtures import ( + override_application_settings, + validate_transaction_metrics, +) + + +def basic_logging(logger): + logger.warning("C") + + +_settings_matrix = [ + (True, True, True), + (True, False, False), + (False, True, False), + (False, False, False), +] + + +@pytest.mark.parametrize("feature_setting,subfeature_setting,expected", _settings_matrix) +@reset_core_stats_engine() +def test_log_forwarding_settings(logger, feature_setting, subfeature_setting, expected): + @override_application_settings({ + "application_logging.enabled": feature_setting, + "application_logging.forwarding.enabled": subfeature_setting, + }) + @validate_log_event_count(1 if expected else 0) + @background_task() + def test(): + basic_logging(logger) + assert len(logger.caplog.records) == 1 + + test() + + +@pytest.mark.parametrize("feature_setting,subfeature_setting,expected", _settings_matrix) +@reset_core_stats_engine() +def test_local_decorating_settings(logger, feature_setting, subfeature_setting, expected): + @override_application_settings({ + "application_logging.enabled": feature_setting, + "application_logging.local_decorating.enabled": subfeature_setting, + }) + @background_task() + def test(): + basic_logging(logger) + assert len(logger.caplog.records) == 1 + message = logger.caplog.records.pop() + if expected: + assert len(message) > 1 + else: + assert len(message) == 1 + + test() + + +@pytest.mark.parametrize("feature_setting,subfeature_setting,expected", _settings_matrix) +@reset_core_stats_engine() +def test_log_metrics_settings(logger, feature_setting, subfeature_setting, expected): + metric_count = 1 if expected else None + txn_name = "test_settings:test_log_metrics_settings..test" if six.PY3 else "test_settings:test" + + @override_application_settings({ + "application_logging.enabled": feature_setting, + "application_logging.metrics.enabled": subfeature_setting, + }) + @validate_transaction_metrics( + txn_name, + custom_metrics=[ + ("Logging/lines", metric_count), + ("Logging/lines/WARNING", metric_count), + ], + background_task=True, + ) + @background_task() + def test(): + basic_logging(logger) + assert len(logger.caplog.records) == 1 + + test() diff --git a/tests/logger_loguru/conftest.py b/tests/logger_loguru/conftest.py new file mode 100644 index 0000000000..af632e3004 --- /dev/null +++ b/tests/logger_loguru/conftest.py @@ -0,0 +1,71 @@ +# 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 logging +import pytest + +from testing_support.fixtures import ( + code_coverage_fixture, + collector_agent_registration_fixture, + collector_available_fixture, +) + +_coverage_source = [ + "newrelic.hooks.logger_loguru", +] + +code_coverage = code_coverage_fixture(source=_coverage_source) + +_default_settings = { + "transaction_tracer.explain_threshold": 0.0, + "transaction_tracer.transaction_threshold": 0.0, + "transaction_tracer.stack_trace_threshold": 0.0, + "debug.log_data_collector_payloads": True, + "debug.record_transaction_failure": True, + "application_logging.enabled": True, + "application_logging.forwarding.enabled": True, + "application_logging.metrics.enabled": True, + "application_logging.local_decorating.enabled": True, + "event_harvest_config.harvest_limits.log_event_data": 100000, +} + +collector_agent_registration = collector_agent_registration_fixture( + app_name="Python Agent Test (logger_loguru)", + default_settings=_default_settings, +) + + +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) + + def emit(self, record): + self.records.append(self.format(record)) + + +@pytest.fixture(scope="function") +def logger(): + import loguru + _logger = loguru.logger + caplog = CaplogHandler() + handler_id = _logger.add(caplog, level="WARNING", format="{message}") + _logger.caplog = caplog + yield _logger + del caplog.records[:] + _logger.remove(handler_id) diff --git a/tests/logger_loguru/test_local_decorating.py b/tests/logger_loguru/test_local_decorating.py new file mode 100644 index 0000000000..915f683a8b --- /dev/null +++ b/tests/logger_loguru/test_local_decorating.py @@ -0,0 +1,85 @@ +# 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 platform + +from newrelic.api.application import application_settings +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 + + +def set_trace_ids(): + txn = current_transaction() + if txn: + txn._trace_id = "abcdefgh12345678" + trace = current_trace() + if trace: + trace.guid = "abcdefgh" + +def exercise_logging(logger): + set_trace_ids() + + logger.warning("C") + + +def get_metadata_string(log_message, is_txn): + host = platform.uname().node + assert host + entity_guid = application_settings().entity_guid + if is_txn: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|abcdefgh12345678|abcdefgh|Python%20Agent%20Test%20%28logger_loguru%29|')) + else: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|||Python%20Agent%20Test%20%28logger_loguru%29|')) + formatted_string = log_message + " " + metadata_string + return formatted_string + + +@reset_core_stats_engine() +def test_local_log_decoration_inside_transaction(logger): + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging(logger) + assert logger.caplog.records[0] == get_metadata_string('C', True) + + test() + + +@reset_core_stats_engine() +def test_local_log_decoration_outside_transaction(logger): + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_logging(logger) + assert logger.caplog.records[0] == get_metadata_string('C', False) + + test() + + +@reset_core_stats_engine() +def test_patcher_application_order(logger): + def patch(record): + record["message"] += "-PATCH" + return record + + @validate_log_event_count_outside_transaction(1) + def test(): + patch_logger = logger.patch(patch) + exercise_logging(patch_logger) + assert logger.caplog.records[0] == get_metadata_string('C-PATCH', False) + + test() diff --git a/tests/logger_loguru/test_log_forwarding.py b/tests/logger_loguru/test_log_forwarding.py new file mode 100644 index 0000000000..aa0414da25 --- /dev/null +++ b/tests/logger_loguru/test_log_forwarding.py @@ -0,0 +1,136 @@ +# 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 logging +import pytest + +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_events import validate_log_events +from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction + + +def set_trace_ids(): + txn = current_transaction() + if txn: + txn._trace_id = "abcdefgh12345678" + trace = current_trace() + if trace: + trace.guid = "abcdefgh" + +def exercise_logging(logger): + set_trace_ids() + + logger.warning("C") + logger.error("D") + logger.critical("E") + + assert len(logger.caplog.records) == 3 + + +_common_attributes_service_linking = {"timestamp": None, "hostname": None, "entity.name": "Python Agent Test (logger_loguru)", "entity.guid": None} +_common_attributes_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678", **_common_attributes_service_linking} + +_test_logging_inside_transaction_events = [ + {"message": "C", "level": "WARNING", **_common_attributes_trace_linking}, + {"message": "D", "level": "ERROR", **_common_attributes_trace_linking}, + {"message": "E", "level": "CRITICAL", **_common_attributes_trace_linking}, +] + + +@reset_core_stats_engine() +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() + + +_test_logging_outside_transaction_events = [ + {"message": "C", "level": "WARNING", **_common_attributes_service_linking}, + {"message": "D", "level": "ERROR", **_common_attributes_service_linking}, + {"message": "E", "level": "CRITICAL", **_common_attributes_service_linking}, +] + +@reset_core_stats_engine() +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() + + +@reset_core_stats_engine() +def test_logging_newrelic_logs_not_forwarded(logger): + @validate_log_event_count(0) + @background_task() + def test(): + nr_logger = logging.getLogger("newrelic") + nr_logger.addHandler(logger.caplog) + nr_logger.error("A") + assert len(logger.caplog.records) == 1 + + test() + + +_test_patcher_application_captured_event = {"message": "C-PATCH", "level": "WARNING"} +_test_patcher_application_captured_event.update(_common_attributes_trace_linking) + +@reset_core_stats_engine() +def test_patcher_application_captured(logger): + def patch(record): + record["message"] += "-PATCH" + return record + + @validate_log_events([_test_patcher_application_captured_event]) + @validate_log_event_count(1) + @background_task() + def test(): + set_trace_ids() + patch_logger = logger.patch(patch) + patch_logger.warning("C") + + test() + +_test_logger_catch_event = {"level": "ERROR"} # Message varies wildly, can't be included in test +_test_logger_catch_event.update(_common_attributes_trace_linking) + +@reset_core_stats_engine() +def test_logger_catch(logger): + @validate_log_events([_test_logger_catch_event]) + @validate_log_event_count(1) + @background_task() + def test(): + set_trace_ids() + + @logger.catch(reraise=True) + def throw(): + raise ValueError("Test") + + try: + with pytest.raises(ValueError): + throw() + except ValueError: + pass + + test() diff --git a/tests/logger_loguru/test_metrics.py b/tests/logger_loguru/test_metrics.py new file mode 100644 index 0000000000..c8a9299c86 --- /dev/null +++ b/tests/logger_loguru/test_metrics.py @@ -0,0 +1,59 @@ +# 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 newrelic.api.background_task import background_task +from testing_support.fixtures import reset_core_stats_engine +from testing_support.validators.validate_custom_metrics_outside_transaction import validate_custom_metrics_outside_transaction +from testing_support.fixtures import ( + validate_transaction_metrics, +) + + +def exercise_logging(logger): + logger.warning("C") + logger.error("D") + logger.critical("E") + + assert len(logger.caplog.records) == 3 + + +_test_logging_unscoped_metrics = [ + ("Logging/lines", 3), + ("Logging/lines/WARNING", 1), + ("Logging/lines/ERROR", 1), + ("Logging/lines/CRITICAL", 1), +] + +@reset_core_stats_engine() +def test_logging_metrics_inside_transaction(logger): + @validate_transaction_metrics( + "test_metrics:test_logging_metrics_inside_transaction..test", + custom_metrics=_test_logging_unscoped_metrics, + background_task=True, + ) + @background_task() + def test(): + exercise_logging(logger) + + test() + + +@reset_core_stats_engine() +def test_logging_metrics_outside_transaction(logger): + @validate_custom_metrics_outside_transaction(_test_logging_unscoped_metrics) + @reset_core_stats_engine() + def test(): + exercise_logging(logger) + + test() diff --git a/tests/logger_loguru/test_settings.py b/tests/logger_loguru/test_settings.py new file mode 100644 index 0000000000..4e5dadf5d3 --- /dev/null +++ b/tests/logger_loguru/test_settings.py @@ -0,0 +1,109 @@ +# 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 +import platform + +from newrelic.api.application import application_settings +from newrelic.api.background_task import background_task +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.fixtures import ( + override_application_settings, + validate_transaction_metrics, +) + + +def get_metadata_string(log_message, is_txn): + host = platform.uname().node + assert host + entity_guid = application_settings().entity_guid + if is_txn: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|abcdefgh12345678|abcdefgh|Python%20Agent%20Test%20%28internal_logging%29|')) + else: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|||Python%20Agent%20Test%20%28internal_logging%29|')) + formatted_string = log_message + " " + metadata_string + return formatted_string + + +def basic_logging(logger): + logger.warning("C") + + +_settings_matrix = [ + (True, True, True), + (True, False, False), + (False, True, False), + (False, False, False), +] + + +@pytest.mark.parametrize("feature_setting,subfeature_setting,expected", _settings_matrix) +@reset_core_stats_engine() +def test_log_forwarding_settings(logger, feature_setting, subfeature_setting, expected): + @override_application_settings({ + "application_logging.enabled": feature_setting, + "application_logging.forwarding.enabled": subfeature_setting, + }) + @validate_log_event_count(1 if expected else 0) + @background_task() + def test(): + basic_logging(logger) + assert len(logger.caplog.records) == 1 + + test() + + +@pytest.mark.parametrize("feature_setting,subfeature_setting,expected", _settings_matrix) +@reset_core_stats_engine() +def test_local_decorating_settings(logger, feature_setting, subfeature_setting, expected): + @override_application_settings({ + "application_logging.enabled": feature_setting, + "application_logging.local_decorating.enabled": subfeature_setting, + }) + @background_task() + def test(): + basic_logging(logger) + assert len(logger.caplog.records) == 1 + message = logger.caplog.records.pop() + if expected: + assert len(message) > 1 + else: + assert len(message) == 1 + + test() + + +@pytest.mark.parametrize("feature_setting,subfeature_setting,expected", _settings_matrix) +@reset_core_stats_engine() +def test_log_metrics_settings(logger, feature_setting, subfeature_setting, expected): + metric_count = 1 if expected else None + @override_application_settings({ + "application_logging.enabled": feature_setting, + "application_logging.metrics.enabled": subfeature_setting, + }) + @validate_transaction_metrics( + "test_settings:test_log_metrics_settings..test", + custom_metrics=[ + ("Logging/lines", metric_count), + ("Logging/lines/WARNING", metric_count), + ], + background_task=True, + ) + @background_task() + def test(): + basic_logging(logger) + assert len(logger.caplog.records) == 1 + + test() diff --git a/tests/testing_support/fixtures.py b/tests/testing_support/fixtures.py index 8b8e059b1b..71bfea6705 100644 --- a/tests/testing_support/fixtures.py +++ b/tests/testing_support/fixtures.py @@ -597,8 +597,14 @@ def _capture_transaction_metrics(wrapped, instance, args, kwargs): def validate_internal_metrics(metrics=None): metrics = metrics or [] + def no_op(wrapped, instance, args, kwargs): + pass + @function_wrapper def _validate_wrapper(wrapped, instance, args, kwargs): + # Apply no-op wrappers to prevent new internal trace contexts from being started, preventing capture + wrapped = transient_function_wrapper("newrelic.core.internal_metrics", "InternalTraceContext.__enter__")(no_op)(wrapped) + wrapped = transient_function_wrapper("newrelic.core.internal_metrics", "InternalTraceContext.__exit__")(no_op)(wrapped) captured_metrics = CustomMetrics() with InternalTraceContext(captured_metrics): @@ -1915,38 +1921,50 @@ def validate_transaction_event_sample_data(required_attrs, required_user_attrs=T validation with those tests. """ - @transient_function_wrapper("newrelic.core.stats_engine", "SampledDataSet.add") - def _validate_transaction_event_sample_data(wrapped, instance, args, kwargs): - def _bind_params(sample, *args, **kwargs): - return sample + add_transaction_called = [] - sample = _bind_params(*args, **kwargs) + @function_wrapper + def _validate_wrapper(wrapped, instance, args, kwargs): + @transient_function_wrapper("newrelic.core.stats_engine", "SampledDataSet.add") + def _validate_transaction_event_sample_data(wrapped, instance, args, kwargs): + def _bind_params(sample, *args, **kwargs): + return sample + + sample = _bind_params(*args, **kwargs) + + assert isinstance(sample, list) + assert len(sample) == 3 - assert isinstance(sample, list) - assert len(sample) == 3 + intrinsics, user_attributes, _ = sample - intrinsics, user_attributes, _ = sample + if intrinsics["type"] != "Transaction": + return wrapped(*args, **kwargs) # Exit early - assert intrinsics["type"] == "Transaction" - assert intrinsics["name"] == required_attrs["name"] + add_transaction_called.append(True) - # check that error event intrinsics haven't bled in + assert intrinsics["name"] == required_attrs["name"] - assert "error.class" not in intrinsics - assert "error.message" not in intrinsics - assert "error.expected" not in intrinsics - assert "transactionName" not in intrinsics + # check that error event intrinsics haven't bled in - _validate_event_attributes( - intrinsics, - user_attributes, - required_attrs, - required_user_attrs, - ) + assert "error.class" not in intrinsics + assert "error.message" not in intrinsics + assert "error.expected" not in intrinsics + assert "transactionName" not in intrinsics - return wrapped(*args, **kwargs) + _validate_event_attributes( + intrinsics, + user_attributes, + required_attrs, + required_user_attrs, + ) - return _validate_transaction_event_sample_data + return wrapped(*args, **kwargs) + + result = _validate_transaction_event_sample_data(wrapped)(*args, **kwargs) + assert add_transaction_called + return result + + return _validate_wrapper def validate_transaction_error_event_count(num_errors=1): @@ -2450,10 +2468,19 @@ def finalize(): def reset_core_stats_engine(): + """Reset the StatsEngine and custom StatsEngine of the core application.""" @function_wrapper def _reset_core_stats_engine(wrapped, instance, args, kwargs): - stats = core_application_stats_engine() + api_application = application_instance() + api_name = api_application.name + core_application = api_application._agent.application(api_name) + + stats = core_application._stats_engine stats.reset_stats(stats.settings) + + custom_stats = core_application._stats_custom_engine + custom_stats.reset_stats(custom_stats.settings) + return wrapped(*args, **kwargs) return _reset_core_stats_engine diff --git a/tests/testing_support/sample_applications.py b/tests/testing_support/sample_applications.py index 3bab069cf3..0d5f03b8b3 100644 --- a/tests/testing_support/sample_applications.py +++ b/tests/testing_support/sample_applications.py @@ -12,6 +12,8 @@ # See the License for the specific language governing permissions and # limitations under the License. +import logging + try: from urllib2 import urlopen # Py2.X except ImportError: @@ -25,6 +27,8 @@ record_custom_event) from newrelic.api.wsgi_application import wsgi_application +_logger = logging.getLogger(__name__) + _custom_parameters = { 'user' : 'user-name', 'account' : 'account-name', @@ -124,6 +128,7 @@ def simple_exceptional_app(environ, start_response): def simple_app(environ, start_response): status = '200 OK' + _logger.info("Starting response") start_response(status, response_headers=[]) return [] diff --git a/tests/testing_support/validators/validate_custom_metrics_outside_transaction.py b/tests/testing_support/validators/validate_custom_metrics_outside_transaction.py new file mode 100644 index 0000000000..bb9e4841e2 --- /dev/null +++ b/tests/testing_support/validators/validate_custom_metrics_outside_transaction.py @@ -0,0 +1,91 @@ +# 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 copy + +from testing_support.fixtures import catch_background_exceptions +from newrelic.common.object_wrapper import transient_function_wrapper, function_wrapper + + +def validate_custom_metrics_outside_transaction(custom_metrics=None): + custom_metrics = custom_metrics or [] + + @function_wrapper + def _validate_wrapper(wrapped, instance, args, kwargs): + + record_custom_metric_called = [] + recorded_metrics = [None] + + @transient_function_wrapper("newrelic.core.stats_engine", "StatsEngine.record_custom_metric") + @catch_background_exceptions + def _validate_custom_metrics_outside_transaction(wrapped, instance, args, kwargs): + record_custom_metric_called.append(True) + try: + result = wrapped(*args, **kwargs) + except: + raise + else: + metrics = instance.stats_table + # Record a copy of the metric value so that the values aren't + # merged in the future + _metrics = {} + for k, v in metrics.items(): + _metrics[k] = copy.copy(v) + recorded_metrics[0] = _metrics + + return result + + def _validate(metrics, name, count): + key = (name, "") + metric = metrics.get(key) + + def _metrics_table(): + out = [""] + out.append("Expected: {0}: {1}".format(key, count)) + for metric_key, metric_value in metrics.items(): + out.append("{0}: {1}".format(metric_key, metric_value[0])) + return "\n".join(out) + + def _metric_details(): + return "metric=%r, count=%r" % (key, metric.call_count) + + if count is not None: + assert metric is not None, _metrics_table() + if count == "present": + assert metric.call_count > 0, _metric_details() + else: + assert metric.call_count == count, _metric_details() + + assert metric.total_call_time >= 0, (key, metric) + assert metric.total_exclusive_call_time >= 0, (key, metric) + assert metric.min_call_time >= 0, (key, metric) + assert metric.sum_of_squares >= 0, (key, metric) + + else: + assert metric is None, _metrics_table() + + _new_wrapper = _validate_custom_metrics_outside_transaction(wrapped) + val = _new_wrapper(*args, **kwargs) + assert record_custom_metric_called + metrics = recorded_metrics[0] + + record_custom_metric_called[:] = [] + recorded_metrics[:] = [] + + for custom_metric, count in custom_metrics: + _validate(metrics, custom_metric, count) + + return val + + return _validate_wrapper diff --git a/tests/testing_support/validators/validate_log_event_collector_json.py b/tests/testing_support/validators/validate_log_event_collector_json.py new file mode 100644 index 0000000000..00bb3d5703 --- /dev/null +++ b/tests/testing_support/validators/validate_log_event_collector_json.py @@ -0,0 +1,69 @@ +# 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 json + +from newrelic.common.encoding_utils import json_encode +from newrelic.common.object_wrapper import (transient_function_wrapper, + function_wrapper) + +def validate_log_event_collector_json(num_logs=1): + """Validate the format, types and number of logs of the data we + send to the collector for harvest. + """ + + + @transient_function_wrapper("newrelic.core.stats_engine", "StatsEngine.record_transaction") + def _validate_log_event_collector_json(wrapped, instance, args, kwargs): + try: + result = wrapped(*args, **kwargs) + except: + raise + else: + + samples = list(instance.log_events) + s_info = instance.log_events.sampling_info + agent_run_id = 666 + + # emulate the payload used in data_collector.py + + payload = (agent_run_id, s_info, samples) + collector_json = json_encode(payload) + + decoded_json = json.loads(collector_json) + + assert decoded_json[0] == agent_run_id + + sampling_info = decoded_json[1] + + reservoir_size = instance.settings.application_logging.max_samples_stored + + assert sampling_info["reservoir_size"] == reservoir_size + assert sampling_info["events_seen"] == num_logs + + log_events = decoded_json[2] + + assert len(log_events) == num_logs + for event in log_events: + + # event is an array containing intrinsics, user-attributes, + # and agent-attributes + + assert len(event) == 3 + for d in event: + assert isinstance(d, dict) + + return result + + return _validate_log_event_collector_json diff --git a/tests/testing_support/validators/validate_log_event_count.py b/tests/testing_support/validators/validate_log_event_count.py new file mode 100644 index 0000000000..243364d2d6 --- /dev/null +++ b/tests/testing_support/validators/validate_log_event_count.py @@ -0,0 +1,54 @@ +# 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 copy + +from newrelic.common.object_wrapper import (transient_function_wrapper, + function_wrapper) +from testing_support.fixtures import catch_background_exceptions + +def validate_log_event_count(count=1): + @function_wrapper + def _validate_wrapper(wrapped, instance, args, kwargs): + + record_called = [] + recorded_logs = [] + + @transient_function_wrapper("newrelic.core.stats_engine", "StatsEngine.record_transaction") + @catch_background_exceptions + def _validate_log_event_count(wrapped, instance, args, kwargs): + record_called.append(True) + try: + result = wrapped(*args, **kwargs) + except: + raise + else: + recorded_logs.extend(list(instance._log_events)) + + return result + + _new_wrapper = _validate_log_event_count(wrapped) + val = _new_wrapper(*args, **kwargs) + if count: + assert record_called + logs = copy.copy(recorded_logs) + + record_called[:] = [] + recorded_logs[:] = [] + + assert count == len(logs), len(logs) + + return val + + return _validate_wrapper diff --git a/tests/testing_support/validators/validate_log_event_count_outside_transaction.py b/tests/testing_support/validators/validate_log_event_count_outside_transaction.py new file mode 100644 index 0000000000..8f1337df81 --- /dev/null +++ b/tests/testing_support/validators/validate_log_event_count_outside_transaction.py @@ -0,0 +1,55 @@ +# 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 copy + +from newrelic.common.object_wrapper import (transient_function_wrapper, + function_wrapper) +from testing_support.fixtures import catch_background_exceptions + +def validate_log_event_count_outside_transaction(count=1): + @function_wrapper + def _validate_wrapper(wrapped, instance, args, kwargs): + + record_called = [] + recorded_logs = [] + + @transient_function_wrapper("newrelic.core.stats_engine", "StatsEngine.record_log_event") + @catch_background_exceptions + def _validate_log_event_count_outside_transaction(wrapped, instance, args, kwargs): + record_called.append(True) + try: + result = wrapped(*args, **kwargs) + except: + raise + else: + recorded_logs[:] = [] + recorded_logs.extend(list(instance._log_events)) + + return result + + _new_wrapper = _validate_log_event_count_outside_transaction(wrapped) + val = _new_wrapper(*args, **kwargs) + if count: + assert record_called + logs = copy.copy(recorded_logs) + + record_called[:] = [] + recorded_logs[:] = [] + + assert count == len(logs), len(logs) + + return val + + return _validate_wrapper diff --git a/tests/testing_support/validators/validate_log_events.py b/tests/testing_support/validators/validate_log_events.py new file mode 100644 index 0000000000..aa6159512e --- /dev/null +++ b/tests/testing_support/validators/validate_log_events.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 copy + +from newrelic.packages import six + +from newrelic.common.object_wrapper import (transient_function_wrapper, + function_wrapper) +from testing_support.fixtures import catch_background_exceptions + +def validate_log_events(events): + @function_wrapper + def _validate_wrapper(wrapped, instance, args, kwargs): + + record_called = [] + recorded_logs = [] + + @transient_function_wrapper("newrelic.core.stats_engine", "StatsEngine.record_transaction") + @catch_background_exceptions + def _validate_log_events(wrapped, instance, args, kwargs): + record_called.append(True) + try: + result = wrapped(*args, **kwargs) + except: + raise + else: + recorded_logs[:] = [] + recorded_logs.extend(list(instance._log_events)) + + return result + + + _new_wrapper = _validate_log_events(wrapped) + val = _new_wrapper(*args, **kwargs) + assert record_called + logs = copy.copy(recorded_logs) + + record_called[:] = [] + recorded_logs[:] = [] + + for expected in events: + matching_log_events = 0 + mismatches = [] + for captured in logs: + if _check_log_attributes(expected, captured, mismatches): + matching_log_events += 1 + assert matching_log_events == 1, _log_details(matching_log_events, logs, mismatches) + + return val + + + def _check_log_attributes(expected, captured, mismatches): + for key, value in six.iteritems(expected): + if hasattr(captured, key): + captured_value = getattr(captured, key, None) + elif key in captured.attributes: + captured_value = captured.attributes[key] + else: + mismatches.append("key: %s, value:<%s><%s>" % (key, value, getattr(captured, key, None))) + return False + + if value is not None: + if value != captured_value: + mismatches.append("key: %s, value:<%s><%s>" % (key, value, captured_value)) + return False + + return True + + def _log_details(matching_log_events, captured, mismatches): + details = [ + "matching_log_events=%d" % matching_log_events, + "mismatches=%s" % mismatches, + "captured_events=%s" % captured, + ] + + return "\n".join(details) + + return _validate_wrapper diff --git a/tests/testing_support/validators/validate_log_events_outside_transaction.py b/tests/testing_support/validators/validate_log_events_outside_transaction.py new file mode 100644 index 0000000000..f46b6e843f --- /dev/null +++ b/tests/testing_support/validators/validate_log_events_outside_transaction.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 copy + +from newrelic.packages import six + +from newrelic.common.object_wrapper import (transient_function_wrapper, + function_wrapper) +from testing_support.fixtures import catch_background_exceptions + +def validate_log_events_outside_transaction(events): + @function_wrapper + def _validate_wrapper(wrapped, instance, args, kwargs): + + record_called = [] + recorded_logs = [] + + @transient_function_wrapper("newrelic.core.stats_engine", "StatsEngine.record_log_event") + @catch_background_exceptions + def _validate_log_events_outside_transaction(wrapped, instance, args, kwargs): + record_called.append(True) + try: + result = wrapped(*args, **kwargs) + except: + raise + else: + recorded_logs[:] = [] + recorded_logs.extend(list(instance._log_events)) + + return result + + + _new_wrapper = _validate_log_events_outside_transaction(wrapped) + val = _new_wrapper(*args, **kwargs) + assert record_called + logs = copy.copy(recorded_logs) + + record_called[:] = [] + recorded_logs[:] = [] + + for expected in events: + matching_log_events = 0 + mismatches = [] + for captured in logs: + if _check_log_attributes(expected, captured, mismatches): + matching_log_events += 1 + assert matching_log_events == 1, _log_details(matching_log_events, logs, mismatches) + + return val + + + def _check_log_attributes(expected, captured, mismatches): + for key, value in six.iteritems(expected): + if hasattr(captured, key): + captured_value = getattr(captured, key, None) + elif key in captured.attributes: + captured_value = captured.attributes[key] + else: + mismatches.append("key: %s, value:<%s><%s>" % (key, value, getattr(captured, key, None))) + return False + + if value is not None: + if value != captured_value: + mismatches.append("key: %s, value:<%s><%s>" % (key, value, captured_value)) + return False + + return True + + def _log_details(matching_log_events, captured, mismatches): + details = [ + "matching_log_events=%d" % matching_log_events, + "mismatches=%s" % mismatches, + "captured_events=%s" % captured, + ] + + return "\n".join(details) + + return _validate_wrapper diff --git a/tox.ini b/tox.ini index 5c05c8c5fb..717b5bcfea 100644 --- a/tox.ini +++ b/tox.ini @@ -119,7 +119,8 @@ envlist = python-framework_fastapi-{py36,py37,py38,py39,py310}, python-framework_flask-{pypy,py27}-flask0012, python-framework_flask-{pypy,py27,py36,py37,py38,py39,py310,pypy36}-flask0101, - python-framework_flask-{py37,py38,py39,py310,pypy37}-flask{latest,master}, + ; temporarily disabling flaskmaster tests + python-framework_flask-{py37,py38,py39,py310,pypy37}-flask{latest}, python-framework_graphene-{py36,py37,py38,py39,py310}-graphenelatest, python-framework_graphene-{py27,py36,py37,py38,py39,pypy,pypy36}-graphene{0200,0201}, python-framework_graphene-py310-graphene0201, @@ -137,6 +138,9 @@ envlist = python-framework_starlette-{py36,py310,pypy36}-starlette{0014,0015,0019}, python-framework_starlette-{py36,py37,py38,py39,py310,pypy36}-starlette{latest}, python-framework_strawberry-{py37,py38,py39,py310}-strawberrylatest, + python-logger_logging-{py27,py36,py37,py38,py39,py310,pypy,pypy36}, + python-logger_loguru-{py36,py37,py38,py39,py310,pypy36}-logurulatest, + python-logger_loguru-py39-loguru{06,05,04,03}, libcurl-framework_tornado-{py36,py37,py38,py39,py310,pypy36}-tornado0600, libcurl-framework_tornado-{py37,py38,py39,py310}-tornadomaster, rabbitmq-messagebroker_pika-{py27,py36,py37,py38,py39,pypy,pypy36}-pika0.13, @@ -322,7 +326,12 @@ deps = framework_tornado: pycurl framework_tornado-tornado0600: tornado<6.1 framework_tornado-tornadomaster: https://github.com/tornadoweb/tornado/archive/master.zip - framework-tornado: pycurl + framework_tornado: pycurl + logger_loguru-logurulatest: loguru + logger_loguru-loguru06: loguru<0.7 + logger_loguru-loguru05: loguru<0.6 + logger_loguru-loguru04: loguru<0.5 + logger_loguru-loguru03: loguru<0.4 messagebroker_pika-pika0.13: pika<0.14 messagebroker_pika-pikalatest: pika messagebroker_pika: tornado<5 @@ -419,5 +428,7 @@ changedir = framework_starlette: tests/framework_starlette framework_strawberry: tests/framework_strawberry framework_tornado: tests/framework_tornado + logger_logging: tests/logger_logging + logger_loguru: tests/logger_loguru messagebroker_pika: tests/messagebroker_pika template_mako: tests/template_mako