change log level to INFO in order to simplify debugging (DEBUG logs in the db are pretty spammy)

This commit is contained in:
Nikita Sivukhin
2025-08-14 12:37:49 +04:00
parent 887b25dd00
commit f603a0dfc8
2 changed files with 23 additions and 24 deletions

View File

@@ -45,7 +45,7 @@ async fn update_meta<IO: ProtocolIO>(
) -> Result<()> {
let mut meta = orig.as_ref().unwrap().clone();
update(&mut meta);
tracing::debug!("update_meta: {meta:?}");
tracing::info!("update_meta: {meta:?}");
let completion = io.full_write(meta_path, meta.dump()?)?;
// todo: what happen if we will actually update the metadata on disk but fail and so in memory state will not be updated
wait_full_body(coro, &completion).await?;
@@ -60,7 +60,7 @@ async fn set_meta<IO: ProtocolIO>(
orig: &mut Option<DatabaseMetadata>,
meta: DatabaseMetadata,
) -> Result<()> {
tracing::debug!("set_meta: {meta:?}");
tracing::info!("set_meta: {meta:?}");
let completion = io.full_write(meta_path, meta.dump()?)?;
// todo: what happen if we will actually update the metadata on disk but fail and so in memory state will not be updated
wait_full_body(coro, &completion).await?;
@@ -103,7 +103,7 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
/// This method will **not** send local changed to the remote
/// This method will block writes for the period of pull
pub async fn pull(&mut self, coro: &Coro) -> Result<()> {
tracing::debug!(
tracing::info!(
"pull: draft={}, synced={}",
self.draft_path,
self.synced_path
@@ -120,7 +120,6 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
// we will "replay" Synced WAL to the Draft WAL later without pushing it to the remote
// so, we pass 'capture: true' as we need to preserve all changes for future push of WAL
let synced = self.io.open_tape(&self.synced_path, true)?;
tracing::info!("opened synced");
// we will start wal write session for Draft DB in order to hold write lock during transfer of changes
let mut draft_session = WalSession::new(connect(coro, &self.draft_tape).await?);
@@ -168,7 +167,7 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
let WalPullResult::NeedCheckpoint = pull_result else {
break;
};
tracing::debug!(
tracing::info!(
"ready to checkpoint synced db file at {:?}, generation={}",
self.synced_path,
self.meta().synced_generation
@@ -198,7 +197,7 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
/// This method will **not** pull remote changes to the local DB
/// This method will **not** block writes for the period of sync
pub async fn push(&mut self, coro: &Coro) -> Result<()> {
tracing::debug!(
tracing::info!(
"push: draft={}, synced={}",
self.draft_path,
self.synced_path
@@ -237,7 +236,7 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
}
async fn init(&mut self, coro: &Coro) -> Result<()> {
tracing::debug!(
tracing::info!(
"initialize sync engine: draft={}, synced={}, opts={:?}",
self.draft_path,
self.synced_path,
@@ -258,7 +257,7 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
}
None => {
let meta = self.bootstrap_db_files(coro).await?;
tracing::debug!("write meta after successful bootstrap: meta={meta:?}");
tracing::info!("write meta after successful bootstrap: meta={meta:?}");
set_meta(
coro,
self.protocol.as_ref(),
@@ -285,7 +284,7 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
}
async fn pull_synced_from_remote(&mut self, coro: &Coro) -> Result<WalPullResult> {
tracing::debug!(
tracing::info!(
"pull_synced_from_remote: draft={:?}, synced={:?}",
self.draft_path,
self.synced_path,
@@ -330,7 +329,7 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
}
async fn push_synced_to_remote(&mut self, coro: &Coro) -> Result<()> {
tracing::debug!(
tracing::info!(
"push_synced_to_remote: draft={}, synced={}, id={}",
self.draft_path,
self.synced_path,
@@ -381,7 +380,7 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
self.meta.is_none(),
"bootstrap_db_files must be called only when meta is not set"
);
tracing::debug!(
tracing::info!(
"bootstrap_db_files: draft={}, synced={}",
self.draft_path,
self.synced_path,
@@ -410,7 +409,7 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
let db_info = db_bootstrap(coro, self.protocol.as_ref(), files).await?;
let elapsed = std::time::Instant::now().duration_since(start_time);
tracing::debug!(
tracing::info!(
"bootstrap_db_files: finished draft={:?}, synced={:?}: elapsed={:?}",
self.draft_path,
self.synced_path,
@@ -428,7 +427,7 @@ impl<C: ProtocolIO> DatabaseSyncEngine<C> {
/// Reset WAL of Synced database which potentially can have some local changes
async fn reset_synced_if_dirty(&mut self, coro: &Coro) -> Result<()> {
tracing::debug!(
tracing::info!(
"reset_synced: synced_path={:?}, synced_is_dirty={}",
self.synced_path,
self.synced_is_dirty

View File

@@ -122,7 +122,7 @@ pub async fn wal_pull<'a, C: ProtocolIO, U: AsyncFnMut(&'a Coro, u64) -> Result<
end_frame: u64,
mut update: U,
) -> Result<WalPullResult> {
tracing::debug!(
tracing::info!(
"wal_pull: generation={}, start_frame={}, end_frame={}",
generation,
start_frame,
@@ -209,7 +209,7 @@ pub async fn wal_push<C: ProtocolIO>(
end_frame: u64,
) -> Result<WalPushResult> {
assert!(wal_session.in_txn());
tracing::debug!("wal_push: baton={baton:?}, generation={generation}, start_frame={start_frame}, end_frame={end_frame}");
tracing::info!("wal_push: baton={baton:?}, generation={generation}, start_frame={start_frame}, end_frame={end_frame}");
if start_frame == end_frame {
return Ok(WalPushResult::Ok { baton: None });
@@ -272,7 +272,7 @@ pub async fn transfer_logical_changes(
client_id: &str,
bump_pull_gen: bool,
) -> Result<()> {
tracing::debug!("transfer_logical_changes: client_id={client_id}");
tracing::info!("transfer_logical_changes: client_id={client_id}");
let source_conn = connect_untracked(source)?;
let target_conn = connect_untracked(target)?;
@@ -293,12 +293,12 @@ pub async fn transfer_logical_changes(
Error::DatabaseSyncEngineError("unexpected source pull_gen type".to_string())
})?,
None => {
tracing::debug!("transfer_logical_changes: client_id={client_id}, turso_sync_last_change_id table is not found");
tracing::info!("transfer_logical_changes: client_id={client_id}, turso_sync_last_change_id table is not found");
0
}
}
};
tracing::debug!(
tracing::info!(
"transfer_logical_changes: client_id={client_id}, source_pull_gen={source_pull_gen}"
);
@@ -383,7 +383,7 @@ pub async fn transfer_logical_changes(
}
DatabaseTapeOperation::Commit => {
if rows_changed > 0 || (bump_pull_gen && last_change_id.unwrap_or(0) > 0) {
tracing::debug!("prepare update stmt for turso_sync_last_change_id table with client_id={} and last_change_id={:?}", client_id, last_change_id);
tracing::info!("prepare update stmt for turso_sync_last_change_id table with client_id={} and last_change_id={:?}", client_id, last_change_id);
// update turso_sync_last_change_id table with new value before commit
let mut set_last_change_id_stmt =
session.conn().prepare(TURSO_SYNC_UPDATE_LAST_CHANGE_ID)?;
@@ -392,7 +392,7 @@ pub async fn transfer_logical_changes(
} else {
(source_pull_gen, last_change_id.unwrap_or(0))
};
tracing::debug!("transfer_logical_changes: client_id={client_id}, set pull_gen={next_pull_gen}, change_id={next_change_id}, rows_changed={rows_changed}");
tracing::info!("transfer_logical_changes: client_id={client_id}, set pull_gen={next_pull_gen}, change_id={next_change_id}, rows_changed={rows_changed}");
set_last_change_id_stmt
.bind_at(1.try_into().unwrap(), Value::Integer(next_pull_gen));
set_last_change_id_stmt
@@ -414,7 +414,7 @@ pub async fn transfer_logical_changes(
session.replay(coro, operation).await?;
}
tracing::debug!("transfer_logical_changes: rows_changed={:?}", rows_changed);
tracing::info!("transfer_logical_changes: rows_changed={:?}", rows_changed);
Ok(())
}
@@ -428,7 +428,7 @@ pub async fn transfer_physical_changes(
source_sync_watermark: u64,
target_wal_match_watermark: u64,
) -> Result<u64> {
tracing::debug!("transfer_physical_changes: source_wal_match_watermark={source_wal_match_watermark}, source_sync_watermark={source_sync_watermark}, target_wal_match_watermark={target_wal_match_watermark}");
tracing::info!("transfer_physical_changes: source_wal_match_watermark={source_wal_match_watermark}, source_sync_watermark={source_sync_watermark}, target_wal_match_watermark={target_wal_match_watermark}");
let source_conn = connect(coro, source).await?;
let mut source_session = WalSession::new(source_conn.clone());
@@ -454,7 +454,7 @@ pub async fn transfer_physical_changes(
let mut last_frame_info = None;
let mut frame = vec![0u8; WAL_FRAME_SIZE];
let mut target_sync_watermark = target_session.frames_count()?;
tracing::debug!(
tracing::info!(
"transfer_physical_changes: start={}, end={}",
source_wal_match_watermark + 1,
source_frames_count
@@ -465,7 +465,7 @@ pub async fn transfer_physical_changes(
target_session.append_page(frame_info.page_no, &frame[WAL_FRAME_HEADER..])?;
if source_frame_no == source_sync_watermark {
target_sync_watermark = target_session.frames_count()? + 1; // +1 because page will be actually commited on next iteration
tracing::debug!("set target_sync_watermark to {}", target_sync_watermark);
tracing::info!("set target_sync_watermark to {}", target_sync_watermark);
}
last_frame_info = Some(frame_info);
}