diff --git a/keepercommander/commands/pam_launch/launch.py b/keepercommander/commands/pam_launch/launch.py index c77bf3112..ff4d0eabc 100644 --- a/keepercommander/commands/pam_launch/launch.py +++ b/keepercommander/commands/pam_launch/launch.py @@ -42,6 +42,10 @@ unregister_tunnel_session, unregister_conversation_key, ) +from .rust_log_filter import ( + enter_pam_launch_terminal_rust_logging, + exit_pam_launch_terminal_rust_logging, +) from ..pam.gateway_helper import get_all_gateways from ..pam.router_helper import router_get_connected_gateways from ... import api, vault @@ -749,7 +753,9 @@ def signal_handler_fn(signum, frame): original_handler = signal.signal(signal.SIGINT, signal_handler_fn) + rust_log_token = None try: + rust_log_token = enter_pam_launch_terminal_rust_logging() tube_id = tunnel_result['tunnel'].get('tube_id') if not tube_id: raise CommandError('pam launch', 'No tube ID in tunnel result') @@ -834,10 +840,18 @@ def signal_handler_fn(signum, frame): connect_as_supported = _version_at_least(remote_webrtc_version, CONNECT_AS_MIN_VERSION) if cli_user_override and effective_credential_uid and gateway_uid: + # When using userRecords[0] fallback, include explanation in CommandError if ConnectAs fails + connect_as_fallback_msg = '' + if launch_credential_uid is None: + connect_as_fallback_msg = ( + f'Using credential from userRecords[0] ({effective_credential_uid}) as ConnectAs fallback because ' + 'no launch credential on record; ConnectAs is enabled but no --credential was given. ' + ) if not connect_as_supported: raise CommandError( 'pam launch', - f'ConnectAs (--credential) requires Gateway with keeper-pam-webrtc-rs >= {CONNECT_AS_MIN_VERSION}. ' + connect_as_fallback_msg + + f'ConnectAs (--credential) requires Gateway with keeper-pam-webrtc-rs >= {CONNECT_AS_MIN_VERSION}. ' f'Remote version: {remote_webrtc_version or "unknown"}. ' 'Please upgrade the Gateway to use --credential.' ) @@ -1057,8 +1071,11 @@ def signal_handler_fn(signum, frame): logging.info("CLI session ended - cleanup complete") + except CommandError: + raise except Exception as e: logging.error(f"Error in PythonHandler CLI session: {e}") raise CommandError('pam launch', f'Failed to start CLI session: {e}') finally: + exit_pam_launch_terminal_rust_logging(rust_log_token) signal.signal(signal.SIGINT, original_handler) diff --git a/keepercommander/commands/pam_launch/rust_log_filter.py b/keepercommander/commands/pam_launch/rust_log_filter.py new file mode 100644 index 000000000..b91ef795d --- /dev/null +++ b/keepercommander/commands/pam_launch/rust_log_filter.py @@ -0,0 +1,143 @@ +""" +Rust/webrtc log filtering for pam launch terminal session only. + +Downgrades Rust/webrtc/turn log messages to DEBUG so they only appear when --debug is on, +and only while the pam launch CLI terminal session is active. +""" + +import logging + + +def _rust_webrtc_logger_name(name: str) -> bool: + """True if logger name is from Rust/webrtc/turn so we treat its messages as DEBUG-only.""" + if not name: + return False + # Normalize so we match both '.' and '::' (Rust may use either when passed to Python) + n = (name or '').replace('::', '.') + return ( + n.startswith('keeper_pam_webrtc_rs') + or n.startswith('webrtc') + or n.startswith('turn') + or n.startswith('stun') + or 'relay_conn' in n # turn crate submodule + ) + + +class _RustWebrtcToDebugFilter(logging.Filter): + """ + Filter for Rust/webrtc/turn log records. + When not in debug mode: suppress entirely (return False) so no handler can emit them. + When in debug mode: allow (return True); downgrading to DEBUG is redundant but harmless. + """ + + def filter(self, record: logging.LogRecord) -> bool: + if not _rust_webrtc_logger_name(record.name): + return True + # Only show these messages when debug is enabled (root or effective level is DEBUG) + if logging.getLogger().getEffectiveLevel() <= logging.DEBUG: + return True + return False # suppress when not in debug + + +class _RustAwareLogger(logging.Logger): + """ + Logger that forces Rust/webrtc/turn loggers to have no handlers and propagate to root, + and applies the downgrade filter at the logger so messages are DEBUG-only. + Used so loggers created *after* enter_ (e.g. by turn crate on first use) are still suppressed. + """ + + def __init__(self, name, level=logging.NOTSET): + super().__init__(name, level) + if _rust_webrtc_logger_name(name): + self.setLevel(logging.DEBUG) + self.propagate = True + self.handlers.clear() + self.addFilter(_RustWebrtcToDebugFilter()) + + +_WEBRTC_CRATE_NAMES = [ + 'webrtc', 'webrtc_ice', 'webrtc_mdns', 'webrtc_dtls', + 'webrtc_sctp', 'turn', 'stun', 'webrtc_ice.agent.agent_internal', + 'webrtc_ice.agent.agent_gather', 'webrtc_ice.mdns', + 'webrtc_mdns.conn', 'webrtc.peer_connection', 'turn.client', + 'turn.client.relay_conn', # turn crate submodule that emits "fail to refresh permissions..." +] + + +def enter_pam_launch_terminal_rust_logging(): + """ + Apply Rust/webrtc log filtering only during pam launch terminal session. + Downgrades Rust/webrtc/turn messages to DEBUG so they only show with --debug. + Returns a token to pass to exit_pam_launch_terminal_rust_logging() on exit. + """ + root = logging.getLogger() + flt = _RustWebrtcToDebugFilter() + root.addFilter(flt) + + # Use custom Logger class so any Rust/webrtc logger created later (e.g. turn crate) + # gets no handlers and propagates to root, where our filter downgrades to DEBUG. + _original_logger_class = logging.getLoggerClass() + logging.setLoggerClass(_RustAwareLogger) + + saved = [] + downgrade_filter = _RustWebrtcToDebugFilter() + for name in list(logging.Logger.manager.loggerDict.keys()): + if not isinstance(name, str) or not _rust_webrtc_logger_name(name): + continue + log = logging.getLogger(name) + # Only save if it's a real Logger with state we can restore (not our custom class yet) + if not isinstance(log, _RustAwareLogger): + saved.append((name, log.level, log.propagate, list(log.handlers))) + log.setLevel(logging.DEBUG) + log.propagate = True + log.handlers.clear() + if downgrade_filter not in log.filters: + log.addFilter(downgrade_filter) + for crate_name in _WEBRTC_CRATE_NAMES: + log = logging.getLogger(crate_name) + if not isinstance(log, _RustAwareLogger): + saved.append((crate_name, log.level, log.propagate, list(log.handlers))) + log.setLevel(logging.DEBUG) + log.propagate = True + log.handlers.clear() + if downgrade_filter not in log.filters: + log.addFilter(downgrade_filter) + + return (flt, saved, _original_logger_class) + + +def exit_pam_launch_terminal_rust_logging(token): + """Restore Rust/webrtc logger state after pam launch terminal session. Pass token from enter_pam_launch_terminal_rust_logging().""" + if not token: + return + flt, saved = token[0], token[1] + original_logger_class = token[2] if len(token) > 2 else logging.Logger + logging.setLoggerClass(original_logger_class) + root = logging.getLogger() + root.removeFilter(flt) + # Remove downgrade filter from all Rust/webrtc loggers (we may have added the shared + # filter to existing loggers, and _RustAwareLogger instances have their own filter) + for name in list(logging.Logger.manager.loggerDict.keys()): + if not isinstance(name, str) or not _rust_webrtc_logger_name(name): + continue + log = logging.getLogger(name) + for f in list(log.filters): + if isinstance(f, _RustWebrtcToDebugFilter): + try: + log.removeFilter(f) + except ValueError: + pass + for crate_name in _WEBRTC_CRATE_NAMES: + log = logging.getLogger(crate_name) + for f in list(log.filters): + if isinstance(f, _RustWebrtcToDebugFilter): + try: + log.removeFilter(f) + except ValueError: + pass + for name, level, propagate, handlers in saved: + log = logging.getLogger(name) + log.setLevel(level) + log.propagate = propagate + for h in handlers: + log.addHandler(h) diff --git a/keepercommander/commands/tunnel/port_forward/tunnel_helpers.py b/keepercommander/commands/tunnel/port_forward/tunnel_helpers.py index 22fac8df3..7fc378f45 100644 --- a/keepercommander/commands/tunnel/port_forward/tunnel_helpers.py +++ b/keepercommander/commands/tunnel/port_forward/tunnel_helpers.py @@ -4,6 +4,7 @@ import logging import re import os +import threading import secrets import socket import string @@ -113,7 +114,6 @@ def set_remote_description_and_parse_version(tube_registry, tube_id, sdp, is_ans # ICE candidate buffering - store until SDP answer is received # Global conversation key management for multiple concurrent tunnels -import threading _CONVERSATION_KEYS_LOCK = threading.Lock() _GLOBAL_CONVERSATION_KEYS = {} # conversationId -> symmetric_key mapping @@ -383,7 +383,6 @@ def _configure_rust_logger_levels(current_is_debug: bool, log_level: int): # CRITICAL: Ensure root logger has a handler # pyo3_log sends Rust logs to Python loggers, but if loggers have no handlers, # messages are lost even if propagate=True - import sys if not root_logger.handlers: # Add a console handler if none exists console_handler = logging.StreamHandler(sys.stderr) @@ -1534,17 +1533,17 @@ def signal_from_rust(self, response: dict): # Detailed logging for specific states if new_state == 'disconnected': - logging.warning(f"Connection disconnected for tube {tube_id} - ICE restart may be attempted by Rust") + logging.debug(f"Connection disconnected for tube {tube_id} - ICE restart may be attempted by Rust") elif new_state == 'failed': - logging.error(f"Connection failed for tube {tube_id} - ICE restart may be attempted by Rust") + logging.debug(f"Connection failed for tube {tube_id} - ICE restart may be attempted by Rust") elif new_state == 'connected': logging.debug( f"Connection established/restored for tube {tube_id} " f"(conversation_id={conversation_id_from_signal or self.conversation_id})" ) - logging.debug(f"Connection state: connected") + logging.debug("Connection state: connected") # CRITICAL: Mark connection as connected - IMMEDIATELY stop sending ICE candidates self.connection_connected = True @@ -1651,9 +1650,9 @@ def signal_from_rust(self, response: dict): logging.debug(f"Stopping dedicated WebSocket for tunnel {tube_id}") session.websocket_stop_event.set() # Signal WebSocket to close # Give it a moment to close gracefully - session.websocket_thread.join(timeout=2.0) + session.websocket_thread.join(timeout=5.0) if session.websocket_thread.is_alive(): - logging.warning(f"Dedicated WebSocket for tunnel {tube_id} did not close in time") + logging.debug(f"Dedicated WebSocket for tunnel {tube_id} did not close in time") else: logging.debug(f"Dedicated WebSocket closed for tunnel {tube_id}") @@ -1678,9 +1677,9 @@ def signal_from_rust(self, response: dict): logging.debug(f"Stopping dedicated WebSocket for failed tunnel {tube_id}") session.websocket_stop_event.set() # Signal WebSocket to close # Give it a moment to close gracefully - session.websocket_thread.join(timeout=2.0) + session.websocket_thread.join(timeout=5.0) if session.websocket_thread.is_alive(): - logging.warning(f"Dedicated WebSocket for tunnel {tube_id} did not close in time") + logging.debug(f"Dedicated WebSocket for tunnel {tube_id} did not close in time") else: logging.debug(f"Dedicated WebSocket closed for failed tunnel {tube_id}")