test_logs.py

import json
import logging
import sys
import time
from typing import List, Any, Mapping, Union
import pytest
from unittest import mock

import sentry_sdk
import sentry_sdk.logger
from sentry_sdk import get_client
from sentry_sdk.envelope import Envelope, Item, PayloadRef
from sentry_sdk.types import Log
from sentry_sdk.consts import SPANDATA, VERSION

minimum_python_37 = pytest.mark.skipif(
    sys.version_info < (3, 7), reason="Asyncio tests need Python >= 3.7"
)


def otel_attributes_to_dict(otel_attrs: "Mapping[str, Any]") -> "Mapping[str, Any]":
    def _convert_attr(attr):
        # type: (Mapping[str, Union[str, float, bool]]) -> Any
        if attr["type"] == "boolean":
            return attr["value"]
        if attr["type"] == "double":
            return attr["value"]
        if attr["type"] == "integer":
            return attr["value"]
        if attr["value"].startswith("{"):
            try:
                return json.loads(attr["value"])
            except ValueError:
                pass
        return str(attr["value"])

    return {k: _convert_attr(v) for (k, v) in otel_attrs.items()}


def envelopes_to_logs(envelopes: List[Envelope]) -> List[Log]:
    res: "List[Log]" = []
    for envelope in envelopes:
        for item in envelope.items:
            if item.type == "log":
                for log_json in item.payload.json["items"]:
                    log: "Log" = {
                        "severity_text": log_json["attributes"]["sentry.severity_text"][
                            "value"
                        ],
                        "severity_number": int(
                            log_json["attributes"]["sentry.severity_number"]["value"]
                        ),
                        "body": log_json["body"],
                        "attributes": otel_attributes_to_dict(log_json["attributes"]),
                        "time_unix_nano": int(float(log_json["timestamp"]) * 1e9),
                        "trace_id": log_json["trace_id"],
                        "span_id": log_json["span_id"],
                    }
                    res.append(log)
    return res


@minimum_python_37
def test_logs_disabled_by_default(sentry_init, capture_envelopes):
    sentry_init()

    python_logger = logging.Logger("some-logger")

    envelopes = capture_envelopes()

    sentry_sdk.logger.trace("This is a 'trace' log.")
    sentry_sdk.logger.debug("This is a 'debug' log...")
    sentry_sdk.logger.info("This is a 'info' log...")
    sentry_sdk.logger.warning("This is a 'warning' log...")
    sentry_sdk.logger.error("This is a 'error' log...")
    sentry_sdk.logger.fatal("This is a 'fatal' log...")
    python_logger.warning("sad")

    assert len(envelopes) == 0


@minimum_python_37
def test_logs_basics(sentry_init, capture_envelopes):
    sentry_init(enable_logs=True)
    envelopes = capture_envelopes()

    sentry_sdk.logger.trace("This is a 'trace' log...")
    sentry_sdk.logger.debug("This is a 'debug' log...")
    sentry_sdk.logger.info("This is a 'info' log...")
    sentry_sdk.logger.warning("This is a 'warn' log...")
    sentry_sdk.logger.error("This is a 'error' log...")
    sentry_sdk.logger.fatal("This is a 'fatal' log...")

    get_client().flush()
    logs = envelopes_to_logs(envelopes)
    assert logs[0].get("severity_text") == "trace"
    assert logs[0].get("severity_number") == 1

    assert logs[1].get("severity_text") == "debug"
    assert logs[1].get("severity_number") == 5

    assert logs[2].get("severity_text") == "info"
    assert logs[2].get("severity_number") == 9

    assert logs[3].get("severity_text") == "warn"
    assert logs[3].get("severity_number") == 13

    assert logs[4].get("severity_text") == "error"
    assert logs[4].get("severity_number") == 17

    assert logs[5].get("severity_text") == "fatal"
    assert logs[5].get("severity_number") == 21


@minimum_python_37
def test_logs_experimental_option_still_works(sentry_init, capture_envelopes):
    sentry_init(_experiments={"enable_logs": True})
    envelopes = capture_envelopes()

    sentry_sdk.logger.error("This is an error log...")

    get_client().flush()

    logs = envelopes_to_logs(envelopes)
    assert len(logs) == 1

    assert logs[0].get("severity_text") == "error"
    assert logs[0].get("severity_number") == 17


@minimum_python_37
def test_logs_before_send_log(sentry_init, capture_envelopes):
    before_log_called = False

    def _before_log(record, hint):
        nonlocal before_log_called

        assert set(record.keys()) == {
            "severity_text",
            "severity_number",
            "body",
            "attributes",
            "time_unix_nano",
            "trace_id",
            "span_id",
        }

        if record["severity_text"] in ["fatal", "error"]:
            return None

        before_log_called = True

        return record

    sentry_init(
        enable_logs=True,
        before_send_log=_before_log,
    )
    envelopes = capture_envelopes()

    sentry_sdk.logger.trace("This is a 'trace' log...")
    sentry_sdk.logger.debug("This is a 'debug' log...")
    sentry_sdk.logger.info("This is a 'info' log...")
    sentry_sdk.logger.warning("This is a 'warning' log...")
    sentry_sdk.logger.error("This is a 'error' log...")
    sentry_sdk.logger.fatal("This is a 'fatal' log...")

    get_client().flush()
    logs = envelopes_to_logs(envelopes)
    assert len(logs) == 4

    assert logs[0]["severity_text"] == "trace"
    assert logs[1]["severity_text"] == "debug"
    assert logs[2]["severity_text"] == "info"
    assert logs[3]["severity_text"] == "warn"
    assert before_log_called is True


@minimum_python_37
def test_logs_before_send_log_experimental_option_still_works(
    sentry_init, capture_envelopes
):
    before_log_called = False

    def _before_log(record, hint):
        nonlocal before_log_called
        before_log_called = True

        return record

    sentry_init(
        enable_logs=True,
        _experiments={
            "before_send_log": _before_log,
        },
    )
    envelopes = capture_envelopes()

    sentry_sdk.logger.error("This is an error log...")

    get_client().flush()
    logs = envelopes_to_logs(envelopes)
    assert len(logs) == 1

    assert logs[0]["severity_text"] == "error"
    assert before_log_called is True


@minimum_python_37
def test_logs_attributes(sentry_init, capture_envelopes):
    """
    Passing arbitrary attributes to log messages.
    """
    sentry_init(enable_logs=True, server_name="test-server")
    envelopes = capture_envelopes()

    attrs = {
        "attr_int": 1,
        "attr_float": 2.0,
        "attr_bool": True,
        "attr_string": "string attribute",
    }

    sentry_sdk.logger.warning(
        "The recorded value was '{my_var}'", my_var="some value", attributes=attrs
    )

    get_client().flush()
    logs = envelopes_to_logs(envelopes)
    assert logs[0]["body"] == "The recorded value was 'some value'"

    for k, v in attrs.items():
        assert logs[0]["attributes"][k] == v
    assert logs[0]["attributes"]["sentry.environment"] == "production"
    if sentry_sdk.get_client().options.get("release") is not None:
        assert "sentry.release" in logs[0]["attributes"]
    assert logs[0]["attributes"]["sentry.message.parameter.my_var"] == "some value"
    assert logs[0]["attributes"][SPANDATA.SERVER_ADDRESS] == "test-server"
    assert logs[0]["attributes"]["sentry.sdk.name"].startswith("sentry.python")
    assert logs[0]["attributes"]["sentry.sdk.version"] == VERSION


@minimum_python_37
def test_logs_message_params(sentry_init, capture_envelopes):
    """
    This is the official way of how to pass vars to log messages.
    """
    sentry_init(enable_logs=True)
    envelopes = capture_envelopes()

    sentry_sdk.logger.warning("The recorded value was '{int_var}'", int_var=1)
    sentry_sdk.logger.warning("The recorded value was '{float_var}'", float_var=2.0)
    sentry_sdk.logger.warning("The recorded value was '{bool_var}'", bool_var=False)
    sentry_sdk.logger.warning(
        "The recorded value was '{string_var}'", string_var="some string value"
    )
    sentry_sdk.logger.error(
        "The recorded error was '{error}'", error=Exception("some error")
    )
    sentry_sdk.logger.warning("The recorded value was hardcoded.")

    get_client().flush()
    logs = envelopes_to_logs(envelopes)

    assert logs[0]["body"] == "The recorded value was '1'"
    assert logs[0]["attributes"]["sentry.message.parameter.int_var"] == 1
    assert (
        logs[0]["attributes"]["sentry.message.template"]
        == "The recorded value was '{int_var}'"
    )

    assert logs[1]["body"] == "The recorded value was '2.0'"
    assert logs[1]["attributes"]["sentry.message.parameter.float_var"] == 2.0
    assert (
        logs[1]["attributes"]["sentry.message.template"]
        == "The recorded value was '{float_var}'"
    )

    assert logs[2]["body"] == "The recorded value was 'False'"
    assert logs[2]["attributes"]["sentry.message.parameter.bool_var"] is False
    assert (
        logs[2]["attributes"]["sentry.message.template"]
        == "The recorded value was '{bool_var}'"
    )

    assert logs[3]["body"] == "The recorded value was 'some string value'"
    assert (
        logs[3]["attributes"]["sentry.message.parameter.string_var"]
        == "some string value"
    )
    assert (
        logs[3]["attributes"]["sentry.message.template"]
        == "The recorded value was '{string_var}'"
    )

    assert logs[4]["body"] == "The recorded error was 'some error'"
    assert (
        logs[4]["attributes"]["sentry.message.parameter.error"]
        == "Exception('some error')"
    )
    assert (
        logs[4]["attributes"]["sentry.message.template"]
        == "The recorded error was '{error}'"
    )

    assert logs[5]["body"] == "The recorded value was hardcoded."
    assert "sentry.message.template" not in logs[5]["attributes"]


@minimum_python_37
def test_logs_tied_to_transactions(sentry_init, capture_envelopes):
    """
    Log messages are also tied to transactions.
    """
    sentry_init(enable_logs=True, traces_sample_rate=1.0)
    envelopes = capture_envelopes()

    with sentry_sdk.start_transaction(name="test-transaction") as trx:
        sentry_sdk.logger.warning("This is a log tied to a transaction")

    get_client().flush()
    logs = envelopes_to_logs(envelopes)

    assert "span_id" in logs[0]
    assert logs[0]["span_id"] == trx.span_id


@minimum_python_37
def test_logs_tied_to_spans(sentry_init, capture_envelopes):
    """
    Log messages are also tied to spans.
    """
    sentry_init(enable_logs=True, traces_sample_rate=1.0)
    envelopes = capture_envelopes()

    with sentry_sdk.start_transaction(name="test-transaction"):
        with sentry_sdk.start_span(name="test-span") as span:
            sentry_sdk.logger.warning("This is a log tied to a span")

    get_client().flush()
    logs = envelopes_to_logs(envelopes)
    assert logs[0]["span_id"] == span.span_id


@minimum_python_37
def test_auto_flush_logs_after_100(sentry_init, capture_envelopes):
    """
    If you log >100 logs, it should automatically trigger a flush.
    """
    sentry_init(enable_logs=True)
    envelopes = capture_envelopes()

    for i in range(200):
        sentry_sdk.logger.warning("log")

    for _ in range(500):
        time.sleep(1.0 / 100.0)
        if len(envelopes) > 0:
            return

    raise AssertionError("200 logs were never flushed after five seconds")


@minimum_python_37
def test_log_user_attributes(sentry_init, capture_envelopes):
    """User attributes are sent if enable_logs is True and send_default_pii is True."""
    sentry_init(enable_logs=True, send_default_pii=True)

    sentry_sdk.set_user({"id": "1", "email": "test@example.com", "username": "test"})
    envelopes = capture_envelopes()

    sentry_sdk.logger.warning("Hello, world!")

    get_client().flush()

    logs = envelopes_to_logs(envelopes)
    (log,) = logs

    # Check that all expected user attributes are present.
    assert log["attributes"].items() >= {
        ("user.id", "1"),
        ("user.email", "test@example.com"),
        ("user.name", "test"),
    }


@minimum_python_37
def test_log_no_user_attributes_if_no_pii(sentry_init, capture_envelopes):
    """User attributes are not if PII sending is off."""
    sentry_init(enable_logs=True, send_default_pii=False)

    sentry_sdk.set_user({"id": "1", "email": "test@example.com", "username": "test"})
    envelopes = capture_envelopes()

    sentry_sdk.logger.warning("Hello, world!")

    get_client().flush()

    logs = envelopes_to_logs(envelopes)
    (log,) = logs

    assert "user.id" not in log["attributes"]
    assert "user.email" not in log["attributes"]
    assert "user.name" not in log["attributes"]


@minimum_python_37
def test_auto_flush_logs_after_5s(sentry_init, capture_envelopes):
    """
    If you log a single log, it should automatically flush after 5 seconds, at most 10 seconds.
    """
    sentry_init(enable_logs=True)
    envelopes = capture_envelopes()

    sentry_sdk.logger.warning("log")

    for _ in range(100):
        time.sleep(1.0 / 10.0)
        if len(envelopes) > 0:
            return

    raise AssertionError("1 logs was never flushed after 10 seconds")


@minimum_python_37
@pytest.mark.parametrize(
    "message,expected_body,params",
    [
        ("any text with {braces} in it", "any text with {braces} in it", None),
        (
            'JSON data: {"key": "value", "number": 42}',
            'JSON data: {"key": "value", "number": 42}',
            None,
        ),
        ("Multiple {braces} {in} {message}", "Multiple {braces} {in} {message}", None),
        ("Nested {{braces}}", "Nested {{braces}}", None),
        ("Empty braces: {}", "Empty braces: {}", None),
        ("Braces with params: {user}", "Braces with params: alice", {"user": "alice"}),
        (
            "Braces with partial params: {user1} {user2}",
            "Braces with partial params: alice {user2}",
            {"user1": "alice"},
        ),
    ],
)
def test_logs_with_literal_braces(
    sentry_init, capture_envelopes, message, expected_body, params
):
    """
    Test that log messages with literal braces (like JSON) work without crashing.
    This is a regression test for issue #4975.
    """
    sentry_init(enable_logs=True)
    envelopes = capture_envelopes()

    if params:
        sentry_sdk.logger.info(message, **params)
    else:
        sentry_sdk.logger.info(message)

    get_client().flush()
    logs = envelopes_to_logs(envelopes)

    assert len(logs) == 1
    assert logs[0]["body"] == expected_body

    # Verify template is only stored when there are parameters
    if params:
        assert logs[0]["attributes"]["sentry.message.template"] == message
    else:
        assert "sentry.message.template" not in logs[0]["attributes"]


@minimum_python_37
def test_transport_format(sentry_init, capture_envelopes):
    sentry_init(enable_logs=True, server_name="test-server", release="1.0.0")

    envelopes = capture_envelopes()

    sentry_sdk.logger.warning("This is a log...")

    sentry_sdk.get_client().flush()

    assert len(envelopes) == 1
    assert len(envelopes[0].items) == 1
    item = envelopes[0].items[0]

    assert item.type == "log"
    assert item.headers == {
        "type": "log",
        "item_count": 1,
        "content_type": "application/vnd.sentry.items.log+json",
    }
    assert item.payload.json == {
        "items": [
            {
                "body": "This is a log...",
                "level": "warn",
                "timestamp": mock.ANY,
                "trace_id": mock.ANY,
                "span_id": mock.ANY,
                "attributes": {
                    "sentry.environment": {
                        "type": "string",
                        "value": "production",
                    },
                    "sentry.release": {
                        "type": "string",
                        "value": "1.0.0",
                    },
                    "sentry.sdk.name": {
                        "type": "string",
                        "value": mock.ANY,
                    },
                    "sentry.sdk.version": {
                        "type": "string",
                        "value": VERSION,
                    },
                    "sentry.severity_number": {
                        "type": "integer",
                        "value": 13,
                    },
                    "sentry.severity_text": {
                        "type": "string",
                        "value": "warn",
                    },
                    "server.address": {
                        "type": "string",
                        "value": "test-server",
                    },
                },
            }
        ]
    }


@minimum_python_37
def test_batcher_drops_logs(sentry_init, monkeypatch):
    sentry_init(enable_logs=True, server_name="test-server", release="1.0.0")
    client = sentry_sdk.get_client()

    def no_op_flush():
        pass

    monkeypatch.setattr(client.log_batcher, "_flush", no_op_flush)

    lost_event_calls = []

    def record_lost_event(reason, data_category=None, item=None, *, quantity=1):
        lost_event_calls.append((reason, data_category, item, quantity))

    monkeypatch.setattr(client.log_batcher, "_record_lost_func", record_lost_event)

    for i in range(1_005):  # 5 logs over the hard limit
        sentry_sdk.logger.info("This is a 'info' log...")

    assert len(lost_event_calls) == 5

    for lost_event_call in lost_event_calls:
        reason, data_category, item, quantity = lost_event_call

        assert reason == "queue_overflow"
        assert data_category == "log_item"
        assert quantity == 1

        assert item.type == "log"
        assert item.headers == {
            "type": "log",
            "item_count": 1,
            "content_type": "application/vnd.sentry.items.log+json",
        }
        assert item.payload.json == {
            "items": [
                {
                    "body": "This is a 'info' log...",
                    "level": "info",
                    "timestamp": mock.ANY,
                    "trace_id": mock.ANY,
                    "span_id": mock.ANY,
                    "attributes": {
                        "sentry.environment": {
                            "type": "string",
                            "value": "production",
                        },
                        "sentry.release": {
                            "type": "string",
                            "value": "1.0.0",
                        },
                        "sentry.sdk.name": {
                            "type": "string",
                            "value": mock.ANY,
                        },
                        "sentry.sdk.version": {
                            "type": "string",
                            "value": VERSION,
                        },
                        "sentry.severity_number": {
                            "type": "integer",
                            "value": 9,
                        },
                        "sentry.severity_text": {
                            "type": "string",
                            "value": "info",
                        },
                        "server.address": {
                            "type": "string",
                            "value": "test-server",
                        },
                    },
                }
            ]
        }


@minimum_python_37
def test_log_gets_attributes_from_scopes(sentry_init, capture_envelopes):
    sentry_init(enable_logs=True)

    envelopes = capture_envelopes()

    global_scope = sentry_sdk.get_global_scope()
    global_scope.set_attribute("global.attribute", "value")

    with sentry_sdk.new_scope() as scope:
        scope.set_attribute("current.attribute", "value")
        sentry_sdk.logger.warning("Hello, world!")

    sentry_sdk.logger.warning("Hello again!")

    get_client().flush()

    logs = envelopes_to_logs(envelopes)
    (log1, log2) = logs

    assert log1["attributes"]["global.attribute"] == "value"
    assert log1["attributes"]["current.attribute"] == "value"

    assert log2["attributes"]["global.attribute"] == "value"
    assert "current.attribute" not in log2["attributes"]


@minimum_python_37
def test_log_attributes_override_scope_attributes(sentry_init, capture_envelopes):
    sentry_init(enable_logs=True)

    envelopes = capture_envelopes()

    with sentry_sdk.new_scope() as scope:
        scope.set_attribute("durable.attribute", "value1")
        scope.set_attribute("temp.attribute", "value1")
        sentry_sdk.logger.warning(
            "Hello, world!", attributes={"temp.attribute": "value2"}
        )

    get_client().flush()

    logs = envelopes_to_logs(envelopes)
    (log,) = logs

    assert log["attributes"]["durable.attribute"] == "value1"
    assert log["attributes"]["temp.attribute"] == "value2"


@minimum_python_37
def test_log_array_attributes(sentry_init, capture_envelopes):
    """Test homogeneous list and tuple attributes, and fallback for inhomogeneous collections."""

    sentry_init(enable_logs=True)

    envelopes = capture_envelopes()

    with sentry_sdk.new_scope() as scope:
        scope.set_attribute("string_list", ["value1", "value2"])
        scope.set_attribute("int_tuple", (3, 2, 1, 4))
        scope.set_attribute("inhomogeneous_tuple", (3, 2.0, 1, 4))  # type: ignore[arg-type]

        sentry_sdk.logger.warning(
            "Hello, world!",
            attributes={
                "float_list": [3.0, 3.5, 4.2],
                "bool_tuple": (False, False, True),
                "inhomogeneous_list": [3.2, True, None],
            },
        )

    get_client().flush()

    assert len(envelopes) == 1
    assert len(envelopes[0].items) == 1
    item = envelopes[0].items[0]
    serialized_attributes = item.payload.json["items"][0]["attributes"]

    assert serialized_attributes["string_list"] == {
        "value": ["value1", "value2"],
        "type": "string[]",
    }
    assert serialized_attributes["int_tuple"] == {
        "value": [3, 2, 1, 4],
        "type": "integer[]",
    }
    assert serialized_attributes["inhomogeneous_tuple"] == {
        "value": "(3, 2.0, 1, 4)",
        "type": "string",
    }

    assert serialized_attributes["float_list"] == {
        "value": [3.0, 3.5, 4.2],
        "type": "double[]",
    }
    assert serialized_attributes["bool_tuple"] == {
        "value": [False, False, True],
        "type": "boolean[]",
    }
    assert serialized_attributes["inhomogeneous_list"] == {
        "value": "[3.2, True, None]",
        "type": "string",
    }


@minimum_python_37
def test_attributes_preserialized_in_before_send(sentry_init, capture_envelopes):
    """We don't surface user-held references to objects in attributes."""

    def before_send_log(log, _):
        assert isinstance(log["attributes"]["instance"], str)
        assert isinstance(log["attributes"]["dictionary"], str)
        assert isinstance(log["attributes"]["inhomogeneous_list"], str)
        assert isinstance(log["attributes"]["inhomogeneous_tuple"], str)

        return log

    sentry_init(enable_logs=True, before_send_log=before_send_log)

    envelopes = capture_envelopes()

    class Cat:
        pass

    instance = Cat()
    dictionary = {"color": "tortoiseshell"}

    sentry_sdk.logger.warning(
        "Hello world!",
        attributes={
            "instance": instance,
            "dictionary": dictionary,
            "inhomogeneous_list": [3.2, True, None],
            "inhomogeneous_tuple": (3, 2.0, 1, 4),
        },
    )

    get_client().flush()

    logs = envelopes_to_logs(envelopes)
    (log,) = logs

    assert isinstance(log["attributes"]["instance"], str)
    assert isinstance(log["attributes"]["dictionary"], str)
    assert isinstance(log["attributes"]["inhomogeneous_list"], str)
    assert isinstance(log["attributes"]["inhomogeneous_tuple"], str)


@minimum_python_37
def test_array_attributes_deep_copied_in_before_send(sentry_init, capture_envelopes):
    """We don't surface user-held references to objects in attributes."""

    strings = ["value1", "value2"]
    ints = (3, 2, 1, 4)

    def before_send_log(log, _):
        assert log["attributes"]["string_list"] is not strings
        assert log["attributes"]["int_tuple"] is not ints

        return log

    sentry_init(enable_logs=True, before_send_log=before_send_log)

    sentry_sdk.logger.warning(
        "Hello world!",
        attributes={
            "string_list": strings,
            "int_tuple": ints,
        },
    )

    get_client().flush()