diff --git a/Cargo.lock b/Cargo.lock index 301c54d..e5d701a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1715,6 +1715,7 @@ name = "otlp-demo" version = "0.9.0" dependencies = [ "colored", + "liblogjet", "logjet", "lz4_flex", "opentelemetry-proto", diff --git a/demo/Cargo.toml b/demo/Cargo.toml index ede1802..60cebcc 100644 --- a/demo/Cargo.toml +++ b/demo/Cargo.toml @@ -4,8 +4,13 @@ version.workspace = true edition.workspace = true license.workspace = true +[[bin]] +name = "benchmark-clib" +path = "benchmark-clib/main.rs" + [dependencies] colored = "3" +liblogjet = { path = "../liblogjet" } logjet = { path = ".." } lz4_flex = { version = "0.11", default-features = false, features = ["std"] } opentelemetry-proto = { version = "0.31", features = ["gen-tonic", "logs", "metrics", "trace"] } diff --git a/demo/benchmark-clib/README.md b/demo/benchmark-clib/README.md new file mode 100644 index 0000000..712e3c5 --- /dev/null +++ b/demo/benchmark-clib/README.md @@ -0,0 +1,113 @@ +# C-API Benchmark (Evidence) + +Decomposes the per-record cost of writing OTEL records through the `liblogjet` +C API (`log_record()` / `lj_logger_log`): the per-connection path is slow, and +this demo shows where the time goes. + +Reference: [`demo/cpp-shared-lib`](../cpp-shared-lib) + +## What it measures + +The driver prints one table per transport (OTLP/gRPC, and OTLP/HTTP when an HTTP +endpoint is given). Each table times these phases with real numbers (mean, p50, +p95, p99, min, max) plus an `index` column — the improvement factor +`per-connection mean / row mean` (baseline = that transport's per-connection; the +`logjet file` row's index is a no-network reference floor): + +1. **logjet file (`LogjetWriter::push`)** — appending one record straight to a + `.logjet` file. No network. Isolates the storage/format layer (gRPC table only). +2. **backend (per-connection)** — one `lj_logger_log()` send to `ljd`. The slow + path: a fresh connection per record. +3. **backend (reuse)** — one `lj_logger_log_reuse()` send, reusing a persistent + gRPC channel / HTTP keep-alive connection (Tickets 1, 4). +4. **backend (batch=N)** — `lj_logger_log_batch()` sending N records in one request + over the reused connection (Tickets 2, 4). Reported per-record amortized. +5. **backend (async enqueue)** — `lj_logger_log_async()` hands the send to a + background runtime and returns immediately (Tickets 3, 4). The row is the + caller-thread enqueue cost; the demo then calls `lj_logger_flush()` and prints + the async error/dropped counters. + +This makes the finding explicit: the file write is cheap (µs); the per-connection +backend send is the expensive part; connection reuse helps, batching brings the +per-record cost down toward the file-write cost, and async removes the network +round-trip from the caller thread entirely. HTTP reuse uses a keep-alive +connection pool (HTTP/1.1 can't multiplex, so concurrency uses several pooled +connections, bounded by backpressure). + +## Columns (in plain terms) + +Each number is measured over the messages sent in that row. Times auto-scale: +`ns` < `us` < `ms` < `s` (smaller is faster). + +- **calls** — how many log messages this row sent. +- **total** — all the per-message times added together (how long the row took). +- **mean** — the average time for one message. +- **p50** — the middle time: half the messages were faster, half slower (median). +- **p95** — almost-worst: only about 5 of every 100 messages were slower (95th percentile). +- **p99** — worst cases: only about 1 of every 100 messages was slower (99th percentile / the occasional hiccup). +- **min** — the single fastest message. +- **max** — the single slowest message (worst hiccup). +- **index** — how many times faster this row is than the slow `per-connection` row. `1.0x` = the baseline, `2.0x` = twice as fast, `48x` = forty-eight times faster. + +## Notes (in plain terms) + +- **index baseline** — every row is compared to the slow original way (a brand-new + connection for every single message). The `logjet file` row uses no network, so + it isn't a fair race — treat its index as "the fastest anything could ever be," + not a real speed-up. +- **batch row** — batching sends many messages in one shipment, so the row shows the + cost *per message* (one shipment's time split across its messages). The note also + prints how long one whole shipment actually took. +- **async row** — "async" hands the message off and carries on without waiting for + the network, so the number is just the tiny hand-off cost. The note also prints + how long we waited at the end for everything to finish (**flush**), how many + **failed** to send, and how many were **thrown away** because messages were + produced faster than the network could send them (a safety valve). +- **reuse first/cold call** — the first `reuse` message opens the connection once + (so it's slower); every message after that reuses it. + +## Async backpressure + +`lj_logger_log_async` never blocks the caller. Outstanding sends are bounded by a +backpressure policy set via `lj_logger_set_backpressure(logger, model, capacity)`: + +- `LJ_BACKPRESSURE_UNBOUNDED` — spawn every send (risk: memory under load). +- `LJ_BACKPRESSURE_DROP` — bounded to `capacity` in-flight; drop + count when full. +- `LJ_BACKPRESSURE_BLOCK` — bounded; block the caller until a slot frees. + +Default is `DROP` with capacity `1024`. Observe behavior with +`lj_logger_async_errors`, `lj_logger_async_dropped`, and `lj_logger_async_inflight`, +and drain in-flight sends with `lj_logger_flush(logger, timeout_ms)` (also done +on `lj_logger_free`). + +The driver is Rust but calls the exported C ABI symbols of `liblogjet` — the +same functions a C/C++ caller exercises through the shared library — while also +linking the `logjet` crate directly for the file row. + +## Run + +From this directory: + +```bash +./run-demo.sh # 1000 records per phase, batch=100 (defaults) +./run-demo.sh 5000 # custom record count +./run-demo.sh 1000 50 # low-mem batch size +./run-demo.sh 1000 1000 # hi-mem batch size +``` + +Arguments are `./run-demo.sh [count] [batch_size]`. The batch size is the number +of records sent per `lj_logger_log_batch()` call (the caller controls it); change +it to see how the per-record amortized cost in the `batch=N` row moves. + +The script builds `ljd`, `liblogjet`, and the driver, starts two file-backed +`ljd` instances (OTLP/gRPC on `127.0.0.1:4317`, OTLP/HTTP on `127.0.0.1:4318`), +runs the benchmark (gRPC table then HTTP table), and stops both. + +The driver itself takes `benchmark-clib +[http_endpoint]`; the HTTP table is printed only when an HTTP endpoint is given. + +## Extending + +Reuse (Ticket 1), batching (Ticket 2), async (Ticket 3), and HTTP keep-alive +(Ticket 4) rows are in place. When further ABI lands, add a phase that calls the +new symbol and a row to the table; the harness is structured for it. diff --git a/demo/benchmark-clib/ljd-http.conf b/demo/benchmark-clib/ljd-http.conf new file mode 100644 index 0000000..27d6d2a --- /dev/null +++ b/demo/benchmark-clib/ljd-http.conf @@ -0,0 +1,8 @@ +output: file +file.path: ./logs +file.size: 1048576 +file.name: benchmark-clib-http.logjet +ingest.protocol: otlp-http +ingest.listen: 127.0.0.1:4318 +ingest.max-clients: 2048 +replay.listen: 127.0.0.1:7003 diff --git a/demo/benchmark-clib/ljd.conf b/demo/benchmark-clib/ljd.conf new file mode 100644 index 0000000..b6eb419 --- /dev/null +++ b/demo/benchmark-clib/ljd.conf @@ -0,0 +1,6 @@ +output: file +file.path: ./logs +file.size: 1048576 +file.name: benchmark-clib.logjet +ingest.protocol: otlp-grpc +ingest.listen: 127.0.0.1:4317 diff --git a/demo/benchmark-clib/main.rs b/demo/benchmark-clib/main.rs new file mode 100644 index 0000000..46890be --- /dev/null +++ b/demo/benchmark-clib/main.rs @@ -0,0 +1,448 @@ +//! Evidence benchmark for the liblogjet C API. +//! +//! Decomposes the per-record cost into: +//! 1. writing one record to a `.logjet` file (storage format, no network) +//! 2. sending one record to the OTEL backend via the C API (`lj_logger_log`) +//! 3. sending one record to the OTEL backend reusing the connection +//! (`lj_logger_log_reuse`) +//! +//! It reproduces the slow per-connection path and shows where the per-record +//! time goes. +//! +//! The "file" row links the `logjet` crate directly; the "backend" rows call +//! the exported C ABI symbols of `liblogjet` (the same code a C/C++ caller +//! exercises through the shared library). + +use std::ffi::{CStr, CString, c_char}; +use std::fs::File; +use std::io::{BufWriter, Write}; +use std::ptr; +use std::time::{Instant, SystemTime, UNIX_EPOCH}; + +use liblogjet::{ + LjAttribute, LjLogRecord, lj_error_message, lj_logger, lj_logger_async_dropped, lj_logger_async_errors, lj_logger_flush, lj_logger_free, + lj_logger_log, lj_logger_log_async, lj_logger_log_batch, lj_logger_log_reuse, lj_logger_new_grpc, lj_logger_new_http, lj_logger_set_backpressure, +}; +use logjet::{LogjetWriter, RecordType}; + +const LJ_ATTR_STRING: i32 = 0; +const LJ_BACKPRESSURE_BLOCK: i32 = 2; +const HTTP_ASYNC_CAPACITY: usize = 64; +const SEVERITY_INFO: i32 = 9; +const TIMEOUT_MS: u64 = 2000; +const PAYLOAD_LEN: usize = 200; + +type LogFn = unsafe extern "C" fn(*mut lj_logger, *const LjLogRecord) -> bool; +type NewFn = unsafe extern "C" fn(*const c_char, *const c_char, u64) -> *mut lj_logger; + +struct Stats { + count: usize, + total: f64, + mean: f64, + p50: f64, + p95: f64, + p99: f64, + min: f64, + max: f64, +} + +fn main() { + let mut args = std::env::args().skip(1); + let endpoint = args.next().unwrap_or_else(|| "127.0.0.1:4317".to_string()); + let count: usize = args.next().and_then(|value| value.parse().ok()).filter(|n| *n > 0).unwrap_or(1000); + let batch_size: usize = args.next().and_then(|value| value.parse().ok()).filter(|n| *n > 0).unwrap_or(100); + let http_endpoint = args.next().filter(|value| !value.is_empty()); + + println!("benchmark-clib: {count} records per phase, batch={batch_size}, gRPC endpoint {endpoint}"); + match &http_endpoint { + Some(http) => println!("HTTP endpoint {http}\n"), + None => println!("(HTTP phases skipped; pass an HTTP endpoint as the 4th argument)\n"), + } + + let file_samples = match run_file_phase(count) { + Ok(samples) => samples, + Err(err) => { + eprintln!("logjet file phase failed: {err}"); + std::process::exit(1); + } + }; + + let endpoint_c = CString::new(endpoint.as_str()).expect("endpoint has interior NUL"); + let service_c = CString::new("benchmark-clib").expect("service name"); + let body_c = CString::new("benchmark log record body from benchmark-clib evidence run").expect("body"); + + let mut keepalive: Vec = Vec::new(); + let mut attrs: Vec = Vec::new(); + for (key, value) in [("appliance.kind", "benchmark"), ("character", "Bender"), ("location", "Planet Express")] { + let key_c = CString::new(key).expect("attr key"); + let value_c = CString::new(value).expect("attr value"); + attrs.push(LjAttribute { key: key_c.as_ptr(), value: value_c.as_ptr(), value_type: LJ_ATTR_STRING }); + keepalive.push(key_c); + keepalive.push(value_c); + } + + let mut record = LjLogRecord { + timestamp_unix_ns: 0, + severity_number: SEVERITY_INFO, + severity_text: ptr::null(), + body: body_c.as_ptr(), + attributes: attrs.as_ptr(), + attributes_len: attrs.len(), + event_name: ptr::null(), + service_name: ptr::null(), + scope_name: ptr::null(), + resource_attrs: ptr::null(), + resource_attrs_len: 0, + scope_attrs: ptr::null(), + scope_attrs_len: 0, + }; + + let file_stats = summarize(file_samples); + + run_and_print_transport("gRPC", lj_logger_new_grpc, &endpoint_c, &endpoint, &service_c, &mut record, count, batch_size, Some(&file_stats)); + + if let Some(http) = http_endpoint { + let http_c = CString::new(http.as_str()).expect("http endpoint has interior NUL"); + run_and_print_transport("HTTP", lj_logger_new_http, &http_c, &http, &service_c, &mut record, count, batch_size, None); + } + + print_legend(); +} + +fn print_legend() { + println!("Columns:"); + println!(" calls how many log messages this test sent"); + println!(" total all the per-message times added together"); + println!(" mean average time for one message"); + println!(" p50 middle time: half the messages were faster, half slower (median)"); + println!(" p95 almost-worst: only ~5 of 100 messages were slower (95th percentile)"); + println!(" p99 worst cases: only ~1 of 100 messages was slower (99th percentile)"); + println!(" min the single fastest message"); + println!(" max the single slowest message (worst hiccup)"); + println!(" index how many times faster than per-connection (1.0x = baseline; higher is better)"); + println!("Units: ns < us < ms < s (smaller is faster)."); +} + +#[allow(clippy::too_many_arguments)] +fn run_and_print_transport( + proto: &str, new_fn: NewFn, endpoint: &CStr, endpoint_str: &str, service: &CStr, record: &mut LjLogRecord, count: usize, batch_size: usize, + file_stats: Option<&Stats>, +) { + let per_connection = match unsafe { run_backend_phase(endpoint, service, record, count, new_fn, lj_logger_log) } { + Ok(result) => result, + Err(err) => { + eprintln!("{proto} per-connection phase failed: {err}"); + eprintln!("is ljd listening on {endpoint_str}? start it with run-demo.sh"); + std::process::exit(1); + } + }; + let reuse = match unsafe { run_backend_phase(endpoint, service, record, count, new_fn, lj_logger_log_reuse) } { + Ok(result) => result, + Err(err) => { + eprintln!("{proto} reuse phase failed: {err}"); + std::process::exit(1); + } + }; + let batch = match unsafe { run_batch_phase(endpoint, service, record, count, batch_size, new_fn) } { + Ok(result) => result, + Err(err) => { + eprintln!("{proto} batch phase failed: {err}"); + std::process::exit(1); + } + }; + let async_backpressure = if proto == "HTTP" { Some((LJ_BACKPRESSURE_BLOCK, HTTP_ASYNC_CAPACITY)) } else { None }; + let async_phase = match unsafe { run_async_phase(endpoint, service, record, count, new_fn, async_backpressure) } { + Ok(result) => result, + Err(err) => { + eprintln!("{proto} async phase failed: {err}"); + std::process::exit(1); + } + }; + + let per_connection_stats = summarize(per_connection.samples); + let reuse_cold = reuse.cold_first; + let reuse_stats = summarize(reuse.samples); + let raw_batch_mean = batch.raw_batch_mean; + let batch_stats = summarize(batch.samples); + let async_stats = summarize(async_phase.samples); + + let pc_label = format!("backend OTLP/{proto} (per-connection)"); + let reuse_label = format!("backend OTLP/{proto} (reuse)"); + let batch_label = format!("backend OTLP/{proto} (batch={batch_size})"); + let async_label = format!("backend OTLP/{proto} (async enqueue)"); + + let baseline = per_connection_stats.mean; + let mut rows: Vec<(&str, &Stats)> = Vec::new(); + if let Some(file_stats) = file_stats { + rows.push(("logjet file (LogjetWriter::push)", file_stats)); + } + rows.push((pc_label.as_str(), &per_connection_stats)); + rows.push((reuse_label.as_str(), &reuse_stats)); + rows.push((batch_label.as_str(), &batch_stats)); + rows.push((async_label.as_str(), &async_stats)); + + println!("== OTLP/{proto} =="); + print_table(&rows, baseline); + println!(); + println!("index = how many times faster than per-connection (baseline 1.0x; higher is better)"); + if file_stats.is_some() { + println!("note: 'logjet file' has no network, so its index is a best-case floor, not a real speed-up"); + } + println!( + "note: 'batch' shows time per message ({batch_size} sent in one shipment, split across them); one full shipment took {} on average", + fmt_dur(raw_batch_mean) + ); + println!( + "note: 'async' is only the hand-off cost (we don't wait for the network); waited {} at the end for all to finish; {} failed to send, {} thrown away (sending slower than produced)", + fmt_dur(async_phase.flush_ns), + async_phase.errors, + async_phase.dropped, + ); + println!("note: the first 'reuse' message opens the connection once ({}); every message after reuses it", fmt_dur(reuse_cold)); + println!(); +} + +fn run_file_phase(count: usize) -> std::io::Result> { + let path = std::env::temp_dir().join("logjet-benchmark-clib.logjet"); + let file = File::create(&path)?; + let mut writer = LogjetWriter::new(BufWriter::new(file)); + let payload = vec![0xABu8; PAYLOAD_LEN]; + let base_ts = 1_700_000_000_000_000_000u64; + + let mut samples = Vec::with_capacity(count); + for index in 0..count { + let seq = index as u64 + 1; + let ts = base_ts + index as u64 * 1_000; + let start = Instant::now(); + writer.push(RecordType::Logs, seq, ts, &payload).map_err(|err| std::io::Error::other(err.to_string()))?; + samples.push(start.elapsed().as_nanos()); + } + + let mut inner = writer.into_inner().map_err(|err| std::io::Error::other(err.to_string()))?; + inner.flush()?; + let _ = std::fs::remove_file(&path); + Ok(samples) +} + +struct BackendResult { + samples: Vec, + cold_first: f64, +} + +unsafe fn run_backend_phase( + endpoint: &CStr, service: &CStr, record: &mut LjLogRecord, count: usize, new_fn: NewFn, log_fn: LogFn, +) -> Result { + let logger = unsafe { new_fn(endpoint.as_ptr(), service.as_ptr(), TIMEOUT_MS) }; + if logger.is_null() { + return Err(last_error()); + } + + let mut samples = Vec::with_capacity(count); + let mut error: Option = None; + for _ in 0..count { + record.timestamp_unix_ns = now_unix_ns(); + let start = Instant::now(); + let ok = unsafe { log_fn(logger, record as *const LjLogRecord) }; + let elapsed = start.elapsed().as_nanos(); + if !ok { + error = Some(last_error()); + break; + } + samples.push(elapsed); + } + + unsafe { lj_logger_free(logger) }; + + if let Some(err) = error { + return Err(err); + } + + let cold_first = samples.first().copied().unwrap_or(0) as f64; + Ok(BackendResult { samples, cold_first }) +} + +struct BatchResult { + samples: Vec, + raw_batch_mean: f64, +} + +fn clone_record(template: &LjLogRecord) -> LjLogRecord { + LjLogRecord { + timestamp_unix_ns: template.timestamp_unix_ns, + severity_number: template.severity_number, + severity_text: template.severity_text, + body: template.body, + attributes: template.attributes, + attributes_len: template.attributes_len, + event_name: template.event_name, + service_name: template.service_name, + scope_name: template.scope_name, + resource_attrs: template.resource_attrs, + resource_attrs_len: template.resource_attrs_len, + scope_attrs: template.scope_attrs, + scope_attrs_len: template.scope_attrs_len, + } +} + +unsafe fn run_batch_phase( + endpoint: &CStr, service: &CStr, template: &LjLogRecord, count: usize, batch_size: usize, new_fn: NewFn, +) -> Result { + let logger = unsafe { new_fn(endpoint.as_ptr(), service.as_ptr(), TIMEOUT_MS) }; + if logger.is_null() { + return Err(last_error()); + } + + let mut batch: Vec = (0..batch_size).map(|_| clone_record(template)).collect(); + let mut samples = Vec::with_capacity(count); + let mut total_batch_ns: u128 = 0; + let mut batch_calls: u128 = 0; + let mut sent = 0; + let mut error: Option = None; + + while sent < count { + let this = batch_size.min(count - sent); + let now = now_unix_ns(); + for entry in batch[..this].iter_mut() { + entry.timestamp_unix_ns = now; + } + let start = Instant::now(); + let ok = unsafe { lj_logger_log_batch(logger, batch.as_ptr(), this) }; + let elapsed = start.elapsed().as_nanos(); + if !ok { + error = Some(last_error()); + break; + } + total_batch_ns += elapsed; + batch_calls += 1; + let per_record = elapsed / this as u128; + for _ in 0..this { + samples.push(per_record); + } + sent += this; + } + + unsafe { lj_logger_free(logger) }; + + if let Some(err) = error { + return Err(err); + } + + let raw_batch_mean = if batch_calls > 0 { total_batch_ns as f64 / batch_calls as f64 } else { 0.0 }; + Ok(BatchResult { samples, raw_batch_mean }) +} + +struct AsyncResult { + samples: Vec, + flush_ns: f64, + errors: u64, + dropped: u64, +} + +unsafe fn run_async_phase( + endpoint: &CStr, service: &CStr, template: &LjLogRecord, count: usize, new_fn: NewFn, backpressure: Option<(i32, usize)>, +) -> Result { + let logger = unsafe { new_fn(endpoint.as_ptr(), service.as_ptr(), TIMEOUT_MS) }; + if logger.is_null() { + return Err(last_error()); + } + if let Some((model, capacity)) = backpressure { + unsafe { lj_logger_set_backpressure(logger, model, capacity) }; + } + + let mut record = clone_record(template); + let mut samples = Vec::with_capacity(count); + for _ in 0..count { + record.timestamp_unix_ns = now_unix_ns(); + let start = Instant::now(); + let ok = unsafe { lj_logger_log_async(logger, &record as *const LjLogRecord) }; + let elapsed = start.elapsed().as_nanos(); + if !ok { + let err = last_error(); + unsafe { lj_logger_free(logger) }; + return Err(err); + } + samples.push(elapsed); + } + + let flush_start = Instant::now(); + unsafe { lj_logger_flush(logger, 60_000) }; + let flush_ns = flush_start.elapsed().as_nanos() as f64; + + let errors = unsafe { lj_logger_async_errors(logger) }; + let dropped = unsafe { lj_logger_async_dropped(logger) }; + + unsafe { lj_logger_free(logger) }; + Ok(AsyncResult { samples, flush_ns, errors, dropped }) +} + +fn last_error() -> String { + let ptr = lj_error_message(); + if ptr.is_null() { + return "unknown error".to_string(); + } + let message = unsafe { CStr::from_ptr(ptr) }.to_string_lossy().into_owned(); + if message.is_empty() { "unknown error".to_string() } else { message } +} + +fn now_unix_ns() -> u64 { + SystemTime::now().duration_since(UNIX_EPOCH).unwrap_or_default().as_nanos() as u64 +} + +fn summarize(mut samples: Vec) -> Stats { + assert!(!samples.is_empty(), "no samples collected"); + samples.sort_unstable(); + let count = samples.len(); + let total: u128 = samples.iter().sum(); + let percentile = |pct: f64| { + let rank = ((pct / 100.0) * count as f64).ceil() as usize; + let index = rank.saturating_sub(1).min(count - 1); + samples[index] as f64 + }; + Stats { + count, + total: total as f64, + mean: total as f64 / count as f64, + p50: percentile(50.0), + p95: percentile(95.0), + p99: percentile(99.0), + min: samples[0] as f64, + max: samples[count - 1] as f64, + } +} + +fn fmt_dur(ns: f64) -> String { + if ns >= 1e9 { + format!("{:.2} s", ns / 1e9) + } else if ns >= 1e6 { + format!("{:.2} ms", ns / 1e6) + } else if ns >= 1e3 { + format!("{:.2} us", ns / 1e3) + } else { + format!("{ns:.0} ns") + } +} + +fn print_table(rows: &[(&str, &Stats)], baseline: f64) { + println!( + "{:<36} {:>7} {:>11} {:>11} {:>11} {:>11} {:>11} {:>11} {:>11} {:>9}", + "path", "calls", "total", "mean", "p50", "p95", "p99", "min", "max", "index" + ); + println!("{}", "-".repeat(36 + 7 + 11 * 7 + 8 + 10)); + for (name, stats) in rows { + let index = if stats.mean > 0.0 && baseline > 0.0 { format!("{:.1}x", baseline / stats.mean) } else { "-".to_string() }; + println!( + "{:<36} {:>7} {:>11} {:>11} {:>11} {:>11} {:>11} {:>11} {:>11} {:>9}", + name, + stats.count, + fmt_dur(stats.total), + fmt_dur(stats.mean), + fmt_dur(stats.p50), + fmt_dur(stats.p95), + fmt_dur(stats.p99), + fmt_dur(stats.min), + fmt_dur(stats.max), + index, + ); + } + let _ = std::io::stdout().flush(); +} diff --git a/demo/benchmark-clib/run-demo.sh b/demo/benchmark-clib/run-demo.sh new file mode 100755 index 0000000..b282e81 --- /dev/null +++ b/demo/benchmark-clib/run-demo.sh @@ -0,0 +1,43 @@ +#!/bin/sh +set -eu + +SCRIPT_DIR=$(CDPATH= cd -- "$(dirname -- "$0")" && pwd) +ROOT_DIR=$(CDPATH= cd -- "$SCRIPT_DIR/../.." && pwd) +TARGET_DIR="$ROOT_DIR/target/debug" +LJD="$TARGET_DIR/ljd" +BENCH="$TARGET_DIR/benchmark-clib" +CONFIG="$SCRIPT_DIR/ljd.conf" +CONFIG_HTTP="$SCRIPT_DIR/ljd-http.conf" +ENDPOINT="127.0.0.1:4317" +ENDPOINT_HTTP="127.0.0.1:4318" +COUNT="${1:-1000}" +BATCH_SIZE="${2:-100}" + +echo "building ljd, liblogjet, and the benchmark driver" +cargo build -p ljd -p liblogjet -p otlp-demo --bin benchmark-clib + +mkdir -p "$SCRIPT_DIR/logs" + +# Run from the demo dir so ljd resolves the relative file.path (./logs), and start +# ljd directly (no subshell) so the trap can actually kill it. +cd "$SCRIPT_DIR" + +echo "starting ljd with file-backed OTLP/gRPC ingest on $ENDPOINT" +"$LJD" --config "$CONFIG" serve & +LJD_PID=$! + +echo "starting ljd with file-backed OTLP/HTTP ingest on $ENDPOINT_HTTP" +"$LJD" --config "$CONFIG_HTTP" serve & +LJD_HTTP_PID=$! + +cleanup() { + kill "${LJD_PID:-}" 2>/dev/null || true + kill "${LJD_HTTP_PID:-}" 2>/dev/null || true +} +trap cleanup EXIT INT TERM + +sleep 1 + +echo "running benchmark ($COUNT records per phase, batch=$BATCH_SIZE)" +echo +"$BENCH" "$ENDPOINT" "$COUNT" "$BATCH_SIZE" "$ENDPOINT_HTTP" diff --git a/demo/cpp-shared-lib/README.md b/demo/cpp-shared-lib/README.md index e7e8bde..f73ca0c 100644 --- a/demo/cpp-shared-lib/README.md +++ b/demo/cpp-shared-lib/README.md @@ -1,11 +1,12 @@ # C++ Shared Library Demo This demo shows one C++ process loading a Rust shared library and sending OTLP -logs into `ljd` over gRPC. +logs into `ljd` over both gRPC and HTTP, exercising the per-connection, reuse, +batch, and async send paths. The path is: -`C++ appliance -> liblogjet.so -> OTLP/gRPC -> ljd -> .logjet file -> ljx view` +`C++ appliance -> liblogjet.so -> OTLP/gRPC or OTLP/HTTP -> ljd -> .logjet file -> ljx view` ## Build First @@ -23,7 +24,8 @@ example on demand. From this directory: ```bash -./run-demo.sh +./run-demo.sh # 25 records per phase (default) +./run-demo.sh 100 # custom record count ``` ## What It Does @@ -31,15 +33,19 @@ From this directory: The script: 1. builds the example C++ logger -2. starts file-backed `ljd` on `127.0.0.1:4317` +2. starts two file-backed `ljd` instances: OTLP/gRPC on `127.0.0.1:4317` and OTLP/HTTP on `127.0.0.1:4318` 3. loads `liblogjet.so` through `dlopen` -4. sends 25 OTLP log records from C++ by default -5. opens `ljx view` on the resulting `./logs/cpp-demo.logjet` +4. runs the C++ logger once per transport, each exercising four send paths: + - **per-connection** (`lj_logger_log`) + - **reuse** (`lj_logger_log_reuse`) + - **batch** (`lj_logger_log_batch`, many records in one request) + - **async** (`lj_logger_log_async` with `lj_logger_set_backpressure` + `lj_logger_flush`, then prints the async counters) +5. opens `ljx view` on `./logs/cpp-demo.logjet` (gRPC), then on `./logs/cpp-demo-http.logjet` (HTTP) ## Notes -- the library now supports both OTLP/HTTP and OTLP/gRPC constructors -- this demo specifically uses OTLP/gRPC +- the demo runs both OTLP/gRPC and OTLP/HTTP; the C++ source picks the constructor (`lj_logger_new_grpc` / `lj_logger_new_http`) from its 4th argument +- reuse/batch/async work over both transports (HTTP uses a keep-alive connection pool) - the FFI API is intentionally small: endpoint, service name, timestamp, severity, message body, and string attributes - those key/value pairs become OTLP `LogRecord.attributes`, which is the standard OTel metadata field for log records - if the appliance already has JSON metadata, the better long-term shape is to flatten that JSON into separate attributes where possible; a raw JSON blob can still be sent as one string attribute when needed diff --git a/demo/cpp-shared-lib/cpp-logger.cpp b/demo/cpp-shared-lib/cpp-logger.cpp index 11e31bb..8901d4c 100644 --- a/demo/cpp-shared-lib/cpp-logger.cpp +++ b/demo/cpp-shared-lib/cpp-logger.cpp @@ -7,7 +7,6 @@ #include #include #include -#include #include namespace { @@ -18,6 +17,10 @@ using new_http_fn = lj_logger *(*)(const char *, const char *, std::uint64_t); using new_grpc_fn = lj_logger *(*)(const char *, const char *, std::uint64_t); using free_fn = void (*)(lj_logger *); using log_fn = bool (*)(lj_logger *, const lj_log_record *); +using batch_fn = bool (*)(lj_logger *, const lj_log_record *, std::size_t); +using set_bp_fn = bool (*)(lj_logger *, std::int32_t, std::size_t); +using flush_fn = bool (*)(lj_logger *, std::uint64_t); +using counter_fn = std::uint64_t (*)(lj_logger *); struct api { version_fn version; @@ -26,15 +29,32 @@ struct api { new_grpc_fn new_grpc; free_fn free_logger; log_fn log_record; + log_fn log_reuse; + batch_fn log_batch; + log_fn log_async; + set_bp_fn set_backpressure; + flush_fn flush; + counter_fn async_errors; + counter_fn async_dropped; + counter_fn async_inflight; }; -std::int32_t info_severity() { - return LJ_SEVERITY_INFO; -} +const std::vector kQuotes = { + "Bender promised a classy fun park financed mostly by blackjack.", + "Fry pressed the glowing button because hesitation felt off-brand.", + "Leela requested a routine delivery and got stylish chaos instead.", + "The Professor called this outage a perfectly normal science moment.", + "Zoidberg celebrated because nobody had blamed him yet.", + "Hermes filed the disaster under efficient bureaucratic progress.", + "Amy said the ship felt stable, which worried everyone instantly.", + "Nibbler stared into the void like it owed him money.", + "Scruffy fixed the panel and resumed mopping without commentary.", + "Calculon demanded better lighting for the emergency landing.", +}; -const char *pick(const std::vector &values, std::mt19937 &rng) { - std::uniform_int_distribution dist(0, values.size() - 1); - return values[dist(rng)]; +std::string pick_message(std::mt19937 &rng) { + std::uniform_int_distribution dist(0, kQuotes.size() - 1); + return kQuotes[dist(rng)]; } std::uint64_t unix_time_nanos() { @@ -61,15 +81,47 @@ api load_api(void *handle) { reinterpret_cast(must_symbol(handle, "lj_logger_new_grpc")), reinterpret_cast(must_symbol(handle, "lj_logger_free")), reinterpret_cast(must_symbol(handle, "lj_logger_log")), + reinterpret_cast(must_symbol(handle, "lj_logger_log_reuse")), + reinterpret_cast(must_symbol(handle, "lj_logger_log_batch")), + reinterpret_cast(must_symbol(handle, "lj_logger_log_async")), + reinterpret_cast(must_symbol(handle, "lj_logger_set_backpressure")), + reinterpret_cast(must_symbol(handle, "lj_logger_flush")), + reinterpret_cast(must_symbol(handle, "lj_logger_async_errors")), + reinterpret_cast(must_symbol(handle, "lj_logger_async_dropped")), + reinterpret_cast(must_symbol(handle, "lj_logger_async_inflight")), }; } +// Sends one record one at a time via the given function (log / reuse / async). +// Safe to use local strings: the library reads them before the call returns +// (async builds its request synchronously, then sends in the background). +void send_one_at_a_time(const api &lib, lj_logger *logger, log_fn send, const char *phase, int count, std::mt19937 &rng) { + int ok = 0; + for (int i = 0; i < count; ++i) { + const std::string message = pick_message(rng); + const lj_attribute attrs[] = { + {"appliance.kind", "cpp-demo"}, + {"phase", phase}, + }; + const lj_log_record record{ + unix_time_nanos(), LJ_SEVERITY_INFO, "INFO", message.c_str(), attrs, sizeof(attrs) / sizeof(attrs[0]), + }; + if (send(logger, &record)) { + ++ok; + } else { + std::cerr << " " << phase << " send failed: " << lib.error_message() << "\n"; + } + } + std::cout << " [" << phase << "] accepted " << ok << "/" << count << "\n"; +} + } // namespace int main(int argc, char **argv) { const std::string so_path = argc > 1 ? argv[1] : "./liblogjet.so"; const std::string endpoint = argc > 2 ? argv[2] : "127.0.0.1:4317"; const int message_count = argc > 3 ? std::atoi(argv[3]) : 25; + const std::string protocol = argc > 4 ? argv[4] : "grpc"; void *handle = dlopen(so_path.c_str(), RTLD_NOW | RTLD_LOCAL); if (handle == nullptr) { @@ -78,92 +130,57 @@ int main(int argc, char **argv) { } const api lib = load_api(handle); - std::cout << "loaded liblogjet version " << lib.version() << "\n"; + std::cout << "loaded liblogjet version " << lib.version() << " (transport: " << protocol << ", endpoint: " << endpoint << ")\n"; - std::mt19937 rng(std::random_device{}()); - const std::vector characters = { - "Bender", "Fry", "Leela", "Professor Farnsworth", "Zoidberg", - "Amy", "Hermes", "Nibbler", "Scruffy", "Calculon", - }; - const std::vector locations = { - "Planet Express", "New New York", "The Moon", "Mars University", - "Robot Hell", "Slurm factory", "Omicron Persei 8", "Bender's fun park", - }; - const std::vector attractions = { - "blackjack dome", "dark matter coaster", "hooker-bot lounge", - "slurm chute", "robot petting zoo", "delivery cannon", - }; - const std::vector moods = { - "greedy", "heroic", "dramatic", "sleepy", - "chaotic", "optimistic", "hungry", "unbothered", - }; - const std::vector schemes = { - "casino expansion", "fun park launch", "delivery detour", - "robot uprising rehearsal", "slurm promotion", "budget evaporation", - }; - const std::vector quotes = { - "Bender promised a classy fun park financed mostly by blackjack.", - "Fry pressed the glowing button because hesitation felt off-brand.", - "Leela requested a routine delivery and got stylish chaos instead.", - "The Professor called this outage a perfectly normal science moment.", - "Zoidberg celebrated because nobody had blamed him yet.", - "Hermes filed the disaster under efficient bureaucratic progress.", - "Amy said the ship felt stable, which worried everyone instantly.", - "Nibbler stared into the void like it owed him money.", - "Scruffy fixed the panel and resumed mopping without commentary.", - "Calculon demanded better lighting for the emergency landing.", - "Bender unveiled a premium attraction featuring hooker-bots and bad odds.", - "The crew found a shortcut through poor planning and dark matter.", - "Mission control agreed this was still cheaper than preparation.", - "Someone ordered suspicious robot bees and called it innovation.", - "The delivery manifest now includes one crate of dramatic overreaction.", - }; - - lj_logger *logger = lib.new_grpc(endpoint.c_str(), "cpp-appliance", 2000); + lj_logger *logger = nullptr; + if (protocol == "http") { + logger = lib.new_http(endpoint.c_str(), "cpp-appliance", 2000); + } else { + logger = lib.new_grpc(endpoint.c_str(), "cpp-appliance", 2000); + } if (logger == nullptr) { - std::cerr << "lj_logger_new_grpc failed: " << lib.error_message() << "\n"; + std::cerr << "logger creation failed: " << lib.error_message() << "\n"; dlclose(handle); return 1; } - for (int index = 1; index <= message_count; ++index) { - const std::string sequence = std::to_string(index); - const std::string character = pick(characters, rng); - const std::string location = pick(locations, rng); - const std::string attraction = pick(attractions, rng); - const std::string mood = pick(moods, rng); - const std::string scheme = pick(schemes, rng); - const std::string message = - std::string(pick(quotes, rng)) + " character=" + character + " location=" + location; - const lj_attribute attributes[] = { + std::mt19937 rng(std::random_device{}()); + const int per_phase = std::max(1, message_count / 4); + + // Phase 1: per-connection (a fresh connection per record). + send_one_at_a_time(lib, logger, lib.log_record, "per-connection", per_phase, rng); + + // Phase 2: reuse (one persistent connection). + send_one_at_a_time(lib, logger, lib.log_reuse, "reuse", per_phase, rng); + + // Phase 3: batch (one request carrying many records). + { + std::vector bodies(static_cast(per_phase)); + const lj_attribute attrs[] = { {"appliance.kind", "cpp-demo"}, - {"appliance.sequence", sequence.c_str()}, - {"character", character.c_str()}, - {"location", location.c_str()}, - {"attraction", attraction.c_str()}, - {"mood", mood.c_str()}, - {"scheme", scheme.c_str()}, - }; - const lj_log_record record{ - unix_time_nanos(), - info_severity(), - "INFO", - message.c_str(), - attributes, - sizeof(attributes) / sizeof(attributes[0]), + {"phase", "batch"}, }; - - if (!lib.log_record(logger, &record)) { - std::cerr << "lj_logger_log failed: " << lib.error_message() << "\n"; - lib.free_logger(logger); - dlclose(handle); - return 1; + std::vector records; + records.reserve(static_cast(per_phase)); + for (int i = 0; i < per_phase; ++i) { + bodies[static_cast(i)] = pick_message(rng); + records.push_back(lj_log_record{ + unix_time_nanos(), LJ_SEVERITY_INFO, "INFO", bodies[static_cast(i)].c_str(), attrs, sizeof(attrs) / sizeof(attrs[0]), + }); + } + if (lib.log_batch(logger, records.data(), records.size())) { + std::cout << " [batch] sent " << records.size() << " records in one request\n"; + } else { + std::cerr << " [batch] send failed: " << lib.error_message() << "\n"; } - - std::cout << "sent: " << message << "\n"; - std::this_thread::sleep_for(std::chrono::milliseconds(20)); } + // Phase 4: async (non-blocking; bounded by backpressure, then drained). + lib.set_backpressure(logger, LJ_BACKPRESSURE_DROP, 256); + send_one_at_a_time(lib, logger, lib.log_async, "async", per_phase, rng); + lib.flush(logger, 5000); + std::cout << " [async] errors=" << lib.async_errors(logger) << " dropped=" << lib.async_dropped(logger) << " inflight=" << lib.async_inflight(logger) << "\n"; + lib.free_logger(logger); dlclose(handle); return 0; diff --git a/demo/cpp-shared-lib/ljd-http.conf b/demo/cpp-shared-lib/ljd-http.conf new file mode 100644 index 0000000..3df3fbb --- /dev/null +++ b/demo/cpp-shared-lib/ljd-http.conf @@ -0,0 +1,8 @@ +output: file +file.path: ./logs +file.size: 1048576 +file.name: cpp-demo-http.logjet +ingest.protocol: otlp-http +ingest.listen: 127.0.0.1:4318 +ingest.max-clients: 2048 +replay.listen: 127.0.0.1:7013 diff --git a/demo/cpp-shared-lib/run-demo.sh b/demo/cpp-shared-lib/run-demo.sh index 696c79c..4fd1b74 100755 --- a/demo/cpp-shared-lib/run-demo.sh +++ b/demo/cpp-shared-lib/run-demo.sh @@ -9,7 +9,9 @@ LIB_SRC="$TARGET_DIR/libliblogjet.so" LIB_DST="$SCRIPT_DIR/liblogjet.so" CPP_SRC="$SCRIPT_DIR/cpp-logger.cpp" CPP_BIN="$SCRIPT_DIR/cpp-logger" -CONFIG="$SCRIPT_DIR/ljd.conf" +CONFIG_GRPC="$SCRIPT_DIR/ljd.conf" +CONFIG_HTTP="$SCRIPT_DIR/ljd-http.conf" +COUNT="${1:-25}" for bin in "$LJD" "$LJX" "$LIB_SRC"; do if [ ! -e "$bin" ]; then @@ -31,22 +33,35 @@ ln -sf "$LIB_SRC" "$LIB_DST" echo "building C++ example" g++ -std=c++17 -Wall -Wextra -pedantic -O2 -I"$SCRIPT_DIR/../../liblogjet/include" "$CPP_SRC" -ldl -o "$CPP_BIN" -echo "starting ljd with file-backed OTLP ingest" -"$LJD" --config "$CONFIG" serve & -LJD_PID=$! +# Run from the demo dir so ljd resolves the relative file.path (./logs). +cd "$SCRIPT_DIR" + +echo "starting ljd: OTLP/gRPC on 127.0.0.1:4317 and OTLP/HTTP on 127.0.0.1:4318" +"$LJD" --config "$CONFIG_GRPC" serve & +LJD_GRPC_PID=$! +"$LJD" --config "$CONFIG_HTTP" serve & +LJD_HTTP_PID=$! cleanup() { - kill "${LJD_PID:-}" 2>/dev/null || true + kill "${LJD_GRPC_PID:-}" 2>/dev/null || true + kill "${LJD_HTTP_PID:-}" 2>/dev/null || true } - trap cleanup EXIT INT TERM sleep 1 -echo "sending logs from C++ through liblogjet.so into ljd over OTLP/gRPC" -"$CPP_BIN" "$LIB_DST" "127.0.0.1:4317" 25 +echo +echo "=== OTLP/gRPC: per-connection, reuse, batch, async ===" +"$CPP_BIN" "$LIB_DST" "127.0.0.1:4317" "$COUNT" grpc + +echo +echo "=== OTLP/HTTP: per-connection, reuse, batch, async ===" +"$CPP_BIN" "$LIB_DST" "127.0.0.1:4318" "$COUNT" http sleep 1 -echo "opening ljx view on ./logs/cpp-demo.logjet" +echo +echo "results: ./logs/cpp-demo.logjet (gRPC) and ./logs/cpp-demo-http.logjet (HTTP)" +echo "opening ljx view on the gRPC capture (quit to open the HTTP capture)" "$LJX" view "$SCRIPT_DIR/logs/cpp-demo.logjet" +"$LJX" view "$SCRIPT_DIR/logs/cpp-demo-http.logjet" diff --git a/demo/src/bin/metrics-emitter.rs b/demo/src/bin/metrics-emitter.rs index 493dc6e..351fba4 100644 --- a/demo/src/bin/metrics-emitter.rs +++ b/demo/src/bin/metrics-emitter.rs @@ -15,11 +15,8 @@ fn main() { let addr = &args[1]; let count: u64 = args.get(2).and_then(|s| s.parse().ok()).unwrap_or(20); - let endpoint = if addr.starts_with("http://") || addr.starts_with("https://") { - format!("{addr}/v1/metrics") - } else { - format!("http://{addr}/v1/metrics") - }; + let endpoint = + if addr.starts_with("http://") || addr.starts_with("https://") { format!("{addr}/v1/metrics") } else { format!("http://{addr}/v1/metrics") }; println!("metrics-emitter sending {count} batches to {endpoint}"); diff --git a/demo/src/bin/metrics-grpc-emitter.rs b/demo/src/bin/metrics-grpc-emitter.rs index abfbeda..527d62d 100644 --- a/demo/src/bin/metrics-grpc-emitter.rs +++ b/demo/src/bin/metrics-grpc-emitter.rs @@ -31,7 +31,9 @@ async fn main() -> Result<(), Box> { Ok(()) } -async fn send_batch(client: &mut MetricsServiceClient, request: ExportMetricsServiceRequest) -> Result<(), Box> { +async fn send_batch( + client: &mut MetricsServiceClient, request: ExportMetricsServiceRequest, +) -> Result<(), Box> { client.export(Request::new(request)).await?; Ok(()) } diff --git a/demo/src/bin/multi-signal-emitter.rs b/demo/src/bin/multi-signal-emitter.rs index f5fa313..c843495 100644 --- a/demo/src/bin/multi-signal-emitter.rs +++ b/demo/src/bin/multi-signal-emitter.rs @@ -15,21 +15,12 @@ fn main() { let addr = &args[1]; let count: u64 = args.get(2).and_then(|s| s.parse().ok()).unwrap_or(8); - let logs_endpoint = if addr.starts_with("http://") || addr.starts_with("https://") { - format!("{addr}/v1/logs") - } else { - format!("http://{addr}/v1/logs") - }; - let metrics_endpoint = if addr.starts_with("http://") || addr.starts_with("https://") { - format!("{addr}/v1/metrics") - } else { - format!("http://{addr}/v1/metrics") - }; - let traces_endpoint = if addr.starts_with("http://") || addr.starts_with("https://") { - format!("{addr}/v1/traces") - } else { - format!("http://{addr}/v1/traces") - }; + let logs_endpoint = + if addr.starts_with("http://") || addr.starts_with("https://") { format!("{addr}/v1/logs") } else { format!("http://{addr}/v1/logs") }; + let metrics_endpoint = + if addr.starts_with("http://") || addr.starts_with("https://") { format!("{addr}/v1/metrics") } else { format!("http://{addr}/v1/metrics") }; + let traces_endpoint = + if addr.starts_with("http://") || addr.starts_with("https://") { format!("{addr}/v1/traces") } else { format!("http://{addr}/v1/traces") }; println!("multi-signal-emitter sending {count} batches per signal (logs, metrics, traces) to {addr}"); diff --git a/demo/src/bin/traces-emitter.rs b/demo/src/bin/traces-emitter.rs index dadc277..f329e4c 100644 --- a/demo/src/bin/traces-emitter.rs +++ b/demo/src/bin/traces-emitter.rs @@ -15,11 +15,8 @@ fn main() { let addr = &args[1]; let count: u64 = args.get(2).and_then(|s| s.parse().ok()).unwrap_or(15); - let endpoint = if addr.starts_with("http://") || addr.starts_with("https://") { - format!("{addr}/v1/traces") - } else { - format!("http://{addr}/v1/traces") - }; + let endpoint = + if addr.starts_with("http://") || addr.starts_with("https://") { format!("{addr}/v1/traces") } else { format!("http://{addr}/v1/traces") }; println!("traces-emitter sending {count} batches to {endpoint}"); diff --git a/demo/src/bin/traces-grpc-emitter.rs b/demo/src/bin/traces-grpc-emitter.rs index 6a73a31..71200b2 100644 --- a/demo/src/bin/traces-grpc-emitter.rs +++ b/demo/src/bin/traces-grpc-emitter.rs @@ -31,7 +31,9 @@ async fn main() -> Result<(), Box> { Ok(()) } -async fn send_batch(client: &mut TraceServiceClient, request: ExportTraceServiceRequest) -> Result<(), Box> { +async fn send_batch( + client: &mut TraceServiceClient, request: ExportTraceServiceRequest, +) -> Result<(), Box> { client.export(Request::new(request)).await?; Ok(()) } diff --git a/demo/src/lib.rs b/demo/src/lib.rs index 0805dc4..01149da 100644 --- a/demo/src/lib.rs +++ b/demo/src/lib.rs @@ -9,14 +9,12 @@ use std::time::{Duration, SystemTime, UNIX_EPOCH}; use colored::Colorize; use opentelemetry_proto::tonic::collector::logs::v1::ExportLogsServiceRequest; use opentelemetry_proto::tonic::collector::metrics::v1::ExportMetricsServiceRequest; +use opentelemetry_proto::tonic::collector::trace::v1::ExportTraceServiceRequest; use opentelemetry_proto::tonic::common::v1::{AnyValue, InstrumentationScope, KeyValue}; use opentelemetry_proto::tonic::logs::v1::{LogRecord, ResourceLogs, ScopeLogs, SeverityNumber}; use opentelemetry_proto::tonic::metrics::v1::number_data_point::Value as DataPointValue; -use opentelemetry_proto::tonic::metrics::v1::{ - AggregationTemporality, Gauge, Metric, NumberDataPoint, ResourceMetrics, ScopeMetrics, Sum, -}; +use opentelemetry_proto::tonic::metrics::v1::{AggregationTemporality, Gauge, Metric, NumberDataPoint, ResourceMetrics, ScopeMetrics, Sum}; use opentelemetry_proto::tonic::resource::v1::Resource; -use opentelemetry_proto::tonic::collector::trace::v1::ExportTraceServiceRequest; use opentelemetry_proto::tonic::trace::v1::{ResourceSpans, ScopeSpans, Span}; use prost::Message; use rustls::pki_types::{CertificateDer, PrivateKeyDer, ServerName}; @@ -131,10 +129,7 @@ pub fn build_metrics_request(sequence: u64) -> ExportMetricsServiceRequest { let request_count = sequence * 100 + 42; let resource = Resource { - attributes: vec![ - string_attr("service.name", "metrics-demo"), - string_attr("host.name", "garage-rig"), - ], + attributes: vec![string_attr("service.name", "metrics-demo"), string_attr("host.name", "garage-rig")], dropped_attributes_count: 0, entity_refs: Vec::new(), }; @@ -185,11 +180,7 @@ pub fn build_metrics_request(sequence: u64) -> ExportMetricsServiceRequest { ExportMetricsServiceRequest { resource_metrics: vec![ResourceMetrics { resource: Some(resource), - scope_metrics: vec![ScopeMetrics { - scope: Some(scope), - metrics: vec![cpu_metric, requests_metric], - schema_url: String::new(), - }], + scope_metrics: vec![ScopeMetrics { scope: Some(scope), metrics: vec![cpu_metric, requests_metric], schema_url: String::new() }], schema_url: String::new(), }], } @@ -537,10 +528,7 @@ pub fn build_trace_request(sequence: u64) -> ExportTraceServiceRequest { ExportTraceServiceRequest { resource_spans: vec![ResourceSpans { resource: Some(Resource { - attributes: vec![ - string_attr("service.name", "traces-demo"), - string_attr("host.name", "garage-rig"), - ], + attributes: vec![string_attr("service.name", "traces-demo"), string_attr("host.name", "garage-rig")], dropped_attributes_count: 0, entity_refs: Vec::new(), }), @@ -582,10 +570,7 @@ pub fn build_trace_request(sequence: u64) -> ExportTraceServiceRequest { kind: 3, start_time_unix_nano: base_nanos + sequence * 1_000_000 + 2_000_000, end_time_unix_nano: base_nanos + sequence * 1_000_000 + ((sequence % 50 + 1) * 1_000_000) - 1_000_000, - attributes: vec![ - string_attr("db.system", "postgres"), - string_attr("db.statement", "SELECT * FROM items WHERE id = $1"), - ], + attributes: vec![string_attr("db.system", "postgres"), string_attr("db.statement", "SELECT * FROM items WHERE id = $1")], dropped_attributes_count: 0, events: vec![], dropped_events_count: 0, diff --git a/doc/c-cpp-integration.md b/doc/c-cpp-integration.md index a374420..8c7e7d1 100644 --- a/doc/c-cpp-integration.md +++ b/doc/c-cpp-integration.md @@ -95,3 +95,128 @@ int main() { - attribute keys and values are currently string-only by design - richer C++ usage lives in the demo: - [`demo/cpp-shared-lib`](../demo/cpp-shared-lib) + +## Performance: connection reuse, batching, async + +`lj_logger_log` opens a fresh connection per record — simplest and most robust, +but the per-connection handshake dominates at scale. Four additional send paths +eliminate that overhead for both gRPC and HTTP (HTTP uses a keep-alive connection +pool, gRPC caches a multiplexed channel): + +| Function | What it does | When to use | +|---|---|---| +| `lj_logger_log` | Fresh connection per record | Low rate, simplest path | +| `lj_logger_log_reuse` | One record over a persistent connection | Moderate rate, replaces `_log` for a speedup | +| `lj_logger_log_batch` | Many records in one request (amortised) | Bulk export, flush loops | +| `lj_logger_log_async` | Non-blocking, hands send to a background runtime | High rate, caller must not block | +| `lj_logger_log_batch_async` | Non-blocking batch send | Bulk export without caller latency | + +All `_reuse`, `_batch`, and `_async` paths share the persistent connection — the +first call establishes it (slightly slower), every subsequent call reuses it. + +### Error semantics + +| Path | Return value `false` means | Network failures | +|---|---|---| +| `lj_logger_log`, `_reuse`, `_batch` | Validation, connection, or HTTP/gRPC error | Returned synchronously via `lj_error_message()` | +| `lj_logger_log_async`, `_batch_async` | Validation error only | Counted later via `lj_logger_async_errors()` | + +The async paths never report network failures in-band because the send happens +after the function returns. Check `lj_logger_async_errors` after `lj_logger_flush` +or `lj_logger_free`. + +### Thread safety + +A single `lj_logger *` may be shared across threads: the underlying gRPC channel +and HTTP connection pool are internally synchronised. The async engine (counters, +backpressure semaphore) is also thread-safe. + +### Async backpressure + +`lj_logger_log_async` and `lj_logger_log_batch_async` never block the caller. +Outstanding sends are bounded by a backpressure policy set before the first send: + +```c +lj_logger_set_backpressure(logger, LJ_BACKPRESSURE_DROP, 1024); // default +``` + +| Model | Behaviour | +|---|---| +| `LJ_BACKPRESSURE_UNBOUNDED` | Spawn every send (risk: memory under load) | +| `LJ_BACKPRESSURE_DROP` | Bounded to `capacity`; drop + count when full | +| `LJ_BACKPRESSURE_BLOCK` | Bounded; block the caller until a slot frees | + +Drain and observe: + +```c +// Block until all in-flight sends finish or 5000 ms elapses +bool drained = lj_logger_flush(logger, 5000); + +uint64_t errors = lj_logger_async_errors(logger); +uint64_t dropped = lj_logger_async_dropped(logger); +uint64_t inflight = lj_logger_async_inflight(logger); +``` + +`lj_logger_free` also drains in-flight sends before freeing resources. + +### Async example (gRPC) + +```cpp +#include "liblogjet.h" +#include +#include + +int main() { + void *so = dlopen("./liblogjet.so", RTLD_NOW | RTLD_LOCAL); + + auto new_grpc = (lj_logger *(*)(const char *, const char *, uint64_t)) + dlsym(so, "lj_logger_new_grpc"); + auto log_async = (bool (*)(lj_logger *, const lj_log_record *)) + dlsym(so, "lj_logger_log_async"); + auto set_bp = (bool (*)(lj_logger *, int32_t, size_t)) + dlsym(so, "lj_logger_set_backpressure"); + auto flush = (bool (*)(lj_logger *, uint64_t)) + dlsym(so, "lj_logger_flush"); + auto async_errors = (uint64_t (*)(lj_logger *)) + dlsym(so, "lj_logger_async_errors"); + auto async_dropped = (uint64_t (*)(lj_logger *)) + dlsym(so, "lj_logger_async_dropped"); + auto free_logger = (void (*)(lj_logger *)) + dlsym(so, "lj_logger_free"); + + lj_logger *logger = new_grpc("127.0.0.1:4317", "demo-async", 2000); + set_bp(logger, LJ_BACKPRESSURE_DROP, 256); + + lj_attribute attrs[] = {{"tag", "async-demo"}}; + lj_log_record record{ + 0, // timestamp (0 = now) + LJ_SEVERITY_INFO, // severity + "INFO", // severity text + "async hello", // body + attrs, // attributes + 1, // attributes count + }; + + for (int i = 0; i < 1000; i++) { + log_async(logger, &record); + } + + flush(logger, 5000); + + uint64_t errors = async_errors(logger); + uint64_t dropped = async_dropped(logger); + printf("errors=%lu dropped=%lu\n", errors, dropped); + + free_logger(logger); + return 0; +} +``` + +### Migration + +Replace `lj_logger_log` with `lj_logger_log_reuse` for an immediate speedup with +no change to call semantics. For bulk inserts, switch to `lj_logger_log_batch`. +When caller latency matters, use `lj_logger_log_async` or +`lj_logger_log_batch_async` with backpressure control. + +A measured comparison lives in [`demo/benchmark-clib`](../demo/benchmark-clib). diff --git a/liblogjet/include/liblogjet.h b/liblogjet/include/liblogjet.h index 10d11d8..cd2ca82 100644 --- a/liblogjet/include/liblogjet.h +++ b/liblogjet/include/liblogjet.h @@ -20,6 +20,11 @@ extern "C" { #define LJ_ATTR_INT 1 #define LJ_ATTR_ARRAY 2 +// Async backpressure models (lj_logger_set_backpressure). +#define LJ_BACKPRESSURE_UNBOUNDED 0 +#define LJ_BACKPRESSURE_DROP 1 +#define LJ_BACKPRESSURE_BLOCK 2 + // Ingest plugin signal bitmask (in descriptor reserved[0], ABI >= 1.1). #define LJ_INGEST_SIGNAL_LOGS (1u << 0) #define LJ_INGEST_SIGNAL_METRICS (1u << 1) @@ -155,7 +160,35 @@ const char *lj_version(void); const char *lj_error_message(void); lj_logger *lj_logger_new_http(const char *endpoint, const char *service_name, uint64_t timeout_ms); lj_logger *lj_logger_new_grpc(const char *endpoint, const char *service_name, uint64_t timeout_ms); +// Send one log record. Opens a fresh connection — simplest, most robust. bool lj_logger_log(lj_logger *logger, const lj_log_record *record); +// Send one record over a persistent gRPC channel or HTTP keep-alive connection. +// First call establishes the connection (slightly slower); subsequent calls reuse it. +bool lj_logger_log_reuse(lj_logger *logger, const lj_log_record *record); +// Send many records in one export request over a persistent connection. +// Records are grouped by service name, resource attributes, and scope. +// A len of 0 or null records is a successful no-op. +bool lj_logger_log_batch(lj_logger *logger, const lj_log_record *records, size_t len); +// Enqueue one record for send on a background runtime; returns immediately. +// Returns false only on validation errors. Network failures are counted via +// lj_logger_async_errors(); records dropped by backpressure via lj_logger_async_dropped(). +bool lj_logger_log_async(lj_logger *logger, const lj_log_record *record); +// Enqueue a batch for background send. Same error semantics as lj_logger_log_async. +bool lj_logger_log_batch_async(lj_logger *logger, const lj_log_record *records, size_t len); +// Configure async backpressure. model is LJ_BACKPRESSURE_UNBOUNDED / _DROP / _BLOCK. +// capacity is the max in-flight sends for bounded models (ignored for unbounded). +// Default: LJ_BACKPRESSURE_DROP, capacity 1024. Call before first async send. +bool lj_logger_set_backpressure(lj_logger *logger, int32_t model, size_t capacity); +// Block until all in-flight async sends complete or timeout_ms elapses. +// Returns true if fully drained. Also called by lj_logger_free. +bool lj_logger_flush(lj_logger *logger, uint64_t timeout_ms); +// Count of async sends that failed on the network. +uint64_t lj_logger_async_errors(lj_logger *logger); +// Count of records dropped by bounded backpressure (LJ_BACKPRESSURE_DROP). +uint64_t lj_logger_async_dropped(lj_logger *logger); +// Number of async sends currently in flight. +uint64_t lj_logger_async_inflight(lj_logger *logger); +// Free the logger. Drains in-flight async sends first. Accepts NULL. void lj_logger_free(lj_logger *logger); lj_ingest_plugin *lj_ingest_create(void); diff --git a/liblogjet/src/lib.rs b/liblogjet/src/lib.rs index 465a307..dce2bde 100644 --- a/liblogjet/src/lib.rs +++ b/liblogjet/src/lib.rs @@ -4,9 +4,10 @@ pub mod export; use std::cell::RefCell; use std::ffi::{CStr, CString, c_char}; -use std::io::{Read, Write}; -use std::net::{Shutdown, TcpStream}; -use std::sync::Mutex; +use std::io::{BufRead, Read, Write}; +use std::net::TcpStream; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::{Arc, Mutex, OnceLock}; use std::time::Duration; use opentelemetry_proto::tonic::collector::logs::v1::{ExportLogsServiceRequest, logs_service_client::LogsServiceClient}; @@ -16,12 +17,18 @@ use opentelemetry_proto::tonic::logs::v1::{LogRecord, ResourceLogs, ScopeLogs}; use opentelemetry_proto::tonic::resource::v1::Resource; use prost::Message; use tokio::runtime::{Builder, Runtime}; +use tokio::sync::{Mutex as TokioMutex, Notify, OwnedSemaphorePermit, Semaphore}; use tonic::Request; -use tonic::transport::Endpoint; +use tonic::transport::{Channel, Endpoint}; const LJ_ATTR_STRING: i32 = 0; const LJ_ATTR_INT: i32 = 1; const LJ_ATTR_ARRAY: i32 = 2; +const LJ_BACKPRESSURE_UNBOUNDED: i32 = 0; +const LJ_BACKPRESSURE_DROP: i32 = 1; +const LJ_BACKPRESSURE_BLOCK: i32 = 2; +const DEFAULT_BACKPRESSURE_CAPACITY: usize = 1024; +const MAX_HTTP_POOL: usize = 256; const DEFAULT_SCOPE_NAME: &str = "liblogjet"; const VERSION: &[u8] = concat!(env!("CARGO_PKG_VERSION"), "\0").as_bytes(); @@ -84,7 +91,7 @@ struct Logger { } enum Backend { - Http(HttpEndpoint), + Http(HttpClient), Grpc(GrpcClient), } @@ -96,8 +103,54 @@ struct HttpEndpoint { } struct GrpcClient { + runtime: Runtime, + engine: Arc, + channel: Arc, +} + +struct GrpcChannel { endpoint: String, - runtime: Mutex, + channel: TokioMutex>, +} + +struct HttpClient { + runtime: OnceLock, + engine: Arc, + pool: Arc, +} + +struct HttpPool { + endpoint: HttpEndpoint, + idle: Mutex>, +} + +/// Backend-agnostic async send engine: backpressure, counters, and drain. +struct AsyncEngine { + backpressure: Mutex, + inflight: AtomicU64, + errors: AtomicU64, + dropped: AtomicU64, + idle: Notify, +} + +impl AsyncEngine { + fn new() -> Arc { + Arc::new(Self { + backpressure: Mutex::new(Backpressure { + model: LJ_BACKPRESSURE_DROP, + semaphore: Arc::new(Semaphore::new(DEFAULT_BACKPRESSURE_CAPACITY)), + }), + inflight: AtomicU64::new(0), + errors: AtomicU64::new(0), + dropped: AtomicU64::new(0), + idle: Notify::new(), + }) + } +} + +struct Backpressure { + model: i32, + semaphore: Arc, } /// Returns the library version string. @@ -148,7 +201,7 @@ pub unsafe extern "C" fn lj_logger_new_grpc(endpoint: *const c_char, service_nam #[unsafe(no_mangle)] pub unsafe extern "C" fn lj_logger_log(logger: *mut lj_logger, record: *const LjLogRecord) -> bool { clear_last_error(); - let logger = match unsafe { logger.as_mut() } { + let logger = match unsafe { logger.as_ref() } { Some(logger) => logger, None => { set_last_error("logger is null"); @@ -171,6 +224,267 @@ pub unsafe extern "C" fn lj_logger_log(logger: *mut lj_logger, record: *const Lj } } +/// Sends one log record, reusing a persistent connection. +/// +/// For gRPC loggers this reuses a cached channel, avoiding a fresh connection +/// handshake on every call. For HTTP loggers it currently behaves like +/// `lj_logger_log` (a new connection per call) until HTTP keep-alive lands. +/// +/// # Safety +/// +/// `logger` must be a valid pointer returned by `lj_logger_new_http` or +/// `lj_logger_new_grpc`. `record` must point to a valid `LjLogRecord` for the +/// duration of the call. +#[unsafe(no_mangle)] +pub unsafe extern "C" fn lj_logger_log_reuse(logger: *mut lj_logger, record: *const LjLogRecord) -> bool { + clear_last_error(); + let logger = match unsafe { logger.as_ref() } { + Some(logger) => logger, + None => { + set_last_error("logger is null"); + return false; + } + }; + let record = match unsafe { record.as_ref() } { + Some(record) => record, + None => { + set_last_error("record is null"); + return false; + } + }; + match build_request(&logger.inner, record).and_then(|request| send_request_reuse(&logger.inner, request)) { + Ok(()) => true, + Err(err) => { + set_last_error(err); + false + } + } +} + +/// Sends a batch of records in a single export request over a persistent +/// connection. +/// +/// Records sharing the same effective service name, scope name, resource +/// attributes, and scope attributes are grouped into one `ScopeLogs`. A `len` +/// of `0` (or a null `records` pointer) is a successful no-op. For gRPC loggers +/// the batch is sent over the reused channel; HTTP loggers send one POST for +/// the whole batch. +/// +/// # Safety +/// +/// `logger` must be a valid pointer returned by `lj_logger_new_http` or +/// `lj_logger_new_grpc`. When `len > 0`, `records` must point to `len` valid +/// `LjLogRecord` values for the duration of the call. +#[unsafe(no_mangle)] +pub unsafe extern "C" fn lj_logger_log_batch(logger: *mut lj_logger, records: *const LjLogRecord, len: usize) -> bool { + clear_last_error(); + let logger = match unsafe { logger.as_ref() } { + Some(logger) => logger, + None => { + set_last_error("logger is null"); + return false; + } + }; + if len == 0 || records.is_null() { + return true; + } + let records = unsafe { std::slice::from_raw_parts(records, len) }; + match build_batch_request(&logger.inner, records).and_then(|request| send_request_reuse(&logger.inner, request)) { + Ok(()) => true, + Err(err) => { + set_last_error(err); + false + } + } +} + +/// Sends one log record without blocking, handing the send to a background +/// runtime and returning immediately. +/// +/// gRPC only. Returns `true` if the record was validated and enqueued; `false` +/// (with `lj_error_message` set) only on immediate validation errors. Network +/// failures occur later and are counted by `lj_logger_async_errors`; records +/// dropped by backpressure are counted by `lj_logger_async_dropped`. +/// +/// # Safety +/// +/// `logger` must be a valid pointer returned by `lj_logger_new_grpc`. `record` +/// must point to a valid `LjLogRecord` for the duration of the call. +#[unsafe(no_mangle)] +pub unsafe extern "C" fn lj_logger_log_async(logger: *mut lj_logger, record: *const LjLogRecord) -> bool { + clear_last_error(); + let logger = match unsafe { logger.as_ref() } { + Some(logger) => logger, + None => { + set_last_error("logger is null"); + return false; + } + }; + let record = match unsafe { record.as_ref() } { + Some(record) => record, + None => { + set_last_error("record is null"); + return false; + } + }; + match build_request(&logger.inner, record).and_then(|request| send_request_async(&logger.inner, request)) { + Ok(()) => true, + Err(err) => { + set_last_error(err); + false + } + } +} + +/// Sends a batch of records without blocking (gRPC only). A `len` of `0` (or a +/// null `records` pointer) is a successful no-op. +/// +/// # Safety +/// +/// `logger` must be a valid pointer returned by `lj_logger_new_grpc`. When +/// `len > 0`, `records` must point to `len` valid `LjLogRecord` values for the +/// duration of the call. +#[unsafe(no_mangle)] +pub unsafe extern "C" fn lj_logger_log_batch_async(logger: *mut lj_logger, records: *const LjLogRecord, len: usize) -> bool { + clear_last_error(); + let logger = match unsafe { logger.as_ref() } { + Some(logger) => logger, + None => { + set_last_error("logger is null"); + return false; + } + }; + if len == 0 || records.is_null() { + return true; + } + let records = unsafe { std::slice::from_raw_parts(records, len) }; + match build_batch_request(&logger.inner, records).and_then(|request| send_request_async(&logger.inner, request)) { + Ok(()) => true, + Err(err) => { + set_last_error(err); + false + } + } +} + +fn logger_engine(logger: &Logger) -> &Arc { + match &logger.backend { + Backend::Grpc(client) => &client.engine, + Backend::Http(client) => &client.engine, + } +} + +fn flush_logger(logger: &Logger, timeout: Duration) -> bool { + match &logger.backend { + Backend::Grpc(client) => flush_engine(&client.runtime, &client.engine, timeout), + Backend::Http(client) => match client.runtime.get() { + Some(runtime) => flush_engine(runtime, &client.engine, timeout), + None => client.engine.inflight.load(Ordering::SeqCst) == 0, + }, + } +} + +/// Configures the async backpressure policy (gRPC or HTTP). +/// +/// `model` is one of `LJ_BACKPRESSURE_UNBOUNDED`, `LJ_BACKPRESSURE_DROP`, or +/// `LJ_BACKPRESSURE_BLOCK`. `capacity` is the maximum number of in-flight async +/// sends for the bounded models (ignored for unbounded). Should be called +/// before the first async send. Returns `false` (with `lj_error_message`) on +/// invalid input. +/// +/// # Safety +/// +/// `logger` must be a valid pointer returned by this library. +#[unsafe(no_mangle)] +pub unsafe extern "C" fn lj_logger_set_backpressure(logger: *mut lj_logger, model: i32, capacity: usize) -> bool { + clear_last_error(); + let logger = match unsafe { logger.as_ref() } { + Some(logger) => logger, + None => { + set_last_error("logger is null"); + return false; + } + }; + if model != LJ_BACKPRESSURE_UNBOUNDED && model != LJ_BACKPRESSURE_DROP && model != LJ_BACKPRESSURE_BLOCK { + set_last_error("invalid backpressure model"); + return false; + } + let capacity = if model == LJ_BACKPRESSURE_UNBOUNDED { + 1 + } else if capacity == 0 { + set_last_error("capacity must be >= 1 for bounded backpressure"); + return false; + } else { + capacity + }; + match logger_engine(&logger.inner).backpressure.lock() { + Ok(mut cfg) => { + cfg.model = model; + cfg.semaphore = Arc::new(Semaphore::new(capacity)); + true + } + Err(_) => { + set_last_error("backpressure lock poisoned"); + false + } + } +} + +/// Blocks until all in-flight async sends complete or `timeout_ms` elapses. +/// +/// Returns `true` if fully drained, `false` on timeout. +/// +/// # Safety +/// +/// `logger` must be a valid pointer returned by this library. +#[unsafe(no_mangle)] +pub unsafe extern "C" fn lj_logger_flush(logger: *mut lj_logger, timeout_ms: u64) -> bool { + let logger = match unsafe { logger.as_ref() } { + Some(logger) => logger, + None => return false, + }; + flush_logger(&logger.inner, Duration::from_millis(timeout_ms)) +} + +/// Returns the number of async sends that failed on the network. +/// +/// # Safety +/// +/// `logger` must be null or a valid pointer returned by this library. +#[unsafe(no_mangle)] +pub unsafe extern "C" fn lj_logger_async_errors(logger: *mut lj_logger) -> u64 { + match unsafe { logger.as_ref() } { + Some(logger) => logger_engine(&logger.inner).errors.load(Ordering::Relaxed), + None => 0, + } +} + +/// Returns the number of records dropped by bounded backpressure. +/// +/// # Safety +/// +/// `logger` must be null or a valid pointer returned by this library. +#[unsafe(no_mangle)] +pub unsafe extern "C" fn lj_logger_async_dropped(logger: *mut lj_logger) -> u64 { + match unsafe { logger.as_ref() } { + Some(logger) => logger_engine(&logger.inner).dropped.load(Ordering::Relaxed), + None => 0, + } +} + +/// Returns the number of async sends currently in flight. +/// +/// # Safety +/// +/// `logger` must be null or a valid pointer returned by this library. +#[unsafe(no_mangle)] +pub unsafe extern "C" fn lj_logger_async_inflight(logger: *mut lj_logger) -> u64 { + match unsafe { logger.as_ref() } { + Some(logger) => logger_engine(&logger.inner).inflight.load(Ordering::SeqCst), + None => 0, + } +} + /// Frees a logger created by one of the constructors. Accepts null. /// /// # Safety @@ -182,7 +496,8 @@ pub unsafe extern "C" fn lj_logger_free(logger: *mut lj_logger) { if logger.is_null() { return; } - let _ = unsafe { Box::from_raw(logger) }; + let boxed = unsafe { Box::from_raw(logger) }; + let _ = flush_logger(&boxed.inner, boxed.inner.timeout); } enum BackendKind { @@ -206,34 +521,131 @@ unsafe fn new_logger_impl(endpoint: *const c_char, service_name: *const c_char, let service_name = read_required(service_name, "service_name")?; let timeout = Duration::from_millis(timeout_ms.max(1)); let backend = match kind { - BackendKind::Http => Backend::Http(parse_http_endpoint(&endpoint)?), - BackendKind::Grpc => Backend::Grpc(GrpcClient { endpoint: normalise_grpc_endpoint(&endpoint), runtime: Mutex::new(grpc_runtime()?) }), + BackendKind::Http => { + let pool = Arc::new(HttpPool { endpoint: parse_http_endpoint(&endpoint)?, idle: Mutex::new(Vec::new()) }); + Backend::Http(HttpClient { runtime: OnceLock::new(), engine: AsyncEngine::new(), pool }) + } + BackendKind::Grpc => { + let channel = Arc::new(GrpcChannel { endpoint: normalise_grpc_endpoint(&endpoint), channel: TokioMutex::new(None) }); + Backend::Grpc(GrpcClient { runtime: make_runtime()?, engine: AsyncEngine::new(), channel }) + } }; Ok(Logger { backend, service_name, timeout }) } -fn grpc_runtime() -> Result { +fn make_runtime() -> Result { Builder::new_multi_thread().enable_all().build().map_err(|err| err.to_string()) } +/// Raw `(key, value_type, value)` attribute triples read once from the C side. +type AttrTriples = Vec<(String, i32, String)>; +/// Grouping key for a resource: effective service name plus resource attributes. +type ResourceKey = (String, AttrTriples); +/// Grouping key for a scope: effective scope name plus scope attributes. +type ScopeKey = (String, AttrTriples); + fn build_request(logger: &Logger, record: &LjLogRecord) -> Result { + let (_, resource_attrs) = resolve_resource(logger, record)?; + let (_, scope) = resolve_scope(record)?; + let log = record_to_log(record)?; + + Ok(ExportLogsServiceRequest { + resource_logs: vec![ResourceLogs { + schema_url: String::new(), + resource: Some(Resource { attributes: resource_attrs, dropped_attributes_count: 0, entity_refs: Vec::new() }), + scope_logs: vec![ScopeLogs { schema_url: String::new(), scope: Some(scope), log_records: vec![log] }], + }], + }) +} + +fn build_batch_request(logger: &Logger, records: &[LjLogRecord]) -> Result { + use std::collections::HashMap; + + struct ScopeGroup { + scope: InstrumentationScope, + log_records: Vec, + } + struct ResourceGroup { + resource_attrs: Vec, + scopes: Vec, + scope_index: HashMap, + } + + let mut groups: Vec = Vec::new(); + let mut resource_index: HashMap = HashMap::new(); + + for record in records { + let (resource_key, resource_attrs) = resolve_resource(logger, record)?; + let (scope_key, scope) = resolve_scope(record)?; + let log = record_to_log(record)?; + + let resource_idx = match resource_index.get(&resource_key) { + Some(idx) => *idx, + None => { + groups.push(ResourceGroup { resource_attrs, scopes: Vec::new(), scope_index: HashMap::new() }); + let idx = groups.len() - 1; + resource_index.insert(resource_key, idx); + idx + } + }; + + let group = &mut groups[resource_idx]; + let scope_idx = match group.scope_index.get(&scope_key) { + Some(idx) => *idx, + None => { + group.scopes.push(ScopeGroup { scope, log_records: Vec::new() }); + let idx = group.scopes.len() - 1; + group.scope_index.insert(scope_key, idx); + idx + } + }; + group.scopes[scope_idx].log_records.push(log); + } + + Ok(ExportLogsServiceRequest { + resource_logs: groups + .into_iter() + .map(|group| ResourceLogs { + schema_url: String::new(), + resource: Some(Resource { attributes: group.resource_attrs, dropped_attributes_count: 0, entity_refs: Vec::new() }), + scope_logs: group + .scopes + .into_iter() + .map(|scope_group| ScopeLogs { schema_url: String::new(), scope: Some(scope_group.scope), log_records: scope_group.log_records }) + .collect(), + }) + .collect(), + }) +} + +fn resolve_resource(logger: &Logger, record: &LjLogRecord) -> Result<(ResourceKey, Vec), String> { let service_name = read_optional(record.service_name)?.unwrap_or_else(|| logger.service_name.clone()); if service_name.is_empty() { return Err("service name is empty".to_string()); } - let severity_text = read_optional(record.severity_text)?.unwrap_or_else(|| severity_text(record.severity_number).to_string()); - let body = read_required_nonnull(record.body, "record.body")?; - let event_name = read_optional(record.event_name)?.unwrap_or_default(); - let scope_name = read_optional(record.scope_name)?.unwrap_or_else(|| DEFAULT_SCOPE_NAME.to_string()); - - let mut resource_attrs = attrs_to_kvs(record.resource_attrs, record.resource_attrs_len)?; - if !resource_attrs.iter().any(|kv| kv.key == "service.name") { + let triples = read_attrs(record.resource_attrs, record.resource_attrs_len)?; + let mut resource_attrs = triples_to_kvs(&triples)?; + if !triples.iter().any(|(key, _, _)| key == "service.name") { resource_attrs.insert(0, key_value("service.name", AnyValue { value: Some(Value::StringValue(service_name.clone())) })); } - let scope_attrs = attrs_to_kvs(record.scope_attrs, record.scope_attrs_len)?; - let log_attrs = attrs_to_kvs(record.attributes, record.attributes_len)?; + Ok(((service_name, triples), resource_attrs)) +} + +fn resolve_scope(record: &LjLogRecord) -> Result<(ScopeKey, InstrumentationScope), String> { + let scope_name = read_optional(record.scope_name)?.unwrap_or_else(|| DEFAULT_SCOPE_NAME.to_string()); + let triples = read_attrs(record.scope_attrs, record.scope_attrs_len)?; + let scope_attrs = triples_to_kvs(&triples)?; + let scope = InstrumentationScope { name: scope_name.clone(), version: String::new(), attributes: scope_attrs, dropped_attributes_count: 0 }; + Ok(((scope_name, triples), scope)) +} + +fn record_to_log(record: &LjLogRecord) -> Result { + let severity_text = read_optional(record.severity_text)?.unwrap_or_else(|| severity_text(record.severity_number).to_string()); + let body = read_required_nonnull(record.body, "record.body")?; + let event_name = read_optional(record.event_name)?.unwrap_or_default(); + let log_attrs = triples_to_kvs(&read_attrs(record.attributes, record.attributes_len)?)?; let mut log = LogRecord { time_unix_nano: record.timestamp_unix_ns, @@ -251,47 +663,46 @@ fn build_request(logger: &Logger, record: &LjLogRecord) -> Result Result, String> { +fn read_attrs(attrs: *const LjAttribute, len: usize) -> Result { if len == 0 || attrs.is_null() { return Ok(Vec::new()); } let attrs = unsafe { std::slice::from_raw_parts(attrs, len) }; - attrs.iter().map(attr_to_kv).collect() -} - -fn attr_to_kv(attr: &LjAttribute) -> Result { - let key = read_required_nonnull(attr.key, "attribute.key")?; - let raw = read_required_nonnull(attr.value, "attribute.value")?; - let value = match attr.value_type { - LJ_ATTR_STRING => AnyValue { value: Some(Value::StringValue(raw)) }, - LJ_ATTR_INT => AnyValue { value: Some(Value::IntValue(raw.parse::().unwrap_or(0))) }, - LJ_ATTR_ARRAY => AnyValue { - value: Some(Value::ArrayValue(ArrayValue { - values: raw - .split(',') - .map(str::trim) - .filter(|part| !part.is_empty()) - .map(|part| AnyValue { value: Some(Value::StringValue(part.to_string())) }) - .collect(), - })), - }, - other => return Err(format!("unsupported attribute value_type {other}")), - }; - Ok(key_value(key, value)) + attrs + .iter() + .map(|attr| { + let key = read_required_nonnull(attr.key, "attribute.key")?; + let value = read_required_nonnull(attr.value, "attribute.value")?; + Ok((key, attr.value_type, value)) + }) + .collect() +} + +fn triples_to_kvs(triples: &[(String, i32, String)]) -> Result, String> { + triples + .iter() + .map(|(key, value_type, raw)| { + let value = match *value_type { + LJ_ATTR_STRING => AnyValue { value: Some(Value::StringValue(raw.clone())) }, + LJ_ATTR_INT => AnyValue { value: Some(Value::IntValue(raw.parse::().unwrap_or(0))) }, + LJ_ATTR_ARRAY => AnyValue { + value: Some(Value::ArrayValue(ArrayValue { + values: raw + .split(',') + .map(str::trim) + .filter(|part| !part.is_empty()) + .map(|part| AnyValue { value: Some(Value::StringValue(part.to_string())) }) + .collect(), + })), + }, + other => return Err(format!("unsupported attribute value_type {other}")), + }; + Ok(key_value(key.clone(), value)) + }) + .collect() } fn key_value(key: impl Into, value: AnyValue) -> KeyValue { @@ -300,14 +711,146 @@ fn key_value(key: impl Into, value: AnyValue) -> KeyValue { fn send_request(logger: &Logger, request: ExportLogsServiceRequest) -> Result<(), String> { match &logger.backend { - Backend::Http(endpoint) => post_otlp_http(endpoint, logger.timeout, &request).map_err(|err| err.to_string()), - Backend::Grpc(client) => client - .runtime - .lock() - .map_err(|_| "gRPC runtime lock poisoned".to_string())? - .block_on(send_otlp_grpc(client.endpoint.clone(), logger.timeout, request)) - .map_err(|err| err.to_string()), + Backend::Http(client) => post_otlp_http_once(&client.pool.endpoint, logger.timeout, &request).map_err(|err| err.to_string()), + Backend::Grpc(client) => { + client.runtime.block_on(send_otlp_grpc(client.channel.endpoint.clone(), logger.timeout, request)).map_err(|err| err.to_string()) + } + } +} + +fn send_request_reuse(logger: &Logger, request: ExportLogsServiceRequest) -> Result<(), String> { + match &logger.backend { + Backend::Http(client) => { + let payload = request.encode_to_vec(); + http_send_blocking(&client.pool, logger.timeout, &payload).map_err(|err| err.to_string()) + } + Backend::Grpc(client) => client.runtime.block_on(send_pooled_async(client.channel.clone(), logger.timeout, request)), + } +} + +fn send_request_async(logger: &Logger, request: ExportLogsServiceRequest) -> Result<(), String> { + match &logger.backend { + Backend::Grpc(client) => { + let channel = client.channel.clone(); + let timeout = logger.timeout; + enqueue_async(&client.runtime, &client.engine, move || send_pooled_async(channel, timeout, request)) + } + Backend::Http(client) => { + let runtime = http_runtime(client)?; + let pool = client.pool.clone(); + let timeout = logger.timeout; + let payload = request.encode_to_vec(); + enqueue_async(runtime, &client.engine, move || http_send_async(pool, timeout, payload)) + } + } +} + +fn http_runtime(client: &HttpClient) -> Result<&Runtime, String> { + if let Some(runtime) = client.runtime.get() { + return Ok(runtime); + } + let runtime = make_runtime()?; + let _ = client.runtime.set(runtime); + Ok(client.runtime.get().expect("http runtime set")) +} + +fn enqueue_async(runtime: &Runtime, engine: &Arc, make_fut: F) -> Result<(), String> +where + F: FnOnce() -> Fut + Send + 'static, + Fut: std::future::Future> + Send + 'static, +{ + let (model, semaphore) = { + let cfg = engine.backpressure.lock().map_err(|_| "backpressure lock poisoned".to_string())?; + (cfg.model, cfg.semaphore.clone()) + }; + match model { + LJ_BACKPRESSURE_UNBOUNDED => spawn_task(runtime, engine, make_fut, None), + LJ_BACKPRESSURE_DROP => match semaphore.try_acquire_owned() { + Ok(permit) => spawn_task(runtime, engine, make_fut, Some(permit)), + Err(_) => { + engine.dropped.fetch_add(1, Ordering::Relaxed); + } + }, + LJ_BACKPRESSURE_BLOCK => { + let permit = runtime.block_on(semaphore.acquire_owned()).map_err(|err| err.to_string())?; + spawn_task(runtime, engine, make_fut, Some(permit)); + } + other => return Err(format!("invalid backpressure model {other}")), } + Ok(()) +} + +fn spawn_task(runtime: &Runtime, engine: &Arc, make_fut: F, permit: Option) +where + F: FnOnce() -> Fut + Send + 'static, + Fut: std::future::Future> + Send + 'static, +{ + let engine = engine.clone(); + engine.inflight.fetch_add(1, Ordering::SeqCst); + runtime.spawn(async move { + let _permit = permit; + if make_fut().await.is_err() { + engine.errors.fetch_add(1, Ordering::Relaxed); + } + if engine.inflight.fetch_sub(1, Ordering::SeqCst) == 1 { + engine.idle.notify_waiters(); + } + }); +} + +fn flush_engine(runtime: &Runtime, engine: &Arc, timeout: Duration) -> bool { + runtime.block_on(async { + let deadline = tokio::time::Instant::now() + timeout; + loop { + if engine.inflight.load(Ordering::SeqCst) == 0 { + return true; + } + let notified = engine.idle.notified(); + if engine.inflight.load(Ordering::SeqCst) == 0 { + return true; + } + let now = tokio::time::Instant::now(); + if now >= deadline { + return false; + } + if tokio::time::timeout(deadline - now, notified).await.is_err() { + return engine.inflight.load(Ordering::SeqCst) == 0; + } + } + }) +} + +async fn send_pooled_async(channel: Arc, timeout: Duration, request: ExportLogsServiceRequest) -> Result<(), String> { + // Connect-once: hold the lock across connect so a concurrent burst opens a + // single connection; release it before export so sends run concurrently over + // the shared multiplexed channel. + let active = { + let mut guard = channel.channel.lock().await; + match guard.as_ref() { + Some(active) => active.clone(), + None => { + let active = connect_channel(&channel.endpoint, timeout).await.map_err(|err| err.to_string())?; + *guard = Some(active.clone()); + active + } + } + }; + + let result = export_on_channel(active, request).await.map_err(|err| err.to_string()); + if result.is_err() { + *channel.channel.lock().await = None; + } + result +} + +async fn connect_channel(endpoint: &str, timeout: Duration) -> Result> { + Ok(Endpoint::from_shared(endpoint.to_string())?.timeout(timeout).connect_timeout(timeout).connect().await?) +} + +async fn export_on_channel(channel: Channel, request: ExportLogsServiceRequest) -> Result<(), Box> { + let mut client = LogsServiceClient::new(channel); + client.export(Request::new(request)).await?; + Ok(()) } async fn send_otlp_grpc(endpoint: String, timeout: Duration, request: ExportLogsServiceRequest) -> Result<(), Box> { @@ -317,22 +860,23 @@ async fn send_otlp_grpc(endpoint: String, timeout: Duration, request: ExportLogs Ok(()) } -fn post_otlp_http(endpoint: &HttpEndpoint, timeout: Duration, request: &ExportLogsServiceRequest) -> std::io::Result<()> { +/// Fresh-connect, `Connection: close` POST. Baseline used by `lj_logger_log`. +fn post_otlp_http_once(endpoint: &HttpEndpoint, timeout: Duration, request: &ExportLogsServiceRequest) -> std::io::Result<()> { let payload = request.encode_to_vec(); let mut stream = TcpStream::connect(endpoint.authority.as_str())?; stream.set_read_timeout(Some(timeout))?; stream.set_write_timeout(Some(timeout))?; - stream.write_all( - format!( - "POST {} HTTP/1.1\r\nHost: {}\r\nContent-Type: application/x-protobuf\r\nContent-Length: {}\r\nConnection: close\r\n\r\n", - endpoint.path, - endpoint.host_header, - payload.len() - ) - .as_bytes(), - )?; - stream.write_all(&payload)?; - stream.shutdown(Shutdown::Write)?; + stream.set_nodelay(true)?; + let header = format!( + "POST {} HTTP/1.1\r\nHost: {}\r\nContent-Type: application/x-protobuf\r\nContent-Length: {}\r\nConnection: close\r\n\r\n", + endpoint.path, + endpoint.host_header, + payload.len() + ); + let mut framed = Vec::with_capacity(header.len() + payload.len()); + framed.extend_from_slice(header.as_bytes()); + framed.extend_from_slice(&payload); + stream.write_all(&framed)?; let mut response = Vec::new(); stream.read_to_end(&mut response)?; @@ -345,6 +889,115 @@ fn post_otlp_http(endpoint: &HttpEndpoint, timeout: Duration, request: &ExportLo Err(std::io::Error::other(format!("HTTP export failed: {status}"))) } +async fn http_send_async(pool: Arc, timeout: Duration, payload: Vec) -> Result<(), String> { + tokio::task::spawn_blocking(move || http_send_blocking(&pool, timeout, &payload)) + .await + .map_err(|err| err.to_string())? + .map_err(|err| err.to_string()) +} + +/// Keep-alive POST over a pooled connection, with one fresh-connect retry. +fn http_send_blocking(pool: &HttpPool, timeout: Duration, payload: &[u8]) -> std::io::Result<()> { + if let Some(stream) = pool_checkout(pool) + && http_exchange(pool, stream, payload).is_ok() + { + return Ok(()); + } + let stream = http_connect(pool, timeout)?; + http_exchange(pool, stream, payload) +} + +fn pool_checkout(pool: &HttpPool) -> Option { + pool.idle.lock().ok().and_then(|mut idle| idle.pop()) +} + +fn pool_checkin(pool: &HttpPool, stream: TcpStream) { + if let Ok(mut idle) = pool.idle.lock() + && idle.len() < MAX_HTTP_POOL + { + idle.push(stream); + } +} + +fn http_connect(pool: &HttpPool, timeout: Duration) -> std::io::Result { + let stream = TcpStream::connect(pool.endpoint.authority.as_str())?; + stream.set_read_timeout(Some(timeout))?; + stream.set_write_timeout(Some(timeout))?; + stream.set_nodelay(true)?; + Ok(stream) +} + +fn http_exchange(pool: &HttpPool, mut stream: TcpStream, payload: &[u8]) -> std::io::Result<()> { + let header = format!( + "POST {} HTTP/1.1\r\nHost: {}\r\nContent-Type: application/x-protobuf\r\nContent-Length: {}\r\n\r\n", + pool.endpoint.path, + pool.endpoint.host_header, + payload.len() + ); + // Single write (header + body) so Nagle/delayed-ACK does not stall the request. + let mut framed = Vec::with_capacity(header.len() + payload.len()); + framed.extend_from_slice(header.as_bytes()); + framed.extend_from_slice(payload); + stream.write_all(&framed)?; + stream.flush()?; + + let (status_ok, keep_alive) = read_http_response(&mut stream)?; + if !status_ok { + return Err(std::io::Error::other("HTTP export failed")); + } + if keep_alive { + pool_checkin(pool, stream); + } + Ok(()) +} + +/// Reads one HTTP/1.1 response. Returns `(status_ok, can_keep_alive)`. +fn read_http_response(stream: &mut TcpStream) -> std::io::Result<(bool, bool)> { + let mut reader = std::io::BufReader::new(stream); + + let mut head = String::new(); + loop { + let mut line = String::new(); + let read = reader.read_line(&mut line)?; + if read == 0 || line == "\r\n" || line == "\n" { + break; + } + head.push_str(&line); + } + + let status_line = head.lines().next().unwrap_or_default(); + let status_ok = status_line.contains(" 200 ") || status_line.contains(" 202 ") || status_line.contains(" 204 "); + + let mut content_length: Option = None; + let mut conn_close = false; + for line in head.lines().skip(1) { + if let Some((key, value)) = line.split_once(':') { + let key = key.trim().to_ascii_lowercase(); + let value = value.trim(); + if key == "content-length" { + content_length = value.parse::().ok(); + } else if key == "connection" && value.eq_ignore_ascii_case("close") { + conn_close = true; + } + } + } + + let keep_alive = match content_length { + Some(len) => { + let mut body = vec![0u8; len]; + reader.read_exact(&mut body)?; + !conn_close + } + None => { + let mut sink = Vec::new(); + let _ = reader.read_to_end(&mut sink); + false + } + }; + + Ok((status_ok, keep_alive)) +} + fn parse_http_endpoint(raw: &str) -> Result { let raw = raw.trim(); if let Some(rest) = raw.strip_prefix("https://") { @@ -411,3 +1064,11 @@ fn set_last_error(message: impl Into) { *slot.borrow_mut() = CString::new(clean).unwrap_or_else(|_| CString::new("invalid error").expect("static")); }); } + +#[cfg(test)] +#[path = "../tests/unit/batch_ut.rs"] +mod batch_ut; + +#[cfg(test)] +#[path = "../tests/unit/async_ut.rs"] +mod async_ut; diff --git a/liblogjet/tests/unit/async_ut.rs b/liblogjet/tests/unit/async_ut.rs new file mode 100644 index 0000000..5cb246a --- /dev/null +++ b/liblogjet/tests/unit/async_ut.rs @@ -0,0 +1,341 @@ +use std::ptr; +use std::sync::atomic::Ordering; +use std::sync::Arc; +use std::time::Duration; + +use tokio::runtime::Builder; +use tokio::sync::{Semaphore, oneshot}; + +use super::{ + Backend, HttpClient, HttpEndpoint, HttpPool, Logger, lj_logger, LjLogRecord, + LJ_BACKPRESSURE_BLOCK, LJ_BACKPRESSURE_DROP, LJ_BACKPRESSURE_UNBOUNDED, DEFAULT_BACKPRESSURE_CAPACITY, + AsyncEngine, enqueue_async, flush_engine, + lj_logger_flush, lj_logger_free, + lj_logger_async_errors, lj_logger_async_dropped, lj_logger_async_inflight, + lj_logger_log_async, lj_logger_set_backpressure, +}; + +fn test_runtime() -> tokio::runtime::Runtime { + Builder::new_multi_thread().enable_time().build().unwrap() +} + +fn test_logger() -> Logger { + let pool = Arc::new(HttpPool { + endpoint: HttpEndpoint { authority: "127.0.0.1:4318".to_string(), host_header: "127.0.0.1:4318".to_string(), path: "/v1/logs".to_string() }, + idle: std::sync::Mutex::new(Vec::new()), + }); + Logger { + backend: Backend::Http(HttpClient { runtime: std::sync::OnceLock::new(), engine: AsyncEngine::new(), pool }), + service_name: "svc".to_string(), + timeout: Duration::from_millis(1000), + } +} + +fn test_logger_ptr() -> *mut lj_logger { + Box::into_raw(Box::new(lj_logger { inner: test_logger() })) +} + +fn set_engine_capacity(engine: &AsyncEngine, model: i32, capacity: usize) { + let mut bp = engine.backpressure.lock().unwrap(); + bp.model = model; + bp.semaphore = Arc::new(Semaphore::new(capacity)); +} + +// +// AsyncEngine defaults +// + +#[test] +fn engine_defaults_to_drop_model() { + let engine = AsyncEngine::new(); + let bp = engine.backpressure.lock().unwrap(); + assert_eq!(bp.model, LJ_BACKPRESSURE_DROP); +} + +#[test] +fn engine_default_capacity_is_1024() { + let engine = AsyncEngine::new(); + let bp = engine.backpressure.lock().unwrap(); + assert_eq!(bp.semaphore.available_permits(), DEFAULT_BACKPRESSURE_CAPACITY); +} + +#[test] +fn engine_counters_start_at_zero() { + let engine = AsyncEngine::new(); + assert_eq!(engine.errors.load(Ordering::Relaxed), 0); + assert_eq!(engine.dropped.load(Ordering::Relaxed), 0); + assert_eq!(engine.inflight.load(Ordering::SeqCst), 0); +} + +// +// enqueue_async: inflight / errors +// + +#[test] +fn enqueue_increments_inflight() { + let runtime = test_runtime(); + let engine = AsyncEngine::new(); + let (tx, rx) = oneshot::channel::<()>(); + + enqueue_async(&runtime, &engine, move || async move { + let _ = rx.await; + Ok(()) + }).unwrap(); + + assert_eq!(engine.inflight.load(Ordering::SeqCst), 1); + tx.send(()).unwrap(); +} + +#[test] +fn enqueue_decrements_inflight_on_completion() { + let runtime = test_runtime(); + let engine = AsyncEngine::new(); + + enqueue_async(&runtime, &engine, || async { Ok(()) }).unwrap(); + std::thread::sleep(Duration::from_millis(100)); + + assert_eq!(engine.inflight.load(Ordering::SeqCst), 0); +} + +#[test] +fn enqueue_counts_task_errors() { + let runtime = test_runtime(); + let engine = AsyncEngine::new(); + + enqueue_async(&runtime, &engine, || async { Err("fail".to_string()) }).unwrap(); + std::thread::sleep(Duration::from_millis(100)); + + assert_eq!(engine.errors.load(Ordering::Relaxed), 1); + assert_eq!(engine.inflight.load(Ordering::SeqCst), 0); +} + +// +// Backpressure: DROP +// + +#[test] +fn drop_drops_when_semaphore_exhausted() { + let runtime = test_runtime(); + let engine = AsyncEngine::new(); + set_engine_capacity(&engine, LJ_BACKPRESSURE_DROP, 1); + + let (tx, rx) = oneshot::channel::<()>(); + + enqueue_async(&runtime, &engine, move || async move { + let _ = rx.await; + Ok(()) + }).unwrap(); + assert_eq!(engine.inflight.load(Ordering::SeqCst), 1); + + let result = enqueue_async(&runtime, &engine, || async { Ok(()) }); + assert!(result.is_ok()); + assert_eq!(engine.dropped.load(Ordering::Relaxed), 1); + + tx.send(()).unwrap(); +} + +#[test] +fn drop_returns_ok_even_when_record_is_dropped() { + let runtime = test_runtime(); + let engine = AsyncEngine::new(); + set_engine_capacity(&engine, LJ_BACKPRESSURE_DROP, 0); + + let result = enqueue_async(&runtime, &engine, || async { Ok(()) }); + assert!(result.is_ok()); + assert_eq!(engine.dropped.load(Ordering::Relaxed), 1); +} + +// +// Backpressure: BLOCK +// + +#[test] +fn block_waits_for_permit_release() { + let runtime = test_runtime(); + let engine = AsyncEngine::new(); + set_engine_capacity(&engine, LJ_BACKPRESSURE_BLOCK, 1); + + let (tx, rx) = oneshot::channel::<()>(); + let (ready_tx, ready_rx) = oneshot::channel::<()>(); + + // First enqueue holds the only permit. + enqueue_async(&runtime, &engine, move || async move { + let _ = rx.await; + Ok(()) + }).unwrap(); + + // Second enqueue should block until the permit is released. + let engine2 = engine.clone(); + let handle = std::thread::spawn(move || { + let rt = Builder::new_current_thread().enable_time().build().unwrap(); + let _ = ready_tx.send(()); + enqueue_async(&rt, &engine2, || async { Ok(()) }) + }); + + // Wait until the thread is ready (blocked on semaphore). + ready_rx.blocking_recv().unwrap(); + std::thread::sleep(Duration::from_millis(30)); + + // Release the first task; the blocked thread should now succeed. + tx.send(()).unwrap(); + let result = handle.join().unwrap(); + assert!(result.is_ok()); +} + +// +// Backpressure: UNBOUNDED +// + +#[test] +fn unbounded_ignores_capacity_limit() { + let runtime = test_runtime(); + let engine = AsyncEngine::new(); + set_engine_capacity(&engine, LJ_BACKPRESSURE_UNBOUNDED, 1); + + let (tx1, rx1) = oneshot::channel::<()>(); + let (tx2, rx2) = oneshot::channel::<()>(); + + enqueue_async(&runtime, &engine, move || async move { + let _ = rx1.await; + Ok(()) + }).unwrap(); + enqueue_async(&runtime, &engine, move || async move { + let _ = rx2.await; + Ok(()) + }).unwrap(); + + assert_eq!(engine.inflight.load(Ordering::SeqCst), 2); + assert_eq!(engine.dropped.load(Ordering::Relaxed), 0); + + tx1.send(()).unwrap(); + tx2.send(()).unwrap(); +} + +// +// flush_engine +// + +#[test] +fn flush_engine_returns_true_when_idle() { + let runtime = test_runtime(); + let engine = AsyncEngine::new(); + + assert!(flush_engine(&runtime, &engine, Duration::from_millis(100))); +} + +#[test] +fn flush_engine_returns_false_on_timeout() { + let runtime = test_runtime(); + let engine = AsyncEngine::new(); + + let (tx, rx) = oneshot::channel::<()>(); + enqueue_async(&runtime, &engine, move || async move { + let _ = rx.await; + Ok(()) + }).unwrap(); + + assert!(!flush_engine(&runtime, &engine, Duration::from_millis(10))); + + tx.send(()).unwrap(); +} + +#[test] +fn flush_engine_wakes_when_inflight_hits_zero() { + let runtime = test_runtime(); + let engine = AsyncEngine::new(); + + let (tx, rx) = oneshot::channel::<()>(); + enqueue_async(&runtime, &engine, move || async move { + let _ = rx.await; + Ok(()) + }).unwrap(); + + // Drop the sender from another thread after a short delay. + let engine2 = engine.clone(); + std::thread::spawn(move || { + std::thread::sleep(Duration::from_millis(30)); + let _ = tx.send(()); + }); + + assert!(flush_engine(&runtime, &engine2, Duration::from_millis(5000))); +} + +// +// lj_logger_set_backpressure +// + +#[test] +fn set_backpressure_null_logger_fails() { + assert!(!unsafe { lj_logger_set_backpressure(ptr::null_mut(), LJ_BACKPRESSURE_DROP, 128) }); +} + +#[test] +fn set_backpressure_invalid_model_fails() { + let logger = test_logger_ptr(); + assert!(!unsafe { lj_logger_set_backpressure(logger, 99, 128) }); + unsafe { lj_logger_free(logger) }; +} + +#[test] +fn set_backpressure_zero_capacity_bounded_fails() { + let logger = test_logger_ptr(); + assert!(!unsafe { lj_logger_set_backpressure(logger, LJ_BACKPRESSURE_DROP, 0) }); + assert!(!unsafe { lj_logger_set_backpressure(logger, LJ_BACKPRESSURE_BLOCK, 0) }); + unsafe { lj_logger_free(logger) }; +} + +#[test] +fn set_backpressure_zero_capacity_unbounded_succeeds() { + let logger = test_logger_ptr(); + assert!(unsafe { lj_logger_set_backpressure(logger, LJ_BACKPRESSURE_UNBOUNDED, 0) }); + unsafe { lj_logger_free(logger) }; +} + +// +// FFI null safety +// + +#[test] +fn log_async_null_logger_returns_false() { + let body = std::ffi::CString::new("hi").unwrap(); + let record = LjLogRecord { + timestamp_unix_ns: 1, severity_number: 9, severity_text: ptr::null(), + body: body.as_ptr(), attributes: ptr::null(), attributes_len: 0, + event_name: ptr::null(), service_name: ptr::null(), scope_name: ptr::null(), + resource_attrs: ptr::null(), resource_attrs_len: 0, + scope_attrs: ptr::null(), scope_attrs_len: 0, + }; + assert!(!unsafe { lj_logger_log_async(ptr::null_mut(), &record) }); +} + +#[test] +fn log_async_null_record_returns_false() { + let logger = test_logger_ptr(); + assert!(!unsafe { lj_logger_log_async(logger, ptr::null()) }); + unsafe { lj_logger_free(logger) }; +} + +#[test] +fn flush_null_logger_returns_false() { + assert!(!unsafe { lj_logger_flush(ptr::null_mut(), 100) }); +} + +#[test] +fn async_errors_null_logger_returns_zero() { + assert_eq!(unsafe { lj_logger_async_errors(ptr::null_mut()) }, 0); +} + +#[test] +fn async_dropped_null_logger_returns_zero() { + assert_eq!(unsafe { lj_logger_async_dropped(ptr::null_mut()) }, 0); +} + +#[test] +fn async_inflight_null_logger_returns_zero() { + assert_eq!(unsafe { lj_logger_async_inflight(ptr::null_mut()) }, 0); +} + +#[test] +fn free_null_logger_does_not_crash() { + unsafe { lj_logger_free(ptr::null_mut()) }; +} diff --git a/liblogjet/tests/unit/batch_ut.rs b/liblogjet/tests/unit/batch_ut.rs new file mode 100644 index 0000000..ac11f21 --- /dev/null +++ b/liblogjet/tests/unit/batch_ut.rs @@ -0,0 +1,546 @@ +use std::ffi::{CStr, CString}; +use std::ptr; +use std::sync::{Mutex, OnceLock}; +use std::time::Duration; + +use opentelemetry_proto::tonic::common::v1::any_value::Value; + +use super::{ + AsyncEngine, Backend, HttpClient, HttpEndpoint, HttpPool, LjAttribute, LjLogRecord, Logger, + LJ_ATTR_ARRAY, LJ_ATTR_INT, LJ_ATTR_STRING, + build_batch_request, build_request, normalise_grpc_endpoint, parse_http_endpoint, + read_attrs, record_to_log, resolve_resource, resolve_scope, severity_text, triples_to_kvs, +}; + +fn test_logger(service: &str) -> Logger { + let pool = std::sync::Arc::new(HttpPool { + endpoint: HttpEndpoint { authority: "127.0.0.1:4318".to_string(), host_header: "127.0.0.1:4318".to_string(), path: "/v1/logs".to_string() }, + idle: Mutex::new(Vec::new()), + }); + Logger { + backend: Backend::Http(HttpClient { runtime: OnceLock::new(), engine: AsyncEngine::new(), pool }), + service_name: service.to_string(), + timeout: Duration::from_millis(1000), + } +} + +fn record(ts: u64, body: &CStr, service: Option<&CStr>, scope: Option<&CStr>) -> LjLogRecord { + LjLogRecord { + timestamp_unix_ns: ts, + severity_number: 9, + severity_text: ptr::null(), + body: body.as_ptr(), + attributes: ptr::null(), + attributes_len: 0, + event_name: ptr::null(), + service_name: service.map_or(ptr::null(), CStr::as_ptr), + scope_name: scope.map_or(ptr::null(), CStr::as_ptr), + resource_attrs: ptr::null(), + resource_attrs_len: 0, + scope_attrs: ptr::null(), + scope_attrs_len: 0, + } +} + +#[test] +fn identical_records_collapse_into_one_scope() { + let logger = test_logger("svc"); + let body = CString::new("hello").unwrap(); + let records = vec![record(1, &body, None, None), record(2, &body, None, None), record(3, &body, None, None)]; + + let request = build_batch_request(&logger, &records).expect("batch request"); + + assert_eq!(request.resource_logs.len(), 1); + assert_eq!(request.resource_logs[0].scope_logs.len(), 1); + assert_eq!(request.resource_logs[0].scope_logs[0].log_records.len(), 3); +} + +#[test] +fn differing_scope_names_split_scopes() { + let logger = test_logger("svc"); + let body = CString::new("hello").unwrap(); + let scope_a = CString::new("scope-a").unwrap(); + let scope_b = CString::new("scope-b").unwrap(); + let records = vec![record(1, &body, None, Some(&scope_a)), record(2, &body, None, Some(&scope_b))]; + + let request = build_batch_request(&logger, &records).expect("batch request"); + + assert_eq!(request.resource_logs.len(), 1); + assert_eq!(request.resource_logs[0].scope_logs.len(), 2); +} + +#[test] +fn differing_service_names_split_resources() { + let logger = test_logger("default-svc"); + let body = CString::new("hello").unwrap(); + let service_a = CString::new("svc-a").unwrap(); + let service_b = CString::new("svc-b").unwrap(); + let records = vec![record(1, &body, Some(&service_a), None), record(2, &body, Some(&service_b), None)]; + + let request = build_batch_request(&logger, &records).expect("batch request"); + + assert_eq!(request.resource_logs.len(), 2); +} + +#[test] +fn injects_service_name_into_resource() { + let logger = test_logger("svc"); + let body = CString::new("hello").unwrap(); + let records = vec![record(1, &body, None, None)]; + + let request = build_batch_request(&logger, &records).expect("batch request"); + + let attributes = &request.resource_logs[0].resource.as_ref().expect("resource").attributes; + let service = attributes.iter().find(|kv| kv.key == "service.name").expect("service.name present"); + match service.value.as_ref().and_then(|value| value.value.as_ref()) { + Some(Value::StringValue(name)) => assert_eq!(name, "svc"), + other => panic!("unexpected service.name value: {other:?}"), + } +} + +#[test] +fn empty_slice_yields_no_resource_logs() { + let logger = test_logger("svc"); + let request = build_batch_request(&logger, &[]).expect("batch request"); + assert!(request.resource_logs.is_empty()); +} + +#[test] +fn missing_body_is_an_error() { + let logger = test_logger("svc"); + let mut bad = record(1, c"x", None, None); + bad.body = ptr::null(); + let records = vec![bad]; + + assert!(build_batch_request(&logger, &records).is_err()); +} + +#[test] +fn timestamps_are_preserved_per_record() { + let logger = test_logger("svc"); + let body = CString::new("hello").unwrap(); + let records = vec![record(111, &body, None, None), record(222, &body, None, None)]; + + let request = build_batch_request(&logger, &records).expect("batch request"); + + let logs = &request.resource_logs[0].scope_logs[0].log_records; + assert_eq!(logs[0].time_unix_nano, 111); + assert_eq!(logs[1].time_unix_nano, 222); +} + +// +// build_request (single record) +// + +#[test] +fn single_record_has_one_resource_logs_scope_logs_log_record() { + let logger = test_logger("svc"); + let body = CString::new("hello").unwrap(); + let rec = record(1, &body, None, None); + + let request = build_request(&logger, &rec).expect("build_request"); + + assert_eq!(request.resource_logs.len(), 1); + assert_eq!(request.resource_logs[0].scope_logs.len(), 1); + assert_eq!(request.resource_logs[0].scope_logs[0].log_records.len(), 1); +} + +#[test] +fn single_record_injects_service_name_in_resource() { + let logger = test_logger("my-svc"); + let body = CString::new("hello").unwrap(); + let rec = record(1, &body, None, None); + + let request = build_request(&logger, &rec).expect("build_request"); + + let attributes = &request.resource_logs[0].resource.as_ref().expect("resource").attributes; + let svc = attributes.iter().find(|kv| kv.key == "service.name").expect("service.name attribute"); + match svc.value.as_ref().and_then(|v| v.value.as_ref()) { + Some(Value::StringValue(name)) => assert_eq!(name, "my-svc"), + other => panic!("unexpected value: {other:?}"), + } +} + +#[test] +fn single_record_default_scope_name() { + let logger = test_logger("svc"); + let body = CString::new("hello").unwrap(); + let rec = record(1, &body, None, None); + + let request = build_request(&logger, &rec).expect("build_request"); + + let scope = request.resource_logs[0].scope_logs[0].scope.as_ref().expect("scope"); + assert_eq!(scope.name, "liblogjet"); +} + +#[test] +fn single_record_explicit_scope_name() { + let logger = test_logger("svc"); + let body = CString::new("hello").unwrap(); + let scope_name = CString::new("my-scope").unwrap(); + let mut rec = record(1, &body, None, None); + rec.scope_name = scope_name.as_ptr(); + + let request = build_request(&logger, &rec).expect("build_request"); + + let scope = request.resource_logs[0].scope_logs[0].scope.as_ref().expect("scope"); + assert_eq!(scope.name, "my-scope"); +} + +#[test] +fn single_record_missing_body_is_error() { + let logger = test_logger("svc"); + let mut rec = record(1, c"x", None, None); + rec.body = ptr::null(); + + assert!(build_request(&logger, &rec).is_err()); +} + +#[test] +fn single_record_zero_timestamp_is_replaced_with_now() { + let logger = test_logger("svc"); + let body = CString::new("hello").unwrap(); + let rec = record(0, &body, None, None); + + let request = build_request(&logger, &rec).expect("build_request"); + + let ts = request.resource_logs[0].scope_logs[0].log_records[0].time_unix_nano; + assert!(ts > 0); +} + +// +// build_batch_request: resource / scope attribute partitioning +// + +#[test] +fn differing_resource_attrs_split_resources() { + let logger = test_logger("svc"); + let body = CString::new("hello").unwrap(); + + let key_a = CString::new("env").unwrap(); + let val_a = CString::new("prod").unwrap(); + let key_b = CString::new("env").unwrap(); + let val_b = CString::new("staging").unwrap(); + + let attrs_a = [LjAttribute { key: key_a.as_ptr(), value: val_a.as_ptr(), value_type: LJ_ATTR_STRING }]; + let attrs_b = [LjAttribute { key: key_b.as_ptr(), value: val_b.as_ptr(), value_type: LJ_ATTR_STRING }]; + + let mut rec_a = record(1, &body, None, None); + rec_a.resource_attrs = attrs_a.as_ptr(); + rec_a.resource_attrs_len = attrs_a.len(); + + let mut rec_b = record(2, &body, None, None); + rec_b.resource_attrs = attrs_b.as_ptr(); + rec_b.resource_attrs_len = attrs_b.len(); + + let request = build_batch_request(&logger, &[rec_a, rec_b]).expect("batch request"); + assert_eq!(request.resource_logs.len(), 2); +} + +#[test] +fn differing_scope_attrs_split_scopes() { + let logger = test_logger("svc"); + let body = CString::new("hello").unwrap(); + + let key_a = CString::new("library").unwrap(); + let val_a = CString::new("fast").unwrap(); + let key_b = CString::new("library").unwrap(); + let val_b = CString::new("slow").unwrap(); + + let attrs_a = [LjAttribute { key: key_a.as_ptr(), value: val_a.as_ptr(), value_type: LJ_ATTR_STRING }]; + let attrs_b = [LjAttribute { key: key_b.as_ptr(), value: val_b.as_ptr(), value_type: LJ_ATTR_STRING }]; + + let mut rec_a = record(1, &body, None, None); + rec_a.scope_attrs = attrs_a.as_ptr(); + rec_a.scope_attrs_len = attrs_a.len(); + + let mut rec_b = record(2, &body, None, None); + rec_b.scope_attrs = attrs_b.as_ptr(); + rec_b.scope_attrs_len = attrs_b.len(); + + let request = build_batch_request(&logger, &[rec_a, rec_b]).expect("batch request"); + assert_eq!(request.resource_logs.len(), 1); + assert_eq!(request.resource_logs[0].scope_logs.len(), 2); +} + +#[test] +fn mixed_services_and_scopes_form_independent_groups() { + let logger = test_logger("default-svc"); + let body = CString::new("hello").unwrap(); + let svc_a = CString::new("svc-a").unwrap(); + let svc_b = CString::new("svc-b").unwrap(); + let scp_a = CString::new("scope-a").unwrap(); + let scp_b = CString::new("scope-b").unwrap(); + + // 2 services × 2 scopes = 4 groupings + let records = vec![ + record(1, &body, Some(&svc_a), Some(&scp_a)), + record(2, &body, Some(&svc_a), Some(&scp_b)), + record(3, &body, Some(&svc_b), Some(&scp_a)), + record(4, &body, Some(&svc_b), Some(&scp_b)), + ]; + + let request = build_batch_request(&logger, &records).expect("batch request"); + assert_eq!(request.resource_logs.len(), 2); + + let total_scopes: usize = request.resource_logs.iter().map(|rl| rl.scope_logs.len()).sum(); + assert_eq!(total_scopes, 4); + + let total_logs: usize = request.resource_logs.iter() + .flat_map(|rl| rl.scope_logs.iter()) + .map(|sl| sl.log_records.len()) + .sum(); + assert_eq!(total_logs, 4); +} + +// +// read_attrs / triples_to_kvs +// + +#[test] +fn read_attrs_null_pointer_returns_empty() { + let result = read_attrs(ptr::null(), 3).unwrap(); + assert!(result.is_empty()); +} + +#[test] +fn read_attrs_zero_len_returns_empty() { + let attr = LjAttribute { key: c"k".as_ptr(), value: c"v".as_ptr(), value_type: LJ_ATTR_STRING }; + let result = read_attrs(&attr, 0).unwrap(); + assert!(result.is_empty()); +} + +#[test] +fn read_attrs_string_type() { + let attrs = [ + LjAttribute { key: c"key".as_ptr(), value: c"val".as_ptr(), value_type: LJ_ATTR_STRING }, + ]; + let result = read_attrs(attrs.as_ptr(), attrs.len()).unwrap(); + assert_eq!(result.len(), 1); + assert_eq!(result[0], ("key".to_string(), LJ_ATTR_STRING, "val".to_string())); +} + +#[test] +fn read_attrs_int_type() { + let attrs = [ + LjAttribute { key: c"count".as_ptr(), value: c"42".as_ptr(), value_type: LJ_ATTR_INT }, + ]; + let result = read_attrs(attrs.as_ptr(), attrs.len()).unwrap(); + assert_eq!(result[0], ("count".to_string(), LJ_ATTR_INT, "42".to_string())); +} + +#[test] +fn read_attrs_array_type() { + let attrs = [ + LjAttribute { key: c"tags".as_ptr(), value: c"a, b, c".as_ptr(), value_type: LJ_ATTR_ARRAY }, + ]; + let result = read_attrs(attrs.as_ptr(), attrs.len()).unwrap(); + assert_eq!(result[0], ("tags".to_string(), LJ_ATTR_ARRAY, "a, b, c".to_string())); +} + +#[test] +fn read_attrs_null_key_is_error() { + let attrs = [ + LjAttribute { key: ptr::null(), value: c"v".as_ptr(), value_type: LJ_ATTR_STRING }, + ]; + assert!(read_attrs(attrs.as_ptr(), attrs.len()).is_err()); +} + +#[test] +fn triples_to_kvs_string_value() { + let triples = vec![("key".to_string(), LJ_ATTR_STRING, "val".to_string())]; + let kvs = triples_to_kvs(&triples).unwrap(); + assert_eq!(kvs[0].key, "key"); + if let Some(ref v) = kvs[0].value + && let Some(Value::StringValue(s)) = &v.value { + assert_eq!(s, "val"); + return; + } + panic!("unexpected value"); +} + +#[test] +fn triples_to_kvs_int_value() { + let triples = vec![("count".to_string(), LJ_ATTR_INT, "42".to_string())]; + let kvs = triples_to_kvs(&triples).unwrap(); + if let Some(ref v) = kvs[0].value + && let Some(Value::IntValue(i)) = &v.value { + assert_eq!(*i, 42); + return; + } + panic!("unexpected value"); +} + +#[test] +fn triples_to_kvs_array_value() { + let triples = vec![("tags".to_string(), LJ_ATTR_ARRAY, "a, b, c".to_string())]; + let kvs = triples_to_kvs(&triples).unwrap(); + if let Some(ref v) = kvs[0].value + && let Some(Value::ArrayValue(arr)) = &v.value { + let items: Vec<&str> = arr.values.iter().filter_map(|av| match &av.value { + Some(Value::StringValue(s)) => Some(s.as_str()), + _ => None, + }).collect(); + assert_eq!(items, vec!["a", "b", "c"]); + return; + } + panic!("unexpected value"); +} + +#[test] +fn triples_to_kvs_unknown_type_is_error() { + let triples = vec![("key".to_string(), 99, "val".to_string())]; + assert!(triples_to_kvs(&triples).is_err()); +} + +// +// resolve_resource / resolve_scope +// + +#[test] +fn resolve_resource_falls_back_to_logger_service_name() { + let logger = test_logger("default-svc"); + let body = CString::new("hello").unwrap(); + let rec = record(1, &body, None, None); // service_name = null + + let (key, attrs) = resolve_resource(&logger, &rec).unwrap(); + assert_eq!(key.0, "default-svc"); + let svc = attrs.iter().find(|kv| kv.key == "service.name").expect("service.name"); + if let Some(ref v) = svc.value + && let Some(Value::StringValue(s)) = &v.value { + assert_eq!(s, "default-svc"); + return; + } + panic!("unexpected service.name value"); +} + +#[test] +fn resolve_resource_empty_service_name_is_error() { + let mut logger = test_logger(""); + let body = CString::new("hello").unwrap(); + let rec = record(1, &body, None, None); + + // Records with null service_name that resolve to "" logger default. + logger.service_name = String::new(); + assert!(resolve_resource(&logger, &rec).is_err()); +} + +#[test] +fn resolve_scope_defaults_to_liblogjet() { + let body = CString::new("hello").unwrap(); + let rec = record(1, &body, None, None); // scope_name = null + + let (key, scope) = resolve_scope(&rec).unwrap(); + assert_eq!(key.0, "liblogjet"); + assert_eq!(scope.name, "liblogjet"); +} + +// +// record_to_log +// + +#[test] +fn record_to_log_defaults_severity_text_from_number() { + let body = CString::new("hello").unwrap(); + let rec = record(1, &body, None, None); // severity_text = null, severity_number = 9 = INFO + + let log = record_to_log(&rec).unwrap(); + assert_eq!(log.severity_text, "INFO"); +} + +#[test] +fn record_to_log_respects_explicit_severity_text() { + let body = CString::new("hello").unwrap(); + let sev = CString::new("WARN").unwrap(); + let mut rec = record(1, &body, None, None); + rec.severity_text = sev.as_ptr(); + + let log = record_to_log(&rec).unwrap(); + assert_eq!(log.severity_text, "WARN"); +} + +#[test] +fn record_to_log_defaults_event_name_to_empty() { + let body = CString::new("hello").unwrap(); + let rec = record(1, &body, None, None); // event_name = null + + let log = record_to_log(&rec).unwrap(); + assert_eq!(log.event_name, ""); +} + +#[test] +fn record_to_log_zero_timestamp_replaced_with_now() { + let body = CString::new("hello").unwrap(); + let rec = record(0, &body, None, None); + + let log = record_to_log(&rec).unwrap(); + assert!(log.time_unix_nano > 0); +} + +// +// severity_text +// + +#[test] +fn severity_text_maps_correctly() { + assert_eq!(severity_text(1), "TRACE"); + assert_eq!(severity_text(4), "TRACE"); + assert_eq!(severity_text(5), "DEBUG"); + assert_eq!(severity_text(9), "INFO"); + assert_eq!(severity_text(13), "WARN"); + assert_eq!(severity_text(17), "ERROR"); + assert_eq!(severity_text(21), "FATAL"); +} + +// +// parse_http_endpoint / normalise_grpc_endpoint +// + +#[test] +fn parse_http_host_port_defaults_path() { + let ep = parse_http_endpoint("127.0.0.1:4318").unwrap(); + assert_eq!(ep.authority, "127.0.0.1:4318"); + assert_eq!(ep.host_header, "127.0.0.1:4318"); + assert_eq!(ep.path, "/v1/logs"); +} + +#[test] +fn parse_http_with_custom_path() { + let ep = parse_http_endpoint("127.0.0.1:4318/custom/path").unwrap(); + assert_eq!(ep.authority, "127.0.0.1:4318"); + assert_eq!(ep.path, "/custom/path"); +} + +#[test] +fn parse_http_scheme_is_stripped() { + let ep = parse_http_endpoint("http://127.0.0.1:4318").unwrap(); + assert_eq!(ep.authority, "127.0.0.1:4318"); + assert_eq!(ep.path, "/v1/logs"); +} + +#[test] +fn parse_http_with_scheme_and_path() { + let ep = parse_http_endpoint("http://127.0.0.1:4318/p").unwrap(); + assert_eq!(ep.authority, "127.0.0.1:4318"); + assert_eq!(ep.path, "/p"); +} + +#[test] +fn parse_https_is_rejected() { + assert!(parse_http_endpoint("https://127.0.0.1:4318").is_err()); +} + +#[test] +fn parse_http_empty_is_error() { + assert!(parse_http_endpoint("").is_err()); +} + +#[test] +fn normalise_grpc_adds_http_scheme() { + assert_eq!(normalise_grpc_endpoint("127.0.0.1:4317"), "http://127.0.0.1:4317"); +} + +#[test] +fn normalise_grpc_preserves_existing_scheme() { + assert_eq!(normalise_grpc_endpoint("http://127.0.0.1:4317"), "http://127.0.0.1:4317"); +} diff --git a/ljx/src/commands/export.rs b/ljx/src/commands/export.rs index de61bdb..2abb243 100644 --- a/ljx/src/commands/export.rs +++ b/ljx/src/commands/export.rs @@ -473,7 +473,8 @@ fn data_point_value_to_json(value: &opentelemetry_proto::tonic::metrics::v1::num } } -fn flatten_otlp_attrs_into_json( target: &mut JsonMap, attrs: &[opentelemetry_proto::tonic::common::v1::KeyValue], preview_bytes: Option, +fn flatten_otlp_attrs_into_json( + target: &mut JsonMap, attrs: &[opentelemetry_proto::tonic::common::v1::KeyValue], preview_bytes: Option, ) { for attr in attrs { let key = attr.key.replace('.', "_"); diff --git a/ljx/src/commands/view/detail.rs b/ljx/src/commands/view/detail.rs index 588628a..74e3566 100644 --- a/ljx/src/commands/view/detail.rs +++ b/ljx/src/commands/view/detail.rs @@ -1,9 +1,9 @@ use chrono::{TimeZone, Utc}; use opentelemetry_proto::tonic::collector::logs::v1::ExportLogsServiceRequest; use opentelemetry_proto::tonic::collector::metrics::v1::ExportMetricsServiceRequest; +use opentelemetry_proto::tonic::collector::trace::v1::ExportTraceServiceRequest; use opentelemetry_proto::tonic::common::v1::any_value::Value; use opentelemetry_proto::tonic::common::v1::{AnyValue, KeyValue}; -use opentelemetry_proto::tonic::collector::trace::v1::ExportTraceServiceRequest; use opentelemetry_proto::tonic::metrics::v1::metric::Data as MetricData; use prost::Message; use ratatui::style::{Color, Modifier, Style}; @@ -289,11 +289,7 @@ pub(crate) fn extract_otlp_metrics_summary(payload: &[u8]) -> Option { } } - if parts.is_empty() { - None - } else { - Some(parts.join(", ")) - } + if parts.is_empty() { None } else { Some(parts.join(", ")) } } pub(crate) fn extract_otlp_traces_summary(payload: &[u8]) -> Option { @@ -315,11 +311,7 @@ pub(crate) fn extract_otlp_traces_summary(payload: &[u8]) -> Option { } } - if parts.is_empty() { - None - } else { - Some(parts.join(", ")) - } + if parts.is_empty() { None } else { Some(parts.join(", ")) } } pub(crate) fn extract_otlp_traces_message(payload: &[u8]) -> Option { @@ -353,11 +345,7 @@ pub(crate) fn extract_otlp_traces_message(payload: &[u8]) -> Option { } } - if lines.is_empty() { - None - } else { - Some(lines.join("\n")) - } + if lines.is_empty() { None } else { Some(lines.join("\n")) } } fn format_span_kind(kind: i32) -> String { @@ -393,13 +381,22 @@ pub(crate) fn extract_otlp_metrics_message(payload: &[u8]) -> Option { Some(Data::Gauge(g)) => { lines.push(" Type: Gauge".to_string()); for dp in &g.data_points { - lines.push(format!(" - time={}, value={}", format_timestamp(dp.time_unix_nano), dp.value.as_ref().map(format_data_point_value).unwrap_or_default())); + lines.push(format!( + " - time={}, value={}", + format_timestamp(dp.time_unix_nano), + dp.value.as_ref().map(format_data_point_value).unwrap_or_default() + )); } } Some(Data::Sum(s)) => { lines.push(format!(" Type: Sum (monotonic={}, temporality={})", s.is_monotonic, s.aggregation_temporality)); for dp in &s.data_points { - lines.push(format!(" - time={}, start_time={}, value={}", format_timestamp(dp.time_unix_nano), format_timestamp(dp.start_time_unix_nano), dp.value.as_ref().map(format_data_point_value).unwrap_or_default())); + lines.push(format!( + " - time={}, start_time={}, value={}", + format_timestamp(dp.time_unix_nano), + format_timestamp(dp.start_time_unix_nano), + dp.value.as_ref().map(format_data_point_value).unwrap_or_default() + )); } } Some(Data::Histogram(h)) => { @@ -427,11 +424,7 @@ pub(crate) fn extract_otlp_metrics_message(payload: &[u8]) -> Option { } } - if lines.is_empty() { - None - } else { - Some(lines.join("\n")) - } + if lines.is_empty() { None } else { Some(lines.join("\n")) } } fn format_data_point_value(value: &opentelemetry_proto::tonic::metrics::v1::number_data_point::Value) -> String { @@ -624,7 +617,7 @@ fn render_modal_metrics_info_entries(detail: &DetailRecord) -> Vec<(String, Stri for resource_metrics in &batch.resource_metrics { for scope_metrics in &resource_metrics.scope_metrics { for metric in &scope_metrics.metrics { - let prefix = format!("metric.{}" , metric.name); + let prefix = format!("metric.{}", metric.name); entries.push((format!("{prefix}.unit"), metric.unit.clone())); if !metric.description.is_empty() { entries.push((format!("{prefix}.description"), metric.description.clone())); @@ -1018,7 +1011,9 @@ fn export_metrics_ndjson(detail: &DetailRecord) -> Vec { fn data_point_value_to_json(value: &opentelemetry_proto::tonic::metrics::v1::number_data_point::Value) -> JsonValue { match value { - opentelemetry_proto::tonic::metrics::v1::number_data_point::Value::AsDouble(v) => serde_json::Number::from_f64(*v).map(JsonValue::Number).unwrap_or(JsonValue::Null), + opentelemetry_proto::tonic::metrics::v1::number_data_point::Value::AsDouble(v) => { + serde_json::Number::from_f64(*v).map(JsonValue::Number).unwrap_or(JsonValue::Null) + } opentelemetry_proto::tonic::metrics::v1::number_data_point::Value::AsInt(v) => JsonValue::Number((*v).into()), } } diff --git a/ljx/tests/unit/commands/export_ut.rs b/ljx/tests/unit/commands/export_ut.rs index 0694de1..7fcf394 100644 --- a/ljx/tests/unit/commands/export_ut.rs +++ b/ljx/tests/unit/commands/export_ut.rs @@ -162,12 +162,20 @@ fn export_ndjson_objects_includes_otlp_metrics_fields() { let batch = ExportMetricsServiceRequest { resource_metrics: vec![ResourceMetrics { resource: Some(Resource { - attributes: vec![KeyValue { key: "service.name".to_string(), value: Some(AnyValue { value: Some(Value::StringValue("metrics-svc".to_string())) }) }], + attributes: vec![KeyValue { + key: "service.name".to_string(), + value: Some(AnyValue { value: Some(Value::StringValue("metrics-svc".to_string())) }), + }], dropped_attributes_count: 0, entity_refs: vec![], }), scope_metrics: vec![ScopeMetrics { - scope: Some(InstrumentationScope { name: "demo.metrics.scope".to_string(), version: "1.0.0".to_string(), attributes: vec![], dropped_attributes_count: 0 }), + scope: Some(InstrumentationScope { + name: "demo.metrics.scope".to_string(), + version: "1.0.0".to_string(), + attributes: vec![], + dropped_attributes_count: 0, + }), metrics: vec![metric], schema_url: String::new(), }], @@ -194,12 +202,20 @@ fn export_ndjson_objects_includes_otlp_traces_fields() { let batch = ExportTraceServiceRequest { resource_spans: vec![ResourceSpans { resource: Some(Resource { - attributes: vec![KeyValue { key: "service.name".to_string(), value: Some(AnyValue { value: Some(Value::StringValue("traces-svc".to_string())) }) }], + attributes: vec![KeyValue { + key: "service.name".to_string(), + value: Some(AnyValue { value: Some(Value::StringValue("traces-svc".to_string())) }), + }], dropped_attributes_count: 0, entity_refs: vec![], }), scope_spans: vec![ScopeSpans { - scope: Some(InstrumentationScope { name: "demo.traces.scope".to_string(), version: "2.0.0".to_string(), attributes: vec![], dropped_attributes_count: 0 }), + scope: Some(InstrumentationScope { + name: "demo.traces.scope".to_string(), + version: "2.0.0".to_string(), + attributes: vec![], + dropped_attributes_count: 0, + }), spans: vec![Span { trace_id: vec![1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16], span_id: vec![16, 17, 18, 19, 20, 21, 22, 23], @@ -208,7 +224,10 @@ fn export_ndjson_objects_includes_otlp_traces_fields() { kind: 2, start_time_unix_nano: 1_700_000_000_000_000_000, end_time_unix_nano: 1_700_000_000_000_000_100, - attributes: vec![KeyValue { key: "http.method".to_string(), value: Some(AnyValue { value: Some(Value::StringValue("GET".to_string())) }) }], + attributes: vec![KeyValue { + key: "http.method".to_string(), + value: Some(AnyValue { value: Some(Value::StringValue("GET".to_string())) }), + }], dropped_attributes_count: 0, events: vec![], dropped_events_count: 0, diff --git a/ljx/tests/unit/commands/view_ut.rs b/ljx/tests/unit/commands/view_ut.rs index 37daf65..62be42a 100644 --- a/ljx/tests/unit/commands/view_ut.rs +++ b/ljx/tests/unit/commands/view_ut.rs @@ -115,7 +115,7 @@ fn modal_info_lists_otlp_attributes() { value: Some(Value::ArrayValue(opentelemetry_proto::tonic::common::v1::ArrayValue { values: vec![ AnyValue { value: Some(Value::StringValue("de".to_string())) }, - AnyValue { value: Some(Value::StringValue("eso".to_string())) }, + AnyValue { value: Some(Value::StringValue("demo".to_string())) }, ], })), }), @@ -159,7 +159,7 @@ fn modal_info_lists_otlp_attributes() { let entries = render_modal_info_entries(&detail); assert!(entries.iter().any(|(key, value)| key == "resource.service.name" && value == "cpp-appliance")); assert!(entries.iter().any(|(key, value)| key == "scope.demo.channel" && value == "de")); - assert!(entries.iter().any(|(key, value)| key.is_empty() && value == "eso")); + assert!(entries.iter().any(|(key, value)| key.is_empty() && value == "demo")); assert!(entries.iter().any(|(key, value)| key == "record.character" && value == "Bender")); } @@ -891,7 +891,12 @@ fn summary_decodes_otlp_metrics_payload() { resource_metrics: vec![ResourceMetrics { resource: Some(Resource { attributes: vec![], dropped_attributes_count: 0, entity_refs: vec![] }), scope_metrics: vec![ScopeMetrics { - scope: Some(InstrumentationScope { name: "test".to_string(), version: String::new(), attributes: vec![], dropped_attributes_count: 0 }), + scope: Some(InstrumentationScope { + name: "test".to_string(), + version: String::new(), + attributes: vec![], + dropped_attributes_count: 0, + }), metrics: vec![metric], schema_url: String::new(), }], @@ -900,7 +905,14 @@ fn summary_decodes_otlp_metrics_payload() { }; let payload = batch.encode_to_vec(); let detail = DetailRecord { - meta: EntryMeta { offset: 0, record_type: RecordType::Metrics, seq: 1, ts_unix_ns: 2, payload_len: payload.len() as u64, source_path: "a.logjet".into() }, + meta: EntryMeta { + offset: 0, + record_type: RecordType::Metrics, + seq: 1, + ts_unix_ns: 2, + payload_len: payload.len() as u64, + source_path: "a.logjet".into(), + }, payload, }; assert_eq!(format_summary(&detail, false), "cpu.usage=45.5%"); @@ -932,7 +944,12 @@ fn modal_message_decodes_otlp_metrics_payload() { resource_metrics: vec![ResourceMetrics { resource: Some(Resource { attributes: vec![], dropped_attributes_count: 0, entity_refs: vec![] }), scope_metrics: vec![ScopeMetrics { - scope: Some(InstrumentationScope { name: "test".to_string(), version: String::new(), attributes: vec![], dropped_attributes_count: 0 }), + scope: Some(InstrumentationScope { + name: "test".to_string(), + version: String::new(), + attributes: vec![], + dropped_attributes_count: 0, + }), metrics: vec![metric], schema_url: String::new(), }], @@ -941,7 +958,14 @@ fn modal_message_decodes_otlp_metrics_payload() { }; let payload = batch.encode_to_vec(); let detail = DetailRecord { - meta: EntryMeta { offset: 0, record_type: RecordType::Metrics, seq: 1, ts_unix_ns: 2, payload_len: payload.len() as u64, source_path: "a.logjet".into() }, + meta: EntryMeta { + offset: 0, + record_type: RecordType::Metrics, + seq: 1, + ts_unix_ns: 2, + payload_len: payload.len() as u64, + source_path: "a.logjet".into(), + }, payload, }; let message = render_modal_message(&detail, false); @@ -975,7 +999,12 @@ fn modal_info_entries_decodes_otlp_metrics_payload() { resource_metrics: vec![ResourceMetrics { resource: Some(Resource { attributes: vec![], dropped_attributes_count: 0, entity_refs: vec![] }), scope_metrics: vec![ScopeMetrics { - scope: Some(InstrumentationScope { name: "test".to_string(), version: String::new(), attributes: vec![], dropped_attributes_count: 0 }), + scope: Some(InstrumentationScope { + name: "test".to_string(), + version: String::new(), + attributes: vec![], + dropped_attributes_count: 0, + }), metrics: vec![metric], schema_url: String::new(), }], @@ -984,7 +1013,14 @@ fn modal_info_entries_decodes_otlp_metrics_payload() { }; let payload = batch.encode_to_vec(); let detail = DetailRecord { - meta: EntryMeta { offset: 0, record_type: RecordType::Metrics, seq: 1, ts_unix_ns: 2, payload_len: payload.len() as u64, source_path: "a.logjet".into() }, + meta: EntryMeta { + offset: 0, + record_type: RecordType::Metrics, + seq: 1, + ts_unix_ns: 2, + payload_len: payload.len() as u64, + source_path: "a.logjet".into(), + }, payload, }; let entries = render_modal_info_entries(&detail); @@ -1006,43 +1042,48 @@ fn summary_decodes_otlp_traces_payload() { entity_refs: vec![], }), scope_spans: vec![ScopeSpans { - scope: Some(InstrumentationScope { name: "test".to_string(), version: String::new(), attributes: vec![], dropped_attributes_count: 0 }), + scope: Some(InstrumentationScope { + name: "test".to_string(), + version: String::new(), + attributes: vec![], + dropped_attributes_count: 0, + }), spans: vec![ Span { trace_id: vec![1, 2, 3, 4], span_id: vec![5, 6, 7, 8], parent_span_id: vec![], name: "GET /api".to_string(), - kind: 2, - start_time_unix_nano: 1_700_000_000_000_000_000, - end_time_unix_nano: 1_700_000_000_000_000_100, - attributes: vec![], - dropped_attributes_count: 0, - events: vec![], - dropped_events_count: 0, - links: vec![], - dropped_links_count: 0, - status: None, - flags: 0, - trace_state: String::new(), - }, - Span { - trace_id: vec![1, 2, 3, 4], - span_id: vec![9, 10, 11, 12], - parent_span_id: vec![5, 6, 7, 8], - name: "SELECT".to_string(), - kind: 3, - start_time_unix_nano: 1_700_000_000_000_000_050, - end_time_unix_nano: 1_700_000_000_000_000_080, - attributes: vec![], - dropped_attributes_count: 0, - events: vec![], - dropped_events_count: 0, - links: vec![], - dropped_links_count: 0, - status: None, - flags: 0, - trace_state: String::new(), + kind: 2, + start_time_unix_nano: 1_700_000_000_000_000_000, + end_time_unix_nano: 1_700_000_000_000_000_100, + attributes: vec![], + dropped_attributes_count: 0, + events: vec![], + dropped_events_count: 0, + links: vec![], + dropped_links_count: 0, + status: None, + flags: 0, + trace_state: String::new(), + }, + Span { + trace_id: vec![1, 2, 3, 4], + span_id: vec![9, 10, 11, 12], + parent_span_id: vec![5, 6, 7, 8], + name: "SELECT".to_string(), + kind: 3, + start_time_unix_nano: 1_700_000_000_000_000_050, + end_time_unix_nano: 1_700_000_000_000_000_080, + attributes: vec![], + dropped_attributes_count: 0, + events: vec![], + dropped_events_count: 0, + links: vec![], + dropped_links_count: 0, + status: None, + flags: 0, + trace_state: String::new(), }, ], schema_url: String::new(), @@ -1052,7 +1093,14 @@ fn summary_decodes_otlp_traces_payload() { }; let payload = batch.encode_to_vec(); let detail = DetailRecord { - meta: EntryMeta { offset: 0, record_type: RecordType::Traces, seq: 1, ts_unix_ns: 2, payload_len: payload.len() as u64, source_path: "a.logjet".into() }, + meta: EntryMeta { + offset: 0, + record_type: RecordType::Traces, + seq: 1, + ts_unix_ns: 2, + payload_len: payload.len() as u64, + source_path: "a.logjet".into(), + }, payload, }; let summary = format_summary(&detail, false); @@ -1066,7 +1114,12 @@ fn modal_message_decodes_otlp_traces_payload() { resource_spans: vec![ResourceSpans { resource: Some(Resource { attributes: vec![], dropped_attributes_count: 0, entity_refs: vec![] }), scope_spans: vec![ScopeSpans { - scope: Some(InstrumentationScope { name: "test".to_string(), version: String::new(), attributes: vec![], dropped_attributes_count: 0 }), + scope: Some(InstrumentationScope { + name: "test".to_string(), + version: String::new(), + attributes: vec![], + dropped_attributes_count: 0, + }), spans: vec![Span { trace_id: vec![1, 2, 3, 4], span_id: vec![5, 6, 7, 8], @@ -1092,7 +1145,14 @@ fn modal_message_decodes_otlp_traces_payload() { }; let payload = batch.encode_to_vec(); let detail = DetailRecord { - meta: EntryMeta { offset: 0, record_type: RecordType::Traces, seq: 1, ts_unix_ns: 2, payload_len: payload.len() as u64, source_path: "a.logjet".into() }, + meta: EntryMeta { + offset: 0, + record_type: RecordType::Traces, + seq: 1, + ts_unix_ns: 2, + payload_len: payload.len() as u64, + source_path: "a.logjet".into(), + }, payload, }; let message = render_modal_message(&detail, false); @@ -1114,7 +1174,12 @@ fn modal_info_entries_decodes_otlp_traces_payload() { entity_refs: vec![], }), scope_spans: vec![ScopeSpans { - scope: Some(InstrumentationScope { name: "test".to_string(), version: String::new(), attributes: vec![], dropped_attributes_count: 0 }), + scope: Some(InstrumentationScope { + name: "test".to_string(), + version: String::new(), + attributes: vec![], + dropped_attributes_count: 0, + }), spans: vec![ Span { trace_id: vec![1, 2, 3, 4], @@ -1160,7 +1225,14 @@ fn modal_info_entries_decodes_otlp_traces_payload() { }; let payload = batch.encode_to_vec(); let detail = DetailRecord { - meta: EntryMeta { offset: 0, record_type: RecordType::Traces, seq: 1, ts_unix_ns: 2, payload_len: payload.len() as u64, source_path: "a.logjet".into() }, + meta: EntryMeta { + offset: 0, + record_type: RecordType::Traces, + seq: 1, + ts_unix_ns: 2, + payload_len: payload.len() as u64, + source_path: "a.logjet".into(), + }, payload, }; let entries = render_modal_info_entries(&detail); diff --git a/logjetd/src/daemon.rs b/logjetd/src/daemon.rs index 9275cca..6a30cf6 100644 --- a/logjetd/src/daemon.rs +++ b/logjetd/src/daemon.rs @@ -284,8 +284,10 @@ fn ingest_loop( ); let runtime = tokio::runtime::Builder::new_multi_thread().enable_all().build().map_err(|err| io::Error::other(err.to_string()))?; - let logs_service = OtlpGrpcLogsService { spool: Arc::clone(&spool), next_seq: Arc::clone(&next_seq), ingest_policy: Arc::clone(&ingest_policy) }; - let metrics_service = OtlpGrpcMetricsService { spool: Arc::clone(&spool), next_seq: Arc::clone(&next_seq), ingest_policy: Arc::clone(&ingest_policy) }; + let logs_service = + OtlpGrpcLogsService { spool: Arc::clone(&spool), next_seq: Arc::clone(&next_seq), ingest_policy: Arc::clone(&ingest_policy) }; + let metrics_service = + OtlpGrpcMetricsService { spool: Arc::clone(&spool), next_seq: Arc::clone(&next_seq), ingest_policy: Arc::clone(&ingest_policy) }; let traces_service = OtlpGrpcTracesService { spool, next_seq, ingest_policy }; let grpc_tls = if ingest_tls.enable { Some(build_grpc_server_tls_config(&ingest_tls)?) } else { None }; @@ -365,15 +367,8 @@ async fn serve_otlp_http_connection( return Ok(()); }; - let svc = service_fn(move |req| { - handle_otlp_http_request( - req, - Arc::clone(&spool), - Arc::clone(&ingest_policy), - Arc::clone(&next_seq), - max_batch_bytes, - ) - }); + let svc = + service_fn(move |req| handle_otlp_http_request(req, Arc::clone(&spool), Arc::clone(&ingest_policy), Arc::clone(&next_seq), max_batch_bytes)); if let Some(acceptor) = tls_acceptor { let tls_stream = acceptor.accept(stream).await.map_err(|err| io::Error::other(err.to_string()))?; @@ -398,8 +393,7 @@ where let is_metrics = req.uri().path() == "/v1/metrics"; let is_traces = req.uri().path() == "/v1/traces"; - let content_encoding = - req.headers().get("content-encoding").and_then(|v| v.to_str().ok()).map(|s| s.to_string()); + let content_encoding = req.headers().get("content-encoding").and_then(|v| v.to_str().ok()).map(|s| s.to_string()); let (parts, body) = req.into_parts(); @@ -407,8 +401,8 @@ where if let Some(len) = parts.headers.get("content-length").and_then(|v| v.to_str().ok()).and_then(|v| v.parse::().ok()) && len > max_batch_bytes { - ingest_policy.note_oversize()?; - return Ok(HyperResponse::builder().status(StatusCode::PAYLOAD_TOO_LARGE).body(Full::new(Bytes::from("payload too large"))).unwrap()); + ingest_policy.note_oversize()?; + return Ok(HyperResponse::builder().status(StatusCode::PAYLOAD_TOO_LARGE).body(Full::new(Bytes::from("payload too large"))).unwrap()); } let collected = body.collect().await.map_err(|err| io::Error::other(format!("failed to read request body: {err}")))?; @@ -448,10 +442,9 @@ where append_batch_record(&spool, record)?; Ok(HyperResponse::builder().status(StatusCode::OK).body(Full::new(Bytes::new())).unwrap()) } - Err(err) => Ok(HyperResponse::builder() - .status(StatusCode::BAD_REQUEST) - .body(Full::new(Bytes::from(format!("decode error: {err}")))) - .unwrap()), + Err(err) => { + Ok(HyperResponse::builder().status(StatusCode::BAD_REQUEST).body(Full::new(Bytes::from(format!("decode error: {err}")))).unwrap()) + } } } else if is_traces { match ExportTraceServiceRequest::decode(body_vec.as_slice()) { @@ -472,10 +465,9 @@ where append_batch_record(&spool, record)?; Ok(HyperResponse::builder().status(StatusCode::OK).body(Full::new(Bytes::new())).unwrap()) } - Err(err) => Ok(HyperResponse::builder() - .status(StatusCode::BAD_REQUEST) - .body(Full::new(Bytes::from(format!("decode error: {err}")))) - .unwrap()), + Err(err) => { + Ok(HyperResponse::builder().status(StatusCode::BAD_REQUEST).body(Full::new(Bytes::from(format!("decode error: {err}")))).unwrap()) + } } } else { match ExportLogsServiceRequest::decode(body_vec.as_slice()) { @@ -496,10 +488,9 @@ where append_batch_record(&spool, record)?; Ok(HyperResponse::builder().status(StatusCode::OK).body(Full::new(Bytes::new())).unwrap()) } - Err(err) => Ok(HyperResponse::builder() - .status(StatusCode::BAD_REQUEST) - .body(Full::new(Bytes::from(format!("decode error: {err}")))) - .unwrap()), + Err(err) => { + Ok(HyperResponse::builder().status(StatusCode::BAD_REQUEST).body(Full::new(Bytes::from(format!("decode error: {err}")))).unwrap()) + } } } } diff --git a/logjetd/src/replay.rs b/logjetd/src/replay.rs index 5b6d6c1..2015455 100644 --- a/logjetd/src/replay.rs +++ b/logjetd/src/replay.rs @@ -345,10 +345,18 @@ impl BridgeStats { fn drop_summary(&self) -> String { let mut parts = Vec::new(); - if self.drops_logs > 0 { parts.push(format!("logs_drops={}", self.drops_logs)); } - if self.drops_metrics > 0 { parts.push(format!("metrics_drops={}", self.drops_metrics)); } - if self.drops_traces > 0 { parts.push(format!("traces_drops={}", self.drops_traces)); } - if self.drops_events > 0 { parts.push(format!("events_drops={}", self.drops_events)); } + if self.drops_logs > 0 { + parts.push(format!("logs_drops={}", self.drops_logs)); + } + if self.drops_metrics > 0 { + parts.push(format!("metrics_drops={}", self.drops_metrics)); + } + if self.drops_traces > 0 { + parts.push(format!("traces_drops={}", self.drops_traces)); + } + if self.drops_events > 0 { + parts.push(format!("events_drops={}", self.drops_events)); + } if parts.is_empty() { "drops=0".to_string() } else { parts.join(" ") } } @@ -551,7 +559,8 @@ impl GrpcCollectorConnection { } fn reconnect(&mut self) -> io::Result<()> { - let (client, metrics_client, traces_client) = self.runtime.block_on(connect_grpc_with_collector(&self.endpoint, self.timeout, Some(&self.collector)))?; + let (client, metrics_client, traces_client) = + self.runtime.block_on(connect_grpc_with_collector(&self.endpoint, self.timeout, Some(&self.collector)))?; self.client = client; self.metrics_client = metrics_client; self.traces_client = traces_client; diff --git a/logjetd/tests/bridge_flows.rs b/logjetd/tests/bridge_flows.rs index e8fca39..2e632be 100644 --- a/logjetd/tests/bridge_flows.rs +++ b/logjetd/tests/bridge_flows.rs @@ -7,8 +7,8 @@ use std::thread; use std::time::Duration; use common::{ - ChildGuard, MockCollector, MockGrpcCollector, ReservedPort, TestDir, connect_replay_client, ensure_rustls_provider, free_port, ljd_command, post_otlp_http, - read_replay_message, replay_messages, reserve_port, wait_for_tcp, wait_until, write_fake_grpc_tls_files, + ChildGuard, MockCollector, MockGrpcCollector, ReservedPort, TestDir, connect_replay_client, ensure_rustls_provider, free_port, ljd_command, + post_otlp_http, read_replay_message, replay_messages, reserve_port, wait_for_tcp, wait_until, write_fake_grpc_tls_files, }; fn http_collector(port: ReservedPort) -> io::Result { diff --git a/logjetd/tests/unit/daemon_utst.rs b/logjetd/tests/unit/daemon_utst.rs index dabcd46..40bc565 100644 --- a/logjetd/tests/unit/daemon_utst.rs +++ b/logjetd/tests/unit/daemon_utst.rs @@ -48,9 +48,7 @@ async fn handle_otlp_http_request_logs_accepts_valid_batch() { log_records: vec![LogRecord { severity_number: 13, severity_text: "WARN".to_string(), - body: Some(AnyValue { - value: Some(opentelemetry_proto::tonic::common::v1::any_value::Value::StringValue("warn".to_string())), - }), + body: Some(AnyValue { value: Some(opentelemetry_proto::tonic::common::v1::any_value::Value::StringValue("warn".to_string())) }), ..Default::default() }], schema_url: String::new(), @@ -223,11 +221,7 @@ async fn handle_otlp_http_request_unknown_path_returns_404() { })); let next_seq = Arc::new(AtomicU64::new(1)); - let req = Request::builder() - .method(Method::POST) - .uri("/v1/unknown") - .body(Full::new(Bytes::new())) - .unwrap(); + let req = Request::builder().method(Method::POST).uri("/v1/unknown").body(Full::new(Bytes::new())).unwrap(); let response = handle_otlp_http_request(req, shared_spool, policy, next_seq, 1024).await.unwrap(); assert_eq!(response.status(), StatusCode::NOT_FOUND); } @@ -475,7 +469,12 @@ fn extract_batch_timestamp_metrics_finds_first_datapoint_time() { resource_metrics: vec![ResourceMetrics { resource: Some(Resource { attributes: vec![], dropped_attributes_count: 0, entity_refs: vec![] }), scope_metrics: vec![ScopeMetrics { - scope: Some(InstrumentationScope { name: "test".to_string(), version: String::new(), attributes: vec![], dropped_attributes_count: 0 }), + scope: Some(InstrumentationScope { + name: "test".to_string(), + version: String::new(), + attributes: vec![], + dropped_attributes_count: 0, + }), metrics: vec![metric], schema_url: String::new(), }], @@ -497,7 +496,12 @@ fn extract_batch_timestamp_traces_finds_first_span_start_time() { resource_spans: vec![ResourceSpans { resource: Some(Resource { attributes: vec![], dropped_attributes_count: 0, entity_refs: vec![] }), scope_spans: vec![ScopeSpans { - scope: Some(InstrumentationScope { name: "test".to_string(), version: String::new(), attributes: vec![], dropped_attributes_count: 0 }), + scope: Some(InstrumentationScope { + name: "test".to_string(), + version: String::new(), + attributes: vec![], + dropped_attributes_count: 0, + }), spans: vec![Span { trace_id: vec![1, 2, 3, 4], span_id: vec![5, 6, 7, 8], diff --git a/plugins/parquet-exporter/src/lib.rs b/plugins/parquet-exporter/src/lib.rs index 123d710..55e69bd 100644 --- a/plugins/parquet-exporter/src/lib.rs +++ b/plugins/parquet-exporter/src/lib.rs @@ -135,11 +135,7 @@ impl ParquetExporter { if record.struct_size < std::mem::size_of::() as u32 { return self.fail_status( LJX_EXPORT_STATUS_BAD_ARG, - format!( - "record struct_size {} is smaller than host ABI expects {}", - record.struct_size, - std::mem::size_of::() - ), + format!("record struct_size {} is smaller than host ABI expects {}", record.struct_size, std::mem::size_of::()), ); } if record.payload.ptr.is_null() && record.payload.len != 0 { @@ -246,7 +242,7 @@ impl ParquetExporter { let request = match ExportMetricsServiceRequest::decode(payload) { Ok(request) => request, Err(err) => { - return self.fail_status(LJX_EXPORT_STATUS_ERROR, format!("failed to decode OTLP metrics payload at seq {}: {err}", record.seq)) + return self.fail_status(LJX_EXPORT_STATUS_ERROR, format!("failed to decode OTLP metrics payload at seq {}: {err}", record.seq)); } }; @@ -269,7 +265,18 @@ impl ParquetExporter { match data { MetricData::Gauge(gauge) => { for dp in &gauge.data_points { - let mut row = self.base_metrics_row(record, &service_name, &resource_attributes_json, scope_name, scope_version, &scope_attributes_json, &metric_name, &metric_description, &metric_unit, "Gauge"); + let mut row = self.base_metrics_row( + record, + &service_name, + &resource_attributes_json, + scope_name, + scope_version, + &scope_attributes_json, + &metric_name, + &metric_description, + &metric_unit, + "Gauge", + ); row.metric_value_number = dp.value.as_ref().and_then(number_data_point_value_f64); row.timestamp_unix_ns = Some(dp.time_unix_nano.max(record.timestamp_unix_ns)); row.start_time_unix_ns = zero_is_none(dp.start_time_unix_nano); @@ -279,7 +286,18 @@ impl ParquetExporter { } MetricData::Sum(sum) => { for dp in &sum.data_points { - let mut row = self.base_metrics_row(record, &service_name, &resource_attributes_json, scope_name, scope_version, &scope_attributes_json, &metric_name, &metric_description, &metric_unit, "Sum"); + let mut row = self.base_metrics_row( + record, + &service_name, + &resource_attributes_json, + scope_name, + scope_version, + &scope_attributes_json, + &metric_name, + &metric_description, + &metric_unit, + "Sum", + ); row.metric_value_number = dp.value.as_ref().and_then(number_data_point_value_f64); row.timestamp_unix_ns = Some(dp.time_unix_nano.max(record.timestamp_unix_ns)); row.start_time_unix_ns = zero_is_none(dp.start_time_unix_nano); @@ -291,7 +309,18 @@ impl ParquetExporter { } MetricData::Histogram(hist) => { for dp in &hist.data_points { - let mut row = self.base_metrics_row(record, &service_name, &resource_attributes_json, scope_name, scope_version, &scope_attributes_json, &metric_name, &metric_description, &metric_unit, "Histogram"); + let mut row = self.base_metrics_row( + record, + &service_name, + &resource_attributes_json, + scope_name, + scope_version, + &scope_attributes_json, + &metric_name, + &metric_description, + &metric_unit, + "Histogram", + ); row.timestamp_unix_ns = Some(dp.time_unix_nano.max(record.timestamp_unix_ns)); row.start_time_unix_ns = zero_is_none(dp.start_time_unix_nano); row.metric_value_count = Some(dp.count); @@ -303,7 +332,18 @@ impl ParquetExporter { } MetricData::ExponentialHistogram(ehist) => { for dp in &ehist.data_points { - let mut row = self.base_metrics_row(record, &service_name, &resource_attributes_json, scope_name, scope_version, &scope_attributes_json, &metric_name, &metric_description, &metric_unit, "ExponentialHistogram"); + let mut row = self.base_metrics_row( + record, + &service_name, + &resource_attributes_json, + scope_name, + scope_version, + &scope_attributes_json, + &metric_name, + &metric_description, + &metric_unit, + "ExponentialHistogram", + ); row.timestamp_unix_ns = Some(dp.time_unix_nano.max(record.timestamp_unix_ns)); row.start_time_unix_ns = zero_is_none(dp.start_time_unix_nano); row.metric_value_count = Some(dp.count); @@ -315,7 +355,18 @@ impl ParquetExporter { } MetricData::Summary(summary) => { for dp in &summary.data_points { - let mut row = self.base_metrics_row(record, &service_name, &resource_attributes_json, scope_name, scope_version, &scope_attributes_json, &metric_name, &metric_description, &metric_unit, "Summary"); + let mut row = self.base_metrics_row( + record, + &service_name, + &resource_attributes_json, + scope_name, + scope_version, + &scope_attributes_json, + &metric_name, + &metric_description, + &metric_unit, + "Summary", + ); row.timestamp_unix_ns = Some(dp.time_unix_nano.max(record.timestamp_unix_ns)); row.start_time_unix_ns = zero_is_none(dp.start_time_unix_nano); row.metric_value_count = Some(dp.count); @@ -327,7 +378,18 @@ impl ParquetExporter { } } else { // Metric with no data: emit one row with metadata only - let row = self.base_metrics_row(record, &service_name, &resource_attributes_json, scope_name, scope_version, &scope_attributes_json, &metric_name, &metric_description, &metric_unit, "Unknown"); + let row = self.base_metrics_row( + record, + &service_name, + &resource_attributes_json, + scope_name, + scope_version, + &scope_attributes_json, + &metric_name, + &metric_description, + &metric_unit, + "Unknown", + ); self.rows.push(row); } } @@ -351,7 +413,7 @@ impl ParquetExporter { let request = match ExportTraceServiceRequest::decode(payload) { Ok(request) => request, Err(err) => { - return self.fail_status(LJX_EXPORT_STATUS_ERROR, format!("failed to decode OTLP traces payload at seq {}: {err}", record.seq)) + return self.fail_status(LJX_EXPORT_STATUS_ERROR, format!("failed to decode OTLP traces payload at seq {}: {err}", record.seq)); } }; @@ -774,11 +836,7 @@ fn schema() -> SchemaRef { fn validate_host(host: &LjxExportHostV1) -> Result<(), String> { if host.struct_size < std::mem::size_of::() as u32 { - return Err(format!( - "host struct_size {} is smaller than plugin ABI expects {}", - host.struct_size, - std::mem::size_of::() - )); + return Err(format!("host struct_size {} is smaller than plugin ABI expects {}", host.struct_size, std::mem::size_of::())); } Ok(()) } @@ -808,11 +866,7 @@ fn abi_bytes<'a>(value: LjxAbiBytes) -> Result<&'a [u8], String> { } fn status_for_message(message: &str) -> i32 { - if message.contains("host callback") || message.contains("flush host output") { - LJX_EXPORT_STATUS_IO - } else { - LJX_EXPORT_STATUS_ERROR - } + if message.contains("host callback") || message.contains("flush host output") { LJX_EXPORT_STATUS_IO } else { LJX_EXPORT_STATUS_ERROR } } fn zero_is_none(value: u64) -> Option { @@ -923,10 +977,8 @@ fn attrs_to_json(attrs: &[KeyValue]) -> Option { if attrs.is_empty() { return None; } - let mut pairs = attrs - .iter() - .filter_map(|attr| attr.value.as_ref().and_then(any_value_to_json).map(|value| (attr.key.clone(), value))) - .collect::>(); + let mut pairs = + attrs.iter().filter_map(|attr| attr.value.as_ref().and_then(any_value_to_json).map(|value| (attr.key.clone(), value))).collect::>(); if pairs.is_empty() { return None; } diff --git a/tests/ljx_export.rs b/tests/ljx_export.rs index 1b0ff5e..911e0fa 100644 --- a/tests/ljx_export.rs +++ b/tests/ljx_export.rs @@ -44,7 +44,9 @@ fn ljx_exports_cpp_demo_to_parquet_and_preserves_rows() -> io::Result<()> { actual.iter().filter_map(|row| row.service_name.clone()).collect::>(), expected.iter().filter_map(|row| row.service_name.clone()).collect::>() ); - assert!(actual.iter().all(|row| row.body_kind == Some("string".to_string()) || row.body_kind == Some("empty".to_string()) || row.body_json.is_some())); + assert!( + actual.iter().all(|row| row.body_kind == Some("string".to_string()) || row.body_kind == Some("empty".to_string()) || row.body_json.is_some()) + ); Ok(()) } @@ -449,11 +451,7 @@ fn encode_metrics_request(service_name: Option<&str>) -> io::Result> { let resource_metrics = ResourceMetrics { resource: Some(resource), - scope_metrics: vec![ScopeMetrics { - scope: None, - metrics, - schema_url: String::new(), - }], + scope_metrics: vec![ScopeMetrics { scope: None, metrics, schema_url: String::new() }], schema_url: String::new(), }; @@ -512,11 +510,7 @@ fn encode_traces_request(service_name: Option<&str>) -> io::Result> { let resource_spans = ResourceSpans { resource: Some(resource), - scope_spans: vec![ScopeSpans { - scope: None, - spans, - schema_url: String::new(), - }], + scope_spans: vec![ScopeSpans { scope: None, spans, schema_url: String::new() }], schema_url: String::new(), };