featherbit/plugins/util/
log_entry.rs

1//! Shared access-log entry builder for the logger plugins.
2//!
3//! Every logger (http-logger, tcp-logger, elasticsearch-logger, ...) turns the
4//! request [`Context`] into the same JSON entry so their output is consistent.
5//! Two shapes, mirroring APISIX's `log-util`:
6//!
7//! - **default entry** — a structured object (`request`, `response`,
8//!   `client_ip`, `latency`, `consumer`, ...) when no `log_format` is set.
9//! - **custom entry** — a flat object built from a configured `log_format` map
10//!   of `name -> "template"`, each pre-parsed into a [`Template`] at config
11//!   load and rendered per request via
12//!   [`Template::render_with_legacy`] (supports `{{namespace.path}}`
13//!   references plus legacy `$var` interpolation).
14//!
15//! Latency is derived from the reserved `__request_start_ms` message key the
16//! data-plane listener stamps at request start; it is omitted when absent
17//! (e.g. in unit tests that build a Context directly).
18
19use std::collections::HashMap;
20
21use serde_json::{json, Map, Value};
22
23use crate::context::Context;
24use crate::vars::template::Template;
25
26/// One entry in a parsed [`LogFormat`]: a string value is pre-parsed into a
27/// [`Template`] at config-load time (one parse, per-request render); a
28/// number/boolean scalar is kept as-is and rendered verbatim.
29#[derive(Debug, Clone)]
30pub enum LogFormatValue {
31    /// Supports `{{namespace.path}}` references and legacy `$var`
32    /// interpolation (see [`Template::render_with_legacy`]).
33    Template(Template),
34    /// A non-string scalar (number/bool), used verbatim.
35    Literal(Value),
36}
37
38/// A parsed `log_format`: entry name -> pre-parsed value.
39pub type LogFormat = HashMap<String, LogFormatValue>;
40
41/// Builds a log entry for `ctx`.
42///
43/// When `log_format` is `Some`, produces a flat object whose string entries
44/// are rendered from their pre-parsed templates. When `None`, produces the
45/// default structured entry. `include_req_body` / `include_resp_body` add the
46/// (UTF-8 lossy) bodies.
47pub fn build_entry(
48    ctx: &Context,
49    log_format: Option<&LogFormat>,
50    include_req_body: bool,
51    include_resp_body: bool,
52) -> Value {
53    match log_format {
54        Some(fmt) => build_custom(ctx, fmt),
55        None => build_default(ctx, include_req_body, include_resp_body),
56    }
57}
58
59/// Whether a logger with this configuration reads `context.response.body`.
60///
61/// A logger opts out of buffering only when it has a `log_format` whose
62/// entries never reference the response body and it was not asked to include
63/// the body outright.
64///
65/// With **no** `log_format` it falls through to [`build_default`], which
66/// always records `size: ctx.response.body.len()`. On a streaming route that
67/// would silently log `0`, so the absent-format case keeps buffering rather
68/// than trading a correct byte count for a stream.
69pub fn reads_response_body(log_format: Option<&LogFormat>, include_resp_body: bool) -> bool {
70    if include_resp_body {
71        return true;
72    }
73    match log_format {
74        None => true,
75        Some(fmt) => fmt.values().any(|v| match v {
76            LogFormatValue::Template(t) => t.references_response_body(),
77            LogFormatValue::Literal(_) => false,
78        }),
79    }
80}
81
82/// Parses a `log_format` config value (an object of `name -> string`) into a
83/// [`LogFormat`], or `None` when absent. Returns an error if it is present but
84/// not an object of scalar values. String values are pre-parsed into
85/// [`Template`]s here (warnings discarded — the compile-time walk, a later
86/// task, reports them); number/boolean values pass through unchanged.
87pub fn parse_log_format(config: &HashMap<String, Value>) -> Result<Option<LogFormat>, String> {
88    match config.get("log_format") {
89        None | Some(Value::Null) => Ok(None),
90        Some(Value::Object(m)) => {
91            let mut out = HashMap::with_capacity(m.len());
92            for (k, v) in m {
93                let entry = match v {
94                    Value::String(s) => LogFormatValue::Template(Template::parse(s).0),
95                    Value::Number(_) | Value::Bool(_) => LogFormatValue::Literal(v.clone()),
96                    _ => return Err(format!("log_format['{}'] must be a scalar", k)),
97                };
98                out.insert(k.clone(), entry);
99            }
100            Ok(Some(out))
101        }
102        Some(_) => Err("log_format must be an object of name -> template".to_string()),
103    }
104}
105
106fn build_custom(ctx: &Context, fmt: &LogFormat) -> Value {
107    let mut out = Map::new();
108    for (name, entry) in fmt {
109        let rendered = match entry {
110            LogFormatValue::Template(tpl) => Value::String(tpl.render_with_legacy(ctx)),
111            LogFormatValue::Literal(v) => v.clone(),
112        };
113        out.insert(name.clone(), rendered);
114    }
115    Value::Object(out)
116}
117
118fn build_default(ctx: &Context, include_req_body: bool, include_resp_body: bool) -> Value {
119    let mut request = json!({
120        "method": ctx.request.method,
121        "uri": request_uri(ctx),
122        "host": ctx.request.host,
123        "scheme": ctx.request.scheme,
124        "headers": headers_to_json(&ctx.request.headers),
125        "size": ctx.request.body.len(),
126    });
127    if include_req_body {
128        request["body"] = json!(String::from_utf8_lossy(&ctx.request.body));
129    }
130
131    let mut response = json!({
132        "status": ctx.response.status_code,
133        "headers": headers_to_json(&ctx.response.headers),
134        "size": ctx.response.body.len(),
135    });
136    if include_resp_body {
137        response["body"] = json!(String::from_utf8_lossy(&ctx.response.body));
138    }
139
140    let mut entry = Map::new();
141    entry.insert("request".to_string(), request);
142    entry.insert("response".to_string(), response);
143    entry.insert(
144        "client_ip".to_string(),
145        json!(client_ip(&ctx.request.remote_addr)),
146    );
147    if let Some(latency) = latency_ms(ctx) {
148        entry.insert("latency".to_string(), json!(latency));
149    }
150    if let Some(start) = ctx
151        .message
152        .get("__request_start_ms")
153        .and_then(|v| v.as_u64())
154    {
155        entry.insert("start_time".to_string(), json!(start));
156    }
157    if let Some(consumer) = ctx.message.get("consumer.name") {
158        entry.insert("consumer".to_string(), consumer.clone());
159    }
160    if !ctx.errors.is_empty() {
161        entry.insert(
162            "errors".to_string(),
163            json!(ctx
164                .errors
165                .iter()
166                .map(|e| json!({ "node_id": e.node_id, "code": e.code, "message": e.message }))
167                .collect::<Vec<_>>()),
168        );
169    }
170    Value::Object(entry)
171}
172
173/// Milliseconds elapsed since the listener stamped `__request_start_ms`.
174fn latency_ms(ctx: &Context) -> Option<u64> {
175    let start = ctx.message.get("__request_start_ms")?.as_u64()?;
176    let now = std::time::SystemTime::now()
177        .duration_since(std::time::UNIX_EPOCH)
178        .ok()?
179        .as_millis() as u64;
180    Some(now.saturating_sub(start))
181}
182
183/// Header map → JSON object of `name -> [values]`.
184fn headers_to_json(headers: &HashMap<String, Vec<String>>) -> Value {
185    let mut m = Map::new();
186    for (k, v) in headers {
187        m.insert(k.clone(), json!(v));
188    }
189    Value::Object(m)
190}
191
192/// Path plus sorted query string.
193fn request_uri(ctx: &Context) -> String {
194    let mut pairs: Vec<String> = Vec::new();
195    for (k, values) in &ctx.request.query_params {
196        for v in values {
197            pairs.push(format!("{}={}", k, v));
198        }
199    }
200    pairs.sort();
201    if pairs.is_empty() {
202        ctx.request.path.clone()
203    } else {
204        format!("{}?{}", ctx.request.path, pairs.join("&"))
205    }
206}
207
208/// Client IP without the port.
209fn client_ip(remote_addr: &str) -> String {
210    match remote_addr.rsplit_once(':') {
211        Some((ip, _)) if !ip.contains(':') => ip.to_string(),
212        _ => remote_addr.to_string(),
213    }
214}
215
216#[cfg(test)]
217mod tests {
218    use super::*;
219    use crate::context::{GatewayRequest, GatewayResponse, Protocol};
220    use bytes::Bytes;
221
222    fn ctx() -> Context {
223        let mut headers = HashMap::new();
224        headers.insert("user-agent".to_string(), vec!["curl/8".to_string()]);
225        let mut query = HashMap::new();
226        query.insert("q".to_string(), vec!["x".to_string()]);
227        let mut message = HashMap::new();
228        message.insert("consumer.name".to_string(), json!("alice"));
229        Context {
230            request: GatewayRequest {
231                method: "GET".to_string(),
232                path: "/api/items".to_string(),
233                host: "example.com".to_string(),
234                scheme: "https".to_string(),
235                headers,
236                query_params: query,
237                body: Bytes::from_static(b"req"),
238                remote_addr: "10.0.0.5:44321".to_string(),
239                protocol: Protocol::Http1,
240            },
241            response: GatewayResponse {
242                status_code: 200,
243                headers: HashMap::new(),
244                body: Bytes::from_static(b"hello"),
245                stream: None,
246            },
247            message,
248            errors: Vec::new(),
249        }
250    }
251
252    #[test]
253    fn test_default_entry() {
254        let e = build_entry(&ctx(), None, false, false);
255        assert_eq!(e["request"]["method"], "GET");
256        assert_eq!(e["request"]["uri"], "/api/items?q=x");
257        assert_eq!(e["request"]["size"], 3);
258        assert_eq!(e["response"]["status"], 200);
259        assert_eq!(e["response"]["size"], 5);
260        assert_eq!(e["client_ip"], "10.0.0.5");
261        assert_eq!(e["consumer"], "alice");
262        assert!(e.get("body").is_none());
263    }
264
265    #[test]
266    fn test_default_entry_with_bodies() {
267        let e = build_entry(&ctx(), None, true, true);
268        assert_eq!(e["request"]["body"], "req");
269        assert_eq!(e["response"]["body"], "hello");
270    }
271
272    #[test]
273    fn test_custom_log_format() {
274        let mut config = HashMap::new();
275        config.insert(
276            "log_format".to_string(),
277            json!({
278                "who": "$consumer_name@$remote_addr",
279                "path": "$uri",
280                "code": "$status",
281                "const": 7,
282            }),
283        );
284        let fmt = parse_log_format(&config).unwrap().unwrap();
285        let e = build_entry(&ctx(), Some(&fmt), false, false);
286        assert_eq!(e["who"], "alice@10.0.0.5");
287        assert_eq!(e["path"], "/api/items");
288        assert_eq!(e["code"], "200");
289        assert_eq!(e["const"], 7);
290    }
291
292    #[test]
293    fn test_custom_log_format_superset_template_and_legacy_dollar() {
294        // `log_format` values must render both the new `{{...}}` template
295        // syntax and the legacy `$var` syntax in the same value.
296        let mut config = HashMap::new();
297        config.insert(
298            "log_format".to_string(),
299            json!({ "combo": "{{request.method}} $uri" }),
300        );
301        let fmt = parse_log_format(&config).unwrap().unwrap();
302        let e = build_entry(&ctx(), Some(&fmt), false, false);
303        assert_eq!(e["combo"], "GET /api/items");
304    }
305
306    #[test]
307    fn test_parse_log_format() {
308        let mut config = HashMap::new();
309        assert!(parse_log_format(&config).unwrap().is_none());
310        config.insert("log_format".to_string(), json!({ "a": "$uri" }));
311        assert!(parse_log_format(&config).unwrap().is_some());
312        config.insert("log_format".to_string(), json!("not an object"));
313        assert!(parse_log_format(&config).is_err());
314        config.insert("log_format".to_string(), json!({ "a": { "nested": 1 } }));
315        assert!(parse_log_format(&config).is_err());
316    }
317
318    fn fmt(entries: &[(&str, &str)]) -> LogFormat {
319        entries
320            .iter()
321            .map(|(k, v)| {
322                let (t, _) = Template::parse(v);
323                (k.to_string(), LogFormatValue::Template(t))
324            })
325            .collect()
326    }
327
328    /// A custom format that never mentions the body is the case worth
329    /// unblocking: a policy of `upstream -> logger -> client` is ordinary, and
330    /// today every one of them is forced to buffer.
331    #[test]
332    fn test_body_free_log_format_does_not_read_the_response_body() {
333        let f = fmt(&[
334            ("path", "{{request.path}}"),
335            ("status", "{{response.status}}"),
336        ]);
337        assert!(!reads_response_body(Some(&f), false));
338    }
339
340    /// Both spellings of a body reference must be caught.
341    #[test]
342    fn test_log_format_referencing_the_body_reads_it() {
343        assert!(reads_response_body(
344            Some(&fmt(&[("b", "{{response.body}}")])),
345            false
346        ));
347        assert!(reads_response_body(
348            Some(&fmt(&[("b", "$resp_body")])),
349            false
350        ));
351    }
352
353    /// With no `log_format` the logger falls through to the default entry,
354    /// which always records `size: ctx.response.body.len()`. Streaming that
355    /// would silently log 0, so it must keep buffering.
356    #[test]
357    fn test_absent_log_format_reads_the_response_body() {
358        assert!(reads_response_body(None, false));
359    }
360
361    /// An explicit request for the body always reads it, whatever the format.
362    #[test]
363    fn test_include_resp_body_reads_the_response_body() {
364        let f = fmt(&[("path", "{{request.path}}")]);
365        assert!(reads_response_body(Some(&f), true));
366    }
367}
featherbit/plugins/util/log_entry.rs

featherbit/plugins/util/
log_entry.rs
