Merge pull request #14 from finecode-dev/feature/better-logging-and-error-handling

Aksem · web-flow · commit 18acbb69c450 · 2025-09-03T13:53:50.000+02:00
Improve logs and handle more errors
diff --git a/finecode_extension_runner/pyproject.toml b/finecode_extension_runner/pyproject.toml
@@ -10,7 +10,6 @@ dependencies = [
     "tomlkit==0.11.*",
     "click==8.1.*",
     "pydantic==2.11.*",
-    "platformdirs==4.3.*",
     "pygls==2.0.0-a6",
     "finecode_extension_api==0.3.*",
     "deepmerge==2.0.*",
diff --git a/finecode_extension_runner/src/finecode_extension_runner/_services/run_action.py b/finecode_extension_runner/src/finecode_extension_runner/_services/run_action.py
@@ -15,7 +15,7 @@
 from finecode_extension_runner import (
     partial_result_sender as partial_result_sender_module,
 )
-from finecode_extension_runner import project_dirs, run_utils, schemas
+from finecode_extension_runner import run_utils, schemas
 from finecode_extension_runner.di import resolver as di_resolver
 
 last_run_id: int = 0
@@ -113,7 +113,10 @@ async def run_action(
 
     # instantiate only on demand?
     project_path = project_def.path
-    project_cache_dir = project_dirs.get_project_dir(project_path=project_path)
+    project_cache_dir = project_path / ".venvs" / global_state.env_name / "cache"
+    if not project_cache_dir.exists():
+        project_cache_dir.mkdir()
+
     action_context = code_action.ActionContext(
         project_dir=project_path, cache_dir=project_cache_dir
     )
diff --git a/finecode_extension_runner/src/finecode_extension_runner/app_dirs.py b/finecode_extension_runner/src/finecode_extension_runner/app_dirs.py
diff --git a/finecode_extension_runner/src/finecode_extension_runner/cli.py b/finecode_extension_runner/src/finecode_extension_runner/cli.py
@@ -47,6 +47,7 @@ def start(
 
     global_state.log_level = "INFO" if trace is False else "TRACE"
     global_state.project_dir_path = project_path
+    global_state.env_name = env_name
     # asyncio.run(runner_start.start_runner())
 
     # extension runner doesn't stop with async start after closing LS client(WM). Use
diff --git a/finecode_extension_runner/src/finecode_extension_runner/global_state.py b/finecode_extension_runner/src/finecode_extension_runner/global_state.py
@@ -8,3 +8,4 @@
 # the runner, not from updating the config
 project_dir_path: Path | None = None
 log_level: Literal["TRACE", "INFO"] = "INFO"
+env_name: str = ""
diff --git a/finecode_extension_runner/src/finecode_extension_runner/lsp_server.py b/finecode_extension_runner/src/finecode_extension_runner/lsp_server.py
@@ -165,12 +165,9 @@ async def get_project_raw_config(
     return json.loads(raw_config.config)
 
 
-async def update_config(ls: lsp_server.LanguageServer, params):
-    logger.trace(f"Update config: {params}")
+async def update_config(ls: lsp_server.LanguageServer, working_dir: pathlib.Path, project_name: str, config: dict[str, typing.Any]):
+    logger.trace(f'Update config: {working_dir} {project_name} {config}')
     try:
-        working_dir = params[0]
-        project_name = params[1]
-        config = params[2]
         actions = config["actions"]
         action_handler_configs = config["action_handler_configs"]
 
@@ -225,14 +222,14 @@ def default(self, obj):
         return super().default(obj)
 
 
-async def run_action(ls: lsp_server.LanguageServer, params):
-    logger.trace(f"Run action: {params[0]}")
-    request = schemas.RunActionRequest(action_name=params[0], params=params[1])
-    options = schemas.RunActionOptions(**params[2] if params[2] is not None else {})
+async def run_action(ls: lsp_server.LanguageServer, action_name: str, params: dict[str, typing.Any], options: dict[str, typing.Any] | None):
+    logger.trace(f"Run action: {action_name}")
+    request = schemas.RunActionRequest(action_name=action_name, params=params)
+    options_schema = schemas.RunActionOptions(**options if options is not None else {})
     status: str = "success"
 
     try:
-        response = await services.run_action(request=request, options=options)
+        response = await services.run_action(request=request, options=options_schema)
     except Exception as exception:
         if isinstance(exception, services.StopWithResponse):
             status = "stopped"
@@ -263,15 +260,15 @@ async def run_action(ls: lsp_server.LanguageServer, params):
     }
 
 
-async def reload_action(ls: lsp_server.LanguageServer, params):
-    logger.trace(f"Reload action: {params}")
-    services.reload_action(params[0])
+async def reload_action(ls: lsp_server.LanguageServer, action_name: str):
+    logger.trace(f"Reload action: {action_name}")
+    services.reload_action(action_name)
     return {}
 
 
-async def resolve_package_path(ls: lsp_server.LanguageServer, params):
-    logger.trace(f"Resolve package path: {params}")
+async def resolve_package_path(ls: lsp_server.LanguageServer, package_name: str):
+    logger.trace(f"Resolve package path: {package_name}")
     # TODO: handle properly ValueError
-    result = services.resolve_package_path(params[0])
-    logger.trace(f"Resolved {params[0]} to {result}")
+    result = services.resolve_package_path(package_name)
+    logger.trace(f"Resolved {package_name} to {result}")
     return {"packagePath": result}
diff --git a/finecode_extension_runner/src/finecode_extension_runner/project_dirs.py b/finecode_extension_runner/src/finecode_extension_runner/project_dirs.py
diff --git a/finecode_extension_runner/src/finecode_extension_runner/services.py b/finecode_extension_runner/src/finecode_extension_runner/services.py
@@ -16,7 +16,6 @@
     context,
     domain,
     global_state,
-    project_dirs,
     run_utils,
     schemas,
 )
diff --git a/src/finecode/cli_app/prepare_envs.py b/src/finecode/cli_app/prepare_envs.py
@@ -206,8 +206,9 @@ async def check_or_recreate_all_dev_workspace_envs(
             project_def=current_project, env_name="dev_workspace", ws_context=ws_context
         )
     except runner_manager.RunnerFailedToStart as exception:
-        # TODO
-        raise exception
+        raise PrepareEnvsFailed(
+            f"Failed to start `dev_workspace` runner in {current_project.name}: {exception.message}"
+        )
 
     envs = []
 
diff --git a/src/finecode/cli_app/run.py b/src/finecode/cli_app/run.py
@@ -339,11 +339,12 @@ async def run_actions_in_running_project(
                     ws_context=ws_context,
                     result_format=services.RunResultFormat.STRING,
                 )
+            except services.ActionRunFailed as exception:
+                raise RunFailed(f"Running of action {action_name} failed: {exception.message}")
             except Exception as error:
-                # TODO: which are expected here?
                 logger.error("Unexpected exception")
                 logger.exception(error)
-                raise RunFailed(f"Running of action {action_name} failed")
+                raise RunFailed(f"Running of action {action_name} failed with unexpected exception")
 
             run_result_str = run_result_to_str(run_result.result, action_name)
             result_by_action[action_name] = ActionRunResult(
diff --git a/src/finecode/dirs_utils.py b/src/finecode/dirs_utils.py
diff --git a/src/finecode/lsp_server/endpoints/document_sync.py b/src/finecode/lsp_server/endpoints/document_sync.py
@@ -76,7 +76,7 @@ async def document_did_close(
                 for runner in runners_by_env.values():
                     if runner.status != runner_info.RunnerStatus.RUNNING:
                         logger.trace(
-                            f"Runner {runner.working_dir_path} is not running, skip it"
+                            f"Runner {runner.readable_id} is not running, skip it"
                         )
                         continue
 
diff --git a/src/finecode/proxy_utils.py b/src/finecode/proxy_utils.py
@@ -326,7 +326,7 @@ async def start_required_environments(
                 if update_config_in_running_runners:
                     runner = existing_runners[env_name]
                     logger.trace(
-                        f"Runner {runner.working_dir_path} {runner.env_name} is running already, update config"
+                        f"Runner {runner.readable_id} is running already, update config"
                     )
 
                     try:
@@ -335,7 +335,7 @@ async def start_required_environments(
                         )
                     except RunnerFailedToStart as exception:
                         raise StartingEnvironmentsFailed(
-                            f"Failed to update config of runner {runner.working_dir_path} {runner.env_name}"
+                            f"Failed to update config of runner {runner.readable_id}"
                         )
 
 
diff --git a/src/finecode/runner/manager.py b/src/finecode/runner/manager.py
@@ -8,7 +8,7 @@
 from loguru import logger
 from lsprotocol import types
 
-from finecode import context, dirs_utils, domain, finecode_cmd
+from finecode import context, domain, finecode_cmd
 from finecode.config import collect_actions, config_models, read_configs
 from finecode.pygls_client_utils import create_lsp_client_io
 from finecode.runner import runner_client, runner_info
@@ -112,7 +112,7 @@ async def _start_extension_runner_process(
     # TODO: recognize started debugger and send command to lsp server
 
     async def on_exit():
-        logger.debug(f"Extension Runner {runner_info_instance.working_dir_path} exited")
+        logger.debug(f"Extension Runner {runner_info_instance.readable_id} exited")
         runner_info_instance.status = runner_info.RunnerStatus.EXITED
         await notify_project_changed(ws_context.ws_projects[runner_dir])  # TODO: fix
         # TODO: restart if WM is not stopping
@@ -160,7 +160,7 @@ async def get_project_raw_config(params):
 
 
 async def stop_extension_runner(runner: runner_info.ExtensionRunnerInfo) -> None:
-    logger.trace(f"Trying to stop extension runner {runner.working_dir_path}")
+    logger.trace(f"Trying to stop extension runner {runner.readable_id}")
     if not runner.client.stopped:
         logger.debug("Send shutdown to server")
         try:
@@ -173,14 +173,14 @@ async def stop_extension_runner(runner: runner_info.ExtensionRunnerInfo) -> None
         await runner.client.stop()
         logger.trace(
             f"Stop extension runner {runner.process_id}"
-            f" in {runner.working_dir_path}"
+            f" in {runner.readable_id}"
         )
     else:
         logger.trace("Extension runner was not running")
 
 
 def stop_extension_runner_sync(runner: runner_info.ExtensionRunnerInfo) -> None:
-    logger.trace(f"Trying to stop extension runner {runner.working_dir_path}")
+    logger.trace(f"Trying to stop extension runner {runner.readable_id}")
     if not runner.client.stopped:
         logger.debug("Send shutdown to server")
         try:
@@ -195,7 +195,7 @@ def stop_extension_runner_sync(runner: runner_info.ExtensionRunnerInfo) -> None:
         logger.debug("Sent exit to server")
         logger.trace(
             f"Stop extension runner {runner.process_id}"
-            f" in {runner.working_dir_path}"
+            f" in {runner.readable_id}"
         )
     else:
         logger.trace("Extension runner was not running")
@@ -372,7 +372,7 @@ async def update_runner_config(
         )
 
     logger.debug(
-        f"Updated config of runner {runner.working_dir_path},"
+        f"Updated config of runner {runner.readable_id},"
         f" process id {runner.process_id}"
     )
 
diff --git a/src/finecode/runner/runner_client.py b/src/finecode/runner/runner_client.py
@@ -41,11 +41,11 @@ class ActionRunStopped(BaseRunnerRequestException): ...
 async def log_process_log_streams(process: asyncio.subprocess.Process) -> None:
     stdout, stderr = await process.communicate()
 
-    logger.debug(f"[Runner exited with {process.returncode}]")
+    logger.info(f"[Runner exited with {process.returncode}]")
     if stdout:
-        logger.debug(f"[stdout]\n{stdout.decode()}")
+        logger.info(f"[stdout]\n{stdout.decode()}")
     if stderr:
-        logger.debug(f"[stderr]\n{stderr.decode()}")
+        logger.error(f"[stderr]\n{stderr.decode()}")
 
 
 async def send_request(
@@ -54,7 +54,7 @@ async def send_request(
     params: Any | None,
     timeout: int | None = 10,
 ) -> Any:
-    logger.debug(f"Send {method} to {runner.working_dir_path}")
+    logger.debug(f"Send {method} to {runner.readable_id}")
     try:
         response = await asyncio.wait_for(
             runner.client.protocol.send_request_async(
@@ -63,13 +63,13 @@ async def send_request(
             ),
             timeout,
         )
-        logger.debug(f"Got response on {method} from {runner.working_dir_path}")
+        logger.debug(f"Got response on {method} from {runner.readable_id}")
         return response
     except RuntimeError as error:
         logger.error(f"Extension runner crashed: {error}")
         await log_process_log_streams(process=runner.client._server)
         raise NoResponse(
-            f"Extension runner {runner.working_dir_path} crashed,"
+            f"Extension runner {runner.readable_id} crashed,"
             f" no response on {method}"
         )
     except TimeoutError:
@@ -78,13 +78,13 @@ async def send_request(
         #     await log_process_log_streams(process=runner.client._server)
         raise ResponseTimeout(
             f"Timeout {timeout}s for response on {method} to"
-            f" runner {runner.working_dir_path} in env {runner.env_name}"
+            f" runner {runner.readable_id}"
         )
     except pygls_exceptions.JsonRpcInternalError as error:
         logger.error(f"JsonRpcInternalError: {error.message} {error.data}")
         raise NoResponse(
-            f"Extension runner {runner.working_dir_path} returned no response,"
-            " check it logs"
+            f"Extension runner {runner.readable_id} returned no response,"
+            f" check it logs: {runner.logs_path}"
         )
 
 
@@ -100,12 +100,12 @@ def send_request_sync(
             params=params,
         )
         response = response_future.result(timeout)
-        logger.debug(f"Got response on {method} from {runner.working_dir_path}")
+        logger.debug(f"Got response on {method} from {runner.readable_id}")
         return response
     except RuntimeError as error:
         logger.error(f"Extension runner crashed? {error}")
         raise NoResponse(
-            f"Extension runner {runner.working_dir_path} crashed,"
+            f"Extension runner {runner.readable_id} crashed,"
             f" no response on {method}"
         )
     except TimeoutError:
@@ -116,13 +116,13 @@ def send_request_sync(
             )
         raise ResponseTimeout(
             f"Timeout {timeout}s for response on {method}"
-            f" to runner {runner.working_dir_path}"
+            f" to runner {runner.readable_id}"
         )
     except pygls_exceptions.JsonRpcInternalError as error:
         logger.error(f"JsonRpcInternalError: {error.message} {error.data}")
         raise NoResponse(
-            f"Extension runner {runner.working_dir_path} returned no response,"
-            " check it logs"
+            f"Extension runner {runner.readable_id} returned no response,"
+            f" check it logs: {runner.logs_path}"
         )
 
 
diff --git a/src/finecode/runner/runner_info.py b/src/finecode/runner/runner_info.py
@@ -81,6 +81,14 @@ def process_id(self) -> int:
             return self.client._server.pid
         else:
             return 0
+    
+    @property
+    def readable_id(self) -> str:
+        return f'{self.working_dir_path} ({self.env_name})'
+    
+    @property
+    def logs_path(self) -> Path:
+        return self.working_dir_path / '.venvs' / self.env_name / 'logs' / 'runner.log'
 
 
 class RunnerStatus(enum.Enum):
diff --git a/src/finecode/services.py b/src/finecode/services.py
@@ -158,14 +158,11 @@ async def _run_action_in_env_runner(
             options={"result_format": result_format},
         )
     except runner_client.BaseRunnerRequestException as error:
-        runner_log_path = (
-            runner.working_dir_path / ".venvs" / runner.env_name / "logs" / "runner.log"
-        )
         await user_messages.error(
-            f"Action {action_name} failed in {runner.env_name} of {runner.working_dir_path}: {error.message} . Log file: {runner_log_path}"
+            f"Action {action_name} failed in {runner.readable_id}: {error.message} . Log file: {runner.logs_path}"
         )
         raise ActionRunFailed(
-            f"Action {action_name} failed in {runner.env_name} of {runner.working_dir_path}: {error.message} . Log file: {runner_log_path}"
+            f"Action {action_name} failed in {runner.readable_id}: {error.message} . Log file: {runner.logs_path}"
         )
 
     return response

Original file line number	Diff line number	Diff line change
`@@ -16,7 +16,6 @@`
`16`	`16`	`context,`
`17`	`17`	`domain,`
`18`	`18`	`global_state,`
`19`		`- project_dirs,`
`20`	`19`	`run_utils,`
`21`	`20`	`schemas,`
`22`	`21`	`)`