From 33c79831173b49d21afb48124d0c2e9b80215ea4 Mon Sep 17 00:00:00 2001 From: jefer94 Date: Thu, 7 Dec 2023 22:33:12 -0500 Subject: [PATCH] hide cache messages on deploy --- breathecode/commons/actions.py | 15 ++++++-- breathecode/commons/tasks.py | 22 ++++++----- .../tasks/tests_mark_task_as_cancelled.py | 10 ++--- .../tests/tasks/tests_mark_task_as_paused.py | 10 ++--- .../tests/tasks/tests_mark_task_as_pending.py | 20 +++++----- .../tasks/tests_mark_task_as_reversed.py | 18 ++++----- breathecode/utils/decorators/task.py | 38 ++++++++++++++----- conftest.py | 14 +++++++ scripts/dyno/celeryworker.sh | 1 - scripts/dyno/release.sh | 2 + 10 files changed, 97 insertions(+), 53 deletions(-) diff --git a/breathecode/commons/actions.py b/breathecode/commons/actions.py index d3acb1b23..88571eecd 100644 --- a/breathecode/commons/actions.py +++ b/breathecode/commons/actions.py @@ -1,3 +1,4 @@ +import functools import logging import os from django_redis import get_redis_connection @@ -20,6 +21,12 @@ def is_test(): return env == 'test' +@functools.lru_cache(maxsize=1) +def is_output_enable(): + # Set to True to enable output within the cache and it's used for testing purposes. + return os.getenv('HIDE_CACHE_LOG', '0') in ['0', 'false', 'False', 'f'] + + def clean_cache(model_cls): from .tasks import clean_task @@ -27,7 +34,8 @@ def clean_cache(model_cls): is_a_dependency = model_cls in CACHE_DEPENDENCIES if not have_descriptor and not is_a_dependency: - logger.warn(f'Cache not implemented for {model_cls.__name__}, skipping') + if is_output_enable(): + logger.warning(f'Cache not implemented for {model_cls.__name__}, skipping') return key = model_cls.__module__ + '.' + model_cls.__name__ @@ -36,7 +44,7 @@ def clean_cache(model_cls): if not have_descriptor and is_a_dependency: if is_test() is False: conn = get_redis_connection('default') - my_lock = Lock(conn, f'cache:descriptor:{key}', timeout=0.2, blocking_timeout=0.2) + my_lock = Lock(conn, f'cache:descriptor:{key}', timeout=3, blocking_timeout=3) if my_lock.acquire(blocking=True): @@ -50,7 +58,8 @@ class DepCache(Cache): my_lock.release() else: - logger.error(f'Could not acquire lock for {key} on get_or_create, operation timed out.') + if is_output_enable(): + logger.error(f'Could not acquire lock for {key} on get_or_create, operation timed out.') return else: diff --git a/breathecode/commons/tasks.py b/breathecode/commons/tasks.py index 797c9fc08..e3ee4abc1 100644 --- a/breathecode/commons/tasks.py +++ b/breathecode/commons/tasks.py @@ -3,6 +3,7 @@ from typing import Any from celery import shared_task from datetime import timedelta +from breathecode.commons.actions import is_output_enable from breathecode.commons.models import TaskManager from django.utils import timezone from breathecode.utils import CACHE_DESCRIPTORS @@ -24,7 +25,7 @@ def mark_task_as_cancelled(task_manager_id): return if x.status not in ['PENDING', 'PAUSED']: - logger.warn(f'TaskManager {task_manager_id} was already DONE') + logger.warning(f'TaskManager {task_manager_id} was already DONE') return x.status = 'CANCELLED' @@ -44,12 +45,12 @@ def mark_task_as_reversed(task_manager_id, *, attempts=0, force=False): return if x.reverse_module is None or x.reverse_name is None: - logger.warn(f'TaskManager {task_manager_id} does not have a reverse function') + logger.warning(f'TaskManager {task_manager_id} does not have a reverse function') return if not force and (x.status != 'DONE' and not x.last_run < timezone.now() - timedelta(minutes=TOLERANCE) and not x.killed and attempts < 10): - logger.warn(f'TaskManager {task_manager_id} was not killed, scheduling to run it again') + logger.warning(f'TaskManager {task_manager_id} was not killed, scheduling to run it again') x.status = 'CANCELLED' x.save() @@ -80,7 +81,7 @@ def mark_task_as_paused(task_manager_id): return if x.status != 'PENDING': - logger.warn(f'TaskManager {task_manager_id} is not running') + logger.warning(f'TaskManager {task_manager_id} is not running') return x.status = 'PAUSED' @@ -100,16 +101,16 @@ def mark_task_as_pending(task_manager_id, *, attempts=0, force=False, last_run=N return if x.status in ['DONE', 'CANCELLED', 'REVERSED']: - logger.warn(f'TaskManager {task_manager_id} was already DONE') + logger.warning(f'TaskManager {task_manager_id} was already DONE') return if last_run and last_run != x.last_run: - logger.warn(f'TaskManager {task_manager_id} is already running') + logger.warning(f'TaskManager {task_manager_id} is already running') return if force is False and not x.last_run < timezone.now() - timedelta( minutes=TOLERANCE) and not x.killed and attempts < 10: - logger.warn(f'TaskManager {task_manager_id} was not killed, scheduling to run it again') + logger.warning(f'TaskManager {task_manager_id} was not killed, scheduling to run it again') mark_task_as_pending.apply_async(args=(task_manager_id, ), kwargs={ @@ -162,13 +163,14 @@ def clean_task(key: str, **_: Any): model_cls = getattr(module, model) if model_cls not in CACHE_DESCRIPTORS: - raise AbortTask(f'Cache not implemented for {model_cls.__name__}, skipping') + raise AbortTask(f'Cache not implemented for {model_cls.__name__}, skipping', log=is_output_enable()) cache = CACHE_DESCRIPTORS[model_cls] try: cache.clear() - logger.debug(f'Cache cleaned for {key}') + if is_output_enable(): + logger.debug(f'Cache cleaned for {key}') except Exception: - raise RetryTask(f'Could not clean the cache {key}') + raise RetryTask(f'Could not clean the cache {key}', log=is_output_enable()) diff --git a/breathecode/commons/tests/tasks/tests_mark_task_as_cancelled.py b/breathecode/commons/tests/tasks/tests_mark_task_as_cancelled.py index d4f391dee..b293bba1f 100644 --- a/breathecode/commons/tests/tasks/tests_mark_task_as_cancelled.py +++ b/breathecode/commons/tests/tasks/tests_mark_task_as_cancelled.py @@ -16,7 +16,7 @@ @pytest.fixture(autouse=True) def setup(db, monkeypatch): monkeypatch.setattr('logging.Logger.info', MagicMock()) - monkeypatch.setattr('logging.Logger.warn', MagicMock()) + monkeypatch.setattr('logging.Logger.warning', MagicMock()) monkeypatch.setattr('logging.Logger.error', MagicMock()) yield @@ -68,7 +68,7 @@ def _arrange(data={}): model = bc.database.create(task_manager=task_manager) Logger.info.call_args_list = [] - Logger.warn.call_args_list = [] + Logger.warning.call_args_list = [] Logger.error.call_args_list = [] return model @@ -84,7 +84,7 @@ def test_not_found(bc: Breathecode): assert res == None assert Logger.info.call_args_list == [call('Running mark_task_as_cancelled for 1')] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [call('TaskManager 1 not found')] assert bc.database.list_of('commons.TaskManager') == [] @@ -105,7 +105,7 @@ def test_found(bc: Breathecode, arrange): call('TaskManager 1 is being marked as CANCELLED'), ] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [ @@ -131,7 +131,7 @@ def test_its_not_running(bc: Breathecode, arrange, status): call('Running mark_task_as_cancelled for 1'), ] - assert Logger.warn.call_args_list == [call('TaskManager 1 was already DONE')] + assert Logger.warning.call_args_list == [call('TaskManager 1 was already DONE')] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [bc.format.to_dict(model.task_manager)] diff --git a/breathecode/commons/tests/tasks/tests_mark_task_as_paused.py b/breathecode/commons/tests/tasks/tests_mark_task_as_paused.py index 64a397753..d1b161cfe 100644 --- a/breathecode/commons/tests/tasks/tests_mark_task_as_paused.py +++ b/breathecode/commons/tests/tasks/tests_mark_task_as_paused.py @@ -16,7 +16,7 @@ @pytest.fixture(autouse=True) def setup(db, monkeypatch): monkeypatch.setattr('logging.Logger.info', MagicMock()) - monkeypatch.setattr('logging.Logger.warn', MagicMock()) + monkeypatch.setattr('logging.Logger.warning', MagicMock()) monkeypatch.setattr('logging.Logger.error', MagicMock()) yield @@ -68,7 +68,7 @@ def _arrange(data={}): model = bc.database.create(task_manager=task_manager) Logger.info.call_args_list = [] - Logger.warn.call_args_list = [] + Logger.warning.call_args_list = [] Logger.error.call_args_list = [] return model @@ -84,7 +84,7 @@ def test_not_found(bc: Breathecode): assert res == None assert Logger.info.call_args_list == [call('Running mark_task_as_paused for 1')] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [call('TaskManager 1 not found')] assert bc.database.list_of('commons.TaskManager') == [] @@ -105,7 +105,7 @@ def test_found(bc: Breathecode, arrange): call('TaskManager 1 is being marked as PAUSED'), ] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [ @@ -131,7 +131,7 @@ def test_its_not_running(bc: Breathecode, arrange, status): call('Running mark_task_as_paused for 1'), ] - assert Logger.warn.call_args_list == [call('TaskManager 1 is not running')] + assert Logger.warning.call_args_list == [call('TaskManager 1 is not running')] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [bc.format.to_dict(model.task_manager)] diff --git a/breathecode/commons/tests/tasks/tests_mark_task_as_pending.py b/breathecode/commons/tests/tasks/tests_mark_task_as_pending.py index a79dba503..c8c522ceb 100644 --- a/breathecode/commons/tests/tasks/tests_mark_task_as_pending.py +++ b/breathecode/commons/tests/tasks/tests_mark_task_as_pending.py @@ -49,7 +49,7 @@ def setup(db, monkeypatch): monkeypatch.setattr('breathecode.commons.tasks.mark_task_as_pending.apply_async', MagicMock()) monkeypatch.setattr('breathecode.commons.tasks.TOLERANCE', TOLERANCE) monkeypatch.setattr('logging.Logger.info', MagicMock()) - monkeypatch.setattr('logging.Logger.warn', MagicMock()) + monkeypatch.setattr('logging.Logger.warning', MagicMock()) monkeypatch.setattr('logging.Logger.error', MagicMock()) yield @@ -106,7 +106,7 @@ def _arrange(data={}): model = bc.database.create(task_manager=task_manager) Logger.info.call_args_list = [] - Logger.warn.call_args_list = [] + Logger.warning.call_args_list = [] Logger.error.call_args_list = [] return model @@ -122,7 +122,7 @@ def test_not_found(bc: Breathecode): assert res == None assert Logger.info.call_args_list == [call('Running mark_task_as_pending for 1')] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [call('TaskManager 1 not found')] assert bc.database.list_of('commons.TaskManager') == [] @@ -148,7 +148,7 @@ def test_found(bc: Breathecode, arrange, task_module, task_name, get_call_args_l call('TaskManager 1 is being marked as PENDING'), ] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [bc.format.to_dict(model.task_manager)] @@ -183,7 +183,7 @@ def test_task_is_done(bc: Breathecode, arrange, task_module, task_name, get_call call('Running mark_task_as_pending for 1'), ] - assert Logger.warn.call_args_list == [call('TaskManager 1 was already DONE')] + assert Logger.warning.call_args_list == [call('TaskManager 1 was already DONE')] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [bc.format.to_dict(model.task_manager)] @@ -213,7 +213,7 @@ def test_task_is_running(bc: Breathecode, arrange, task_module, task_name, get_c call('Running mark_task_as_pending for 1'), ] - assert Logger.warn.call_args_list == [call('TaskManager 1 is already running')] + assert Logger.warning.call_args_list == [call('TaskManager 1 is already running')] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [bc.format.to_dict(model.task_manager)] @@ -242,7 +242,7 @@ def test_task_last_run_less_than_the_tolerance(bc: Breathecode, arrange, task_mo call('Running mark_task_as_pending for 1'), ] - assert Logger.warn.call_args_list == [call('TaskManager 1 was not killed, scheduling to run it again')] + assert Logger.warning.call_args_list == [call('TaskManager 1 was not killed, scheduling to run it again')] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [bc.format.to_dict(model.task_manager)] @@ -279,7 +279,7 @@ def test_task_last_run_less_than_the_tolerance__force_true(bc: Breathecode, arra call('TaskManager 1 is being marked as PENDING'), ] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [bc.format.to_dict(model.task_manager)] @@ -317,7 +317,7 @@ def test_task_last_run_less_than_the_tolerance__attempts_gt_10(bc: Breathecode, call('TaskManager 1 is being marked as PENDING'), ] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [bc.format.to_dict(model.task_manager)] @@ -353,7 +353,7 @@ def test_task_last_run_greater_than_the_tolerance(bc: Breathecode, arrange, task call('TaskManager 1 is being marked as PENDING'), ] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [bc.format.to_dict(model.task_manager)] diff --git a/breathecode/commons/tests/tasks/tests_mark_task_as_reversed.py b/breathecode/commons/tests/tasks/tests_mark_task_as_reversed.py index e2c084b92..fdf25087a 100644 --- a/breathecode/commons/tests/tasks/tests_mark_task_as_reversed.py +++ b/breathecode/commons/tests/tasks/tests_mark_task_as_reversed.py @@ -40,7 +40,7 @@ def setup(db, monkeypatch): monkeypatch.setattr('breathecode.commons.tasks.mark_task_as_reversed.apply_async', MagicMock()) monkeypatch.setattr('logging.Logger.info', MagicMock()) - monkeypatch.setattr('logging.Logger.warn', MagicMock()) + monkeypatch.setattr('logging.Logger.warning', MagicMock()) monkeypatch.setattr('logging.Logger.error', MagicMock()) monkeypatch.setattr('importlib.import_module', MagicMock()) monkeypatch.setattr('breathecode.commons.tasks.TOLERANCE', TOLERANCE) @@ -93,7 +93,7 @@ def _arrange(data={}): model = bc.database.create(task_manager=task_manager) Logger.info.call_args_list = [] - Logger.warn.call_args_list = [] + Logger.warning.call_args_list = [] Logger.error.call_args_list = [] importlib.import_module.call_args_list = [] @@ -110,7 +110,7 @@ def test_not_found(bc: Breathecode): assert res == None assert Logger.info.call_args_list == [call('Running mark_task_as_reversed for 1')] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [call('TaskManager 1 not found')] assert bc.database.list_of('commons.TaskManager') == [] @@ -138,7 +138,7 @@ def test_no_reverse_function(bc: Breathecode, arrange, task_module, task_name): call('Running mark_task_as_reversed for 1'), ] - assert Logger.warn.call_args_list == [call('TaskManager 1 does not have a reverse function')] + assert Logger.warning.call_args_list == [call('TaskManager 1 does not have a reverse function')] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [bc.format.to_dict(model.task_manager)] @@ -169,7 +169,7 @@ def test_reversed(bc: Breathecode, arrange, task_module, task_name): call('TaskManager 1 is being marked as REVERSED'), ] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [ @@ -210,7 +210,7 @@ def test_task_last_run_less_than_the_tolerance(bc: Breathecode, arrange, task_mo call('Running mark_task_as_reversed for 1'), ] - assert Logger.warn.call_args_list == [call('TaskManager 1 was not killed, scheduling to run it again')] + assert Logger.warning.call_args_list == [call('TaskManager 1 was not killed, scheduling to run it again')] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [ @@ -251,7 +251,7 @@ def test_task_last_run_less_than_the_tolerance__force_true(bc: Breathecode, arra call('TaskManager 1 is being marked as REVERSED'), ] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [ @@ -289,7 +289,7 @@ def test_task_last_run_less_than_the_tolerance__attempts_gt_10(bc: Breathecode, call('TaskManager 1 is being marked as REVERSED'), ] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [ @@ -326,7 +326,7 @@ def test_task_last_run_greater_than_the_tolerance(bc: Breathecode, arrange, task call('TaskManager 1 is being marked as REVERSED'), ] - assert Logger.warn.call_args_list == [] + assert Logger.warning.call_args_list == [] assert Logger.error.call_args_list == [] assert bc.database.list_of('commons.TaskManager') == [ diff --git a/breathecode/utils/decorators/task.py b/breathecode/utils/decorators/task.py index ab25d47e2..a12e04f8e 100644 --- a/breathecode/utils/decorators/task.py +++ b/breathecode/utils/decorators/task.py @@ -42,12 +42,20 @@ class TaskPriority(Enum): FIXER = 10 # fixes -class AbortTask(Exception): +class TaskException(Exception): + """Base class for other exceptions""" + + def __init__(self, message: str, log=True) -> None: + self.log = log + super().__init__(message) + + +class AbortTask(TaskException): """Abort task due to it doesn't meet the requirements, it will not be reattempted.""" pass -class RetryTask(Exception): +class RetryTask(TaskException): """Retry task due to it doesn't meet the requirements for a synchronization issue like a not found, it will be reattempted.""" pass @@ -208,7 +216,7 @@ def wrapper(*args, **kwargs): x.save() else: - logger.warn(str(e)) + logger.warning(str(e)) x.save() self.manage_circuit_breaker(e, x.task_module, x.task_name, x.attempts, @@ -221,12 +229,16 @@ def wrapper(*args, **kwargs): x.status_message = str(e)[:255] if x.attempts >= RETRIES_LIMIT: - logger.exception(str(e)) + if e.log: + logger.exception(str(e)) + x.status = 'ERROR' x.save() else: - logger.warn(str(e)) + if e.log: + logger.warning(str(e)) + x.save() self.reattempt(x.task_module, x.task_name, x.attempts, arguments['args'], @@ -240,7 +252,8 @@ def wrapper(*args, **kwargs): x.status_message = str(e)[:255] x.save() - logger.exception(str(e)) + if e.log: + logger.exception(str(e)) # avoid reattempts return @@ -279,7 +292,7 @@ def wrapper(*args, **kwargs): x.save() else: - logger.warn(str(e)) + logger.warning(str(e)) x.save() self.manage_circuit_breaker(e, x.task_module, x.task_name, x.attempts, @@ -292,12 +305,16 @@ def wrapper(*args, **kwargs): x.status_message = str(e)[:255] if x.attempts >= RETRIES_LIMIT: - logger.exception(str(e)) + if e.log: + logger.exception(str(e)) + x.status = 'ERROR' x.save() else: - logger.warn(str(e)) + if e.log: + logger.warning(str(e)) + x.save() self.reattempt(x.task_module, x.task_name, x.attempts, arguments['args'], @@ -311,7 +328,8 @@ def wrapper(*args, **kwargs): x.status_message = str(e)[:255] x.save() - logger.exception(str(e)) + if e.log: + logger.exception(str(e)) # avoid reattempts return diff --git a/conftest.py b/conftest.py index 41b096d07..2f37e584e 100644 --- a/conftest.py +++ b/conftest.py @@ -104,6 +104,20 @@ def wrapper(): yield wrapper +@pytest.fixture(autouse=True) +def enable_cache_logging(monkeypatch): + """ + Disable all signals by default. You can re-enable them within a test by calling the provided wrapper. + """ + + monkeypatch.setattr('breathecode.commons.actions.is_output_enable', lambda: False) + + def wrapper(*args, **kwargs): + monkeypatch.setattr('breathecode.commons.actions.is_output_enable', lambda: True) + + yield wrapper + + @pytest.fixture(autouse=True, scope='module') def random_seed(): seed = os.getenv('RANDOM_SEED') diff --git a/scripts/dyno/celeryworker.sh b/scripts/dyno/celeryworker.sh index 1f89456d2..1c33de2c4 100755 --- a/scripts/dyno/celeryworker.sh +++ b/scripts/dyno/celeryworker.sh @@ -4,7 +4,6 @@ CELERY_MIN_WORKERS=${CELERY_MIN_WORKERS:-2} CELERY_MAX_WORKERS=${CELERY_MAX_WORKERS:-2} CELERY_PREFETCH_MULTIPLIER=${CELERY_PREFETCH_MULTIPLIER:-4} CELERY_POOL=${CELERY_POOL:-prefork} -# CELERY_POOL=${CELERY_POOL:-gevent} LOG_LEVEL=${LOG_LEVEL:-INFO} export NEW_RELIC_METADATA_COMMIT=$HEROKU_SLUG_COMMIT; diff --git a/scripts/dyno/release.sh b/scripts/dyno/release.sh index 705e7b5d5..3e314f910 100755 --- a/scripts/dyno/release.sh +++ b/scripts/dyno/release.sh @@ -1,5 +1,7 @@ #!/bin/env bash +HIDE_CACHE_LOG=${HIDE_CACHE_LOG:-1} + export CORALOGIX_SUBSYSTEM=release; python manage.py migrate python manage.py create_academy_roles