From 44030e38944a3520868cdf31952d7c6c0b542008 Mon Sep 17 00:00:00 2001 From: Tobias Wochinger Date: Thu, 4 Mar 2021 10:49:38 +0100 Subject: [PATCH 1/2] improve log message --- changelog/8100.improvement.md | 2 ++ rasa/core/lock_store.py | 9 +++++++-- tests/core/test_lock_store.py | 37 +++++++++++++++++++++++++++++++++++ 3 files changed, 46 insertions(+), 2 deletions(-) create mode 100644 changelog/8100.improvement.md diff --git a/changelog/8100.improvement.md b/changelog/8100.improvement.md new file mode 100644 index 000000000000..b8e6dc0319df --- /dev/null +++ b/changelog/8100.improvement.md @@ -0,0 +1,2 @@ +Improved the [lock store](lock-stores.mdx) debug log message when the process has to +queue because other messages have to be processed before this item. diff --git a/rasa/core/lock_store.py b/rasa/core/lock_store.py index 9a88a1214e42..9d002a40a254 100644 --- a/rasa/core/lock_store.py +++ b/rasa/core/lock_store.py @@ -123,9 +123,14 @@ async def _acquire_lock( logger.debug(f"Acquired lock for conversation '{conversation_id}'.") return lock + items_before_this = ticket - (lock.now_serving or 0) + title = "items" if items_before_this > 1 else "item" + logger.debug( - f"Failed to acquire lock for conversation ID '{conversation_id}'. " - f"Retrying..." + f"Failed to acquire lock for conversation ID '{conversation_id}' " + f"because {items_before_this} other {title} for this " + f"conversation ID have to be finished processing first. " + f"Retrying in {wait_time_in_seconds} seconds ..." ) # sleep and update lock diff --git a/tests/core/test_lock_store.py b/tests/core/test_lock_store.py index 96f330c9f58d..f0e8226f2cca 100644 --- a/tests/core/test_lock_store.py +++ b/tests/core/test_lock_store.py @@ -1,4 +1,5 @@ import asyncio +import logging import os import sys from pathlib import Path @@ -7,6 +8,7 @@ import pytest import time +from _pytest.logging import LogCaptureFixture from _pytest.monkeypatch import MonkeyPatch from _pytest.tmpdir import TempdirFactory from unittest.mock import patch, Mock @@ -282,6 +284,41 @@ async def test_lock_lifetime_environment_variable(monkeypatch: MonkeyPatch): assert rasa.core.lock_store._get_lock_lifetime() == new_lock_lifetime +@pytest.mark.parametrize("lock_store", [InMemoryLockStore(), FakeRedisLockStore()]) +async def test_acquire_lock_debug_message( + lock_store: LockStore, caplog: LogCaptureFixture +): + conversation_id = "test_acquire_lock_debug_message" + wait_time_in_seconds = 0.01 + + async def locking_task() -> None: + async with lock_store.lock( + conversation_id, wait_time_in_seconds=wait_time_in_seconds + ): + # Do a very short sleep so that the other tasks can try to acquire the lock + # in the meantime + await asyncio.sleep(0.0) + + with caplog.at_level(logging.DEBUG): + await asyncio.gather( + locking_task(), # Gets served immediately + locking_task(), # Gets served second + locking_task(), # Gets served last + ) + + assert any( + f"because 1 other item for this conversation ID have to be finished processing " + f"first. Retrying in {wait_time_in_seconds} seconds ..." in message + for message in caplog.messages + ) + + assert any( + f"because 2 other items for this conversation ID have to be finished processing " + f"first. Retrying in {wait_time_in_seconds} seconds ..." in message + for message in caplog.messages + ) + + async def test_redis_lock_store_timeout(monkeypatch: MonkeyPatch): import redis.exceptions From c0d18e5cc208bf21398c5dcb898f87c770ccf582 Mon Sep 17 00:00:00 2001 From: Tobias Wochinger Date: Wed, 10 Mar 2021 09:30:49 +0100 Subject: [PATCH 2/2] remove length check --- rasa/core/lock_store.py | 3 +-- tests/core/test_lock_store.py | 8 ++++---- 2 files changed, 5 insertions(+), 6 deletions(-) diff --git a/rasa/core/lock_store.py b/rasa/core/lock_store.py index 9d002a40a254..107eadd43519 100644 --- a/rasa/core/lock_store.py +++ b/rasa/core/lock_store.py @@ -124,11 +124,10 @@ async def _acquire_lock( return lock items_before_this = ticket - (lock.now_serving or 0) - title = "items" if items_before_this > 1 else "item" logger.debug( f"Failed to acquire lock for conversation ID '{conversation_id}' " - f"because {items_before_this} other {title} for this " + f"because {items_before_this} other item(s) for this " f"conversation ID have to be finished processing first. " f"Retrying in {wait_time_in_seconds} seconds ..." ) diff --git a/tests/core/test_lock_store.py b/tests/core/test_lock_store.py index f0e8226f2cca..77c12f236e65 100644 --- a/tests/core/test_lock_store.py +++ b/tests/core/test_lock_store.py @@ -307,14 +307,14 @@ async def locking_task() -> None: ) assert any( - f"because 1 other item for this conversation ID have to be finished processing " - f"first. Retrying in {wait_time_in_seconds} seconds ..." in message + f"because 1 other item(s) for this conversation ID have to be finished " + f"processing first. Retrying in {wait_time_in_seconds} seconds ..." in message for message in caplog.messages ) assert any( - f"because 2 other items for this conversation ID have to be finished processing " - f"first. Retrying in {wait_time_in_seconds} seconds ..." in message + f"because 2 other item(s) for this conversation ID have to be finished " + f"processing first. Retrying in {wait_time_in_seconds} seconds ..." in message for message in caplog.messages )