tests/event_logger_tests.py

# Licensed to the Apache Software Foundation (ASF) under one
# or more contributor license agreements.  See the NOTICE file
# distributed with this work for additional information
# regarding copyright ownership.  The ASF licenses this file
# to you 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 time
import unittest
from datetime import datetime, timedelta
from typing import Any, Callable, cast, Dict, Iterator, Optional, Type, Union
from unittest.mock import patch

from flask import current_app
from freezegun import freeze_time

from superset import security_manager
from superset.utils.log import (
    AbstractEventLogger,
    DBEventLogger,
    get_event_logger_from_cfg_value,
)
from tests.test_app import app


class TestEventLogger(unittest.TestCase):
    def test_correct_config_object(self):
        # test that assignment of concrete AbstractBaseClass impl returns
        # unmodified object
        obj = DBEventLogger()
        res = get_event_logger_from_cfg_value(obj)
        self.assertIs(obj, res)

    def test_config_class_deprecation(self):
        # test that assignment of a class object to EVENT_LOGGER is correctly
        # deprecated
        res = None

        # print warning if a class is assigned to EVENT_LOGGER
        with self.assertLogs(level="WARNING"):
            res = get_event_logger_from_cfg_value(DBEventLogger)

        # class is instantiated and returned
        self.assertIsInstance(res, DBEventLogger)

    def test_raises_typerror_if_not_abc(self):
        # test that assignment of non AbstractEventLogger derived type raises
        # TypeError
        with self.assertRaises(TypeError):
            get_event_logger_from_cfg_value(logging.getLogger())

    @patch.object(DBEventLogger, "log")
    def test_log_this(self, mock_log):
        logger = DBEventLogger()

        @logger.log_this
        def test_func():
            time.sleep(0.05)
            return 1

        with app.test_request_context("/superset/dashboard/1/?myparam=foo"):
            result = test_func()
            payload = mock_log.call_args[1]
            self.assertEqual(result, 1)
            self.assertEqual(
                payload["records"],
                [
                    {
                        "myparam": "foo",
                        "path": "/superset/dashboard/1/",
                        "url_rule": "/superset/dashboard/<dashboard_id_or_slug>/",
                        "object_ref": test_func.__qualname__,
                    }
                ],
            )
            self.assertGreaterEqual(payload["duration_ms"], 50)

    @patch.object(DBEventLogger, "log")
    def test_log_this_with_extra_payload(self, mock_log):
        logger = DBEventLogger()

        @logger.log_this_with_extra_payload
        def test_func(arg1, add_extra_log_payload, karg1=1):
            time.sleep(0.1)
            add_extra_log_payload(foo="bar")
            return arg1 * karg1

        with app.test_request_context():
            result = test_func(1, karg1=2)  # pylint: disable=no-value-for-parameter
            payload = mock_log.call_args[1]
            self.assertEqual(result, 2)
            self.assertEqual(
                payload["records"],
                [
                    {
                        "foo": "bar",
                        "path": "/",
                        "karg1": 2,
                        "object_ref": test_func.__qualname__,
                    }
                ],
            )
            self.assertGreaterEqual(payload["duration_ms"], 100)

    @patch("superset.utils.log.g", spec={})
    @freeze_time("Jan 14th, 2020", auto_tick_seconds=15)
    def test_context_manager_log(self, mock_g):
        class DummyEventLogger(AbstractEventLogger):
            def __init__(self):
                self.records = []

            def log(
                self,
                user_id: Optional[int],
                action: str,
                dashboard_id: Optional[int],
                duration_ms: Optional[int],
                slice_id: Optional[int],
                referrer: Optional[str],
                *args: Any,
                **kwargs: Any,
            ):
                self.records.append(
                    {**kwargs, "user_id": user_id, "duration": duration_ms}
                )

        logger = DummyEventLogger()

        with app.test_request_context():
            mock_g.user = security_manager.find_user("gamma")
            with logger(action="foo", engine="bar"):
                pass

        assert logger.records == [
            {
                "records": [{"path": "/", "engine": "bar"}],
                "user_id": "2",
                "duration": 15000.0,
            }
        ]

    @patch("superset.utils.log.g", spec={})
    def test_context_manager_log_with_context(self, mock_g):
        class DummyEventLogger(AbstractEventLogger):
            def __init__(self):
                self.records = []

            def log(
                self,
                user_id: Optional[int],
                action: str,
                dashboard_id: Optional[int],
                duration_ms: Optional[int],
                slice_id: Optional[int],
                referrer: Optional[str],
                *args: Any,
                **kwargs: Any,
            ):
                self.records.append(
                    {**kwargs, "user_id": user_id, "duration": duration_ms}
                )

        logger = DummyEventLogger()

        with app.test_request_context():
            mock_g.user = security_manager.find_user("gamma")
            logger.log_with_context(
                action="foo",
                duration=timedelta(days=64, seconds=29156, microseconds=10),
                object_ref={"baz": "food"},
                log_to_statsd=False,
                payload_override={"engine": "sqllite"},
            )

        assert logger.records == [
            {
                "records": [
                    {
                        "path": "/",
                        "object_ref": {"baz": "food"},
                        "payload_override": {"engine": "sqllite"},
                    }
                ],
                "user_id": "2",
                "duration": 5558756000,
            }
        ]

    @patch("superset.utils.log.g", spec={})
    def test_log_with_context_user_null(self, mock_g):
        class DummyEventLogger(AbstractEventLogger):
            def __init__(self):
                self.records = []

            def log(
                self,
                user_id: Optional[int],
                action: str,
                dashboard_id: Optional[int],
                duration_ms: Optional[int],
                slice_id: Optional[int],
                referrer: Optional[str],
                *args: Any,
                **kwargs: Any,
            ):
                self.records.append(
                    {**kwargs, "user_id": user_id, "duration": duration_ms}
                )

        logger = DummyEventLogger()

        with app.test_request_context():
            mock_g.side_effect = Exception("oops")
            logger.log_with_context(
                action="foo",
                duration=timedelta(days=64, seconds=29156, microseconds=10),
                object_ref={"baz": "food"},
                log_to_statsd=False,
                payload_override={"engine": "sqllite"},
            )

        assert logger.records[0]["user_id"] == None