diff --git a/src/bin/bro-server.rs b/src/bin/bro-server.rs index 6dac3e6..a80adab 100644 --- a/src/bin/bro-server.rs +++ b/src/bin/bro-server.rs @@ -276,7 +276,7 @@ fn accept_ready_connections(listener: &UnixListener, config: &ServerConfig) -> R loop { match listener.accept() { Ok((stream, address)) => { - log::info!("accepted client connection from {address:?}"); + log::debug!("accepted client connection from {address:?}"); if let Err(error) = handle_connection(stream, config) { log::warn!("connection handling failed: {error:#}"); } @@ -372,7 +372,7 @@ impl ServerConfig { fn log_server_config(config: &ServerConfig) { match &config.listener_mode { ListenerMode::Systemd => { - log::info!( + log::debug!( "loaded server configuration: listener_mode={} executable={} fd_passing={}", config.listener_mode.label(), config.executable.display(), @@ -380,7 +380,7 @@ fn log_server_config(config: &ServerConfig) { ); } ListenerMode::Path(path) => { - log::info!( + log::debug!( "loaded server configuration: listener_mode={} socket_path={} executable={} fd_passing={}", config.listener_mode.label(), path.display(), @@ -427,11 +427,11 @@ fn ensure_tmp_root_exists(config: &ServerConfig) -> Result<()> { fn open_listener(config: &ServerConfig) -> Result { match &config.listener_mode { ListenerMode::Systemd => { - log::info!("opening listener from systemd socket activation"); + log::debug!("opening listener from systemd socket activation"); activated_listener() } ListenerMode::Path(path) => { - log::info!("binding listener at unix socket path {}", path.display()); + log::debug!("binding listener at unix socket path {}", path.display()); bound_listener(path) } } @@ -506,7 +506,7 @@ fn bound_listener(path: &Path) -> Result { path.display() ) })?; - log::info!("bound unix socket listener at {}", path.display()); + log::debug!("bound unix socket listener at {}", path.display()); Ok(listener) } @@ -619,17 +619,6 @@ fn handle_execute_connection_inner( config: &ServerConfig, header: RequestHeader, ) -> Result<()> { - log::info!( - "received request header: args={} uploads={} stdin_size={:?} forwarded_env={} upload_transport={:?} stdin_transport={:?} response_transport={:?}", - header.args.len(), - header.uploads.len(), - header.stdin_size, - header.env.len(), - header.upload_transport, - header.stdin_transport, - header.response_transport, - ); - validate_request(&header, config)?; let tempdir = create_request_tempdir(config)?; @@ -646,6 +635,10 @@ fn handle_execute_connection_inner( config, rewritten_args, stdin, + match header.stdin_transport { + UploadTransport::StreamedBytes => header.stdin_size, + UploadTransport::PassedFileDescriptors => None, + }, header.response_transport, &header.env, received_uploads, @@ -991,10 +984,12 @@ fn execute_request( config: &ServerConfig, args: Vec, stdin: File, + stdin_size: Option, response_transport: ResponseTransport, forwarded_env: &BTreeMap, received_uploads: HashMap, ) -> Result<()> { + let file_transfer_count = received_uploads.len(); let _keep_received_uploads_alive = received_uploads; let inherited_env = config.inherited_environment(); let disallowed_forwarded_env = forwarded_env @@ -1003,7 +998,7 @@ fn execute_request( .cloned() .collect::>(); if !disallowed_forwarded_env.is_empty() { - log::warn!( + log::debug!( "ignoring {} forwarded environment variable(s) that are not allowed by server policy: {}", disallowed_forwarded_env.len(), disallowed_forwarded_env.join(", ") @@ -1014,12 +1009,13 @@ fn execute_request( .filter(|(key, _value)| config.forwarded_env_is_allowed(key)) .map(|(key, value)| (key.clone(), value.clone())) .collect::>(); - log::info!( - "spawning configured executable {} with {} args, {} inherited env vars, and {} forwarded env vars", - config.executable.display(), - args.len(), + log_request_execution( + config, + &args, + allowed_forwarded_env.len(), inherited_env.len(), - allowed_forwarded_env.len() + file_transfer_count, + stdin_size, ); let mut command = Command::new(&config.executable); @@ -1037,7 +1033,7 @@ fn execute_request( config.executable.display() ) })?; - log::info!("spawned configured executable with pid {}", child.id()); + log::debug!("spawned configured executable with pid {}", child.id()); let stdout = child .stdout @@ -1069,7 +1065,7 @@ fn execute_request( let status = child .wait() .context("failed to wait for remote executable")?; - log::info!("configured executable exited with status {status}"); + log::debug!("configured executable exited with status {status}"); write_response_frame( stream, response_transport, @@ -1080,6 +1076,57 @@ fn execute_request( Ok(()) } +fn log_request_execution( + config: &ServerConfig, + args: &[String], + forwarded_env_count: usize, + inherited_env_count: usize, + file_transfer_count: usize, + stdin_size: Option, +) { + let rendered_command = render_command_for_log(&config.executable, args); + + match stdin_size { + Some(stdin_size) => log::info!( + "forwarded_env_count={} inherited_env_count={} file_transfer_count={} stdin_size={} -- {}", + forwarded_env_count, + inherited_env_count, + file_transfer_count, + stdin_size, + rendered_command, + ), + None => log::info!( + "forwarded_env_count={} inherited_env_count={} file_transfer_count={} -- {}", + forwarded_env_count, + inherited_env_count, + file_transfer_count, + rendered_command, + ), + } +} + +fn render_command_for_log(executable: &Path, args: &[String]) -> String { + let mut rendered_parts = Vec::with_capacity(args.len() + 1); + rendered_parts.push(shell_quote_for_log(executable.to_string_lossy().as_ref())); + rendered_parts.extend(args.iter().map(|arg| shell_quote_for_log(arg))); + rendered_parts.join(" ") +} + +fn shell_quote_for_log(text: &str) -> String { + if text.is_empty() { + return "''".to_owned(); + } + + if text.chars().all(|character| { + character.is_ascii_alphanumeric() + || matches!(character, '_' | '@' | '%' | '+' | '=' | ':' | ',' | '.' | '/' | '-') + }) { + return text.to_owned(); + } + + format!("'{}'", text.replace('\'', "'\"'\"'")) +} + fn is_control_environment_key(key: &str) -> bool { key.starts_with("BRO_") || matches!(