server: only info log once per request

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<UnixListener> {
     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<UnixListener> {
             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<String>,
     stdin: File,
+    stdin_size: Option<u64>,
     response_transport: ResponseTransport,
     forwarded_env: &BTreeMap<String, String>,
     received_uploads: HashMap<u32, ReceivedUpload>,
 ) -> 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::<Vec<_>>();
     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::<BTreeMap<_, _>>();
-    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<u64>,
+) {
+    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!(