From 99d571a4a6ad368b3b49fd63ff46ed39ebca4447 Mon Sep 17 00:00:00 2001 From: Daniel Messer Date: Mon, 17 Jun 2024 21:17:39 +0200 Subject: [PATCH] logs: allow without strict logging (PROJQUAY-7116) (#2846) * allow to disable strict logging in general Signed-off-by: dmesser * add strict logging exceptions for log kinds during reads Signed-off-by: dmesser * add strict logging exceptions for log kinds during reads Signed-off-by: dmesser * formatting Signed-off-by: dmesser --------- Signed-off-by: dmesser --- config-tool/utils/scripts/dumpschema.py | 7 ++ config.py | 3 + data/logs_model/document_logs_model.py | 12 +- data/logs_model/splunk_logs_model.py | 10 +- data/logs_model/test/test_elasticsearch.py | 50 +++++++- data/logs_model/test/test_splunk.py | 127 +++++++++++++++++---- data/model/_basequery.py | 4 +- data/model/log.py | 15 ++- data/model/test/test_log.py | 22 ++-- util/config/schema.py | 7 ++ 10 files changed, 214 insertions(+), 43 deletions(-) diff --git a/config-tool/utils/scripts/dumpschema.py b/config-tool/utils/scripts/dumpschema.py index b18945cc27..c4b29e5dd5 100644 --- a/config-tool/utils/scripts/dumpschema.py +++ b/config-tool/utils/scripts/dumpschema.py @@ -182,6 +182,13 @@ + "and it is desired for pulls to continue during that time. Defaults to False.", "x-example": True, }, + "ALLOW_WITHOUT_STRICT_LOGGING": { + "type": "boolean", + "description": "If true, any action in which the audit log entry cannot be written will " + + "still succeed. Useful if using an external logging service that may be down " + + "intermittently and the registry should continue to work. Defaults to False.", + "x-example": False, + }, # Storage. "FEATURE_STORAGE_REPLICATION": { "type": "boolean", diff --git a/config.py b/config.py index 473d1cb47a..3510bb5e03 100644 --- a/config.py +++ b/config.py @@ -456,6 +456,9 @@ def create_transaction(db): # Allow registry pulls when unable to write to the audit log ALLOW_PULLS_WITHOUT_STRICT_LOGGING = False + # Allow any registry action when unable to write to the audit log + ALLOW_WITHOUT_STRICT_LOGGING = False + # Temporary tag expiration in seconds, this may actually be longer based on GC policy PUSH_TEMP_TAG_EXPIRATION_SEC = 60 * 60 # One hour per layer diff --git a/data/logs_model/document_logs_model.py b/data/logs_model/document_logs_model.py index 0879145a55..b3dab1b2b9 100644 --- a/data/logs_model/document_logs_model.py +++ b/data/logs_model/document_logs_model.py @@ -511,9 +511,15 @@ def log_action( try: self._logs_producer.send(log) except LogSendException as lse: - strict_logging_disabled = config.app_config.get("ALLOW_PULLS_WITHOUT_STRICT_LOGGING") - logger.exception("log_action failed", extra=({"exception": lse}).update(log.to_dict())) - if not (strict_logging_disabled and kind_name in ACTIONS_ALLOWED_WITHOUT_AUDIT_LOGGING): + strict_logging_disabled = config.app_config.get("ALLOW_WITHOUT_STRICT_LOGGING") or ( + config.app_config.get("ALLOW_PULLS_WITHOUT_STRICT_LOGGING") + and kind_name in ACTIONS_ALLOWED_WITHOUT_AUDIT_LOGGING + ) + if strict_logging_disabled: + logger.exception( + "log_action failed", extra=({"exception": lse}).update(log.to_dict()) + ) + else: raise def yield_logs_for_export( diff --git a/data/logs_model/splunk_logs_model.py b/data/logs_model/splunk_logs_model.py index da68e800b9..a2cfd0af76 100644 --- a/data/logs_model/splunk_logs_model.py +++ b/data/logs_model/splunk_logs_model.py @@ -94,9 +94,13 @@ def log_action( try: self._logs_producer.send(log_data) except LogSendException as lse: - strict_logging_disabled = config.app_config.get("ALLOW_PULLS_WITHOUT_STRICT_LOGGING") - logger.exception("log_action failed", extra=({"exception": lse}).update(log_data)) - if not (strict_logging_disabled and kind_name in ACTIONS_ALLOWED_WITHOUT_AUDIT_LOGGING): + strict_logging_disabled = config.app_config.get("ALLOW_WITHOUT_STRICT_LOGGING") or ( + config.app_config.get("ALLOW_PULLS_WITHOUT_STRICT_LOGGING") + and kind_name in ACTIONS_ALLOWED_WITHOUT_AUDIT_LOGGING + ) + if strict_logging_disabled: + logger.exception("log_action failed", extra=({"exception": lse}).update(log_data)) + else: raise def lookup_logs( diff --git a/data/logs_model/test/test_elasticsearch.py b/data/logs_model/test/test_elasticsearch.py index b09594af73..7156bc7b73 100644 --- a/data/logs_model/test/test_elasticsearch.py +++ b/data/logs_model/test/test_elasticsearch.py @@ -10,6 +10,7 @@ from httmock import HTTMock, urlmatch from mock import Mock, patch +from .mock_elasticsearch import * from data.logs_model import LogsModelProxy, configure from data.logs_model.elastic_logs import ( INDEX_DATE_FORMAT, @@ -18,8 +19,6 @@ ) from data.model.log import _json_serialize -from .mock_elasticsearch import * - FAKE_ES_HOST = "fakees" FAKE_ES_HOST_PATTERN = r"fakees.*" FAKE_ES_PORT = 443 @@ -210,16 +209,27 @@ def search(url, req): @pytest.mark.parametrize( """ - unlogged_pulls_ok, kind_name, namespace_name, repository, repository_name, + unlogged_ok,unlogged_pulls_ok, kind_name, namespace_name, repository, repository_name, timestamp, index_response, expected_request, throws """, [ # Invalid inputs pytest.param( - False, "non-existing", None, None, None, None, None, None, True, id="Invalid Kind" + False, + False, + "non-existing", + None, + None, + None, + None, + None, + None, + True, + id="Invalid Kind", ), pytest.param( + False, False, "pull_repo", "user1", @@ -233,6 +243,7 @@ def search(url, req): ), # Remote exceptions pytest.param( + False, False, "pull_repo", "user1", @@ -244,8 +255,22 @@ def search(url, req): True, id="Throw on pull log failure", ), + pytest.param( + False, + True, + "pull_repo", + "user1", + Mock(id=1), + None, + parse("2017-03-08T03:30"), + FAILURE_400, + INDEX_REQUEST_2017_03_08, + False, + id="Ok on pull log failure", + ), pytest.param( True, + False, "pull_repo", "user1", Mock(id=1), @@ -256,8 +281,22 @@ def search(url, req): False, id="Ok on pull log failure", ), + pytest.param( + True, + False, + "push_repo", + "user1", + None, + "repo1", + parse("2019-01-01T03:30"), + FAILURE_400, + INDEX_REQUEST_2019_01_01, + False, + id="Ok on push log failure", + ), # Success executions pytest.param( + False, False, "pull_repo", "user1", @@ -270,6 +309,7 @@ def search(url, req): id="Log with namespace name and repository", ), pytest.param( + False, False, "push_repo", "user1", @@ -284,6 +324,7 @@ def search(url, req): ], ) def test_log_action( + unlogged_ok, unlogged_pulls_ok, kind_name, namespace_name, @@ -302,6 +343,7 @@ def test_log_action( mock_elasticsearch.template = Mock(return_value=DEFAULT_TEMPLATE_RESPONSE) mock_elasticsearch.index = Mock(return_value=index_response) app_config["ALLOW_PULLS_WITHOUT_STRICT_LOGGING"] = unlogged_pulls_ok + app_config["ALLOW_WITHOUT_STRICT_LOGGING"] = unlogged_ok configure(app_config) performer = Mock(id=1) diff --git a/data/logs_model/test/test_splunk.py b/data/logs_model/test/test_splunk.py index 2f20d0ea11..1e01fb98b7 100644 --- a/data/logs_model/test/test_splunk.py +++ b/data/logs_model/test/test_splunk.py @@ -15,6 +15,8 @@ from ..logs_producer.splunk_logs_producer import SplunkLogsProducer from .test_elasticsearch import logs_model, mock_db_model from data.logs_model import configure +from data.logs_model.logs_producer import LogSendException +from data.model import config as _config from test.fixtures import * FAKE_SPLUNK_HOST = "fakesplunk" @@ -48,6 +50,12 @@ } +@pytest.fixture(scope="function") +def app_config(): + with patch.dict(_config.app_config, {}, clear=True): + yield _config.app_config + + @pytest.fixture() def splunk_logs_model_config(): conf = { @@ -105,11 +113,29 @@ def cert_file_path(): @pytest.mark.parametrize( """ - kind_name, namespace_name, - performer, ip, metadata, repository, repository_name, timestamp, throws + unlogged_ok, unlogged_pulls_ok, kind_name, namespace_name, performer, ip, + metadata, repository, repository_name, timestamp, throws, send_exception """, [ + # logs a push_repo action + pytest.param( + False, + False, + "push_repo", + "devtable", + FAKE_PERFORMER["user1"], + "192.168.1.1", + {"key": "value"}, + None, + "repo1", + parse("2019-01-01T03:30"), + False, + None, + ), + # doesn't raise a failed push_repo action pytest.param( + True, + False, "push_repo", "devtable", FAKE_PERFORMER["user1"], @@ -119,9 +145,42 @@ def cert_file_path(): "repo1", parse("2019-01-01T03:30"), False, + LogSendException("Failed to send log data"), + ), + # doesn't raise a failed pull_repo action + pytest.param( + False, + True, + "pull_repo", + "devtable", + FAKE_PERFORMER["user1"], + "192.168.1.1", + {"key": "value"}, + None, + "repo1", + parse("2019-01-01T03:30"), + False, + LogSendException("Failed to send log data"), + ), + # raise a failed pull_repo action + pytest.param( + False, + False, + "pull_repo", + "devtable", + FAKE_PERFORMER["user1"], + "192.168.1.1", + {"key": "value"}, + None, + "repo1", + parse("2019-01-01T03:30"), + True, + LogSendException("Failed to send log data"), ), # raises ValueError when repository_name is not None and repository is not None pytest.param( + False, + False, "pull_repo", "devtable", FAKE_PERFORMER["user1"], @@ -131,9 +190,12 @@ def cert_file_path(): "repo1", parse("2019-01-01T03:30"), True, + None, ), # raises exception when no namespace is given pytest.param( + False, + False, "pull_repo", None, FAKE_PERFORMER["user1"], @@ -143,10 +205,13 @@ def cert_file_path(): "user1/repo1", parse("2019-01-01T03:30"), True, + None, ), ], ) -def test_splunk_logs_producer( +def test_splunk_logs_producers( + unlogged_ok, + unlogged_pulls_ok, kind_name, namespace_name, performer, @@ -156,12 +221,17 @@ def test_splunk_logs_producer( repository_name, timestamp, throws, + send_exception, logs_model, splunk_logs_model_config, mock_db_model, initialized_db, cert_file_path, + app_config, ): + app_config["ALLOW_PULLS_WITHOUT_STRICT_LOGGING"] = unlogged_pulls_ok + app_config["ALLOW_WITHOUT_STRICT_LOGGING"] = unlogged_ok + with ( patch( "data.logs_model.logs_producer.splunk_logs_producer.SplunkLogsProducer.send" @@ -170,23 +240,40 @@ def test_splunk_logs_producer( ): with patch("ssl.SSLContext.load_verify_locations"): configure(splunk_logs_model_config) + + if send_exception: + mock_send.side_effect = send_exception + if throws: - with pytest.raises( - ValueError, - match=r"Incorrect argument provided when logging action logs, " - r"namespace name should not be empty", - ): - logs_model.log_action( - kind_name, - namespace_name, - performer, - ip, - metadata, - repository, - repository_name, - timestamp, - ) - mock_send.assert_not_called() + if not send_exception: + with pytest.raises( + ValueError, + match=r"Incorrect argument provided when logging action logs, " + r"namespace name should not be empty", + ): + logs_model.log_action( + kind_name, + namespace_name, + performer, + ip, + metadata, + repository, + repository_name, + timestamp, + ) + mock_send.assert_not_called() + else: + with pytest.raises(LogSendException): + logs_model.log_action( + kind_name, + namespace_name, + performer, + ip, + metadata, + repository, + repository_name, + timestamp, + ) else: logs_model.log_action( kind_name, @@ -203,7 +290,7 @@ def test_splunk_logs_producer( "account": "devtable", "datetime": datetime(2019, 1, 1, 3, 30), "ip": "192.168.1.1", - "kind": "push_repo", + "kind": kind_name, "metadata_json": {"key": "value"}, "performer": "fake_username", "repository": None, diff --git a/data/model/_basequery.py b/data/model/_basequery.py index c407f72781..69a9e7eeae 100644 --- a/data/model/_basequery.py +++ b/data/model/_basequery.py @@ -224,7 +224,9 @@ def update_last_accessed(token_or_user): pass except PeeweeException as ex: # If there is any form of DB exception, only fail if strict logging is enabled. - strict_logging_disabled = config.app_config.get("ALLOW_PULLS_WITHOUT_STRICT_LOGGING") + strict_logging_disabled = config.app_config.get( + "ALLOW_WITHOUT_STRICT_LOGGING" + ) or config.app_config.get("ALLOW_PULLS_WITHOUT_STRICT_LOGGING") if strict_logging_disabled: data = { "exception": ex, diff --git a/data/model/log.py b/data/model/log.py index 3c3536093c..9c4759311d 100644 --- a/data/model/log.py +++ b/data/model/log.py @@ -11,7 +11,13 @@ logger = logging.getLogger(__name__) -ACTIONS_ALLOWED_WITHOUT_AUDIT_LOGGING = ["pull_repo"] +ACTIONS_ALLOWED_WITHOUT_AUDIT_LOGGING = [ + "pull_repo", + "login_failure", + "pull_repo_failed", + "login_success", + "logout_success", +] def _logs_query( @@ -266,8 +272,11 @@ def log_action( try: LogEntry3.create(**log_data) except PeeweeException as ex: - strict_logging_disabled = config.app_config.get("ALLOW_PULLS_WITHOUT_STRICT_LOGGING") - if strict_logging_disabled and kind_name in ACTIONS_ALLOWED_WITHOUT_AUDIT_LOGGING: + strict_logging_disabled = config.app_config.get("ALLOW_WITHOUT_STRICT_LOGGING") or ( + config.app_config.get("ALLOW_PULLS_WITHOUT_STRICT_LOGGING") + and kind_name in ACTIONS_ALLOWED_WITHOUT_AUDIT_LOGGING + ) + if strict_logging_disabled: logger.exception("log_action failed", extra=({"exception": ex}).update(log_data)) else: raise diff --git a/data/model/test/test_log.py b/data/model/test/test_log.py index e6239e1569..5c970cf1d1 100644 --- a/data/model/test/test_log.py +++ b/data/model/test/test_log.py @@ -54,22 +54,25 @@ def test_log_action_unknown_action(action_kind): ], ) @pytest.mark.parametrize( - "unlogged_pulls_ok,action_kind,db_exception,throws", + "unlogged_ok,unlogged_pulls_ok,action_kind,db_exception,throws", [ - (False, "pull_repo", None, False), - (False, "push_repo", None, False), - (False, "pull_repo", PeeweeException, True), - (False, "push_repo", PeeweeException, True), - (True, "pull_repo", PeeweeException, False), - (True, "push_repo", PeeweeException, True), - (True, "pull_repo", Exception, True), - (True, "push_repo", Exception, True), + (False, False, "pull_repo", None, False), + (False, False, "push_repo", None, False), + (False, False, "pull_repo", PeeweeException, True), + (False, False, "push_repo", PeeweeException, True), + (False, True, "pull_repo", PeeweeException, False), + (False, True, "push_repo", PeeweeException, True), + (False, True, "pull_repo", Exception, True), + (False, True, "push_repo", Exception, True), + (True, False, "push_repo", Exception, True), + (True, True, "push_repo", Exception, True), ], ) def test_log_action( user_or_org_name, account_id, account, + unlogged_ok, unlogged_pulls_ok, action_kind, db_exception, @@ -87,6 +90,7 @@ def test_log_action( } app_config["SERVICE_LOG_ACCOUNT_ID"] = account_id app_config["ALLOW_PULLS_WITHOUT_STRICT_LOGGING"] = unlogged_pulls_ok + app_config["ALLOW_WITHOUT_STRICT_LOGGING"] = unlogged_ok logentry.create.side_effect = db_exception diff --git a/util/config/schema.py b/util/config/schema.py index 29ec42841d..01752b3513 100644 --- a/util/config/schema.py +++ b/util/config/schema.py @@ -278,6 +278,13 @@ + "and it is desired for pulls to continue during that time. Defaults to False.", "x-example": True, }, + "ALLOW_WITHOUT_STRICT_LOGGING": { + "type": "boolean", + "description": "If true, any action in which the audit log entry cannot be written will " + + "still succeed. Useful if using an external logging service that may be down " + + "intermittently and the registry should continue to work. Defaults to False.", + "x-example": False, + }, # Storage. "FEATURE_STORAGE_REPLICATION": { "type": "boolean",