From 4da812c78175e87eebc780dab16feb4e54dd056f Mon Sep 17 00:00:00 2001 From: Robert Brennan Date: Tue, 14 Jan 2025 10:22:39 -0500 Subject: [PATCH] Better handling of stack traces and exc_info (#6253) --- openhands/core/config/utils.py | 3 --- openhands/core/logger.py | 11 ++++++++++ openhands/events/stream.py | 2 -- openhands/llm/retry_mixin.py | 1 - openhands/memory/condenser.py | 2 +- openhands/runtime/action_execution_server.py | 6 ++--- openhands/runtime/base.py | 6 +---- openhands/runtime/browser/browser_env.py | 4 ++-- openhands/server/routes/conversation.py | 4 ++-- openhands/server/routes/files.py | 22 +++++++++---------- .../server/routes/manage_conversations.py | 8 +++---- openhands/server/routes/public.py | 2 +- openhands/server/session/agent_session.py | 2 +- openhands/server/session/manager.py | 10 ++++----- openhands/server/session/session.py | 4 ++-- .../conversation/file_conversation_store.py | 4 +--- 16 files changed, 41 insertions(+), 50 deletions(-) diff --git a/openhands/core/config/utils.py b/openhands/core/config/utils.py index 7719ce0d59b1..32e78b9f7631 100644 --- a/openhands/core/config/utils.py +++ b/openhands/core/config/utils.py @@ -109,7 +109,6 @@ def load_from_toml(cfg: AppConfig, toml_file: str = 'config.toml'): except toml.TomlDecodeError as e: logger.openhands_logger.warning( f'Cannot parse config from toml, toml values have not been applied.\nError: {e}', - exc_info=False, ) return @@ -167,7 +166,6 @@ def load_from_toml(cfg: AppConfig, toml_file: str = 'config.toml'): except (TypeError, KeyError) as e: logger.openhands_logger.warning( f'Cannot parse [{key}] config from toml, values have not been applied.\nError: {e}', - exc_info=False, ) else: logger.openhands_logger.warning(f'Unknown section [{key}] in {toml_file}') @@ -204,7 +202,6 @@ def load_from_toml(cfg: AppConfig, toml_file: str = 'config.toml'): except (TypeError, KeyError) as e: logger.openhands_logger.warning( f'Cannot parse [sandbox] config from toml, values have not been applied.\nError: {e}', - exc_info=False, ) diff --git a/openhands/core/logger.py b/openhands/core/logger.py index e74a2b9decb9..d6bd0ffd9253 100644 --- a/openhands/core/logger.py +++ b/openhands/core/logger.py @@ -52,6 +52,14 @@ } +class StackInfoFilter(logging.Filter): + def filter(self, record): + if record.levelno >= logging.ERROR: + record.stack_info = True + record.exc_info = True + return True + + class NoColorFormatter(logging.Formatter): """Formatter for non-colored logging in files.""" @@ -260,6 +268,9 @@ def log_uncaught_exceptions( current_log_level = logging.getLevelNamesMapping()[LOG_LEVEL] openhands_logger.setLevel(current_log_level) +if DEBUG: + openhands_logger.addFilter(StackInfoFilter()) + if current_log_level == logging.DEBUG: LOG_TO_FILE = True openhands_logger.debug('DEBUG mode enabled.') diff --git a/openhands/events/stream.py b/openhands/events/stream.py index e58f90e79d9c..f6177c7081e4 100644 --- a/openhands/events/stream.py +++ b/openhands/events/stream.py @@ -301,8 +301,6 @@ def _handle_callback_error(fut): except Exception as e: logger.error( f'Error in event callback {callback_id} for subscriber {subscriber_id}: {str(e)}', - exc_info=True, - stack_info=True, ) # Re-raise in the main thread so the error is not swallowed raise e diff --git a/openhands/llm/retry_mixin.py b/openhands/llm/retry_mixin.py index 1005677320e1..2942c913a268 100644 --- a/openhands/llm/retry_mixin.py +++ b/openhands/llm/retry_mixin.py @@ -46,5 +46,4 @@ def log_retry_attempt(self, retry_state): exception = retry_state.outcome.exception() logger.error( f'{exception}. Attempt #{retry_state.attempt_number} | You can customize retry values in the configuration.', - exc_info=False, ) diff --git a/openhands/memory/condenser.py b/openhands/memory/condenser.py index 6318025171d0..ac937eda079b 100644 --- a/openhands/memory/condenser.py +++ b/openhands/memory/condenser.py @@ -268,7 +268,7 @@ def condense(self, events: list[Event]) -> list[Event]: return [summary_event] except Exception as e: - logger.error('Error condensing events: %s', str(e), exc_info=False) + logger.error(f'Error condensing events: {str(e)}') raise e diff --git a/openhands/runtime/action_execution_server.py b/openhands/runtime/action_execution_server.py index 63d2d1cbdf3e..b483c183cbdc 100644 --- a/openhands/runtime/action_execution_server.py +++ b/openhands/runtime/action_execution_server.py @@ -522,9 +522,7 @@ async def execute_action(action_request: ActionRequest): observation = await client.run_action(action) return event_to_dict(observation) except Exception as e: - logger.error( - f'Error processing command: {str(e)}', exc_info=True, stack_info=True - ) + logger.error(f'Error while running /execute_action: {str(e)}') raise HTTPException( status_code=500, detail=traceback.format_exc(), @@ -716,7 +714,7 @@ async def list_files(request: Request): return sorted_entries except Exception as e: - logger.error(f'Error listing files: {e}', exc_info=True) + logger.error(f'Error listing files: {e}') return [] logger.debug(f'Starting action execution API on port {args.port}') diff --git a/openhands/runtime/base.py b/openhands/runtime/base.py index 79f501c83d68..27643ac3bc8d 100644 --- a/openhands/runtime/base.py +++ b/openhands/runtime/base.py @@ -193,11 +193,7 @@ async def _handle_action(self, event: Action) -> None: e, AgentRuntimeDisconnectedError ): err_id = 'STATUS$ERROR_RUNTIME_DISCONNECTED' - logger.error( - 'Unexpected error while running action', - exc_info=True, - stack_info=True, - ) + self.log('error', f'Unexpected error while running action: {str(e)}') self.log('error', f'Problematic action: {str(event)}') self.send_error_message(err_id, str(e)) self.close() diff --git a/openhands/runtime/browser/browser_env.py b/openhands/runtime/browser/browser_env.py index d9a7fd752956..e7752a701236 100644 --- a/openhands/runtime/browser/browser_env.py +++ b/openhands/runtime/browser/browser_env.py @@ -195,8 +195,8 @@ def close(self): self.process.join(5) # Wait for the process to terminate self.agent_side.close() self.browser_side.close() - except Exception: - logger.error('Encountered an error when closing browser env', exc_info=True) + except Exception as e: + logger.error(f'Encountered an error when closing browser env: {e}') @staticmethod def image_to_png_base64_url( diff --git a/openhands/server/routes/conversation.py b/openhands/server/routes/conversation.py index 80d0f8516146..1fcda4763518 100644 --- a/openhands/server/routes/conversation.py +++ b/openhands/server/routes/conversation.py @@ -42,7 +42,7 @@ async def get_vscode_url(request: Request): logger.debug(f'Runtime VSCode URL: {runtime.vscode_url}') return JSONResponse(status_code=200, content={'vscode_url': runtime.vscode_url}) except Exception as e: - logger.error(f'Error getting VSCode URL: {e}', exc_info=True) + logger.error(f'Error getting VSCode URL: {e}') return JSONResponse( status_code=500, content={ @@ -81,7 +81,7 @@ async def get_hosts(request: Request): logger.debug(f'Runtime hosts: {runtime.web_hosts}') return JSONResponse(status_code=200, content={'hosts': runtime.web_hosts}) except Exception as e: - logger.error(f'Error getting runtime hosts: {e}', exc_info=True) + logger.error(f'Error getting runtime hosts: {e}') return JSONResponse( status_code=500, content={ diff --git a/openhands/server/routes/files.py b/openhands/server/routes/files.py index 2efb85ceaddd..1581d3abaddb 100644 --- a/openhands/server/routes/files.py +++ b/openhands/server/routes/files.py @@ -68,7 +68,7 @@ async def list_files(request: Request, conversation_id: str, path: str | None = try: file_list = await call_sync_from_async(runtime.list_files, path) except AgentRuntimeUnavailableError as e: - logger.error(f'Error listing files: {e}', exc_info=True) + logger.error(f'Error listing files: {e}') return JSONResponse( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, content={'error': f'Error listing files: {e}'}, @@ -95,7 +95,7 @@ async def filter_for_gitignore(file_list, base_path): try: file_list = await filter_for_gitignore(file_list, '') except AgentRuntimeUnavailableError as e: - logger.error(f'Error filtering files: {e}', exc_info=True) + logger.error(f'Error filtering files: {e}') return JSONResponse( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, content={'error': f'Error filtering files: {e}'}, @@ -131,7 +131,7 @@ async def select_file(file: str, request: Request): try: observation = await call_sync_from_async(runtime.run_action, read_action) except AgentRuntimeUnavailableError as e: - logger.error(f'Error opening file {file}: {e}', exc_info=True) + logger.error(f'Error opening file {file}: {e}') return JSONResponse( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, content={'error': f'Error opening file: {e}'}, @@ -141,7 +141,7 @@ async def select_file(file: str, request: Request): content = observation.content return {'code': content} elif isinstance(observation, ErrorObservation): - logger.error(f'Error opening file {file}: {observation}', exc_info=False) + logger.error(f'Error opening file {file}: {observation}') return JSONResponse( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, content={'error': f'Error opening file: {observation}'}, @@ -207,9 +207,7 @@ async def upload_file(request: Request, conversation_id: str, files: list[Upload runtime.config.workspace_mount_path_in_sandbox, ) except AgentRuntimeUnavailableError as e: - logger.error( - f'Error saving file {safe_filename}: {e}', exc_info=True - ) + logger.error(f'Error saving file {safe_filename}: {e}') return JSONResponse( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, content={'error': f'Error saving file: {e}'}, @@ -234,7 +232,7 @@ async def upload_file(request: Request, conversation_id: str, files: list[Upload return JSONResponse(status_code=status.HTTP_200_OK, content=response_content) except Exception as e: - logger.error(f'Error during file upload: {e}', exc_info=True) + logger.error(f'Error during file upload: {e}') return JSONResponse( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, content={ @@ -284,7 +282,7 @@ async def save_file(request: Request): try: observation = await call_sync_from_async(runtime.run_action, write_action) except AgentRuntimeUnavailableError as e: - logger.error(f'Error saving file: {e}', exc_info=True) + logger.error(f'Error saving file: {e}') return JSONResponse( status_code=500, content={'error': f'Error saving file: {e}'}, @@ -306,7 +304,7 @@ async def save_file(request: Request): ) except Exception as e: # Log the error and return a 500 response - logger.error(f'Error saving file: {e}', exc_info=True) + logger.error(f'Error saving file: {e}') raise HTTPException(status_code=500, detail=f'Error saving file: {e}') @@ -321,7 +319,7 @@ async def zip_current_workspace( try: zip_file = await call_sync_from_async(runtime.copy_from, path) except AgentRuntimeUnavailableError as e: - logger.error(f'Error zipping workspace: {e}', exc_info=True) + logger.error(f'Error zipping workspace: {e}') return JSONResponse( status_code=500, content={'error': f'Error zipping workspace: {e}'}, @@ -337,7 +335,7 @@ async def zip_current_workspace( return response except Exception as e: - logger.error(f'Error zipping workspace: {e}', exc_info=True) + logger.error(f'Error zipping workspace: {e}') raise HTTPException( status_code=500, detail='Failed to zip workspace', diff --git a/openhands/server/routes/manage_conversations.py b/openhands/server/routes/manage_conversations.py index c1f3d75e3faa..61fedd8a4f4e 100644 --- a/openhands/server/routes/manage_conversations.py +++ b/openhands/server/routes/manage_conversations.py @@ -214,11 +214,9 @@ async def _get_conversation_info( if is_running else ConversationStatus.STOPPED, ) - except Exception: # type: ignore - logger.warning( - f'Error loading conversation: {conversation.conversation_id[:5]}', - exc_info=True, - stack_info=True, + except Exception as e: + logger.error( + f'Error loading conversation {conversation.conversation_id}: {str(e)}', ) return None diff --git a/openhands/server/routes/public.py b/openhands/server/routes/public.py index 5a8925b741b4..a057bebb3692 100644 --- a/openhands/server/routes/public.py +++ b/openhands/server/routes/public.py @@ -70,7 +70,7 @@ async def get_litellm_models() -> list[str]: model_list.append('ollama/' + model['name']) break except requests.exceptions.RequestException as e: - logger.error(f'Error getting OLLAMA models: {e}', exc_info=True) + logger.error(f'Error getting OLLAMA models: {e}') return list(sorted(set(model_list))) diff --git a/openhands/server/session/agent_session.py b/openhands/server/session/agent_session.py index 0bb0d2387e5e..0e7bf554a814 100644 --- a/openhands/server/session/agent_session.py +++ b/openhands/server/session/agent_session.py @@ -205,7 +205,7 @@ async def _create_runtime( try: await self.runtime.connect() except AgentRuntimeUnavailableError as e: - logger.error(f'Runtime initialization failed: {e}', exc_info=True) + logger.error(f'Runtime initialization failed: {e}') if self._status_callback: self._status_callback( 'error', 'STATUS$ERROR_RUNTIME_DISCONNECTED', str(e) diff --git a/openhands/server/session/manager.py b/openhands/server/session/manager.py index 45b75805e412..250a7a4cc90b 100644 --- a/openhands/server/session/manager.py +++ b/openhands/server/session/manager.py @@ -92,12 +92,10 @@ async def _redis_subscribe(self): await self._process_message(message) except asyncio.CancelledError: return - except Exception: + except Exception as e: try: asyncio.get_running_loop() - logger.warning( - 'error_reading_from_redis', exc_info=True, stack_info=True - ) + logger.error(f'error_reading_from_redis:{str(e)}') except RuntimeError: return # Loop has been shut down @@ -259,8 +257,8 @@ async def _cleanup_detached_conversations(self): await conversation.disconnect() self._detached_conversations.clear() return - except Exception: - logger.warning('error_cleaning_detached_conversations', exc_info=True) + except Exception as e: + logger.warning(f'error_cleaning_detached_conversations: {str(e)}') await asyncio.sleep(_CLEANUP_EXCEPTION_WAIT_TIME) async def get_agent_loop_running(self, user_id, sids: set[str]) -> set[str]: diff --git a/openhands/server/session/session.py b/openhands/server/session/session.py index b8aff5a76009..2767c05149c7 100644 --- a/openhands/server/session/session.py +++ b/openhands/server/session/session.py @@ -187,8 +187,8 @@ async def _send(self, data: dict[str, object]) -> bool: await asyncio.sleep(0.001) # This flushes the data to the client self.last_active_ts = int(time.time()) return True - except RuntimeError: - logger.error('Error sending', stack_info=True, exc_info=True) + except RuntimeError as e: + logger.error(f'Error sending data to websocket: {str(e)}') self.is_alive = False return False diff --git a/openhands/storage/conversation/file_conversation_store.py b/openhands/storage/conversation/file_conversation_store.py index c51ab3219db3..858315b632a8 100644 --- a/openhands/storage/conversation/file_conversation_store.py +++ b/openhands/storage/conversation/file_conversation_store.py @@ -76,10 +76,8 @@ async def search( try: conversations.append(await self.get_metadata(conversation_id)) except Exception: - logger.warning( + logger.error( f'Error loading conversation: {conversation_id}', - exc_info=True, - stack_info=True, ) conversations.sort(key=_sort_key, reverse=True) conversations = conversations[start:end]