2019-08-08 16:47:18 -04:00
|
|
|
# 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
|
2020-10-14 13:44:06 -04:00
|
|
|
import time
|
2019-08-08 16:47:18 -04:00
|
|
|
import unittest
|
2023-06-01 15:01:10 -04:00
|
|
|
from datetime import timedelta
|
|
|
|
from typing import Any, Optional
|
2020-10-14 13:44:06 -04:00
|
|
|
from unittest.mock import patch
|
2019-08-08 16:47:18 -04:00
|
|
|
|
2024-04-24 20:19:53 -04:00
|
|
|
from flask import current_app # noqa: F401
|
2021-03-05 15:12:42 -05:00
|
|
|
from freezegun import freeze_time
|
|
|
|
|
|
|
|
from superset import security_manager
|
|
|
|
from superset.utils.log import (
|
|
|
|
AbstractEventLogger,
|
|
|
|
DBEventLogger,
|
|
|
|
get_event_logger_from_cfg_value,
|
|
|
|
)
|
2021-07-01 11:03:07 -04:00
|
|
|
from tests.integration_tests.test_app import app
|
2019-08-08 16:47:18 -04:00
|
|
|
|
|
|
|
|
|
|
|
class TestEventLogger(unittest.TestCase):
|
2020-12-15 20:22:23 -05:00
|
|
|
def test_correct_config_object(self):
|
|
|
|
# test that assignment of concrete AbstractBaseClass impl returns
|
|
|
|
# unmodified object
|
2019-08-08 16:47:18 -04:00
|
|
|
obj = DBEventLogger()
|
|
|
|
res = get_event_logger_from_cfg_value(obj)
|
2020-12-15 20:22:23 -05:00
|
|
|
self.assertIs(obj, res)
|
2019-08-08 16:47:18 -04:00
|
|
|
|
2020-12-15 20:22:23 -05:00
|
|
|
def test_config_class_deprecation(self):
|
|
|
|
# test that assignment of a class object to EVENT_LOGGER is correctly
|
|
|
|
# deprecated
|
2019-08-08 16:47:18 -04:00
|
|
|
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)
|
|
|
|
|
2020-12-15 20:22:23 -05:00
|
|
|
def test_raises_typerror_if_not_abc(self):
|
|
|
|
# test that assignment of non AbstractEventLogger derived type raises
|
|
|
|
# TypeError
|
2019-08-08 16:47:18 -04:00
|
|
|
with self.assertRaises(TypeError):
|
|
|
|
get_event_logger_from_cfg_value(logging.getLogger())
|
2020-10-14 13:44:06 -04:00
|
|
|
|
|
|
|
@patch.object(DBEventLogger, "log")
|
2020-12-15 20:22:23 -05:00
|
|
|
def test_log_this(self, mock_log):
|
2020-10-14 13:44:06 -04:00
|
|
|
logger = DBEventLogger()
|
|
|
|
|
|
|
|
@logger.log_this
|
|
|
|
def test_func():
|
|
|
|
time.sleep(0.05)
|
|
|
|
return 1
|
|
|
|
|
2020-12-15 20:22:23 -05:00
|
|
|
with app.test_request_context("/superset/dashboard/1/?myparam=foo"):
|
2020-10-14 13:44:06 -04:00
|
|
|
result = test_func()
|
2020-12-15 20:22:23 -05:00
|
|
|
payload = mock_log.call_args[1]
|
2020-10-14 13:44:06 -04:00
|
|
|
self.assertEqual(result, 1)
|
2020-12-15 20:22:23 -05:00
|
|
|
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)
|
2020-10-14 13:44:06 -04:00
|
|
|
|
|
|
|
@patch.object(DBEventLogger, "log")
|
2020-12-15 20:22:23 -05:00
|
|
|
def test_log_this_with_extra_payload(self, mock_log):
|
2020-10-14 13:44:06 -04:00
|
|
|
logger = DBEventLogger()
|
|
|
|
|
2020-12-15 20:22:23 -05:00
|
|
|
@logger.log_this_with_extra_payload
|
|
|
|
def test_func(arg1, add_extra_log_payload, karg1=1):
|
2020-10-14 13:44:06 -04:00
|
|
|
time.sleep(0.1)
|
2020-12-15 20:22:23 -05:00
|
|
|
add_extra_log_payload(foo="bar")
|
2020-10-14 13:44:06 -04:00
|
|
|
return arg1 * karg1
|
|
|
|
|
|
|
|
with app.test_request_context():
|
|
|
|
result = test_func(1, karg1=2) # pylint: disable=no-value-for-parameter
|
2020-12-15 20:22:23 -05:00
|
|
|
payload = mock_log.call_args[1]
|
2020-10-14 13:44:06 -04:00
|
|
|
self.assertEqual(result, 2)
|
2020-12-04 10:59:28 -05:00
|
|
|
self.assertEqual(
|
2020-12-15 20:22:23 -05:00
|
|
|
payload["records"],
|
|
|
|
[
|
|
|
|
{
|
|
|
|
"foo": "bar",
|
|
|
|
"path": "/",
|
|
|
|
"karg1": 2,
|
|
|
|
"object_ref": test_func.__qualname__,
|
|
|
|
}
|
|
|
|
],
|
2020-12-04 10:59:28 -05:00
|
|
|
)
|
2020-12-15 20:22:23 -05:00
|
|
|
self.assertGreaterEqual(payload["duration_ms"], 100)
|
2021-03-05 15:12:42 -05:00
|
|
|
|
2022-06-24 20:57:04 -04:00
|
|
|
@patch("superset.utils.core.g", spec={})
|
2021-03-05 15:12:42 -05:00
|
|
|
@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"}],
|
2024-04-22 19:30:50 -04:00
|
|
|
"database_id": None,
|
2022-06-24 20:57:04 -04:00
|
|
|
"user_id": 2,
|
2024-04-22 19:30:50 -04:00
|
|
|
"duration": 15000,
|
2021-03-05 15:12:42 -05:00
|
|
|
}
|
|
|
|
]
|
|
|
|
|
2022-06-24 20:57:04 -04:00
|
|
|
@patch("superset.utils.core.g", spec={})
|
2021-03-05 15:12:42 -05:00
|
|
|
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,
|
2023-02-17 12:48:24 -05:00
|
|
|
payload_override={"engine": "sqlite"},
|
2021-03-05 15:12:42 -05:00
|
|
|
)
|
|
|
|
|
|
|
|
assert logger.records == [
|
|
|
|
{
|
|
|
|
"records": [
|
|
|
|
{
|
|
|
|
"path": "/",
|
|
|
|
"object_ref": {"baz": "food"},
|
2023-02-17 12:48:24 -05:00
|
|
|
"payload_override": {"engine": "sqlite"},
|
2021-03-05 15:12:42 -05:00
|
|
|
}
|
|
|
|
],
|
2024-04-22 19:30:50 -04:00
|
|
|
"database_id": None,
|
2022-06-24 20:57:04 -04:00
|
|
|
"user_id": 2,
|
2021-03-05 15:12:42 -05:00
|
|
|
"duration": 5558756000,
|
|
|
|
}
|
|
|
|
]
|
2021-04-13 10:08:34 -04:00
|
|
|
|
2022-06-24 20:57:04 -04:00
|
|
|
@patch("superset.utils.core.g", spec={})
|
2021-04-13 10:08:34 -04:00
|
|
|
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,
|
2023-02-17 12:48:24 -05:00
|
|
|
payload_override={"engine": "sqlite"},
|
2021-04-13 10:08:34 -04:00
|
|
|
)
|
|
|
|
|
2024-04-24 20:19:53 -04:00
|
|
|
assert logger.records[0]["user_id"] == None # noqa: E711
|