KC-1434: Mask secrets consistently in service-mode command logs

keepercommander/service/config/cli_handler.py

@@ -14,7 +14,7 @@
 import re
 from pathlib import Path
 from typing import Optional
-from ..decorators.logging import logger, debug_decorator
+from ..decorators.logging import logger, debug_decorator, sanitize_command_fields, sanitize_debug_data
 from ...params import KeeperParams
 
 class CommandHandler:
@@ -32,7 +32,7 @@ def execute_cli_command(self, params: KeeperParams, command: str) -> str:
             cli.do_command(params, command)
             return output.getvalue()
         except Exception as e:
-            logger.debug(f"Error executing CLI command '{command}': {e}")
+            logger.debug(f"Error executing CLI command '{sanitize_command_fields(command)}': {sanitize_debug_data(str(e))}")
             return ''
         finally:
             sys.stdout = sys.__stdout__

keepercommander/service/core/request_queue.py

@@ -21,7 +21,7 @@
 from dataclasses import dataclass, asdict
 
 from ..util.command_util import CommandExecutor
-from ..decorators.logging import logger, debug_decorator
+from ..decorators.logging import logger, debug_decorator, sanitize_command_fields, sanitize_debug_data
 
 
 def derive_owner_key(api_key: Optional[str]) -> Optional[str]:
@@ -150,7 +150,7 @@ def submit_request(self, command: str, temp_files: list = None,
             self.request_queue.put(request, block=False)
             with self.data_lock:
                 self.active_requests[request_id] = request
-            logger.info(f"Request {request_id} queued: {command}")
+            logger.info(f"Request {request_id} queued: {sanitize_command_fields(command)}")
             return request_id
         except queue.Full:
             logger.error("Error: Request queue is full")
@@ -304,7 +304,7 @@ def _process_queue(self):
                 self._cleanup_expired_requests()
                 continue
             except Exception as e:
-                logger.error(f"Unexpected error in queue worker: {e}")
+                logger.error(f"Unexpected error in queue worker: {sanitize_debug_data(str(e))}")
                 time.sleep(1)
 
         logger.info("Queue worker thread stopped")
@@ -321,7 +321,7 @@ def _process_request(self, request: QueuedRequest):
         request.status = RequestStatus.PROCESSING
         request.started_at = datetime.now()
 
-        logger.info(f"Processing request {request.request_id}: {request.command}")
+        logger.info(f"Processing request {request.request_id}: {sanitize_command_fields(request.command)}")
 
         try:
             # Execute the command using existing CommandExecutor
@@ -341,7 +341,7 @@ def _process_request(self, request: QueuedRequest):
             request.completed_at = datetime.now()
             request.error_message = str(e)
 
-            logger.error(f"Request {request.request_id} failed: {e}")
+            logger.error(f"Request {request.request_id} failed: {sanitize_debug_data(str(e))}")
 
         finally:
             # Clean up temporary files

keepercommander/service/decorators/api_logging.py

@@ -14,8 +14,11 @@
 from typing import Callable, Any
 from flask import request
 import time
-import re
-from .logging import logger
+from .logging import logger, sanitize_command_fields, SENSITIVE_FIELD_TYPES
+
+# Legacy generic keys (kept for JSON payloads that aren't shaped like Keeper
+# record fields, e.g. arbitrary nested config blobs).
+_SENSITIVE_DICT_KEYS = frozenset({'password', 'login', 'secret', 'token', 'key'}) | SENSITIVE_FIELD_TYPES
 
 
 class SSLHandshakeFilter(logging.Filter):
@@ -29,32 +32,44 @@ def filter(self, record):
         return True
 
 def sanitize_password_in_command(data):
-    """Sanitize password values in command string and filedata"""
+    """Sanitize password, login, secret and TOTP (oneTimeCode) values in command string and filedata"""
     if not data:
         return data
-    
+
     sanitized = data.copy()
-    
+
     # Sanitize command string if present
-    if 'command' in sanitized:
-        command = sanitized['command']
-        # Pattern to match password=value (with or without quotes)
-        password_pattern = r"password=(['\"]?)([^'\"\s]{1,1024})\1"
-        sanitized['command'] = re.sub(password_pattern, r"password=\1***\1", command)
-
+    if 'command' in sanitized and isinstance(sanitized['command'], str):
+        sanitized['command'] = sanitize_command_fields(sanitized['command'])
+
     # Sanitize filedata if present
     if 'filedata' in sanitized:
         sanitized['filedata'] = _sanitize_nested_data(sanitized['filedata'])
 
     return sanitized
 
+def _mask_field_value(value):
+    """Mask a Keeper record field's `value`, preserving its container shape."""
+    if isinstance(value, list):
+        return ['***' for _ in value]
+    if isinstance(value, dict):
+        return {k: '***' for k in value}
+    return '***'
+
+
 def _sanitize_nested_data(data):
     """Recursively sanitize nested data structures"""
     if isinstance(data, dict):
+        field_type = data.get('type')
+        if isinstance(field_type, str) and field_type.lower() in SENSITIVE_FIELD_TYPES and 'value' in data:
+            sanitized = dict(data)
+            sanitized['value'] = _mask_field_value(data['value'])
+            return sanitized
+
         sanitized = {}
         for key, value in data.items():
             # Sanitize sensitive field names
-            if key.lower() in ['password', 'login', 'secret', 'token', 'key']:
+            if key.lower() in _SENSITIVE_DICT_KEYS:
                 if isinstance(value, str) and len(value) > 0:
                     sanitized[key] = '*' * min(len(value), 15)
                 else:

keepercommander/service/decorators/logging.py

@@ -14,9 +14,18 @@
 import logging
 import sys, os, yaml
 import re
+import shlex
 from enum import Enum
 from ... import utils
 
+# Values that must never reach the logs when set via record-add/record-update/
+# nsf-record-* CLI args.
+SENSITIVE_FIELD_TYPES = frozenset({
+    'password', 'login', 'secret', 'onetimecode', 'pincode', 'keypair',
+    'privatekey', 'passphrase', 'paymentcard', 'bankaccount',
+    'securityquestion', 'passkey',
+})
+
 class LogLevel(Enum):
     ERROR = logging.ERROR
     WARNING = logging.WARNING
@@ -112,15 +121,15 @@ def debug_decorator(fn: Callable) -> Callable:
     @wraps(fn)
     def wrapper(*args: Any, **kwargs: Any) -> Any:
         if logger._logger.isEnabledFor(logging.DEBUG):
-            args_repr = [repr(a) for a in args]
-            kwargs_repr = [f"{k}={v!r}" for k, v in kwargs.items()]
+            args_repr = [sanitize_debug_data(repr(a)) for a in args]
+            kwargs_repr = [f"{k}={sanitize_debug_data(repr(v))}" for k, v in kwargs.items()]
             signature = ", ".join(args_repr + kwargs_repr)
             logger.debug(f"Call: {fn.__name__}({signature})")
-        
+
         value = fn(*args, **kwargs)
-        
+
         if logger._logger.isEnabledFor(logging.INFO):
-            logger.debug(f"Return: {fn.__name__} → {value!r}")
+            logger.debug(f"Return: {fn.__name__} → {sanitize_debug_data(repr(value))}")
 
         return value
     return wrapper
@@ -151,16 +160,71 @@ def sanitize_debug_data(data: str) -> str:
         (r'"secret"\s*:\s*"[^"]*"', '"secret": "***"'),
         (r'"token"\s*:\s*"[^"]*"', '"token": "***"'),
         (r'"key"\s*:\s*"[^"]*"', '"key": "***"'),
-        (r'password=[^\s]*', 'password=***'),
-        (r'login=[^\s]*', 'login=***'),
+        (r'\bpassword=[^\s]*', 'password=***'),
+        (r'\blogin=[^\s]*', 'login=***'),
+        # oneTimeCode=otpauth://totp/...?secret=... — mask the whole value, TOTP seed included
+        (r'\boneTimeCode=[^\s]*', 'oneTimeCode=***'),
+        (r'\bsecret=[^\s]*', 'secret=***'),
+        # Other sensitive record field types (see SENSITIVE_FIELD_TYPES) that can
+        # appear as bare CLI args on record-add/record-update/nsf-* commands.
+        (r'\bpinCode=[^\s]*', 'pinCode=***'),
+        (r'\bkeyPair=[^\s]*', 'keyPair=***'),
+        (r'\bprivateKey=[^\s]*', 'privateKey=***'),
+        (r'\bpassphrase=[^\s]*', 'passphrase=***'),
+        (r'\bpaymentCard=[^\s]*', 'paymentCard=***'),
+        (r'\bbankAccount=[^\s]*', 'bankAccount=***'),
+        (r'\bsecurityQuestion=[^\s]*', 'securityQuestion=***'),
+        (r'\bpasskey=[^\s]*', 'passkey=***'),
         # Sanitize email addresses in logs to protect PII
         (r'\b[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Z|a-z]{2,}\b', '***@***.***'),
     ]
 
     for pattern, replacement in patterns:
         sanitized = re.sub(pattern, replacement, sanitized, flags=re.IGNORECASE)
-    
+
     return sanitized
 
 
+def _record_field_type(token_key: str) -> str:
+    """Extract the FIELD_TYPE from a record-add/record-update field token key.
+
+    Field tokens follow [f.|c.]<FIELD_TYPE>[.<FIELD_LABEL>]=<VALUE> (see the
+    `record-add`/`record-update` --syntax-help). Custom fields carrying a
+    sensitive type (e.g. c.secret.APIKey=...) must be masked the same as bare
+    fields (secret=...).
+    """
+    key = token_key[2:] if token_key[:2] in ('f.', 'c.') else token_key
+    return key.split('.', 1)[0]
+
+
+def sanitize_command_fields(command: str) -> str:
+    """Mask sensitive record field values (password, secret, keyPair, private
+    key passphrases, payment/bank data, security answers, ...) in a
+    record-add/record-update/nsf-record-* command string.
+
+    Unlike the plain keyword patterns in `sanitize_debug_data`, this masks
+    labeled and custom fields too (password.Label=..., c.secret.APIKey=...),
+    which a literal `password=` substring match cannot catch.
+    """
+    if not command:
+        return command
+
+    try:
+        tokens = shlex.split(command, posix=True)
+    except ValueError:
+        # Unbalanced quotes: fall back to whitespace split so we still mask
+        # what we can instead of logging the raw string.
+        tokens = command.split()
+
+    masked_tokens = []
+    for token in tokens:
+        key, sep, value = token.partition('=')
+        if sep and value and _record_field_type(key).lower() in SENSITIVE_FIELD_TYPES:
+            masked_tokens.append(f'{key}=***')
+        else:
+            masked_tokens.append(token)
+
+    return sanitize_debug_data(' '.join(masked_tokens))
+
+
 logger = GlobalLogger()

keepercommander/service/util/command_util.py

@@ -27,7 +27,7 @@
 )
 from .verified_command import Verifycommand
 from ..core.globals import get_current_params
-from ..decorators.logging import logger, debug_decorator, sanitize_debug_data
+from ..decorators.logging import logger, debug_decorator, sanitize_debug_data, sanitize_command_fields
 from ... import cli, utils
 from ...crypto import encrypt_aes_v2
 from ...error import KeeperApiError
@@ -149,7 +149,7 @@ def _finalize_parsed_response(cls, response: Any) -> Tuple[Any, int]:
 
     @classmethod
     def execute(cls, command: str) -> Tuple[Any, int]:
-        logger.debug(f"Executing command: {command}")
+        logger.debug(f"Executing command: {sanitize_command_fields(command)}")
 
         validation_error = cls.validate_command(command)
         if validation_error:
@@ -209,7 +209,7 @@ def execute(cls, command: str) -> Tuple[Any, int]:
                 try:
                     SailPointService.after_command(params, command, success=True)
                 except Exception as e:
-                    logger.error(f'SailPoint post-process failed: {e}')
+                    logger.error(f'SailPoint post-process failed: {sanitize_debug_data(str(e))}')
                     err = {
                         'status': 'error',
                         'error': (
@@ -224,18 +224,18 @@ def execute(cls, command: str) -> Tuple[Any, int]:
             return response, status_code
         except CommandExecutionError as e:
             # Return the actual command error instead of generic "server busy"
-            logger.error(f"Command execution error: {e}")
+            logger.error(f"Command execution error: {sanitize_debug_data(str(e))}")
             if is_throttle_error(e):
                 return throttle_error_response(str(e))
             return {"status": "error", "error": str(e)}, 400
         except KeeperApiError as e:
             if is_throttle_error(e):
                 return throttle_error_response(e.message or str(e), e.result_code)
-            logger.error(f"Unexpected error during command execution: {e}")
+            logger.error(f"Unexpected error during command execution: {sanitize_debug_data(str(e))}")
             return {"status": "error", "error": f"Unexpected error: {str(e)}"}, 500
         except Exception as e:
             if is_throttle_error(e):
                 return throttle_error_response(str(e))
             # Log unexpected errors and return a proper error response
-            logger.error(f"Unexpected error during command execution: {e}")
+            logger.error(f"Unexpected error during command execution: {sanitize_debug_data(str(e))}")
             return {"status": "error", "error": f"Unexpected error: {str(e)}"}, 500

keepercommander/service/util/request_validation.py

@@ -15,7 +15,7 @@
 import tempfile
 import os
 import json
-from ..decorators.logging import logger
+from ..decorators.logging import logger, sanitize_command_fields
 
 
 class RequestValidator:
@@ -46,7 +46,7 @@ def validate_and_escape_command(request_data: Dict[str, Any]) -> Tuple[Optional[
 
         # Escape HTML to prevent XSS
         escaped_command = escape(command)
-        logger.debug(f"Command validated and escaped: {escaped_command}")
+        logger.debug(f"Command validated and escaped: {sanitize_command_fields(escaped_command)}")
         return escaped_command, None
 
     @staticmethod