rws_server/log/
mod.rs

1use std::net::SocketAddr;
2use std::thread;
3use crate::entry_point::command_line_args::CommandLineArgument;
4use crate::request::Request;
5use crate::response::Response;
6use crate::server_config::log_privacy::{self, LogPrivacy};
7
8#[cfg(test)]
9mod tests;
10#[doc(hidden)]
11pub mod access_sink;
12pub mod syslog;
13pub mod tail;
14
15/// Logging helpers for access logs and server info.
16///
17/// [`Log::combined`] produces standard Combined Log Format lines compatible with
18/// GoAccess, AWStats, and similar tools. All three server code paths (HTTP/1.1,
19/// HTTP/2, HTTP/3) use it.
20pub struct Log;
21
22/// Called for every access-logged request, before the line is written: the
23/// traffic insights (`traffic`, above this layer) set it when enabled.
24static ACCESS_OBSERVER: std::sync::OnceLock<fn(&Request, &Response, std::net::IpAddr)> = std::sync::OnceLock::new();
25
26/// Set the [`Log::log_access`] observer (once; later calls are ignored).
27#[doc(hidden)]
28pub fn set_access_observer(observe: fn(&Request, &Response, std::net::IpAddr)) {
29    let _ = ACCESS_OBSERVER.set(observe);
30}
31
32impl Log {
33    /// A multi-line debugging dump of a request and its response, headers
34    /// included — the values of `Authorization`, `Proxy-Authorization`,
35    /// `Cookie`, `Set-Cookie` and of `RWS_CONFIG_LOG_REDACT_HEADERS` shown as
36    /// `REDACTED` (since 18.33.0).
37    pub fn request_response(request: &Request, response: &Response, peer_addr: &SocketAddr) -> String {
38        let config = crate::server_config::ServerConfig::current();
39        let shown = |header: &crate::header::Header| -> String {
40            if config.log_privacy.redacts_header(&header.name) {
41                log_privacy::REDACTED.to_string()
42            } else {
43                header.value.to_string()
44            }
45        };
46        let mut request_headers = "".to_string();
47        for header in &request.headers {
48            if &header.name.chars().count() > &0 {
49                request_headers = [
50                    request_headers,
51                    "\n  ".to_string(),
52                    header.name.to_string(),
53                    ": ".to_string(),
54                    shown(header)
55                ].join("");
56            }
57        }
58
59        let mut response_headers = "".to_string();
60        for header in &response.headers {
61            if &header.name.chars().count() > &0 {
62                response_headers = [
63                    response_headers,
64                    "\n  ".to_string(),
65                    header.name.to_string(),
66                    ": ".to_string(),
67                    shown(header)
68                ].join("");
69            }
70        }
71
72        let mut response_body_length = 0;
73        let mut response_body_parts_number = 0;
74        for content_range in &response.content_range_list {
75            let boxed_parse = content_range.size.parse::<i32>();
76            if boxed_parse.is_ok() {
77                response_body_length += boxed_parse.unwrap();
78                response_body_parts_number += 1;
79            }
80        }
81
82        let current_thread = thread::current();
83        let thread_id = current_thread.name().unwrap();
84
85        let log_request_response = format!("\n\nRequest (thread id: {} peer address is {}):\n  {} {} {}  {}\n  Body: {} byte(s) total (including default initialization vector)\nEnd of Request\nResponse:\n  {} {} {}\n\n  Body: {} part(s), {} byte(s) total\nEnd of Response",
86                                           thread_id,
87                                           peer_addr,
88                                           &request.http_version,
89                                           &request.method,
90                                           &request.request_uri,
91                                           request_headers,
92                                           request.body.len(),
93
94                                           &response.status_code,
95                                           &response.reason_phrase,
96                                           response_headers,
97                                           response_body_parts_number,
98                                           response_body_length);
99
100        log_request_response
101    }
102
103    pub fn usage_information() -> String {
104        let mut log = "Usage:\n\n".to_string();
105        let command_line_arg_list = CommandLineArgument::get_command_line_arg_list();
106        for arg in command_line_arg_list {
107            let flags = if arg.short_form.is_empty() {
108                format!("--{}", arg.long_form)
109            } else {
110                format!("-{} or --{}", arg.short_form, arg.long_form)
111            };
112            let argument_info = format!("  {} environment variable\n  {} as command line line argument\n  {}\n\n", arg.environment_variable, flags, arg._hint.unwrap());
113            log = [log, argument_info].join("");
114        }
115        log = [log, "End of usage section\n\n".to_string()].join("");
116        log
117    }
118
119    /// The user rws runs as, for the startup banner: `$USER`, `$LOGNAME` or
120    /// `%USERNAME%`, else `"unknown"`. Deliberately not `whoami` (what
121    /// `FileExt::get_current_user` runs): minimal container images such as
122    /// distroless have no `whoami`, and the banner's `unwrap()` on that
123    /// error crashed the published Docker image at startup.
124    pub fn current_user() -> String {
125        ["USER", "LOGNAME", "USERNAME"]
126            .iter()
127            .find_map(|var| std::env::var(var).ok().filter(|v| !v.trim().is_empty()))
128            .unwrap_or_else(|| "unknown".to_string())
129    }
130
131    pub fn info(name: &str) -> String {
132        let mut log = format!("{}\n", name).to_string();
133        const VERSION: &str = env!("CARGO_PKG_VERSION");
134        const AUTHORS: &str = env!("CARGO_PKG_AUTHORS");
135        const REPOSITORY: &str = env!("CARGO_PKG_REPOSITORY");
136        const DESCRIPTION: &str = env!("CARGO_PKG_DESCRIPTION");
137        const RUST_VERSION: &str = env!("CARGO_PKG_RUST_VERSION");
138        const LICENSE: &str = env!("CARGO_PKG_LICENSE");
139        let user = Log::current_user();
140        let working_directory = crate::app::controller::static_resource::working_directory().to_string();
141
142        let version = format!("Version:           {}\n", VERSION);
143        log = [log, version].join("");
144
145        let authors = format!("Authors:           {}\n", AUTHORS);
146        log = [log, authors].join("");
147
148        let repository = format!("Repository:        {}\n", REPOSITORY);
149        log = [log, repository].join("");
150
151        let description = format!("Description:       {}\n", DESCRIPTION);
152        log = [log, description].join("");
153
154        let rust_version = format!("Rust Version:      {}\n", RUST_VERSION);
155        log = [log, rust_version].join("");
156
157        let license = format!("License:           {}\n", LICENSE);
158        log = [log, license].join("");
159
160        let license = format!("User:              {}\n", user);
161        log = [log, license].join("");
162
163        let license = format!("Working Directory: {}\n", working_directory);
164        log = [log, license].join("");
165
166        log
167    }
168
169    /// Returns a structured JSON log line for one request/response pair:
170    /// `time`, `remote_addr`, `method`, `path`, `protocol`, `status`, `bytes`,
171    /// then `host`, `user_agent` and `referer` when the request has them.
172    ///
173    /// Enable with `RWS_CONFIG_LOG_FORMAT=json`. Useful for log aggregators
174    /// (Loki, Fluentd, Datadog) that ingest JSON from pod stdout.
175    pub fn json(request: &Request, response: &Response, peer_addr: &SocketAddr) -> String {
176        let mut line = Vec::with_capacity(160);
177        Log::write_json(&mut line, request, response, peer_addr);
178        bytes_to_string(line)
179    }
180
181    /// [`Log::json`] appended to `out`, without intermediate strings.
182    fn write_json(out: &mut Vec<u8>, request: &Request, response: &Response, peer_addr: &SocketAddr) {
183        let config = crate::server_config::ServerConfig::current();
184        Log::write_json_with(out, request, response, peer_addr, &config.log_privacy)
185    }
186
187    /// [`Log::write_json`] with the privacy settings at hand: with
188    /// everything off, exactly the line of 18.32.
189    fn write_json_with(out: &mut Vec<u8>, request: &Request, response: &Response, peer_addr: &SocketAddr, privacy: &LogPrivacy) {
190        use std::io::Write;
191        let body_size: usize = response.content_range_list.iter().map(|cr| cr.body.len()).sum();
192        let plain = privacy.is_off();
193        out.extend_from_slice(b"{\"time\":\"");
194        with_timestamps(|iso, _| out.extend_from_slice(iso.as_bytes()));
195        out.extend_from_slice(b"\",\"remote_addr\":\"");
196        if plain {
197            let _ = write!(out, "{}", peer_addr.ip());
198        } else {
199            privacy.write_ip(out, peer_addr.ip());
200        }
201        out.extend_from_slice(b"\",\"method\":\"");
202        push_json_escaped(out, &request.method);
203        out.extend_from_slice(b"\",\"path\":\"");
204        if plain {
205            push_json_escaped(out, &request.request_uri);
206        } else {
207            privacy.redact_target(&request.request_uri, |piece| push_json_escaped(out, piece));
208        }
209        out.extend_from_slice(b"\",\"protocol\":\"");
210        push_json_escaped(out, &request.http_version);
211        out.extend_from_slice(b"\",\"status\":");
212        let _ = write!(out, "{}", response.status_code);
213        out.extend_from_slice(b",\"bytes\":");
214        out.extend_from_slice(crate::ext::decimal::Decimal::new(body_size as u128).as_str().as_bytes());
215        // Who asked, for what site, from where (18.15.0): only when sent.
216        for (key, name) in [(&b",\"host\":\""[..], "host"), (&b",\"user_agent\":\""[..], "user-agent"), (&b",\"referer\":\""[..], "referer")] {
217            if let Some(header) = request.header(name).filter(|h| !h.value.is_empty()) {
218                out.extend_from_slice(key);
219                if plain {
220                    push_json_escaped(out, &header.value);
221                } else if privacy.redacts_header(name) {
222                    out.extend_from_slice(log_privacy::REDACTED.as_bytes());
223                } else if name == "referer" {
224                    privacy.redact_target(&header.value, |piece| push_json_escaped(out, piece));
225                } else {
226                    push_json_escaped(out, &header.value);
227                }
228                out.push(b'"');
229            }
230        }
231        out.push(b'}');
232    }
233
234    /// Writes one access log line to stdout using the format configured by
235    /// `RWS_CONFIG_LOG_FORMAT` (`"combined"` or `"json"`). Call this instead of
236    /// `Log::combined` so that format selection is centralised.
237    ///
238    /// Lines are buffered per thread and written by a background thread every
239    /// 100 ms (and when a thread's buffer passes 32 KiB, when the thread
240    /// exits, and at process exit); [`Log::flush_access_log`] writes them now.
241    pub fn log_access(request: &Request, response: &Response, peer_addr: &SocketAddr) {
242        Log::log_access_traced(request, response, peer_addr, None)
243    }
244
245    /// [`Log::log_access`] for the server's own connection loops: takes the
246    /// request's trace context off the response first (`OtelLayer` puts it
247    /// there only while OTLP log export is on), so it reaches the OTLP log
248    /// record but not the client.
249    #[doc(hidden)]
250    pub fn log_served(request: &Request, response: &mut Response, peer_addr: &SocketAddr) {
251        let trace = crate::otel::logs::take_trace(response);
252        Log::log_access_traced(request, response, peer_addr, trace)
253    }
254
255    fn log_access_traced(request: &Request, response: &Response, peer_addr: &SocketAddr, trace: Option<crate::otel::logs::TraceIds>) {
256        // The client behind a trusted proxy (`ip_filter::client_ip`), not the
257        // proxy; only looked up when the request says it was forwarded.
258        let client;
259        let peer_addr = if request.header("x-forwarded-for").is_some() || request.header("forwarded").is_some() {
260            client = crate::ip_filter::client_ip(request, &peer_addr.ip().to_string())
261                .parse::<std::net::IpAddr>()
262                .map_or(*peer_addr, |ip| SocketAddr::new(ip, peer_addr.port()));
263            &client
264        } else {
265            peer_addr
266        };
267        // Traffic insights count every request, whether lines are written.
268        if let Some(observe) = ACCESS_OBSERVER.get() {
269            observe(request, response, peer_addr.ip());
270        }
271        let config = crate::server_config::ServerConfig::current();
272        let format = &config.log_format;
273        let off = format.eq_ignore_ascii_case("off") || format.eq_ignore_ascii_case("none");
274        let otlp = crate::otel::logs::enabled();
275        if off && !otlp {
276            return;
277        }
278        let json = format == "json";
279        let privacy = &config.log_privacy;
280        if !off {
281            access_sink::write_line(|out| {
282                if json {
283                    Log::write_json_with(out, request, response, peer_addr, privacy)
284                } else {
285                    Log::write_combined_with(out, request, response, peer_addr, privacy)
286                }
287            });
288        }
289        if otlp {
290            // The same line as the record's body (JSON while the access log
291            // itself is off), beside semantic-convention attributes.
292            crate::otel::logs::record(request, response, peer_addr.ip(), privacy, trace, |out| {
293                if json || off {
294                    Log::write_json_with(out, request, response, peer_addr, privacy)
295                } else {
296                    Log::write_combined_with(out, request, response, peer_addr, privacy)
297                }
298            });
299        }
300    }
301
302    /// Have `SIGUSR1` reopen the access-log file (`RWS_CONFIG_ACCESS_LOG`)
303    /// before its next write, for logrotate; does nothing when the log goes
304    /// to stdout. The `rws` binary calls it at startup.
305    pub fn reopen_access_log_on_sigusr1() {
306        access_sink::install_reopen_signal();
307    }
308
309    /// Reopen the access-log file before its next write — what `SIGUSR1`
310    /// does, for a program that moves the file itself.
311    pub fn reopen_access_log() {
312        access_sink::reopen();
313    }
314
315    /// Write out the buffered access-log lines now (they're otherwise written
316    /// within 100 ms) — e.g. before exiting without returning from `main`.
317    pub fn flush_access_log() {
318        access_sink::flush();
319    }
320
321    /// The access-log line for `RWS_CONFIG_LOG_FORMAT`: `json` (the `rws`
322    /// binary's default), Combined Log Format for any other value (including
323    /// unset, in library use), or `None` for `off`/`none` — no per-request
324    /// line, e.g. behind a proxy that already logs or when benchmarking.
325    /// Taken from `ServerConfig::current()`, so it's hot-reloadable.
326    pub fn access_log_line(request: &Request, response: &Response, peer_addr: &SocketAddr) -> Option<String> {
327        let config = crate::server_config::ServerConfig::current();
328        let format = &config.log_format;
329        if format.eq_ignore_ascii_case("off") || format.eq_ignore_ascii_case("none") {
330            return None;
331        }
332        Some(if format == "json" {
333            Log::json(request, response, peer_addr)
334        } else {
335            Log::combined(request, response, peer_addr)
336        })
337    }
338
339    fn format_iso8601(secs: u64) -> String {
340        let sec = secs % 60;
341        let min = (secs / 60) % 60;
342        let hour = (secs / 3600) % 24;
343        let days = secs / 86400;
344        let (year, month, day) = Log::days_to_ymd(days);
345        format!("{:04}-{:02}-{:02}T{:02}:{:02}:{:02}Z", year, month, day, hour, min, sec)
346    }
347
348    /// Returns a Combined Log Format (CLF) line for one request/response pair:
349    /// `IP - - [DD/Mon/YYYY:HH:MM:SS +0000] "METHOD URI VERSION" STATUS SIZE`
350    pub fn combined(request: &Request, response: &Response, peer_addr: &SocketAddr) -> String {
351        let mut line = Vec::with_capacity(128);
352        Log::write_combined(&mut line, request, response, peer_addr);
353        bytes_to_string(line)
354    }
355
356    /// [`Log::combined`] appended to `out`, without intermediate strings.
357    fn write_combined(out: &mut Vec<u8>, request: &Request, response: &Response, peer_addr: &SocketAddr) {
358        let config = crate::server_config::ServerConfig::current();
359        Log::write_combined_with(out, request, response, peer_addr, &config.log_privacy)
360    }
361
362    fn write_combined_with(out: &mut Vec<u8>, request: &Request, response: &Response, peer_addr: &SocketAddr, privacy: &LogPrivacy) {
363        use std::io::Write;
364        let body_size: usize = response.content_range_list.iter().map(|cr| cr.body.len()).sum();
365        if privacy.is_off() {
366            let _ = write!(out, "{}", peer_addr.ip());
367        } else {
368            privacy.write_ip(out, peer_addr.ip());
369        }
370        out.extend_from_slice(b" - - [");
371        with_timestamps(|_, clf| out.extend_from_slice(clf.as_bytes()));
372        out.extend_from_slice(b"] \"");
373        out.extend_from_slice(request.method.as_bytes());
374        out.push(b' ');
375        if privacy.redact_query.is_empty() {
376            out.extend_from_slice(request.request_uri.as_bytes());
377        } else {
378            privacy.redact_target(&request.request_uri, |piece| out.extend_from_slice(piece.as_bytes()));
379        }
380        out.push(b' ');
381        out.extend_from_slice(request.http_version.as_bytes());
382        out.extend_from_slice(b"\" ");
383        let _ = write!(out, "{}", response.status_code);
384        out.push(b' ');
385        if body_size > 0 {
386            out.extend_from_slice(crate::ext::decimal::Decimal::new(body_size as u128).as_str().as_bytes());
387        } else {
388            out.push(b'-');
389        }
390    }
391
392    fn format_clf_timestamp(secs: u64) -> String {
393        let sec = secs % 60;
394        let min = (secs / 60) % 60;
395        let hour = (secs / 3600) % 24;
396        let days = secs / 86400;
397        let (year, month, day) = Log::days_to_ymd(days);
398        const MONTHS: [&str; 12] = ["Jan","Feb","Mar","Apr","May","Jun","Jul","Aug","Sep","Oct","Nov","Dec"];
399        format!("{:02}/{}/{:04}:{:02}:{:02}:{:02} +0000",
400            day, MONTHS[(month - 1) as usize], year, hour, min, sec)
401    }
402
403    fn days_to_ymd(days: u64) -> (u64, u64, u64) {
404        let z = days + 719468;
405        let era = z / 146097;
406        let doe = z % 146097;
407        let yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365;
408        let y = yoe + era * 400;
409        let doy = doe - (365 * yoe + yoe / 4 - yoe / 100);
410        let mp = (5 * doy + 2) / 153;
411        let d = doy - (153 * mp + 2) / 5 + 1;
412        let m = if mp < 10 { mp + 3 } else { mp - 9 };
413        let y = if m <= 2 { y + 1 } else { y };
414        (y, m, d)
415    }
416
417    pub fn server_url_thread_count(protocol: &str, bind_addr: &String, thread_count: i32) -> String {
418        let url = format!("Server is up and running at: {}://{}\n", protocol, &bind_addr);
419        let thread_count = format!("Spawned {} thread(s) to handle incoming requests\n", thread_count);
420        [url, thread_count].join("")
421    }
422}
423/// The current second as ISO 8601 (`2026-10-29T12:00:00Z`), cached per
424/// thread like the access log's.
425#[doc(hidden)]
426pub fn iso8601_now(use_it: impl FnOnce(&str)) {
427    with_timestamps(|iso, _| use_it(iso));
428}
429
430/// The current second's ISO 8601 and Combined Log Format timestamps,
431/// formatted at most once per second per thread.
432fn with_timestamps(use_them: impl FnOnce(&str, &str)) {
433    use std::cell::RefCell;
434    use std::time::{SystemTime, UNIX_EPOCH};
435    thread_local! {
436        static CACHED: RefCell<(u64, String, String)> = const { RefCell::new((u64::MAX, String::new(), String::new())) };
437    }
438    let secs = SystemTime::now().duration_since(UNIX_EPOCH).unwrap_or_default().as_secs();
439    CACHED.with(|cached| {
440        let mut cached = cached.borrow_mut();
441        if cached.0 != secs {
442            *cached = (secs, Log::format_iso8601(secs), Log::format_clf_timestamp(secs));
443        }
444        use_them(&cached.1, &cached.2);
445    });
446}
447
448/// `s` JSON-escaped as the access log always did it: backslash, double
449/// quote, newline and carriage return.
450fn push_json_escaped(out: &mut Vec<u8>, s: &str) {
451    for b in s.bytes() {
452        match b {
453            b'\\' => out.extend_from_slice(b"\\\\"),
454            b'"' => out.extend_from_slice(b"\\\""),
455            b'\n' => out.extend_from_slice(b"\\n"),
456            b'\r' => out.extend_from_slice(b"\\r"),
457            _ => out.push(b),
458        }
459    }
460}
461
462/// A line built only from `&str` pieces is UTF-8.
463fn bytes_to_string(bytes: Vec<u8>) -> String {
464    String::from_utf8(bytes).unwrap_or_else(|e| String::from_utf8_lossy(e.as_bytes()).into_owned())
465}
rws_server/log/mod.rs

rws_server/log/
mod.rs
