From 51b3bcdbe4e5f56ab281009d0abd11bd32c418dc Mon Sep 17 00:00:00 2001 From: Zygo Blaxell Date: Wed, 12 Feb 2025 22:01:31 -0500 Subject: [PATCH] trace: deprecate BEESLOGTRACE, align trace logs with exception notices Exceptions were logged at level NOTICE while the stack traces were logged at level DEBUG. That produced useless noise in the output with `-v5` or `-v6`, where there were exception headings logged, but no details. Fix that by placing the exceptions and traces at level DEBUG, but prefix them with `TRACE:` for easy grepping. Most of the events associated with BEESLOGTRACE either never happen, or they are harmless (e.g. trying to open deleted files or subvols). Reassign them to ordinary BEESLOGDEBUG, with one exception for unrecognized Extent flags that should be debugged if any appear. Signed-off-by: Zygo Blaxell --- src/bees-context.cc | 6 ++++-- src/bees-roots.cc | 6 +++--- src/bees-trace.cc | 12 ++++++------ src/bees-types.cc | 4 ++-- src/bees.cc | 2 +- src/bees.h | 4 ++-- 6 files changed, 18 insertions(+), 16 deletions(-) diff --git a/src/bees-context.cc b/src/bees-context.cc index 7602e21..ff3e3ca 100644 --- a/src/bees-context.cc +++ b/src/bees-context.cc @@ -230,8 +230,10 @@ BeesContext::dedup(const BeesRangePair &brp_in) BeesAddress first_addr(brp.first.fd(), brp.first.begin()); BeesAddress second_addr(brp.second.fd(), brp.second.begin()); - if (first_addr.get_physical_or_zero() == second_addr.get_physical_or_zero()) { - BEESLOGTRACE("equal physical addresses in dedup"); + const auto first_gpoz = first_addr.get_physical_or_zero(); + const auto second_gpoz = second_addr.get_physical_or_zero(); + if (first_gpoz == second_gpoz) { + BEESLOGDEBUG("equal physical addresses " << first_addr << " and " << second_addr << " in dedup"); BEESCOUNT(bug_dedup_same_physical); } diff --git a/src/bees-roots.cc b/src/bees-roots.cc index 0d03594..d72531e 100644 --- a/src/bees-roots.cc +++ b/src/bees-roots.cc @@ -2013,7 +2013,7 @@ BeesRoots::open_root_nocache(uint64_t rootid) BEESCOUNT(root_parent_open_try); Fd parent_fd = open_root(parent_rootid); if (!parent_fd) { - BEESLOGTRACE("no parent_fd"); + BEESLOGDEBUG("no parent_fd for " << parent_rootid); BEESCOUNT(root_parent_open_fail); return Fd(); } @@ -2036,7 +2036,7 @@ BeesRoots::open_root_nocache(uint64_t rootid) BEESTRACE("dirid " << dirid << " path " << ino.m_paths.at(0)); parent_fd = bees_openat(parent_fd, ino.m_paths.at(0).c_str(), FLAGS_OPEN_DIR); if (!parent_fd) { - BEESLOGTRACE("no parent_fd from dirid"); + BEESLOGDEBUG("no parent_fd from dirid " << dirid << " in parent_rootid " << parent_rootid); BEESCOUNT(root_parent_path_open_fail); return Fd(); } @@ -2044,7 +2044,7 @@ BeesRoots::open_root_nocache(uint64_t rootid) BEESTRACE("openat(" << name_fd(parent_fd) << ", " << name << ")"); Fd rv = bees_openat(parent_fd, name.c_str(), FLAGS_OPEN_DIR); if (!rv) { - BEESLOGTRACE("open failed for name " << name << ": " << strerror(errno)); + BEESLOGDEBUG("open failed for name " << name << " in parent_fd " << name_fd(parent_fd) << ": " << strerror(errno)); BEESCOUNT(root_open_fail); return rv; } diff --git a/src/bees-trace.cc b/src/bees-trace.cc index 81b70d5..bc75678 100644 --- a/src/bees-trace.cc +++ b/src/bees-trace.cc @@ -28,18 +28,18 @@ BeesTracer::~BeesTracer() { if (!tl_silent && exception_check()) { if (tl_first) { - BEESLOGNOTICE("--- BEGIN TRACE --- exception ---"); + BEESLOG(BEES_TRACE_LEVEL, "TRACE: --- BEGIN TRACE --- exception ---"); tl_first = false; } try { m_func(); } catch (exception &e) { - BEESLOGNOTICE("Nested exception: " << e.what()); + BEESLOG(BEES_TRACE_LEVEL, "TRACE: Nested exception: " << e.what()); } catch (...) { - BEESLOGNOTICE("Nested exception ..."); + BEESLOG(BEES_TRACE_LEVEL, "TRACE: Nested exception ..."); } if (!m_next_tracer) { - BEESLOGNOTICE("--- END TRACE --- exception ---"); + BEESLOG(BEES_TRACE_LEVEL, "TRACE: --- END TRACE --- exception ---"); } } tl_next_tracer = m_next_tracer; @@ -61,12 +61,12 @@ void BeesTracer::trace_now() { BeesTracer *tp = tl_next_tracer; - BEESLOGNOTICE("--- BEGIN TRACE ---"); + BEESLOG(BEES_TRACE_LEVEL, "TRACE: --- BEGIN TRACE ---"); while (tp) { tp->m_func(); tp = tp->m_next_tracer; } - BEESLOGNOTICE("--- END TRACE ---"); + BEESLOG(BEES_TRACE_LEVEL, "TRACE: --- END TRACE ---"); } bool diff --git a/src/bees-types.cc b/src/bees-types.cc index 3ee21d3..68b6ce4 100644 --- a/src/bees-types.cc +++ b/src/bees-types.cc @@ -572,7 +572,7 @@ BeesRangePair::grow(shared_ptr ctx, bool constrained) } if (first.overlaps(second)) { - BEESLOGTRACE("after grow, first " << first << "\n\toverlaps " << second); + BEESLOGDEBUG("after grow, first " << first << "\n\toverlaps " << second); BEESCOUNT(bug_grow_pair_overlaps); } @@ -674,7 +674,7 @@ BeesAddress::magic_check(uint64_t flags) static const unsigned recognized_flags = compressed_flags | delalloc_flags | ignore_flags | unusable_flags; if (flags & ~recognized_flags) { - BEESLOGTRACE("Unrecognized flags in " << fiemap_extent_flags_ntoa(flags)); + BEESLOGNOTICE("Unrecognized flags in " << fiemap_extent_flags_ntoa(flags)); m_addr = UNUSABLE; // maybe we throw here? BEESCOUNT(addr_unrecognized); diff --git a/src/bees.cc b/src/bees.cc index a8fa5ce..c447a99 100644 --- a/src/bees.cc +++ b/src/bees.cc @@ -741,7 +741,7 @@ bees_main(int argc, char *argv[]) BEESLOGDEBUG("exception (ignored): " << s); BEESCOUNT(exception_caught_silent); } else { - BEESLOGNOTICE("\n\n*** EXCEPTION ***\n\t" << s << "\n***\n"); + BEESLOGNOTICE("\n\nTRACE: *** EXCEPTION ***\n\t" << s << "\n***\n"); BEESCOUNT(exception_caught); } }); diff --git a/src/bees.h b/src/bees.h index 888f91e..2cbe466 100644 --- a/src/bees.h +++ b/src/bees.h @@ -122,9 +122,9 @@ const int FLAGS_OPEN_FANOTIFY = O_RDWR | O_NOATIME | O_CLOEXEC | O_LARGEFILE; // macros ---------------------------------------- #define BEESLOG(lv,x) do { if (lv < bees_log_level) { Chatter __chatter(lv, BeesNote::get_name()); __chatter << x; } } while (0) -#define BEESLOGTRACE(x) do { BEESLOG(LOG_DEBUG, x); BeesTracer::trace_now(); } while (0) -#define BEESTRACE(x) BeesTracer SRSLY_WTF_C(beesTracer_, __LINE__) ([&]() { BEESLOG(LOG_ERR, x << " at " << __FILE__ << ":" << __LINE__); }) +#define BEES_TRACE_LEVEL LOG_DEBUG +#define BEESTRACE(x) BeesTracer SRSLY_WTF_C(beesTracer_, __LINE__) ([&]() { BEESLOG(BEES_TRACE_LEVEL, "TRACE: " << x << " at " << __FILE__ << ":" << __LINE__); }) #define BEESTOOLONG(x) BeesTooLong SRSLY_WTF_C(beesTooLong_, __LINE__) ([&](ostream &_btl_os) { _btl_os << x; }) #define BEESNOTE(x) BeesNote SRSLY_WTF_C(beesNote_, __LINE__) ([&](ostream &_btl_os) { _btl_os << x; })