feat: add opt-in structured HTTP request logging via tracing (#478)
Add PII-free structured logging controlled by two environment variables: - GOOGLE_WORKSPACE_CLI_LOG: stderr log filter (e.g., gws=debug) - GOOGLE_WORKSPACE_CLI_LOG_FILE: directory for JSON log files (daily rotation) Logging is silent by default (zero overhead). Instrumented sites: - executor.rs: API request/response (method, status, latency) - client.rs: 429 retry events - discovery.rs: cache hit vs network fetch Co-authored-by: jpoehnelt-bot <jpoehnelt-bot@users.noreply.github.com>
This commit is contained in:
Justin Poehnelt
@@ -0,0 +1,11 @@
|
||||
---
|
||||
"@googleworkspace/cli": minor
|
||||
---
|
||||
|
||||
Add opt-in structured HTTP request logging via `tracing`
|
||||
|
||||
New environment variables:
|
||||
- `GOOGLE_WORKSPACE_CLI_LOG`: stderr log filter (e.g., `gws=debug`)
|
||||
- `GOOGLE_WORKSPACE_CLI_LOG_FILE`: directory for JSON log files with daily rotation
|
||||
|
||||
Logging is completely silent by default (zero overhead). Only PII-free metadata is logged: API method ID, HTTP method, status code, latency, and content-type.
|
||||
@@ -56,6 +56,7 @@ The CLI uses a **two-phase argument parsing** strategy:
|
||||
| `src/executor.rs` | HTTP request construction, response handling, schema validation |
|
||||
| `src/schema.rs` | `gws schema` command — introspect API method schemas |
|
||||
| `src/error.rs` | Structured JSON error output |
|
||||
| `src/logging.rs` | Opt-in structured logging (stderr + file) via `tracing` |
|
||||
|
||||
## Demo Videos
|
||||
|
||||
@@ -202,4 +203,11 @@ Use these labels to categorize pull requests and issues:
|
||||
|---|---|
|
||||
| `GOOGLE_WORKSPACE_PROJECT_ID` | GCP project ID override for quota/billing and fallback for helper commands (overridden by `--project` flag) |
|
||||
|
||||
### Logging
|
||||
|
||||
| Variable | Description |
|
||||
|---|---|
|
||||
| `GOOGLE_WORKSPACE_CLI_LOG` | Log level filter for stderr output (e.g., `gws=debug`). Off by default. |
|
||||
| `GOOGLE_WORKSPACE_CLI_LOG_FILE` | Directory for JSON-line log files with daily rotation. Off by default. |
|
||||
|
||||
All variables can also live in a `.env` file (loaded via `dotenvy`).
|
||||
|
||||
Generated
+128
@@ -373,6 +373,21 @@ dependencies = [
|
||||
"libc",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "crossbeam-channel"
|
||||
version = "0.5.15"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "82b8f8f868b36967f9606790d1903570de9ceaf870a7bf9fbbd3016d636a2cb2"
|
||||
dependencies = [
|
||||
"crossbeam-utils",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "crossbeam-utils"
|
||||
version = "0.8.21"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "d0a5c400df2834b80a4c3327b3aad3a4c4cd4de0629063962b03235697506a28"
|
||||
|
||||
[[package]]
|
||||
name = "crossterm"
|
||||
version = "0.29.0"
|
||||
@@ -890,6 +905,9 @@ dependencies = [
|
||||
"thiserror 2.0.18",
|
||||
"tokio",
|
||||
"tokio-util",
|
||||
"tracing",
|
||||
"tracing-appender",
|
||||
"tracing-subscriber",
|
||||
"yup-oauth2",
|
||||
"zeroize",
|
||||
]
|
||||
@@ -1417,6 +1435,15 @@ dependencies = [
|
||||
"winapi",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "matchers"
|
||||
version = "0.2.0"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9"
|
||||
dependencies = [
|
||||
"regex-automata",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "memchr"
|
||||
version = "2.8.0"
|
||||
@@ -1479,6 +1506,15 @@ dependencies = [
|
||||
"minimal-lexical",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "nu-ansi-term"
|
||||
version = "0.50.3"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5"
|
||||
dependencies = [
|
||||
"windows-sys 0.61.2",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "num-conv"
|
||||
version = "0.2.0"
|
||||
@@ -2344,6 +2380,15 @@ dependencies = [
|
||||
"digest",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "sharded-slab"
|
||||
version = "0.1.7"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6"
|
||||
dependencies = [
|
||||
"lazy_static",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "shlex"
|
||||
version = "1.3.0"
|
||||
@@ -2612,6 +2657,15 @@ dependencies = [
|
||||
"syn 2.0.117",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "thread_local"
|
||||
version = "1.1.9"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "f60246a4944f24f6e018aa17cdeffb7818b76356965d03b07d6a9886e8962185"
|
||||
dependencies = [
|
||||
"cfg-if",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "time"
|
||||
version = "0.3.47"
|
||||
@@ -2619,6 +2673,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "743bd48c283afc0388f9b8827b976905fb217ad9e647fae3a379a9283c4def2c"
|
||||
dependencies = [
|
||||
"deranged",
|
||||
"itoa",
|
||||
"libc",
|
||||
"num-conv",
|
||||
"num_threads",
|
||||
@@ -2772,9 +2827,33 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "63e71662fa4b2a2c3a26f570f037eb95bb1f85397f3cd8076caed2f026a6d100"
|
||||
dependencies = [
|
||||
"pin-project-lite",
|
||||
"tracing-attributes",
|
||||
"tracing-core",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "tracing-appender"
|
||||
version = "0.2.4"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "786d480bce6247ab75f005b14ae1624ad978d3029d9113f0a22fa1ac773faeaf"
|
||||
dependencies = [
|
||||
"crossbeam-channel",
|
||||
"thiserror 2.0.18",
|
||||
"time",
|
||||
"tracing-subscriber",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "tracing-attributes"
|
||||
version = "0.1.31"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "7490cfa5ec963746568740651ac6781f701c9c5ea257c58e057f3ba8cf69e8da"
|
||||
dependencies = [
|
||||
"proc-macro2",
|
||||
"quote",
|
||||
"syn 2.0.117",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "tracing-core"
|
||||
version = "0.1.36"
|
||||
@@ -2782,6 +2861,49 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a"
|
||||
dependencies = [
|
||||
"once_cell",
|
||||
"valuable",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "tracing-log"
|
||||
version = "0.2.0"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3"
|
||||
dependencies = [
|
||||
"log",
|
||||
"once_cell",
|
||||
"tracing-core",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "tracing-serde"
|
||||
version = "0.2.0"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "704b1aeb7be0d0a84fc9828cae51dab5970fee5088f83d1dd7ee6f6246fc6ff1"
|
||||
dependencies = [
|
||||
"serde",
|
||||
"tracing-core",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "tracing-subscriber"
|
||||
version = "0.3.23"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319"
|
||||
dependencies = [
|
||||
"matchers",
|
||||
"nu-ansi-term",
|
||||
"once_cell",
|
||||
"regex-automata",
|
||||
"serde",
|
||||
"serde_json",
|
||||
"sharded-slab",
|
||||
"smallvec",
|
||||
"thread_local",
|
||||
"tracing",
|
||||
"tracing-core",
|
||||
"tracing-log",
|
||||
"tracing-serde",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
@@ -2895,6 +3017,12 @@ dependencies = [
|
||||
"wasm-bindgen",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "valuable"
|
||||
version = "0.1.1"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65"
|
||||
|
||||
[[package]]
|
||||
name = "version_check"
|
||||
version = "0.9.5"
|
||||
|
||||
@@ -58,6 +58,9 @@ async-trait = "0.1.89"
|
||||
serde_yaml = "0.9.34"
|
||||
percent-encoding = "2.3.2"
|
||||
zeroize = { version = "1.8.2", features = ["derive"] }
|
||||
tracing = "0.1"
|
||||
tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] }
|
||||
tracing-appender = "0.2"
|
||||
|
||||
[target.'cfg(target_os = "macos")'.dependencies]
|
||||
keyring = { version = "3.6.3", features = ["apple-native"] }
|
||||
|
||||
@@ -383,6 +383,8 @@ All variables are optional. See [`.env.example`](.env.example) for a copy-paste
|
||||
| `GOOGLE_WORKSPACE_CLI_CONFIG_DIR` | Override config directory (default: `~/.config/gws`) |
|
||||
| `GOOGLE_WORKSPACE_CLI_SANITIZE_TEMPLATE` | Default Model Armor template |
|
||||
| `GOOGLE_WORKSPACE_CLI_SANITIZE_MODE` | `warn` (default) or `block` |
|
||||
| `GOOGLE_WORKSPACE_CLI_LOG` | Log level for stderr (e.g., `gws=debug`). Off by default. |
|
||||
| `GOOGLE_WORKSPACE_CLI_LOG_FILE` | Directory for JSON log files with daily rotation. Off by default. |
|
||||
| `GOOGLE_WORKSPACE_PROJECT_ID` | GCP project ID override for quota/billing and fallback for helper commands |
|
||||
|
||||
Environment variables can also be set in a `.env` file (loaded via [dotenvy](https://crates.io/crates/dotenvy)).
|
||||
|
||||
@@ -41,6 +41,13 @@ pub async fn send_with_retry(
|
||||
.and_then(|s| s.parse::<u64>().ok())
|
||||
.unwrap_or(1 << attempt); // 1, 2, 4 seconds
|
||||
|
||||
tracing::debug!(
|
||||
attempt = attempt + 1,
|
||||
max_retries = MAX_RETRIES,
|
||||
retry_after_secs = retry_after,
|
||||
"Rate limited, retrying"
|
||||
);
|
||||
|
||||
tokio::time::sleep(std::time::Duration::from_secs(retry_after)).await;
|
||||
}
|
||||
|
||||
|
||||
@@ -207,6 +207,7 @@ pub async fn fetch_discovery_document(
|
||||
if modified.elapsed().unwrap_or_default() < std::time::Duration::from_secs(86400) {
|
||||
let data = std::fs::read_to_string(&cache_file)?;
|
||||
let doc: RestDescription = serde_json::from_str(&data)?;
|
||||
tracing::debug!(service = %service, version = %version, "Discovery cache hit");
|
||||
return Ok(doc);
|
||||
}
|
||||
}
|
||||
@@ -219,6 +220,7 @@ pub async fn fetch_discovery_document(
|
||||
crate::validate::encode_path_segment(version),
|
||||
);
|
||||
|
||||
tracing::debug!(service = %service, version = %version, "Fetching discovery document");
|
||||
let client = crate::client::build_client()?;
|
||||
let resp = client.get(&url).send().await?;
|
||||
|
||||
|
||||
@@ -422,7 +422,10 @@ pub async fn execute_method(
|
||||
)
|
||||
.await?;
|
||||
|
||||
let method_id = method.id.as_deref().unwrap_or("unknown");
|
||||
let start = std::time::Instant::now();
|
||||
let response = request.send().await.context("HTTP request failed")?;
|
||||
let latency_ms = start.elapsed().as_millis() as u64;
|
||||
|
||||
let status = response.status();
|
||||
let content_type = response
|
||||
@@ -434,9 +437,27 @@ pub async fn execute_method(
|
||||
|
||||
if !status.is_success() {
|
||||
let error_body = response.text().await.unwrap_or_default();
|
||||
tracing::warn!(
|
||||
api_method = method_id,
|
||||
http_method = %method.http_method,
|
||||
status = status.as_u16(),
|
||||
latency_ms = latency_ms,
|
||||
"API error"
|
||||
);
|
||||
return handle_error_response(status, &error_body, &auth_method);
|
||||
}
|
||||
|
||||
tracing::debug!(
|
||||
api_method = method_id,
|
||||
http_method = %method.http_method,
|
||||
status = status.as_u16(),
|
||||
latency_ms = latency_ms,
|
||||
content_type = %content_type,
|
||||
is_upload = input.is_upload,
|
||||
page = pages_fetched,
|
||||
"API request"
|
||||
);
|
||||
|
||||
let is_json =
|
||||
content_type.contains("application/json") || content_type.contains("text/json");
|
||||
|
||||
|
||||
+112
@@ -0,0 +1,112 @@
|
||||
// Copyright 2026 Google LLC
|
||||
//
|
||||
// Licensed under the Apache License, Version 2.0 (the "License");
|
||||
// you may not use this file except in compliance with the License.
|
||||
// You may obtain a copy of the License at
|
||||
//
|
||||
// http://www.apache.org/licenses/LICENSE-2.0
|
||||
//
|
||||
// Unless required by applicable law or agreed to in writing, software
|
||||
// distributed under the License is distributed on an "AS IS" BASIS,
|
||||
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||
// See the License for the specific language governing permissions and
|
||||
// limitations under the License.
|
||||
|
||||
//! Structured Logging
|
||||
//!
|
||||
//! Provides opt-in, PII-free logging for HTTP requests and CLI operations.
|
||||
//! All output goes to stderr or a log file — stdout remains clean for
|
||||
//! machine-consumable JSON output.
|
||||
//!
|
||||
//! ## Environment Variables
|
||||
//!
|
||||
//! - `GOOGLE_WORKSPACE_CLI_LOG`: Filter directive for stderr logging
|
||||
//! (e.g., `gws=debug`, `gws=trace`). If unset, no stderr logging.
|
||||
//!
|
||||
//! - `GOOGLE_WORKSPACE_CLI_LOG_FILE`: Directory path for JSON-line log
|
||||
//! files with daily rotation. If unset, no file logging.
|
||||
|
||||
use tracing_subscriber::prelude::*;
|
||||
|
||||
/// Environment variable controlling stderr log output.
|
||||
const ENV_LOG: &str = "GOOGLE_WORKSPACE_CLI_LOG";
|
||||
|
||||
/// Environment variable controlling file log output.
|
||||
const ENV_LOG_FILE: &str = "GOOGLE_WORKSPACE_CLI_LOG_FILE";
|
||||
|
||||
/// Initialize the tracing subscriber based on environment variables.
|
||||
///
|
||||
/// If neither `GOOGLE_WORKSPACE_CLI_LOG` nor `GOOGLE_WORKSPACE_CLI_LOG_FILE`
|
||||
/// is set, this is a no-op and logging adds zero overhead.
|
||||
///
|
||||
/// This function must be called at most once (typically in `main()`).
|
||||
/// Subsequent calls will silently fail (tracing only allows one global
|
||||
/// subscriber).
|
||||
pub fn init_logging() {
|
||||
let stderr_filter = std::env::var(ENV_LOG).ok();
|
||||
let log_file_dir = std::env::var(ENV_LOG_FILE).ok();
|
||||
|
||||
// If neither env var is set, skip initialization entirely for zero overhead.
|
||||
if stderr_filter.is_none() && log_file_dir.is_none() {
|
||||
return;
|
||||
}
|
||||
|
||||
let registry = tracing_subscriber::registry();
|
||||
|
||||
// Stderr layer: human-readable, filtered by GOOGLE_WORKSPACE_CLI_LOG
|
||||
let stderr_layer = stderr_filter.map(|filter| {
|
||||
let env_filter = tracing_subscriber::EnvFilter::new(filter);
|
||||
tracing_subscriber::fmt::layer()
|
||||
.with_writer(std::io::stderr)
|
||||
.with_target(false)
|
||||
.compact()
|
||||
.with_filter(env_filter)
|
||||
});
|
||||
|
||||
// File layer: JSON-line output with daily rotation
|
||||
let (file_layer, _guard) = if let Some(ref dir) = log_file_dir {
|
||||
let file_appender = tracing_appender::rolling::daily(dir, "gws.log");
|
||||
let (non_blocking, guard) = tracing_appender::non_blocking(file_appender);
|
||||
let layer = tracing_subscriber::fmt::layer()
|
||||
.json()
|
||||
.with_writer(non_blocking)
|
||||
.with_target(true)
|
||||
.with_filter(tracing_subscriber::EnvFilter::new("gws=debug"));
|
||||
(Some(layer), Some(guard))
|
||||
} else {
|
||||
(None, None)
|
||||
};
|
||||
|
||||
// Compose layers and set as global subscriber.
|
||||
// The guard is leaked intentionally so the non-blocking writer stays
|
||||
// alive for the lifetime of the process.
|
||||
let subscriber = registry.with(stderr_layer).with(file_layer);
|
||||
if tracing::subscriber::set_global_default(subscriber).is_ok() {
|
||||
if let Some(guard) = _guard {
|
||||
// Leak the guard so the non-blocking writer lives for the process lifetime.
|
||||
// This is the recommended pattern from tracing-appender docs.
|
||||
std::mem::forget(guard);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::*;
|
||||
|
||||
#[test]
|
||||
fn test_init_logging_default_no_panic() {
|
||||
// With no env vars set, init_logging should be a no-op and not panic.
|
||||
// We can't truly test the global subscriber in unit tests (it's global state),
|
||||
// but we can verify the early-return path doesn't panic.
|
||||
std::env::remove_var(ENV_LOG);
|
||||
std::env::remove_var(ENV_LOG_FILE);
|
||||
init_logging();
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn test_env_var_names() {
|
||||
assert_eq!(ENV_LOG, "GOOGLE_WORKSPACE_CLI_LOG");
|
||||
assert_eq!(ENV_LOG_FILE, "GOOGLE_WORKSPACE_CLI_LOG_FILE");
|
||||
}
|
||||
}
|
||||
@@ -31,6 +31,7 @@ mod formatter;
|
||||
mod fs_util;
|
||||
mod generate_skills;
|
||||
mod helpers;
|
||||
mod logging;
|
||||
mod oauth_config;
|
||||
mod schema;
|
||||
mod services;
|
||||
@@ -47,6 +48,9 @@ async fn main() {
|
||||
// Load .env file if present (silently ignored if missing)
|
||||
let _ = dotenvy::dotenv();
|
||||
|
||||
// Initialize structured logging (no-op if env vars are unset)
|
||||
logging::init_logging();
|
||||
|
||||
if let Err(err) = run().await {
|
||||
print_error_json(&err);
|
||||
std::process::exit(err.exit_code());
|
||||
@@ -466,6 +470,10 @@ fn print_usage() {
|
||||
println!(
|
||||
" GOOGLE_WORKSPACE_PROJECT_ID Override the GCP project ID for quota and billing"
|
||||
);
|
||||
println!(" GOOGLE_WORKSPACE_CLI_LOG Log level for stderr (e.g., gws=debug)");
|
||||
println!(
|
||||
" GOOGLE_WORKSPACE_CLI_LOG_FILE Directory for JSON log files (daily rotation)"
|
||||
);
|
||||
println!();
|
||||
println!("EXIT CODES:");
|
||||
for (code, description) in crate::error::EXIT_CODE_DOCUMENTATION {
|
||||
|
||||
Reference in New Issue
Block a user