From 84f077f36bb6b58e8c1a76df3c17cac899ab415f Mon Sep 17 00:00:00 2001 From: Andras Schmelczer Date: Sat, 29 Nov 2025 14:22:05 +0000 Subject: [PATCH] Improve logging --- sync-server/src/app_state/database.rs | 11 ++++----- .../src/app_state/websocket/broadcasts.rs | 5 ++-- sync-server/src/config.rs | 10 ++++---- sync-server/src/config/logging_config.rs | 2 +- sync-server/src/config/server_config.rs | 4 ++-- sync-server/src/config/user_config.rs | 4 ++-- sync-server/src/server/auth.rs | 4 ++-- sync-server/src/server/create_document.rs | 11 ++++++++- sync-server/src/server/delete_document.rs | 24 ++++++++++++++++--- .../src/server/fetch_document_version.rs | 5 ++++ .../server/fetch_document_version_content.rs | 5 ++++ .../server/fetch_latest_document_version.rs | 3 +++ .../src/server/fetch_latest_documents.rs | 3 +++ sync-server/src/server/ping.rs | 3 +++ sync-server/src/server/update_document.rs | 22 +++++++++++++---- sync-server/src/server/websocket.rs | 8 +++---- 16 files changed, 90 insertions(+), 34 deletions(-) diff --git a/sync-server/src/app_state/database.rs b/sync-server/src/app_state/database.rs index 3ca3cb64..d64bd560 100644 --- a/sync-server/src/app_state/database.rs +++ b/sync-server/src/app_state/database.rs @@ -50,7 +50,7 @@ impl Database { .await .with_context(|| { format!( - "Failed to create databases directory: {}", + "Failed to create databases directory at `{}`", config.databases_directory_path.to_string_lossy() ) })?; @@ -110,7 +110,7 @@ impl Database { .test_before_acquire(true) .connect_with(connection_options) .await - .with_context(|| format!("Cannot open database at {}", file_name.display()))?; + .with_context(|| format!("Cannot open database at `{}`", file_name.display()))?; Self::run_migrations(&pool).await?; @@ -254,7 +254,7 @@ impl Database { .await } .with_context(|| { - format!("Cannot fetch latest documents since vault_update_id {vault_update_id}") + format!("Cannot fetch latest documents since vault_update_id `{vault_update_id}`") }) .map(|rows| { rows.into_iter() @@ -489,10 +489,7 @@ impl Database { // Close and remove idle pools for vault_id in &vaults_to_remove { if let Some(pool_with_timestamp) = pools.remove(vault_id) { - info!( - "Closing idle database connection pool for vault {}", - vault_id - ); + info!("Closing idle database connection pool for vault `{vault_id}`"); pool_with_timestamp.pool.close().await; } } diff --git a/sync-server/src/app_state/websocket/broadcasts.rs b/sync-server/src/app_state/websocket/broadcasts.rs index cef6ee6a..b8200d91 100644 --- a/sync-server/src/app_state/websocket/broadcasts.rs +++ b/sync-server/src/app_state/websocket/broadcasts.rs @@ -1,6 +1,7 @@ use std::{collections::HashMap, sync::Arc}; use anyhow::Context; +use log::warn; use tokio::sync::{Mutex, broadcast}; use super::models::WebSocketServerMessageWithOrigin; @@ -32,7 +33,7 @@ impl Broadcasts { } /// Notify all clients (who are subscribed to the vault) about an update. - /// We only log failures. + /// We only log failures and don't propagate them. pub async fn send_document_update( &self, vault: VaultId, @@ -46,7 +47,7 @@ impl Broadcasts { .map_err(server_error); if result.is_err() { - log::debug!("Failed to send message: {result:?}"); + warn!("Failed to send message: {result:?}"); } } diff --git a/sync-server/src/config.rs b/sync-server/src/config.rs index 2e1a6e39..6a003d2e 100644 --- a/sync-server/src/config.rs +++ b/sync-server/src/config.rs @@ -30,7 +30,7 @@ impl Config { pub async fn read_or_create(path: &Path) -> Result { let config = if path.exists() { info!( - "Loading configuration from '{}'", + "Loading configuration from `{}`", path.canonicalize().unwrap().display() ); Self::load_from_file(path).await? @@ -40,7 +40,7 @@ impl Config { config.write(path).await?; info!( - "Updated configuration at '{}'", + "Updated configuration at `{}`", path.canonicalize().unwrap().display() ); @@ -50,14 +50,12 @@ impl Config { pub async fn load_from_file(path: &Path) -> Result { let contents = fs::read_to_string(path).await.with_context(|| { format!( - "Cannot load configuration from disk from {}", + "Cannot load configuration from disk from `{}`", path.display() ) })?; - let config = serde_yaml::from_str(&contents).context("Failed to parse configuration")?; - - Ok(config) + serde_yaml::from_str(&contents).context("Failed to parse configuration") } pub async fn write(&self, path: &Path) -> Result<()> { diff --git a/sync-server/src/config/logging_config.rs b/sync-server/src/config/logging_config.rs index 95ab9350..79d4fa1e 100644 --- a/sync-server/src/config/logging_config.rs +++ b/sync-server/src/config/logging_config.rs @@ -24,7 +24,7 @@ impl Default for LoggingConfig { } fn default_log_directory() -> String { - debug!("Using default log directory: {DEFAULT_LOG_DIRECTORY}"); + debug!("Using default log directory: `{DEFAULT_LOG_DIRECTORY}`"); DEFAULT_LOG_DIRECTORY.to_owned() } diff --git a/sync-server/src/config/server_config.rs b/sync-server/src/config/server_config.rs index 07dc61b3..fc6034ed 100644 --- a/sync-server/src/config/server_config.rs +++ b/sync-server/src/config/server_config.rs @@ -38,7 +38,7 @@ fn default_port() -> u16 { } fn default_max_body_size_mb() -> usize { - debug!("Using default max body size (MB): {DEFAULT_MAX_BODY_SIZE_MB}"); + debug!("Using default max body size {DEFAULT_MAX_BODY_SIZE_MB} MB"); DEFAULT_MAX_BODY_SIZE_MB } @@ -48,7 +48,7 @@ fn default_max_clients_per_vault() -> usize { } fn default_response_timeout_seconds() -> u64 { - debug!("Using default response timeout (seconds): {DEFAULT_RESPONSE_TIMEOUT_SECONDS}"); + debug!("Using default response timeout: {DEFAULT_RESPONSE_TIMEOUT_SECONDS} seconds"); DEFAULT_RESPONSE_TIMEOUT_SECONDS } diff --git a/sync-server/src/config/user_config.rs b/sync-server/src/config/user_config.rs index ed7ecc23..cdfed838 100644 --- a/sync-server/src/config/user_config.rs +++ b/sync-server/src/config/user_config.rs @@ -20,7 +20,7 @@ where for user in &users { if let Some(existing_name) = user_token_map.get_by_right(&user.token) { return Err(D::Error::custom(format!( - "Duplicate user token found: '{}' for users '{}' and '{}'. User tokens must be \ + "Duplicate user token found: `{}` for users `{}` and `{}`. User tokens must be \ unique.", user.token, existing_name, user.name ))); @@ -28,7 +28,7 @@ where if user_token_map.contains_left(&user.name) { return Err(D::Error::custom(format!( - "Duplicate user name found: '{}'. User names must be unique.", + "Duplicate user name found: `{}`. User names must be unique.", user.name ))); } diff --git a/sync-server/src/server/auth.rs b/sync-server/src/server/auth.rs index d27c16e3..e56f4acc 100644 --- a/sync-server/src/server/auth.rs +++ b/sync-server/src/server/auth.rs @@ -52,14 +52,14 @@ pub fn auth(state: &AppState, token: &str, vault_id: &VaultId) -> Result allowed.contains(vault_id), } { info!( - "User '{}' is authenticated and is authorised to access to vault '{vault_id}'", + "User `{}` is authenticated and is authorised to access to vault `{vault_id}`", user.name ); Ok(user) } else { info!( - "User '{}' is authenticated but is not authorised to access vault '{vault_id}'", + "User `{}` is authenticated but is not authorised to access vault `{vault_id}`", user.name ); diff --git a/sync-server/src/server/create_document.rs b/sync-server/src/server/create_document.rs index a8d80f39..859c0db4 100644 --- a/sync-server/src/server/create_document.rs +++ b/sync-server/src/server/create_document.rs @@ -4,6 +4,7 @@ use axum::{ }; use axum_extra::TypedHeader; use axum_typed_multipart::TypedMultipart; +use log::{debug, info}; use serde::Deserialize; use super::{device_id_header::DeviceIdHeader, requests::CreateDocumentVersion}; @@ -37,6 +38,8 @@ pub async fn create_document( State(state): State, TypedMultipart(request): TypedMultipart, ) -> Result, SyncServerError> { + debug!("Creating document in vault `{vault_id}`"); + let mut transaction = state .database .create_write_transaction(&vault_id) @@ -53,7 +56,7 @@ pub async fn create_document( if existing_version.is_some() { return Err(client_error(anyhow::anyhow!( - "Document with the same ID already exists" + "Document with the same ID `{document_id}` already exists" ))); } @@ -78,6 +81,12 @@ pub async fn create_document( .await .map_err(server_error)?; + if deduped_path != sanitized_relative_path { + info!( + "Document already exists at new location: `{sanitized_relative_path}` when trying to create it in vault `{vault_id}`, deconflicting by creating at `{deduped_path}`" + ); + } + let new_version = StoredDocumentVersion { vault_update_id: last_update_id + 1, document_id, diff --git a/sync-server/src/server/delete_document.rs b/sync-server/src/server/delete_document.rs index f7080417..e126d6b5 100644 --- a/sync-server/src/server/delete_document.rs +++ b/sync-server/src/server/delete_document.rs @@ -1,8 +1,10 @@ +use anyhow::Context; use axum::{ Extension, Json, extract::{Path, State}, }; use axum_extra::TypedHeader; +use log::{debug, info}; use serde::Deserialize; use super::{device_id_header::DeviceIdHeader, requests::DeleteDocumentVersion}; @@ -37,6 +39,8 @@ pub async fn delete_document( State(state): State, Json(request): Json, ) -> Result, SyncServerError> { + debug!("Deleting document `{document_id}` in vault `{vault_id}`"); + let mut transaction = state .database .create_write_transaction(&vault_id) @@ -49,12 +53,26 @@ pub async fn delete_document( .await .map_err(server_error)?; - let latest_content = state + let latest_version = state .database .get_latest_document(&vault_id, &document_id, Some(&mut transaction)) .await - .map_err(server_error)? - .map_or_else(Vec::new, |version| version.content); // in case the document has never existed before deleting it + .map_err(server_error)?; + + if let Some(latest_version) = &latest_version + && latest_version.is_deleted + { + transaction + .rollback() + .await + .context("Failed to roll back transaction") + .map_err(server_error)?; + + info!("Document `{document_id}` has already been deleted",); + return Ok(Json(latest_version.clone().into())); + } + + let latest_content = latest_version.map_or_else(Vec::new, |version| version.content); // in case the document has never existed before deleting it let new_version = StoredDocumentVersion { vault_update_id: last_update_id + 1, diff --git a/sync-server/src/server/fetch_document_version.rs b/sync-server/src/server/fetch_document_version.rs index 5b571a7b..67e72ca4 100644 --- a/sync-server/src/server/fetch_document_version.rs +++ b/sync-server/src/server/fetch_document_version.rs @@ -3,6 +3,7 @@ use axum::{ Json, extract::{Path, State}, }; +use log::debug; use serde::Deserialize; use crate::{ @@ -32,6 +33,10 @@ pub async fn fetch_document_version( }): Path, State(state): State, ) -> Result, SyncServerError> { + debug!( + "Fetching document version `{vault_update_id}` for document `{document_id}` in vault `{vault_id}`" + ); + let result = state .database .get_document_version(&vault_id, vault_update_id, None) diff --git a/sync-server/src/server/fetch_document_version_content.rs b/sync-server/src/server/fetch_document_version_content.rs index a419b7bf..a74e88ec 100644 --- a/sync-server/src/server/fetch_document_version_content.rs +++ b/sync-server/src/server/fetch_document_version_content.rs @@ -3,6 +3,7 @@ use axum::{ body::Bytes, extract::{Path, State}, }; +use log::debug; use serde::Deserialize; use crate::{ @@ -32,6 +33,10 @@ pub async fn fetch_document_version_content( }): Path, State(state): State, ) -> Result { + debug!( + "Fetching document version `{vault_update_id}` for document `{document_id}` in vault `{vault_id}`" + ); + let result = state .database .get_document_version(&vault_id, vault_update_id, None) diff --git a/sync-server/src/server/fetch_latest_document_version.rs b/sync-server/src/server/fetch_latest_document_version.rs index 07f07860..a9973606 100644 --- a/sync-server/src/server/fetch_latest_document_version.rs +++ b/sync-server/src/server/fetch_latest_document_version.rs @@ -3,6 +3,7 @@ use axum::{ Json, extract::{Path, State}, }; +use log::debug; use serde::Deserialize; use crate::{ @@ -30,6 +31,8 @@ pub async fn fetch_latest_document_version( }): Path, State(state): State, ) -> Result, SyncServerError> { + debug!("Fetching latest document version for document `{document_id}` in vault `{vault_id}`"); + let latest_version = state .database .get_latest_document(&vault_id, &document_id, None) diff --git a/sync-server/src/server/fetch_latest_documents.rs b/sync-server/src/server/fetch_latest_documents.rs index 6101f55c..209374ce 100644 --- a/sync-server/src/server/fetch_latest_documents.rs +++ b/sync-server/src/server/fetch_latest_documents.rs @@ -2,6 +2,7 @@ use axum::{ Json, extract::{Path, Query, State}, }; +use log::debug; use serde::Deserialize; use super::responses::FetchLatestDocumentsResponse; @@ -31,6 +32,8 @@ pub async fn fetch_latest_documents( Query(QueryParams { since_update_id }): Query, State(state): State, ) -> Result, SyncServerError> { + debug!("Fetching latest documents in vault `{vault_id}` since update ID `{since_update_id:?}`"); + let documents = if let Some(since_update_id) = since_update_id { state .database diff --git a/sync-server/src/server/ping.rs b/sync-server/src/server/ping.rs index 82eefff7..31aa8acd 100644 --- a/sync-server/src/server/ping.rs +++ b/sync-server/src/server/ping.rs @@ -6,6 +6,7 @@ use axum_extra::{ TypedHeader, headers::{Authorization, authorization::Bearer}, }; +use log::debug; use serde::Deserialize; use super::{auth::auth, responses::PingResponse}; @@ -28,6 +29,8 @@ pub async fn ping( Path(PingPathParams { vault_id }): Path, State(state): State, ) -> Result, SyncServerError> { + debug!("Pinging vault `{vault_id}`"); + let is_authenticated = maybe_auth_header .is_some_and(|auth_header| auth(&state, auth_header.token(), &vault_id).is_ok()); diff --git a/sync-server/src/server/update_document.rs b/sync-server/src/server/update_document.rs index b8a17c11..9da37832 100644 --- a/sync-server/src/server/update_document.rs +++ b/sync-server/src/server/update_document.rs @@ -5,7 +5,7 @@ use axum::{ }; use axum_extra::TypedHeader; use axum_typed_multipart::TypedMultipart; -use log::info; +use log::{debug, info}; use reconcile_text::{BuiltinTokenizer, EditedText, reconcile}; use serde::Deserialize; @@ -129,6 +129,8 @@ async fn update_document( relative_path: &str, content: Vec, ) -> Result, SyncServerError> { + debug!("Updating document `{document_id}` in vault `{vault_id}`"); + let sanitized_relative_path = sanitize_path(relative_path); let mut transaction = state @@ -164,6 +166,7 @@ async fn update_document( .context("Failed to roll back transaction") .map_err(server_error)?; + info!("Document `{document_id}` has been deleted, ignoring update to it",); return Ok(Json(DocumentUpdateResponse::FastForwardUpdate( latest_version.into(), ))); @@ -173,7 +176,9 @@ async fn update_document( // version if content == latest_version.content && sanitized_relative_path == latest_version.relative_path { - info!("Document content is the same as the latest version, skipping update"); + info!( + "Document content is the same as the latest version for `{document_id}`, skipping update" + ); transaction .rollback() .await @@ -193,6 +198,7 @@ async fn update_document( && !is_binary(&content); let merged_content = if are_all_participants_mergable { + info!("Merging changes for document `{document_id}` in vault `{vault_id}`"); reconcile( str::from_utf8(&parent_document.content) .expect("parent must be valid UTF-8 because it's not binary"), @@ -217,14 +223,22 @@ async fn update_document( let new_relative_path = if parent_document.relative_path == latest_version.relative_path && latest_version.relative_path != sanitized_relative_path { - find_first_available_path( + let new_path = find_first_available_path( &vault_id, &sanitized_relative_path, &state.database, &mut transaction, ) .await - .map_err(server_error)? + .map_err(server_error)?; + + if new_path != sanitized_relative_path { + info!( + "Document already exists at new location: `{sanitized_relative_path}` when trying to update it in vault `{vault_id}`, deconflicting by creating at `{new_path}`" + ); + } + + new_path } else { latest_version.relative_path.clone() }; diff --git a/sync-server/src/server/websocket.rs b/sync-server/src/server/websocket.rs index 5e94b277..bb10b49f 100644 --- a/sync-server/src/server/websocket.rs +++ b/sync-server/src/server/websocket.rs @@ -43,12 +43,12 @@ pub async fn websocket_handler( } async fn websocket_wrapped(state: AppState, stream: WebSocket, vault_id: VaultId) { - info!("WebSocket connection opened on vault '{vault_id}'"); + info!("WebSocket connection opened on vault `{vault_id}`"); let result = websocket(state, stream, vault_id.clone()).await; if let Err(err) = result { - debug!("WebSocket connection error on vault '{vault_id}': {err}"); + debug!("WebSocket connection error on vault `{vault_id}`: {err}"); } } @@ -71,7 +71,7 @@ async fn websocket( )?; info!( - "WebSocket handshake successful for vault '{vault_id}' for '{}'", + "WebSocket handshake successful for vault `{vault_id}` for `{}`", authed_handshake.handshake.device_id ); @@ -184,7 +184,7 @@ async fn websocket( if result.is_err() { info!( - "WebSocket disconnected on vault '{vault_id}' for '{}'", + "WebSocket disconnected on vault `{vault_id}` for `{}`", authed_handshake.handshake.device_id ); }