Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(utils): prevent duplicate log messages (#339) #366

Merged
merged 3 commits into from
Jul 17, 2023
Merged

fix(utils): prevent duplicate log messages (#339) #366

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
9b59d6c
fix(utils): prevent duplicate log messages (#339)
nweston Jul 8, 2023
8850785
refactor(record): remove redundant configure_logging calls
nweston Jul 8, 2023
af9391e
fixup! fix(utils): prevent duplicate log messages (#339)
nweston Jul 11, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 0 additions & 7 deletions openadapt/record.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -134,7 +134,6 @@ def process_events(
terminate_event: An event to signal the termination of the process.
"""

utils.configure_logging(logger, LOG_LEVEL)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @nweston !

Can you please clarify why it was necessary to remove these calls to utils.configure_logging?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's not strictly necessary -- adding the lock is sufficient to fix the bug. But these calls appear to be redundant (utils.configure_logging is already called at module level with the same arguments), and it's possible that there could be other race conditions, e.g. if one thread is outputting log messages while another is configuring. So removing them seemed like the safest option.

But if there's a reason to keep them, we can do that and the duplicate log messages will still be fixed.

utils.set_start_time(recording_timestamp)
logger.info(f"starting")

Expand Down Expand Up @@ -278,7 +277,6 @@ def write_events(
the number of events left to be written.
"""

utils.configure_logging(logger, LOG_LEVEL)
utils.set_start_time(recording_timestamp)
logger.info(f"{event_type=} starting")
signal.signal(signal.SIGINT, signal.SIG_IGN)
Expand Down Expand Up @@ -436,7 +434,6 @@ def read_screen_events(
recording_timestamp: The timestamp of the recording.
"""

utils.configure_logging(logger, LOG_LEVEL)
utils.set_start_time(recording_timestamp)
logger.info(f"starting")
while not terminate_event.is_set():
Expand All @@ -463,7 +460,6 @@ def read_window_events(
recording_timestamp: The timestamp of the recording.
"""

utils.configure_logging(logger, LOG_LEVEL)
utils.set_start_time(recording_timestamp)
logger.info(f"starting")
prev_window_data = {}
Expand Down Expand Up @@ -513,7 +509,6 @@ def performance_stats_writer(
terminate_event: An event to signal the termination of the process.
"""

utils.configure_logging(logger, LOG_LEVEL)
utils.set_start_time(recording_timestamp)
logger.info("performance stats writer starting")
signal.signal(signal.SIGINT, signal.SIG_IGN)
Expand All @@ -535,7 +530,6 @@ def performance_stats_writer(
def memory_writer(
recording_timestamp: float, terminate_event: multiprocessing.Event, record_pid: int
):
utils.configure_logging(logger, LOG_LEVEL)
utils.set_start_time(recording_timestamp)
logger.info("Memory writer starting")
signal.signal(signal.SIGINT, signal.SIG_IGN)
Expand Down Expand Up @@ -689,7 +683,6 @@ def record(
task_description: a text description of the task that will be recorded
"""

utils.configure_logging(logger, LOG_LEVEL)
logger.info(f"{task_description=}")

recording = create_recording(task_description)
Expand Down
37 changes: 21 additions & 16 deletions openadapt/utils.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
import inspect
import os
import sys
import threading
import time

from loguru import logger
Expand All @@ -20,27 +21,31 @@

EMPTY = (None, [], {}, "")

_logger_lock = threading.Lock()


def configure_logging(logger, log_level):
# TODO: redact log messages (https://github.com/Delgan/loguru/issues/17#issuecomment-717526130)
log_level_override = os.getenv("LOG_LEVEL")
log_level = log_level_override or log_level
logger.remove()
logger_format = (
"<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
"<level>{level: <8}</level> | "
"<cyan>{name}</cyan>:<cyan>{function}</cyan>:<cyan>{line}</cyan> "
"- <level>{message}</level>"
)
logger.add(
StreamHandler(sys.stderr),
colorize=True,
level=log_level,
enqueue=True,
format=logger_format,
filter=config.filter_log_messages if config.IGNORE_WARNINGS else None,
)
logger.debug(f"{log_level=}")

with _logger_lock:
logger.remove()
logger_format = (
"<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
"<level>{level: <8}</level> | "
"<cyan>{name}</cyan>:<cyan>{function}</cyan>:<cyan>{line}</cyan> "
"- <level>{message}</level>"
)
logger.add(
StreamHandler(sys.stderr),
colorize=True,
level=log_level,
enqueue=True,
format=logger_format,
filter=config.filter_log_messages if config.IGNORE_WARNINGS else None,
)
logger.debug(f"{log_level=}")


def row2dict(row, follow=True):
Expand Down