(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

Author: tobitege

openhands/controller/agent_controller.py

@@ -351,9 +351,6 @@ async def _step(self) -> None:
             return
 
         if self._pending_action:
-            logger.debug(
-                f'[Agent Controller {self.id}] waiting for pending action: {self._pending_action}'
-            )
             await asyncio.sleep(1)
             return
 

openhands/core/logger.py

@@ -117,21 +117,21 @@ def filter(self, record):
         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))
-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',
-)
+current_log_level = logging.INFO
 
-if DEBUG:
-    openhands_logger.setLevel(logging.DEBUG)
+if LOG_LEVEL in logging.getLevelNamesMapping():
+    current_log_level = logging.getLevelNamesMapping()[LOG_LEVEL]
+openhands_logger.setLevel(current_log_level)
 
-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))
+if current_log_level == logging.DEBUG:
+    LOG_TO_FILE = True
+    openhands_logger.info('DEBUG mode enabled.')
 
-openhands_logger.addHandler(get_console_handler())
+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')
 
-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')
+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 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 @@ def emit(self, record):
         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)