Log processing cycles on verbosity level 2

CHANGELOG.md

@@ -23,6 +23,8 @@ Versioning](https://semver.org/spec/v2.0.0.html).
 - When `YABRIDGE_DEBUG_LEVEL` is set to 2 or higher and a plugin asks the host
   for the current position in the song, yabridge will now print that position in
   quarter notes and samples as part of the debug output.
+- `YABRIDGE_DEBUG_LEVEL` 2 will now also cause all audio processing callbacks to
+  be logged. This makes recognizing misbheaving plugins a bit easier.
 - Symbols in all `libyabridge.so` and all Winelib `.so` files are now hidden by
   default.
 

src/common/logging.cpp

@@ -105,6 +105,12 @@ void Logger::log(const std::string& message) {
     *stream << formatted_message.str() << std::flush;
 }
 
+void Logger::log_trace(const std::string& message) {
+    if (verbosity >= Verbosity::all_events) {
+        log(message);
+    }
+}
+
 void Logger::log_get_parameter(int index) {
     if (BOOST_UNLIKELY(verbosity >= Verbosity::most_events)) {
         std::ostringstream message;

src/common/logging.h

@@ -55,6 +55,9 @@ class Logger {
          * The same as the above but without filtering out any events. This is
          * very chatty but it can be crucial for debugging plugin-specific
          * problems.
+         *
+         * This will also print print information about the audio processing
+         * callbacks, which can be useful for diagnosing misbehaving plugins.
          */
         all_events = 2,
     };
@@ -114,6 +117,16 @@ class Logger {
         const EventResultPayload& payload,
         const std::optional<EventResultPayload>& value_payload);
 
+    /**
+     * Log a message that should only be printed when the `verbosity` is set to
+     * `all_events`. This should only be used for simple primitive messages
+     * without any formatting since the actual check happens within this
+     * function.
+     *
+     * @param message The message to write.
+     */
+    void log_trace(const std::string& message);
+
    private:
     /**
      * Determine whether an event should be filtered based on the current

src/plugin/plugin-bridge.cpp

@@ -544,21 +544,30 @@ void PluginBridge::process(AEffect* /*plugin*/,
                            float** inputs,
                            float** outputs,
                            int sample_frames) {
+    // Technically either `Vst2PluginBridge::process()` or
+    // `Vst2PluginBridge::process_replacing()` could actually call the other
+    // function on the plugin depending on what the plugin supports.
+    logger.log_trace(">> process() :: start");
     do_process<float, false>(inputs, outputs, sample_frames);
+    logger.log_trace("   process() :: end");
 }
 
 void PluginBridge::process_replacing(AEffect* /*plugin*/,
                                      float** inputs,
                                      float** outputs,
                                      int sample_frames) {
+    logger.log_trace(">> processReplacing() :: start");
     do_process<float, true>(inputs, outputs, sample_frames);
+    logger.log_trace("   processReplacing() :: end");
 }
 
 void PluginBridge::process_double_replacing(AEffect* /*plugin*/,
                                             double** inputs,
                                             double** outputs,
                                             int sample_frames) {
+    logger.log_trace(">> processDoubleReplacing() :: start");
     do_process<double, true>(inputs, outputs, sample_frames);
+    logger.log_trace("   processDoubleReplacing() :: end");
 }
 
 float PluginBridge::get_parameter(AEffect* /*plugin*/, int index) {