From ae153aa8abfaa6b7201af2a21651cf6d829fafd9 Mon Sep 17 00:00:00 2001
From: tobitege <10787084+tobitege@users.noreply.github.com>
Date: Thu, 29 Aug 2024 16:07:38 +0200
Subject: [PATCH] (enh) review of logger.py; less logging in AgentController
 (#3648)

* revised logger.py; agent_controller: less debug logging (every second)

* agent_controller._step: removed logging upon _pending_action
---
 openhands/controller/agent_controller.py |  3 --
 openhands/core/logger.py                 | 55 ++++++++++++------------
 2 files changed, 28 insertions(+), 30 deletions(-)

diff --git a/openhands/controller/agent_controller.py b/openhands/controller/agent_controller.py
index 060f51630d..d510d651cc 100644
--- a/openhands/controller/agent_controller.py
+++ b/openhands/controller/agent_controller.py
@@ -351,9 +351,6 @@ class AgentController:
             return
 
         if self._pending_action:
-            logger.debug(
-                f'[Agent Controller {self.id}] waiting for pending action: {self._pending_action}'
-            )
             await asyncio.sleep(1)
             return
 
diff --git a/openhands/core/logger.py b/openhands/core/logger.py
index 6778e9ec86..7700da6af6 100644
--- a/openhands/core/logger.py
+++ b/openhands/core/logger.py
@@ -117,21 +117,21 @@ class SensitiveDataFilter(logging.Filter):
         return True
 
 
-def get_console_handler():
+def get_console_handler(log_level=logging.INFO):
     """Returns a console handler for logging."""
     console_handler = logging.StreamHandler()
-    console_handler.setLevel(logging.getLevelName(LOG_LEVEL))
+    console_handler.setLevel(log_level)
     console_handler.setFormatter(console_formatter)
     return console_handler
 
 
-def get_file_handler(log_dir):
+def get_file_handler(log_dir, log_level=logging.INFO):
     """Returns a file handler for logging."""
     os.makedirs(log_dir, exist_ok=True)
     timestamp = datetime.now().strftime('%Y-%m-%d')
     file_name = f'openhands_{timestamp}.log'
     file_handler = logging.FileHandler(os.path.join(log_dir, file_name))
-    file_handler.setLevel(logging.getLevelName(LOG_LEVEL))
+    file_handler.setLevel(log_level)
     file_handler.setFormatter(file_formatter)
     return file_handler
 
@@ -156,32 +156,33 @@ def log_uncaught_exceptions(ex_cls, ex, tb):
 
 
 sys.excepthook = log_uncaught_exceptions
-
 openhands_logger = logging.getLogger('openhands')
-openhands_logger.setLevel(logging.getLevelName(LOG_LEVEL))
+current_log_level = logging.INFO
+
+if LOG_LEVEL in logging.getLevelNamesMapping():
+    current_log_level = logging.getLevelNamesMapping()[LOG_LEVEL]
+openhands_logger.setLevel(current_log_level)
+
+if current_log_level == logging.DEBUG:
+    LOG_TO_FILE = True
+    openhands_logger.info('DEBUG mode enabled.')
+
+openhands_logger.addHandler(get_console_handler(current_log_level))
+openhands_logger.addFilter(SensitiveDataFilter(openhands_logger.name))
+openhands_logger.propagate = False
+openhands_logger.debug('Logging initialized')
+
 LOG_DIR = os.path.join(
     # parent dir of openhands/core (i.e., root of the repo)
     os.path.dirname(os.path.dirname(os.path.dirname(os.path.abspath(__file__)))),
     'logs',
 )
 
-if DEBUG:
-    openhands_logger.setLevel(logging.DEBUG)
-
-if LOG_TO_FILE or DEBUG:
-    # default log to project root
-    openhands_logger.debug('Logging to file is enabled. Logging to %s', LOG_DIR)
-    openhands_logger.addHandler(get_file_handler(LOG_DIR))
-
-openhands_logger.addHandler(get_console_handler())
-openhands_logger.addFilter(SensitiveDataFilter(openhands_logger.name))
-openhands_logger.propagate = False
-openhands_logger.debug('Logging initialized')
-
-if LOG_TO_FILE or DEBUG:
-    openhands_logger.info('Logging to file is enabled. Logging to %s', LOG_DIR)
-    if DEBUG:
-        openhands_logger.info('DEBUG mode enabled')
+if LOG_TO_FILE:
+    openhands_logger.addHandler(
+        get_file_handler(LOG_DIR, current_log_level)
+    )  # default log to project root
+    openhands_logger.info(f'Logging to file in: {LOG_DIR}')
 
 # Exclude LiteLLM from logging output
 logging.getLogger('LiteLLM').disabled = True
@@ -238,7 +239,7 @@ class LlmFileHandler(logging.FileHandler):
         self.message_counter += 1
 
 
-def _get_llm_file_handler(name, log_level=logging.DEBUG):
+def _get_llm_file_handler(name, log_level=logging.INFO):
     # The 'delay' parameter, when set to True, postpones the opening of the log file
     # until the first log message is emitted.
     llm_file_handler = LlmFileHandler(name, delay=True)
@@ -247,7 +248,7 @@ def _get_llm_file_handler(name, log_level=logging.DEBUG):
     return llm_file_handler
 
 
-def _setup_llm_logger(name, log_level=logging.DEBUG):
+def _setup_llm_logger(name, log_level=logging.INFO):
     logger = logging.getLogger(name)
     logger.propagate = False
     logger.setLevel(log_level)
@@ -256,5 +257,5 @@ def _setup_llm_logger(name, log_level=logging.DEBUG):
     return logger
 
 
-llm_prompt_logger = _setup_llm_logger('prompt', logging.DEBUG)
-llm_response_logger = _setup_llm_logger('response', logging.DEBUG)
+llm_prompt_logger = _setup_llm_logger('prompt', current_log_level)
+llm_response_logger = _setup_llm_logger('response', current_log_level)