Add file and line num to log messages (#3782)

This commit adds a `slog::KV` implementation to `omicron_common` that
can be plugged into any root slog logger to append file and line number
information to all log entries.

An example log message looks like the following:

```
Jul 27 22:19:44.139 WARN Connection error: Close, remote_peer_id: pc-a-1, peer_id: pc-b-1, subcomponent: bootstore, file: bootstore/src/schemes/v0/peer_networking.rs:216
```

This logging support was then added to a bunch of existing servers.

Author: andrewjstone

common/src/lib.rs

@@ -50,3 +50,28 @@ macro_rules! generate_logging_api {
         );
     };
 }
+
+/// A type that allows adding file and line numbers to log messages
+/// automatically. It should be instantiated at the root logger of each
+/// executable that desires this functionality, as in the following example.
+/// ```ignore
+///     slog::Logger::root(drain, o!(FileKv))
+/// ```
+pub struct FileKv;
+
+impl slog::KV for FileKv {
+    fn serialize(
+        &self,
+        record: &slog::Record,
+        serializer: &mut dyn slog::Serializer,
+    ) -> slog::Result {
+        // Only log file information when severity is at least info level
+        if record.level() > slog::Level::Info {
+            return Ok(());
+        }
+        serializer.emit_arguments(
+            "file".into(),
+            &format_args!("{}:{}", record.file(), record.line()),
+        )
+    }
+}

gateway/src/lib.rs

@@ -25,6 +25,7 @@ pub use management_switch::SpIdentifier;
 pub use management_switch::SpType;
 pub use management_switch::SwitchPortConfig;
 pub use management_switch::SwitchPortDescription;
+use omicron_common::FileKv;
 
 use dropshot::ConfigDropshot;
 use dropshot::HandlerTaskMode;
@@ -302,7 +303,7 @@ pub async fn start_server(
             .to_logger("gateway")
             .map_err(|message| format!("initializing logger: {}", message))?,
     );
-    let log = slog::Logger::root(drain.fuse(), slog::o!());
+    let log = slog::Logger::root(drain.fuse(), slog::o!(FileKv));
     if let slog_dtrace::ProbeRegistration::Failed(e) = registration {
         let msg = format!("failed to register DTrace probes: {}", e);
         error!(log, "{}", msg);

installinator/src/dispatch.rs

@@ -13,6 +13,7 @@ use installinator_common::{
     InstallinatorStepId, StepContext, StepHandle, StepProgress, StepSuccess,
     StepWarning, UpdateEngine,
 };
+use omicron_common::FileKv;
 use omicron_common::{
     api::internal::nexus::KnownArtifactKind,
     update::{ArtifactHash, ArtifactHashId, ArtifactKind},
@@ -66,7 +67,7 @@ impl InstallinatorApp {
 
         let drain = slog::Duplicate::new(file_drain, stderr_drain).fuse();
         let drain = slog_async::Async::new(drain).build().fuse();
-        Ok(slog::Logger::root(drain, slog::o!()))
+        Ok(slog::Logger::root(drain, slog::o!(FileKv)))
     }
 }
 

nexus/src/lib.rs

@@ -34,6 +34,7 @@ use omicron_common::address::IpRange;
 use omicron_common::api::internal::shared::{
     ExternalPortDiscovery, SwitchLocation,
 };
+use omicron_common::FileKv;
 use slog::Logger;
 use std::collections::HashMap;
 use std::net::{SocketAddr, SocketAddrV6};
@@ -311,7 +312,7 @@ pub async fn run_server(config: &Config) -> Result<(), String> {
                 format!("initializing logger: {}", message)
             })?,
         );
-    let log = slog::Logger::root(drain.fuse(), slog::o!());
+    let log = slog::Logger::root(drain.fuse(), slog::o!(FileKv));
     if let slog_dtrace::ProbeRegistration::Failed(e) = registration {
         let msg = format!("failed to register DTrace probes: {}", e);
         error!(log, "{}", msg);

oximeter/collector/src/lib.rs

@@ -15,7 +15,7 @@ use internal_dns::resolver::{ResolveError, Resolver};
 use internal_dns::ServiceName;
 use omicron_common::address::{CLICKHOUSE_PORT, NEXUS_INTERNAL_PORT};
 use omicron_common::api::internal::nexus::ProducerEndpoint;
-use omicron_common::backoff;
+use omicron_common::{backoff, FileKv};
 use oximeter::types::{ProducerResults, ProducerResultsItem};
 use oximeter_db::{Client, DbWrite};
 use serde::{Deserialize, Serialize};
@@ -472,7 +472,7 @@ impl Oximeter {
         log: Logger,
     ) -> Result<Self, Error> {
         let (drain, registration) = slog_dtrace::with_drain(log);
-        let log = slog::Logger::root(drain.fuse(), o!());
+        let log = slog::Logger::root(drain.fuse(), o!(FileKv));
         if let slog_dtrace::ProbeRegistration::Failed(e) = registration {
             let msg = format!("failed to register DTrace probes: {}", e);
             error!(log, "{}", msg);

oximeter/producer/src/lib.rs

@@ -17,6 +17,7 @@ use dropshot::HttpServerStarter;
 use dropshot::Path;
 use dropshot::RequestContext;
 use omicron_common::api::internal::nexus::ProducerEndpoint;
+use omicron_common::FileKv;
 use oximeter::types::ProducerRegistry;
 use oximeter::types::ProducerResults;
 use schemars::JsonSchema;
@@ -95,7 +96,7 @@ impl Server {
             LogConfig::Logger(log) => log.clone(),
         };
         let (drain, registration) = slog_dtrace::with_drain(base_logger);
-        let log = Logger::root(drain.fuse(), slog::o!());
+        let log = Logger::root(drain.fuse(), slog::o!(FileKv));
         if let slog_dtrace::ProbeRegistration::Failed(e) = registration {
             let msg = format!("failed to register DTrace probes: {}", e);
             error!(log, "failed to register DTrace probes: {}", e);

sled-agent/src/bootstrap/server.rs

@@ -14,6 +14,7 @@ use super::views::ResponseEnvelope;
 use crate::bootstrap::http_entrypoints::api as http_api;
 use crate::bootstrap::maghemite;
 use crate::config::Config as SledConfig;
+use omicron_common::FileKv;
 use sled_hardware::underlay;
 use slog::Drain;
 use slog::Logger;
@@ -44,7 +45,7 @@ impl Server {
                 format!("initializing logger: {}", message)
             })?,
         );
-        let log = slog::Logger::root(drain.fuse(), slog::o!());
+        let log = slog::Logger::root(drain.fuse(), slog::o!(FileKv));
         if let slog_dtrace::ProbeRegistration::Failed(e) = registration {
             let msg = format!("Failed to register DTrace probes: {}", e);
             error!(log, "{}", msg);

sled-agent/src/sim/server.rs

@@ -22,6 +22,7 @@ use omicron_common::backoff::{
     retry_notify, retry_policy_internal_service_aggressive, BackoffError,
 };
 use omicron_common::nexus_config::NUM_INITIAL_RESERVED_IP_ADDRESSES;
+use omicron_common::FileKv;
 use slog::{info, Drain, Logger};
 use std::collections::HashMap;
 use std::net::IpAddr;
@@ -269,7 +270,7 @@ pub async fn run_standalone_server(
             .to_logger("sled-agent")
             .map_err(|message| anyhow!("initializing logger: {}", message))?,
     );
-    let log = slog::Logger::root(drain.fuse(), slog::o!());
+    let log = slog::Logger::root(drain.fuse(), slog::o!(FileKv));
     if let slog_dtrace::ProbeRegistration::Failed(e) = registration {
         let msg = format!("failed to register DTrace probes: {}", e);
         error!(log, "{}", msg);

wicket/src/dispatch.rs

@@ -9,7 +9,7 @@ use std::net::{Ipv6Addr, SocketAddrV6};
 use anyhow::{bail, Context, Result};
 use camino::{Utf8Path, Utf8PathBuf};
 use clap::Parser;
-use omicron_common::address::WICKETD_PORT;
+use omicron_common::{address::WICKETD_PORT, FileKv};
 use slog::Drain;
 
 use crate::{rack_setup::SetupArgs, upload::UploadArgs, Runner};
@@ -81,7 +81,7 @@ fn setup_log(
         WithStderr::No => slog_async::Async::new(drain).build().fuse(),
     };
 
-    Ok(slog::Logger::root(drain, slog::o!()))
+    Ok(slog::Logger::root(drain, slog::o!(FileKv)))
 }
 
 #[derive(Copy, Clone, Debug)]

wicketd/src/lib.rs

@@ -22,6 +22,7 @@ pub use installinator_progress::{IprUpdateTracker, RunningUpdateState};
 pub use inventory::{RackV1Inventory, SpInventory};
 use mgs::make_mgs_client;
 pub(crate) use mgs::{MgsHandle, MgsManager};
+use omicron_common::FileKv;
 use sled_hardware::Baseboard;
 
 use dropshot::{ConfigDropshot, HandlerTaskMode, HttpServer};
@@ -65,7 +66,7 @@ impl Server {
     pub async fn start(log: slog::Logger, args: Args) -> Result<Self, String> {
         let (drain, registration) = slog_dtrace::with_drain(log);
 
-        let log = slog::Logger::root(drain.fuse(), slog::o!());
+        let log = slog::Logger::root(drain.fuse(), slog::o!(FileKv));
         if let slog_dtrace::ProbeRegistration::Failed(e) = registration {
             let msg = format!("failed to register DTrace probes: {}", e);
             error!(log, "{}", msg);