fix(logs): Updated remaining log messages to match standards (vectord…

…otdev#4737) Co-authored-by: Bruce Guenter <[email protected]> Co-authored-by: Jesse Szwedko <[email protected]>
DocLM · Oct 28, 2020 · 068d158 · 068d158
1 parent b0a95f2
commit 068d158
Show file tree

Hide file tree

Showing 155 changed files with 572 additions and 513 deletions.
diff --git a/.github/workflows/pr.yml b/.github/workflows/pr.yml
@@ -249,9 +249,9 @@ jobs:
       - name: Check that generated Kubernetes YAML doesn't diverge from Helm
         if: needs.changes.outputs.helm == 'true'
         run: make check-kubernetes-yaml
-      - name: Check internal events
-        if: needs.changes.outputs.internal_events == 'true'
-        run: make check-internal-events
+      - name: Check events
+        if: needs.changes.outputs.source == 'true'
+        run: make check-events
       - name: Check cargo deny
         if: needs.changes.outputs.dependencies == 'true'
         uses: EmbarkStudios/cargo-deny-action@v1

diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md
@@ -429,6 +429,26 @@ rustup component add rustfmt
 make fmt
 ```
 
+##### Logging style
+
+
+- Always use the [Tracing crate](https://tracing.rs/tracing/)'s key/value style for log events.
+- Events should be capitalized and end with a period, `.`.
+- Never use `e` or `err` - always spell out `error` to enrich logs and make it clear what the output is.
+- Prefer Display over Debug, `?error` and not `%error`.
+
+Nope!
+
+```rust
+warn!("Failed to merge value: {}.", err);
+```
+
+Yep!
+
+```rust
+warn!(message = "Failed to merge value.", error = ?error);
+```
+
 #### Feature flags
 
 When a new component (a source, transform, or sink) is added, it has to be put

diff --git a/Makefile b/Makefile
@@ -851,8 +851,8 @@ check-helm-dependencies: ## Check that Helm charts have up-to-date dependencies
 check-kubernetes-yaml: ## Check that the generated Kubernetes YAML config is up to date
 	${MAYBE_ENVIRONMENT_EXEC} ./scripts/kubernetes-yaml.sh check
 
-check-internal-events: ## Check that internal events satisfy patterns set in https://github.com/timberio/vector/blob/master/rfcs/2020-03-17-2064-event-driven-observability.md
-	${MAYBE_ENVIRONMENT_EXEC} ./scripts/check-internal-events.sh
+check-events: ## Check that events satisfy patterns set in https://github.com/timberio/vector/blob/master/rfcs/2020-03-17-2064-event-driven-observability.md
+	${MAYBE_ENVIRONMENT_EXEC} ./scripts/check-events.sh
 
 ##@ Packaging
 

diff --git a/benches/batch.rs b/benches/batch.rs
@@ -41,7 +41,7 @@ fn batching(
                     Duration::from_secs(1),
                     acker,
                 )
-                .sink_map_err(|e| panic!(e));
+                .sink_map_err(|error| panic!(error));
 
                 let _ = rt.block_on(input.forward(batch_sink).compat()).unwrap();
             },
@@ -86,7 +86,7 @@ fn partitioned_batching(
                     Duration::from_secs(1),
                     acker,
                 )
-                .sink_map_err(|e| panic!(e));
+                .sink_map_err(|error| panic!(error));
 
                 let _ = rt.block_on(input.forward(batch_sink).compat()).unwrap();
             },

diff --git a/lib/codec/src/lib.rs b/lib/codec/src/lib.rs
@@ -93,7 +93,7 @@ impl Decoder for BytesDelimitedCodec {
                     // reach the next delimiter
                     self.is_discarding = true;
                     warn!(
-                        message = "Discarding frame larger than max_length",
+                        message = "Discarding frame larger than max_length.",
                         buf_len = buf.len(),
                         max_length = self.max_length,
                         rate_limit_secs = 30

diff --git a/lib/file-source/src/file_server.rs b/lib/file-source/src/file_server.rs
@@ -189,7 +189,7 @@ where
                                     ) {
                                         if old_modified_time < new_modified_time {
                                             info!(
-                                                message = "switching to watch most recently modified file.",
+                                                message = "Switching to watch most recently modified file.",
                                                 new_modified_time = ?new_modified_time,
                                                 old_modified_time = ?old_modified_time,
                                             );
@@ -224,7 +224,7 @@ where
 
                     let sz = line.len();
                     trace!(
-                        message = "read bytes.",
+                        message = "Read bytes.",
                         path = ?watcher.path,
                         bytes = ?sz
                     );
@@ -290,7 +290,7 @@ where
             match result {
                 Ok(()) => {}
                 Err(error) => {
-                    error!(message = "output channel closed.", ?error);
+                    error!(message = "Output channel closed.", error = ?error);
                     return Err(error);
                 }
             }
@@ -487,14 +487,14 @@ impl Fingerprinter {
         emitter: &impl FileSourceInternalEvents,
     ) -> Option<FileFingerprint> {
         self.get_fingerprint_of_file(path, buffer)
-            .map_err(|err| {
-                if err.kind() == io::ErrorKind::UnexpectedEof {
+            .map_err(|error| {
+                if error.kind() == io::ErrorKind::UnexpectedEof {
                     if !known_small_files.contains(path) {
                         emitter.emit_file_checksum_failed(path);
                         known_small_files.insert(path.clone());
                     }
                 } else {
-                    emitter.emit_file_fingerprint_read_failed(path, err);
+                    emitter.emit_file_fingerprint_read_failed(path, error);
                 }
             })
             .ok()

diff --git a/lib/file-source/src/file_watcher.rs b/lib/file-source/src/file_watcher.rs
@@ -254,7 +254,7 @@ fn read_until_with_max_size<R: BufRead + ?Sized>(
 
         if !discarding && buf.len() > max_size {
             warn!(
-                message = "found line that exceeds max_line_bytes; discarding.",
+                message = "Found line that exceeds max_line_bytes; discarding.",
                 rate_limit_secs = 30
             );
             discarding = true;

diff --git a/lib/tracing-limit/benches/limit.rs b/lib/tracing-limit/benches/limit.rs
@@ -25,7 +25,7 @@ fn bench(c: &mut Criterion) {
                 b.iter(|| {
                     for _ in 0..**n {
                         info!(
-                            message = "hello world",
+                            message = "Hello world!",
                             foo = "foo",
                             bar = "bar",
                             baz = 3,
@@ -47,7 +47,7 @@ fn bench(c: &mut Criterion) {
                 b.iter(|| {
                     for _ in 0..**n {
                         info!(
-                            message = "hello world",
+                            message = "Hello world!",
                             foo = "foo",
                             bar = "bar",
                             baz = 3,

diff --git a/lib/tracing-limit/examples/basic.rs b/lib/tracing-limit/examples/basic.rs
@@ -17,7 +17,7 @@ fn main() {
     tracing::dispatcher::with_default(&dispatch, || {
         // This should print every 2 events
         for i in 0..40 {
-            info!(message = "hello, world!", count = &i, rate_limit_secs = 5);
+            info!(message = "Hello, world!", count = &i, rate_limit_secs = 5);
             trace!("This field is not rate limited!");
             std::thread::sleep(std::time::Duration::from_millis(1000));
         }

diff --git a/rfcs/2020-03-17-2064-event-driven-observability.md b/rfcs/2020-03-17-2064-event-driven-observability.md
@@ -24,7 +24,7 @@ messages
         counter!("bytes_processed", msg.len() as u64, "source" => "file");
         create_event(msg, file, &host_key, &hostname, &file_key)
     })
-    .forward(out.sink_map_err(|e| error!(%e)))
+    .forward(out.sink_map_err(|error| error!(?error)))
 ```
 
 It's immediately obvious that we're trading off brevity for thoroughness. There
@@ -79,7 +79,7 @@ messages
         });
         create_event(msg, file, &host_key, &hostname, &file_key)
     })
-    .forward(out.sink_map_err(|e| error!(%e)))
+    .forward(out.sink_map_err(|error| error!(?error)))
 ```
 
 And in the `internal_events` module, we would add the following:

diff --git a/scripts/check-internal-events.sh → scripts/check-events.sh b/scripts/check-internal-events.sh → scripts/check-events.sh
@@ -1,13 +1,13 @@
 #!/usr/bin/env bash
 # shellcheck disable=SC2016
-exec find src/internal_events -type f -name \*.rs -exec awk '
+exec find src -type f -name \*.rs -exec awk '
   BEGIN {
     RS = ""
     FS = "\n"
     error_count = 0
   }
 
-  match($0, /(trace|debug|info|warn|error)!\(\s*(message\s*=\s*)?"([^"]+)"/, groups) {
+  match($0, /(trace|debug|info|warn|error)!\(\s*(message\s*=\s*)?"([^({)][^("]+)"/, groups) {
     message = groups[3]
     delete errors;
     if (!match(message, /^[A-Z]/)) { errors[1] = "Message must begin with a capital." }

diff --git a/src/app.rs b/src/app.rs
@@ -127,14 +127,14 @@ impl Application {
                     return Err(code);
                 };
 
-                info!("Log level {:?} is enabled.", level);
+                info!(message = "Log level is enabled.", level = ?level);
 
                 let config_paths = config::process_paths(&config_paths).ok_or(exitcode::CONFIG)?;
 
                 if watch_config {
                     // Start listening for config changes immediately.
                     config::watcher::spawn_thread(&config_paths, None).map_err(|error| {
-                        error!(message = "Unable to start config watcher.", %error);
+                        error!(message = "Unable to start config watcher.", error = ?error);
                         exitcode::CONFIG
                     })?;
                 }

diff --git a/src/buffers/disk/leveldb_buffer.rs b/src/buffers/disk/leveldb_buffer.rs
@@ -197,8 +197,8 @@ impl Stream for Reader {
                     let event = Event::from(event);
                     Ok(Async::Ready(Some(event)))
                 }
-                Err(err) => {
-                    error!("Error deserializing proto: {:?}", err);
+                Err(error) => {
+                    error!(message = "Error deserializing proto.", error = ?error);
                     debug_assert!(false);
                     self.poll()
                 }

diff --git a/src/buffers/mod.rs b/src/buffers/mod.rs
@@ -60,7 +60,9 @@ impl BufferInputCloner {
     pub fn get(&self) -> Box<dyn Sink<SinkItem = Event, SinkError = ()> + Send> {
         match self {
             BufferInputCloner::Memory(tx, when_full) => {
-                let inner = tx.clone().sink_map_err(|e| error!("sender error: {:?}", e));
+                let inner = tx
+                    .clone()
+                    .sink_map_err(|error| error!(message = "Sender error.", error = ?error));
                 if when_full == &WhenFull::DropNewest {
                     Box::new(DropWhenFull { inner })
                 } else {
@@ -123,7 +125,7 @@ impl BufferConfig {
                 let buffer_dir = format!("{}_buffer", sink_name);
 
                 let (tx, rx, acker) = disk::open(&data_dir, buffer_dir.as_ref(), *max_size)
-                    .map_err(|err| err.to_string())?;
+                    .map_err(|error| error.to_string())?;
                 let tx = BufferInputCloner::Disk(tx, *when_full);
                 let rx = Box::new(rx);
                 Ok((tx, rx, acker))

diff --git a/src/cli.rs b/src/cli.rs
@@ -169,7 +169,7 @@ impl std::str::FromStr for LogFormat {
 
 pub fn handle_config_errors(errors: Vec<String>) -> exitcode::ExitCode {
     for error in errors {
-        error!("Configuration error: {}", error);
+        error!(message = "Configuration error.", error = ?error);
     }
 
     exitcode::CONFIG

diff --git a/src/conditions/check_fields.rs b/src/conditions/check_fields.rs
@@ -348,7 +348,7 @@ impl IpCidrPredicate {
         };
         let cidrs = match cidr_strings.iter().map(IpCidr::from_str).collect() {
             Ok(v) => v,
-            Err(e) => return Err(format!("Invalid IP CIDR: {}", e)),
+            Err(error) => return Err(format!("Invalid IP CIDR: {}", error)),
         };
         Ok(Box::new(Self { target, cidrs }))
     }
@@ -450,7 +450,7 @@ fn build_predicate(
         "contains" => ContainsPredicate::new(target, arg),
         "prefix" => {
             warn!(
-                message = "The \"prefix\" comparison predicate is deprecated, use \"starts_with\" instead",
+                message = "The `prefix` comparison predicate is deprecated, use `starts_with` instead.",
                 %target,
             );
             StartsWithPredicate::new(target, arg)

diff --git a/src/config/loading.rs b/src/config/loading.rs
@@ -120,10 +120,10 @@ fn open_config(path: &Path) -> Option<File> {
         Ok(f) => Some(f),
         Err(error) => {
             if let std::io::ErrorKind::NotFound = error.kind() {
-                error!(message = "Config file not found in path.", ?path);
+                error!(message = "Config file not found in path.", path = ?path);
                 None
             } else {
-                error!(message = "Error opening config file.", %error);
+                error!(message = "Error opening config file.", error = ?error);
                 None
             }
         }

diff --git a/src/config/vars.rs b/src/config/vars.rs
@@ -10,7 +10,7 @@ pub fn interpolate(input: &str, vars: &HashMap<String, String>) -> String {
             .map(|name| {
                 vars.get(name).map(|val| val.as_str()).unwrap_or_else(|| {
                     caps.get(3).map(|m| m.as_str()).unwrap_or_else(|| {
-                        warn!("unknown env var in config: {:?}", name);
+                        warn!(message = "Unknown env var in config.", name = ?name);
                         ""
                     })
                 })

diff --git a/src/config/watcher.rs b/src/config/watcher.rs
@@ -43,30 +43,30 @@ pub fn spawn_thread(
         if let Some((mut watcher, receiver)) = watcher.take() {
             while let Ok(RawEvent { op: Ok(event), .. }) = receiver.recv() {
                 if event.intersects(Op::CREATE | Op::REMOVE | Op::WRITE | Op::CLOSE_WRITE) {
-                    debug!(message = "Configuration file change detected.", ?event);
+                    debug!(message = "Configuration file change detected.", event = ?event);
 
                     // Consume events until delay amount of time has passed since the latest event.
                     while let Ok(..) = receiver.recv_timeout(delay) {}
 
                     // We need to read paths to resolve any inode changes that may have happened.
                     // And we need to do it before raising sighup to avoid missing any change.
                     if let Err(error) = add_paths(&mut watcher, &config_paths) {
-                        error!(message = "Failed to read files to watch.", ?error);
+                        error!(message = "Failed to read files to watch.", error = ?error);
                         break;
                     }
 
                     info!("Configuration file changed.");
                     raise_sighup();
                 } else {
-                    debug!(message = "Ignoring event.", ?event)
+                    debug!(message = "Ignoring event.", event = ?event)
                 }
             }
         }
 
         thread::sleep(RETRY_TIMEOUT);
 
         watcher = create_watcher(&config_paths)
-            .map_err(|error| error!(message = "Failed to create file watcher.", ?error))
+            .map_err(|error| error!(message = "Failed to create file watcher.", error = ?error))
             .ok();
 
         if watcher.is_some() {

diff --git a/src/event/mod.rs b/src/event/mod.rs
@@ -123,7 +123,7 @@ fn decode_value(input: proto::Value) -> Option<Value> {
         Some(proto::value::Kind::Array(array)) => decode_array(array.items),
         Some(proto::value::Kind::Null(_)) => Some(Value::Null),
         None => {
-            error!("encoded event contains unknown value kind");
+            error!("Encoded event contains unknown value kind.");
             None
         }
     }

diff --git a/src/expiring_hash_map.rs b/src/expiring_hash_map.rs
@@ -166,7 +166,7 @@ where
     ///                 println!("Expired: {}", val);
     ///                 break;
     ///             }
-    ///             Some(Err(err)) => panic!(format!("Timer error: {:?}", err)),
+    ///             Some(Err(error)) => panic!(format!("Timer error: {:?}", error)),
     ///         },
     ///         _ = tokio::time::delay_for(Duration::from_millis(100)) => map.insert(
     ///             "key".to_owned(),

diff --git a/src/http.rs b/src/http.rs
@@ -150,7 +150,9 @@ impl Auth {
             }
             Auth::Bearer { token } => match Authorization::bearer(&token) {
                 Ok(auth) => req.headers_mut().typed_insert(auth),
-                Err(error) => error!(message = "invalid bearer token", %token, %error),
+                Err(error) => {
+                    error!(message = "Invalid bearer token.", token = %token, error = ?error)
+                }
             },
         }
     }

diff --git a/src/internal_events/add_fields.rs b/src/internal_events/add_fields.rs
@@ -17,7 +17,7 @@ pub struct AddFieldsTemplateRenderingError<'a> {
 
 impl<'a> InternalEvent for AddFieldsTemplateRenderingError<'a> {
     fn emit_logs(&self) {
-        error!(message = "Failed to render templated value; discarding value.", %self.field, rate_limit_secs = 30);
+        error!(message = "Failed to render templated value; discarding value.", field = %self.field, rate_limit_secs = 30);
     }
 
     fn emit_metrics(&self) {
@@ -33,7 +33,7 @@ pub struct AddFieldsTemplateInvalid<'a> {
 
 impl<'a> InternalEvent for AddFieldsTemplateInvalid<'a> {
     fn emit_logs(&self) {
-        error!(message = "Invalid template; using as string.", %self.field, %self.error, rate_limit_secs = 30);
+        error!(message = "Invalid template; using as string.", field = %self.field, error = ?self.error, rate_limit_secs = 30);
     }
 
     fn emit_metrics(&self) {
@@ -48,7 +48,7 @@ pub struct AddFieldsFieldOverwritten<'a> {
 
 impl<'a> InternalEvent for AddFieldsFieldOverwritten<'a> {
     fn emit_logs(&self) {
-        debug!(message = "Field overwritten.", %self.field, rate_limit_secs = 30);
+        debug!(message = "Field overwritten.", field = %self.field, rate_limit_secs = 30);
     }
 }
 
@@ -59,6 +59,6 @@ pub struct AddFieldsFieldNotOverwritten<'a> {
 
 impl<'a> InternalEvent for AddFieldsFieldNotOverwritten<'a> {
     fn emit_logs(&self) {
-        debug!(message = "Field not overwritten.", %self.field, rate_limit_secs = 30);
+        debug!(message = "Field not overwritten.", field = %self.field, rate_limit_secs = 30);
     }
 }