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 <bees@furryterror.org>

diff --git a/src/bees-context.cc b/src/bees-context.cc
index 7602e21f17d1f4451a278b45c78a1e7bcefdc11e..ff3e3ca94464de87e06552b3bbd342f5545e11ae 100644 (file)
--- 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 0d03594c8307067e825fb5999400acf64ca3f037..d72531ec7464472ac128509ac7e0d87084a3eb15 100644 (file)
--- 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 81b70d577c3a337d98c6744604ffbd30cf40e5b7..bc756786a34a28557c4796e3fd4bb9055c796c31 100644 (file)
--- 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 3ee21d38ea578e1f6fa4a6a22b0d04b3c0fe90db..68b6ce49591ceafbbf146fccad4fb000b1b77f83 100644 (file)
--- a/src/bees-types.cc
+++ b/src/bees-types.cc
@@ -572,7 +572,7 @@ BeesRangePair::grow(shared_ptr<BeesContext> 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 a8fa5ce430a2c123dba700250aeb4801f397d2e9..c447a99faf0ae24d4d5d78fa5915ee92f88f6e88 100644 (file)
--- 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 888f91edcfcdb906745612e32c878bc37f362c6d..2cbe466696a90de8a12c8ef0097f9e02959dcdd1 100644 (file)
--- 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; })