* [pbs-devel] [RFC proxmox-backup 1/2] log: removed task_log! macro and moved to tracing
2023-10-11 14:01 [pbs-devel] [RFC proxmox-backup 0/2] Tasklog rewrite with tracing Gabriel Goller
@ 2023-10-11 14:01 ` Gabriel Goller
2023-10-11 14:01 ` [pbs-devel] [RFC proxmox 2/2] proxmox-log: added tracing infra Gabriel Goller
2023-10-18 13:12 ` [pbs-devel] [RFC proxmox-backup 0/2] Tasklog rewrite with tracing Dominik Csapak
2 siblings, 0 replies; 14+ messages in thread
From: Gabriel Goller @ 2023-10-11 14:01 UTC (permalink / raw)
To: pbs-devel
Imported `proxmox-log` and substituted all `task_log!`
(and task_warn) invocations with tracing calls (info!,
warn!, etc..). Removed worker where it isn't necessary
anymore.
Signed-off-by: Gabriel Goller <g.goller@proxmox.com>
---
Cargo.toml | 61 ++++---
pbs-api-types/src/metrics.rs | 1 -
pbs-api-types/src/node.rs | 3 +-
pbs-datastore/Cargo.toml | 1 +
pbs-datastore/src/chunk_store.rs | 33 ++--
pbs-datastore/src/datastore.rs | 101 ++++++-----
src/api2/admin/datastore.rs | 29 +--
src/api2/admin/metrics.rs | 2 +-
src/api2/config/acme.rs | 23 ++-
src/api2/config/datastore.rs | 15 +-
src/api2/node/apt.rs | 13 +-
src/api2/node/certificates.rs | 69 +++----
src/api2/node/disks/directory.rs | 16 +-
src/api2/node/disks/mod.rs | 6 +-
src/api2/node/disks/zfs.rs | 32 ++--
src/api2/node/mod.rs | 11 +-
src/api2/pull.rs | 27 ++-
src/api2/tape/backup.rs | 82 ++++-----
src/api2/tape/drive.rs | 158 +++++++++--------
src/api2/tape/restore.rs | 296 ++++++++++++++++---------------
src/backup/verify.rs | 108 +++++------
src/bin/proxmox-backup-api.rs | 10 +-
src/bin/proxmox-backup-proxy.rs | 45 ++---
src/server/gc_job.rs | 9 +-
src/server/prune_job.rs | 31 ++--
src/server/pull.rs | 192 +++++++++-----------
src/server/realm_sync_job.rs | 37 ++--
src/server/verify_job.rs | 13 +-
src/tape/drive/mod.rs | 37 ++--
src/tape/pool_writer/mod.rs | 90 +++++-----
tests/worker-task-abort.rs | 9 +-
31 files changed, 764 insertions(+), 796 deletions(-)
diff --git a/Cargo.toml b/Cargo.toml
index cfbf2ba1..fea99f01 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -64,6 +64,7 @@ proxmox-http = { version = "0.9.0", features = [ "client", "http-helpers", "webs
proxmox-human-byte = "0.1"
proxmox-io = "1.0.1" # tools and client use "tokio" feature
proxmox-lang = "1.1"
+proxmox-log = "0.1"
proxmox-ldap = "0.2.1"
proxmox-metrics = "0.3"
proxmox-openid = "0.10.0"
@@ -144,6 +145,8 @@ tokio = "1.6"
tokio-openssl = "0.6.1"
tokio-stream = "0.1.0"
tokio-util = { version = "0.7", features = [ "io" ] }
+tracing = "0.1"
+tracing-subscriber = "0.3.16"
tower-service = "0.3.0"
udev = "0.4"
url = "2.1"
@@ -189,6 +192,8 @@ tokio = { workspace = true, features = [ "fs", "io-util", "io-std", "macros", "n
tokio-openssl.workspace = true
tokio-stream.workspace = true
tokio-util = { workspace = true, features = [ "codec" ] }
+tracing.workspace = true
+tracing-subscriber.workspace = true
tower-service.workspace = true
udev.workspace = true
url.workspace = true
@@ -207,6 +212,7 @@ proxmox-http = { workspace = true, features = [ "client-trait", "proxmox-async",
proxmox-human-byte.workspace = true
proxmox-io.workspace = true
proxmox-lang.workspace = true
+proxmox-log.workspace = true
proxmox-ldap.workspace = true
proxmox-metrics.workspace = true
proxmox-openid.workspace = true
@@ -243,35 +249,36 @@ proxmox-rrd.workspace = true
# NOTE: You must run `cargo update` after changing this for it to take effect!
[patch.crates-io]
-#proxmox-apt = { path = "../proxmox/proxmox-apt" }
-#proxmox-async = { path = "../proxmox/proxmox-async" }
-#proxmox-auth-api = { path = "../proxmox/proxmox-auth-api" }
-#proxmox-borrow = { path = "../proxmox/proxmox-borrow" }
-#proxmox-compression = { path = "../proxmox/proxmox-compression" }
-#proxmox-fuse = { path = "../proxmox-fuse" }
-#proxmox-http = { path = "../proxmox/proxmox-http" }
-#proxmox-human-byte = { path = "../proxmox/proxmox-human-byte" }
-#proxmox-io = { path = "../proxmox/proxmox-io" }
-#proxmox-lang = { path = "../proxmox/proxmox-lang" }
-#proxmox-ldap = { path = "../proxmox/proxmox-ldap" }
-#proxmox-metrics = { path = "../proxmox/proxmox-metrics" }
-#proxmox-openid = { path = "../proxmox/proxmox-openid" }
-#proxmox-rest-server = { path = "../proxmox/proxmox-rest-server" }
-#proxmox-router = { path = "../proxmox/proxmox-router" }
-#proxmox-schema = { path = "../proxmox/proxmox-schema" }
-#proxmox-section-config = { path = "../proxmox/proxmox-section-config" }
-#proxmox-serde = { path = "../proxmox/proxmox-serde" }
-#proxmox-shared-memory = { path = "../proxmox/proxmox-shared-memory" }
-#proxmox-sortable-macro = { path = "../proxmox/proxmox-sortable-macro" }
-#proxmox-subscription = { path = "../proxmox/proxmox-subscription" }
-#proxmox-sys = { path = "../proxmox/proxmox-sys" }
-#proxmox-tfa = { path = "../proxmox/proxmox-tfa" }
-#proxmox-time = { path = "../proxmox/proxmox-time" }
-#proxmox-uuid = { path = "../proxmox/proxmox-uuid" }
+proxmox-apt = { path = "../proxmox/proxmox-apt" }
+proxmox-async = { path = "../proxmox/proxmox-async" }
+proxmox-auth-api = { path = "../proxmox/proxmox-auth-api" }
+proxmox-borrow = { path = "../proxmox/proxmox-borrow" }
+proxmox-compression = { path = "../proxmox/proxmox-compression" }
+proxmox-fuse = { path = "../proxmox-fuse" }
+proxmox-http = { path = "../proxmox/proxmox-http" }
+proxmox-human-byte = { path = "../proxmox/proxmox-human-byte" }
+proxmox-io = { path = "../proxmox/proxmox-io" }
+proxmox-lang = { path = "../proxmox/proxmox-lang" }
+proxmox-log = { path = "../proxmox/proxmox-log" }
+proxmox-ldap = { path = "../proxmox/proxmox-ldap" }
+proxmox-metrics = { path = "../proxmox/proxmox-metrics" }
+proxmox-openid = { path = "../proxmox/proxmox-openid" }
+proxmox-rest-server = { path = "../proxmox/proxmox-rest-server" }
+proxmox-router = { path = "../proxmox/proxmox-router" }
+proxmox-schema = { path = "../proxmox/proxmox-schema" }
+proxmox-section-config = { path = "../proxmox/proxmox-section-config" }
+proxmox-serde = { path = "../proxmox/proxmox-serde" }
+proxmox-shared-memory = { path = "../proxmox/proxmox-shared-memory" }
+proxmox-sortable-macro = { path = "../proxmox/proxmox-sortable-macro" }
+proxmox-subscription = { path = "../proxmox/proxmox-subscription" }
+proxmox-sys = { path = "../proxmox/proxmox-sys" }
+proxmox-tfa = { path = "../proxmox/proxmox-tfa" }
+proxmox-time = { path = "../proxmox/proxmox-time" }
+proxmox-uuid = { path = "../proxmox/proxmox-uuid" }
-#proxmox-acme-rs = { path = "../proxmox-acme-rs" }
+proxmox-acme-rs = { path = "../proxmox-acme-rs" }
#pathpatterns = {path = "../pathpatterns" }
-#pxar = { path = "../pxar" }
+pxar = { path = "../pxar" }
[features]
default = []
diff --git a/pbs-api-types/src/metrics.rs b/pbs-api-types/src/metrics.rs
index be5ff27a..99df88a7 100644
--- a/pbs-api-types/src/metrics.rs
+++ b/pbs-api-types/src/metrics.rs
@@ -147,7 +147,6 @@ pub struct InfluxDbHttp {
pub comment: Option<String>,
}
-
#[api]
#[derive(Copy, Clone, Deserialize, Serialize, PartialEq, Eq, PartialOrd, Ord)]
/// Type of the metric server
diff --git a/pbs-api-types/src/node.rs b/pbs-api-types/src/node.rs
index 704215bb..9033d586 100644
--- a/pbs-api-types/src/node.rs
+++ b/pbs-api-types/src/node.rs
@@ -1,9 +1,8 @@
-use serde::{Deserialize, Serialize};
use proxmox_schema::*;
+use serde::{Deserialize, Serialize};
use crate::StorageStatus;
-
#[api]
#[derive(Serialize, Deserialize, Default)]
#[serde(rename_all = "kebab-case")]
diff --git a/pbs-datastore/Cargo.toml b/pbs-datastore/Cargo.toml
index b793dc5b..fcb11ac4 100644
--- a/pbs-datastore/Cargo.toml
+++ b/pbs-datastore/Cargo.toml
@@ -20,6 +20,7 @@ openssl.workspace = true
serde.workspace = true
serde_json.workspace = true
tokio = { workspace = true, features = [] }
+tracing.workspace = true
walkdir.workspace = true
zstd.workspace = true
diff --git a/pbs-datastore/src/chunk_store.rs b/pbs-datastore/src/chunk_store.rs
index fb282749..7cb3ee33 100644
--- a/pbs-datastore/src/chunk_store.rs
+++ b/pbs-datastore/src/chunk_store.rs
@@ -3,6 +3,7 @@ use std::path::{Path, PathBuf};
use std::sync::{Arc, Mutex};
use anyhow::{bail, format_err, Error};
+use tracing::info;
use pbs_api_types::{DatastoreFSyncLevel, GarbageCollectionStatus};
use proxmox_io::ReadExt;
@@ -10,7 +11,6 @@ use proxmox_sys::fs::{create_dir, create_path, file_type_from_file_stat, CreateO
use proxmox_sys::process_locker::{
ProcessLockExclusiveGuard, ProcessLockSharedGuard, ProcessLocker,
};
-use proxmox_sys::task_log;
use proxmox_sys::WorkerTaskContext;
use crate::file_formats::{
@@ -92,7 +92,6 @@ impl ChunkStore {
path: P,
uid: nix::unistd::Uid,
gid: nix::unistd::Gid,
- worker: Option<&dyn WorkerTaskContext>,
sync_level: DatastoreFSyncLevel,
) -> Result<Self, Error>
where
@@ -143,9 +142,7 @@ impl ChunkStore {
}
let percentage = (i * 100) / (64 * 1024);
if percentage != last_percentage {
- if let Some(worker) = worker {
- task_log!(worker, "Chunkstore create: {}%", percentage)
- }
+ info!(tasklog = true, "Chunkstore create: {}%", percentage);
last_percentage = percentage;
}
}
@@ -374,7 +371,10 @@ impl ChunkStore {
for (entry, percentage, bad) in self.get_chunk_iterator()? {
if last_percentage != percentage {
last_percentage = percentage;
- task_log!(worker, "processed {}% ({} chunks)", percentage, chunk_count,);
+ info!(
+ tasklog = true,
+ "processed {}% ({} chunks)", percentage, chunk_count,
+ );
}
worker.check_abort()?;
@@ -578,15 +578,8 @@ fn test_chunk_store1() {
let user = nix::unistd::User::from_uid(nix::unistd::Uid::current())
.unwrap()
.unwrap();
- let chunk_store = ChunkStore::create(
- "test",
- &path,
- user.uid,
- user.gid,
- None,
- DatastoreFSyncLevel::None,
- )
- .unwrap();
+ let chunk_store =
+ ChunkStore::create("test", &path, user.uid, user.gid, DatastoreFSyncLevel::None).unwrap();
let (chunk, digest) = crate::data_blob::DataChunkBuilder::new(&[0u8, 1u8])
.build()
@@ -598,14 +591,8 @@ fn test_chunk_store1() {
let (exists, _) = chunk_store.insert_chunk(&chunk, &digest).unwrap();
assert!(exists);
- let chunk_store = ChunkStore::create(
- "test",
- &path,
- user.uid,
- user.gid,
- None,
- DatastoreFSyncLevel::None,
- );
+ let chunk_store =
+ ChunkStore::create("test", &path, user.uid, user.gid, DatastoreFSyncLevel::None);
assert!(chunk_store.is_err());
if let Err(_e) = std::fs::remove_dir_all(".testdir") { /* ignore */ }
diff --git a/pbs-datastore/src/datastore.rs b/pbs-datastore/src/datastore.rs
index 41c9f4f2..23cadd58 100644
--- a/pbs-datastore/src/datastore.rs
+++ b/pbs-datastore/src/datastore.rs
@@ -7,6 +7,7 @@ use std::sync::{Arc, Mutex};
use anyhow::{bail, format_err, Error};
use lazy_static::lazy_static;
use nix::unistd::{unlinkat, UnlinkatFlags};
+use tracing::{info, warn};
use proxmox_human_byte::HumanByte;
use proxmox_schema::ApiType;
@@ -16,7 +17,6 @@ use proxmox_sys::fs::{file_read_optional_string, replace_file, CreateOptions};
use proxmox_sys::fs::{lock_dir_noblock, DirLockGuard};
use proxmox_sys::process_locker::ProcessLockSharedGuard;
use proxmox_sys::WorkerTaskContext;
-use proxmox_sys::{task_log, task_warn};
use pbs_api_types::{
Authid, BackupNamespace, BackupType, ChunkOrder, DataStoreConfig, DatastoreFSyncLevel,
@@ -925,8 +925,8 @@ impl DataStore {
let digest = index.index_digest(pos).unwrap();
if !self.inner.chunk_store.cond_touch_chunk(digest, false)? {
let hex = hex::encode(digest);
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"warning: unable to access non-existent chunk {hex}, required by {file_name:?}"
);
@@ -992,8 +992,8 @@ impl DataStore {
let percentage = (i + 1) * 100 / image_count;
if percentage > last_percentage {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"marked {}% ({} of {} index files)",
percentage,
i + 1,
@@ -1004,8 +1004,8 @@ impl DataStore {
}
if strange_paths_count > 0 {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"found (and marked) {} index files outside of expected directory scheme",
strange_paths_count,
);
@@ -1045,11 +1045,11 @@ impl DataStore {
..Default::default()
};
- task_log!(worker, "Start GC phase1 (mark used chunks)");
+ info!(tasklog = true, "Start GC phase1 (mark used chunks)");
self.mark_used_chunks(&mut gc_status, worker)?;
- task_log!(worker, "Start GC phase2 (sweep unused chunks)");
+ info!(tasklog = true, "Start GC phase2 (sweep unused chunks)");
self.inner.chunk_store.sweep_unused_chunks(
oldest_writer,
phase1_start_time,
@@ -1057,30 +1057,39 @@ impl DataStore {
worker,
)?;
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"Removed garbage: {}",
HumanByte::from(gc_status.removed_bytes),
);
- task_log!(worker, "Removed chunks: {}", gc_status.removed_chunks);
+ info!(
+ tasklog = true,
+ "Removed chunks: {}", gc_status.removed_chunks
+ );
if gc_status.pending_bytes > 0 {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"Pending removals: {} (in {} chunks)",
HumanByte::from(gc_status.pending_bytes),
gc_status.pending_chunks,
);
}
if gc_status.removed_bad > 0 {
- task_log!(worker, "Removed bad chunks: {}", gc_status.removed_bad);
+ info!(
+ tasklog = true,
+ "Removed bad chunks: {}", gc_status.removed_bad
+ );
}
if gc_status.still_bad > 0 {
- task_log!(worker, "Leftover bad chunks: {}", gc_status.still_bad);
+ info!(
+ tasklog = true,
+ "Leftover bad chunks: {}", gc_status.still_bad
+ );
}
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"Original data usage: {}",
HumanByte::from(gc_status.index_data_bytes),
);
@@ -1088,15 +1097,15 @@ impl DataStore {
if gc_status.index_data_bytes > 0 {
let comp_per =
(gc_status.disk_bytes as f64 * 100.) / gc_status.index_data_bytes as f64;
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"On-Disk usage: {} ({:.2}%)",
HumanByte::from(gc_status.disk_bytes),
comp_per,
);
}
- task_log!(worker, "On-Disk chunks: {}", gc_status.disk_chunks);
+ info!(tasklog = true, "On-Disk chunks: {}", gc_status.disk_chunks);
let deduplication_factor = if gc_status.disk_bytes > 0 {
(gc_status.index_data_bytes as f64) / (gc_status.disk_bytes as f64)
@@ -1104,11 +1113,18 @@ impl DataStore {
1.0
};
- task_log!(worker, "Deduplication factor: {:.2}", deduplication_factor);
+ info!(
+ tasklog = true,
+ "Deduplication factor: {:.2}", deduplication_factor
+ );
if gc_status.disk_chunks > 0 {
let avg_chunk = gc_status.disk_bytes / (gc_status.disk_chunks as u64);
- task_log!(worker, "Average chunk size: {}", HumanByte::from(avg_chunk));
+ info!(
+ tasklog = true,
+ "Average chunk size: {}",
+ HumanByte::from(avg_chunk)
+ );
}
if let Ok(serialized) = serde_json::to_string(&gc_status) {
@@ -1340,11 +1356,7 @@ impl DataStore {
/// Destroy a datastore. This requires that there are no active operations on the datastore.
///
/// This is a synchronous operation and should be run in a worker-thread.
- pub fn destroy(
- name: &str,
- destroy_data: bool,
- worker: &dyn WorkerTaskContext,
- ) -> Result<(), Error> {
+ pub fn destroy(name: &str, destroy_data: bool) -> Result<(), Error> {
let config_lock = pbs_config::datastore::lock_config()?;
let (mut config, _digest) = pbs_config::datastore::config()?;
@@ -1368,13 +1380,16 @@ impl DataStore {
let remove = |subdir, ok: &mut bool| {
if let Err(err) = std::fs::remove_dir_all(base.join(subdir)) {
if err.kind() != io::ErrorKind::NotFound {
- task_warn!(worker, "failed to remove {subdir:?} subdirectory: {err}");
+ warn!(
+ tasklog = true,
+ "failed to remove {subdir:?} subdirectory: {err}"
+ );
*ok = false;
}
}
};
- task_log!(worker, "Deleting datastore data...");
+ info!(tasklog = true, "Deleting datastore data...");
remove("ns", &mut ok); // ns first
remove("ct", &mut ok);
remove("vm", &mut ok);
@@ -1383,7 +1398,7 @@ impl DataStore {
if ok {
if let Err(err) = std::fs::remove_file(base.join(".gc-status")) {
if err.kind() != io::ErrorKind::NotFound {
- task_warn!(worker, "failed to remove .gc-status file: {err}");
+ warn!(tasklog = true, "failed to remove .gc-status file: {err}");
ok = false;
}
}
@@ -1397,7 +1412,7 @@ impl DataStore {
// now the config
if ok {
- task_log!(worker, "Removing datastore from config...");
+ info!(tasklog = true, "Removing datastore from config...");
let _lock = pbs_config::datastore::lock_config()?;
let _ = config.sections.remove(name);
pbs_config::datastore::save_config(&config)?;
@@ -1408,35 +1423,41 @@ impl DataStore {
if ok {
if let Err(err) = std::fs::remove_file(base.join(".lock")) {
if err.kind() != io::ErrorKind::NotFound {
- task_warn!(worker, "failed to remove .lock file: {err}");
+ warn!(tasklog = true, "failed to remove .lock file: {err}");
ok = false;
}
}
}
if ok {
- task_log!(worker, "Finished deleting data.");
+ info!(tasklog = true, "Finished deleting data.");
match std::fs::remove_dir(base) {
- Ok(()) => task_log!(worker, "Removed empty datastore directory."),
+ Ok(()) => info!(tasklog = true, "Removed empty datastore directory."),
Err(err) if err.kind() == io::ErrorKind::NotFound => {
// weird, but ok
}
Err(err) if err.is_errno(nix::errno::Errno::EBUSY) => {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"Cannot delete datastore directory (is it a mount point?)."
)
}
Err(err) if err.is_errno(nix::errno::Errno::ENOTEMPTY) => {
- task_warn!(worker, "Datastore directory not empty, not deleting.")
+ warn!(
+ tasklog = true,
+ "Datastore directory not empty, not deleting."
+ )
}
Err(err) => {
- task_warn!(worker, "Failed to remove datastore directory: {err}");
+ warn!(
+ tasklog = true,
+ "Failed to remove datastore directory: {err}"
+ );
}
}
} else {
- task_log!(worker, "There were errors deleting data.");
+ info!(tasklog = true, "There were errors deleting data.");
}
}
diff --git a/src/api2/admin/datastore.rs b/src/api2/admin/datastore.rs
index a95031e7..bb211378 100644
--- a/src/api2/admin/datastore.rs
+++ b/src/api2/admin/datastore.rs
@@ -13,6 +13,7 @@ use hyper::{header, Body, Response, StatusCode};
use serde::Deserialize;
use serde_json::{json, Value};
use tokio_stream::wrappers::ReceiverStream;
+use tracing::{info, warn};
use proxmox_async::blocking::WrappedReaderStream;
use proxmox_async::{io::AsyncChannelWriter, stream::AsyncReaderStream};
@@ -26,7 +27,6 @@ use proxmox_sortable_macro::sortable;
use proxmox_sys::fs::{
file_read_firstline, file_read_optional_string, replace_file, CreateOptions,
};
-use proxmox_sys::{task_log, task_warn};
use pxar::accessor::aio::Accessor;
use pxar::EntryKind;
@@ -907,9 +907,12 @@ pub fn verify(
)?
};
if !failed_dirs.is_empty() {
- task_log!(worker, "Failed to verify the following snapshots/groups:");
+ info!(
+ tasklog = true,
+ "Failed to verify the following snapshots/groups:"
+ );
for dir in failed_dirs {
- task_log!(worker, "\t{}", dir);
+ info!(tasklog = true, "\t{}", dir);
}
bail!("verification failed - please check the log for details");
}
@@ -1009,10 +1012,10 @@ pub fn prune(
}
// We use a WorkerTask just to have a task log, but run synchrounously
- let worker = WorkerTask::new("prune", Some(worker_id), auth_id.to_string(), true)?;
+ let (worker, _) = WorkerTask::new("prune", Some(worker_id), auth_id.to_string(), true)?;
if keep_all {
- task_log!(worker, "No prune selection - keeping all files.");
+ info!(tasklog = true, "No prune selection - keeping all files.");
} else {
let mut opts = Vec::new();
if !ns.is_root() {
@@ -1020,9 +1023,9 @@ pub fn prune(
}
crate::server::cli_keep_options(&mut opts, &keep_options);
- task_log!(worker, "retention options: {}", opts.join(" "));
- task_log!(
- worker,
+ info!(tasklog = true, "retention options: {}", opts.join(" "));
+ info!(
+ tasklog = true,
"Starting prune on {} group \"{}\"",
print_store_and_ns(&store, &ns),
group.group(),
@@ -1038,7 +1041,7 @@ pub fn prune(
let msg = format!("{}/{}/{} {}", group.ty, group.id, timestamp, mark,);
- task_log!(worker, "{}", msg);
+ info!(tasklog = true, "{}", msg);
prune_result.push(json!({
"backup-type": group.ty,
@@ -1050,8 +1053,8 @@ pub fn prune(
if !(dry_run || keep) {
if let Err(err) = info.backup_dir.destroy(false) {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"failed to remove dir {:?}: {}",
info.backup_dir.relative_path(),
err,
@@ -1121,9 +1124,7 @@ pub fn prune_datastore(
Some(worker_id),
auth_id.to_string(),
to_stdout,
- move |worker| {
- crate::server::prune_datastore(worker, auth_id, prune_options, datastore, dry_run)
- },
+ move |_worker| crate::server::prune_datastore(auth_id, prune_options, datastore, dry_run),
)?;
Ok(upid_str)
diff --git a/src/api2/admin/metrics.rs b/src/api2/admin/metrics.rs
index d72bd98b..c299485f 100644
--- a/src/api2/admin/metrics.rs
+++ b/src/api2/admin/metrics.rs
@@ -4,7 +4,7 @@ use serde_json::Value;
use proxmox_router::{Permission, Router, RpcEnvironment};
use proxmox_schema::api;
-use pbs_api_types::{PRIV_SYS_AUDIT, MetricServerInfo};
+use pbs_api_types::{MetricServerInfo, PRIV_SYS_AUDIT};
use pbs_config::metrics;
#[api(
diff --git a/src/api2/config/acme.rs b/src/api2/config/acme.rs
index 1954318b..6f9b3547 100644
--- a/src/api2/config/acme.rs
+++ b/src/api2/config/acme.rs
@@ -9,12 +9,12 @@ use hex::FromHex;
use lazy_static::lazy_static;
use serde::{Deserialize, Serialize};
use serde_json::{json, Value};
+use tracing::{info, warn};
use proxmox_router::{
http_bail, list_subdirs_api_method, Permission, Router, RpcEnvironment, SubdirMap,
};
use proxmox_schema::{api, param_bail};
-use proxmox_sys::{task_log, task_warn};
use proxmox_acme_rs::account::AccountData as AcmeAccountData;
use proxmox_acme_rs::Account;
@@ -219,18 +219,17 @@ fn register_account(
Some(name.to_string()),
auth_id.to_string(),
true,
- move |worker| async move {
+ move |_worker| async move {
let mut client = AcmeClient::new(directory);
- task_log!(worker, "Registering ACME account '{}'...", &name);
+ info!(tasklog = true, "Registering ACME account '{}'...", &name);
let account =
do_register_account(&mut client, &name, tos_url.is_some(), contact, None).await?;
- task_log!(
- worker,
- "Registration successful, account URL: {}",
- account.location
+ info!(
+ tasklog = true,
+ "Registration successful, account URL: {}", account.location
);
Ok(())
@@ -325,7 +324,7 @@ pub fn deactivate_account(
Some(name.to_string()),
auth_id.to_string(),
true,
- move |worker| async move {
+ move |_worker| async move {
match AcmeClient::load(&name)
.await?
.update_account(&json!({"status": "deactivated"}))
@@ -334,11 +333,9 @@ pub fn deactivate_account(
Ok(_account) => (),
Err(err) if !force => return Err(err),
Err(err) => {
- task_warn!(
- worker,
- "error deactivating account {}, proceedeing anyway - {}",
- name,
- err,
+ warn!(
+ tasklog = true,
+ "error deactivating account {}, proceedeing anyway - {}", name, err,
);
}
}
diff --git a/src/api2/config/datastore.rs b/src/api2/config/datastore.rs
index 5e013c39..299e1bea 100644
--- a/src/api2/config/datastore.rs
+++ b/src/api2/config/datastore.rs
@@ -4,11 +4,11 @@ use ::serde::{Deserialize, Serialize};
use anyhow::Error;
use hex::FromHex;
use serde_json::Value;
+use tracing::warn;
use proxmox_router::{http_bail, Permission, Router, RpcEnvironment, RpcEnvironmentType};
use proxmox_schema::{api, param_bail, ApiType};
use proxmox_section_config::SectionConfigData;
-use proxmox_sys::{task_warn, WorkerTaskContext};
use pbs_api_types::{
Authid, DataStoreConfig, DataStoreConfigUpdater, DatastoreNotify, DatastoreTuning,
@@ -69,7 +69,6 @@ pub(crate) fn do_create_datastore(
_lock: BackupLockGuard,
mut config: SectionConfigData,
datastore: DataStoreConfig,
- worker: Option<&dyn WorkerTaskContext>,
) -> Result<(), Error> {
let path: PathBuf = datastore.path.clone().into();
@@ -83,7 +82,6 @@ pub(crate) fn do_create_datastore(
path,
backup_user.uid,
backup_user.gid,
- worker,
tuning.sync_level.unwrap_or_default(),
)?;
@@ -132,7 +130,7 @@ pub fn create_datastore(
Some(config.name.to_string()),
auth_id.to_string(),
to_stdout,
- move |worker| do_create_datastore(lock, section_config, config, Some(&worker)),
+ move |_worker| do_create_datastore(lock, section_config, config),
)
}
@@ -460,8 +458,8 @@ pub async fn delete_datastore(
Some(name.clone()),
auth_id.to_string(),
to_stdout,
- move |worker| {
- pbs_datastore::DataStore::destroy(&name, destroy_data, &worker)?;
+ move |_worker| {
+ pbs_datastore::DataStore::destroy(&name, destroy_data)?;
// ignore errors
let _ = jobstate::remove_state_file("prune", &name);
@@ -470,7 +468,10 @@ pub async fn delete_datastore(
if let Err(err) =
proxmox_async::runtime::block_on(crate::server::notify_datastore_removed())
{
- task_warn!(worker, "failed to notify after datastore removal: {err}");
+ warn!(
+ tasklog = true,
+ "failed to notify after datastore removal: {err}"
+ );
}
Ok(())
diff --git a/src/api2/node/apt.rs b/src/api2/node/apt.rs
index 8e4f150d..a9853b31 100644
--- a/src/api2/node/apt.rs
+++ b/src/api2/node/apt.rs
@@ -2,6 +2,7 @@ use anyhow::{bail, format_err, Error};
use serde_json::{json, Value};
use std::collections::HashMap;
use std::os::unix::prelude::OsStrExt;
+use tracing::{info, warn};
use proxmox_router::{
list_subdirs_api_method, Permission, Router, RpcEnvironment, RpcEnvironmentType, SubdirMap,
@@ -85,9 +86,9 @@ fn read_and_update_proxy_config() -> Result<Option<ProxyConfig>, Error> {
Ok(proxy_config)
}
-fn do_apt_update(worker: &WorkerTask, quiet: bool) -> Result<(), Error> {
+fn do_apt_update(quiet: bool) -> Result<(), Error> {
if !quiet {
- worker.log_message("starting apt-get update")
+ info!(log = "file", "starting apt-get update")
}
read_and_update_proxy_config()?;
@@ -101,7 +102,7 @@ fn do_apt_update(worker: &WorkerTask, quiet: bool) -> Result<(), Error> {
.map_err(|err| format_err!("failed to execute {:?} - {}", command, err))?;
if !quiet {
- worker.log_message(String::from_utf8(output.stdout)?);
+ info!(tasklog = true, "{}", String::from_utf8(output.stdout)?);
}
// TODO: improve run_command to allow outputting both, stderr and stdout
@@ -116,7 +117,7 @@ fn do_apt_update(worker: &WorkerTask, quiet: bool) -> Result<(), Error> {
}
})
.unwrap_or_else(|_| String::from("non utf8 error message (suppressed)"));
- worker.log_warning(msg);
+ warn!(tasklog = true, msg);
} else {
bail!("terminated by signal");
}
@@ -162,8 +163,8 @@ pub fn apt_update_database(
let auth_id = rpcenv.get_auth_id().unwrap();
let to_stdout = rpcenv.env_type() == RpcEnvironmentType::CLI;
- let upid_str = WorkerTask::new_thread("aptupdate", None, auth_id, to_stdout, move |worker| {
- do_apt_update(&worker, quiet)?;
+ let upid_str = WorkerTask::new_thread("aptupdate", None, auth_id, to_stdout, move |_worker| {
+ do_apt_update(quiet)?;
let mut cache = apt::update_cache()?;
diff --git a/src/api2/node/certificates.rs b/src/api2/node/certificates.rs
index d514001a..24a40e7d 100644
--- a/src/api2/node/certificates.rs
+++ b/src/api2/node/certificates.rs
@@ -5,16 +5,17 @@ use anyhow::{bail, format_err, Error};
use openssl::pkey::PKey;
use openssl::x509::X509;
use serde::{Deserialize, Serialize};
+use tracing::info;
use proxmox_router::list_subdirs_api_method;
use proxmox_router::SubdirMap;
use proxmox_router::{Permission, Router, RpcEnvironment};
use proxmox_schema::api;
-use proxmox_sys::{task_log, task_warn};
use pbs_api_types::{NODE_SCHEMA, PRIV_SYS_MODIFY};
use pbs_buildcfg::configdir;
use pbs_tools::cert;
+use tracing::warn;
use crate::acme::AcmeClient;
use crate::api2::types::AcmeDomain;
@@ -305,8 +306,8 @@ async fn order_certificate(
};
if domains.is_empty() {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"No domains configured to be ordered from an ACME server."
);
return Ok(None);
@@ -316,11 +317,11 @@ async fn order_certificate(
let mut acme = node_config.acme_client().await?;
- task_log!(worker, "Placing ACME order");
+ info!(tasklog = true, "Placing ACME order");
let order = acme
.new_order(domains.iter().map(|d| d.domain.to_ascii_lowercase()))
.await?;
- task_log!(worker, "Order URL: {}", order.location);
+ info!(tasklog = true, "Order URL: {}", order.location);
let identifiers: Vec<String> = order
.data
@@ -332,7 +333,10 @@ async fn order_certificate(
.collect();
for auth_url in &order.data.authorizations {
- task_log!(worker, "Getting authorization details from '{}'", auth_url);
+ info!(
+ tasklog = true,
+ "Getting authorization details from '{}'", auth_url
+ );
let mut auth = acme.get_authorization(auth_url).await?;
let domain = match &mut auth.identifier {
@@ -340,11 +344,11 @@ async fn order_certificate(
};
if auth.status == Status::Valid {
- task_log!(worker, "{} is already validated!", domain);
+ info!(tasklog = true, "{} is already validated!", domain);
continue;
}
- task_log!(worker, "The validation for {} is pending", domain);
+ info!(tasklog = true, "The validation for {} is pending", domain);
let domain_config: &AcmeDomain = get_domain_config(&domain)?;
let plugin_id = domain_config.plugin.as_deref().unwrap_or("standalone");
let mut plugin_cfg =
@@ -352,31 +356,28 @@ async fn order_certificate(
format_err!("plugin '{}' for domain '{}' not found!", plugin_id, domain)
})?;
- task_log!(worker, "Setting up validation plugin");
+ info!(tasklog = true, "Setting up validation plugin");
let validation_url = plugin_cfg
.setup(&mut acme, &auth, domain_config, Arc::clone(&worker))
.await?;
- let result = request_validation(&worker, &mut acme, auth_url, validation_url).await;
+ let result = request_validation(&mut acme, auth_url, validation_url).await;
if let Err(err) = plugin_cfg
.teardown(&mut acme, &auth, domain_config, Arc::clone(&worker))
.await
{
- task_warn!(
- worker,
- "Failed to teardown plugin '{}' for domain '{}' - {}",
- plugin_id,
- domain,
- err
+ warn!(
+ tasklog = true,
+ "Failed to teardown plugin '{}' for domain '{}' - {}", plugin_id, domain, err
);
}
result?;
}
- task_log!(worker, "All domains validated");
- task_log!(worker, "Creating CSR");
+ info!(tasklog = true, "All domains validated");
+ info!(tasklog = true, "Creating CSR");
let csr = proxmox_acme_rs::util::Csr::generate(&identifiers, &Default::default())?;
let mut finalize_error_cnt = 0u8;
@@ -389,7 +390,7 @@ async fn order_certificate(
match order.status {
Status::Pending => {
- task_log!(worker, "still pending, trying to finalize anyway");
+ info!(tasklog = true, "still pending, trying to finalize anyway");
let finalize = order
.finalize
.as_deref()
@@ -404,7 +405,7 @@ async fn order_certificate(
tokio::time::sleep(Duration::from_secs(5)).await;
}
Status::Ready => {
- task_log!(worker, "order is ready, finalizing");
+ info!(tasklog = true, "order is ready, finalizing");
let finalize = order
.finalize
.as_deref()
@@ -413,18 +414,21 @@ async fn order_certificate(
tokio::time::sleep(Duration::from_secs(5)).await;
}
Status::Processing => {
- task_log!(worker, "still processing, trying again in 30 seconds");
+ info!(
+ tasklog = true,
+ "still processing, trying again in 30 seconds"
+ );
tokio::time::sleep(Duration::from_secs(30)).await;
}
Status::Valid => {
- task_log!(worker, "valid");
+ info!(tasklog = true, "valid");
break;
}
other => bail!("order status: {:?}", other),
}
}
- task_log!(worker, "Downloading certificate");
+ info!(tasklog = true, "Downloading certificate");
let certificate = acme
.get_certificate(
order
@@ -441,15 +445,14 @@ async fn order_certificate(
}
async fn request_validation(
- worker: &WorkerTask,
acme: &mut AcmeClient,
auth_url: &str,
validation_url: &str,
) -> Result<(), Error> {
- task_log!(worker, "Triggering validation");
+ info!(tasklog = true, "Triggering validation");
acme.request_challenge_validation(validation_url).await?;
- task_log!(worker, "Sleeping for 5 seconds");
+ info!(tasklog = true, "Sleeping for 5 seconds");
tokio::time::sleep(Duration::from_secs(5)).await;
loop {
@@ -458,8 +461,8 @@ async fn request_validation(
let auth = acme.get_authorization(auth_url).await?;
match auth.status {
Status::Pending => {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"Status is still 'pending', trying again in 10 seconds"
);
tokio::time::sleep(Duration::from_secs(10)).await;
@@ -586,13 +589,13 @@ pub fn revoke_acme_cert(rpcenv: &mut dyn RpcEnvironment) -> Result<String, Error
None,
auth_id,
true,
- move |worker| async move {
- task_log!(worker, "Loading ACME account");
+ move |_worker| async move {
+ info!(tasklog = true, "Loading ACME account");
let mut acme = node_config.acme_client().await?;
- task_log!(worker, "Revoking old certificate");
+ info!(tasklog = true, "Revoking old certificate");
acme.revoke_certificate(cert_pem.as_bytes(), None).await?;
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"Deleting certificate and regenerating a self-signed one"
);
delete_custom_certificate().await?;
diff --git a/src/api2/node/disks/directory.rs b/src/api2/node/disks/directory.rs
index d5a16be7..20de1d9c 100644
--- a/src/api2/node/disks/directory.rs
+++ b/src/api2/node/disks/directory.rs
@@ -1,11 +1,11 @@
use ::serde::{Deserialize, Serialize};
use anyhow::{bail, Error};
use serde_json::json;
+use tracing::info;
use proxmox_router::{Permission, Router, RpcEnvironment, RpcEnvironmentType};
use proxmox_schema::api;
use proxmox_section_config::SectionConfigData;
-use proxmox_sys::task_log;
use pbs_api_types::{
DataStoreConfig, BLOCKDEVICE_NAME_SCHEMA, DATASTORE_SCHEMA, NODE_SCHEMA, PRIV_SYS_AUDIT,
@@ -170,8 +170,11 @@ pub fn create_datastore_disk(
Some(name.clone()),
auth_id,
to_stdout,
- move |worker| {
- task_log!(worker, "create datastore '{}' on disk {}", name, disk);
+ move |_worker| {
+ info!(
+ tasklog = true,
+ "create datastore '{}' on disk {}", name, disk
+ );
let add_datastore = add_datastore.unwrap_or(false);
let filesystem = filesystem.unwrap_or(FileSystemType::Ext4);
@@ -204,12 +207,7 @@ pub fn create_datastore_disk(
bail!("datastore '{}' already exists.", datastore.name);
}
- crate::api2::config::datastore::do_create_datastore(
- lock,
- config,
- datastore,
- Some(&worker),
- )?;
+ crate::api2::config::datastore::do_create_datastore(lock, config, datastore)?;
}
Ok(())
diff --git a/src/api2/node/disks/mod.rs b/src/api2/node/disks/mod.rs
index 5ee959cd..3cb13ff0 100644
--- a/src/api2/node/disks/mod.rs
+++ b/src/api2/node/disks/mod.rs
@@ -6,7 +6,7 @@ use proxmox_router::{
};
use proxmox_schema::api;
use proxmox_sortable_macro::sortable;
-use proxmox_sys::task_log;
+use tracing::info;
use pbs_api_types::{
BLOCKDEVICE_NAME_SCHEMA, NODE_SCHEMA, PRIV_SYS_AUDIT, PRIV_SYS_MODIFY, UPID_SCHEMA,
@@ -163,8 +163,8 @@ pub fn initialize_disk(
Some(disk.clone()),
auth_id,
to_stdout,
- move |worker| {
- task_log!(worker, "initialize disk {}", disk);
+ move |_worker| {
+ info!(tasklog = true, "initialize disk {}", disk);
let disk_manager = DiskManage::new();
let disk_info = disk_manager.disk_by_name(&disk)?;
diff --git a/src/api2/node/disks/zfs.rs b/src/api2/node/disks/zfs.rs
index c8d221cc..b143d178 100644
--- a/src/api2/node/disks/zfs.rs
+++ b/src/api2/node/disks/zfs.rs
@@ -1,9 +1,9 @@
use anyhow::{bail, Error};
use serde_json::{json, Value};
+use tracing::{error, info};
use proxmox_router::{Permission, Router, RpcEnvironment, RpcEnvironmentType};
use proxmox_schema::api;
-use proxmox_sys::{task_error, task_log};
use pbs_api_types::{
DataStoreConfig, ZfsCompressionType, ZfsRaidLevel, ZpoolListItem, DATASTORE_SCHEMA,
@@ -228,13 +228,10 @@ pub fn create_zpool(
Some(name.clone()),
auth_id,
to_stdout,
- move |worker| {
- task_log!(
- worker,
- "create {:?} zpool '{}' on devices '{}'",
- raidlevel,
- name,
- devices_text
+ move |_worker| {
+ info!(
+ tasklog = true,
+ "create {:?} zpool '{}' on devices '{}'", raidlevel, name, devices_text
);
let mut command = std::process::Command::new("zpool");
@@ -275,12 +272,12 @@ pub fn create_zpool(
}
}
- task_log!(worker, "# {:?}", command);
+ info!(tasklog = true, "# {:?}", command);
match proxmox_sys::command::run_command(command, None) {
- Ok(output) => task_log!(worker, "{output}"),
+ Ok(output) => info!(tasklog = true, "{output}"),
Err(err) => {
- task_error!(worker, "{err}");
+ error!(tasklog = true, "{err}");
bail!("Error during 'zpool create', see task log for more details");
}
};
@@ -299,11 +296,11 @@ pub fn create_zpool(
command.arg(&format!("compression={}", compression));
}
command.args(["relatime=on", &name]);
- task_log!(worker, "# {:?}", command);
+ info!(tasklog = true, "# {:?}", command);
match proxmox_sys::command::run_command(command, None) {
- Ok(output) => task_log!(worker, "{output}"),
+ Ok(output) => info!(tasklog = true, "{output}"),
Err(err) => {
- task_error!(worker, "{err}");
+ error!(tasklog = true, "{err}");
bail!("Error during 'zfs set', see task log for more details");
}
};
@@ -319,12 +316,7 @@ pub fn create_zpool(
bail!("datastore '{}' already exists.", datastore.name);
}
- crate::api2::config::datastore::do_create_datastore(
- lock,
- config,
- datastore,
- Some(&worker),
- )?;
+ crate::api2::config::datastore::do_create_datastore(lock, config, datastore)?;
}
Ok(())
diff --git a/src/api2/node/mod.rs b/src/api2/node/mod.rs
index 931143fd..32373e08 100644
--- a/src/api2/node/mod.rs
+++ b/src/api2/node/mod.rs
@@ -25,6 +25,7 @@ use proxmox_sortable_macro::sortable;
use proxmox_sys::fd::fd_change_cloexec;
use pbs_api_types::{NODE_SCHEMA, PRIV_SYS_CONSOLE};
+use tracing::{info, warn};
use crate::auth::{private_auth_keyring, public_auth_keyring};
use crate::tools;
@@ -181,20 +182,18 @@ async fn termproxy(cmd: Option<String>, rpcenv: &mut dyn RpcEnvironment) -> Resu
let stdout = child.stdout.take().expect("no child stdout handle");
let stderr = child.stderr.take().expect("no child stderr handle");
- let worker_stdout = worker.clone();
let stdout_fut = async move {
let mut reader = BufReader::new(stdout).lines();
while let Some(line) = reader.next_line().await? {
- worker_stdout.log_message(line);
+ info!(tasklog = true, line);
}
Ok::<(), Error>(())
};
- let worker_stderr = worker.clone();
let stderr_fut = async move {
let mut reader = BufReader::new(stderr).lines();
while let Some(line) = reader.next_line().await? {
- worker_stderr.log_warning(line);
+ warn!(tasklog = true, line);
}
Ok::<(), Error>(())
};
@@ -226,9 +225,9 @@ async fn termproxy(cmd: Option<String>, rpcenv: &mut dyn RpcEnvironment) -> Resu
}
if let Err(err) = child.kill().await {
- worker.log_warning(format!("error killing termproxy: {}", err));
+ warn!(tasklog = true, "error killing termproxy: {}", err);
} else if let Err(err) = child.wait().await {
- worker.log_warning(format!("error awaiting termproxy: {}", err));
+ warn!(tasklog = true, "error awaiting termproxy: {}", err);
}
}
diff --git a/src/api2/pull.rs b/src/api2/pull.rs
index daeba7cf..2c5d02d2 100644
--- a/src/api2/pull.rs
+++ b/src/api2/pull.rs
@@ -1,10 +1,10 @@
//! Sync datastore from remote server
use anyhow::{format_err, Error};
use futures::{future::FutureExt, select};
+use tracing::info;
use proxmox_router::{Permission, Router, RpcEnvironment};
use proxmox_schema::api;
-use proxmox_sys::task_log;
use pbs_api_types::{
Authid, BackupNamespace, GroupFilter, RateLimitConfig, SyncJobConfig, DATASTORE_SCHEMA,
@@ -116,21 +116,21 @@ pub fn do_sync_job(
let pull_params = PullParameters::try_from(&sync_job)?;
let client = pull_params.client().await?;
- task_log!(worker, "Starting datastore sync job '{}'", job_id);
+ info!(tasklog = true, "Starting datastore sync job '{}'", job_id);
if let Some(event_str) = schedule {
- task_log!(worker, "task triggered by schedule '{}'", event_str);
+ info!(tasklog = true, "task triggered by schedule '{}'", event_str);
}
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"sync datastore '{}' from '{}/{}'",
sync_job.store,
sync_job.remote,
sync_job.remote_store,
);
- pull_store(&worker, &client, pull_params).await?;
+ pull_store(&client, pull_params).await?;
- task_log!(worker, "sync job '{}' end", &job_id);
+ info!(tasklog = true, "sync job '{}' end", &job_id);
Ok(())
};
@@ -276,21 +276,18 @@ async fn pull(
auth_id.to_string(),
true,
move |worker| async move {
- task_log!(
- worker,
- "pull datastore '{}' from '{}/{}'",
- store,
- remote,
- remote_store,
+ info!(
+ tasklog = true,
+ "pull datastore '{}' from '{}/{}'", store, remote, remote_store,
);
- let pull_future = pull_store(&worker, &client, pull_params);
+ let pull_future = pull_store(&client, pull_params);
(select! {
success = pull_future.fuse() => success,
abort = worker.abort_future().map(|_| Err(format_err!("pull aborted"))) => abort,
})?;
- task_log!(worker, "pull datastore '{}' end", store);
+ info!(tasklog = true, "pull datastore '{}' end", store);
Ok(())
},
diff --git a/src/api2/tape/backup.rs b/src/api2/tape/backup.rs
index 2f9385a7..5f50a0b0 100644
--- a/src/api2/tape/backup.rs
+++ b/src/api2/tape/backup.rs
@@ -2,11 +2,12 @@ use std::sync::{Arc, Mutex};
use anyhow::{bail, format_err, Error};
use serde_json::Value;
+use tracing::{info, warn};
use proxmox_lang::try_block;
use proxmox_router::{Permission, Router, RpcEnvironment, RpcEnvironmentType};
use proxmox_schema::api;
-use proxmox_sys::{task_log, task_warn, WorkerTaskContext};
+use proxmox_sys::WorkerTaskContext;
use pbs_api_types::{
print_ns_and_snapshot, print_store_and_ns, Authid, GroupFilter, MediaPoolConfig, Operation,
@@ -181,7 +182,7 @@ pub fn do_tape_backup_job(
let job_result = try_block!({
if schedule.is_some() {
// for scheduled tape backup jobs, we wait indefinitely for the lock
- task_log!(worker, "waiting for drive lock...");
+ info!(tasklog = true, "waiting for drive lock...");
loop {
worker.check_abort()?;
match lock_tape_device(&drive_config, &setup.drive) {
@@ -196,9 +197,9 @@ pub fn do_tape_backup_job(
}
set_tape_device_state(&setup.drive, &worker.upid().to_string())?;
- task_log!(worker, "Starting tape backup job '{}'", job_id);
+ info!(tasklog = true, "Starting tape backup job '{}'", job_id);
if let Some(event_str) = schedule {
- task_log!(worker, "task triggered by schedule '{}'", event_str);
+ info!(tasklog = true, "task triggered by schedule '{}'", event_str);
}
backup_worker(
@@ -392,7 +393,7 @@ fn backup_worker(
) -> Result<(), Error> {
let start = std::time::Instant::now();
- task_log!(worker, "update media online status");
+ info!(tasklog = true, "update media online status");
let changer_name = update_media_online_status(&setup.drive)?;
let root_namespace = setup.ns.clone().unwrap_or_default();
@@ -400,8 +401,7 @@ fn backup_worker(
let pool = MediaPool::with_config(TAPE_STATUS_DIR, pool_config, changer_name, false)?;
- let mut pool_writer =
- PoolWriter::new(pool, &setup.drive, worker, email, force_media_set, ns_magic)?;
+ let mut pool_writer = PoolWriter::new(pool, &setup.drive, email, force_media_set, ns_magic)?;
let mut group_list = Vec::new();
let namespaces = datastore.recursive_iter_backup_ns_ok(root_namespace, setup.max_depth)?;
@@ -422,16 +422,14 @@ fn backup_worker(
.filter(|group| filter_fn(group, group_filters))
.collect();
let group_count = list.len();
- task_log!(
- worker,
- "found {} groups (out of {} total)",
- group_count,
- group_count_full
+ info!(
+ tasklog = true,
+ "found {} groups (out of {} total)", group_count, group_count_full
);
(list, group_count)
} else {
let group_count = group_list.len();
- task_log!(worker, "found {} groups", group_count);
+ info!(tasklog = true, "found {} groups", group_count);
(group_list, group_count)
};
@@ -440,8 +438,8 @@ fn backup_worker(
let latest_only = setup.latest_only.unwrap_or(false);
if latest_only {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"latest-only: true (only considering latest snapshots)"
);
}
@@ -466,8 +464,8 @@ fn backup_worker(
.collect();
if snapshot_list.is_empty() {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"{}, group {} was empty",
print_store_and_ns(datastore_name, group.backup_ns()),
group.group()
@@ -487,7 +485,7 @@ fn backup_worker(
info.backup_dir.backup_ns(),
info.backup_dir.as_ref(),
) {
- task_log!(worker, "skip snapshot {}", rel_path);
+ info!(tasklog = true, "skip snapshot {}", rel_path);
continue;
}
@@ -500,7 +498,7 @@ fn backup_worker(
SnapshotBackupResult::Ignored => {}
}
progress.done_snapshots = 1;
- task_log!(worker, "percentage done: {}", progress);
+ info!(tasklog = true, "percentage done: {}", progress);
}
} else {
progress.group_snapshots = snapshot_list.len() as u64;
@@ -513,7 +511,7 @@ fn backup_worker(
info.backup_dir.backup_ns(),
info.backup_dir.as_ref(),
) {
- task_log!(worker, "skip snapshot {}", rel_path);
+ info!(tasklog = true, "skip snapshot {}", rel_path);
continue;
}
@@ -526,7 +524,7 @@ fn backup_worker(
SnapshotBackupResult::Ignored => {}
}
progress.done_snapshots = snapshot_number as u64 + 1;
- task_log!(worker, "percentage done: {}", progress);
+ info!(tasklog = true, "percentage done: {}", progress);
}
}
}
@@ -534,18 +532,18 @@ fn backup_worker(
pool_writer.commit()?;
if need_catalog {
- task_log!(worker, "append media catalog");
+ info!(tasklog = true, "append media catalog");
let uuid = pool_writer.load_writable_media(worker)?;
- let done = pool_writer.append_catalog_archive(worker)?;
+ let done = pool_writer.append_catalog_archive()?;
if !done {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"catalog does not fit on tape, writing to next volume"
);
pool_writer.set_media_status_full(&uuid)?;
pool_writer.load_writable_media(worker)?;
- let done = pool_writer.append_catalog_archive(worker)?;
+ let done = pool_writer.append_catalog_archive()?;
if !done {
bail!("write_catalog_archive failed on second media");
}
@@ -553,9 +551,9 @@ fn backup_worker(
}
if setup.export_media_set.unwrap_or(false) {
- pool_writer.export_media_set(worker)?;
+ pool_writer.export_media_set()?;
} else if setup.eject_media.unwrap_or(false) {
- pool_writer.eject_media(worker)?;
+ pool_writer.eject_media()?;
}
if errors {
@@ -565,7 +563,10 @@ fn backup_worker(
summary.used_tapes = match pool_writer.get_used_media_labels() {
Ok(tapes) => Some(tapes),
Err(err) => {
- task_warn!(worker, "could not collect list of used tapes: {err}");
+ warn!(
+ tasklog = true,
+ "could not collect list of used tapes: {err}"
+ );
None
}
};
@@ -599,7 +600,7 @@ fn backup_snapshot(
snapshot: BackupDir,
) -> Result<SnapshotBackupResult, Error> {
let snapshot_path = snapshot.relative_path();
- task_log!(worker, "backup snapshot {:?}", snapshot_path);
+ info!(tasklog = true, "backup snapshot {:?}", snapshot_path);
let snapshot_reader = match snapshot.locked_reader() {
Ok(reader) => reader,
@@ -607,14 +608,15 @@ fn backup_snapshot(
if !snapshot.full_path().exists() {
// we got an error and the dir does not exist,
// it probably just vanished, so continue
- task_log!(worker, "snapshot {:?} vanished, skipping", snapshot_path);
+ info!(
+ tasklog = true,
+ "snapshot {:?} vanished, skipping", snapshot_path
+ );
return Ok(SnapshotBackupResult::Ignored);
}
- task_warn!(
- worker,
- "failed opening snapshot {:?}: {}",
- snapshot_path,
- err
+ warn!(
+ tasklog = true,
+ "failed opening snapshot {:?}: {}", snapshot_path, err
);
return Ok(SnapshotBackupResult::Error);
}
@@ -661,7 +663,7 @@ fn backup_snapshot(
let snapshot_reader = snapshot_reader.lock().unwrap();
- let (done, _bytes) = pool_writer.append_snapshot_archive(worker, &snapshot_reader)?;
+ let (done, _bytes) = pool_writer.append_snapshot_archive(&snapshot_reader)?;
if !done {
// does not fit on tape, so we try on next volume
@@ -670,15 +672,15 @@ fn backup_snapshot(
worker.check_abort()?;
pool_writer.load_writable_media(worker)?;
- let (done, _bytes) = pool_writer.append_snapshot_archive(worker, &snapshot_reader)?;
+ let (done, _bytes) = pool_writer.append_snapshot_archive(&snapshot_reader)?;
if !done {
bail!("write_snapshot_archive failed on second media");
}
}
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"end backup {}:{:?}",
datastore.name(),
snapshot_path
diff --git a/src/api2/tape/drive.rs b/src/api2/tape/drive.rs
index 5306e605..f3550328 100644
--- a/src/api2/tape/drive.rs
+++ b/src/api2/tape/drive.rs
@@ -4,6 +4,7 @@ use std::sync::Arc;
use anyhow::{bail, format_err, Error};
use serde_json::Value;
+use tracing::{info, warn};
use proxmox_router::{
list_subdirs_api_method, Permission, Router, RpcEnvironment, RpcEnvironmentType, SubdirMap,
@@ -11,7 +12,6 @@ use proxmox_router::{
use proxmox_schema::api;
use proxmox_section_config::SectionConfigData;
use proxmox_sortable_macro::sortable;
-use proxmox_sys::{task_log, task_warn};
use proxmox_uuid::Uuid;
use pbs_api_types::{
@@ -131,12 +131,10 @@ pub fn load_media(
drive.clone(),
"load-media",
Some(job_id),
- move |worker, config| {
- task_log!(
- worker,
- "loading media '{}' into drive '{}'",
- label_text,
- drive
+ move |_worker, config| {
+ info!(
+ tasklog = true,
+ "loading media '{}' into drive '{}'", label_text, drive
);
let (mut changer, _) = required_media_changer(&config, &drive)?;
changer.load_media(&label_text)?;
@@ -250,8 +248,8 @@ pub fn unload(
drive.clone(),
"unload-media",
Some(drive.clone()),
- move |worker, config| {
- task_log!(worker, "unloading media from drive '{}'", drive);
+ move |_worker, config| {
+ info!(tasklog = true, "unloading media from drive '{}'", drive);
let (mut changer, _) = required_media_changer(&config, &drive)?;
changer.unload_media(target_slot)?;
@@ -299,9 +297,9 @@ pub fn format_media(
drive.clone(),
"format-media",
Some(drive.clone()),
- move |worker, config| {
+ move |_worker, config| {
if let Some(ref label) = label_text {
- task_log!(worker, "try to load media '{}'", label);
+ info!(tasklog = true, "try to load media '{}'", label);
if let Some((mut changer, _)) = media_changer(&config, &drive)? {
changer.load_media(label)?;
}
@@ -315,15 +313,15 @@ pub fn format_media(
bail!("expected label '{}', found unrelated data", label);
}
/* assume drive contains no or unrelated data */
- task_log!(worker, "unable to read media label: {}", err);
- task_log!(worker, "format anyways");
+ info!(tasklog = true, "unable to read media label: {}", err);
+ info!(tasklog = true, "format anyways");
handle.format_media(fast.unwrap_or(true))?;
}
Ok((None, _)) => {
if let Some(label) = label_text {
bail!("expected label '{}', found empty tape", label);
}
- task_log!(worker, "found empty media - format anyways");
+ info!(tasklog = true, "found empty media - format anyways");
handle.format_media(fast.unwrap_or(true))?;
}
Ok((Some(media_id), _key_config)) => {
@@ -337,8 +335,8 @@ pub fn format_media(
}
}
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"found media '{}' with uuid '{}'",
media_id.label.label_text,
media_id.label.uuid,
@@ -489,7 +487,7 @@ pub fn label_media(
drive.clone(),
"label-media",
Some(drive.clone()),
- move |worker, config| {
+ move |_worker, config| {
let mut drive = open_drive(&config, &drive)?;
drive.rewind()?;
@@ -511,7 +509,7 @@ pub fn label_media(
pool: pool.clone(),
};
- write_media_label(worker, &mut drive, label, pool)
+ write_media_label(&mut drive, label, pool)
},
)?;
@@ -519,24 +517,20 @@ pub fn label_media(
}
fn write_media_label(
- worker: Arc<WorkerTask>,
drive: &mut Box<dyn TapeDriver>,
label: MediaLabel,
pool: Option<String>,
) -> Result<(), Error> {
drive.label_tape(&label)?;
if let Some(ref pool) = pool {
- task_log!(
- worker,
- "Label media '{}' for pool '{}'",
- label.label_text,
- pool
+ info!(
+ tasklog = true,
+ "Label media '{}' for pool '{}'", label.label_text, pool
);
} else {
- task_log!(
- worker,
- "Label media '{}' (no pool assignment)",
- label.label_text
+ info!(
+ tasklog = true,
+ "Label media '{}' (no pool assignment)", label.label_text
);
}
@@ -729,10 +723,10 @@ pub fn clean_drive(drive: String, rpcenv: &mut dyn RpcEnvironment) -> Result<Val
drive.clone(),
"clean-drive",
Some(drive.clone()),
- move |worker, config| {
+ move |_worker, config| {
let (mut changer, _changer_name) = required_media_changer(&config, &drive)?;
- task_log!(worker, "Starting drive clean");
+ info!(tasklog = true, "Starting drive clean");
changer.clean_drive()?;
@@ -743,7 +737,7 @@ pub fn clean_drive(drive: String, rpcenv: &mut dyn RpcEnvironment) -> Result<Val
// test for critical tape alert flags
if let Ok(alert_flags) = handle.tape_alert_flags() {
if !alert_flags.is_empty() {
- task_log!(worker, "TapeAlertFlags: {:?}", alert_flags);
+ info!(tasklog = true, "TapeAlertFlags: {:?}", alert_flags);
if tape_alert_flags_critical(alert_flags) {
bail!("found critical tape alert flags: {:?}", alert_flags);
}
@@ -752,13 +746,16 @@ pub fn clean_drive(drive: String, rpcenv: &mut dyn RpcEnvironment) -> Result<Val
// test wearout (max. 50 mounts)
if let Ok(volume_stats) = handle.volume_statistics() {
- task_log!(worker, "Volume mounts: {}", volume_stats.volume_mounts);
+ info!(
+ tasklog = true,
+ "Volume mounts: {}", volume_stats.volume_mounts
+ );
let wearout = volume_stats.volume_mounts * 2; // (*100.0/50.0);
- task_log!(worker, "Cleaning tape wearout: {}%", wearout);
+ info!(tasklog = true, "Cleaning tape wearout: {}%", wearout);
}
}
- task_log!(worker, "Drive cleaned successfully");
+ info!(tasklog = true, "Drive cleaned successfully");
Ok(())
},
@@ -880,12 +877,15 @@ pub fn update_inventory(
drive.clone(),
"inventory-update",
Some(drive.clone()),
- move |worker, config| {
+ move |_worker, config| {
let (mut changer, changer_name) = required_media_changer(&config, &drive)?;
let label_text_list = changer.online_media_label_texts()?;
if label_text_list.is_empty() {
- task_log!(worker, "changer device does not list any media labels");
+ info!(
+ tasklog = true,
+ "changer device does not list any media labels"
+ );
}
let mut inventory = Inventory::load(TAPE_STATUS_DIR)?;
@@ -894,7 +894,7 @@ pub fn update_inventory(
for label_text in label_text_list.iter() {
if label_text.starts_with("CLN") {
- task_log!(worker, "skip cleaning unit '{}'", label_text);
+ info!(tasklog = true, "skip cleaning unit '{}'", label_text);
continue;
}
@@ -903,42 +903,43 @@ pub fn update_inventory(
if !read_all_labels {
if let Some(media_id) = inventory.find_media_by_label_text(&label_text) {
if !catalog || MediaCatalog::exists(TAPE_STATUS_DIR, &media_id.label.uuid) {
- task_log!(worker, "media '{}' already inventoried", label_text);
+ info!(tasklog = true, "media '{}' already inventoried", label_text);
continue;
}
}
}
if let Err(err) = changer.load_media(&label_text) {
- task_warn!(worker, "unable to load media '{}' - {}", label_text, err);
+ warn!(
+ tasklog = true,
+ "unable to load media '{}' - {}", label_text, err
+ );
continue;
}
let mut drive = open_drive(&config, &drive)?;
match drive.read_label() {
Err(err) => {
- task_warn!(
- worker,
- "unable to read label form media '{}' - {}",
- label_text,
- err
+ warn!(
+ tasklog = true,
+ "unable to read label form media '{}' - {}", label_text, err
);
}
Ok((None, _)) => {
- task_log!(worker, "media '{}' is empty", label_text);
+ info!(tasklog = true, "media '{}' is empty", label_text);
}
Ok((Some(media_id), _key_config)) => {
if label_text != media_id.label.label_text {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"label text mismatch ({} != {})",
label_text,
media_id.label.label_text
);
continue;
}
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"inventorize media '{}' with uuid '{}'",
label_text,
media_id.label.uuid
@@ -962,13 +963,12 @@ pub fn update_inventory(
if catalog {
let media_set = inventory.compute_media_set_members(&set.uuid)?;
if let Err(err) = fast_catalog_restore(
- &worker,
&mut drive,
&media_set,
&media_id.label.uuid,
) {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"could not restore catalog for {label_text}: {err}"
);
}
@@ -1026,14 +1026,13 @@ pub fn barcode_label_media(
drive.clone(),
"barcode-label-media",
Some(drive.clone()),
- move |worker, config| barcode_label_media_worker(worker, drive, &config, pool),
+ move |_worker, config| barcode_label_media_worker(drive, &config, pool),
)?;
Ok(upid_str.into())
}
fn barcode_label_media_worker(
- worker: Arc<WorkerTask>,
drive: String,
drive_config: &SectionConfigData,
pool: Option<String>,
@@ -1065,18 +1064,20 @@ fn barcode_label_media_worker(
inventory.reload()?;
if inventory.find_media_by_label_text(&label_text).is_some() {
- task_log!(
- worker,
- "media '{}' already inventoried (already labeled)",
- label_text
+ info!(
+ tasklog = true,
+ "media '{}' already inventoried (already labeled)", label_text
);
continue;
}
- task_log!(worker, "checking/loading media '{}'", label_text);
+ info!(tasklog = true, "checking/loading media '{}'", label_text);
if let Err(err) = changer.load_media(&label_text) {
- task_warn!(worker, "unable to load media '{}' - {}", label_text, err);
+ warn!(
+ tasklog = true,
+ "unable to load media '{}' - {}", label_text, err
+ );
continue;
}
@@ -1085,20 +1086,18 @@ fn barcode_label_media_worker(
match drive.read_next_file() {
Ok(_reader) => {
- task_log!(
- worker,
- "media '{}' is not empty (format it first)",
- label_text
+ info!(
+ tasklog = true,
+ "media '{}' is not empty (format it first)", label_text
);
continue;
}
Err(BlockReadError::EndOfFile) => { /* EOF mark at BOT, assume tape is empty */ }
Err(BlockReadError::EndOfStream) => { /* tape is empty */ }
Err(_err) => {
- task_warn!(
- worker,
- "media '{}' read error (maybe not empty - format it first)",
- label_text
+ warn!(
+ tasklog = true,
+ "media '{}' read error (maybe not empty - format it first)", label_text
);
continue;
}
@@ -1112,7 +1111,7 @@ fn barcode_label_media_worker(
pool: pool.clone(),
};
- write_media_label(worker.clone(), &mut drive, label, pool.clone())?
+ write_media_label(&mut drive, label, pool.clone())?
}
Ok(())
@@ -1271,14 +1270,14 @@ pub fn catalog_media(
let media_id = match drive.read_label()? {
(Some(media_id), key_config) => {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"found media label: {}",
serde_json::to_string_pretty(&serde_json::to_value(&media_id)?)?
);
if key_config.is_some() {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"encryption key config: {}",
serde_json::to_string_pretty(&serde_json::to_value(&key_config)?)?
);
@@ -1292,7 +1291,7 @@ pub fn catalog_media(
let (_media_set_lock, media_set_uuid) = match media_id.media_set_label {
None => {
- task_log!(worker, "media is empty");
+ info!(tasklog = true, "media is empty");
let _pool_lock = if let Some(pool) = media_id.pool() {
lock_media_pool(TAPE_STATUS_DIR, &pool)?
} else {
@@ -1305,7 +1304,7 @@ pub fn catalog_media(
Some(ref set) => {
if set.unassigned() {
// media is empty
- task_log!(worker, "media is empty");
+ info!(tasklog = true, "media is empty");
let _lock = lock_unassigned_media_pool(TAPE_STATUS_DIR)?;
MediaCatalog::destroy(TAPE_STATUS_DIR, &media_id.label.uuid)?;
inventory.store(media_id.clone(), false)?;
@@ -1336,14 +1335,17 @@ pub fn catalog_media(
if !scan {
let media_set = inventory.compute_media_set_members(media_set_uuid)?;
- if fast_catalog_restore(&worker, &mut drive, &media_set, &media_id.label.uuid)? {
+ if fast_catalog_restore(&mut drive, &media_set, &media_id.label.uuid)? {
return Ok(());
}
- task_log!(worker, "no catalog found");
+ info!(tasklog = true, "no catalog found");
}
- task_log!(worker, "scanning entire media to reconstruct catalog");
+ info!(
+ tasklog = true,
+ "scanning entire media to reconstruct catalog"
+ );
drive.rewind()?;
drive.read_label()?; // skip over labels - we already read them above
diff --git a/src/api2/tape/restore.rs b/src/api2/tape/restore.rs
index 7b6c8978..0a138e7b 100644
--- a/src/api2/tape/restore.rs
+++ b/src/api2/tape/restore.rs
@@ -6,6 +6,7 @@ use std::sync::Arc;
use anyhow::{bail, format_err, Error};
use serde_json::Value;
+use tracing::{info, warn};
use proxmox_human_byte::HumanByte;
use proxmox_io::ReadExt;
@@ -13,7 +14,7 @@ use proxmox_router::{Permission, Router, RpcEnvironment, RpcEnvironmentType};
use proxmox_schema::{api, ApiType};
use proxmox_section_config::SectionConfigData;
use proxmox_sys::fs::{replace_file, CreateOptions};
-use proxmox_sys::{task_log, task_warn, WorkerTaskContext};
+use proxmox_sys::WorkerTaskContext;
use proxmox_uuid::Uuid;
use pbs_api_types::{
@@ -399,8 +400,8 @@ pub fn restore(
.and_then(lookup_user_email)
.or_else(|| lookup_user_email(&auth_id.clone().into()));
- task_log!(worker, "Mediaset '{media_set}'");
- task_log!(worker, "Pool: {pool}");
+ info!(tasklog = true, "Mediaset '{media_set}'");
+ info!(tasklog = true, "Pool: {pool}");
let res = if snapshots.is_some() || namespaces {
restore_list_worker(
@@ -430,10 +431,13 @@ pub fn restore(
)
};
if res.is_ok() {
- task_log!(worker, "Restore mediaset '{media_set}' done");
+ info!(tasklog = true, "Restore mediaset '{media_set}' done");
}
if let Err(err) = set_tape_device_state(&drive, "") {
- task_log!(worker, "could not unset drive state for {drive}: {err}");
+ info!(
+ tasklog = true,
+ "could not unset drive state for {drive}: {err}"
+ );
}
res
@@ -484,7 +488,7 @@ fn restore_full_worker(
}
if let Some(fingerprint) = encryption_key_fingerprint {
- task_log!(worker, "Encryption key fingerprint: {fingerprint}");
+ info!(tasklog = true, "Encryption key fingerprint: {fingerprint}");
}
let used_datastores = store_map.used_datastores();
@@ -493,13 +497,9 @@ fn restore_full_worker(
.map(|(t, _)| String::from(t.name()))
.collect::<Vec<String>>()
.join(", ");
- task_log!(worker, "Datastore(s): {datastore_list}",);
- task_log!(worker, "Drive: {drive_name}");
- log_required_tapes(
- &worker,
- &inventory,
- media_id_list.iter().map(|id| &id.label.uuid),
- );
+ info!(tasklog = true, "Datastore(s): {datastore_list}",);
+ info!(tasklog = true, "Drive: {drive_name}");
+ log_required_tapes(&inventory, media_id_list.iter().map(|id| &id.label.uuid));
let mut datastore_locks = Vec::new();
for (target, _) in used_datastores.values() {
@@ -529,7 +529,6 @@ fn restore_full_worker(
#[allow(clippy::too_many_arguments)]
fn check_snapshot_restorable(
- worker: &WorkerTask,
store_map: &DataStoreMap,
store: &str,
snapshot: &str,
@@ -570,7 +569,10 @@ fn check_snapshot_restorable(
auth_id,
Some(restore_owner),
) {
- task_warn!(worker, "cannot restore {store}:{snapshot} to {ns}: '{err}'");
+ warn!(
+ tasklog = true,
+ "cannot restore {store}:{snapshot} to {ns}: '{err}'"
+ );
continue;
}
@@ -578,8 +580,8 @@ fn check_snapshot_restorable(
if let Ok(owner) = datastore.get_owner(&ns, dir.as_ref()) {
if restore_owner != &owner {
// only the owner is allowed to create additional snapshots
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"restore of '{snapshot}' to {ns} failed, owner check failed ({restore_owner} \
!= {owner})",
);
@@ -590,8 +592,8 @@ fn check_snapshot_restorable(
have_some_permissions = true;
if datastore.snapshot_path(&ns, dir).exists() {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"found snapshot {snapshot} on target datastore/namespace, skipping...",
);
continue;
@@ -606,11 +608,7 @@ fn check_snapshot_restorable(
Ok(can_restore_some)
}
-fn log_required_tapes<'a>(
- worker: &WorkerTask,
- inventory: &Inventory,
- list: impl Iterator<Item = &'a Uuid>,
-) {
+fn log_required_tapes<'a>(inventory: &Inventory, list: impl Iterator<Item = &'a Uuid>) {
let mut tape_list = list
.map(|uuid| {
inventory
@@ -622,7 +620,11 @@ fn log_required_tapes<'a>(
})
.collect::<Vec<&str>>();
tape_list.sort_unstable();
- task_log!(worker, "Required media list: {}", tape_list.join(";"));
+ info!(
+ tasklog = true,
+ "Required media list: {}",
+ tape_list.join(";")
+ );
}
#[allow(clippy::too_many_arguments)]
@@ -654,14 +656,13 @@ fn restore_list_worker(
let (ns, dir) = match parse_ns_and_snapshot(snapshot) {
Ok((ns, dir)) if store_map.has_full_mapping(store, &ns) => (ns, dir),
Err(err) => {
- task_warn!(worker, "couldn't parse snapshot {snapshot} - {err}");
+ warn!(tasklog = true, "couldn't parse snapshot {snapshot} - {err}");
continue;
}
_ => continue,
};
let snapshot = print_ns_and_snapshot(&ns, &dir);
match check_snapshot_restorable(
- &worker,
&store_map,
store,
&snapshot,
@@ -675,7 +676,7 @@ fn restore_list_worker(
Ok(true) => restorable.push((store.to_string(), snapshot.to_string(), ns, dir)),
Ok(false) => {}
Err(err) => {
- task_warn!(worker, "{err}");
+ warn!(tasklog = true, "{err}");
skipped.push(format!("{store}:{snapshot}"));
}
}
@@ -693,7 +694,6 @@ fn restore_list_worker(
match parse_ns_and_snapshot(snapshot) {
Ok((ns, dir)) => {
match check_snapshot_restorable(
- &worker,
&store_map,
store,
snapshot,
@@ -709,14 +709,14 @@ fn restore_list_worker(
}
Ok(false) => None,
Err(err) => {
- task_warn!(worker, "{err}");
+ warn!(tasklog = true, "{err}");
skipped.push(format!("{store}:{snapshot}"));
None
}
}
}
Err(err) => {
- task_warn!(worker, "could not restore {store_snapshot}: {err}");
+ warn!(tasklog = true, "could not restore {store_snapshot}: {err}");
skipped.push(store_snapshot);
None
}
@@ -734,8 +734,8 @@ fn restore_list_worker(
let media_id = inventory.lookup_media(media_uuid).unwrap();
(media_id, file_num)
} else {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"did not find snapshot '{store}:{snapshot}' in media set",
);
skipped.push(format!("{store}:{snapshot}"));
@@ -750,26 +750,31 @@ fn restore_list_worker(
.or_insert_with(Vec::new);
file_list.push(file_num);
- task_log!(
- worker,
- "found snapshot {snapshot} on {}: file {file_num}",
- media_id.label.label_text,
+ info!(
+ tasklog = true,
+ "found snapshot {snapshot} on {}: file {file_num}", media_id.label.label_text,
);
}
if snapshot_file_hash.is_empty() {
- task_log!(worker, "nothing to restore, skipping remaining phases...");
+ info!(
+ tasklog = true,
+ "nothing to restore, skipping remaining phases..."
+ );
if !skipped.is_empty() {
- task_log!(worker, "skipped the following snapshots:");
+ info!(tasklog = true, "skipped the following snapshots:");
for snap in skipped {
- task_log!(worker, " {snap}");
+ info!(tasklog = true, " {snap}");
}
}
return Ok(());
}
- task_log!(worker, "Phase 1: temporarily restore snapshots to temp dir");
- log_required_tapes(&worker, &inventory, snapshot_file_hash.keys());
+ info!(
+ tasklog = true,
+ "Phase 1: temporarily restore snapshots to temp dir"
+ );
+ log_required_tapes(&inventory, snapshot_file_hash.keys());
let mut datastore_chunk_map: HashMap<String, HashSet<[u8; 32]>> = HashMap::new();
let mut tmp_paths = Vec::new();
for (media_uuid, file_list) in snapshot_file_hash.iter_mut() {
@@ -822,10 +827,13 @@ fn restore_list_worker(
drop(catalog);
if !media_file_chunk_map.is_empty() {
- task_log!(worker, "Phase 2: restore chunks to datastores");
- log_required_tapes(&worker, &inventory, media_file_chunk_map.keys());
+ info!(tasklog = true, "Phase 2: restore chunks to datastores");
+ log_required_tapes(&inventory, media_file_chunk_map.keys());
} else {
- task_log!(worker, "All chunks are already present, skip phase 2...");
+ info!(
+ tasklog = true,
+ "All chunks are already present, skip phase 2..."
+ );
}
for (media_uuid, file_chunk_map) in media_file_chunk_map.iter_mut() {
@@ -840,8 +848,8 @@ fn restore_list_worker(
restore_file_chunk_map(worker.clone(), &mut drive, &store_map, file_chunk_map)?;
}
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"Phase 3: copy snapshots from temp dir to datastores"
);
let mut errors = false;
@@ -900,18 +908,18 @@ fn restore_list_worker(
Ok(())
}) {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"could not restore {source_datastore}:{snapshot}: '{err}'"
);
skipped.push(format!("{source_datastore}:{snapshot}"));
}
}
- task_log!(worker, "Restore snapshot '{}' done", snapshot);
+ info!(tasklog = true, "Restore snapshot '{}' done", snapshot);
Ok::<_, Error>(())
}) {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"could not copy {source_datastore}:{snapshot}: {err}"
);
errors = true;
@@ -923,7 +931,10 @@ fn restore_list_worker(
std::fs::remove_dir_all(&tmp_path)
.map_err(|err| format_err!("remove_dir_all failed - {err}"))
}) {
- task_warn!(worker, "could not clean up temp dir {tmp_path:?}: {err}");
+ warn!(
+ tasklog = true,
+ "could not clean up temp dir {tmp_path:?}: {err}"
+ );
errors = true;
};
}
@@ -932,17 +943,20 @@ fn restore_list_worker(
bail!("errors during copy occurred");
}
if !skipped.is_empty() {
- task_log!(worker, "(partially) skipped the following snapshots:");
+ info!(
+ tasklog = true,
+ "(partially) skipped the following snapshots:"
+ );
for snap in skipped {
- task_log!(worker, " {snap}");
+ info!(tasklog = true, " {snap}");
}
}
Ok(())
});
if res.is_err() {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"Error during restore, partially restored snapshots will NOT be cleaned up"
);
}
@@ -952,7 +966,7 @@ fn restore_list_worker(
match std::fs::remove_dir_all(tmp_path) {
Ok(()) => {}
Err(err) if err.kind() == std::io::ErrorKind::NotFound => {}
- Err(err) => task_warn!(worker, "error cleaning up: {}", err),
+ Err(err) => warn!(tasklog = true, "error cleaning up: {}", err),
}
}
@@ -1030,7 +1044,7 @@ fn restore_snapshots_to_tmpdir(
);
}
let encrypt_fingerprint = set.encryption_key_fingerprint.clone().map(|fp| {
- task_log!(worker, "Encryption key fingerprint: {}", fp);
+ info!(tasklog = true, "Encryption key fingerprint: {}", fp);
(fp, set.uuid.clone())
});
@@ -1041,13 +1055,13 @@ fn restore_snapshots_to_tmpdir(
for file_num in file_list {
let current_file_number = drive.current_file_number()?;
if current_file_number != *file_num {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"was at file {current_file_number}, moving to {file_num}"
);
drive.move_to_file(*file_num)?;
let current_file_number = drive.current_file_number()?;
- task_log!(worker, "now at file {}", current_file_number);
+ info!(tasklog = true, "now at file {}", current_file_number);
}
let mut reader = drive.read_next_file()?;
@@ -1069,8 +1083,8 @@ fn restore_snapshots_to_tmpdir(
let source_datastore = archive_header.store;
let snapshot = archive_header.snapshot;
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"File {file_num}: snapshot archive {source_datastore}:{snapshot}",
);
@@ -1079,8 +1093,8 @@ fn restore_snapshots_to_tmpdir(
let target_datastore = match store_map.target_store(&source_datastore) {
Some(datastore) => datastore,
None => {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"could not find target datastore for {source_datastore}:{snapshot}",
);
continue;
@@ -1136,10 +1150,13 @@ fn restore_file_chunk_map(
for (nr, chunk_map) in file_chunk_map.iter_mut() {
let current_file_number = drive.current_file_number()?;
if current_file_number != *nr {
- task_log!(worker, "was at file {current_file_number}, moving to {nr}");
+ info!(
+ tasklog = true,
+ "was at file {current_file_number}, moving to {nr}"
+ );
drive.move_to_file(*nr)?;
let current_file_number = drive.current_file_number()?;
- task_log!(worker, "now at file {}", current_file_number);
+ info!(tasklog = true, "now at file {}", current_file_number);
}
let mut reader = drive.read_next_file()?;
let header: MediaContentHeader = unsafe { reader.read_le_value()? };
@@ -1156,8 +1173,8 @@ fn restore_file_chunk_map(
let source_datastore = archive_header.store;
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"File {nr}: chunk archive for datastore '{source_datastore}'",
);
@@ -1171,7 +1188,7 @@ fn restore_file_chunk_map(
datastore.clone(),
chunk_map,
)?;
- task_log!(worker, "restored {count} chunks");
+ info!(tasklog = true, "restored {count} chunks");
}
_ => bail!("unexpected content magic {:?}", header.content_magic),
}
@@ -1231,8 +1248,8 @@ fn restore_partial_chunk_archive<'a>(
let elapsed = start_time.elapsed()?.as_secs_f64();
let bytes = bytes.load(std::sync::atomic::Ordering::SeqCst) as f64;
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"restored {} ({:.2}/s)",
HumanByte::new_decimal(bytes),
HumanByte::new_decimal(bytes / elapsed),
@@ -1317,15 +1334,17 @@ pub fn restore_media(
let current_file_number = drive.current_file_number()?;
let reader = match drive.read_next_file() {
Err(BlockReadError::EndOfFile) => {
- task_log!(
- worker,
- "skip unexpected filemark at pos {}",
- current_file_number
+ info!(
+ tasklog = true,
+ "skip unexpected filemark at pos {}", current_file_number
);
continue;
}
Err(BlockReadError::EndOfStream) => {
- task_log!(worker, "detected EOT after {} files", current_file_number);
+ info!(
+ tasklog = true,
+ "detected EOT after {} files", current_file_number
+ );
break;
}
Err(BlockReadError::Error(err)) => {
@@ -1389,12 +1408,9 @@ fn restore_archive<'a>(
let datastore_name = archive_header.store;
let snapshot = archive_header.snapshot;
- task_log!(
- worker,
- "File {}: snapshot archive {}:{}",
- current_file_number,
- datastore_name,
- snapshot
+ info!(
+ tasklog = true,
+ "File {}: snapshot archive {}:{}", current_file_number, datastore_name, snapshot
);
let (backup_ns, backup_dir) = parse_ns_and_snapshot(&snapshot)?;
@@ -1429,7 +1445,7 @@ fn restore_archive<'a>(
path.push(rel_path);
if is_new {
- task_log!(worker, "restore snapshot {}", backup_dir);
+ info!(tasklog = true, "restore snapshot {}", backup_dir);
match restore_snapshot_archive(worker.clone(), reader, &path) {
Err(err) => {
@@ -1438,7 +1454,7 @@ fn restore_archive<'a>(
}
Ok(false) => {
std::fs::remove_dir_all(&path)?;
- task_log!(worker, "skip incomplete snapshot {}", backup_dir);
+ info!(tasklog = true, "skip incomplete snapshot {}", backup_dir);
}
Ok(true) => {
catalog.register_snapshot(
@@ -1454,7 +1470,7 @@ fn restore_archive<'a>(
return Ok(());
}
} else {
- task_log!(worker, "skipping...");
+ info!(tasklog = true, "skipping...");
}
}
@@ -1481,11 +1497,9 @@ fn restore_archive<'a>(
let source_datastore = archive_header.store;
- task_log!(
- worker,
- "File {}: chunk archive for datastore '{}'",
- current_file_number,
- source_datastore
+ info!(
+ tasklog = true,
+ "File {}: chunk archive for datastore '{}'", current_file_number, source_datastore
);
let datastore = target
.as_ref()
@@ -1521,12 +1535,12 @@ fn restore_archive<'a>(
&source_datastore,
&chunks[..],
)?;
- task_log!(worker, "register {} chunks", chunks.len());
+ info!(tasklog = true, "register {} chunks", chunks.len());
catalog.commit_if_large()?;
}
return Ok(());
} else if target.is_some() {
- task_log!(worker, "skipping...");
+ info!(tasklog = true, "skipping...");
}
reader.skip_data()?; // read all data
@@ -1537,11 +1551,9 @@ fn restore_archive<'a>(
let archive_header: CatalogArchiveHeader = serde_json::from_slice(&header_data)
.map_err(|err| format_err!("unable to parse catalog archive header - {}", err))?;
- task_log!(
- worker,
- "File {}: skip catalog '{}'",
- current_file_number,
- archive_header.uuid
+ info!(
+ tasklog = true,
+ "File {}: skip catalog '{}'", current_file_number, archive_header.uuid
);
reader.skip_data()?; // read all data
@@ -1576,7 +1588,7 @@ fn scan_chunk_archive<'a>(
// check if this is an aborted stream without end marker
if let Ok(false) = reader.has_end_marker() {
- task_log!(worker, "missing stream end marker");
+ info!(tasklog = true, "missing stream end marker");
return Ok(None);
}
@@ -1588,7 +1600,7 @@ fn scan_chunk_archive<'a>(
worker.check_abort()?;
if verbose {
- task_log!(worker, "Found chunk: {}", hex::encode(digest));
+ info!(tasklog = true, "Found chunk: {}", hex::encode(digest));
}
chunks.push(digest);
@@ -1612,8 +1624,6 @@ fn restore_chunk_archive<'a>(
let bytes = Arc::new(std::sync::atomic::AtomicU64::new(0));
let bytes2 = bytes.clone();
- let worker2 = worker.clone();
-
let writer_pool = ParallelHandler::new(
"tape restore chunk writer",
4,
@@ -1621,7 +1631,7 @@ fn restore_chunk_archive<'a>(
let chunk_exists = datastore.cond_touch_chunk(&digest, false)?;
if !chunk_exists {
if verbose {
- task_log!(worker2, "Insert chunk: {}", hex::encode(digest));
+ info!(tasklog = true, "Insert chunk: {}", hex::encode(digest));
}
bytes2.fetch_add(chunk.raw_size(), std::sync::atomic::Ordering::SeqCst);
// println!("verify and write {}", hex::encode(&digest));
@@ -1632,7 +1642,11 @@ fn restore_chunk_archive<'a>(
datastore.insert_chunk(&chunk, &digest)?;
} else if verbose {
- task_log!(worker2, "Found existing chunk: {}", hex::encode(digest));
+ info!(
+ tasklog = true,
+ "Found existing chunk: {}",
+ hex::encode(digest)
+ );
}
Ok(())
},
@@ -1654,7 +1668,7 @@ fn restore_chunk_archive<'a>(
// check if this is an aborted stream without end marker
if let Ok(false) = reader.has_end_marker() {
- task_log!(worker, "missing stream end marker");
+ info!(tasklog = true, "missing stream end marker");
return Ok(None);
}
@@ -1678,8 +1692,8 @@ fn restore_chunk_archive<'a>(
let elapsed = start_time.elapsed()?.as_secs_f64();
let bytes = bytes.load(std::sync::atomic::Ordering::SeqCst) as f64;
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"restored {} ({:.2}/s)",
HumanByte::new_decimal(bytes),
HumanByte::new_decimal(bytes / elapsed),
@@ -1830,7 +1844,6 @@ fn try_restore_snapshot_archive<R: pxar::decoder::SeqRead>(
/// Try to restore media catalogs (form catalog_archives)
pub fn fast_catalog_restore(
- worker: &WorkerTask,
drive: &mut Box<dyn TapeDriver>,
media_set: &MediaSet,
uuid: &Uuid, // current media Uuid
@@ -1851,14 +1864,17 @@ pub fn fast_catalog_restore(
// limit reader scope
let mut reader = match drive.read_next_file() {
Err(BlockReadError::EndOfFile) => {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"skip unexpected filemark at pos {current_file_number}"
);
continue;
}
Err(BlockReadError::EndOfStream) => {
- task_log!(worker, "detected EOT after {current_file_number} files");
+ info!(
+ tasklog = true,
+ "detected EOT after {current_file_number} files"
+ );
break;
}
Err(BlockReadError::Error(err)) => {
@@ -1875,7 +1891,10 @@ pub fn fast_catalog_restore(
if header.content_magic == PROXMOX_BACKUP_CATALOG_ARCHIVE_MAGIC_1_0
|| header.content_magic == PROXMOX_BACKUP_CATALOG_ARCHIVE_MAGIC_1_1
{
- task_log!(worker, "found catalog at pos {}", current_file_number);
+ info!(
+ tasklog = true,
+ "found catalog at pos {}", current_file_number
+ );
let header_data = reader.read_exact_allocated(header.size as usize)?;
@@ -1885,10 +1904,9 @@ pub fn fast_catalog_restore(
})?;
if &archive_header.media_set_uuid != media_set.uuid() {
- task_log!(
- worker,
- "skipping unrelated catalog at pos {}",
- current_file_number
+ info!(
+ tasklog = true,
+ "skipping unrelated catalog at pos {}", current_file_number
);
reader.skip_data()?; // read all data
continue;
@@ -1902,10 +1920,9 @@ pub fn fast_catalog_restore(
});
if !wanted {
- task_log!(
- worker,
- "skip catalog because media '{}' not inventarized",
- catalog_uuid
+ info!(
+ tasklog = true,
+ "skip catalog because media '{}' not inventarized", catalog_uuid
);
reader.skip_data()?; // read all data
continue;
@@ -1916,10 +1933,9 @@ pub fn fast_catalog_restore(
} else {
// only restore if catalog does not exist
if MediaCatalog::exists(TAPE_STATUS_DIR, catalog_uuid) {
- task_log!(
- worker,
- "catalog for media '{}' already exists",
- catalog_uuid
+ info!(
+ tasklog = true,
+ "catalog for media '{}' already exists", catalog_uuid
);
reader.skip_data()?; // read all data
continue;
@@ -1936,18 +1952,16 @@ pub fn fast_catalog_restore(
match MediaCatalog::parse_catalog_header(&mut file)? {
(true, Some(media_uuid), Some(media_set_uuid)) => {
if &media_uuid != catalog_uuid {
- task_log!(
- worker,
- "catalog uuid mismatch at pos {}",
- current_file_number
+ info!(
+ tasklog = true,
+ "catalog uuid mismatch at pos {}", current_file_number
);
continue;
}
if media_set_uuid != archive_header.media_set_uuid {
- task_log!(
- worker,
- "catalog media_set mismatch at pos {}",
- current_file_number
+ info!(
+ tasklog = true,
+ "catalog media_set mismatch at pos {}", current_file_number
);
continue;
}
@@ -1959,18 +1973,17 @@ pub fn fast_catalog_restore(
)?;
if catalog_uuid == uuid {
- task_log!(worker, "successfully restored catalog");
+ info!(tasklog = true, "successfully restored catalog");
found_catalog = true
} else {
- task_log!(
- worker,
- "successfully restored related catalog {}",
- media_uuid
+ info!(
+ tasklog = true,
+ "successfully restored related catalog {}", media_uuid
);
}
}
_ => {
- task_warn!(worker, "got incomplete catalog header - skip file");
+ warn!(tasklog = true, "got incomplete catalog header - skip file");
continue;
}
}
@@ -1984,7 +1997,10 @@ pub fn fast_catalog_restore(
}
moved_to_eom = true;
- task_log!(worker, "searching for catalog at EOT (moving to EOT)");
+ info!(
+ tasklog = true,
+ "searching for catalog at EOT (moving to EOT)"
+ );
drive.move_to_last_file()?;
let new_file_number = drive.current_file_number()?;
diff --git a/src/backup/verify.rs b/src/backup/verify.rs
index c972e532..77d5ee8b 100644
--- a/src/backup/verify.rs
+++ b/src/backup/verify.rs
@@ -5,8 +5,9 @@ use std::sync::{Arc, Mutex};
use std::time::Instant;
use anyhow::{bail, format_err, Error};
+use tracing::info;
-use proxmox_sys::{task_log, WorkerTaskContext};
+use proxmox_sys::WorkerTaskContext;
use pbs_api_types::{
print_ns_and_snapshot, print_store_and_ns, Authid, BackupNamespace, BackupType, CryptMode,
@@ -69,11 +70,7 @@ fn verify_blob(backup_dir: &BackupDir, info: &FileInfo) -> Result<(), Error> {
}
}
-fn rename_corrupted_chunk(
- datastore: Arc<DataStore>,
- digest: &[u8; 32],
- worker: &dyn WorkerTaskContext,
-) {
+fn rename_corrupted_chunk(datastore: Arc<DataStore>, digest: &[u8; 32]) {
let (path, digest_str) = datastore.chunk_path(digest);
let mut counter = 0;
@@ -89,16 +86,14 @@ fn rename_corrupted_chunk(
match std::fs::rename(&path, &new_path) {
Ok(_) => {
- task_log!(worker, "corrupted chunk renamed to {:?}", &new_path);
+ info!(tasklog = true, "corrupted chunk renamed to {:?}", &new_path);
}
Err(err) => {
match err.kind() {
std::io::ErrorKind::NotFound => { /* ignored */ }
- _ => task_log!(
- worker,
- "could not rename corrupted chunk {:?} - {}",
- &path,
- err
+ _ => info!(
+ tasklog = true,
+ "could not rename corrupted chunk {:?} - {}", &path, err
),
}
}
@@ -117,7 +112,6 @@ fn verify_index_chunks(
let mut read_bytes = 0;
let mut decoded_bytes = 0;
- let worker2 = Arc::clone(&verify_worker.worker);
let datastore2 = Arc::clone(&verify_worker.datastore);
let corrupt_chunks2 = Arc::clone(&verify_worker.corrupt_chunks);
let verified_chunks2 = Arc::clone(&verify_worker.verified_chunks);
@@ -130,7 +124,10 @@ fn verify_index_chunks(
let chunk_crypt_mode = match chunk.crypt_mode() {
Err(err) => {
corrupt_chunks2.lock().unwrap().insert(digest);
- task_log!(worker2, "can't verify chunk, unknown CryptMode - {}", err);
+ info!(
+ tasklog = true,
+ "can't verify chunk, unknown CryptMode - {}", err
+ );
errors2.fetch_add(1, Ordering::SeqCst);
return Ok(());
}
@@ -138,8 +135,8 @@ fn verify_index_chunks(
};
if chunk_crypt_mode != crypt_mode {
- task_log!(
- worker2,
+ info!(
+ tasklog = true,
"chunk CryptMode {:?} does not match index CryptMode {:?}",
chunk_crypt_mode,
crypt_mode
@@ -149,9 +146,9 @@ fn verify_index_chunks(
if let Err(err) = chunk.verify_unencrypted(size as usize, &digest) {
corrupt_chunks2.lock().unwrap().insert(digest);
- task_log!(worker2, "{}", err);
+ info!(tasklog = true, "{}", err);
errors2.fetch_add(1, Ordering::SeqCst);
- rename_corrupted_chunk(datastore2.clone(), &digest, &worker2);
+ rename_corrupted_chunk(datastore2.clone(), &digest);
} else {
verified_chunks2.lock().unwrap().insert(digest);
}
@@ -175,11 +172,7 @@ fn verify_index_chunks(
.contains(digest)
{
let digest_str = hex::encode(digest);
- task_log!(
- verify_worker.worker,
- "chunk {} was marked as corrupt",
- digest_str
- );
+ info!(tasklog = true, "chunk {} was marked as corrupt", digest_str);
errors.fetch_add(1, Ordering::SeqCst);
true
} else {
@@ -218,17 +211,9 @@ fn verify_index_chunks(
.lock()
.unwrap()
.insert(info.digest);
- task_log!(
- verify_worker.worker,
- "can't verify chunk, load failed - {}",
- err
- );
+ info!(tasklog = true, "can't verify chunk, load failed - {}", err);
errors.fetch_add(1, Ordering::SeqCst);
- rename_corrupted_chunk(
- verify_worker.datastore.clone(),
- &info.digest,
- &verify_worker.worker,
- );
+ rename_corrupted_chunk(verify_worker.datastore.clone(), &info.digest);
}
Ok(chunk) => {
let size = info.size();
@@ -251,8 +236,8 @@ fn verify_index_chunks(
let error_count = errors.load(Ordering::SeqCst);
- task_log!(
- verify_worker.worker,
+ info!(
+ tasklog = true,
" verified {:.2}/{:.2} MiB in {:.2} seconds, speed {:.2}/{:.2} MiB/s ({} errors)",
read_bytes_mib,
decoded_bytes_mib,
@@ -329,8 +314,8 @@ pub fn verify_backup_dir(
filter: Option<&dyn Fn(&BackupManifest) -> bool>,
) -> Result<bool, Error> {
if !backup_dir.full_path().exists() {
- task_log!(
- verify_worker.worker,
+ info!(
+ tasklog = true,
"SKIPPED: verify {}:{} - snapshot does not exist (anymore).",
verify_worker.datastore.name(),
backup_dir.dir(),
@@ -348,8 +333,8 @@ pub fn verify_backup_dir(
verify_backup_dir_with_lock(verify_worker, backup_dir, upid, filter, snap_lock)
}
Err(err) => {
- task_log!(
- verify_worker.worker,
+ info!(
+ tasklog = true,
"SKIPPED: verify {}:{} - could not acquire snapshot lock: {}",
verify_worker.datastore.name(),
backup_dir.dir(),
@@ -371,8 +356,8 @@ pub fn verify_backup_dir_with_lock(
let manifest = match backup_dir.load_manifest() {
Ok((manifest, _)) => manifest,
Err(err) => {
- task_log!(
- verify_worker.worker,
+ info!(
+ tasklog = true,
"verify {}:{} - manifest load error: {}",
verify_worker.datastore.name(),
backup_dir.dir(),
@@ -384,8 +369,8 @@ pub fn verify_backup_dir_with_lock(
if let Some(filter) = filter {
if !filter(&manifest) {
- task_log!(
- verify_worker.worker,
+ info!(
+ tasklog = true,
"SKIPPED: verify {}:{} (recently verified)",
verify_worker.datastore.name(),
backup_dir.dir(),
@@ -394,8 +379,8 @@ pub fn verify_backup_dir_with_lock(
}
}
- task_log!(
- verify_worker.worker,
+ info!(
+ tasklog = true,
"verify {}:{}",
verify_worker.datastore.name(),
backup_dir.dir()
@@ -406,7 +391,7 @@ pub fn verify_backup_dir_with_lock(
let mut verify_result = VerifyState::Ok;
for info in manifest.files() {
let result = proxmox_lang::try_block!({
- task_log!(verify_worker.worker, " check {}", info.filename);
+ info!(tasklog = true, " check {}", info.filename);
match archive_type(&info.filename)? {
ArchiveType::FixedIndex => verify_fixed_index(verify_worker, backup_dir, info),
ArchiveType::DynamicIndex => verify_dynamic_index(verify_worker, backup_dir, info),
@@ -418,8 +403,8 @@ pub fn verify_backup_dir_with_lock(
verify_worker.worker.fail_on_shutdown()?;
if let Err(err) = result {
- task_log!(
- verify_worker.worker,
+ info!(
+ tasklog = true,
"verify {}:{}/{} failed: {}",
verify_worker.datastore.name(),
backup_dir.dir(),
@@ -463,8 +448,8 @@ pub fn verify_backup_group(
let mut list = match group.list_backups() {
Ok(list) => list,
Err(err) => {
- task_log!(
- verify_worker.worker,
+ info!(
+ tasklog = true,
"verify {}, group {} - unable to list backups: {}",
print_store_and_ns(verify_worker.datastore.name(), group.backup_ns()),
group.group(),
@@ -475,8 +460,8 @@ pub fn verify_backup_group(
};
let snapshot_count = list.len();
- task_log!(
- verify_worker.worker,
+ info!(
+ tasklog = true,
"verify group {}:{} ({} snapshots)",
verify_worker.datastore.name(),
group.group(),
@@ -494,9 +479,8 @@ pub fn verify_backup_group(
));
}
progress.done_snapshots = pos as u64 + 1;
- task_log!(verify_worker.worker, "percentage done: {}", progress);
+ info!(tasklog = true, "percentage done: {}", progress);
}
-
Ok(errors)
}
@@ -516,16 +500,15 @@ pub fn verify_all_backups(
filter: Option<&dyn Fn(&BackupManifest) -> bool>,
) -> Result<Vec<String>, Error> {
let mut errors = Vec::new();
- let worker = Arc::clone(&verify_worker.worker);
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"verify datastore {}",
verify_worker.datastore.name()
);
let owner_filtered = if let Some(owner) = &owner {
- task_log!(worker, "limiting to backups owned by {}", owner);
+ info!(tasklog = true, "limiting to backups owned by {}", owner);
true
} else {
false
@@ -553,7 +536,10 @@ pub fn verify_all_backups(
}
Err(err) => {
// we don't filter by owner, but we want to log the error
- task_log!(worker, "error on iterating groups in ns '{ns}' - {err}");
+ info!(
+ tasklog = true,
+ "error on iterating groups in ns '{ns}' - {err}"
+ );
errors.push(err.to_string());
None
}
@@ -563,7 +549,7 @@ pub fn verify_all_backups(
})
.collect::<Vec<BackupGroup>>(),
Err(err) => {
- task_log!(worker, "unable to list backups: {}", err,);
+ info!(tasklog = true, "unable to list backups: {}", err,);
return Ok(errors);
}
};
@@ -571,7 +557,7 @@ pub fn verify_all_backups(
list.sort_unstable_by(|a, b| a.group().cmp(b.group()));
let group_count = list.len();
- task_log!(worker, "found {} groups", group_count);
+ info!(tasklog = true, "found {} groups", group_count);
let mut progress = StoreProgress::new(group_count as u64);
diff --git a/src/bin/proxmox-backup-api.rs b/src/bin/proxmox-backup-api.rs
index c6c24449..993d1d98 100644
--- a/src/bin/proxmox-backup-api.rs
+++ b/src/bin/proxmox-backup-api.rs
@@ -7,6 +7,7 @@ use http::Response;
use hyper::{Body, StatusCode};
use proxmox_lang::try_block;
+use proxmox_log::init_logger;
use proxmox_router::RpcEnvironmentType;
use proxmox_sys::fs::CreateOptions;
@@ -15,6 +16,7 @@ use proxmox_rest_server::{daemon, ApiConfig, RestServer};
use proxmox_backup::auth_helpers::*;
use proxmox_backup::config;
use proxmox_backup::server::auth::check_pbs_auth;
+use tracing_subscriber::filter::LevelFilter;
fn main() {
pbs_tools::setup_libc_malloc_opts();
@@ -40,13 +42,7 @@ fn get_index() -> Pin<Box<dyn Future<Output = Response<Body>> + Send>> {
}
async fn run() -> Result<(), Error> {
- if let Err(err) = syslog::init(
- syslog::Facility::LOG_DAEMON,
- log::LevelFilter::Info,
- Some("proxmox-backup-api"),
- ) {
- bail!("unable to inititialize syslog - {}", err);
- }
+ init_logger("PBS_LOG", LevelFilter::INFO, "proxmox-backup-api")?;
config::create_configdir()?;
diff --git a/src/bin/proxmox-backup-proxy.rs b/src/bin/proxmox-backup-proxy.rs
index f38a02bd..4fed24fb 100644
--- a/src/bin/proxmox-backup-proxy.rs
+++ b/src/bin/proxmox-backup-proxy.rs
@@ -7,6 +7,9 @@ use http::request::Parts;
use http::Response;
use hyper::header;
use hyper::{Body, StatusCode};
+use proxmox_log::init_logger;
+use tracing::{info, warn};
+use tracing_subscriber::filter::LevelFilter;
use url::form_urlencoded;
use openssl::ssl::SslAcceptor;
@@ -18,7 +21,6 @@ use proxmox_router::{RpcEnvironment, RpcEnvironmentType};
use proxmox_sys::fs::{CreateOptions, FileSystemInformation};
use proxmox_sys::linux::procfs::{Loadavg, ProcFsMemInfo, ProcFsNetDev, ProcFsStat};
use proxmox_sys::logrotate::LogRotate;
-use proxmox_sys::{task_log, task_warn};
use pbs_datastore::DataStore;
@@ -181,21 +183,7 @@ async fn get_index_future(env: RestEnvironment, parts: Parts) -> Response<Body>
}
async fn run() -> Result<(), Error> {
- // Note: To debug early connection error use
- // PROXMOX_DEBUG=1 ./target/release/proxmox-backup-proxy
- let debug = std::env::var("PROXMOX_DEBUG").is_ok();
-
- if let Err(err) = syslog::init(
- syslog::Facility::LOG_DAEMON,
- if debug {
- log::LevelFilter::Debug
- } else {
- log::LevelFilter::Info
- },
- Some("proxmox-backup-proxy"),
- ) {
- bail!("unable to inititialize syslog - {err}");
- }
+ init_logger("PBS_LOG", LevelFilter::INFO, "proxmox-backup-proxy")?;
proxmox_backup::auth_helpers::setup_auth_context(false);
@@ -289,7 +277,7 @@ async fn run() -> Result<(), Error> {
})?;
let connections = proxmox_rest_server::connection::AcceptBuilder::with_acceptor(acceptor)
- .debug(debug)
+ .debug(tracing::enabled!(tracing::Level::DEBUG))
.rate_limiter_lookup(Arc::new(lookup_rate_limiter))
.tcp_keepalive_time(PROXMOX_BACKUP_TCP_KEEPALIVE_TIME);
let server = daemon::create_daemon(
@@ -714,7 +702,7 @@ async fn schedule_task_log_rotate() {
false,
move |worker| {
job.start(&worker.upid().to_string())?;
- task_log!(worker, "starting task log rotation");
+ info!(tasklog = true, "starting task log rotation");
let result = try_block!({
let max_size = 512 * 1024 - 1; // an entry has ~ 100b, so > 5000 entries/file
@@ -739,9 +727,9 @@ async fn schedule_task_log_rotate() {
)?;
if has_rotated {
- task_log!(worker, "task log archive was rotated");
+ info!(tasklog = true, "task log archive was rotated");
} else {
- task_log!(worker, "task log archive was not rotated");
+ info!(tasklog = true, "task log archive was not rotated");
}
let max_size = 32 * 1024 * 1024 - 1;
@@ -757,9 +745,9 @@ async fn schedule_task_log_rotate() {
if logrotate.rotate(max_size)? {
println!("rotated access log, telling daemons to re-open log file");
proxmox_async::runtime::block_on(command_reopen_access_logfiles())?;
- task_log!(worker, "API access log was rotated");
+ info!(tasklog = true, "API access log was rotated");
} else {
- task_log!(worker, "API access log was not rotated");
+ info!(tasklog = true, "API access log was not rotated");
}
let mut logrotate = LogRotate::new(
@@ -772,15 +760,18 @@ async fn schedule_task_log_rotate() {
if logrotate.rotate(max_size)? {
println!("rotated auth log, telling daemons to re-open log file");
proxmox_async::runtime::block_on(command_reopen_auth_logfiles())?;
- task_log!(worker, "API authentication log was rotated");
+ info!(tasklog = true, "API authentication log was rotated");
} else {
- task_log!(worker, "API authentication log was not rotated");
+ info!(tasklog = true, "API authentication log was not rotated");
}
if has_rotated {
- task_log!(worker, "cleaning up old task logs");
- if let Err(err) = cleanup_old_tasks(&worker, true) {
- task_warn!(worker, "could not completely cleanup old tasks: {err}");
+ info!(tasklog = true, "cleaning up old task logs");
+ if let Err(err) = cleanup_old_tasks(true) {
+ warn!(
+ tasklog = true,
+ "could not completely cleanup old tasks: {err}"
+ );
}
}
diff --git a/src/server/gc_job.rs b/src/server/gc_job.rs
index 41375d72..4a79a92d 100644
--- a/src/server/gc_job.rs
+++ b/src/server/gc_job.rs
@@ -1,7 +1,7 @@
use anyhow::Error;
use std::sync::Arc;
-use proxmox_sys::task_log;
+use tracing::info;
use pbs_api_types::Authid;
use pbs_datastore::DataStore;
@@ -30,9 +30,12 @@ pub fn do_garbage_collection_job(
move |worker| {
job.start(&worker.upid().to_string())?;
- task_log!(worker, "starting garbage collection on store {store}");
+ info!(
+ tasklog = true,
+ "starting garbage collection on store {store}"
+ );
if let Some(event_str) = schedule {
- task_log!(worker, "task triggered by schedule '{event_str}'");
+ info!(tasklog = true, "task triggered by schedule '{event_str}'");
}
let result = datastore.garbage_collection(&*worker, worker.upid());
diff --git a/src/server/prune_job.rs b/src/server/prune_job.rs
index 2de34973..ae85886e 100644
--- a/src/server/prune_job.rs
+++ b/src/server/prune_job.rs
@@ -1,8 +1,7 @@
use std::sync::Arc;
use anyhow::Error;
-
-use proxmox_sys::{task_log, task_warn};
+use tracing::{info, warn};
use pbs_api_types::{
print_store_and_ns, Authid, KeepOptions, Operation, PruneJobOptions, MAX_NAMESPACE_DEPTH,
@@ -16,7 +15,6 @@ use crate::backup::ListAccessibleBackupGroups;
use crate::server::jobstate::Job;
pub fn prune_datastore(
- worker: Arc<WorkerTask>,
auth_id: Authid,
prune_options: PruneJobOptions,
datastore: Arc<DataStore>,
@@ -31,19 +29,22 @@ pub fn prune_datastore(
};
let ns = prune_options.ns.clone().unwrap_or_default();
let store_ns = print_store_and_ns(store, &ns);
- task_log!(worker, "Starting datastore prune on {store_ns}, {depth}");
+ info!(
+ tasklog = true,
+ "Starting datastore prune on {store_ns}, {depth}"
+ );
if dry_run {
- task_log!(worker, "(dry test run)");
+ info!(tasklog = true, "(dry test run)");
}
let keep_all = !prune_options.keeps_something();
if keep_all {
- task_log!(worker, "No prune selection - keeping all files.");
+ info!(tasklog = true, "No prune selection - keeping all files.");
} else {
let rendered_options = cli_prune_options_string(&prune_options);
- task_log!(worker, "retention options: {rendered_options}");
+ info!(tasklog = true, "retention options: {rendered_options}");
}
for group in ListAccessibleBackupGroups::new_with_privs(
@@ -61,8 +62,8 @@ pub fn prune_datastore(
let mut prune_info = compute_prune_info(list, &prune_options.keep)?;
prune_info.reverse(); // delete older snapshots first
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"Pruning group {ns}:\"{}/{}\"",
group.backup_type(),
group.backup_id()
@@ -70,8 +71,8 @@ pub fn prune_datastore(
for (info, mark) in prune_info {
let keep = keep_all || mark.keep();
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"{}{} {}/{}/{}",
if dry_run { "would " } else { "" },
mark,
@@ -82,7 +83,7 @@ pub fn prune_datastore(
if !keep && !dry_run {
if let Err(err) = datastore.remove_backup_dir(ns, info.backup_dir.as_ref(), false) {
let path = info.backup_dir.relative_path();
- task_warn!(worker, "failed to remove dir {path:?}: {err}");
+ warn!(tasklog = true, "failed to remove dir {path:?}: {err}");
}
}
}
@@ -150,13 +151,13 @@ pub fn do_prune_job(
move |worker| {
job.start(&worker.upid().to_string())?;
- task_log!(worker, "prune job '{}'", job.jobname());
+ info!(tasklog = true, "prune job '{}'", job.jobname());
if let Some(event_str) = schedule {
- task_log!(worker, "task triggered by schedule '{event_str}'");
+ info!(tasklog = true, "task triggered by schedule '{event_str}'");
}
- let result = prune_datastore(worker.clone(), auth_id, prune_options, datastore, false);
+ let result = prune_datastore(auth_id, prune_options, datastore, false);
let status = worker.create_state(&result);
diff --git a/src/server/pull.rs b/src/server/pull.rs
index a973a10e..cc9229b1 100644
--- a/src/server/pull.rs
+++ b/src/server/pull.rs
@@ -10,9 +10,9 @@ use anyhow::{bail, format_err, Error};
use http::StatusCode;
use pbs_config::CachedUserInfo;
use serde_json::json;
+use tracing::info;
use proxmox_router::HttpError;
-use proxmox_sys::task_log;
use pbs_api_types::{
print_store_and_ns, Authid, BackupNamespace, GroupFilter, GroupListItem, NamespaceListItem,
@@ -32,7 +32,6 @@ use pbs_datastore::manifest::{
};
use pbs_datastore::{check_backup_owner, DataStore, StoreProgress};
use pbs_tools::sha::sha256;
-use proxmox_rest_server::WorkerTask;
use crate::backup::{check_ns_modification_privs, check_ns_privs};
use crate::tools::parallel_handler::ParallelHandler;
@@ -123,7 +122,6 @@ impl PullParameters {
}
async fn pull_index_chunks<I: IndexFile>(
- worker: &WorkerTask,
chunk_reader: RemoteChunkReader,
target: Arc<DataStore>,
index: I,
@@ -176,10 +174,10 @@ async fn pull_index_chunks<I: IndexFile>(
target.cond_touch_chunk(&info.digest, false)
})?;
if chunk_exists {
- //task_log!(worker, "chunk {} exists {}", pos, hex::encode(digest));
+ //info!(tasklog = true, "chunk {} exists {}", pos, hex::encode(digest));
return Ok::<_, Error>(());
}
- //task_log!(worker, "sync {} chunk {}", pos, hex::encode(digest));
+ //info!(tasklog = true, "sync {} chunk {}", pos, hex::encode(digest));
let chunk = chunk_reader.read_raw_chunk(&info.digest).await?;
let raw_size = chunk.raw_size() as usize;
@@ -205,8 +203,8 @@ async fn pull_index_chunks<I: IndexFile>(
let bytes = bytes.load(Ordering::SeqCst);
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"downloaded {} bytes ({:.2} MiB/s)",
bytes,
(bytes as f64) / (1024.0 * 1024.0 * elapsed)
@@ -261,7 +259,6 @@ fn verify_archive(info: &FileInfo, csum: &[u8; 32], size: u64) -> Result<(), Err
/// - if archive is an index, pull referenced chunks
/// - Rename tmp file into real path
async fn pull_single_archive(
- worker: &WorkerTask,
reader: &BackupReader,
chunk_reader: &mut RemoteChunkReader,
snapshot: &pbs_datastore::BackupDir,
@@ -275,7 +272,7 @@ async fn pull_single_archive(
let mut tmp_path = path.clone();
tmp_path.set_extension("tmp");
- task_log!(worker, "sync archive {}", archive_name);
+ info!(tasklog = true, "sync archive {}", archive_name);
let mut tmpfile = std::fs::OpenOptions::new()
.write(true)
@@ -294,7 +291,6 @@ async fn pull_single_archive(
verify_archive(archive_info, &csum, size)?;
pull_index_chunks(
- worker,
chunk_reader.clone(),
snapshot.datastore().clone(),
index,
@@ -310,7 +306,6 @@ async fn pull_single_archive(
verify_archive(archive_info, &csum, size)?;
pull_index_chunks(
- worker,
chunk_reader.clone(),
snapshot.datastore().clone(),
index,
@@ -333,7 +328,6 @@ async fn pull_single_archive(
// Note: The client.log.blob is uploaded after the backup, so it is
// not mentioned in the manifest.
async fn try_client_log_download(
- worker: &WorkerTask,
reader: Arc<BackupReader>,
path: &std::path::Path,
) -> Result<(), Error> {
@@ -351,7 +345,10 @@ async fn try_client_log_download(
if let Err(err) = std::fs::rename(&tmp_path, path) {
bail!("Atomic rename file {:?} failed - {}", path, err);
}
- task_log!(worker, "got backup log file {:?}", CLIENT_LOG_BLOB_NAME);
+ info!(
+ tasklog = true,
+ "got backup log file {:?}", CLIENT_LOG_BLOB_NAME
+ );
}
Ok(())
@@ -367,7 +364,6 @@ async fn try_client_log_download(
/// -- if not, pull it from the remote
/// - Download log if not already existing
async fn pull_snapshot(
- worker: &WorkerTask,
reader: Arc<BackupReader>,
snapshot: &pbs_datastore::BackupDir,
downloaded_chunks: Arc<Mutex<HashSet<[u8; 32]>>>,
@@ -388,8 +384,8 @@ async fn pull_snapshot(
match err.downcast_ref::<HttpError>() {
Some(HttpError { code, message }) => match *code {
StatusCode::NOT_FOUND => {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"skipping snapshot {} - vanished since start of sync",
snapshot.dir(),
);
@@ -422,9 +418,9 @@ async fn pull_snapshot(
if manifest_blob.raw_data() == tmp_manifest_blob.raw_data() {
if !client_log_name.exists() {
- try_client_log_download(worker, reader, &client_log_name).await?;
+ try_client_log_download(reader, &client_log_name).await?;
}
- task_log!(worker, "no data changes");
+ info!(tasklog = true, "no data changes");
let _ = std::fs::remove_file(&tmp_manifest_name);
return Ok(()); // nothing changed
}
@@ -444,7 +440,7 @@ async fn pull_snapshot(
match manifest.verify_file(&item.filename, &csum, size) {
Ok(_) => continue,
Err(err) => {
- task_log!(worker, "detected changed file {:?} - {}", path, err);
+ info!(tasklog = true, "detected changed file {:?} - {}", path, err);
}
}
}
@@ -454,7 +450,7 @@ async fn pull_snapshot(
match manifest.verify_file(&item.filename, &csum, size) {
Ok(_) => continue,
Err(err) => {
- task_log!(worker, "detected changed file {:?} - {}", path, err);
+ info!(tasklog = true, "detected changed file {:?} - {}", path, err);
}
}
}
@@ -464,7 +460,7 @@ async fn pull_snapshot(
match manifest.verify_file(&item.filename, &csum, size) {
Ok(_) => continue,
Err(err) => {
- task_log!(worker, "detected changed file {:?} - {}", path, err);
+ info!(tasklog = true, "detected changed file {:?} - {}", path, err);
}
}
}
@@ -479,7 +475,6 @@ async fn pull_snapshot(
);
pull_single_archive(
- worker,
&reader,
&mut chunk_reader,
snapshot,
@@ -494,7 +489,7 @@ async fn pull_snapshot(
}
if !client_log_name.exists() {
- try_client_log_download(worker, reader, &client_log_name).await?;
+ try_client_log_download(reader, &client_log_name).await?;
}
snapshot
@@ -509,7 +504,6 @@ async fn pull_snapshot(
/// The `reader` is configured to read from the remote / source namespace, while the `snapshot` is
/// pointing to the local datastore and target namespace.
async fn pull_snapshot_from(
- worker: &WorkerTask,
reader: Arc<BackupReader>,
snapshot: &pbs_datastore::BackupDir,
downloaded_chunks: Arc<Mutex<HashSet<[u8; 32]>>>,
@@ -519,22 +513,22 @@ async fn pull_snapshot_from(
.create_locked_backup_dir(snapshot.backup_ns(), snapshot.as_ref())?;
if is_new {
- task_log!(worker, "sync snapshot {}", snapshot.dir());
+ info!(tasklog = true, "sync snapshot {}", snapshot.dir());
- if let Err(err) = pull_snapshot(worker, reader, snapshot, downloaded_chunks).await {
+ if let Err(err) = pull_snapshot(reader, snapshot, downloaded_chunks).await {
if let Err(cleanup_err) = snapshot.datastore().remove_backup_dir(
snapshot.backup_ns(),
snapshot.as_ref(),
true,
) {
- task_log!(worker, "cleanup error - {}", cleanup_err);
+ info!(tasklog = true, "cleanup error - {}", cleanup_err);
}
return Err(err);
}
- task_log!(worker, "sync snapshot {} done", snapshot.dir());
+ info!(tasklog = true, "sync snapshot {} done", snapshot.dir());
} else {
- task_log!(worker, "re-sync snapshot {}", snapshot.dir());
- pull_snapshot(worker, reader, snapshot, downloaded_chunks).await?;
+ info!(tasklog = true, "re-sync snapshot {}", snapshot.dir());
+ pull_snapshot(reader, snapshot, downloaded_chunks).await?;
}
Ok(())
@@ -638,14 +632,13 @@ impl std::fmt::Display for SkipInfo {
/// - remote snapshot access is checked by remote (twice: query and opening the backup reader)
/// - local group owner is already checked by pull_store
async fn pull_group(
- worker: &WorkerTask,
client: &HttpClient,
params: &PullParameters,
group: &pbs_api_types::BackupGroup,
remote_ns: BackupNamespace,
progress: &mut StoreProgress,
) -> Result<(), Error> {
- task_log!(worker, "sync group {}", group);
+ info!(tasklog = true, "sync group {}", group);
let path = format!(
"api2/json/admin/datastore/{}/snapshots",
@@ -697,10 +690,9 @@ async fn pull_group(
// in-progress backups can't be synced
if item.size.is_none() {
- task_log!(
- worker,
- "skipping snapshot {} - in-progress backup",
- snapshot
+ info!(
+ tasklog = true,
+ "skipping snapshot {} - in-progress backup", snapshot
);
continue;
}
@@ -711,7 +703,7 @@ async fn pull_group(
already_synced_skip_info.update(snapshot.time);
continue;
} else if already_synced_skip_info.count > 0 {
- task_log!(worker, "{}", already_synced_skip_info);
+ info!(tasklog = true, "{}", already_synced_skip_info);
already_synced_skip_info.reset();
}
@@ -719,7 +711,7 @@ async fn pull_group(
transfer_last_skip_info.update(snapshot.time);
continue;
} else if transfer_last_skip_info.count > 0 {
- task_log!(worker, "{}", transfer_last_skip_info);
+ info!(tasklog = true, "{}", transfer_last_skip_info);
transfer_last_skip_info.reset();
}
@@ -749,10 +741,10 @@ async fn pull_group(
let snapshot = params.store.backup_dir(target_ns.clone(), snapshot)?;
- let result = pull_snapshot_from(worker, reader, &snapshot, downloaded_chunks.clone()).await;
+ let result = pull_snapshot_from(reader, &snapshot, downloaded_chunks.clone()).await;
progress.done_snapshots = pos as u64 + 1;
- task_log!(worker, "percentage done: {}", progress);
+ info!(tasklog = true, "percentage done: {}", progress);
result?; // stop on error
}
@@ -766,14 +758,18 @@ async fn pull_group(
continue;
}
if snapshot.is_protected() {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"don't delete vanished snapshot {} (protected)",
snapshot.dir()
);
continue;
}
- task_log!(worker, "delete vanished snapshot {}", snapshot.dir());
+ info!(
+ tasklog = true,
+ "delete vanished snapshot {}",
+ snapshot.dir()
+ );
params
.store
.remove_backup_dir(&target_ns, snapshot.as_ref(), false)?;
@@ -785,7 +781,6 @@ async fn pull_group(
// will modify params if switching to backwards mode for lack of NS support on remote end
async fn query_namespaces(
- worker: &WorkerTask,
client: &HttpClient,
params: &mut PullParameters,
) -> Result<Vec<BackupNamespace>, Error> {
@@ -808,8 +803,8 @@ async fn query_namespaces(
Some(HttpError { code, message }) => match *code {
StatusCode::NOT_FOUND => {
if params.remote_ns.is_root() && params.max_depth.is_none() {
- task_log!(worker, "Could not query remote for namespaces (404) -> temporarily switching to backwards-compat mode");
- task_log!(worker, "Either make backwards-compat mode explicit (max-depth == 0) or upgrade remote system.");
+ info!(tasklog = true, "Could not query remote for namespaces (404) -> temporarily switching to backwards-compat mode");
+ info!(tasklog = true, "Either make backwards-compat mode explicit (max-depth == 0) or upgrade remote system.");
params.max_depth = Some(0);
} else {
bail!("Remote namespace set/recursive sync requested, but remote does not support namespaces.")
@@ -875,7 +870,6 @@ fn check_and_remove_ns(params: &PullParameters, local_ns: &BackupNamespace) -> R
}
fn check_and_remove_vanished_ns(
- worker: &WorkerTask,
params: &PullParameters,
synced_ns: HashSet<BackupNamespace>,
) -> Result<bool, Error> {
@@ -913,14 +907,16 @@ fn check_and_remove_vanished_ns(
continue;
}
match check_and_remove_ns(params, &local_ns) {
- Ok(true) => task_log!(worker, "Removed namespace {}", local_ns),
- Ok(false) => task_log!(
- worker,
- "Did not remove namespace {} - protected snapshots remain",
- local_ns
+ Ok(true) => info!(tasklog = true, "Removed namespace {}", local_ns),
+ Ok(false) => info!(
+ tasklog = true,
+ "Did not remove namespace {} - protected snapshots remain", local_ns
),
Err(err) => {
- task_log!(worker, "Failed to remove namespace {} - {}", local_ns, err);
+ info!(
+ tasklog = true,
+ "Failed to remove namespace {} - {}", local_ns, err
+ );
errors = true;
}
}
@@ -947,7 +943,6 @@ fn check_and_remove_vanished_ns(
/// - creation and removal of sub-NS checked here
/// - access to sub-NS checked here
pub(crate) async fn pull_store(
- worker: &WorkerTask,
client: &HttpClient,
mut params: PullParameters,
) -> Result<(), Error> {
@@ -959,7 +954,7 @@ pub(crate) async fn pull_store(
let namespaces = if params.remote_ns.is_root() && params.max_depth == Some(0) {
vec![params.remote_ns.clone()] // backwards compat - don't query remote namespaces!
} else {
- query_namespaces(worker, client, &mut params).await?
+ query_namespaces(client, &mut params).await?
};
errors |= old_max_depth != params.max_depth; // fail job if we switched to backwards-compat mode
@@ -972,41 +967,36 @@ pub(crate) async fn pull_store(
let target_ns = namespace.map_prefix(¶ms.remote_ns, ¶ms.ns)?;
let target_store_ns_str = print_store_and_ns(params.store.name(), &target_ns);
- task_log!(worker, "----");
- task_log!(
- worker,
- "Syncing {} into {}",
- source_store_ns_str,
- target_store_ns_str
+ info!(tasklog = true, "----");
+ info!(
+ tasklog = true,
+ "Syncing {} into {}", source_store_ns_str, target_store_ns_str
);
synced_ns.insert(target_ns.clone());
match check_and_create_ns(¶ms, &target_ns) {
- Ok(true) => task_log!(worker, "Created namespace {}", target_ns),
+ Ok(true) => info!(tasklog = true, "Created namespace {}", target_ns),
Ok(false) => {}
Err(err) => {
- task_log!(
- worker,
- "Cannot sync {} into {} - {}",
- source_store_ns_str,
- target_store_ns_str,
- err,
+ info!(
+ tasklog = true,
+ "Cannot sync {} into {} - {}", source_store_ns_str, target_store_ns_str, err,
);
errors = true;
continue;
}
}
- match pull_ns(worker, client, ¶ms, namespace.clone(), target_ns).await {
+ match pull_ns(client, ¶ms, namespace.clone(), target_ns).await {
Ok((ns_progress, ns_errors)) => {
errors |= ns_errors;
if params.max_depth != Some(0) {
groups += ns_progress.done_groups;
snapshots += ns_progress.done_snapshots;
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"Finished syncing namespace {}, current progress: {} groups, {} snapshots",
namespace,
groups,
@@ -1016,18 +1006,16 @@ pub(crate) async fn pull_store(
}
Err(err) => {
errors = true;
- task_log!(
- worker,
- "Encountered errors while syncing namespace {} - {}",
- namespace,
- err,
+ info!(
+ tasklog = true,
+ "Encountered errors while syncing namespace {} - {}", namespace, err,
);
}
};
}
if params.remove_vanished {
- errors |= check_and_remove_vanished_ns(worker, ¶ms, synced_ns)?;
+ errors |= check_and_remove_vanished_ns(¶ms, synced_ns)?;
}
if errors {
@@ -1050,7 +1038,6 @@ pub(crate) async fn pull_store(
/// - remote namespaces are filtered by remote
/// - owner check for vanished groups done here
pub(crate) async fn pull_ns(
- worker: &WorkerTask,
client: &HttpClient,
params: &PullParameters,
source_ns: BackupNamespace,
@@ -1096,15 +1083,15 @@ pub(crate) async fn pull_ns(
.into_iter()
.filter(|group| apply_filters(group, group_filter))
.collect();
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"found {} groups to sync (out of {} total)",
list.len(),
unfiltered_count
);
list
} else {
- task_log!(worker, "found {} groups to sync", total_count);
+ info!(tasklog = true, "found {} groups to sync", total_count);
list
};
@@ -1129,11 +1116,9 @@ pub(crate) async fn pull_ns(
{
Ok(result) => result,
Err(err) => {
- task_log!(
- worker,
- "sync group {} failed - group lock failed: {}",
- &group,
- err
+ info!(
+ tasklog = true,
+ "sync group {} failed - group lock failed: {}", &group, err
);
errors = true; // do not stop here, instead continue
continue;
@@ -1143,25 +1128,15 @@ pub(crate) async fn pull_ns(
// permission check
if params.owner != owner {
// only the owner is allowed to create additional snapshots
- task_log!(
- worker,
- "sync group {} failed - owner check failed ({} != {})",
- &group,
- params.owner,
- owner
+ info!(
+ tasklog = true,
+ "sync group {} failed - owner check failed ({} != {})", &group, params.owner, owner
);
errors = true; // do not stop here, instead continue
- } else if let Err(err) = pull_group(
- worker,
- client,
- params,
- &group,
- source_ns.clone(),
- &mut progress,
- )
- .await
+ } else if let Err(err) =
+ pull_group(client, params, &group, source_ns.clone(), &mut progress).await
{
- task_log!(worker, "sync group {} failed - {}", &group, err,);
+ info!(tasklog = true, "sync group {} failed - {}", &group, err,);
errors = true; // do not stop here, instead continue
}
}
@@ -1183,18 +1158,17 @@ pub(crate) async fn pull_ns(
continue;
}
}
- task_log!(worker, "delete vanished group '{local_group}'",);
+ info!(tasklog = true, "delete vanished group '{local_group}'",);
match params.store.remove_backup_group(&target_ns, local_group) {
Ok(true) => {}
Ok(false) => {
- task_log!(
- worker,
- "kept some protected snapshots of group '{}'",
- local_group
+ info!(
+ tasklog = true,
+ "kept some protected snapshots of group '{}'", local_group
);
}
Err(err) => {
- task_log!(worker, "{}", err);
+ info!(tasklog = true, "{}", err);
errors = true;
}
}
@@ -1202,7 +1176,7 @@ pub(crate) async fn pull_ns(
Ok(())
});
if let Err(err) = result {
- task_log!(worker, "error during cleanup: {}", err);
+ info!(tasklog = true, "error during cleanup: {}", err);
errors = true;
};
}
diff --git a/src/server/realm_sync_job.rs b/src/server/realm_sync_job.rs
index 1f92e843..952d09ad 100644
--- a/src/server/realm_sync_job.rs
+++ b/src/server/realm_sync_job.rs
@@ -1,13 +1,14 @@
use anyhow::{bail, format_err, Context, Error};
+use tracing::{info, warn};
+
use pbs_config::{acl::AclTree, token_shadow, BackupLockGuard};
use proxmox_lang::try_block;
use proxmox_ldap::{Config, Connection, SearchParameters, SearchResult};
use proxmox_rest_server::WorkerTask;
use proxmox_schema::{ApiType, Schema};
use proxmox_section_config::SectionConfigData;
-use proxmox_sys::{task_log, task_warn};
-use std::{collections::HashSet, sync::Arc};
+use std::collections::HashSet;
use pbs_api_types::{
ApiToken, Authid, LdapRealmConfig, Realm, RemoveVanished, SyncAttributes as LdapSyncAttributes,
@@ -38,7 +39,7 @@ pub fn do_realm_sync_job(
move |worker| {
job.start(&worker.upid().to_string()).unwrap();
- task_log!(worker, "starting realm sync for {}", realm.as_str());
+ info!(tasklog = true, "starting realm sync for {}", realm.as_str());
let override_settings = GeneralSyncSettingsOverride {
remove_vanished,
@@ -46,7 +47,7 @@ pub fn do_realm_sync_job(
};
async move {
- let sync_job = LdapRealmSyncJob::new(worker, realm, &override_settings, dry_run)?;
+ let sync_job = LdapRealmSyncJob::new(realm, &override_settings, dry_run)?;
sync_job.sync().await
}
},
@@ -57,7 +58,6 @@ pub fn do_realm_sync_job(
/// Implemenation for syncing LDAP realms
struct LdapRealmSyncJob {
- worker: Arc<WorkerTask>,
realm: Realm,
general_sync_settings: GeneralSyncSettings,
ldap_sync_settings: LdapSyncSettings,
@@ -68,7 +68,6 @@ struct LdapRealmSyncJob {
impl LdapRealmSyncJob {
/// Create new LdapRealmSyncJob
fn new(
- worker: Arc<WorkerTask>,
realm: Realm,
override_settings: &GeneralSyncSettingsOverride,
dry_run: bool,
@@ -88,7 +87,6 @@ impl LdapRealmSyncJob {
let ldap_config = auth::LdapAuthenticator::api_type_to_config(&config)?;
Ok(Self {
- worker,
realm,
general_sync_settings: sync_settings,
ldap_sync_settings: sync_attributes,
@@ -100,8 +98,8 @@ impl LdapRealmSyncJob {
/// Perform realm synchronization
async fn sync(&self) -> Result<(), Error> {
if self.dry_run {
- task_log!(
- self.worker,
+ info!(
+ tasklog = true,
"this is a DRY RUN - changes will not be persisted"
);
}
@@ -185,7 +183,7 @@ impl LdapRealmSyncJob {
anyhow::Ok(())
});
if let Err(e) = result {
- task_log!(self.worker, "could not create/update user: {e}");
+ info!(tasklog = true, "could not create/update user: {e}");
}
}
@@ -204,15 +202,15 @@ impl LdapRealmSyncJob {
if let Some(existing_user) = existing_user {
if existing_user != new_or_updated_user {
- task_log!(
- self.worker,
+ info!(
+ tasklog = true,
"updating user {}",
new_or_updated_user.userid.as_str()
);
}
} else {
- task_log!(
- self.worker,
+ info!(
+ tasklog = true,
"creating user {}",
new_or_updated_user.userid.as_str()
);
@@ -237,8 +235,8 @@ impl LdapRealmSyncJob {
let schema = schema.unwrap_string_schema();
if let Err(e) = schema.check_constraints(value) {
- task_warn!(
- self.worker,
+ warn!(
+ tasklog = true,
"{userid}: ignoring attribute `{attribute}`: {e}"
);
@@ -319,7 +317,7 @@ impl LdapRealmSyncJob {
to_delete: &[Userid],
) -> Result<(), Error> {
for userid in to_delete {
- task_log!(self.worker, "deleting user {}", userid.as_str());
+ info!(tasklog = true, "deleting user {}", userid.as_str());
// Delete the user
user_config.sections.remove(userid.as_str());
@@ -346,7 +344,10 @@ impl LdapRealmSyncJob {
if !self.dry_run {
if let Err(e) = token_shadow::delete_secret(&tokenid) {
- task_warn!(self.worker, "could not delete token for user {userid}: {e}",)
+ warn!(
+ tasklog = true,
+ "could not delete token for user {userid}: {e}",
+ )
}
}
diff --git a/src/server/verify_job.rs b/src/server/verify_job.rs
index 8bf2a0c9..55c0a574 100644
--- a/src/server/verify_job.rs
+++ b/src/server/verify_job.rs
@@ -1,9 +1,9 @@
use anyhow::{format_err, Error};
+use tracing::info;
use pbs_api_types::{Authid, Operation, VerificationJobConfig};
use pbs_datastore::DataStore;
use proxmox_rest_server::WorkerTask;
-use proxmox_sys::task_log;
use crate::{
backup::{verify_all_backups, verify_filter},
@@ -36,9 +36,9 @@ pub fn do_verification_job(
move |worker| {
job.start(&worker.upid().to_string())?;
- task_log!(worker, "Starting datastore verify job '{}'", job_id);
+ info!(tasklog = true, "Starting datastore verify job '{}'", job_id);
if let Some(event_str) = schedule {
- task_log!(worker, "task triggered by schedule '{}'", event_str);
+ info!(tasklog = true, "task triggered by schedule '{}'", event_str);
}
let ns = match verification_job.ns {
@@ -60,9 +60,12 @@ pub fn do_verification_job(
let job_result = match result {
Ok(ref failed_dirs) if failed_dirs.is_empty() => Ok(()),
Ok(ref failed_dirs) => {
- task_log!(worker, "Failed to verify the following snapshots/groups:");
+ info!(
+ tasklog = true,
+ "Failed to verify the following snapshots/groups:"
+ );
for dir in failed_dirs {
- task_log!(worker, "\t{}", dir);
+ info!(tasklog = true, "\t{}", dir);
}
Err(format_err!(
diff --git a/src/tape/drive/mod.rs b/src/tape/drive/mod.rs
index 86f01201..a85c353f 100644
--- a/src/tape/drive/mod.rs
+++ b/src/tape/drive/mod.rs
@@ -12,6 +12,7 @@ use nix::fcntl::OFlag;
use nix::sys::stat::Mode;
use serde::Deserialize;
use serde_json::Value;
+use tracing::info;
use proxmox_sys::fs::{
atomic_open_or_create_file, file_read_optional_string, lock_file, replace_file, CreateOptions,
@@ -19,7 +20,7 @@ use proxmox_sys::fs::{
use proxmox_io::ReadExt;
use proxmox_section_config::SectionConfigData;
-use proxmox_sys::{task_log, WorkerTaskContext};
+use proxmox_sys::WorkerTaskContext;
use proxmox_uuid::Uuid;
use pbs_api_types::{Fingerprint, LtoTapeDrive, VirtualTapeDrive};
@@ -343,11 +344,9 @@ pub fn request_and_load_media(
) -> Result<(Box<dyn TapeDriver>, MediaId), Error> {
let check_label = |handle: &mut dyn TapeDriver, uuid: &proxmox_uuid::Uuid| {
if let Ok((Some(media_id), _)) = handle.read_label() {
- task_log!(
- worker,
- "found media label {} ({})",
- media_id.label.label_text,
- media_id.label.uuid,
+ info!(
+ tasklog = true,
+ "found media label {} ({})", media_id.label.label_text, media_id.label.uuid,
);
if media_id.label.uuid == *uuid {
@@ -385,15 +384,15 @@ pub fn request_and_load_media(
let update_and_log_request_error =
|old: &mut TapeRequestError, new: TapeRequestError| -> Result<(), Error> {
if new != *old {
- task_log!(worker, "{}", new);
+ info!(tasklog = true, "{}", new);
let (device_type, device) = if let Some(changer) = changer {
("changer", changer.as_str())
} else {
("drive", drive)
};
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"Please insert media '{}' into {} '{}'",
label_text,
device_type,
@@ -423,18 +422,14 @@ pub fn request_and_load_media(
std::thread::sleep(std::time::Duration::from_millis(100));
}
} else if drive_config.changer.is_none() {
- task_log!(
- worker,
- "Checking for media '{}' in drive '{}'",
- label_text,
- drive
+ info!(
+ tasklog = true,
+ "Checking for media '{}' in drive '{}'", label_text, drive
);
} else {
- task_log!(
- worker,
- "trying to load media '{}' into drive '{}'",
- label_text,
- drive
+ info!(
+ tasklog = true,
+ "trying to load media '{}' into drive '{}'", label_text, drive
);
}
@@ -462,8 +457,8 @@ pub fn request_and_load_media(
let request_error = match handle.read_label() {
Ok((Some(media_id), _)) if media_id.label.uuid == label.uuid => {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"found media label {} ({})",
media_id.label.label_text,
media_id.label.uuid.to_string(),
diff --git a/src/tape/pool_writer/mod.rs b/src/tape/pool_writer/mod.rs
index d1add203..b05b8921 100644
--- a/src/tape/pool_writer/mod.rs
+++ b/src/tape/pool_writer/mod.rs
@@ -11,8 +11,8 @@ use std::sync::{Arc, Mutex};
use std::time::SystemTime;
use anyhow::{bail, Error};
+use tracing::{info, warn};
-use proxmox_sys::{task_log, task_warn};
use proxmox_uuid::Uuid;
use pbs_datastore::{DataStore, SnapshotReader};
@@ -57,7 +57,6 @@ impl PoolWriter {
pub fn new(
mut pool: MediaPool,
drive_name: &str,
- worker: &WorkerTask,
notify_email: Option<String>,
force_media_set: bool,
ns_magic: bool,
@@ -66,11 +65,14 @@ impl PoolWriter {
let new_media_set_reason = pool.start_write_session(current_time, force_media_set)?;
if let Some(reason) = new_media_set_reason {
- task_log!(worker, "starting new media set - reason: {}", reason,);
+ info!(
+ tasklog = true,
+ "starting new media set - reason: {}", reason,
+ );
}
let media_set_uuid = pool.current_media_set().uuid();
- task_log!(worker, "media set uuid: {}", media_set_uuid);
+ info!(tasklog = true, "media set uuid: {}", media_set_uuid);
let mut catalog_set = CatalogSet::new();
@@ -125,7 +127,7 @@ impl PoolWriter {
}
/// Eject media and drop PoolWriterState (close drive)
- pub fn eject_media(&mut self, worker: &WorkerTask) -> Result<(), Error> {
+ pub fn eject_media(&mut self) -> Result<(), Error> {
let mut status = match self.status.take() {
Some(status) => status,
None => return Ok(()), // no media loaded
@@ -134,13 +136,13 @@ impl PoolWriter {
let (drive_config, _digest) = pbs_config::drive::config()?;
if let Some((mut changer, _)) = media_changer(&drive_config, &self.drive_name)? {
- task_log!(worker, "eject media");
+ info!(tasklog = true, "eject media");
status.drive.eject_media()?; // rewind and eject early, so that unload_media is faster
drop(status); // close drive
- task_log!(worker, "unload media");
+ info!(tasklog = true, "unload media");
changer.unload_media(None)?; //eject and unload
} else {
- task_log!(worker, "standalone drive - ejecting media");
+ info!(tasklog = true, "standalone drive - ejecting media");
status.drive.eject_media()?;
}
@@ -148,14 +150,14 @@ impl PoolWriter {
}
/// Export current media set and drop PoolWriterState (close drive)
- pub fn export_media_set(&mut self, worker: &WorkerTask) -> Result<(), Error> {
+ pub fn export_media_set(&mut self) -> Result<(), Error> {
let mut status = self.status.take();
let (drive_config, _digest) = pbs_config::drive::config()?;
if let Some((mut changer, _)) = media_changer(&drive_config, &self.drive_name)? {
if let Some(ref mut status) = status {
- task_log!(worker, "rewind media");
+ info!(tasklog = true, "rewind media");
// rewind first so that the unload command later does not run into a timeout
status.drive.rewind()?;
}
@@ -165,23 +167,21 @@ impl PoolWriter {
let media = self.pool.lookup_media(media_uuid)?;
let label_text = media.label_text();
if let Some(slot) = changer.export_media(label_text)? {
- task_log!(
- worker,
- "exported media '{}' to import/export slot {}",
- label_text,
- slot
+ info!(
+ tasklog = true,
+ "exported media '{}' to import/export slot {}", label_text, slot
);
} else {
- task_warn!(
- worker,
+ warn!(
+ tasklog = true,
"export failed - media '{}' is not online or in different drive",
label_text
);
}
}
} else if let Some(mut status) = status {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"standalone drive - ejecting media instead of export"
);
status.drive.eject_media()?;
@@ -224,15 +224,15 @@ impl PoolWriter {
return Ok(media_uuid);
}
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"allocated new writable media '{}'",
media.label_text()
);
if let Some(PoolWriterState { mut drive, .. }) = self.status.take() {
if last_media_uuid.is_some() {
- task_log!(worker, "eject current media");
+ info!(tasklog = true, "eject current media");
drive.eject_media()?;
}
}
@@ -250,7 +250,7 @@ impl PoolWriter {
// test for critical tape alert flags
if let Ok(alert_flags) = drive.tape_alert_flags() {
if !alert_flags.is_empty() {
- task_log!(worker, "TapeAlertFlags: {:?}", alert_flags);
+ info!(tasklog = true, "TapeAlertFlags: {:?}", alert_flags);
if tape_alert_flags_critical(alert_flags) {
self.pool.set_media_status_damaged(&media_uuid)?;
bail!(
@@ -261,12 +261,8 @@ impl PoolWriter {
}
}
- let (catalog, is_new_media) = update_media_set_label(
- worker,
- drive.as_mut(),
- old_media_id.media_set_label,
- media.id(),
- )?;
+ let (catalog, is_new_media) =
+ update_media_set_label(drive.as_mut(), old_media_id.media_set_label, media.id())?;
self.catalog_set.lock().unwrap().append_catalog(catalog)?;
@@ -288,7 +284,7 @@ impl PoolWriter {
if is_new_media {
// add catalogs from previous media
- self.append_media_set_catalogs(worker)?;
+ self.append_media_set_catalogs()?;
}
self.used_tapes.insert(media_uuid.clone());
@@ -308,12 +304,12 @@ impl PoolWriter {
// Check it tape is loaded, then move to EOM (if not already there)
//
// Returns the tape position at EOM.
- fn prepare_tape_write(status: &mut PoolWriterState, worker: &WorkerTask) -> Result<u64, Error> {
+ fn prepare_tape_write(status: &mut PoolWriterState) -> Result<u64, Error> {
if !status.at_eom {
- task_log!(worker, "moving to end of media");
+ info!(tasklog = true, "moving to end of media");
status.drive.move_to_eom(true)?;
status.at_eom = true;
- task_log!(worker, "arrived at end of media");
+ info!(tasklog = true, "arrived at end of media");
}
let current_file_number = status.drive.current_file_number()?;
@@ -334,7 +330,7 @@ impl PoolWriter {
/// on the media (return value 'Ok(false, _)'). In that case, the
/// archive is marked incomplete. The caller should mark the media
/// as full and try again using another media.
- pub fn append_catalog_archive(&mut self, worker: &WorkerTask) -> Result<bool, Error> {
+ pub fn append_catalog_archive(&mut self) -> Result<bool, Error> {
let catalog_magic = self.catalog_version();
let status = match self.status {
@@ -342,7 +338,7 @@ impl PoolWriter {
None => bail!("PoolWriter - no media loaded"),
};
- Self::prepare_tape_write(status, worker)?;
+ Self::prepare_tape_write(status)?;
let catalog_set = self.catalog_set.lock().unwrap();
@@ -385,7 +381,7 @@ impl PoolWriter {
}
// Append catalogs for all previous media in set (without last)
- fn append_media_set_catalogs(&mut self, worker: &WorkerTask) -> Result<(), Error> {
+ fn append_media_set_catalogs(&mut self) -> Result<(), Error> {
let media_set = self.pool.current_media_set();
let mut media_list = media_set.media_list();
@@ -401,7 +397,7 @@ impl PoolWriter {
None => bail!("PoolWriter - no media loaded"),
};
- Self::prepare_tape_write(status, worker)?;
+ Self::prepare_tape_write(status)?;
for (seq_nr, uuid) in media_list.iter().enumerate() {
let uuid = match uuid {
@@ -413,7 +409,7 @@ impl PoolWriter {
let mut file = Self::open_catalog_file(uuid)?;
- task_log!(worker, "write catalog for previous media: {}", uuid);
+ info!(tasklog = true, "write catalog for previous media: {}", uuid);
if tape_write_catalog(
writer.as_mut(),
@@ -444,7 +440,6 @@ impl PoolWriter {
/// media.
pub fn append_snapshot_archive(
&mut self,
- worker: &WorkerTask,
snapshot_reader: &SnapshotReader,
) -> Result<(bool, usize), Error> {
let status = match self.status {
@@ -452,7 +447,7 @@ impl PoolWriter {
None => bail!("PoolWriter - no media loaded"),
};
- let current_file_number = Self::prepare_tape_write(status, worker)?;
+ let current_file_number = Self::prepare_tape_write(status)?;
let (done, bytes_written) = {
let mut writer: Box<dyn TapeWrite> = status.drive.write_file()?;
@@ -498,7 +493,7 @@ impl PoolWriter {
None => bail!("PoolWriter - no media loaded"),
};
- let current_file_number = Self::prepare_tape_write(status, worker)?;
+ let current_file_number = Self::prepare_tape_write(status)?;
let writer = status.drive.write_file()?;
@@ -510,8 +505,8 @@ impl PoolWriter {
status.bytes_written += bytes_written;
let elapsed = start_time.elapsed()?.as_secs_f64();
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"wrote {} chunks ({:.2} MB at {:.2} MB/s)",
saved_chunks.len(),
bytes_written as f64 / 1_000_000.0,
@@ -591,7 +586,7 @@ fn write_chunk_archive<'a>(
}
if writer.bytes_written() > max_size {
- //task_log!(worker, "Chunk Archive max size reached, closing archive");
+ //info!(tasklog = true, "Chunk Archive max size reached, closing archive");
break;
}
}
@@ -605,7 +600,6 @@ fn write_chunk_archive<'a>(
// set label does not match the expected media set, overwrite the
// media set label.
fn update_media_set_label(
- worker: &WorkerTask,
drive: &mut dyn TapeDriver,
old_set: Option<MediaSetLabel>,
media_id: &MediaId,
@@ -634,7 +628,7 @@ fn update_media_set_label(
let new_media = match old_set {
None => {
- task_log!(worker, "writing new media set label");
+ info!(tasklog = true, "writing new media set label");
drive.write_media_set_label(new_set, key_config.as_ref())?;
media_catalog = MediaCatalog::overwrite(TAPE_STATUS_DIR, media_id, false)?;
true
@@ -658,8 +652,8 @@ fn update_media_set_label(
false
} else {
- task_log!(
- worker,
+ info!(
+ tasklog = true,
"writing new media set label (overwrite '{}/{}')",
media_set_label.uuid.to_string(),
media_set_label.seq_nr,
diff --git a/tests/worker-task-abort.rs b/tests/worker-task-abort.rs
index eda86f01..b022b38f 100644
--- a/tests/worker-task-abort.rs
+++ b/tests/worker-task-abort.rs
@@ -7,24 +7,25 @@ extern crate tokio;
use proxmox_lang::try_block;
use proxmox_sys::fs::CreateOptions;
-use proxmox_sys::{task_log, WorkerTaskContext};
+use proxmox_sys::WorkerTaskContext;
use pbs_api_types::{Authid, UPID};
use proxmox_rest_server::{CommandSocket, WorkerTask};
+use tracing::info;
fn garbage_collection(worker: &WorkerTask) -> Result<(), Error> {
- task_log!(worker, "start garbage collection");
+ info!(tasklog = true, "start garbage collection");
for i in 0..50 {
worker.check_abort()?;
- task_log!(worker, "progress {}", i);
+ info!(tasklog = true, "progress {}", i);
std::thread::sleep(std::time::Duration::from_millis(10));
}
- task_log!(worker, "end garbage collection");
+ info!(tasklog = true, "end garbage collection");
Ok(())
}
--
2.39.2
^ permalink raw reply [flat|nested] 14+ messages in thread