feat: replace log with tracing and use tracing::instrument where useful

[simonsan]

Fixes #315

TODO:

• replace log with tracing
• annotate functions/methods with tracing::instrument, candidates:
  • async, e.g. WebDavFS and opendal backend
  • in general multithreading (TreeArchiver)
  • contain *_par_*/readahead* via rayon
  • send/recv data on channels
• add SpanTrace to RusticError for https://crates.io/crates/tracing-error
• add more fine-grained spans and logging for above impl, e.g. in closures where we spawn threads
• add debug and trace at some more sensible places to make diagnosing backend issues more easy (ref.: Not enough context to root-cause S3 access error #346 )
• what else to prepare, that we can use the instrumented library in rustic-rs?
  • See [WIP] refactor(logging): use tracing and utilize associated type in Application::Path rustic#1342

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 45.4%. Comparing base (f68ffa3) to head (c9e8292).

Additional details and impacted files

Files with missing lines	Coverage Δ
crates/backend/src/local.rs	0.0% <ø> (ø)
crates/backend/src/opendal.rs	90.6% <ø> (ø)
crates/backend/src/rclone.rs	9.7% <ø> (-0.3%)	⬇️
crates/backend/src/rest.rs	0.0% <ø> (ø)
crates/core/src/archiver.rs	64.7% <ø> (-1.5%)	⬇️
crates/core/src/archiver/parent.rs	65.2% <ø> (-1.5%)	⬇️
crates/core/src/archiver/tree_archiver.rs	73.2% <ø> (ø)
crates/core/src/backend.rs	57.5% <ø> (ø)
crates/core/src/backend/cache.rs	70.3% <ø> (-4.9%)	⬇️
crates/core/src/backend/ignore.rs	45.5% <ø> (-1.6%)	⬇️
... and 17 more

... and 13 files with indirect coverage changes

[aawsome]

While I agree that we might want to migrate from log to tracing, I actually would do so when we have decided for the architecture we are using to run rustic in some optimal sync/async/parallelized way. Then, it will be a first implementation step to go into this direction.

[simonsan]

Hmm, I don't understand, why would that be related to an architectural decision? tracing is essential in async/parallelized contexts, for sure. But we can already profit a lot from it by just instrumenting some essential functions/methods so we get more context in our logging. Do you see any downside there? 🤔

[aawsome]

Hmm, I don't understand, why would that be related to an architectural decision? tracing is essential in async/parallelized contexts, for sure. But we can already profit a lot from it by just instrumenting some essential functions/methods so we get more context in our logging. Do you see any downside there? 🤔

No downside. I just don't see any benefit we currently can get. That might change and tracing may help us finding bugs during a big refactor. But currently I just don't see the point in doing so. Better focus on topics like error handling..

[simonsan]

(Sorry, I accidentally edited your comment instead of answering! 😅)

I collected all the advantages in here: #315

The benefits are structured logging, the tracing::instrument macro, and others. I think it's not a big effort, to be honest. It's just replacing log:: with tracing (log facade) and start to instrument certain methods and functions where we are often asking us what the input values to that functions were. For example, tree archiver. Everything where we already parallelize, for example to find race conditions/send errors:

• refactor(errors): improve message and add logging when sending tree from backend panics #314
• fix(errors): replace unwrap/remove panic by logging an error in check when reading data for pack files #306

[simonsan]

I started out to instrument the functions, that are related to:

• async, e.g. WebDavFS and opendal backend
• in general multithreading (TreeArchiver)
• contain *_par_*/readahead* via rayon
• send/recv data on channels

Follow up: I think what can be useful, is also to create functions from closures, where we spawn threads and instrument them, for smaller spans/scopes -- or we can just manually create the needed spans. (: