//! An optional thread for writing logs.
//!
//! ## Logging Standards
//!
//! For consistency across the codebase, all logging (debug, info, warn, error, trace) should follow these format standards:
//!
//! ### User-related Log Messages
//! Use the format: `[user {}]: message content`
//! ```rust
//! use log::{info, debug};
//! let user_id = 1;
//! let scenario_name = "LoadTest";
//! let transaction_name = "login";
//! info!("[user {}]: launching user from {}", user_id, scenario_name);
//! debug!("[user {}]: launching {} transaction from {}", user_id, transaction_name, scenario_name);
//! ```
//!
//! ### Component-specific Log Messages
//! Use the format: `[component]: message content`
//! ```rust
//! use log::{info, warn, error};
//! let count = 10;
//! let scenario_index = 0;
//! let err = std::io::Error::new(std::io::ErrorKind::Other, "file not found");
//! info!("[scheduler]: allocating {} users from Scenario {}", count, scenario_index);
//! warn!("[controller]: failed to send response via one-shot channel");
//! error!("[throttle]: failed to create log file: {}", err);
//! ```
//!
//! ### System-level Messages
//! Use the format: `[system]: message content` for general system operations
//! ```rust
//! use log::info;
//! #[derive(Debug)]
//! enum Phase { Starting, Running, Stopping }
//! let phase = Phase::Starting;
//! info!("[system]: entering GooseAttack phase: {:?}", phase);
//! info!("[system]: load test complete, closing throttle channel");
//! ```
//!
//! This standardization improves log readability, makes filtering easier, and provides consistent structure across all log levels.
//!
//! ## Log Files
//!
//! Goose can generate a number of log files during a load test, enabled through any combination of
//! the following run time options:
//! - `--debug-log`, `--request-log`, `--transaction-log`, `--scenario-log`
//!
//! It's also possible to configure the format of any of thse logs to be `json`, `csv`, or `raw`
//! (the standard debug output of a Rust structure), using the following run time optios:
//! - `--debug-format`, `--request-format`, `--transaction-format`, `--scenario-format`
//!
//! A log option given without a path writes its log into the run's folder. A log whose name
//! ends in `.gz` is written gzipped.
//!
//! All of these loggers use a single shared logger thread, with
//! [`GooseUser`](../goose/struct.GooseUser.html)s sending log messages through the same shared
//! channel. The logger determines which log file to write the message to based on the message
//! data type. The logger thread uses Tokio's asynchronous
//! [`BufWriter`](https://docs.rs/tokio/*/tokio/io/struct.BufWriter.html). The logger thread only
//! starts if at least one logger is enabled.
//!
//! The `--goose-log` run time option records the errors and messages Goose logs. The logger
//! thread does not write this log: the global logger writes it, through a handle kept in this
//! file. A bare `--goose-log` starts a new Goose log in each run's folder as the run starts,
//! and lines logged between runs go to the last run's log. A Goose log named `.gz` ends a
//! gzip member at the end of each run, so the file is whole between runs.
//!
//! ## Request File logger
//! The Goose requests logger is enabled with the `--request-log` command-line option, or the
//! [`GooseDefault::RequestLog`](../config/enum.GooseDefault.html#variant.RequestLog) default
//! configuration option. The format of the log is configured with the `--request-format`
//! command-line option, or the
//! [`GooseDefault::RequestFormat`](../config/enum.GooseDefault.html#variant.RequestFormat) default
//! configuration option.
//!
//! Each [`GooseRequestMetric`] object generated by all [`GooseUser`](../goose/struct.GooseUser.html)
//! threads during a load test is written to this log file.
//!
//! ## Transaction File logger
//! The Goose transactions logger is enabled with the `--transaction-log` command-line option, or the
//! [`GooseDefault::TransactionLog`](../config/enum.GooseDefault.html#variant.TransactionLog) default
//! configuration option. The format of the log is configured with the `--transaction-format`
//! command-line option, or the
//! [`GooseDefault::TransactionFormat`](../config/enum.GooseDefault.html#variant.TransactionFormat) default
//! configuration option.
//!
//! Each [`TransactionMetric`] object generated by all [`GooseUser`](../goose/struct.GooseUser.html)
//! threads during a load test is written to this log file.
//!
//! ## Scenario File logger
//! The Goose scenarios logger is enabled with the `--scenario-log` command-line option, or the
//! [`GooseDefault::ScenarioLog`](../config/enum.GooseDefault.html#variant.ScenarioLog) default
//! configuration option. The format of the log is configured with the `--scenario-format`
//! command-line option, or the
//! [`GooseDefault::ScenarioFormat`](../config/enum.GooseDefault.html#variant.ScenarioFormat) default
//! configuration option.
//!
//! Each [`ScenarioMetric`] object generated by all [`GooseUser`](../goose/struct.GooseUser.html)
//! threads during a load test is written to this log file.
//!
//! ## Debug File logger
//! The Goose debug logger is enabled with the `--debug-log` command-line option, or the
//! [`GooseDefault::DebugLog`](../config/enum.GooseDefault.html#variant.DebugLog) default
//! configuration option.
//!
//! Each [`GooseDebug`] object generated by all [`GooseUser`](../goose/struct.GooseUser.html)
//! threads during a load test is written to this log file.
//!
//! ### Writing Debug Logs
//! Logs can be sent to the logger thread by invoking
//! [`log_debug`](../goose/struct.GooseUser.html#method.log_debug) from load test transaction functions.
//!
//! Calls to
//! [`set_failure`](../goose/struct.GooseUser.html#method.set_failure)
//! automatically invoke
//! [`log_debug`](../goose/struct.GooseUser.html#method.log_debug).
//!
//! Most of the included examples showing how to use the debug logger include a copy of the
//! request made, the response headers returned by the server, and the response body. It can
//! also be used to log arbitrary information, for example if you want to record everything you
//! sent via a POST to a form.
//!
//! ```rust
//! use goose::prelude::*;
//!
//! let mut transaction = transaction!(post_to_form);
//!
//! async fn post_to_form(user: &mut GooseUser) -> TransactionResult {
//! let path = "/path/to/form";
//! let params = [
//! ("field_1", "foo"),
//! ("field_2", "bar"),
//! ("op", "Save"),
//! ];
//!
//! // Only log the form parameters we will post.
//! user.log_debug(
//! &format!("POSTing {:?} on {}", ¶ms, path),
//! None,
//! None,
//! None,
//! )?;
//!
//! let goose = user.post_form(path, ¶ms).await?;
//!
//! // Log the form parameters that were posted together with details about the entire
//! // request that was sent to the server.
//! user.log_debug(
//! &format!("POSTing {:#?} on {}", ¶ms, path),
//! Some(&goose.request),
//! None,
//! None,
//! )?;
//!
//! Ok(())
//! }
//! ```
//!
//! The first call to
//! [`log_debug`](../goose/struct.GooseUser.html#method.log_debug)
//! results in a debug log message similar to:
//! ```json
//! {"tag":"POSTing [(\"field_1\", \"foo\"), (\"field_2\", \"bar\"), (\"op\", \"Save\")] on /path/to/form","request":null,"header":null,"body":null}
//! ```
//!
//! The second call to
//! [`log_debug`](../goose/struct.GooseUser.html#method.log_debug)
//! results in a debug log message similar to:
//! ```json
//! {"tag":"POSTing [\n (\n \"field_1\",\n \"foo\",\n ),\n (\n \"field_2\",\n \"bar\",\n ),\n (\n \"op\",\n \"Save\",\n ),\n] on /path/to/form","request":{"elapsed":0,"scenario_index":0,"scenario_name":"doc","transaction_index":0,"transaction_name":{"TransactionOnly":""},"raw":{"method":"Post","url":"http://local.dev/path/to/form","headers":["(\"content-type\", \"application/x-www-form-urlencoded\")"],"body":"","custom_method":""},"name":"/path/to/form","final_url":"http://local.dev/path/to/form","redirected":false,"response_time":1,"status_code":200,"success":true,"update":false,"user":0,"error":"","coordinated_omission_elapsed":0,"user_cadence":0,"response_time_fraction_us":372},"header":null,"body":null}
//! ```
//!
//! For a more complex debug logging example, refer to the
//! [`log_debug`](../goose/struct.GooseUser.html#method.log_debug) documentation.
//!
//! ### Reducing File And Memory Usage
//!
//! The debug logger can result in a very large debug file, as by default it includes the
//! entire body of any pages returned that result in an error. This also requires allocating
//! a bigger [`BufWriter`](https://docs.rs/tokio/*/tokio/io/struct.BufWriter.html), and can
//! generate a lot of disk io.
//!
//! If you don't need to log response bodies, you can disable this functionality (and reduce
//! the amount of RAM required by the
//! [`BufWriter`](https://docs.rs/tokio/*/tokio/io/struct.BufWriter.html) by setting the
//! `--no-debug-body` command-line option, or the
//! [`GooseDefault::NoDebugBody`](../config/enum.GooseDefault.html#variant.NoDebugBody) default
//! configuration option. The debug logger will still record any custom messages, details
//! about the request (when available), and all server response headers (when available).
//!
//! ## Thread Safety Considerations
//!
//! The `ScopedLogLevel` provides thread-safe temporary log level changes using a global mutex.
//! This is necessary because Rust's `log::set_max_level()` modifies global state, and we need
//! to temporarily suppress verbose Chromium logging during PDF generation.
//!
//! ### Mutex Poisoning
//!
//! If a thread panics while holding the log level mutex, the mutex becomes "poisoned".
//! The current implementation fails fast when this occurs to expose potential threading
//! issues rather than masking them.
use async_compression::tokio::write::GzipEncoder;
use async_compression::Level;
use log::LevelFilter;
use regex::RegexSet;
use serde::{Deserialize, Serialize};
use std::pin::Pin;
use std::str::FromStr;
use std::sync::Mutex;
use std::task::{Context, Poll};
use tokio::fs::File;
use tokio::io::{AsyncWrite, AsyncWriteExt, BufWriter};
use crate::config::{GooseValue, RUN_FOLDER};
use crate::goose::GooseDebug;
use crate::metrics::{
GooseErrorMetric, GooseRequestMetric, GooseTransactionErrorMetric, ScenarioMetric,
TransactionMetric,
};
use crate::runs::{log_file_name, without_gz, RunFolder, LOG_NAMES};
use crate::{GooseConfiguration, GooseDefaults, GooseError};
/// A thread-safe scoped log level guard that changes the global log level for its lifetime
/// and restores the previous level when dropped. Uses a mutex to prevent race conditions
/// when multiple threads attempt to change log levels simultaneously.
pub struct ScopedLogLevel {
previous_level: LevelFilter,
_guard: std::sync::MutexGuard<'static, ()>,
}
// Static mutex to synchronize access to global log level changes
static LOG_LEVEL_MUTEX: Mutex<()> = Mutex::new(());
impl ScopedLogLevel {
/// Create a new thread-safe scoped log level guard, changing the global log level
/// to the specified level and storing the previous level for restoration.
///
/// This method acquires a mutex lock to ensure thread-safe access to the global
/// log level, preventing race conditions if multiple threads generate PDF reports
/// or perform other operations that require temporary log level changes.
///
/// # Errors
///
/// Returns `GooseError::InvalidOption` if the internal logging mutex is poisoned,
/// indicating a concurrency issue that should not be masked.
pub fn new(level: LevelFilter) -> Result<Self, GooseError> {
// Acquire the mutex lock to ensure exclusive access to global log level
let guard = LOG_LEVEL_MUTEX.lock().map_err(|_| GooseError::InvalidOption {
option: "--pdf (internal logging)".to_string(),
value: "mutex_poisoned".to_string(),
detail: "Thread safety violation in logging system: mutex poisoned due to concurrent thread panic. This indicates a serious concurrency bug that requires investigation.".to_string(),
})?;
let previous_level = log::max_level();
log::set_max_level(level);
Ok(Self {
previous_level,
_guard: guard,
})
}
}
impl Drop for ScopedLogLevel {
/// Restore the previous log level when the guard is dropped.
/// The mutex guard is automatically released when this struct is dropped.
fn drop(&mut self) {
log::set_max_level(self.previous_level);
// The mutex guard (_guard) is automatically dropped here, releasing the lock
}
}
/// The most bytes of Goose log a bare `--goose-log` holds before a run's folder
/// is known; later lines are dropped until it is.
const WAITING_LOG_LIMIT: usize = 1024 * 1024;
/// Where the Goose log goes.
enum GooseLogTarget {
/// A bare `--goose-log`, before the first run's folder is known: the
/// lines so far.
Waiting(Vec<u8>),
File(std::fs::File),
/// A Goose log named `.gz`: the gzip member being written, ended at the
/// end of each run and each `execute()`. Lines are buffered above the
/// encoder, so it compresses one whole buffer at a time, not each piece
/// of a line.
Gzip(std::io::BufWriter<flate2::write::GzEncoder<std::fs::File>>),
/// A Goose log named `.gz` between runs: each line is written as a whole
/// gzip member, and a line not yet ended waits in the buffer.
GzipIdle(std::fs::File, Vec<u8>),
/// The file failed; lines are dropped.
Failed,
}
/// The Goose log's file, behind a handle Goose keeps, as the global logger
/// owns its writer for the whole process: so a bare `--goose-log` can move to
/// each run's folder, and a gzipped one can end a gzip member when each run
/// and each `execute()` ends. Members one after another are one valid gzip
/// file.
#[derive(Clone)]
pub(crate) struct GooseLogFile {
target: std::sync::Arc<Mutex<GooseLogTarget>>,
level: u32,
}
/// The Goose log's handle, once the global logger writes to it.
static GOOSE_LOG_FILE: Mutex<Option<GooseLogFile>> = Mutex::new(None);
impl GooseLogTarget {
/// The log at `path`: gzipped at `level` when its name ends in `.gz`, its
/// first member started at once, so a log with no lines is still gzip.
fn create(path: &std::path::Path, level: u32) -> std::io::Result<Self> {
let file = std::fs::File::create(path)?;
Ok(if without_gz(&path.to_string_lossy()).1 {
Self::member(file, level)
} else {
GooseLogTarget::File(file)
})
}
/// A new gzip member in `file`.
fn member(file: std::fs::File, level: u32) -> Self {
GooseLogTarget::Gzip(std::io::BufWriter::new(flate2::write::GzEncoder::new(
file,
flate2::Compression::new(level),
)))
}
fn write_all(&mut self, buf: &[u8], level: u32) -> std::io::Result<()> {
match self {
GooseLogTarget::Waiting(lines) => {
if lines.len() + buf.len() <= WAITING_LOG_LIMIT {
lines.extend_from_slice(buf);
}
Ok(())
}
GooseLogTarget::File(file) => std::io::Write::write_all(file, buf),
GooseLogTarget::Gzip(gzip) => std::io::Write::write_all(gzip, buf),
// Between runs each line is a whole member, so no line waits in a
// buffer nothing will finish.
GooseLogTarget::GzipIdle(file, line) => {
line.extend_from_slice(buf);
match line.iter().rposition(|&b| b == b'\n') {
Some(end) => {
let lines: Vec<u8> = line.drain(..=end).collect();
Self::whole_member(file, &lines, level)
}
None => Ok(()),
}
}
GooseLogTarget::Failed => Ok(()),
}
}
/// Start a gzip member between members, as each run and each `execute()`
/// starts, so lines during a run compress a buffer at a time.
fn start(&mut self, level: u32) {
match std::mem::replace(self, GooseLogTarget::Failed) {
GooseLogTarget::GzipIdle(file, line) => {
*self = Self::member(file, level);
let _ = self.write_all(&line, level);
}
other => *self = other,
}
}
/// `bytes` as one whole gzip member at the end of `file`.
fn whole_member(file: &std::fs::File, bytes: &[u8], level: u32) -> std::io::Result<()> {
let mut gzip = flate2::write::GzEncoder::new(file, flate2::Compression::new(level));
std::io::Write::write_all(&mut gzip, bytes)?;
gzip.finish().map(drop)
}
/// Flush the log, ending a gzip member, so the file is whole.
fn finish(&mut self) {
match std::mem::replace(self, GooseLogTarget::Failed) {
GooseLogTarget::Gzip(gzip) => {
if let Ok(file) = gzip
.into_inner()
.map_err(|e| e.into_error())
.and_then(flate2::write::GzEncoder::finish)
{
*self = GooseLogTarget::GzipIdle(file, Vec::new());
}
}
GooseLogTarget::File(mut file) => {
let _ = std::io::Write::flush(&mut file);
*self = GooseLogTarget::File(file);
}
other => *self = other,
}
}
}
impl GooseLogFile {
/// The Goose log at `path`, gzipped at `level` when its name ends in
/// `.gz`, or with no path, waiting for a run's folder.
pub(crate) fn open(path: Option<&std::path::Path>, level: u32) -> std::io::Result<Self> {
let target = match path {
Some(path) => GooseLogTarget::create(path, level)?,
None => GooseLogTarget::Waiting(Vec::new()),
};
Ok(GooseLogFile {
target: std::sync::Arc::new(Mutex::new(target)),
level,
})
}
/// Keep this handle as the one the global logger writes to.
pub(crate) fn install(&self) {
if let Ok(mut file) = GOOSE_LOG_FILE.lock() {
*file = Some(self.clone());
}
}
fn target(&self) -> std::sync::MutexGuard<'_, GooseLogTarget> {
self.target
.lock()
.unwrap_or_else(|poisoned| poisoned.into_inner())
}
}
impl std::io::Write for GooseLogFile {
fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
let level = self.level;
self.target().write_all(buf, level)?;
Ok(buf.len())
}
fn flush(&mut self) -> std::io::Result<()> {
match &mut *self.target() {
GooseLogTarget::File(file) => file.flush(),
GooseLogTarget::Gzip(gzip) => gzip.flush(),
_ => Ok(()),
}
}
}
/// Whether the global logger already writes a Goose log.
pub(crate) fn goose_log_installed() -> bool {
goose_log_file().is_some()
}
/// The Goose log's handle, when the global logger writes one.
fn goose_log_file() -> Option<GooseLogFile> {
GOOSE_LOG_FILE.lock().ok().and_then(|file| file.clone())
}
/// Move a bare `--goose-log` to `path` in a run's folder, gzipped when its
/// name ends in `.gz`, writing any lines logged before the first run there
/// first. Does nothing when the global logger writes no Goose log.
pub(crate) fn move_goose_log(path: &std::path::Path) -> std::io::Result<()> {
let Some(handle) = goose_log_file() else {
return Ok(());
};
let mut target = handle.target();
target.finish();
let waiting = match std::mem::replace(&mut *target, GooseLogTarget::create(path, handle.level)?)
{
GooseLogTarget::Waiting(lines) => lines,
_ => Vec::new(),
};
target.write_all(&waiting, handle.level)
}
/// Start the Goose log's gzip member as each `execute()` and each run starts.
pub(crate) fn start_goose_log() {
if let Some(handle) = goose_log_file() {
handle.target().start(handle.level);
}
}
/// End the Goose log's gzip member, or flush it, as each run and each
/// `execute()` ends.
pub(crate) fn finish_goose_log() {
if let Some(handle) = goose_log_file() {
handle.target().finish();
}
}
/// A log file: plain, or gzipped when its name ends in `.gz`. It sits under the
/// log's `BufWriter`, so a line costs no more than it does in a plain log.
pub(crate) enum LogSink {
Plain(File),
Gzip(GzipEncoder<File>),
}
impl AsyncWrite for LogSink {
fn poll_write(
self: Pin<&mut Self>,
cx: &mut Context<'_>,
buf: &[u8],
) -> Poll<std::io::Result<usize>> {
match self.get_mut() {
LogSink::Plain(file) => Pin::new(file).poll_write(cx, buf),
LogSink::Gzip(gzip) => Pin::new(gzip).poll_write(cx, buf),
}
}
fn poll_flush(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<std::io::Result<()>> {
match self.get_mut() {
LogSink::Plain(file) => Pin::new(file).poll_flush(cx),
LogSink::Gzip(gzip) => Pin::new(gzip).poll_flush(cx),
}
}
fn poll_shutdown(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<std::io::Result<()>> {
match self.get_mut() {
LogSink::Plain(file) => Pin::new(file).poll_shutdown(cx),
LogSink::Gzip(gzip) => Pin::new(gzip).poll_shutdown(cx),
}
}
}
/// Optional unbounded receiver for logger thread, if debug logger is enabled.
pub(crate) type GooseLoggerJoinHandle =
Option<tokio::task::JoinHandle<std::result::Result<(), GooseError>>>;
/// Optional unbounded sender from all GooseUsers to logger thread, if enabled.
pub(crate) type GooseLoggerTx = Option<flume::Sender<Option<GooseLog>>>;
/// Formats comma separated arguments into a csv row according to RFC 4180. Every argument has to be `Display`.
///
/// Specifically, this encloses all values with double quotes `"` which contain a comma, a quote or a new line.
/// Inner quotes are doubled according to RFC 4180 2.7.
/// The fields are joined by commas `,`, but *not* terminated with a line ending.
#[macro_export]
#[doc(hidden)]
macro_rules! format_csv_row {
($( $field:expr ),+ $(,)?) => {{
[$( $field.to_string() ),*]
.iter()
.map(|s| {
if s.contains('"') || s.contains(',') || s.contains('\n') {
// Enclose in quotes and escape inner quotes
format!("\"{}\"", s.replace('"', "\"\""))
} else {
// Because into_iter is not available in edition 2018
s.clone()
}
})
.collect::<Vec<String>>()
.join(",")
}};
}
pub use format_csv_row;
/// If enabled, the logger thread can accept any of the following types of messages, and will
/// write them to the correct log file.
#[derive(Debug, Deserialize, Serialize)]
pub enum GooseLog {
Debug(GooseDebug),
Error(GooseErrorMetric),
/// A transaction error, written to the error log.
TransactionError(GooseTransactionErrorMetric),
Request(GooseRequestMetric),
Transaction(TransactionMetric),
/// A transaction that failed, and why, written to the transaction log.
FailedTransaction {
transaction: TransactionMetric,
/// The transaction log's `error` field, as
/// [`TransactionError`](../goose/enum.TransactionError.html) describes.
error: String,
},
Scenario(ScenarioMetric),
}
/// Defines the formats logs can be written to file.
#[derive(Debug, Clone, Eq, PartialEq, Serialize, Deserialize)]
pub enum GooseLogFormat {
Csv,
Json,
Raw,
Pretty,
}
/// Allow setting log formats from the command line by impleenting [`FromStr`].
impl FromStr for GooseLogFormat {
type Err = GooseError;
fn from_str(s: &str) -> Result<Self, Self::Err> {
// Use a [`RegexSet`] to match string representations of `GooseCoordinatedOmissionMitigation`,
// returning the appropriate enum value. Also match a wide range of abbreviations and synonyms.
let log_format = RegexSet::new([
r"(?i)^csv$",
r"(?i)^(json|jsn)$",
r"(?i)^raw$",
r"(?i)^pretty$",
])
.expect("failed to compile log_format RegexSet");
let matches = log_format.matches(s);
if matches.matched(0) {
Ok(GooseLogFormat::Csv)
} else if matches.matched(1) {
Ok(GooseLogFormat::Json)
} else if matches.matched(2) {
Ok(GooseLogFormat::Raw)
} else if matches.matched(3) {
Ok(GooseLogFormat::Pretty)
} else {
Err(GooseError::InvalidOption {
option: format!("GooseLogFormat::{s:?}"),
value: s.to_string(),
detail: "Invalid log_format, expected: csv, json, raw, or pretty".to_string(),
})
}
}
}
// @TODO this should be automatically derived from the structure.
fn debug_csv_header() -> &'static str {
"tag,request,header,body"
}
// @TODO this should be automatically derived from the structure.
// A request error fills the first nine columns and leaves the last five empty;
// a transaction error fills `elapsed`, `user` and `error`, and the last five.
// Every row has every column, so a strict CSV reader reads both.
fn error_csv_header() -> &'static str {
concat!(
"elapsed,raw,name,final_url,redirected,response_time,status_code,user,error,",
"scenario_index,scenario_name,transaction_index,transaction_name,run_time",
)
}
// @TODO this should be automatically derived from the structure.
fn requests_csv_header() -> &'static str {
concat!(
"elapsed,scenario_index,scenario_name,transaction_index,transaction_name,",
"raw,name,final_url,redirected,response_time,status_code,success,update,",
"user,error,coordinated_omission_elapsed,user_cadence,response_time_us",
)
}
// @TODO this should be automatically derived from the structure.
fn transactions_csv_header() -> &'static str {
"elapsed,scenario_index,transaction_index,name,run_time,success,user,run_time_us,error"
}
// @TODO this should be automatically derived from the structure.
fn scenarios_csv_header() -> &'static str {
"elapsed,name,index,run_time,user,run_time_us"
}
/// Two traits that must be implemented by all loggers provided through this thread.
pub(crate) trait GooseLogger<T> {
/// Converts a rust structure to a formatted string.
/// @TODO: rework with .to_string()
fn format_message(&self, message: T) -> String;
}
/// Traits for GooseDebug logs.
impl GooseLogger<GooseDebug> for GooseConfiguration {
/// Converts a GooseDebug structure to a formatted string.
fn format_message(&self, message: GooseDebug) -> String {
if let Some(debug_format) = self.debug_format.as_ref() {
match debug_format {
// Use serde_json to create JSON.
GooseLogFormat::Json => {
serde_json::to_string(&message).expect("a log message serializes to JSON")
}
// Raw format is Debug output for GooseRawRequest structure.
GooseLogFormat::Raw => format!("{message:?}"),
// Pretty format is Debug Pretty output for GooseRawRequest structure.
GooseLogFormat::Pretty => format!("{message:#?}"),
// Csv format with `,` separator and `"` quotes.
GooseLogFormat::Csv => {
// @TODO: properly handle Option<>; flatten raw request in own columns
format_csv_row!(
message.tag,
format!("{:?}", message.request),
format!("{:?}", message.header),
format!("{:?}", message.body)
)
}
}
} else {
// A log format is required.
unreachable!()
}
}
}
/// Traits for GooseErrorMetric logs.
impl GooseLogger<GooseErrorMetric> for GooseConfiguration {
/// Converts a GooseErrorMetric structure to a formatted string.
fn format_message(&self, message: GooseErrorMetric) -> String {
if let Some(error_format) = self.error_format.as_ref() {
match error_format {
// Use serde_json to create JSON.
GooseLogFormat::Json => {
serde_json::to_string(&message).expect("a log message serializes to JSON")
}
// Raw format is Debug output for GooseErrorMetric structure.
GooseLogFormat::Raw => format!("{message:?}"),
// Pretty format is Debug Pretty output for GooseErrorMetric structure.
GooseLogFormat::Pretty => format!("{message:#?}"),
// Csv format with `,` separator and `"` quotes.
GooseLogFormat::Csv => {
format_csv_row!(
message.elapsed,
format!("{:?}", message.raw),
message.name,
message.final_url,
message.redirected,
message.response_time,
message.status_code,
message.user,
message.error,
// The transaction error columns, empty for a request.
"",
"",
"",
"",
"",
)
}
}
} else {
// A log format is required.
unreachable!()
}
}
}
/// Traits for GooseTransactionErrorMetric logs, written to the error log.
impl GooseLogger<GooseTransactionErrorMetric> for GooseConfiguration {
/// Converts a GooseTransactionErrorMetric structure to a formatted string.
fn format_message(&self, message: GooseTransactionErrorMetric) -> String {
if let Some(error_format) = self.error_format.as_ref() {
match error_format {
// Use serde_json to create JSON.
GooseLogFormat::Json => {
serde_json::to_string(&message).expect("a log message serializes to JSON")
}
// Raw format is Debug output for GooseTransactionErrorMetric structure.
GooseLogFormat::Raw => format!("{message:?}"),
// Pretty format is Debug Pretty output for GooseTransactionErrorMetric structure.
GooseLogFormat::Pretty => format!("{message:#?}"),
// Csv format with `,` separator and `"` quotes: the request
// columns a transaction has no value for are left empty.
GooseLogFormat::Csv => {
format_csv_row!(
message.elapsed,
"",
"",
"",
"",
"",
"",
message.user,
message.error,
message.scenario_index,
message.scenario_name,
message.transaction_index,
message.transaction_name,
message.run_time,
)
}
}
} else {
// A log format is required.
unreachable!()
}
}
}
/// Traits for GooseRequestMetric logs.
impl GooseLogger<GooseRequestMetric> for GooseConfiguration {
/// Converts a GooseRequestMetric structure to a formatted string.
fn format_message(&self, message: GooseRequestMetric) -> String {
if let Some(request_format) = self.request_format.as_ref() {
match request_format {
// Use serde_json to create JSON.
GooseLogFormat::Json => {
serde_json::to_string(&message).expect("a log message serializes to JSON")
}
// Raw format is Debug output for GooseRequestMetric structure.
GooseLogFormat::Raw => format!("{message:?}"),
// Pretty format is Debug Pretty output for GooseRequestMetric structure.
GooseLogFormat::Pretty => format!("{message:#?}"),
// Csv format with `,` separator and `"` quotes.
GooseLogFormat::Csv => {
format_csv_row!(
message.elapsed,
message.scenario_index,
message.scenario_name,
message.transaction_index,
message.transaction_name.name_for_request(),
format!("{:?}", message.raw),
message.name,
message.final_url,
message.redirected,
message.response_time,
message.status_code,
message.success,
message.update,
message.user,
message.error,
message.coordinated_omission_elapsed,
message.user_cadence,
message.response_time_micros(),
)
}
}
} else {
// A log format is required.
unreachable!()
}
}
}
/// Traits for TransactionMetric logs.
impl GooseLogger<TransactionMetric> for GooseConfiguration {
/// Converts a TransactionMetric structure to a formatted string, with an
/// empty `error`.
fn format_message(&self, message: TransactionMetric) -> String {
self.format_transaction(&message, "")
}
}
impl GooseConfiguration {
/// A transaction log line: the TransactionMetric's fields, then `error`,
/// why it failed, empty when it did not. The error is added to each
/// format's output of the TransactionMetric, so the line keeps every
/// field the TransactionMetric has, in its order.
fn format_transaction(&self, message: &TransactionMetric, error: &str) -> String {
if let Some(transaction_format) = self.transaction_format.as_ref() {
match transaction_format {
// Use serde_json to create JSON, the error the last key.
GooseLogFormat::Json => {
let mut line =
serde_json::to_string(message).expect("a log message serializes to JSON");
line.pop();
line.push_str(",\"error\":");
line.push_str(
&serde_json::to_string(error).expect("a string serializes to JSON"),
);
line.push('}');
line
}
// Raw format is Debug output for TransactionMetric structure,
// the error its last field.
GooseLogFormat::Raw => {
let mut line = format!("{message:?}");
line.truncate(line.len() - " }".len());
format!("{line}, error: {error:?} }}")
}
// Pretty format is Debug Pretty output for TransactionMetric
// structure, the error its last field.
GooseLogFormat::Pretty => {
let mut line = format!("{message:#?}");
line.truncate(line.len() - "}".len());
format!("{line} error: {error:?},\n}}")
}
// Csv format with `,` separator and `"` quotes.
GooseLogFormat::Csv => {
format_csv_row!(
message.elapsed,
message.scenario_index,
message.transaction_index,
message.name,
message.run_time,
message.success,
message.user,
message.run_time_micros(),
error,
)
}
}
} else {
// A log format is required.
unreachable!()
}
}
}
/// Traits for ScenarioMetric logs.
impl GooseLogger<ScenarioMetric> for GooseConfiguration {
/// Converts a ScenarioMetric structure to a formatted string.
fn format_message(&self, message: ScenarioMetric) -> String {
if let Some(scenario_format) = self.scenario_format.as_ref() {
match scenario_format {
// Use serde_json to create JSON.
GooseLogFormat::Json => {
serde_json::to_string(&message).expect("a log message serializes to JSON")
}
// Raw format is Debug output for ScenarioMetric structure.
GooseLogFormat::Raw => format!("{message:?}"),
// Pretty format is Debug Pretty output for ScenarioMetric structure.
GooseLogFormat::Pretty => format!("{message:#?}"),
// Csv format with `,` separator and `"` quotes.
GooseLogFormat::Csv => {
format_csv_row!(
message.elapsed,
message.name,
message.index,
message.run_time,
message.user,
message.run_time_micros(),
)
}
}
} else {
// A log format is required.
unreachable!()
}
}
}
/// Helpers to launch and control configured loggers.
impl GooseConfiguration {
/// Makes sure the GooseConfiguration has any/all configured log files (loading from defaults
/// if not configured through a run time option).
pub(crate) fn configure_loggers(&mut self, defaults: &GooseDefaults) {
// Configure debug_log path if enabled.
self.debug_log = self.get_value(vec![
// Use --debug-log if set.
GooseValue {
value: self.debug_log.clone(),
filter: self.debug_log.is_none(),
message: "",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.debug_log.clone(),
filter: defaults.debug_log.is_none(),
message: "",
},
]);
// Set `debug_format`.
self.debug_format = self.get_value(vec![
// Use --debug-format if set.
GooseValue {
value: self.debug_format.clone(),
filter: self.debug_format.is_none(),
message: "",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.debug_format.clone(),
filter: defaults.debug_format.is_none(),
message: "",
},
// Otherwise default to GooseLogFormat::Json.
GooseValue {
value: Some(GooseLogFormat::Json),
filter: false,
message: "",
},
]);
// Configure error_log path if enabled.
self.error_log = self.get_value(vec![
// Use --error-log if set.
GooseValue {
value: self.error_log.clone(),
filter: self.error_log.is_none(),
message: "",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.error_log.clone(),
filter: defaults.error_log.is_none(),
message: "",
},
]);
// Set `error_format`.
self.error_format = self.get_value(vec![
// Use --error-format if set.
GooseValue {
value: self.error_format.clone(),
filter: self.error_format.is_none(),
message: "",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.error_format.clone(),
filter: defaults.error_format.is_none(),
message: "",
},
// Otherwise default to GooseLogFormat::Json.
GooseValue {
value: Some(GooseLogFormat::Json),
filter: false,
message: "",
},
]);
// Configure request_log path if enabled.
self.request_log = self.get_value(vec![
// Use --request-log if set.
GooseValue {
value: self.request_log.clone(),
filter: self.request_log.is_none(),
message: "",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.request_log.clone(),
filter: defaults.request_log.is_none(),
message: "",
},
]);
// Set `request_format`.
self.request_format = self.get_value(vec![
// Use --request-format if set.
GooseValue {
value: self.request_format.clone(),
filter: self.request_format.is_none(),
message: "",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.request_format.clone(),
filter: defaults.request_format.is_none(),
message: "",
},
// Otherwise default to GooseLogFormat::Json.
GooseValue {
value: Some(GooseLogFormat::Json),
filter: false,
message: "",
},
]);
// Configure `request_body`.
self.request_body = self
.get_value(vec![
// Use --request-body if set.
GooseValue {
value: Some(self.request_body),
filter: !self.request_body,
message: "request_body",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.request_body,
filter: defaults.request_body.is_none(),
message: "request_body",
},
])
.unwrap_or(false);
// Configure transaction_log path if enabled.
self.transaction_log = self.get_value(vec![
// Use --transaction-log if set.
GooseValue {
value: self.transaction_log.clone(),
filter: self.transaction_log.is_none(),
message: "",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.transaction_log.clone(),
filter: defaults.transaction_log.is_none(),
message: "",
},
]);
// Set `transaction_format`.
self.transaction_format = self.get_value(vec![
// Use --transaction-format if set.
GooseValue {
value: self.transaction_format.clone(),
filter: self.transaction_format.is_none(),
message: "",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.transaction_format.clone(),
filter: defaults.transaction_format.is_none(),
message: "",
},
// Otherwise default to GooseLogFormat::Json.
GooseValue {
value: Some(GooseLogFormat::Json),
filter: false,
message: "",
},
]);
// Configure scenario_log path if enabled.
self.scenario_log = self.get_value(vec![
// Use --scenario-log if set.
GooseValue {
value: self.scenario_log.clone(),
filter: self.scenario_log.is_none(),
message: "",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.scenario_log.clone(),
filter: defaults.scenario_log.is_none(),
message: "",
},
]);
// Set `scenario_format`.
self.scenario_format = self.get_value(vec![
// Use --scenario-format if set.
GooseValue {
value: self.scenario_format.clone(),
filter: self.scenario_format.is_none(),
message: "",
},
// Otherwise use GooseDefault if set.
GooseValue {
value: defaults.scenario_format.clone(),
filter: defaults.scenario_format.is_none(),
message: "",
},
// Otherwise default to GooseLogFormat::Json.
GooseValue {
value: Some(GooseLogFormat::Json),
filter: false,
message: "",
},
]);
}
/// Spawns the logger thread if one or more loggers are enabled.
pub(crate) async fn setup_loggers(
&mut self,
defaults: &GooseDefaults,
folder: Option<&RunFolder>,
) -> Result<(GooseLoggerJoinHandle, GooseLoggerTx), GooseError> {
// Update the logger configuration, loading defaults if necessasry.
self.configure_loggers(defaults);
// If no logger is enabled, return immediately without launching logger thread.
if self.debug_log().is_none()
&& self.request_log().is_none()
&& self.transaction_log().is_none()
&& self.scenario_log().is_none()
&& self.error_log().is_none()
{
return Ok((None, None));
}
// Create an unbounded channel allowing GooseUser threads to log errors.
let (all_threads_logger_tx, logger_rx): (
flume::Sender<Option<GooseLog>>,
flume::Receiver<Option<GooseLog>>,
) = flume::unbounded();
// Launch a new thread for logging, with each log given without a path
// named in the run's folder.
let mut configuration = self.clone();
if let Some(folder) = folder {
for (log, name, format) in [
(
&mut configuration.request_log,
LOG_NAMES[0],
&self.request_format,
),
(
&mut configuration.transaction_log,
LOG_NAMES[1],
&self.transaction_format,
),
(
&mut configuration.scenario_log,
LOG_NAMES[2],
&self.scenario_format,
),
(
&mut configuration.error_log,
LOG_NAMES[3],
&self.error_format,
),
(
&mut configuration.debug_log,
LOG_NAMES[4],
&self.debug_format,
),
] {
if log.as_deref() == Some(RUN_FOLDER) {
let mut file = log_file_name(name, format.as_ref());
if self.compress.is_some() {
file.push_str(".gz");
}
let path = folder.file(&file);
*log = Some(path.to_string_lossy().into_owned());
}
}
}
let logger_handle = tokio::spawn(async move { configuration.logger_main(logger_rx).await });
Ok((Some(logger_handle), Some(all_threads_logger_tx)))
}
/// A helper used to open any/all log files, deleting any file that already exists.
/// A name that ends in `.gz` is written gzipped.
async fn open_log_file(
&self,
log_file_path: Option<&str>,
log_file_type: &str,
buffer_capacity: usize,
) -> std::option::Option<BufWriter<LogSink>> {
let log_file_path = log_file_path?;
match File::create(log_file_path).await {
Ok(f) => {
info!("[logger]: writing {log_file_type} to: {log_file_path}");
let sink = if without_gz(log_file_path).1 {
LogSink::Gzip(GzipEncoder::with_quality(
f,
Level::Precise(self.compression_level() as i32),
))
} else {
LogSink::Plain(f)
};
Some(BufWriter::with_capacity(buffer_capacity, sink))
}
Err(e) => {
error!("[logger]: failed to create {log_file_type} ({log_file_path}): {e}");
None
}
}
}
/// Helper to write a line to the log file.
async fn write_to_log_file(
&self,
log_file: &mut BufWriter<LogSink>,
log_file_path: &str,
formatted_message: &str,
) {
let written = match log_file.write_all(formatted_message.as_bytes()).await {
Ok(()) => log_file.write_all(b"\n").await,
Err(e) => Err(e),
};
if let Err(e) = written {
warn!("failed to write to {log_file_path}: {e}");
}
}
/// Logger thread, opens a log file (if configured) and waits for messages from
/// [`GooseUser`](../goose/struct.GooseUser.html) threads.
pub(crate) async fn logger_main(
self: GooseConfiguration,
receiver: flume::Receiver<Option<GooseLog>>,
) -> Result<(), GooseError> {
// If the debug_log is enabled, allocate a buffer and open the file.
let mut debug_log = self
.open_log_file(
self.debug_log(),
"debug file",
if self.no_debug_body {
// Allocate a smaller 64K buffer if not logging response body.
64 * 1024
} else {
// Allocate a larger 8M buffer if logging response body.
8 * 1024 * 1024
},
)
.await;
// If the debug_log is a CSV, write the header.
if self.debug_format == Some(GooseLogFormat::Csv) {
if let Some(log_file) = debug_log.as_mut() {
// This will generate a warning if it fails to write to log file.
self.write_to_log_file(
log_file,
self.debug_log().unwrap_or_default(),
debug_csv_header(),
)
.await;
}
}
// If the error_log is enabled, allocate a buffer and open the file.
let mut error_log = self
.open_log_file(self.error_log(), "error log", 64 * 1024)
.await;
// If the request_log is a CSV, write the header.
if self.error_format == Some(GooseLogFormat::Csv) {
if let Some(log_file) = error_log.as_mut() {
// This will generate a warning if it fails to write to log file.
self.write_to_log_file(
log_file,
self.error_log().unwrap_or_default(),
error_csv_header(),
)
.await;
}
}
// If the request_log is enabled, allocate a buffer and open the file.
let mut request_log = self
.open_log_file(
self.request_log(),
"request log",
if self.request_body {
// Allocate a larger 8M buffer if logging request body.
8 * 1024 * 1024
} else {
// Allocate a smaller 64K buffer if not logging request body.
64 * 1024
},
)
.await;
// If the request_log is a CSV, write the header.
if self.request_format == Some(GooseLogFormat::Csv) {
if let Some(log_file) = request_log.as_mut() {
// This will generate a warning if it fails to write to log file.
self.write_to_log_file(
log_file,
self.request_log().unwrap_or_default(),
requests_csv_header(),
)
.await;
}
}
// If the transaction_log is enabled, allocate a buffer and open the file.
let mut transaction_log = self
.open_log_file(self.transaction_log(), "transaction log", 64 * 1024)
.await;
// If the transaction_log is a CSV, write the header.
if self.transaction_format == Some(GooseLogFormat::Csv) {
if let Some(log_file) = transaction_log.as_mut() {
// This will generate a warning if it fails to write to log file.
self.write_to_log_file(
log_file,
self.transaction_log().unwrap_or_default(),
transactions_csv_header(),
)
.await;
}
}
// If the scenario_log is enabled, allocate a buffer and open the file.
let mut scenario_log = self
.open_log_file(self.scenario_log(), "scenario log", 64 * 1024)
.await;
// If the scenario_log is a CSV, write the header.
if self.scenario_format == Some(GooseLogFormat::Csv) {
if let Some(log_file) = scenario_log.as_mut() {
// This will generate a warning if it fails to write to log file.
self.write_to_log_file(
log_file,
self.scenario_log().unwrap_or_default(),
scenarios_csv_header(),
)
.await;
}
}
// Loop waiting for and writing error logs from GooseUser threads.
while let Ok(received_message) = receiver.recv_async().await {
if let Some(message) = received_message {
let formatted_message;
if let Some((log_file, log_file_path)) = match message {
GooseLog::Debug(debug_message) => {
formatted_message = self.format_message(debug_message);
debug_log
.as_mut()
.map(|file| (file, self.debug_log().unwrap_or_default()))
}
GooseLog::Error(error_message) => {
formatted_message = self.format_message(error_message);
error_log
.as_mut()
.map(|file| (file, self.error_log().unwrap_or_default()))
}
GooseLog::TransactionError(error_message) => {
formatted_message = self.format_message(error_message);
error_log
.as_mut()
.map(|file| (file, self.error_log().unwrap_or_default()))
}
GooseLog::Request(request_message) => {
formatted_message = self.format_message(request_message);
request_log
.as_mut()
.map(|file| (file, self.request_log().unwrap_or_default()))
}
GooseLog::Transaction(transaction_message) => {
formatted_message = self.format_message(transaction_message);
transaction_log
.as_mut()
.map(|file| (file, self.transaction_log().unwrap_or_default()))
}
GooseLog::FailedTransaction { transaction, error } => {
formatted_message = self.format_transaction(&transaction, &error);
transaction_log
.as_mut()
.map(|file| (file, self.transaction_log().unwrap_or_default()))
}
GooseLog::Scenario(scenario_message) => {
formatted_message = self.format_message(scenario_message);
scenario_log
.as_mut()
.map(|file| (file, self.scenario_log().unwrap_or_default()))
}
} {
// This will generate a warning if it fails to write to log file.
self.write_to_log_file(log_file, log_file_path, &formatted_message)
.await;
}
} else {
// Empty message means it's time to exit.
break;
}
}
// Flush debug logs to disk if enabled.
if let Some(debug_log_file) = debug_log.as_mut() {
info!(
"[logger]: flushing debug_log: {}",
self.debug_log().unwrap_or_default()
);
// Shut down, not only flush, so a gzipped log gets its trailer.
let _ = debug_log_file.shutdown().await;
};
// Flush requests log to disk if enabled.
if let Some(requests_log_file) = request_log.as_mut() {
info!(
"[logger]: flushing request_log: {}",
self.request_log().unwrap_or_default()
);
// Shut down, not only flush, so a gzipped log gets its trailer.
let _ = requests_log_file.shutdown().await;
}
// Flush transaction log to disk if enabled.
if let Some(transactions_log_file) = transaction_log.as_mut() {
info!(
"[logger]: flushing transaction_log: {}",
self.transaction_log().unwrap_or_default()
);
// Shut down, not only flush, so a gzipped log gets its trailer.
let _ = transactions_log_file.shutdown().await;
}
// Flush scenario log to disk if enabled.
if let Some(scenarios_log_file) = scenario_log.as_mut() {
info!(
"[logger]: flushing scenario: {}",
self.scenario_log().unwrap_or_default()
);
// Shut down, not only flush, so a gzipped log gets its trailer.
let _ = scenarios_log_file.shutdown().await;
}
// Flush error logs to disk if enabled.
if let Some(error_log_file) = error_log.as_mut() {
info!(
"[logger]: flushing error_log: {}",
self.error_log().unwrap_or_default()
);
// Shut down, not only flush, so a gzipped log gets its trailer.
let _ = error_log_file.shutdown().await;
};
Ok(())
}
}
/// The microseconds request, transaction and scenario logs carry (#585).
#[cfg(test)]
mod microsecond_tests {
use super::*;
use crate::goose::{GooseMethod, TransactionName};
use crate::metrics::{GooseRawRequest, TransactionDetail};
use std::sync::Arc;
use std::time::Duration;
fn configuration(format: GooseLogFormat) -> GooseConfiguration {
let mut configuration = GooseConfiguration::parse_args_default(&[] as &[&str]).unwrap();
configuration.request_format = Some(format.clone());
configuration.transaction_format = Some(format.clone());
configuration.scenario_format = Some(format);
configuration
}
fn last_csv_cell(line: &str) -> &str {
line.rsplit(',').next().unwrap()
}
#[test]
fn request_log_ends_with_its_microseconds() {
assert_eq!(last_csv_cell(requests_csv_header()), "response_time_us");
let mut request = GooseRequestMetric::new(
GooseRawRequest::new(GooseMethod::Get, "/", vec![], ""),
TransactionDetail {
scenario_index: 0,
scenario_name: Arc::from("Scenario"),
transaction_index: None,
transaction_name: TransactionName::TransactionOnly(Arc::from("")),
},
"/",
0,
0,
);
request.set_response_duration(Duration::from_micros(2_345));
let csv = configuration(GooseLogFormat::Csv).format_message(request.clone());
assert_eq!(last_csv_cell(&csv), "2345");
// The whole milliseconds keep their column.
let header: Vec<&str> = requests_csv_header().split(',').collect();
let cells: Vec<&str> = csv.split(',').collect();
let at = header.iter().position(|&h| h == "response_time").unwrap();
assert_eq!(cells[cells.len() - header.len() + at], "2");
let raw = configuration(GooseLogFormat::Raw).format_message(request.clone());
assert!(raw.ends_with("response_time_fraction_us: 345 }"), "{}", raw);
let pretty = configuration(GooseLogFormat::Pretty).format_message(request.clone());
assert!(
pretty.ends_with("response_time_fraction_us: 345,\n}"),
"{}",
pretty
);
let json: serde_json::Value =
serde_json::from_str(&configuration(GooseLogFormat::Json).format_message(request))
.unwrap();
assert_eq!(json["response_time"], 2);
assert_eq!(json["response_time_fraction_us"], 345);
}
/// The CSV cell before the last.
fn penultimate_csv_cell(line: &str) -> &str {
line.rsplit(',').nth(1).unwrap()
}
#[test]
fn transaction_and_scenario_logs_end_with_their_microseconds() {
// The transaction log ends with run_time_us, then the error.
assert_eq!(
penultimate_csv_cell(transactions_csv_header()),
"run_time_us"
);
let mut transaction = TransactionMetric::new(0, 0, 0, Arc::from("t"), 0);
transaction.set_duration(Duration::from_micros(1_250), true);
let csv = configuration(GooseLogFormat::Csv).format_message(transaction.clone());
assert_eq!(penultimate_csv_cell(&csv), "1250");
let raw = configuration(GooseLogFormat::Raw).format_message(transaction.clone());
assert!(
raw.ends_with("run_time_fraction_us: 250, error: \"\" }"),
"{}",
raw
);
let json: serde_json::Value =
serde_json::from_str(&configuration(GooseLogFormat::Json).format_message(transaction))
.unwrap();
assert_eq!(json["run_time"], 1);
assert_eq!(json["run_time_fraction_us"], 250);
assert_eq!(last_csv_cell(scenarios_csv_header()), "run_time_us");
let scenario = ScenarioMetric::new(0, Arc::from("s"), 0, Duration::from_micros(750), 0);
let csv = configuration(GooseLogFormat::Csv).format_message(scenario.clone());
assert_eq!(last_csv_cell(&csv), "750");
let raw = configuration(GooseLogFormat::Raw).format_message(scenario);
assert!(raw.ends_with("run_time_fraction_us: 750 }"), "{}", raw);
}
/// The transaction log's CSV ends with the error, empty for a transaction
/// that succeeded.
#[test]
fn transaction_log_csv_ends_with_the_error() {
assert_eq!(last_csv_cell(transactions_csv_header()), "error");
let mut transaction = TransactionMetric::new(0, 0, 0, Arc::from("t"), 0);
transaction.set_duration(Duration::from_micros(1_250), true);
let csv = configuration(GooseLogFormat::Csv).format_message(transaction.clone());
assert_eq!(csv, "0,0,0,t,1,true,0,1250,");
transaction.success = false;
let error = "TransactionError: custom error (a, b)";
let csv = configuration(GooseLogFormat::Csv).format_transaction(&transaction, error);
assert_eq!(
csv,
r#"0,0,0,t,1,false,0,1250,"TransactionError: custom error (a, b)""#
);
let raw = configuration(GooseLogFormat::Raw).format_transaction(&transaction, error);
assert!(
raw.ends_with(
r#"run_time_fraction_us: 250, error: "TransactionError: custom error (a, b)" }"#
),
"{}",
raw
);
let pretty = configuration(GooseLogFormat::Pretty).format_transaction(&transaction, error);
assert!(
pretty.ends_with(
" run_time_fraction_us: 250,\n error: \"TransactionError: custom error (a, b)\",\n}"
),
"{}",
pretty
);
let json: serde_json::Value = serde_json::from_str(
&configuration(GooseLogFormat::Json).format_transaction(&transaction, error),
)
.unwrap();
assert_eq!(json["error"], error);
assert_eq!(json["run_time_fraction_us"], 250);
}
/// A request error fills the error log's first nine CSV columns, in the
/// order it always has, and leaves the last five empty; a transaction
/// error fills `elapsed`, `user` and `error`, and the last five.
#[test]
fn error_log_csv_holds_both_kinds_of_error() {
let header: Vec<&str> = error_csv_header().split(',').collect();
assert_eq!(
header,
[
"elapsed",
"raw",
"name",
"final_url",
"redirected",
"response_time",
"status_code",
"user",
"error",
"scenario_index",
"scenario_name",
"transaction_index",
"transaction_name",
"run_time",
]
);
let mut configuration = configuration(GooseLogFormat::Csv);
configuration.error_format = Some(GooseLogFormat::Csv);
let error = GooseTransactionErrorMetric {
elapsed: 837,
scenario_index: 0,
scenario_name: Arc::from("websiteuser"),
transaction_index: 2,
transaction_name: Arc::from("log in"),
run_time: 1,
user: 5,
error: "boom".to_string(),
};
let csv = configuration.format_message(error);
assert_eq!(csv, "837,,,,,,,5,boom,0,websiteuser,2,log in,1");
assert_eq!(csv.split(',').count(), header.len());
let request_error = GooseErrorMetric {
elapsed: 9318,
raw: crate::metrics::GooseRawRequest::new(
crate::goose::GooseMethod::Get,
"http://example.com/",
vec![],
"",
),
name: "front page".to_string(),
final_url: "http://example.com/".to_string(),
redirected: false,
response_time: 6,
status_code: 503,
user: 1,
error: "503 Service Unavailable: /".to_string(),
};
let csv = configuration.format_message(request_error);
assert!(
csv.ends_with(",http://example.com/,false,6,503,1,503 Service Unavailable: /,,,,,"),
"{}",
csv
);
}
}
/// Each JSON log line, its keys in the order of the message's fields.
#[cfg(test)]
mod json_line_tests {
use super::*;
use crate::goose::{GooseMethod, TransactionName};
use crate::metrics::{GooseRawRequest, TransactionDetail};
use std::sync::Arc;
use std::time::Duration;
fn configuration() -> GooseConfiguration {
let mut configuration = GooseConfiguration::parse_args_default(&[] as &[&str]).unwrap();
configuration.debug_format = Some(GooseLogFormat::Json);
configuration.error_format = Some(GooseLogFormat::Json);
configuration.transaction_format = Some(GooseLogFormat::Json);
configuration.scenario_format = Some(GooseLogFormat::Json);
configuration
}
#[test]
fn error_json_line() {
let error = GooseErrorMetric {
elapsed: 9318,
raw: GooseRawRequest::new(GooseMethod::Get, "http://example.com/", vec![], ""),
name: "(Auth) front page".to_string(),
final_url: "http://example.com/".to_string(),
redirected: false,
response_time: 6,
status_code: 503,
user: 1,
error: "503 Service Unavailable: /".to_string(),
};
assert_eq!(
configuration().format_message(error),
r#"{"elapsed":9318,"raw":{"method":"Get","url":"http://example.com/","headers":[],"body":"","custom_method":""},"name":"(Auth) front page","final_url":"http://example.com/","redirected":false,"response_time":6,"status_code":503,"user":1,"error":"503 Service Unavailable: /"}"#
);
}
#[test]
fn transaction_json_line() {
let mut transaction = TransactionMetric::new(837, 0, 2, Arc::from("log in"), 5);
transaction.set_duration(Duration::from_micros(1_250), false);
assert_eq!(
configuration().format_message(transaction),
r#"{"elapsed":837,"scenario_index":0,"transaction_index":2,"name":"log in","run_time":1,"success":false,"user":5,"run_time_fraction_us":250,"error":""}"#
);
}
#[test]
fn transaction_error_json_line() {
let error = GooseTransactionErrorMetric {
elapsed: 837,
scenario_index: 0,
scenario_name: Arc::from("websiteuser"),
transaction_index: 2,
transaction_name: Arc::from("log in"),
run_time: 1,
user: 5,
error: "TransactionError: custom error (boom)".to_string(),
};
assert_eq!(
configuration().format_message(error),
r#"{"elapsed":837,"scenario_index":0,"scenario_name":"websiteuser","transaction_index":2,"transaction_name":"log in","run_time":1,"user":5,"error":"TransactionError: custom error (boom)"}"#
);
}
#[test]
fn scenario_json_line() {
let scenario = ScenarioMetric::new(
14_503,
Arc::from("Website User"),
0,
Duration::from_micros(750),
3,
);
assert_eq!(
configuration().format_message(scenario),
r#"{"elapsed":14503,"name":"Website User","index":0,"run_time":0,"user":3,"run_time_fraction_us":750}"#
);
}
/// The nested request's strings need escaping: quotes, a comma, a newline,
/// a control character and a letter outside ASCII.
#[test]
fn debug_json_line() {
let request = GooseRequestMetric::new(
GooseRawRequest::new(
GooseMethod::Post,
"http://example.com/a?b=\"c\"",
vec![],
"name=\"Zoë\", one\ntwo\u{1}",
),
TransactionDetail {
scenario_index: 0,
scenario_name: Arc::from("Anon"),
transaction_index: Some(1),
transaction_name: TransactionName::InheritNameByRequests(Arc::from("front page")),
},
"/a",
1500,
2,
);
let debug = GooseDebug {
tag: "post".to_string(),
request: Some(request),
header: None,
body: Some("ok".to_string()),
};
let line = configuration().format_message(debug);
assert!(!line.contains('\n'), "{}", line);
assert_eq!(
line,
r#"{"tag":"post","request":{"elapsed":1500,"scenario_index":0,"scenario_name":"Anon","transaction_index":1,"transaction_name":{"InheritNameByRequests":"front page"},"raw":{"method":"Post","url":"http://example.com/a?b=\"c\"","headers":[],"body":"name=\"Zoë\", one\ntwo\u0001","custom_method":""},"name":"/a","final_url":"","redirected":false,"response_time":0,"status_code":0,"success":true,"update":false,"user":2,"error":"","coordinated_omission_elapsed":0,"user_cadence":0,"response_time_fraction_us":0},"header":null,"body":"ok"}"#
);
}
}