import logging
import time
from unittest.mock import MagicMock

import pytest
from aarecommon.config.logger_events import log_timing, merge_log_context


def test_log_timing_success():
    logger = MagicMock(spec=logging.Logger)

    @log_timing(logger, message_prefix="Test", level=logging.INFO)
    def sample_func(x):
        time.sleep(0.01)
        return x * 2

    result = sample_func(21)

    assert result == 42
    assert logger.log.call_count == 2
    # First call: Starting
    logger.log.assert_any_call(logging.INFO, "Test: Starting sample_func")
    # Second call: Finished (check that it contains the message and duration_s in extra)
    args, kwargs = logger.log.call_args_list[1]
    assert args[0] == logging.INFO
    assert "Finished sample_func in" in args[1]
    assert "duration_s" in kwargs["extra"]
    assert kwargs["extra"]["duration_s"] >= 0.01


def test_log_timing_failure():
    logger = MagicMock(spec=logging.Logger)

    @log_timing(logger, level=logging.ERROR)
    def failing_func():
        time.sleep(0.01)
        raise ValueError("Something went wrong")

    with pytest.raises(ValueError, match="Something went wrong"):
        failing_func()

    assert logger.log.call_count == 2
    # First call: Starting
    logger.log.assert_any_call(logging.ERROR, "Starting failing_func")
    # Second call: FAILED
    args, kwargs = logger.log.call_args_list[1]
    assert args[0] == logging.ERROR
    assert "failing_func FAILED after" in args[1]
    assert "Something went wrong" in args[1]
    assert "duration_s" in kwargs["extra"]


def test_merge_log_context():
    ctx1 = {"a": 1, "b": 2}
    ctx2 = {"b": 3, "c": 4}
    merged = merge_log_context(ctx1, ctx2, d=5)
    assert merged == {"a": 1, "b": 3, "c": 4, "d": 5}

    merged_none = merge_log_context(ctx1, None)
    assert merged_none == {"a": 1, "b": 2}