CM-59965 add additional logging for SCA verbose mode (#392)

Author: omerr-cycode

cycode/cli/files_collector/sca/base_restore_dependencies.py

@@ -7,6 +7,9 @@
 from cycode.cli.models import Document
 from cycode.cli.utils.path_utils import get_file_content, get_file_dir, get_path_from_context, join_paths
 from cycode.cli.utils.shell_executor import shell
+from cycode.logger import get_logger
+
+logger = get_logger('SCA Restore')
 
 
 def build_dep_tree_path(path: str, generated_file_name: str) -> str:
@@ -19,6 +22,16 @@ def execute_commands(
     output_file_path: Optional[str] = None,
     working_directory: Optional[str] = None,
 ) -> Optional[str]:
+    logger.debug(
+        'Executing restore commands, %s',
+        {
+            'commands_count': len(commands),
+            'timeout_sec': timeout,
+            'working_directory': working_directory,
+            'output_file_path': output_file_path,
+        },
+    )
+
     try:
         outputs = []
 
@@ -32,7 +45,8 @@ def execute_commands(
         if output_file_path:
             with open(output_file_path, 'w', encoding='UTF-8') as output_file:
                 output_file.writelines(joined_output)
-    except Exception:
+    except Exception as e:
+        logger.debug('Unexpected error during command execution', exc_info=e)
         return None
 
     return joined_output
@@ -75,8 +89,21 @@ def try_restore_dependencies(self, document: Document) -> Optional[Document]:
             )
             if output is None:  # one of the commands failed
                 return None
+        else:
+            logger.debug(
+                'Lock file already exists, skipping restore commands, %s',
+                {'restore_file_path': restore_file_path},
+            )
 
         restore_file_content = get_file_content(restore_file_path)
+        logger.debug(
+            'Restore file loaded, %s',
+            {
+                'restore_file_path': restore_file_path,
+                'content_size': len(restore_file_content) if restore_file_content else 0,
+                'content_empty': not restore_file_content,
+            },
+        )
         return Document(relative_restore_file_path, restore_file_content, self.is_git_diff)
 
     def get_working_directory(self, document: Document) -> Optional[str]:

cycode/cli/files_collector/sca/go/restore_go_dependencies.py

@@ -4,8 +4,10 @@
 import typer
 
 from cycode.cli.files_collector.sca.base_restore_dependencies import BaseRestoreDependencies
-from cycode.cli.logger import logger
 from cycode.cli.models import Document
+from cycode.logger import get_logger
+
+logger = get_logger('Go Restore Dependencies')
 
 GO_PROJECT_FILE_EXTENSIONS = ['.mod', '.sum']
 GO_RESTORE_FILE_NAME = 'go.mod.graph'

cycode/cli/files_collector/sca/sca_file_collector.py

@@ -106,11 +106,17 @@ def _try_restore_dependencies(
 
     restore_dependencies_document = restore_dependencies.restore(document)
     if restore_dependencies_document is None:
-        logger.warning('Error occurred while trying to generate dependencies tree, %s', {'filename': document.path})
+        logger.warning(
+            'Error occurred while trying to generate dependencies tree, %s',
+            {'filename': document.path, 'handler': type(restore_dependencies).__name__},
+        )
         return None
 
     if restore_dependencies_document.content is None:
-        logger.warning('Error occurred while trying to generate dependencies tree, %s', {'filename': document.path})
+        logger.warning(
+            'Error occurred while trying to generate dependencies tree, %s',
+            {'filename': document.path, 'handler': type(restore_dependencies).__name__},
+        )
         restore_dependencies_document.content = ''
     else:
         is_monitor_action = ctx.obj.get('monitor', False)
@@ -124,6 +130,13 @@ def _try_restore_dependencies(
 
 def _get_restore_handlers(ctx: typer.Context, is_git_diff: bool) -> list[BaseRestoreDependencies]:
     build_dep_tree_timeout = int(os.getenv('CYCODE_BUILD_DEP_TREE_TIMEOUT_SECONDS', BUILD_DEP_TREE_TIMEOUT))
+    logger.debug(
+        'SCA restore handler timeout, %s',
+        {
+            'timeout_sec': build_dep_tree_timeout,
+            'source': 'env' if os.getenv('CYCODE_BUILD_DEP_TREE_TIMEOUT_SECONDS') else 'default',
+        },
+    )
     return [
         RestoreGradleDependencies(ctx, is_git_diff, build_dep_tree_timeout),
         RestoreMavenDependencies(ctx, is_git_diff, build_dep_tree_timeout),

cycode/cli/utils/shell_executor.py

@@ -1,4 +1,5 @@
 import subprocess
+import time
 from typing import Optional, Union
 
 import click
@@ -21,15 +22,27 @@ def shell(
     logger.debug('Executing shell command: %s', command)
 
     try:
+        start = time.monotonic()
         result = subprocess.run(  # noqa: S603
             command, cwd=working_directory, timeout=timeout, check=True, capture_output=True
         )
-        logger.debug('Shell command executed successfully')
+        duration_sec = round(time.monotonic() - start, 2)
+        stdout = result.stdout.decode('UTF-8').strip()
+        stderr = result.stderr.decode('UTF-8').strip()
 
-        return result.stdout.decode('UTF-8').strip()
+        logger.debug(
+            'Shell command executed successfully, %s',
+            {'duration_sec': duration_sec, 'stdout': stdout if stdout else '', 'stderr': stderr if stderr else ''},
+        )
+
+        return stdout
     except subprocess.CalledProcessError as e:
         if not silent_exc_info:
             logger.debug('Error occurred while running shell command', exc_info=e)
+            if e.stdout:
+                logger.debug('Shell command stdout: %s', e.stdout.decode('UTF-8').strip())
+            if e.stderr:
+                logger.debug('Shell command stderr: %s', e.stderr.decode('UTF-8').strip())
     except subprocess.TimeoutExpired as e:
         logger.debug('Command timed out', exc_info=e)
         raise typer.Abort(f'Command "{command}" timed out') from e