diff --git a/README.md b/README.md index 65aef233..1ef5ae76 100644 --- a/README.md +++ b/README.md @@ -157,9 +157,13 @@ variables: - A value of `0` (the default) means that yabridge will only output messages from the Wine process and some basic information such as the plugin being loaded and the wineprefix being used. - - A value of `1` will log information about all events and function calls - being sent between the VST host and the plugin. This can be very verbose but - it makes it easier to see if yabridge is handling things incorrectly. + - A value of `1` will log information about most events and function calls + being sent between the VST host and the plugin. This filters out the + `effEditIdle()` and `audioMasterGetTime()` calls since those are sent tens + of times per second by for every plugin. + - A value of `2` will cause all of the events to be logged, including + `effEditIdle()` and `audioMasterGettime()`. This can be very verbose but it + can be crucial for debugging plugin-specific problems. More detailed information about these levels can be found in `src/common/logging.h`. diff --git a/src/common/events.h b/src/common/events.h index 6c90c00e..fcb599ce 100644 --- a/src/common/events.h +++ b/src/common/events.h @@ -157,7 +157,7 @@ intptr_t send_event(boost::asio::local::stream_protocol::socket& socket, if (logging.has_value()) { auto [logger, is_dispatch] = logging.value(); - logger.log_event_response(is_dispatch, response.return_value, + logger.log_event_response(is_dispatch, opcode, response.return_value, response.payload); } @@ -299,7 +299,8 @@ void passthrough_event(boost::asio::local::stream_protocol::socket& socket, if (logging.has_value()) { auto [logger, is_dispatch] = logging.value(); - logger.log_event_response(is_dispatch, return_value, response_data); + logger.log_event_response(is_dispatch, event.opcode, return_value, + response_data); } EventResult response{return_value, response_data}; diff --git a/src/common/logging.cpp b/src/common/logging.cpp index ad547832..361b3cd8 100644 --- a/src/common/logging.cpp +++ b/src/common/logging.cpp @@ -101,7 +101,7 @@ void Logger::log(const std::string& message) { } void Logger::log_get_parameter(int index) { - if (BOOST_UNLIKELY(verbosity >= Verbosity::events)) { + if (BOOST_UNLIKELY(verbosity >= Verbosity::most_events)) { std::ostringstream message; message << ">> getParameter() " << index; @@ -110,7 +110,7 @@ void Logger::log_get_parameter(int index) { } void Logger::log_get_parameter_response(float value) { - if (BOOST_UNLIKELY(verbosity >= Verbosity::events)) { + if (BOOST_UNLIKELY(verbosity >= Verbosity::most_events)) { std::ostringstream message; message << " getParameter() :: " << value; @@ -119,7 +119,7 @@ void Logger::log_get_parameter_response(float value) { } void Logger::log_set_parameter(int index, float value) { - if (BOOST_UNLIKELY(verbosity >= Verbosity::events)) { + if (BOOST_UNLIKELY(verbosity >= Verbosity::most_events)) { std::ostringstream message; message << ">> setParameter() " << index << " = " << value; @@ -128,7 +128,7 @@ void Logger::log_set_parameter(int index, float value) { } void Logger::log_set_parameter_response() { - if (BOOST_UNLIKELY(verbosity >= Verbosity::events)) { + if (BOOST_UNLIKELY(verbosity >= Verbosity::most_events)) { log(" setParameter() :: OK"); } } @@ -139,7 +139,11 @@ void Logger::log_event(bool is_dispatch, intptr_t value, const EventPayload& payload, float option) { - if (BOOST_UNLIKELY(verbosity >= Verbosity::events)) { + if (BOOST_UNLIKELY(verbosity >= Verbosity::most_events)) { + if (should_filter_event(is_dispatch, opcode)) { + return; + } + std::ostringstream message; if (is_dispatch) { message << ">> dispatch() "; @@ -190,9 +194,14 @@ void Logger::log_event(bool is_dispatch, } void Logger::log_event_response(bool is_dispatch, + int opcode, intptr_t return_value, const EventResposnePayload& payload) { - if (BOOST_UNLIKELY(verbosity >= Verbosity::events)) { + if (BOOST_UNLIKELY(verbosity >= Verbosity::most_events)) { + if (should_filter_event(is_dispatch, opcode)) { + return; + } + std::ostringstream message; if (is_dispatch) { message << " dispatch() :: "; @@ -228,6 +237,21 @@ void Logger::log_event_response(bool is_dispatch, } } +bool Logger::should_filter_event(bool is_dispatch, int opcode) { + if (verbosity >= Verbosity::all_events) { + return false; + } + + // Filter out log messages related to these events by default since they are + // called tens of times per second + if ((is_dispatch && opcode == effEditIdle) || + (!is_dispatch && opcode == audioMasterGetTime)) { + return true; + } + + return false; +} + /** * Convert an event opcode to a human readable string for debugging purposes. * See `src/include/vestige/aeffectx.h` for a complete list of these opcodes. diff --git a/src/common/logging.h b/src/common/logging.h index 8bec6209..52ee363c 100644 --- a/src/common/logging.h +++ b/src/common/logging.h @@ -45,9 +45,17 @@ class Logger { basic = 0, /** * Also print information about callbacks and functions being called by - * the plugin and the host. Every message is prefixed with a timestamp. + * the plugin and the host. This excludes the `effEditIdle()` and + * `audioMasterGetTime()` events since those events are typically sent + * tens of times per second. Every message is prefixed with a timestamp. */ - events = 1, + most_events = 1, + /** + * 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. + */ + all_events = 2, }; /** @@ -97,10 +105,17 @@ class Logger { const EventPayload& payload, float option); void log_event_response(bool is_dispatch, + int opcode, intptr_t return_value, const EventResposnePayload& payload); private: + /** + * Determine whether an event should be filtered based on the current + * verbosity level. + */ + bool should_filter_event(bool is_dispatch, int opcode); + /** * The output stream to write the log messages to. Typically either STDERR * or a file stream.