Merge pull request #4523 from Holzhaus/logging-controller-debug

Controller logging categories (with --controllerDebug support)

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

src/control/controlobjectscript.cpp

@@ -1,12 +1,11 @@
 #include "control/controlobjectscript.h"
 
-#include <QtDebug>
-
-#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

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<ScriptConnection> m_scriptConnections;
+    const RuntimeLoggingCategory m_logger;
 };

src/controllers/bulk/bulkcontroller.cpp

@@ -3,7 +3,6 @@
 #include <libusb.h>
 
 #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,15 +163,15 @@ 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;
     }
 
     setOpen(true);
     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;
     }
 }

src/controllers/controller.cpp

@@ -2,14 +2,25 @@
 
 #include <QApplication>
 #include <QJSValue>
+#include <QRegularExpression>
 
-#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,38 +39,40 @@ 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;
     m_pScriptEngineLegacy = nullptr;
 }
 
 bool Controller::applyMapping() {
-    qDebug() << "Applying controller mapping...";
+    qCInfo(m_logBase) << "Applying controller mapping...";
 
     const std::shared_ptr<LegacyControllerMapping> 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<LegacyControllerMapping::ScriptFileInfo> 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);

src/controllers/controller.h

@@ -1,13 +1,15 @@
 #pragma once
 
 #include <QElapsedTimer>
+#include <QLoggingCategory>
 #include <QTimerEvent>
 
 #include "controllers/controllermappinginfo.h"
 #include "controllers/legacycontrollermapping.h"
 #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