diff --git a/CMakeLists.txt b/CMakeLists.txt index 88022cf62e0..e8703488991 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -475,7 +475,6 @@ add_library(mixxx-lib STATIC EXCLUDE_FROM_ALL src/control/controlpushbutton.cpp src/control/controlttrotary.cpp src/controllers/controller.cpp - src/controllers/controllerdebug.cpp src/controllers/controllerenumerator.cpp src/controllers/controllerinputmappingtablemodel.cpp src/controllers/controllerlearningeventfilter.cpp @@ -889,6 +888,7 @@ add_library(mixxx-lib STATIC EXCLUDE_FROM_ALL src/util/readaheadsamplebuffer.cpp src/util/rlimit.cpp src/util/rotary.cpp + src/util/runtimeloggingcategory.cpp src/util/sample.cpp src/util/samplebuffer.cpp src/util/sandbox.cpp diff --git a/src/control/controlobjectscript.cpp b/src/control/controlobjectscript.cpp index 3c6a6495732..d64a780fdd9 100644 --- a/src/control/controlobjectscript.cpp +++ b/src/control/controlobjectscript.cpp @@ -1,12 +1,11 @@ #include "control/controlobjectscript.h" -#include - -#include "controllers/controllerdebug.h" #include "moc_controlobjectscript.cpp" -ControlObjectScript::ControlObjectScript(const ConfigKey& key, QObject* pParent) - : ControlProxy(key, pParent, ControllerDebug::controlFlags()) { +ControlObjectScript::ControlObjectScript( + const ConfigKey& key, const RuntimeLoggingCategory& logger, QObject* pParent) + : ControlProxy(key, pParent, ControlFlag::AllowMissingOrInvalid), + m_logger(logger) { } bool ControlObjectScript::addScriptConnection(const ScriptConnection& conn) { @@ -27,31 +26,31 @@ bool ControlObjectScript::addScriptConnection(const ScriptConnection& conn) { for (const auto& priorConnection : qAsConst(m_scriptConnections)) { if (conn == priorConnection) { - qWarning() << "Connection " + conn.id.toString() + - " already connected to (" + - conn.key.group + ", " + conn.key.item + - "). Ignoring attempt to connect again."; + qCWarning(m_logger) << "Connection " + conn.id.toString() + + " already connected to (" + + conn.key.group + ", " + conn.key.item + + "). Ignoring attempt to connect again."; return false; } } m_scriptConnections.append(conn); - controllerDebug("Connected (" + + qCDebug(m_logger) << "Connected (" + conn.key.group + ", " + conn.key.item + - ") to connection " + conn.id.toString()); + ") to connection " + conn.id.toString(); return true; } bool ControlObjectScript::removeScriptConnection(const ScriptConnection& conn) { bool success = m_scriptConnections.removeOne(conn); if (success) { - controllerDebug("Disconnected (" + + qCDebug(m_logger) << "Disconnected (" + conn.key.group + ", " + conn.key.item + - ") from connection " + conn.id.toString()); + ") from connection " + conn.id.toString(); } else { - qWarning() << "Failed to disconnect (" + - conn.key.group + ", " + conn.key.item + - ") from connection " + conn.id.toString(); + qCWarning(m_logger) << "Failed to disconnect (" + + conn.key.group + ", " + conn.key.item + + ") from connection " + conn.id.toString(); } if (m_scriptConnections.isEmpty()) { // no ScriptConnections left, so disconnect signals diff --git a/src/control/controlobjectscript.h b/src/control/controlobjectscript.h index 219a4b0a991..6f892982895 100644 --- a/src/control/controlobjectscript.h +++ b/src/control/controlobjectscript.h @@ -4,12 +4,15 @@ #include "control/controlproxy.h" #include "controllers/scripting/legacy/scriptconnection.h" +#include "util/runtimeloggingcategory.h" // this is used for communicate with controller scripts class ControlObjectScript : public ControlProxy { Q_OBJECT public: - explicit ControlObjectScript(const ConfigKey& key, QObject* pParent = nullptr); + explicit ControlObjectScript(const ConfigKey& key, + const RuntimeLoggingCategory& logger, + QObject* pParent = nullptr); bool addScriptConnection(const ScriptConnection& conn); @@ -37,4 +40,5 @@ class ControlObjectScript : public ControlProxy { private: QVector m_scriptConnections; + const RuntimeLoggingCategory m_logger; }; diff --git a/src/controllers/bulk/bulkcontroller.cpp b/src/controllers/bulk/bulkcontroller.cpp index 03e1af6a438..3bfe3f0db87 100644 --- a/src/controllers/bulk/bulkcontroller.cpp +++ b/src/controllers/bulk/bulkcontroller.cpp @@ -3,7 +3,6 @@ #include #include "controllers/bulk/bulksupported.h" -#include "controllers/controllerdebug.h" #include "controllers/defs_controllers.h" #include "moc_bulkcontroller.cpp" #include "util/time.h" @@ -63,11 +62,13 @@ static QString get_string(libusb_device_handle *handle, u_int8_t id) { return QString::fromLatin1((char*)buf); } -BulkController::BulkController( - libusb_context* context, +BulkController::BulkController(libusb_context* context, libusb_device_handle* handle, struct libusb_device_descriptor* desc) - : m_context(context), + : Controller(QString("%1 %2").arg( + get_string(handle, desc->iProduct), + get_string(handle, desc->iSerialNumber))), + m_context(context), m_phandle(handle), in_epaddr(0), out_epaddr(0) { @@ -80,8 +81,6 @@ BulkController::BulkController( setDeviceCategory(tr("USB Controller")); - setDeviceName(QString("%1 %2").arg(product, m_sUID)); - setInputDevice(true); setOutputDevice(true); m_pReader = nullptr; @@ -137,7 +136,7 @@ bool BulkController::matchProductInfo(const ProductInfo& product) { int BulkController::open() { if (isOpen()) { - qDebug() << "USB Bulk device" << getName() << "already open"; + qCWarning(m_logBase) << "USB Bulk device" << getName() << "already open"; return -1; } @@ -153,7 +152,7 @@ int BulkController::open() { } if (bulk_supported[i].vendor_id == 0) { - qWarning() << "USB Bulk device" << getName() << "unsupported"; + qCWarning(m_logBase) << "USB Bulk device" << getName() << "unsupported"; return -1; } @@ -164,7 +163,7 @@ int BulkController::open() { } if (m_phandle == nullptr) { - qWarning() << "Unable to open USB Bulk device" << getName(); + qCWarning(m_logBase) << "Unable to open USB Bulk device" << getName(); return -1; } @@ -172,7 +171,7 @@ int BulkController::open() { startEngine(); if (m_pReader != nullptr) { - qWarning() << "BulkReader already present for" << getName(); + qCWarning(m_logBase) << "BulkReader already present for" << getName(); } else { m_pReader = new BulkReader(m_phandle, in_epaddr); m_pReader->setObjectName(QString("BulkReader %1").arg(getName())); @@ -189,20 +188,20 @@ int BulkController::open() { int BulkController::close() { if (!isOpen()) { - qDebug() << " device" << getName() << "already closed"; + qCWarning(m_logBase) << " device" << getName() << "already closed"; return -1; } - qDebug() << "Shutting down USB Bulk device" << getName(); + qCInfo(m_logBase) << "Shutting down USB Bulk device" << getName(); // Stop the reading thread if (m_pReader == nullptr) { - qWarning() << "BulkReader not present for" << getName() - << "yet the device is open!"; + qCWarning(m_logBase) << "BulkReader not present for" << getName() + << "yet the device is open!"; } else { disconnect(m_pReader, &BulkReader::incomingData, this, &BulkController::receive); m_pReader->stop(); - controllerDebug(" Waiting on reader to finish"); + qCInfo(m_logBase) << " Waiting on reader to finish"; m_pReader->wait(); delete m_pReader; m_pReader = nullptr; @@ -213,7 +212,7 @@ int BulkController::close() { stopEngine(); // Close device - controllerDebug(" Closing device"); + qCInfo(m_logBase) << " Closing device"; libusb_close(m_phandle); m_phandle = nullptr; setOpen(false); @@ -239,10 +238,10 @@ void BulkController::sendBytes(const QByteArray& data) { (unsigned char *)data.constData(), data.size(), &transferred, 0); if (ret < 0) { - qWarning() << "Unable to send data to" << getName() - << "serial #" << m_sUID; + qCWarning(m_logOutput) << "Unable to send data to" << getName() + << "serial #" << m_sUID; } else { - controllerDebug(ret << "bytes sent to" << getName() - << "serial #" << m_sUID); + qCDebug(m_logOutput) << ret << "bytes sent to" << getName() + << "serial #" << m_sUID; } } diff --git a/src/controllers/controller.cpp b/src/controllers/controller.cpp index c48daf2fa14..aeb5f95d408 100644 --- a/src/controllers/controller.cpp +++ b/src/controllers/controller.cpp @@ -2,14 +2,25 @@ #include #include +#include -#include "controllers/controllerdebug.h" #include "controllers/defs_controllers.h" #include "moc_controller.cpp" #include "util/screensaver.h" -Controller::Controller() - : m_pScriptEngineLegacy(nullptr), +namespace { +QString loggingCategoryPrefix(const QString& deviceName) { + return QStringLiteral("controller.") + + RuntimeLoggingCategory::removeInvalidCharsFromCategory(deviceName.toLower()); +} +} // namespace + +Controller::Controller(const QString& deviceName) + : m_sDeviceName(deviceName), + m_logBase(loggingCategoryPrefix(deviceName)), + m_logInput(loggingCategoryPrefix(deviceName) + QStringLiteral(".input")), + m_logOutput(loggingCategoryPrefix(deviceName) + QStringLiteral(".output")), + m_pScriptEngineLegacy(nullptr), m_bIsOutputDevice(false), m_bIsInputDevice(false), m_bIsOpen(false), @@ -28,18 +39,18 @@ ControllerJSProxy* Controller::jsProxy() { void Controller::startEngine() { - controllerDebug(" Starting engine"); + qCInfo(m_logBase) << " Starting engine"; if (m_pScriptEngineLegacy) { - qWarning() << "Controller: Engine already exists! Restarting:"; + qCWarning(m_logBase) << "Controller: Engine already exists! Restarting:"; stopEngine(); } - m_pScriptEngineLegacy = new ControllerScriptEngineLegacy(this); + m_pScriptEngineLegacy = new ControllerScriptEngineLegacy(this, m_logBase); } void Controller::stopEngine() { - controllerDebug(" Shutting down engine"); + qCInfo(m_logBase) << " Shutting down engine"; if (!m_pScriptEngineLegacy) { - qWarning() << "Controller::stopEngine(): No engine exists!"; + qCWarning(m_logBase) << "Controller::stopEngine(): No engine exists!"; return; } delete m_pScriptEngineLegacy; @@ -47,19 +58,21 @@ void Controller::stopEngine() { } bool Controller::applyMapping() { - qDebug() << "Applying controller mapping..."; + qCInfo(m_logBase) << "Applying controller mapping..."; const std::shared_ptr pMapping = cloneMapping(); // Load the script code into the engine if (!m_pScriptEngineLegacy) { - qWarning() << "Controller::applyMapping(): No engine exists!"; + qCWarning(m_logBase) << "Controller::applyMapping(): No engine exists!"; return false; } QList scriptFiles = pMapping->getScriptFiles(); if (scriptFiles.isEmpty()) { - qWarning() << "No script functions available! Did the XML file(s) load successfully? See above for any errors."; + qCWarning(m_logBase) + << "No script functions available! Did the XML file(s) load " + "successfully? See above for any errors."; return true; } @@ -68,7 +81,7 @@ bool Controller::applyMapping() { } void Controller::startLearning() { - qDebug() << m_sDeviceName << "started learning"; + qCDebug(m_logBase) << m_sDeviceName << "started learning"; m_bLearning = true; } @@ -110,11 +123,10 @@ void Controller::receive(const QByteArray& data, mixxx::Duration timestamp) { triggerActivity(); int length = data.size(); - if (ControllerDebug::isEnabled()) { + if (m_logInput().isDebugEnabled()) { // Formatted packet display - QString message = QString("%1: t:%2, %3 bytes:\n") - .arg(m_sDeviceName, - timestamp.formatMillisWithUnit(), + QString message = QString("t:%2, %3 bytes:\n") + .arg(timestamp.formatMillisWithUnit(), QString::number(length)); for (int i = 0; i < length; i++) { QString spacer; @@ -131,7 +143,7 @@ void Controller::receive(const QByteArray& data, mixxx::Duration timestamp) { .rightJustified(2, QChar('0')) + spacer; } - controllerDebug(message); + qCDebug(m_logInput).noquote() << message; } m_pScriptEngineLegacy->handleIncomingData(data); diff --git a/src/controllers/controller.h b/src/controllers/controller.h index 6d764bb4a9c..8838450119d 100644 --- a/src/controllers/controller.h +++ b/src/controllers/controller.h @@ -1,6 +1,7 @@ #pragma once #include +#include #include #include "controllers/controllermappinginfo.h" @@ -8,6 +9,7 @@ #include "controllers/legacycontrollermappingfilehandler.h" #include "controllers/scripting/legacy/controllerscriptenginelegacy.h" #include "util/duration.h" +#include "util/runtimeloggingcategory.h" class ControllerJSProxy; @@ -17,7 +19,7 @@ class ControllerJSProxy; class Controller : public QObject { Q_OBJECT public: - explicit Controller(); + explicit Controller(const QString& deviceName); ~Controller() override; // Subclass should call close() at minimum. /// The object that is exposed to the JS scripts as the "controller" object. @@ -118,9 +120,6 @@ class Controller : public QObject { inline ControllerScriptEngineLegacy* getScriptEngine() const { return m_pScriptEngineLegacy; } - inline void setDeviceName(const QString& deviceName) { - m_sDeviceName = deviceName; - } inline void setDeviceCategory(const QString& deviceCategory) { m_sDeviceCategory = deviceCategory; } @@ -135,6 +134,11 @@ class Controller : public QObject { emit openChanged(m_bIsOpen); } + const QString m_sDeviceName; + const RuntimeLoggingCategory m_logBase; + const RuntimeLoggingCategory m_logInput; + const RuntimeLoggingCategory m_logOutput; + private: // but used by ControllerManager virtual int open() = 0; @@ -152,8 +156,6 @@ class Controller : public QObject { private: ControllerScriptEngineLegacy* m_pScriptEngineLegacy; - // Verbose and unique device name suitable for display. - QString m_sDeviceName; // Verbose and unique description of device type, defaults to empty QString m_sDeviceCategory; // Flag indicating if this device supports output (receiving data from diff --git a/src/controllers/controllerdebug.cpp b/src/controllers/controllerdebug.cpp deleted file mode 100644 index ce71d4381cf..00000000000 --- a/src/controllers/controllerdebug.cpp +++ /dev/null @@ -1,13 +0,0 @@ -#include "controllers/controllerdebug.h" - -#include "util/cmdlineargs.h" - - -//static -bool ControllerDebug::s_enabled = false; -bool ControllerDebug::s_testing = false; - -//static -bool ControllerDebug::isEnabled() { - return s_enabled || CmdlineArgs::Instance().getMidiDebug(); -} diff --git a/src/controllers/controllerdebug.h b/src/controllers/controllerdebug.h deleted file mode 100644 index 16fe5918c76..00000000000 --- a/src/controllers/controllerdebug.h +++ /dev/null @@ -1,61 +0,0 @@ -#pragma once - -#include - -#include "control/control.h" - -// Specifies whether or not we should dump incoming data to the console at -// runtime. This is useful for end-user debugging and script-writing. -class ControllerDebug { - public: - // Any debug statement starting with this prefix bypasses the --logLevel - // command line flags. - static constexpr const char kLogMessagePrefix[] = "CDBG"; - static constexpr int kLogMessagePrefixLength = sizeof(kLogMessagePrefix) - 1; - - static bool isEnabled(); - - /// Override the command-line argument (for testing) - static void setEnabled(bool enabled) { - s_enabled = enabled; - } - - static void setTesting(bool isTesting) { - s_testing = isTesting; - } - - /// Return the appropriate flag for ControlProxies in mappings. - /// - /// Normally, accessing an invalid control from a mapping should *not* - /// throw a debug assertion because controller mappings are considered - /// user data. If we're testing or controller debugging is enabled, we *do* - /// want assertions to prevent overlooking bugs in controller mappings. - static ControlFlags controlFlags() { - if (s_enabled || s_testing) { - return ControlFlag::None; - } - - return ControlFlag::AllowMissingOrInvalid; - } - - private: - ControllerDebug() = delete; - - static bool s_enabled; - static bool s_testing; -}; - -// Usage: controllerDebug("hello" << "world"); -// -// We prefix every log message with Logging::kControllerDebugPrefix so that we -// can bypass the --logLevel commandline argument when --controllerDebug is -// specified. -// -// In order of Bug #1797746, since transition to qt5 it is needed unquote the -// output for mixxx.log with .noquote(), because in qt5 QDebug() is quoted by default. -#define controllerDebug(stream) \ - { \ - if (ControllerDebug::isEnabled()) { \ - QDebug(QtDebugMsg).noquote() << ControllerDebug::kLogMessagePrefix << stream; \ - } \ - } diff --git a/src/controllers/hid/hidcontroller.cpp b/src/controllers/hid/hidcontroller.cpp index e86290c6b34..e243029fa34 100644 --- a/src/controllers/hid/hidcontroller.cpp +++ b/src/controllers/hid/hidcontroller.cpp @@ -2,7 +2,6 @@ #include -#include "controllers/controllerdebug.h" #include "controllers/defs_controllers.h" #include "controllers/hid/legacyhidcontrollermappingfilehandler.h" #include "moc_hidcontroller.cpp" @@ -17,11 +16,11 @@ constexpr int kMaxHidErrorMessageSize = 512; HidController::HidController( mixxx::hid::DeviceInfo&& deviceInfo) - : m_deviceInfo(std::move(deviceInfo)), + : Controller(deviceInfo.formatName()), + m_deviceInfo(std::move(deviceInfo)), m_pHidDevice(nullptr), m_pollingBufferIndex(0) { setDeviceCategory(mixxx::hid::DeviceCategory::guessFromDeviceInfo(m_deviceInfo)); - setDeviceName(m_deviceInfo.formatName()); // All HID devices are full-duplex setInputDevice(true); @@ -66,16 +65,16 @@ int HidController::open() { } // Open device by path - controllerDebug("Opening HID device" << getName() << "by HID path" - << m_deviceInfo.pathRaw()); + qCInfo(m_logBase) << "Opening HID device" << getName() << "by HID path" + << m_deviceInfo.pathRaw(); m_pHidDevice = hid_open_path(m_deviceInfo.pathRaw()); // If that fails, try to open device with vendor/product/serial # if (!m_pHidDevice) { - controllerDebug("Failed. Trying to open with make, model & serial no:" - << m_deviceInfo.vendorId() << m_deviceInfo.productId() - << m_deviceInfo.serialNumber()); + qCWarning(m_logBase) << "Failed. Trying to open with make, model & serial no:" + << m_deviceInfo.vendorId() << m_deviceInfo.productId() + << m_deviceInfo.serialNumber(); m_pHidDevice = hid_open( m_deviceInfo.vendorId(), m_deviceInfo.productId(), @@ -85,9 +84,9 @@ int HidController::open() { // If it does fail, try without serial number WARNING: This will only open // one of multiple identical devices if (!m_pHidDevice) { - qWarning() << "Unable to open specific HID device" << getName() - << "Trying now with just make and model." - << "(This may only open the first of multiple identical devices.)"; + qCWarning(m_logBase) << "Unable to open specific HID device" << getName() + << "Trying now with just make and model." + << "(This may only open the first of multiple identical devices.)"; m_pHidDevice = hid_open(m_deviceInfo.vendorId(), m_deviceInfo.productId(), nullptr); @@ -95,13 +94,13 @@ int HidController::open() { // If that fails, we give up! if (!m_pHidDevice) { - qWarning() << "Unable to open HID device" << getName(); + qCWarning(m_logBase) << "Unable to open HID device" << getName(); return -1; } // Set hid controller to non-blocking if (hid_set_nonblocking(m_pHidDevice, 1) != 0) { - qWarning() << "Unable to set HID device " << getName() << " to non-blocking"; + qCWarning(m_logBase) << "Unable to set HID device " << getName() << " to non-blocking"; return -1; } @@ -119,18 +118,18 @@ int HidController::open() { int HidController::close() { if (!isOpen()) { - qDebug() << "HID device" << getName() << "already closed"; + qCWarning(m_logBase) << "HID device" << getName() << "already closed"; return -1; } - qDebug() << "Shutting down HID device" << getName(); + qCInfo(m_logBase) << "Shutting down HID device" << getName(); // Stop controller engine here to ensure it's done before the device is closed // in case it has any final parting messages stopEngine(); // Close device - controllerDebug(" Closing device"); + qCInfo(m_logBase) << "Closing device"; hid_close(m_pHidDevice); setOpen(false); return 0; @@ -172,14 +171,14 @@ QList HidController::getInputReport(unsigned int reportID) { // https://github.com/libusb/hidapi/issues/259 bytesRead = hid_get_input_report(m_pHidDevice, m_pPollData[m_pollingBufferIndex], kBufferSize); - controllerDebug(bytesRead - << "bytes received by hid_get_input_report" << getName() - << "serial #" << m_deviceInfo.serialNumber() - << "(including one byte for the report ID:" - << QString::number(static_cast(reportID), 16) - .toUpper() - .rightJustified(2, QChar('0')) - << ")"); + qCDebug(m_logInput) << bytesRead + << "bytes received by hid_get_input_report" << getName() + << "serial #" << m_deviceInfo.serialNumber() + << "(including one byte for the report ID:" + << QString::number(static_cast(reportID), 16) + .toUpper() + .rightJustified(2, QChar('0')) + << ")"; if (bytesRead <= kReportIdSize) { // -1 is the only error value according to hidapi documentation. @@ -244,22 +243,14 @@ void HidController::sendBytesReport(QByteArray data, unsigned int reportID) { int result = hid_write(m_pHidDevice, (unsigned char*)data.constData(), data.size()); if (result == -1) { - if (ControllerDebug::isEnabled()) { - qWarning() << "Unable to send data to" << getName() - << "serial #" << m_deviceInfo.serialNumber() << ":" - << mixxx::convertWCStringToQString( - hid_error(m_pHidDevice), - kMaxHidErrorMessageSize); - } else { - qWarning() << "Unable to send data to" << getName() << ":" - << mixxx::convertWCStringToQString( - hid_error(m_pHidDevice), - kMaxHidErrorMessageSize); - } + qCWarning(m_logOutput) << "Unable to send data to" << getName() << ":" + << mixxx::convertWCStringToQString( + hid_error(m_pHidDevice), + kMaxHidErrorMessageSize); } else { - controllerDebug(result << "bytes sent to" << getName() - << "serial #" << m_deviceInfo.serialNumber() - << "(including report ID of" << reportID << ")"); + qCDebug(m_logOutput) << result << "bytes sent to" << getName() + << "serial #" << m_deviceInfo.serialNumber() + << "(including report ID of" << reportID << ")"; } } @@ -279,16 +270,16 @@ void HidController::sendFeatureReport( reinterpret_cast(dataArray.constData()), dataArray.size()); if (result == -1) { - qWarning() << "sendFeatureReport is unable to send data to" - << getName() << "serial #" << m_deviceInfo.serialNumber() - << ":" - << mixxx::convertWCStringToQString( - hid_error(m_pHidDevice), - kMaxHidErrorMessageSize); + qCWarning(m_logOutput) << "sendFeatureReport is unable to send data to" + << getName() << "serial #" << m_deviceInfo.serialNumber() + << ":" + << mixxx::convertWCStringToQString( + hid_error(m_pHidDevice), + kMaxHidErrorMessageSize); } else { - controllerDebug(result << "bytes sent by sendFeatureReport to" << getName() - << "serial #" << m_deviceInfo.serialNumber() - << "(including report ID of" << reportID << ")"); + qCDebug(m_logOutput) << result << "bytes sent by sendFeatureReport to" << getName() + << "serial #" << m_deviceInfo.serialNumber() + << "(including report ID of" << reportID << ")"; } } @@ -309,20 +300,20 @@ QList HidController::getFeatureReport( // -1 is the only error value according to hidapi documentation. // Otherwise minimum possible value is 1, because 1 byte is for the reportID, // the smallest report with data is therefore 2 bytes. - qWarning() << "getFeatureReport is unable to get data from" << getName() - << "serial #" << m_deviceInfo.serialNumber() << ":" - << mixxx::convertWCStringToQString( - hid_error(m_pHidDevice), - kMaxHidErrorMessageSize); + qCWarning(m_logInput) << "getFeatureReport is unable to get data from" << getName() + << "serial #" << m_deviceInfo.serialNumber() << ":" + << mixxx::convertWCStringToQString( + hid_error(m_pHidDevice), + kMaxHidErrorMessageSize); } else { - controllerDebug(bytesRead - << "bytes received by getFeatureReport from" << getName() - << "serial #" << m_deviceInfo.serialNumber() - << "(including one byte for the report ID:" - << QString::number(static_cast(reportID), 16) - .toUpper() - .rightJustified(2, QChar('0')) - << ")") + qCDebug(m_logInput) << bytesRead + << "bytes received by getFeatureReport from" << getName() + << "serial #" << m_deviceInfo.serialNumber() + << "(including one byte for the report ID:" + << QString::number(static_cast(reportID), 16) + .toUpper() + .rightJustified(2, QChar('0')) + << ")"; } // Convert array of bytes read in a JavaScript compatible return type diff --git a/src/controllers/midi/hss1394controller.cpp b/src/controllers/midi/hss1394controller.cpp index 95fd45ab676..15e2c8e9b52 100644 --- a/src/controllers/midi/hss1394controller.cpp +++ b/src/controllers/midi/hss1394controller.cpp @@ -1,6 +1,5 @@ #include "controllers/midi/hss1394controller.h" -#include "controllers/controllerdebug.h" #include "controllers/midi/midiutils.h" #include "moc_hss1394controller.cpp" #include "util/time.h" @@ -60,14 +59,9 @@ void DeviceChannelListener::Reconnected() { Hss1394Controller::Hss1394Controller( const hss1394::TNodeInfo& deviceInfo, int deviceIndex) - : MidiController(), + : MidiController(QString::fromLocal8Bit(deviceInfo.sName.c_str())), m_deviceInfo(deviceInfo), m_iDeviceIndex(deviceIndex) { - // Note: We prepend the input stream's index to the device's name to prevent - // duplicate devices from causing mayhem. - //setDeviceName(QString("H%1. %2").arg(QString::number(m_iDeviceIndex), QString(deviceInfo.sName.c_str()))); - setDeviceName(QString("%1").arg(QString(deviceInfo.sName.c_str()))); - // All HSS1394 devices are full-duplex setInputDevice(true); setOutputDevice(true); @@ -81,7 +75,7 @@ Hss1394Controller::~Hss1394Controller() { int Hss1394Controller::open() { if (isOpen()) { - qDebug() << "HSS1394 device" << getName() << "already open"; + qCWarning(m_logBase) << "HSS1394 device" << getName() << "already open"; return -1; } @@ -89,14 +83,14 @@ int Hss1394Controller::open() { return -1; } - controllerDebug("Hss1394Controller: Opening" << getName() << "index" - << m_iDeviceIndex); + qCInfo(m_logBase) << "Hss1394Controller: Opening" << getName() << "index" + << m_iDeviceIndex; using namespace hss1394; m_pChannel = Node::Instance()->OpenChannel(m_iDeviceIndex); if (m_pChannel == NULL) { - qDebug() << "HSS1394 device" << getName() << "could not be opened"; + qCWarning(m_logBase) << "HSS1394 device" << getName() << "could not be opened"; m_pChannelListener = NULL; return -1; } @@ -112,7 +106,9 @@ int Hss1394Controller::open() { &Hss1394Controller::receive); if (!m_pChannel->InstallChannelListener(m_pChannelListener)) { - qDebug() << "HSS1394 channel listener could not be installed for device" << getName(); + qCWarning(m_logBase) + << "HSS1394 channel listener could not be installed for device" + << getName(); delete m_pChannelListener; m_pChannelListener = NULL; m_pChannel = NULL; @@ -140,7 +136,7 @@ int Hss1394Controller::open() { int Hss1394Controller::close() { if (!isOpen()) { - qDebug() << "HSS1394 device" << getName() << "already closed"; + qCWarning(m_logBase) << "HSS1394 device" << getName() << "already closed"; return -1; } @@ -159,7 +155,7 @@ int Hss1394Controller::close() { // Clean up the HSS1394Node using namespace hss1394; if (!Node::Instance()->ReleaseChannel(m_pChannel)) { - qDebug() << "HSS1394 device" << getName() << "could not be released"; + qCWarning(m_logBase) << "HSS1394 device" << getName() << "could not be released"; return -1; } if (m_pChannelListener != NULL) { @@ -176,15 +172,15 @@ void Hss1394Controller::sendShortMsg(unsigned char status, unsigned char byte1, const unsigned char data[3] = {status, byte1, byte2}; int bytesSent = m_pChannel->SendChannelBytes(data, 3); - controllerDebug(MidiUtils::formatMidiOpCode(getName(), + qCDebug(m_logOutput) << MidiUtils::formatMidiOpCode(getName(), status, byte1, byte2, MidiUtils::channelFromStatus(status), - MidiUtils::opCodeFromStatus(status))); + MidiUtils::opCodeFromStatus(status)); if (bytesSent != 3) { - qWarning() << "Sent" << bytesSent << "of 3 bytes:" << status << byte1 << byte2; + qCWarning(m_logOutput) << "Sent" << bytesSent << "of 3 bytes:" << status << byte1 << byte2; //m_pChannel->Flush(); } } @@ -193,9 +189,9 @@ void Hss1394Controller::sendBytes(const QByteArray& data) { const int bytesSent = m_pChannel->SendChannelBytes( reinterpret_cast(data.constData()), data.size()); - controllerDebug(MidiUtils::formatSysexMessage(getName(), data)); + qCDebug(m_logOutput) << MidiUtils::formatSysexMessage(getName(), data); if (bytesSent != data.size()) { - qWarning() << "Sent" << bytesSent << "of" << data.size() << "bytes (SysEx)"; + qCWarning(m_logOutput) << "Sent" << bytesSent << "of" << data.size() << "bytes (SysEx)"; //m_pChannel->Flush(); } } diff --git a/src/controllers/midi/midicontroller.cpp b/src/controllers/midi/midicontroller.cpp index 96b27172c1b..3131cb50244 100644 --- a/src/controllers/midi/midicontroller.cpp +++ b/src/controllers/midi/midicontroller.cpp @@ -1,7 +1,6 @@ #include "controllers/midi/midicontroller.h" #include "control/controlobject.h" -#include "controllers/controllerdebug.h" #include "controllers/defs_controllers.h" #include "controllers/midi/midiutils.h" #include "defs_urls.h" @@ -11,8 +10,8 @@ #include "util/math.h" #include "util/screensaver.h" -MidiController::MidiController() - : Controller() { +MidiController::MidiController(const QString& deviceName) + : Controller(deviceName) { setDeviceCategory(tr("MIDI Controller")); } @@ -88,16 +87,25 @@ void MidiController::createOutputHandlers() { double min = mapping.output.min; double max = mapping.output.max; - controllerDebug(QString( - "Creating output handler for %1,%2 between %3 and %4 to MIDI out: 0x%5 0x%6, on: 0x%7 off: 0x%8") - .arg(group, key, - QString::number(min), QString::number(max), - QString::number(status, 16).toUpper(), - QString::number(control, 16).toUpper().rightJustified(2,'0'), - QString::number(on, 16).toUpper().rightJustified(2,'0'), - QString::number(off, 16).toUpper().rightJustified(2,'0'))); - - MidiOutputHandler* moh = new MidiOutputHandler(this, mapping); + qCDebug(m_logBase) + << QString("Creating output handler for %1,%2 between %3 and " + "%4 to MIDI out: 0x%5 0x%6, on: 0x%7 off: 0x%8") + .arg(group, + key, + QString::number(min), + QString::number(max), + QString::number(status, 16).toUpper(), + QString::number(control, 16) + .toUpper() + .rightJustified(2, '0'), + QString::number(on, 16) + .toUpper() + .rightJustified(2, '0'), + QString::number(off, 16) + .toUpper() + .rightJustified(2, '0')); + + MidiOutputHandler* moh = new MidiOutputHandler(this, mapping, m_logOutput); if (!moh->validate()) { QString errorLog = QString("MIDI output message 0x%1 0x%2 has invalid MixxxControl %3, %4") @@ -106,10 +114,10 @@ void MidiController::createOutputHandlers() { group, key) .toUtf8(); - qWarning() << errorLog; + qCWarning(m_logBase) << errorLog; int deckNum = 0; - if (ControllerDebug::isEnabled()) { + if (m_logBase().isDebugEnabled()) { failures.append(errorLog); } else if (PlayerManager::isDeckGroup(group, &deckNum)) { int numDecks = PlayerManager::numDecks(); @@ -219,8 +227,8 @@ void MidiController::receivedShortMessage(unsigned char status, return; } - controllerDebug(MidiUtils::formatMidiOpCode( - getName(), status, control, value, channel, opCode, timestamp)); + qCDebug(m_logInput) << MidiUtils::formatMidiOpCode( + getName(), status, control, value, channel, opCode, timestamp); MidiKey mappingKey(status, control); triggerActivity(); @@ -265,8 +273,8 @@ void MidiController::processInputMapping(const MidiInputMapping& mapping, args << QJSValue(status); args << QJSValue(mapping.control.group); if (!pEngine->executeFunction(function, args)) { - qDebug() << "MidiController: Invalid script function" - << mapping.control.item; + qCWarning(m_logBase) << "MidiController: Invalid script function" + << mapping.control.item; } return; } @@ -282,9 +290,9 @@ void MidiController::processInputMapping(const MidiInputMapping& mapping, const bool mapping_is_14bit = mapping.options & (MidiOption::FourteenBitMSB | MidiOption::FourteenBitLSB); if (!mapping_is_14bit && !m_fourteen_bit_queued_mappings.isEmpty()) { - qWarning() << "MidiController was waiting for the MSB/LSB of a 14-bit" - << "message but the next message received was not mapped as 14-bit." - << "Ignoring the original message."; + qCWarning(m_logBase) << "MidiController was waiting for the MSB/LSB of a 14-bit" + << "message but the next message received was not mapped as 14-bit." + << "Ignoring the original message."; m_fourteen_bit_queued_mappings.clear(); } @@ -297,8 +305,10 @@ void MidiController::processInputMapping(const MidiInputMapping& mapping, if (it->first.control == mapping.control) { if ((it->first.options & mapping.options) & (MidiOption::FourteenBitLSB | MidiOption::FourteenBitMSB)) { - qWarning() << "MidiController: 14-bit MIDI mapping has mis-matched LSB/MSB options." - << "Ignoring both messages."; + qCWarning(m_logBase) + << "MidiController: 14-bit MIDI mapping has " + "mis-matched LSB/MSB options." + << "Ignoring both messages."; m_fourteen_bit_queued_mappings.erase(it); return; } @@ -475,7 +485,7 @@ double MidiController::computeValue( } void MidiController::receive(const QByteArray& data, mixxx::Duration timestamp) { - controllerDebug(MidiUtils::formatSysexMessage(getName(), data, timestamp)); + qCDebug(m_logInput) << MidiUtils::formatSysexMessage(getName(), data, timestamp); MidiKey mappingKey(data.at(0), 0xFF); @@ -513,6 +523,6 @@ void MidiController::processInputMapping(const MidiInputMapping& mapping, pEngine->handleIncomingData(data); return; } - qWarning() << "MidiController: No script function specified for" - << MidiUtils::formatSysexMessage(getName(), data, timestamp); + qCWarning(m_logBase) << "MidiController: No script function specified for" + << MidiUtils::formatSysexMessage(getName(), data, timestamp); } diff --git a/src/controllers/midi/midicontroller.h b/src/controllers/midi/midicontroller.h index e7b3a8f06a6..513b1a38d46 100644 --- a/src/controllers/midi/midicontroller.h +++ b/src/controllers/midi/midicontroller.h @@ -18,7 +18,7 @@ class DlgControllerLearning; class MidiController : public Controller { Q_OBJECT public: - explicit MidiController(); + explicit MidiController(const QString& deviceName); ~MidiController() override; ControllerJSProxy* jsProxy() override; diff --git a/src/controllers/midi/midioutputhandler.cpp b/src/controllers/midi/midioutputhandler.cpp index bf3bb4dc012..f104a8c4b42 100644 --- a/src/controllers/midi/midioutputhandler.cpp +++ b/src/controllers/midi/midioutputhandler.cpp @@ -3,23 +3,24 @@ #include #include "control/controlobject.h" -#include "controllers/controllerdebug.h" #include "controllers/midi/midicontroller.h" #include "moc_midioutputhandler.cpp" MidiOutputHandler::MidiOutputHandler(MidiController* controller, - const MidiOutputMapping& mapping) + const MidiOutputMapping& mapping, + const RuntimeLoggingCategory& logger) : m_pController(controller), m_mapping(mapping), m_cos(mapping.controlKey, this, ControlFlag::NoAssertIfMissing), - m_lastVal(-1) { // -1 = virgin + m_lastVal(-1), // arbitrary invalid MIDI value + m_logger(logger) { m_cos.connectValueChanged(this, &MidiOutputHandler::controlChanged); } MidiOutputHandler::~MidiOutputHandler() { ConfigKey cKey = m_cos.getKey(); - controllerDebug(QString("Destroying static MIDI output handler on %1 for %2,%3") - .arg(m_pController->getName(), cKey.group, cKey.item)); + qCDebug(m_logger) << QString("Destroying static MIDI output handler on %1 for %2,%3") + .arg(m_pController->getName(), cKey.group, cKey.item); } bool MidiOutputHandler::validate() { @@ -45,11 +46,11 @@ void MidiOutputHandler::controlChanged(double value) { } if (!m_pController->isOpen()) { - qWarning() << "MIDI device" << m_pController->getName() << "not open for output!"; + qCWarning(m_logger) << "MIDI device" << m_pController->getName() << "not open for output!"; } else if (byte3 != 0xFF) { - controllerDebug("sending MIDI bytes:" << m_mapping.output.status - << "," << m_mapping.output.control << "," - << byte3); + qCDebug(m_logger) << "sending MIDI bytes:" << m_mapping.output.status + << "," << m_mapping.output.control << "," + << byte3; m_pController->sendShortMsg(m_mapping.output.status, m_mapping.output.control, byte3); m_lastVal = static_cast(byte3); diff --git a/src/controllers/midi/midioutputhandler.h b/src/controllers/midi/midioutputhandler.h index dc64911d029..6f1957fb948 100644 --- a/src/controllers/midi/midioutputhandler.h +++ b/src/controllers/midi/midioutputhandler.h @@ -2,6 +2,7 @@ #include "control/controlproxy.h" #include "controllers/midi/midimessage.h" +#include "util/runtimeloggingcategory.h" class MidiController; @@ -13,7 +14,8 @@ class MidiOutputHandler : public QObject { Q_OBJECT public: MidiOutputHandler(MidiController* controller, - const MidiOutputMapping& mapping); + const MidiOutputMapping& mapping, + const RuntimeLoggingCategory& logger); virtual ~MidiOutputHandler(); bool validate(); @@ -27,4 +29,5 @@ class MidiOutputHandler : public QObject { const MidiOutputMapping m_mapping; ControlProxy m_cos; int m_lastVal; + const RuntimeLoggingCategory m_logger; }; diff --git a/src/controllers/midi/portmidicontroller.cpp b/src/controllers/midi/portmidicontroller.cpp index 4abfc33b14f..2de0d6af35e 100644 --- a/src/controllers/midi/portmidicontroller.cpp +++ b/src/controllers/midi/portmidicontroller.cpp @@ -1,14 +1,23 @@ #include "controllers/midi/portmidicontroller.h" -#include "controllers/controllerdebug.h" #include "controllers/midi/midiutils.h" #include "moc_portmidicontroller.cpp" +namespace { +const QString kUnknownControllerName = QStringLiteral("Unknown PortMidiController"); +} + PortMidiController::PortMidiController(const PmDeviceInfo* inputDeviceInfo, const PmDeviceInfo* outputDeviceInfo, int inputDeviceIndex, int outputDeviceIndex) - : MidiController(), m_cReceiveMsg_index(0), m_bInSysex(false) { + : MidiController((inputDeviceInfo || outputDeviceInfo) + ? QString::fromLocal8Bit(inputDeviceInfo + ? inputDeviceInfo->name + : outputDeviceInfo->name) + : kUnknownControllerName), + m_cReceiveMsg_index(0), + m_bInSysex(false) { for (unsigned int k = 0; k < MIXXX_PORTMIDI_BUFFER_LEN; ++k) { // Can be shortened to `m_midiBuffer[k] = {}` with C++11. m_midiBuffer[k].message = 0; @@ -19,15 +28,11 @@ PortMidiController::PortMidiController(const PmDeviceInfo* inputDeviceInfo, // duplicate devices from causing mayhem. //setDeviceName(QString("%1. %2").arg(QString::number(m_iInputDeviceIndex), inputDeviceInfo->name)); if (inputDeviceInfo) { - setDeviceName(QString("%1").arg(inputDeviceInfo->name)); setInputDevice(inputDeviceInfo->input); m_pInputDevice.reset(new PortMidiDevice( inputDeviceInfo, inputDeviceIndex)); } if (outputDeviceInfo) { - if (inputDeviceInfo == nullptr) { - setDeviceName(QString("%1").arg(outputDeviceInfo->name)); - } setOutputDevice(outputDeviceInfo->output); m_pOutputDevice.reset(new PortMidiDevice( outputDeviceInfo, outputDeviceIndex)); @@ -42,7 +47,7 @@ PortMidiController::~PortMidiController() { int PortMidiController::open() { if (isOpen()) { - qDebug() << "PortMIDI device" << getName() << "already open"; + qCWarning(m_logBase) << "PortMIDI device" << getName() << "already open"; return -1; } @@ -54,24 +59,24 @@ int PortMidiController::open() { m_cReceiveMsg_index = 0; if (m_pInputDevice && isInputDevice()) { - controllerDebug("PortMidiController: Opening" - << m_pInputDevice->info()->name << "index" - << m_pInputDevice->index() << "for input"); + qCInfo(m_logBase) << "PortMidiController: Opening" + << m_pInputDevice->info()->name << "index" + << m_pInputDevice->index() << "for input"; PmError err = m_pInputDevice->openInput(MIXXX_PORTMIDI_BUFFER_LEN); if (err != pmNoError) { - qWarning() << "PortMidi error:" << Pm_GetErrorText(err); + qCWarning(m_logBase) << "PortMidi error:" << Pm_GetErrorText(err); return -2; } } if (m_pOutputDevice && isOutputDevice()) { - controllerDebug("PortMidiController: Opening" - << m_pOutputDevice->info()->name << "index" - << m_pOutputDevice->index() << "for output"); + qCInfo(m_logBase) << "PortMidiController: Opening" + << m_pOutputDevice->info()->name << "index" + << m_pOutputDevice->index() << "for output"; PmError err = m_pOutputDevice->openOutput(); if (err != pmNoError) { - qWarning() << "PortMidi error:" << Pm_GetErrorText(err); + qCWarning(m_logBase) << "PortMidi error:" << Pm_GetErrorText(err); return -2; } } @@ -83,7 +88,7 @@ int PortMidiController::open() { int PortMidiController::close() { if (!isOpen()) { - qDebug() << "PortMIDI device" << getName() << "already closed"; + qCWarning(m_logBase) << "PortMIDI device" << getName() << "already closed"; return -1; } @@ -95,7 +100,7 @@ int PortMidiController::close() { if (m_pInputDevice && m_pInputDevice->isOpen()) { PmError err = m_pInputDevice->close(); if (err != pmNoError) { - qWarning() << "PortMidi error:" << Pm_GetErrorText(err); + qCWarning(m_logBase) << "PortMidi error:" << Pm_GetErrorText(err); result = -1; } } @@ -103,7 +108,7 @@ int PortMidiController::close() { if (m_pOutputDevice && m_pOutputDevice->isOpen()) { PmError err = m_pOutputDevice->close(); if (err != pmNoError) { - qWarning() << "PortMidi error:" << Pm_GetErrorText(err); + qCWarning(m_logBase) << "PortMidi error:" << Pm_GetErrorText(err); result = -1; } } @@ -123,7 +128,7 @@ bool PortMidiController::poll() { //qDebug() << "PortMidiController::poll()" << numEvents; if (numEvents < 0) { - qWarning() << "PortMidi error:" << Pm_GetErrorText((PmError)numEvents); + qCWarning(m_logInput) << "PortMidi error:" << Pm_GetErrorText((PmError)numEvents); return false; } @@ -157,7 +162,7 @@ bool PortMidiController::poll() { if (status > 0x7F && status < 0xF7) { m_bInSysex = false; m_cReceiveMsg_index = 0; - qWarning() << "Buggy MIDI device: SysEx interrupted!"; + qCWarning(m_logInput) << "Buggy MIDI device: SysEx interrupted!"; goto reprocessMessage; // Don't lose the new message } @@ -199,22 +204,22 @@ void PortMidiController::sendShortMsg(unsigned char status, unsigned char byte1, PmError err = m_pOutputDevice->writeShort(word); if (err == pmNoError) { - controllerDebug(MidiUtils::formatMidiOpCode(getName(), + qCDebug(m_logOutput) << MidiUtils::formatMidiOpCode(getName(), status, byte1, byte2, MidiUtils::channelFromStatus(status), - MidiUtils::opCodeFromStatus(status))); + MidiUtils::opCodeFromStatus(status)); } else { // Use two qWarnings() to ensure line break works on all operating systems - qWarning() << "Error sending short message" - << MidiUtils::formatMidiOpCode(getName(), - status, - byte1, - byte2, - MidiUtils::channelFromStatus(status), - MidiUtils::opCodeFromStatus(status)); - qWarning() << "PortMidi error:" << Pm_GetErrorText(err); + qCWarning(m_logOutput) << "Error sending short message" + << MidiUtils::formatMidiOpCode(getName(), + status, + byte1, + byte2, + MidiUtils::channelFromStatus(status), + MidiUtils::opCodeFromStatus(status)); + qCWarning(m_logOutput) << "PortMidi error:" << Pm_GetErrorText(err); } } @@ -224,7 +229,7 @@ void PortMidiController::sendBytes(const QByteArray& data) { // to know when the message is over. If one is not provided, it will // overflow the buffer and cause a segfault. if (!data.endsWith(MidiUtils::opCodeValue(MidiOpCode::EndOfExclusive))) { - controllerDebug("SysEx message does not end with 0xF7 -- ignoring."); + qCDebug(m_logOutput) << "SysEx message does not end with 0xF7 -- ignoring."; return; } @@ -234,11 +239,11 @@ void PortMidiController::sendBytes(const QByteArray& data) { PmError err = m_pOutputDevice->writeSysEx((unsigned char*)data.constData()); if (err == pmNoError) { - controllerDebug(MidiUtils::formatSysexMessage(getName(), data)); + qCDebug(m_logOutput) << MidiUtils::formatSysexMessage(getName(), data); } else { // Use two qWarnings() to ensure line break works on all operating systems - qWarning() << "Error sending SysEx message:" - << MidiUtils::formatSysexMessage(getName(), data); - qWarning() << "PortMidi error:" << Pm_GetErrorText(err); + qCWarning(m_logOutput) << "Error sending SysEx message:" + << MidiUtils::formatSysexMessage(getName(), data); + qCWarning(m_logOutput) << "PortMidi error:" << Pm_GetErrorText(err); } } diff --git a/src/controllers/scripting/controllerscriptenginebase.cpp b/src/controllers/scripting/controllerscriptenginebase.cpp index b8052060884..3d4dd9a7166 100644 --- a/src/controllers/scripting/controllerscriptenginebase.cpp +++ b/src/controllers/scripting/controllerscriptenginebase.cpp @@ -2,16 +2,17 @@ #include "control/controlobject.h" #include "controllers/controller.h" -#include "controllers/controllerdebug.h" #include "controllers/scripting/colormapperjsproxy.h" #include "errordialoghandler.h" #include "mixer/playermanager.h" #include "moc_controllerscriptenginebase.cpp" -ControllerScriptEngineBase::ControllerScriptEngineBase(Controller* controller) +ControllerScriptEngineBase::ControllerScriptEngineBase( + Controller* controller, const RuntimeLoggingCategory& logger) : m_bDisplayingExceptionDialog(false), m_pJSEngine(nullptr), m_pController(controller), + m_logger(logger), m_bTesting(false) { // Handle error dialog buttons qRegisterMetaType("QMessageBox::StandardButton"); @@ -117,7 +118,7 @@ void ControllerScriptEngineBase::showScriptExceptionDialog( // Add backtrace to the error details errorText += QStringLiteral("\nBacktrace: ") + backtrace; - qWarning() << "ControllerScriptHandlerBase:" << errorText; + qCWarning(m_logger) << "ControllerScriptHandlerBase:" << errorText; if (!m_bDisplayingExceptionDialog) { scriptErrorDialog(errorText, key, bFatalError); diff --git a/src/controllers/scripting/controllerscriptenginebase.h b/src/controllers/scripting/controllerscriptenginebase.h index 4aab36ef66c..232683fdabf 100644 --- a/src/controllers/scripting/controllerscriptenginebase.h +++ b/src/controllers/scripting/controllerscriptenginebase.h @@ -8,6 +8,7 @@ #include "controllers/legacycontrollermapping.h" #include "util/duration.h" +#include "util/runtimeloggingcategory.h" class Controller; class EvaluationException; @@ -18,7 +19,8 @@ class EvaluationException; class ControllerScriptEngineBase : public QObject { Q_OBJECT public: - explicit ControllerScriptEngineBase(Controller* controller); + explicit ControllerScriptEngineBase( + Controller* controller, const RuntimeLoggingCategory& logger); virtual ~ControllerScriptEngineBase() override = default; virtual bool initialize(); @@ -47,6 +49,7 @@ class ControllerScriptEngineBase : public QObject { std::shared_ptr m_pJSEngine; Controller* m_pController; + const RuntimeLoggingCategory m_logger; bool m_bTesting; diff --git a/src/controllers/scripting/controllerscriptmoduleengine.cpp b/src/controllers/scripting/controllerscriptmoduleengine.cpp index b6da8a2208c..7f3f8ad5e73 100644 --- a/src/controllers/scripting/controllerscriptmoduleengine.cpp +++ b/src/controllers/scripting/controllerscriptmoduleengine.cpp @@ -2,8 +2,9 @@ #include "moc_controllerscriptmoduleengine.cpp" -ControllerScriptModuleEngine::ControllerScriptModuleEngine(Controller* controller) - : ControllerScriptEngineBase(controller) { +ControllerScriptModuleEngine::ControllerScriptModuleEngine( + Controller* controller, const RuntimeLoggingCategory& logger) + : ControllerScriptEngineBase(controller, logger) { connect(&m_fileWatcher, &QFileSystemWatcher::fileChanged, this, @@ -27,7 +28,7 @@ bool ControllerScriptModuleEngine::initialize() { } if (!m_fileWatcher.addPath(m_moduleFileInfo.absoluteFilePath())) { - qWarning() << "Failed to watch script file" << m_moduleFileInfo.absoluteFilePath(); + qCWarning(m_logger) << "Failed to watch script file" << m_moduleFileInfo.absoluteFilePath(); } QJSValue initFunction = mod.property("init"); @@ -40,7 +41,7 @@ bool ControllerScriptModuleEngine::initialize() { if (shutdownFunction.isCallable()) { m_shutdownFunction = shutdownFunction; } else { - qDebug() << "Module exports no shutdown function."; + qCDebug(m_logger) << "Module exports no shutdown function."; } return true; } diff --git a/src/controllers/scripting/controllerscriptmoduleengine.h b/src/controllers/scripting/controllerscriptmoduleengine.h index 76b14ee774c..5e32af4306c 100644 --- a/src/controllers/scripting/controllerscriptmoduleengine.h +++ b/src/controllers/scripting/controllerscriptmoduleengine.h @@ -6,7 +6,8 @@ class ControllerScriptModuleEngine : public ControllerScriptEngineBase { Q_OBJECT public: - explicit ControllerScriptModuleEngine(Controller* controller); + explicit ControllerScriptModuleEngine( + Controller* controller, const RuntimeLoggingCategory& logger); ~ControllerScriptModuleEngine() override; bool initialize() override; diff --git a/src/controllers/scripting/legacy/controllerscriptenginelegacy.cpp b/src/controllers/scripting/legacy/controllerscriptenginelegacy.cpp index f1f77434fb9..babc9c2bbd0 100644 --- a/src/controllers/scripting/legacy/controllerscriptenginelegacy.cpp +++ b/src/controllers/scripting/legacy/controllerscriptenginelegacy.cpp @@ -2,15 +2,15 @@ #include "control/controlobject.h" #include "controllers/controller.h" -#include "controllers/controllerdebug.h" #include "controllers/scripting/colormapperjsproxy.h" #include "controllers/scripting/legacy/controllerscriptinterfacelegacy.h" #include "errordialoghandler.h" #include "mixer/playermanager.h" #include "moc_controllerscriptenginelegacy.cpp" -ControllerScriptEngineLegacy::ControllerScriptEngineLegacy(Controller* controller) - : ControllerScriptEngineBase(controller) { +ControllerScriptEngineLegacy::ControllerScriptEngineLegacy( + Controller* controller, const RuntimeLoggingCategory& logger) + : ControllerScriptEngineBase(controller, logger) { connect(&m_fileWatcher, &QFileSystemWatcher::fileChanged, this, @@ -36,18 +36,18 @@ bool ControllerScriptEngineLegacy::callFunctionOnObjects( for (const QString& prefixName : scriptFunctionPrefixes) { QJSValue prefix = global.property(prefixName); if (!prefix.isObject()) { - qWarning() << "No" << prefixName << "object in script"; + qCWarning(m_logger) << "No" << prefixName << "object in script"; continue; } QJSValue init = prefix.property(function); if (!init.isCallable()) { - qWarning() << prefixName << "has no" - << function << " method"; + qCWarning(m_logger) << prefixName << "has no" + << function << " method"; continue; } - controllerDebug("Executing" - << prefixName << "." << function); + qCDebug(m_logger) << "Executing" + << prefixName << "." << function; QJSValue result = init.callWithInstance(prefix, args); if (result.isError()) { showScriptExceptionDialog(result, bFatalError); @@ -113,7 +113,7 @@ bool ControllerScriptEngineLegacy::initialize() { // Make this ControllerScriptHandler instance available to scripts as 'engine'. QJSValue engineGlobalObject = m_pJSEngine->globalObject(); ControllerScriptInterfaceLegacy* legacyScriptInterface = - new ControllerScriptInterfaceLegacy(this); + new ControllerScriptInterfaceLegacy(this, m_logger); engineGlobalObject.setProperty( "engine", m_pJSEngine->newQObject(legacyScriptInterface)); @@ -149,7 +149,7 @@ bool ControllerScriptEngineLegacy::initialize() { } else { // m_pController is nullptr in tests. args << QJSValue(); } - args << QJSValue(ControllerDebug::isEnabled()); + args << QJSValue(m_logger().isDebugEnabled()); if (!callFunctionOnObjects(m_scriptFunctionPrefixes, "init", args, true)) { shutdown(); return false; @@ -190,8 +190,8 @@ bool ControllerScriptEngineLegacy::evaluateScriptFile(const QFileInfo& scriptFil } if (!scriptFile.exists()) { - qWarning() << "File does not exist:" - << scriptFile.absoluteFilePath(); + qCWarning(m_logger) << "File does not exist:" + << scriptFile.absoluteFilePath(); return false; } @@ -199,22 +199,22 @@ bool ControllerScriptEngineLegacy::evaluateScriptFile(const QFileInfo& scriptFil // without having to restart Mixxx. So, add it to the watcher before // evaluating it. if (!m_fileWatcher.addPath(scriptFile.absoluteFilePath())) { - qWarning() << "Failed to watch script file" << scriptFile.absoluteFilePath(); + qCWarning(m_logger) << "Failed to watch script file" << scriptFile.absoluteFilePath(); }; - qDebug() << "Loading" - << scriptFile.absoluteFilePath(); + qCDebug(m_logger) << "Loading" + << scriptFile.absoluteFilePath(); // Read in the script file QString filename = scriptFile.absoluteFilePath(); QFile input(filename); if (!input.open(QIODevice::ReadOnly)) { - qWarning() << QString( + qCWarning(m_logger) << QString( "Problem opening the script file: %1, " "error # %2, %3") - .arg(filename, - QString::number(input.error()), - input.errorString()); + .arg(filename, + QString::number(input.error()), + input.errorString()); // Set up error dialog ErrorDialogProperties* props = ErrorDialogHandler::instance()->newDialogProperties(); props->setType(DLG_WARNING); diff --git a/src/controllers/scripting/legacy/controllerscriptenginelegacy.h b/src/controllers/scripting/legacy/controllerscriptenginelegacy.h index 6aaa7c4c64f..5a997ff6196 100644 --- a/src/controllers/scripting/legacy/controllerscriptenginelegacy.h +++ b/src/controllers/scripting/legacy/controllerscriptenginelegacy.h @@ -13,7 +13,8 @@ class ControllerScriptEngineLegacy : public ControllerScriptEngineBase { Q_OBJECT public: - explicit ControllerScriptEngineLegacy(Controller* controller); + explicit ControllerScriptEngineLegacy( + Controller* controller, const RuntimeLoggingCategory& logger); ~ControllerScriptEngineLegacy() override; bool initialize() override; diff --git a/src/controllers/scripting/legacy/controllerscriptinterfacelegacy.cpp b/src/controllers/scripting/legacy/controllerscriptinterfacelegacy.cpp index 3088cff43bd..28aa760d4ee 100644 --- a/src/controllers/scripting/legacy/controllerscriptinterfacelegacy.cpp +++ b/src/controllers/scripting/legacy/controllerscriptinterfacelegacy.cpp @@ -2,7 +2,6 @@ #include "control/controlobject.h" #include "control/controlobjectscript.h" -#include "controllers/controllerdebug.h" #include "controllers/scripting/legacy/controllerscriptenginelegacy.h" #include "controllers/scripting/legacy/scriptconnectionjsproxy.h" #include "mixer/playermanager.h" @@ -20,8 +19,9 @@ const double kAlphaBetaDt = kScratchTimerMs / 1000.0; } // anonymous namespace ControllerScriptInterfaceLegacy::ControllerScriptInterfaceLegacy( - ControllerScriptEngineLegacy* m_pEngine) - : m_pScriptEngineLegacy(m_pEngine) { + ControllerScriptEngineLegacy* m_pEngine, const RuntimeLoggingCategory& logger) + : m_pScriptEngineLegacy(m_pEngine), + m_logger(logger) { // Pre-allocate arrays for average number of virtual decks m_intervalAccumulator.resize(kDecks); m_lastMovement.resize(kDecks); @@ -53,7 +53,7 @@ ControllerScriptInterfaceLegacy::~ControllerScriptInterfaceLegacy() { QHashIterator it(m_scratchTimers); while (it.hasNext()) { it.next(); - qDebug() << "Aborting scratching on deck" << it.value(); + qCDebug(m_logger) << "Aborting scratching on deck" << it.value(); // Clear scratch2_enable. PlayerManager::groupForDeck is 0-indexed. QString group = PlayerManager::groupForDeck(it.value() - 1); ControlObjectScript* pScratch2Enable = @@ -72,7 +72,7 @@ ControllerScriptInterfaceLegacy::~ControllerScriptInterfaceLegacy() { { auto it = m_controlCache.begin(); while (it != m_controlCache.end()) { - qDebug() + qCDebug(m_logger) << "Deleting ControlObjectScript" << it.key().group << it.key().item; @@ -89,7 +89,7 @@ ControlObjectScript* ControllerScriptInterfaceLegacy::getControlObjectScript( ControlObjectScript* coScript = m_controlCache.value(key, nullptr); if (coScript == nullptr) { // create COT - coScript = new ControlObjectScript(key, this); + coScript = new ControlObjectScript(key, m_logger, this); if (coScript->valid()) { m_controlCache.insert(key, coScript); } else { @@ -103,8 +103,8 @@ ControlObjectScript* ControllerScriptInterfaceLegacy::getControlObjectScript( double ControllerScriptInterfaceLegacy::getValue(const QString& group, const QString& name) { ControlObjectScript* coScript = getControlObjectScript(group, name); if (coScript == nullptr) { - qWarning() << "Unknown control" << group << name - << ", returning 0.0"; + qCWarning(m_logger) << "Unknown control" << group << name + << ", returning 0.0"; return 0.0; } return coScript->get(); @@ -113,8 +113,8 @@ double ControllerScriptInterfaceLegacy::getValue(const QString& group, const QSt void ControllerScriptInterfaceLegacy::setValue( const QString& group, const QString& name, double newValue) { if (util_isnan(newValue)) { - qWarning() << "script setting [" << group << "," - << name << "] to NotANumber, ignoring."; + qCWarning(m_logger) << "script setting [" << group << "," + << name << "] to NotANumber, ignoring."; return; } @@ -122,7 +122,7 @@ void ControllerScriptInterfaceLegacy::setValue( if (coScript != nullptr) { ControlObject* pControl = ControlObject::getControl( - coScript->getKey(), ControllerDebug::controlFlags()); + coScript->getKey(), ControlFlag::AllowMissingOrInvalid); if (pControl && !m_st.ignore( pControl, coScript->getParameterForValue(newValue))) { @@ -134,8 +134,8 @@ void ControllerScriptInterfaceLegacy::setValue( double ControllerScriptInterfaceLegacy::getParameter(const QString& group, const QString& name) { ControlObjectScript* coScript = getControlObjectScript(group, name); if (coScript == nullptr) { - qWarning() << "Unknown control" << group << name - << ", returning 0.0"; + qCWarning(m_logger) << "Unknown control" << group << name + << ", returning 0.0"; return 0.0; } return coScript->getParameter(); @@ -144,8 +144,8 @@ double ControllerScriptInterfaceLegacy::getParameter(const QString& group, const void ControllerScriptInterfaceLegacy::setParameter( const QString& group, const QString& name, double newParameter) { if (util_isnan(newParameter)) { - qWarning() << "script setting [" << group << "," - << name << "] to NotANumber, ignoring."; + qCWarning(m_logger) << "script setting [" << group << "," + << name << "] to NotANumber, ignoring."; return; } @@ -153,7 +153,7 @@ void ControllerScriptInterfaceLegacy::setParameter( if (coScript != nullptr) { ControlObject* pControl = ControlObject::getControl( - coScript->getKey(), ControllerDebug::controlFlags()); + coScript->getKey(), ControlFlag::AllowMissingOrInvalid); if (pControl && !m_st.ignore(pControl, newParameter)) { coScript->setParameter(newParameter); } @@ -163,16 +163,16 @@ void ControllerScriptInterfaceLegacy::setParameter( double ControllerScriptInterfaceLegacy::getParameterForValue( const QString& group, const QString& name, double value) { if (util_isnan(value)) { - qWarning() << "script setting [" << group << "," - << name << "] to NotANumber, ignoring."; + qCWarning(m_logger) << "script setting [" << group << "," + << name << "] to NotANumber, ignoring."; return 0.0; } ControlObjectScript* coScript = getControlObjectScript(group, name); if (coScript == nullptr) { - qWarning() << "Unknown control" << group << name - << ", returning 0.0"; + qCWarning(m_logger) << "Unknown control" << group << name + << ", returning 0.0"; return 0.0; } @@ -190,8 +190,8 @@ double ControllerScriptInterfaceLegacy::getDefaultValue(const QString& group, co ControlObjectScript* coScript = getControlObjectScript(group, name); if (coScript == nullptr) { - qWarning() << "Unknown control" << group << name - << ", returning 0.0"; + qCWarning(m_logger) << "Unknown control" << group << name + << ", returning 0.0"; return 0.0; } @@ -203,8 +203,8 @@ double ControllerScriptInterfaceLegacy::getDefaultParameter( ControlObjectScript* coScript = getControlObjectScript(group, name); if (coScript == nullptr) { - qWarning() << "Unknown control" << group << name - << ", returning 0.0"; + qCWarning(m_logger) << "Unknown control" << group << name + << ", returning 0.0"; return 0.0; } @@ -358,7 +358,7 @@ QJSValue ControllerScriptInterfaceLegacy::connectControl(const QString& group, // not break. ScriptConnection connection = coScript->firstConnection(); - qWarning() << "Tried to make duplicate connection between (" + + qCWarning(m_logger) << "Tried to make duplicate connection between (" + group + ", " + name + ") and " + passedCallback.toString() + " but this is not allowed when passing a callback " @@ -380,8 +380,8 @@ QJSValue ControllerScriptInterfaceLegacy::connectControl(const QString& group, QObject* qobject = passedCallback.toQObject(); const QMetaObject* qmeta = qobject->metaObject(); - qWarning() << "QObject passed to engine.connectControl. Assuming it is" - << "a connection object to disconnect and returning false."; + qCWarning(m_logger) << "QObject passed to engine.connectControl. Assuming it is" + << "a connection object to disconnect and returning false."; if (!strcmp(qmeta->className(), "ScriptConnectionJSProxy")) { ScriptConnectionJSProxy* proxy = (ScriptConnectionJSProxy*)qobject; proxy->disconnect(); @@ -415,7 +415,8 @@ void ControllerScriptInterfaceLegacy::trigger(const QString& group, const QStrin } void ControllerScriptInterfaceLegacy::log(const QString& message) { - controllerDebug(message); + qCDebug(m_logger) << "engine.log is deprecated. Use console.log instead."; + qCDebug(m_logger) << message; } int ControllerScriptInterfaceLegacy::beginTimer( int intervalMillis, QJSValue timerCallback, bool oneShot) { @@ -434,8 +435,8 @@ int ControllerScriptInterfaceLegacy::beginTimer( } if (intervalMillis < 20) { - qWarning() << "Timer request for" << intervalMillis - << "ms is too short. Setting to the minimum of 20ms."; + qCWarning(m_logger) << "Timer request for" << intervalMillis + << "ms is too short. Setting to the minimum of 20ms."; intervalMillis = 20; } @@ -448,22 +449,22 @@ int ControllerScriptInterfaceLegacy::beginTimer( info.oneShot = oneShot; m_timers[timerId] = info; if (timerId == 0) { - qWarning() << "Script timer could not be created"; + qCWarning(m_logger) << "Script timer could not be created"; } else if (oneShot) { - controllerDebug("Starting one-shot timer:" << timerId); + qCDebug(m_logger) << "Starting one-shot timer:" << timerId; } else { - controllerDebug("Starting timer:" << timerId); + qCDebug(m_logger) << "Starting timer:" << timerId; } return timerId; } void ControllerScriptInterfaceLegacy::stopTimer(int timerId) { if (!m_timers.contains(timerId)) { - qWarning() << "Killing timer" << timerId - << ": That timer does not exist!"; + qCWarning(m_logger) << "Killing timer" << timerId + << ": That timer does not exist!"; return; } - controllerDebug("Killing timer:" << timerId); + qCDebug(m_logger) << "Killing timer:" << timerId; killTimer(timerId); m_timers.remove(timerId); } @@ -479,8 +480,8 @@ void ControllerScriptInterfaceLegacy::timerEvent(QTimerEvent* event) { auto it = m_timers.constFind(timerId); if (it == m_timers.constEnd()) { - qWarning() << "Timer" << timerId - << "fired but there's no function mapped to it!"; + qCWarning(m_logger) << "Timer" << timerId + << "fired but there's no function mapped to it!"; return; } @@ -499,7 +500,7 @@ void ControllerScriptInterfaceLegacy::timerEvent(QTimerEvent* event) { void ControllerScriptInterfaceLegacy::softTakeover( const QString& group, const QString& name, bool set) { ControlObject* pControl = ControlObject::getControl( - ConfigKey(group, name), ControllerDebug::controlFlags()); + ConfigKey(group, name), ControlFlag::AllowMissingOrInvalid); if (!pControl) { return; } @@ -513,7 +514,7 @@ void ControllerScriptInterfaceLegacy::softTakeover( void ControllerScriptInterfaceLegacy::softTakeoverIgnoreNextValue( const QString& group, const QString& name) { ControlObject* pControl = ControlObject::getControl( - ConfigKey(group, name), ControllerDebug::controlFlags()); + ConfigKey(group, name), ControlFlag::AllowMissingOrInvalid); if (!pControl) { return; } @@ -557,7 +558,7 @@ void ControllerScriptInterfaceLegacy::scratchEnable(int deck, bool ramp) { // If we're already scratching this deck, override that with this request if (static_cast(m_dx[deck])) { - //qDebug() << "Already scratching deck" << deck << ". Overriding."; + //qCDebug(m_logger) << "Already scratching deck" << deck << ". Overriding."; int timerId = m_scratchTimers.key(deck); killTimer(timerId); m_scratchTimers.remove(timerId); @@ -568,8 +569,8 @@ void ControllerScriptInterfaceLegacy::scratchEnable(int deck, double intervalsPerSecond = (rpm * intervalsPerRev) / 60.0; if (intervalsPerSecond == 0.0) { - qWarning() << "Invalid rpm or intervalsPerRev supplied to " - "scratchEnable. Ignoring request."; + qCWarning(m_logger) << "Invalid rpm or intervalsPerRev supplied to " + "scratchEnable. Ignoring request."; return; } @@ -636,7 +637,7 @@ void ControllerScriptInterfaceLegacy::scratchProcess(int timerId) { QString group = PlayerManager::groupForDeck(deck - 1); AlphaBetaFilter* filter = m_scratchFilters[deck]; if (!filter) { - qWarning() << "Scratch filter pointer is null on deck" << deck; + qCWarning(m_logger) << "Scratch filter pointer is null on deck" << deck; return; } diff --git a/src/controllers/scripting/legacy/controllerscriptinterfacelegacy.h b/src/controllers/scripting/legacy/controllerscriptinterfacelegacy.h index 11087394eb5..afeb8914a5b 100644 --- a/src/controllers/scripting/legacy/controllerscriptinterfacelegacy.h +++ b/src/controllers/scripting/legacy/controllerscriptinterfacelegacy.h @@ -5,6 +5,7 @@ #include "controllers/softtakeover.h" #include "util/alphabetafilter.h" +#include "util/runtimeloggingcategory.h" class ControllerScriptEngineLegacy; class ControlObjectScript; @@ -16,7 +17,8 @@ class ConfigKey; class ControllerScriptInterfaceLegacy : public QObject { Q_OBJECT public: - ControllerScriptInterfaceLegacy(ControllerScriptEngineLegacy* m_pEngine); + ControllerScriptInterfaceLegacy(ControllerScriptEngineLegacy* m_pEngine, + const RuntimeLoggingCategory& logger); virtual ~ControllerScriptInterfaceLegacy(); @@ -87,4 +89,5 @@ class ControllerScriptInterfaceLegacy : public QObject { double getDeckRate(const QString& group); ControllerScriptEngineLegacy* m_pScriptEngineLegacy; + const RuntimeLoggingCategory m_logger; }; diff --git a/src/test/controller_mapping_validation_test.cpp b/src/test/controller_mapping_validation_test.cpp index 9ac6649529f..2a91e4715fe 100644 --- a/src/test/controller_mapping_validation_test.cpp +++ b/src/test/controller_mapping_validation_test.cpp @@ -27,7 +27,8 @@ void FakeControllerJSProxy::sendShortMsg(unsigned char status, } FakeController::FakeController() - : m_bMidiMapping(false), + : Controller("Test Controller"), + m_bMidiMapping(false), m_bHidMapping(false) { startEngine(); getScriptEngine()->setTesting(true); @@ -60,7 +61,6 @@ bool LegacyControllerMappingValidationTest::testLoadMapping(const MappingInfo& m } FakeController controller; - controller.setDeviceName("Test Controller"); controller.setMapping(pMapping); bool result = controller.applyMapping(); controller.stopEngine(); diff --git a/src/test/controllerscriptenginelegacy_test.cpp b/src/test/controllerscriptenginelegacy_test.cpp index ff6b97ed7d4..b1afc9b2ec5 100644 --- a/src/test/controllerscriptenginelegacy_test.cpp +++ b/src/test/controllerscriptenginelegacy_test.cpp @@ -8,7 +8,6 @@ #include "control/controlobject.h" #include "control/controlpotmeter.h" -#include "controllers/controllerdebug.h" #include "controllers/softtakeover.h" #include "preferences/usersettings.h" #include "test/mixxxtest.h" @@ -17,6 +16,8 @@ typedef std::unique_ptr ScopedTemporaryFile; +const RuntimeLoggingCategory logger(QString("test").toLocal8Bit()); + class ControllerScriptEngineLegacyTest : public MixxxTest { protected: static ScopedTemporaryFile makeTemporaryFile(const QString& contents) { @@ -32,9 +33,8 @@ class ControllerScriptEngineLegacyTest : public MixxxTest { mixxx::Time::setTestMode(true); mixxx::Time::setTestElapsedTime(mixxx::Duration::fromMillis(10)); QThread::currentThread()->setObjectName("Main"); - cEngine = new ControllerScriptEngineLegacy(nullptr); + cEngine = new ControllerScriptEngineLegacy(nullptr, logger); cEngine->initialize(); - ControllerDebug::setTesting(true); } void TearDown() override { @@ -80,29 +80,17 @@ TEST_F(ControllerScriptEngineLegacyTest, setValue) { } TEST_F(ControllerScriptEngineLegacyTest, getValue_InvalidKey) { - ControllerDebug::setEnabled(false); - ControllerDebug::setTesting(false); EXPECT_TRUE(evaluateAndAssert("engine.getValue('', '');")); EXPECT_TRUE(evaluateAndAssert("engine.getValue('', 'invalid');")); EXPECT_TRUE(evaluateAndAssert("engine.getValue('[Invalid]', '');")); - ControllerDebug::setTesting(true); - ControllerDebug::setEnabled(true); } TEST_F(ControllerScriptEngineLegacyTest, setValue_InvalidControl) { - ControllerDebug::setEnabled(false); - ControllerDebug::setTesting(false); EXPECT_TRUE(evaluateAndAssert("engine.setValue('[Nothing]', 'nothing', 1.0);")); - ControllerDebug::setTesting(true); - ControllerDebug::setEnabled(true); } TEST_F(ControllerScriptEngineLegacyTest, getValue_InvalidControl) { - ControllerDebug::setEnabled(false); - ControllerDebug::setTesting(false); EXPECT_TRUE(evaluateAndAssert("engine.getValue('[Nothing]', 'nothing');")); - ControllerDebug::setTesting(true); - ControllerDebug::setEnabled(true); } TEST_F(ControllerScriptEngineLegacyTest, setValue_IgnoresNaN) { diff --git a/src/test/midicontrollertest.cpp b/src/test/midicontrollertest.cpp index 84b99a63ebd..3b9e22c5539 100644 --- a/src/test/midicontrollertest.cpp +++ b/src/test/midicontrollertest.cpp @@ -13,7 +13,9 @@ class MockMidiController : public MidiController { public: - explicit MockMidiController(): MidiController() {} + explicit MockMidiController() + : MidiController("test") { + } ~MockMidiController() override { } MOCK_METHOD0(open, int()); diff --git a/src/util/cmdlineargs.cpp b/src/util/cmdlineargs.cpp index 1fe6d1cc04f..86fc35d3b76 100644 --- a/src/util/cmdlineargs.cpp +++ b/src/util/cmdlineargs.cpp @@ -19,7 +19,7 @@ CmdlineArgs::CmdlineArgs() : m_startInFullscreen(false), // Initialize vars - m_midiDebug(false), + m_controllerDebug(false), m_developer(false), m_safeMode(false), m_debugAssertBreak(false), @@ -325,7 +325,7 @@ bool CmdlineArgs::parse(const QStringList& arguments, CmdlineArgs::ParseMode mod m_timelinePath = parser.value(timelinePathDeprecated); } - m_midiDebug = parser.isSet(controllerDebug) || parser.isSet(controllerDebugDeprecated); + m_controllerDebug = parser.isSet(controllerDebug) || parser.isSet(controllerDebugDeprecated); m_developer = parser.isSet(developer); m_qml = parser.isSet(qml); m_safeMode = parser.isSet(safeMode) || parser.isSet(safeModeDeprecated); diff --git a/src/util/cmdlineargs.h b/src/util/cmdlineargs.h index 331ecdce8ad..df1d8a5acb7 100644 --- a/src/util/cmdlineargs.h +++ b/src/util/cmdlineargs.h @@ -31,7 +31,9 @@ class CmdlineArgs final { const QList& getMusicFiles() const { return m_musicFiles; } bool getStartInFullscreen() const { return m_startInFullscreen; } - bool getMidiDebug() const { return m_midiDebug; } + bool getControllerDebug() const { + return m_controllerDebug; + } bool getDeveloper() const { return m_developer; } bool getQml() const { return m_qml; @@ -70,7 +72,7 @@ class CmdlineArgs final { QList m_musicFiles; // List of files to load into players at startup bool m_startInFullscreen; // Start in fullscreen mode - bool m_midiDebug; + bool m_controllerDebug; bool m_developer; // Developer Mode bool m_qml; bool m_safeMode; diff --git a/src/util/logging.cpp b/src/util/logging.cpp index cf26ba62544..859b111b2c0 100644 --- a/src/util/logging.cpp +++ b/src/util/logging.cpp @@ -13,7 +13,6 @@ #include #include -#include "controllers/controllerdebug.h" #include "util/assert.h" #include "util/cmdlineargs.h" #include "util/compatibility/qmutex.h" @@ -29,6 +28,26 @@ QMutex s_mutexStdErr; // The file handle for Mixxx's log file. QFile s_logfile; +QLoggingCategory::CategoryFilter oldCategoryFilter = nullptr; + +/// Filters logging categories for the `--controller-debug` command line +/// argument, so that debug messages are enabled for all categories in the +/// `controller` namespace, and disabled for all other categories. +void controllerDebugCategoryFilter(QLoggingCategory* category) { + // Configure controller.*.input/output category here, otherwise forward to to default filter. + constexpr char controllerPrefix[] = "controller."; + const char* categoryName = category->categoryName(); + if (qstrncmp(categoryName, controllerPrefix, sizeof(controllerPrefix) - 1) == 0) { + // If the logging category name starts with `controller.`, show debug messages. + category->setEnabled(QtDebugMsg, true); + } else { + // Otherwise, pass it on to the default filter (via function pointer) + // and disable all debug messages for those categories. + oldCategoryFilter(category); + category->setEnabled(QtDebugMsg, false); + } +} + // The log level. // Whether to break on debug assertions. bool s_debugAssertBreak = false; @@ -236,6 +255,10 @@ namespace mixxx { namespace { +bool isControllerLoggingCategory(const QString& categoryName) { + return categoryName.startsWith("controller."); +} + // Debug message handler which outputs to stderr and a logfile, // prepending the thread name, log category, and log level. void handleMessage( @@ -245,15 +268,11 @@ void handleMessage( const char* levelName = nullptr; WriteFlags writeFlags = WriteFlag::None; bool isDebugAssert = false; - bool isControllerDebug = false; + const QString categoryName(context.category); switch (type) { case QtDebugMsg: levelName = "Debug"; - isControllerDebug = - input.startsWith(QLatin1String( - ControllerDebug::kLogMessagePrefix)); - if (isControllerDebug || - Logging::enabled(LogLevel::Debug)) { + if (Logging::enabled(LogLevel::Debug)) { writeFlags |= WriteFlag::StdErr; writeFlags |= WriteFlag::File; } @@ -263,8 +282,12 @@ void handleMessage( // TODO: Remove the following line. // Do not write debug log messages into log file if log level // Debug is not enabled starting with release 2.4.0! Until then - // write debug messages unconditionally into the log file - writeFlags |= WriteFlag::File; + // write debug messages into the log file, but skip controller I/O + // to avoid flooding the log file. + // Skip expensive string comparisons if WriteFlag::File is already set. + if (!writeFlags.testFlag(WriteFlag::File) && !isControllerLoggingCategory(categoryName)) { + writeFlags |= WriteFlag::File; + } break; case QtInfoMsg: levelName = "Info"; @@ -383,6 +406,23 @@ void Logging::initialize( "*.debug=true\n" "qt.*.debug=false"); #endif + + if (CmdlineArgs::Instance().getControllerDebug()) { + // Due to our hacky custom logging system, all debug messages are + // discarded if the overall log level is not `Debug` - even if debug + // messages for a specific category are enabled. So if we want to be + // able to show controller debug messages on the terminal, the log + // level has to be set to `Debug`. We then filter out all + // non-controller-related debug messages via the custom + // `controllerDebugCategoryFilter`. + setLogLevel(LogLevel::Debug); + // Move the the old filter to oldCategoryFilter first, because it is + // used in controllerDebugCategoryFilter(). Qt 5 does not have + // a function to just copy the old filter. This is the proposed + // workaround in: https://bugreports.qt.io/browse/QTBUG-49704 + oldCategoryFilter = QLoggingCategory::installFilter(nullptr); + QLoggingCategory::installFilter(controllerDebugCategoryFilter); + } } // static diff --git a/src/util/runtimeloggingcategory.cpp b/src/util/runtimeloggingcategory.cpp new file mode 100644 index 00000000000..3d0fc2e86ef --- /dev/null +++ b/src/util/runtimeloggingcategory.cpp @@ -0,0 +1,11 @@ +#include "util/runtimeloggingcategory.h" + +#include + +namespace { +const QRegularExpression invalidLoggingCategoryChars("[^a-zA-Z0-9]"); +} // anonymous namespace + +QString RuntimeLoggingCategory::removeInvalidCharsFromCategory(QString categoryName) { + return categoryName.remove(invalidLoggingCategoryChars); +} diff --git a/src/util/runtimeloggingcategory.h b/src/util/runtimeloggingcategory.h new file mode 100644 index 00000000000..e614036965a --- /dev/null +++ b/src/util/runtimeloggingcategory.h @@ -0,0 +1,50 @@ +#pragma once + +#include +#include + +/// RuntimeLoggingCategory is a wrapper around QLoggingCategory +/// that facilitates using a QLoggingCategory for a category +/// name string that is determined at run time. To use a +/// RuntimeLoggingCategory, simply pass it to the +/// qCInfo, qCDebug, qCWarning, or qCCritical macros like a +/// QLoggingCategory. If the category name is fully known at +/// compile time, simply construct a QLoggingCategory with a +/// string literal instead of using RuntimeLoggingCategory. +/// +/// RuntimeLoggingCategory stores the logging category name as a +/// QByteArray. This is helpful because QLoggingCategory has a deleted +/// copy constructor, does not take ownership nor make a copy of the +/// const char* passed to its constructor, and requires that the +/// data pointed to by the const char* lives as long as the +/// QLoggingCategory. +/// +/// RuntimeLoggingCategory takes advantage of QByteArray's +/// implicit sharing to ensure that the const char* for the +/// QLoggingCategory lives as long as the QLoggingCategory without +/// requiring excessive deep copies. +struct RuntimeLoggingCategory { + public: + explicit RuntimeLoggingCategory(const QString& categoryName) + : m_categoryName(categoryName.toLocal8Bit()), + m_logger(m_categoryName.constData()) { + } + + explicit RuntimeLoggingCategory(const RuntimeLoggingCategory& other) + : m_categoryName(other.m_categoryName), + m_logger(m_categoryName.constData()) { + } + + /// Implicit converter for passing a RuntimeLoggingCategory to the + /// qCInfo/qCDebug/qCWarning/qCCritical macros as if it was a + /// QLoggingCategory. + const QLoggingCategory& operator()() const { + return m_logger; + } + + static QString removeInvalidCharsFromCategory(QString categoryName); + + private: + const QByteArray m_categoryName; + const QLoggingCategory m_logger; +};