Initial structured logging support (#564)

* Initial structured logging support

* More structured logging

* More structured logging

* version bump 0.4.2

* unbreak build

* remove extra newline

.cargo/config

@@ -0,0 +1,4 @@
+# See: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/index.html#unstable-features
+
+[build]
+rustflags = ["--cfg", "tracing_unstable"]

dev/controller.sh

@@ -1,3 +1,8 @@
 #!/bin/sh
 
-cargo run -- controller --db postgres://postgres@localhost "$@" --default-cluster localhost:9090
+PLANE_LOG_JSON=true \
+    cargo run -- \
+    controller \
+    --db postgres://postgres@localhost \
+    --default-cluster localhost:9090 \
+    "$@"

dev/drone.sh

@@ -1,3 +1,9 @@
 #!/bin/sh
 
-cargo run -- drone --controller-url ws://localhost:8080/ --cluster "localhost:9090" --db "drone.sqlite" "$@"
+PLANE_LOG_JSON=true \
+    cargo run -- \
+    drone \
+    --controller-url ws://localhost:8080/ \
+    --cluster "localhost:9090" \
+    --db "drone.sqlite" \
+    "$@"

dev/proxy.sh

@@ -1,3 +1,8 @@
 #!/bin/sh
 
-cargo run -- proxy --controller-url ws://localhost:8080/ --cluster "localhost:9090" "$@"
+PLANE_LOG_JSON=true \
+    cargo run -- \
+    proxy \
+    --controller-url ws://localhost:8080/ \
+    --cluster "localhost:9090" \
+    "$@"

plane/Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "plane"
-version = "0.4.1"
+version = "0.4.2"
 edition = "2021"
 default-run = "plane"
 description = "Session backend orchestrator for ambitious browser-based apps."
@@ -44,8 +44,9 @@ tokio-stream = "0.1.14"
 tokio-tungstenite = { version = "0.20.1", features = ["rustls-tls-webpki-roots"] }
 tower-http = { version = "0.4.4", features = ["trace", "cors"] }
 tracing = "0.1.40"
-tracing-subscriber = { version = "0.3.17", features = ["env-filter"] }
+tracing-subscriber = { version = "0.3.18", features = ["env-filter", "json", "valuable"] }
 trust-dns-server = "0.23.2"
 tungstenite = "0.20.1"
 url = "2.4.1"
 x509-parser = "0.15.1"
+valuable = { version = "0.1.0", features = ["derive"] }

plane/plane-tests/tests/backend_actions.rs

@@ -4,6 +4,7 @@ use hyper::StatusCode;
 use plane::{
     client::PlaneClientError,
     database::backend::BackendActionMessage,
+    log_types::LoggableTime,
     names::{DroneName, Name},
     protocol::{BackendAction, Heartbeat, MessageFromDrone, MessageToDrone},
     types::{ClusterName, ConnectRequest, ConnectResponse, ExecutorConfig, SpawnConfig},
@@ -59,7 +60,7 @@ async fn backend_action_resent_if_not_acked(env: TestEnvironment) {
         tracing::info!("Sending initial heartbeat message (mocking the drone).");
         drone_connection
             .send(MessageFromDrone::Heartbeat(Heartbeat {
-                local_time: Utc::now(),
+                local_time: LoggableTime(Utc::now()),
             }))
             .await
             .unwrap();

plane/src/admin.rs

@@ -174,7 +174,7 @@ pub async fn run_admin_command_inner(opts: AdminOpts) -> Result<(), PlaneClientE
                     println!(
                         "Status: {} at {}",
                         status.status.to_string().magenta(),
-                        status.time.to_string().bright_cyan()
+                        status.time.0.to_string().bright_cyan()
                     );
 
                     if status.status >= BackendStatus::Ready {
@@ -206,7 +206,7 @@ pub async fn run_admin_command_inner(opts: AdminOpts) -> Result<(), PlaneClientE
                     println!(
                         "Status: {} at {}",
                         status.status.to_string().magenta(),
-                        status.time.to_string().bright_cyan()
+                        status.time.0.to_string().bright_cyan()
                     );
 
                     if status.status >= BackendStatus::Terminated {

plane/src/controller/backend_status.rs

@@ -1,5 +1,6 @@
 use super::{core::Controller, error::IntoApiError};
 use crate::{
+    log_types::LoggableTime,
     names::BackendName,
     types::{BackendStatus, TimestampedBackendStatus},
 };
@@ -29,7 +30,7 @@ async fn backend_status(
 
     let result = TimestampedBackendStatus {
         status: backend.last_status,
-        time: backend.last_status_time,
+        time: LoggableTime(backend.last_status_time),
     };
 
     Ok(result)

plane/src/controller/dns.rs

@@ -8,6 +8,7 @@ use axum::{
     response::IntoResponse,
 };
 use std::net::{IpAddr, SocketAddr};
+use valuable::Valuable;
 
 pub async fn dns_socket_inner(
     ws: WebSocket,
@@ -21,7 +22,10 @@ pub async fn dns_socket_inner(
 
     loop {
         let message_from_dns_result = socket.recv().await;
-        tracing::info!(?message_from_dns_result, "Handling message from DNS...");
+        tracing::info!(
+            v = message_from_dns_result.as_value(),
+            "Handling message from DNS..."
+        );
         match message_from_dns_result {
             Some(MessageFromDns::TxtRecordRequest { cluster }) => {
                 let txt_value = match controller.db.acme().txt_record_for_cluster(&cluster).await {

plane/src/controller/drone.rs

@@ -9,6 +9,7 @@ use crate::{
         subscribe::Subscription,
         PlaneDatabase,
     },
+    log_types::LoggableTime,
     protocol::{
         BackendAction, Heartbeat, KeyDeadlines, MessageFromDrone, MessageToDrone, RenewKeyResponse,
     },
@@ -21,6 +22,7 @@ use axum::{
     response::{IntoResponse, Response},
 };
 use std::net::{IpAddr, SocketAddr};
+use valuable::Valuable;
 
 pub async fn handle_message_from_drone(
     msg: MessageFromDrone,
@@ -36,14 +38,11 @@ pub async fn handle_message_from_drone(
             controller
                 .db
                 .drone()
-                .heartbeat(drone_id, local_time)
+                .heartbeat(drone_id, local_time.0)
                 .await?;
         }
         MessageFromDrone::BackendEvent(backend_event) => {
-            tracing::info!(
-                event = ?backend_event,
-                "Received backend event"
-            );
+            tracing::info!(event = backend_event.as_value(), "Received backend event");
 
             controller
                 .db
@@ -77,9 +76,13 @@ pub async fn handle_message_from_drone(
                 .await?;
 
             let deadlines = KeyDeadlines {
-                renew_at: renew_key_request.local_time + KEY_LEASE_RENEW_AFTER,
-                soft_terminate_at: renew_key_request.local_time + KEY_LEASE_SOFT_TERMINATE_AFTER,
-                hard_terminate_at: renew_key_request.local_time + KEY_LEASE_HARD_TERMINATE_AFTER,
+                renew_at: LoggableTime(renew_key_request.local_time.0 + KEY_LEASE_RENEW_AFTER),
+                soft_terminate_at: LoggableTime(
+                    renew_key_request.local_time.0 + KEY_LEASE_SOFT_TERMINATE_AFTER,
+                ),
+                hard_terminate_at: LoggableTime(
+                    renew_key_request.local_time.0 + KEY_LEASE_HARD_TERMINATE_AFTER,
+                ),
             };
 
             let renew_key_response = RenewKeyResponse {

plane/src/controller/proxy.rs

@@ -14,6 +14,7 @@ use axum::{
     response::{IntoResponse, Response},
 };
 use std::net::{IpAddr, SocketAddr};
+use valuable::Valuable;
 
 pub async fn proxy_socket_inner(
     cluster: ClusterName,
@@ -97,7 +98,10 @@ pub async fn proxy_socket_inner(
                     }
                 };
 
-                tracing::info!(?response, "Sending cert manager response");
+                tracing::info!(
+                    response = response.as_value(),
+                    "Sending cert manager response"
+                );
 
                 if let Err(err) = socket
                     .send(MessageToProxy::CertManagerResponse(response))

plane/src/database/backend.rs

@@ -1,5 +1,6 @@
 use super::{subscribe::emit_with_key, util::MapSqlxError, PlaneDatabase};
 use crate::{
+    log_types::{BackendAddr, LoggableTime},
     names::{BackendActionName, BackendName},
     protocol::{BackendAction, RouteInfo},
     types::{BackendStatus, BearerToken, NodeId, SecretToken, TimestampedBackendStatus},
@@ -68,7 +69,7 @@ impl<'a> BackendDatabase<'a> {
                 match status {
                     Ok(status) => {
                         yield TimestampedBackendStatus {
-                            time: row.created_at,
+                            time: LoggableTime(row.created_at),
                             status,
                         };
                         last_status = Some(status);
@@ -95,7 +96,7 @@ impl<'a> BackendDatabase<'a> {
 
                 let item = TimestampedBackendStatus {
                     status,
-                    time,
+                    time: LoggableTime(time),
                 };
 
                 yield item;
@@ -148,7 +149,7 @@ impl<'a> BackendDatabase<'a> {
         &self,
         backend: &BackendName,
         status: BackendStatus,
-        address: Option<SocketAddr>,
+        address: Option<BackendAddr>,
         exit_code: Option<i32>,
     ) -> sqlx::Result<()> {
         let mut txn = self.db.pool.begin().await?;
@@ -167,7 +168,7 @@ impl<'a> BackendDatabase<'a> {
             "#,
             backend.to_string(),
             status.to_string(),
-            address.map(|a| a.to_string()),
+            address.map(|a| a.0.to_string()),
             exit_code,
         )
         .execute(&mut *txn)
@@ -281,7 +282,7 @@ impl<'a> BackendDatabase<'a> {
         Ok(Some(RouteInfo {
             backend_id: BackendName::try_from(result.backend_id)
                 .map_err(|_| sqlx::Error::Decode("Failed to decode backend name.".into()))?,
-            address,
+            address: BackendAddr(address),
             secret_token: SecretToken::from(result.secret_token),
             user: result.username,
             user_data: Some(result.auth),
@@ -351,7 +352,7 @@ impl<'a> BackendDatabase<'a> {
     }
 }
 
-#[derive(Debug, Clone, Serialize, Deserialize)]
+#[derive(Debug, Clone)]
 pub struct TerminationCandidate {
     pub backend_id: BackendName,
     pub expiration_time: Option<DateTime<Utc>>,

plane/src/database/connect.rs

@@ -9,6 +9,7 @@ use crate::{
         backend_key::{KeysDatabase, KEY_LEASE_EXPIRATION},
         drone::DroneDatabase,
     },
+    log_types::LoggableTime,
     names::{BackendName, Name},
     protocol::{AcquiredKey, BackendAction, KeyDeadlines},
     types::{
@@ -129,9 +130,13 @@ async fn create_backend_with_key(
     let acquired_key = AcquiredKey {
         key: key.clone(),
         deadlines: KeyDeadlines {
-            renew_at: drone_for_spawn.last_local_time + KEY_LEASE_RENEW_AFTER,
-            soft_terminate_at: drone_for_spawn.last_local_time + KEY_LEASE_SOFT_TERMINATE_AFTER,
-            hard_terminate_at: drone_for_spawn.last_local_time + KEY_LEASE_SOFT_TERMINATE_AFTER,
+            renew_at: LoggableTime(drone_for_spawn.last_local_time + KEY_LEASE_RENEW_AFTER),
+            soft_terminate_at: LoggableTime(
+                drone_for_spawn.last_local_time + KEY_LEASE_SOFT_TERMINATE_AFTER,
+            ),
+            hard_terminate_at: LoggableTime(
+                drone_for_spawn.last_local_time + KEY_LEASE_SOFT_TERMINATE_AFTER,
+            ),
         },
         token: result.fencing_token,
     };

plane/src/database/drone.rs

@@ -4,7 +4,7 @@ use crate::{
 };
 use chrono::{DateTime, Utc};
 use sqlx::{postgres::types::PgInterval, query, query_as, PgPool};
-use std::time::{Duration, SystemTime};
+use std::time::Duration;
 
 pub struct DroneDatabase<'a> {
     pool: &'a PgPool,
@@ -114,5 +114,5 @@ impl<'a> DroneDatabase<'a> {
 
 pub struct DroneForSpawn {
     pub id: NodeId,
-    pub last_local_time: SystemTime,
+    pub last_local_time: DateTime<Utc>,
 }

plane/src/database/subscribe.rs

@@ -269,7 +269,7 @@ impl EventSubscriptionManager {
 
         let mut listeners = self.listeners.write().expect("Listener map is poisoned.");
         let key = (kind.clone(), key.map(|s| s.to_string()));
-        tracing::info!(?key, "Subscribing to event");
+        tracing::info!(kind = key.0, key = key.1, "Subscribing to event");
 
         match listeners.entry(key.clone()) {
             std::collections::hash_map::Entry::Occupied(entry) => {