diff --git a/elasticapm/conf/__init__.py b/elasticapm/conf/__init__.py index 45b4db5a2..d787491ab 100644 --- a/elasticapm/conf/__init__.py +++ b/elasticapm/conf/__init__.py @@ -883,10 +883,6 @@ def setup_logging(handler): For a typical Python install: - >>> from elasticapm.handlers.logging import LoggingHandler - >>> client = ElasticAPM(...) - >>> setup_logging(LoggingHandler(client)) - Returns a boolean based on if logging was configured or not. """ # TODO We should probably revisit this. Does it make more sense as diff --git a/elasticapm/contrib/flask/__init__.py b/elasticapm/contrib/flask/__init__.py index b6e4e312b..4be9fe7ae 100644 --- a/elasticapm/contrib/flask/__init__.py +++ b/elasticapm/contrib/flask/__init__.py @@ -82,6 +82,9 @@ def __init__(self, app=None, client=None, client_cls=Client, **defaults) -> None self.client = client or get_client() self.client_cls = client_cls + if "logging" in defaults: + raise ValueError("Flask log shipping has been removed, drop the ElasticAPM logging parameter") + if app: self.init_app(app, **defaults) diff --git a/elasticapm/handlers/logging.py b/elasticapm/handlers/logging.py index 96718d2db..bcdd15bb0 100644 --- a/elasticapm/handlers/logging.py +++ b/elasticapm/handlers/logging.py @@ -32,181 +32,11 @@ from __future__ import absolute_import import logging -import sys -import traceback -import warnings import wrapt from elasticapm import get_client -from elasticapm.base import Client from elasticapm.traces import execution_context -from elasticapm.utils.stacks import iter_stack_frames - - -class LoggingHandler(logging.Handler): - def __init__(self, *args, **kwargs) -> None: - warnings.warn( - "The LoggingHandler is deprecated and will be removed in v7.0 of " - "the agent. Please use `log_ecs_reformatting` and ship the logs " - "with Elastic Agent or Filebeat instead. " - "https://www.elastic.co/guide/en/apm/agent/python/current/logs.html", - DeprecationWarning, - ) - self.client = None - if "client" in kwargs: - self.client = kwargs.pop("client") - elif len(args) > 0: - arg = args[0] - if isinstance(arg, Client): - self.client = arg - - if not self.client: - client_cls = kwargs.pop("client_cls", None) - if client_cls: - self.client = client_cls(*args, **kwargs) - else: - warnings.warn( - "LoggingHandler requires a Client instance. No Client was received.", - DeprecationWarning, - ) - self.client = Client(*args, **kwargs) - logging.Handler.__init__(self, level=kwargs.get("level", logging.NOTSET)) - - def emit(self, record): - self.format(record) - - # Avoid typical config issues by overriding loggers behavior - if record.name.startswith(("elasticapm.errors",)): - sys.stderr.write(record.getMessage() + "\n") - return - - try: - return self._emit(record) - except Exception: - sys.stderr.write("Top level ElasticAPM exception caught - failed creating log record.\n") - sys.stderr.write(record.getMessage() + "\n") - sys.stderr.write(traceback.format_exc() + "\n") - - try: - self.client.capture("Exception") - except Exception: - pass - - def _emit(self, record, **kwargs): - data = {} - - for k, v in record.__dict__.items(): - if "." not in k and k not in ("culprit",): - continue - data[k] = v - - stack = getattr(record, "stack", None) - if stack is True: - stack = iter_stack_frames(config=self.client.config) - - if stack: - frames = [] - started = False - last_mod = "" - for item in stack: - if isinstance(item, (list, tuple)): - frame, lineno = item - else: - frame, lineno = item, item.f_lineno - - if not started: - f_globals = getattr(frame, "f_globals", {}) - module_name = f_globals.get("__name__", "") - if last_mod.startswith("logging") and not module_name.startswith("logging"): - started = True - else: - last_mod = module_name - continue - frames.append((frame, lineno)) - stack = frames - - custom = getattr(record, "data", {}) - # Add in all of the data from the record that we aren't already capturing - for k in record.__dict__.keys(): - if k in ( - "stack", - "name", - "args", - "msg", - "levelno", - "exc_text", - "exc_info", - "data", - "created", - "levelname", - "msecs", - "relativeCreated", - ): - continue - if k.startswith("_"): - continue - custom[k] = record.__dict__[k] - - # If there's no exception being processed, - # exc_info may be a 3-tuple of None - # http://docs.python.org/library/sys.html#sys.exc_info - if record.exc_info and all(record.exc_info): - handler = self.client.get_handler("elasticapm.events.Exception") - exception = handler.capture(self.client, exc_info=record.exc_info) - else: - exception = None - - return self.client.capture( - "Message", - param_message={"message": str(record.msg), "params": record.args}, - stack=stack, - custom=custom, - exception=exception, - level=record.levelno, - logger_name=record.name, - **kwargs, - ) - - -class LoggingFilter(logging.Filter): - """ - This filter doesn't actually do any "filtering" -- rather, it just adds - three new attributes to any "filtered" LogRecord objects: - - * elasticapm_transaction_id - * elasticapm_trace_id - * elasticapm_span_id - * elasticapm_service_name - - These attributes can then be incorporated into your handlers and formatters, - so that you can tie log messages to transactions in elasticsearch. - - This filter also adds these fields to a dictionary attribute, - `elasticapm_labels`, using the official tracing fields names as documented - here: https://www.elastic.co/guide/en/ecs/current/ecs-tracing.html - - Note that if you're using Python 3.2+, by default we will add a - LogRecordFactory to your root logger which will add these attributes - automatically. - """ - - def __init__(self, name=""): - super().__init__(name=name) - warnings.warn( - "The LoggingFilter is deprecated and will be removed in v7.0 of " - "the agent. On Python 3.2+, by default we add a LogRecordFactory to " - "your root logger automatically" - "https://www.elastic.co/guide/en/apm/agent/python/current/logs.html", - DeprecationWarning, - ) - - def filter(self, record): - """ - Add elasticapm attributes to `record`. - """ - _add_attributes_to_log_record(record) - return True @wrapt.decorator diff --git a/tests/contrib/flask/flask_tests.py b/tests/contrib/flask/flask_tests.py index 4a38dc3b4..8d893533b 100644 --- a/tests/contrib/flask/flask_tests.py +++ b/tests/contrib/flask/flask_tests.py @@ -50,6 +50,11 @@ pytestmark = pytest.mark.flask +def test_logging_parameter_raises_exception(): + with pytest.raises(ValueError, match="Flask log shipping has been removed, drop the ElasticAPM logging parameter"): + ElasticAPM(config=None, logging=True) + + def test_error_handler(flask_apm_client): client = flask_apm_client.app.test_client() response = client.get("/an-error/") diff --git a/tests/handlers/logging/logging_tests.py b/tests/handlers/logging/logging_tests.py index 8cc8fc4f1..00a1a4ab6 100644 --- a/tests/handlers/logging/logging_tests.py +++ b/tests/handlers/logging/logging_tests.py @@ -40,238 +40,13 @@ from elasticapm.conf import Config from elasticapm.conf.constants import ERROR -from elasticapm.handlers.logging import Formatter, LoggingFilter, LoggingHandler +from elasticapm.handlers.logging import Formatter from elasticapm.handlers.structlog import structlog_processor from elasticapm.traces import capture_span from elasticapm.utils.stacks import iter_stack_frames from tests.fixtures import TempStoreClient -@pytest.fixture() -def logger(elasticapm_client): - elasticapm_client.config.include_paths = ["tests", "elasticapm"] - handler = LoggingHandler(elasticapm_client) - logger = logging.getLogger(__name__) - logger.handlers = [] - logger.addHandler(handler) - logger.client = elasticapm_client - logger.level = logging.INFO - return logger - - -def test_logger_basic(logger): - logger.error("This is a test error") - - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - assert event["log"]["logger_name"] == __name__ - assert event["log"]["level"] == "error" - assert event["log"]["message"] == "This is a test error" - assert "stacktrace" in event["log"] - assert "exception" not in event - assert "param_message" in event["log"] - assert event["log"]["param_message"] == "This is a test error" - - -def test_logger_warning(logger): - logger.warning("This is a test warning") - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - assert event["log"]["logger_name"] == __name__ - assert event["log"]["level"] == "warning" - assert "exception" not in event - assert "param_message" in event["log"] - assert event["log"]["param_message"] == "This is a test warning" - - -def test_logger_extra_data(logger): - logger.info("This is a test info with a url", extra=dict(data=dict(url="http://example.com"))) - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - assert event["context"]["custom"]["url"] == "http://example.com" - assert "stacktrace" in event["log"] - assert "exception" not in event - assert "param_message" in event["log"] - assert event["log"]["param_message"] == "This is a test info with a url" - - -def test_logger_exc_info(logger): - try: - raise ValueError("This is a test ValueError") - except ValueError: - logger.info("This is a test info with an exception", exc_info=True) - - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - - # assert event['message'] == 'This is a test info with an exception' - assert "exception" in event - assert "stacktrace" in event["exception"] - exc = event["exception"] - assert exc["type"] == "ValueError" - assert exc["message"] == "ValueError: This is a test ValueError" - assert "param_message" in event["log"] - assert event["log"]["message"] == "This is a test info with an exception" - - -def test_message_params(logger): - logger.info("This is a test of %s", "args") - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - assert "exception" not in event - assert "param_message" in event["log"] - assert event["log"]["message"] == "This is a test of args" - assert event["log"]["param_message"] == "This is a test of %s" - - -def test_record_stack(logger): - logger.info("This is a test of stacks", extra={"stack": True}) - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - frames = event["log"]["stacktrace"] - assert len(frames) != 1 - frame = frames[0] - assert frame["module"] == __name__ - assert "exception" not in event - assert "param_message" in event["log"] - assert event["log"]["param_message"] == "This is a test of stacks" - assert event["culprit"] == "tests.handlers.logging.logging_tests.test_record_stack" - assert event["log"]["message"] == "This is a test of stacks" - - -def test_no_record_stack(logger): - logger.info("This is a test of no stacks", extra={"stack": False}) - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - assert event.get("culprit") == None - assert event["log"]["message"] == "This is a test of no stacks" - assert "stacktrace" not in event["log"] - assert "exception" not in event - assert "param_message" in event["log"] - assert event["log"]["param_message"] == "This is a test of no stacks" - - -def test_no_record_stack_via_config(logger): - logger.client.config.auto_log_stacks = False - logger.info("This is a test of no stacks") - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - assert event.get("culprit") == None - assert event["log"]["message"] == "This is a test of no stacks" - assert "stacktrace" not in event["log"] - assert "exception" not in event - assert "param_message" in event["log"] - assert event["log"]["param_message"] == "This is a test of no stacks" - - -def test_explicit_stack(logger): - logger.info("This is a test of stacks", extra={"stack": iter_stack_frames()}) - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - assert "culprit" in event, event - assert event["culprit"] == "tests.handlers.logging.logging_tests.test_explicit_stack" - assert "message" in event["log"], event - assert event["log"]["message"] == "This is a test of stacks" - assert "exception" not in event - assert "param_message" in event["log"] - assert event["log"]["param_message"] == "This is a test of stacks" - assert "stacktrace" in event["log"] - - -def test_extra_culprit(logger): - logger.info("This is a test of stacks", extra={"culprit": "foo.bar"}) - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - assert event["culprit"] == "foo.bar" - assert "culprit" not in event["context"]["custom"] - - -def test_logger_exception(logger): - try: - raise ValueError("This is a test ValueError") - except ValueError: - logger.exception("This is a test with an exception", extra={"stack": True}) - - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - - assert event["log"]["message"] == "This is a test with an exception" - assert "stacktrace" in event["log"] - assert "exception" in event - exc = event["exception"] - assert exc["type"] == "ValueError" - assert exc["message"] == "ValueError: This is a test ValueError" - assert "param_message" in event["log"] - assert event["log"]["message"] == "This is a test with an exception" - - -def test_client_arg(elasticapm_client): - handler = LoggingHandler(elasticapm_client) - assert handler.client == elasticapm_client - - -def test_client_kwarg(elasticapm_client): - handler = LoggingHandler(client=elasticapm_client) - assert handler.client == elasticapm_client - - -def test_logger_setup(): - handler = LoggingHandler( - server_url="foo", service_name="bar", secret_token="baz", metrics_interval="0ms", client_cls=TempStoreClient - ) - client = handler.client - assert client.config.server_url == "foo" - assert client.config.service_name == "bar" - assert client.config.secret_token == "baz" - assert handler.level == logging.NOTSET - - -def test_logging_handler_emit_error(capsys, elasticapm_client): - handler = LoggingHandler(elasticapm_client) - handler._emit = lambda: 1 / 0 - handler.emit(LogRecord("x", 1, "/ab/c/", 10, "Oops", (), None)) - out, err = capsys.readouterr() - assert "Top level ElasticAPM exception caught" in err - assert "Oops" in err - - -def test_logging_handler_dont_emit_elasticapm(capsys, elasticapm_client): - handler = LoggingHandler(elasticapm_client) - handler.emit(LogRecord("elasticapm.errors", 1, "/ab/c/", 10, "Oops", (), None)) - out, err = capsys.readouterr() - assert "Oops" in err - - -def test_logging_handler_emit_error_non_str_message(capsys, elasticapm_client): - handler = LoggingHandler(elasticapm_client) - handler._emit = lambda: 1 / 0 - handler.emit(LogRecord("x", 1, "/ab/c/", 10, ValueError("oh no"), (), None)) - out, err = capsys.readouterr() - assert "Top level ElasticAPM exception caught" in err - assert "oh no" in err - - -def test_arbitrary_object(logger): - logger.error(["a", "list", "of", "strings"]) - assert len(logger.client.events) == 1 - event = logger.client.events[ERROR][0] - assert "param_message" in event["log"] - assert event["log"]["param_message"] == "['a', 'list', 'of', 'strings']" - - -def test_logging_filter_no_span(elasticapm_client): - transaction = elasticapm_client.begin_transaction("test") - f = LoggingFilter() - record = logging.LogRecord(__name__, logging.DEBUG, __file__, 252, "dummy_msg", [], None) - f.filter(record) - assert record.elasticapm_transaction_id == transaction.id - assert record.elasticapm_service_name == transaction.tracer.config.service_name - assert record.elasticapm_service_environment == transaction.tracer.config.environment - assert record.elasticapm_trace_id == transaction.trace_parent.trace_id - assert record.elasticapm_span_id is None - assert record.elasticapm_labels - - def test_structlog_processor_no_span(elasticapm_client): transaction = elasticapm_client.begin_transaction("test") event_dict = {} @@ -281,37 +56,6 @@ def test_structlog_processor_no_span(elasticapm_client): assert "span.id" not in new_dict -@pytest.mark.parametrize("elasticapm_client", [{"transaction_max_spans": 5}], indirect=True) -def test_logging_filter_span(elasticapm_client): - transaction = elasticapm_client.begin_transaction("test") - with capture_span("test") as span: - f = LoggingFilter() - record = logging.LogRecord(__name__, logging.DEBUG, __file__, 252, "dummy_msg", [], None) - f.filter(record) - assert record.elasticapm_transaction_id == transaction.id - assert record.elasticapm_service_name == transaction.tracer.config.service_name - assert record.elasticapm_service_environment == transaction.tracer.config.environment - assert record.elasticapm_trace_id == transaction.trace_parent.trace_id - assert record.elasticapm_span_id == span.id - assert record.elasticapm_labels - - # Capture too many spans so we start dropping - for i in range(10): - with capture_span("drop"): - pass - - # Test logging with DroppedSpan - with capture_span("drop") as span: - record = logging.LogRecord(__name__, logging.DEBUG, __file__, 252, "dummy_msg2", [], None) - f.filter(record) - assert record.elasticapm_transaction_id == transaction.id - assert record.elasticapm_service_name == transaction.tracer.config.service_name - assert record.elasticapm_service_environment == transaction.tracer.config.environment - assert record.elasticapm_trace_id == transaction.trace_parent.trace_id - assert record.elasticapm_span_id is None - assert record.elasticapm_labels - - @pytest.mark.parametrize("elasticapm_client", [{"transaction_max_spans": 5}], indirect=True) def test_structlog_processor_span(elasticapm_client): transaction = elasticapm_client.begin_transaction("test") @@ -373,18 +117,6 @@ def test_formatter(): assert hasattr(record, "elasticapm_service_environment") -def test_logging_handler_no_client(recwarn): - # In 6.0, this should be changed to expect a ValueError instead of a log - warnings.simplefilter("always") - LoggingHandler(transport_class="tests.fixtures.DummyTransport") - while True: - # If we never find our desired warning this will eventually throw an - # AssertionError - w = recwarn.pop(DeprecationWarning) - if "LoggingHandler requires a Client instance" in w.message.args[0]: - return True - - @pytest.mark.parametrize( "elasticapm_client,expected", [