[Logging] Improved logging using spdlog. Also increased build time by 5x!

CMakeLists.txt

@@ -4,8 +4,13 @@ project(KittehPlayer)
 include_directories(${CMAKE_SOURCE_DIR} ${CMAKE_BINARY_DIR}) 
 set(CMAKE_AUTOMOC ON)
 
+include(ExternalProject)
+
+
 find_package(Qt5Core REQUIRED)
 find_package(Qt5Gui REQUIRED)
+find_package(Qt5Concurrent REQUIRED)
+
 find_package(Qt5 CONFIG REQUIRED COMPONENTS Qml Quick Gui Widgets Core X11Extras)
 
 find_package(Qt5QuickCompiler)
@@ -16,6 +21,16 @@ pkg_check_modules(MPV REQUIRED mpv)
 pkg_check_modules(X11 x11)
 pkg_check_modules(Xext xext)
 
+
+execute_process(
+  COMMAND git clone --depth 1 https://github.com/gabime/spdlog.git
+  WORKING_DIRECTORY ${CMAKE_BINARY_DIR}
+)
+
+include_directories(${CMAKE_BINARY_DIR}/spdlog/include)
+
+
+
 if(X11_FOUND AND Xext_FOUND)
 add_definitions(-DENABLE_X11)
 endif(X11_FOUND AND Xext_FOUND)
@@ -27,6 +42,7 @@ set(SOURCES
     src/enums.hpp
     src/Process.cpp
     src/ThumbnailCache.cpp
+    src/logger.cpp
 )
 
 if(MPV_VERSION VERSION_GREATER_EQUAL "1.28.0")
@@ -58,7 +74,7 @@ add_executable(KittehPlayer ${SOURCES} ${qml_QRC})
 
 # Use the Qml/Quick modules from Qt 5.
 target_link_libraries(KittehPlayer ${MPV_LIBRARIES} ${X11_LIBRARIES} ${Xext_LIBRARIES} Qt5::X11Extras)
-include_directories(${Qt5Gui_PRIVATE_INCLUDE_DIRS})
+include_directories(${Qt5Gui_PRIVATE_INCLUDE_DIRS} ${Qt5Concurrent_INCLUDE_DIRS})
 qt5_use_modules(KittehPlayer Qml Quick Core Gui Widgets X11Extras)
 
 install (TARGETS ${PROJECT_NAME} DESTINATION bin)

src/MpvPlayerBackend.cpp

@@ -1,8 +1,5 @@
 #include "MpvPlayerBackend.h"
-#include <clocale>
-#include <stdbool.h>
-#include <stdexcept>
-
+#include "logger.h"
 #include "utils.hpp"
 #include <QApplication>
 #include <QElapsedTimer>
@@ -10,7 +7,10 @@
 #include <QOpenGLFramebufferObject>
 #include <QQuickWindow>
 #include <QSequentialIterable>
+#include <clocale>
 #include <math.h>
+#include <stdbool.h>
+#include <stdexcept>
 
 #ifdef __linux__
 #include <QX11Info>
@@ -20,6 +20,8 @@
 #include <qpa/qplatformnativeinterface.h>
 #endif
 
+auto mpvLogger = initLogger("mpv");
+
 namespace {
 
 void
@@ -80,13 +82,11 @@ public:
       if (QGuiApplication::platformName().contains("xcb")) {
         params[2].type = MPV_RENDER_PARAM_X11_DISPLAY;
         params[2].data = QX11Info::display();
-        qDebug() << "On Xorg.";
       } else if (QGuiApplication::platformName().contains("wayland")) {
         QPlatformNativeInterface* native =
           QGuiApplication::platformNativeInterface();
         params[2].type = MPV_RENDER_PARAM_WL_DISPLAY;
         params[2].data = native->nativeResourceForWindow("display", nullptr);
-        qDebug() << "On wayland.";
       }
 #endif
 
@@ -129,10 +129,11 @@ MpvPlayerBackend::MpvPlayerBackend(QQuickItem* parent)
   , mpv{ mpv_create() }
   , mpv_gl(nullptr)
 {
+  mpvLogger->set_pattern("%^[%d-%m-%Y %T.%e][%l][%n]%v%$");
   if (!mpv)
     throw std::runtime_error("could not create mpv context");
 
-  mpv_set_option_string(mpv, "terminal", "off");
+  mpv_set_option_string(mpv, "terminal", "on");
   mpv_set_option_string(mpv, "msg-level", "all=v");
 
   // Fix?
@@ -161,6 +162,9 @@ MpvPlayerBackend::MpvPlayerBackend(QQuickItem* parent)
   mpv_observe_property(mpv, 0, "pause", MPV_FORMAT_NODE);
   mpv_observe_property(mpv, 0, "playlist", MPV_FORMAT_NODE);
   mpv_observe_property(mpv, 0, "speed", MPV_FORMAT_DOUBLE);
+
+  mpv_request_log_messages(mpv, "debug");
+
   mpv_set_wakeup_callback(mpv, wakeup, this);
 
   if (mpv_initialize(mpv) < 0)
@@ -550,6 +554,20 @@ MpvPlayerBackend::handle_mpv_event(mpv_event* event)
       }
       break;
     }
+
+    case MPV_EVENT_LOG_MESSAGE: {
+      struct mpv_event_log_message* msg =
+        (struct mpv_event_log_message*)event->data;
+      QString logMsg = "[" + QString(msg->prefix) + "] " + QString(msg->text);
+      QString msgLevel = QString(msg->level);
+      if (msgLevel.startsWith("d")) {
+        mpvLogger->debug("{}", logMsg.toUtf8().constData());
+      } else if (msgLevel.startsWith("v") || msgLevel.startsWith("i")) {
+        mpvLogger->info("{}", logMsg.toUtf8().constData());
+      }
+
+      break;
+    }
     case MPV_EVENT_SHUTDOWN: {
       qApp->exit();
       break;

src/logger.cpp

@@ -0,0 +1,21 @@
+#include "logger.h"
+
+#include <QObject>
+#include <QString>
+#include <iostream>
+
+std::shared_ptr<spdlog::logger>
+initLogger(std::string name)
+{
+  std::vector<spdlog::sink_ptr> sinks;
+  sinks.push_back(std::make_shared<spdlog::sinks::stdout_color_sink_mt>());
+  sinks.push_back(std::make_shared<spdlog::sinks::basic_file_sink_mt>(
+    "/tmp/KittehPlayer.log"));
+  auto console =
+    std::make_shared<spdlog::logger>(name, begin(sinks), end(sinks));
+  console->set_pattern("%^[%d-%m-%Y %T.%e][%l][%n] %v%$");
+
+  spdlog::register_logger(console);
+
+  return spdlog::get(name);
+}

src/logger.h

@@ -0,0 +1,20 @@
+#ifndef LOGGER_HPP
+#define LOGGER_HPP
+#include <spdlog/spdlog.h>
+
+#include <spdlog/sinks/basic_file_sink.h>
+#include <spdlog/sinks/daily_file_sink.h>
+#include <spdlog/sinks/stdout_color_sinks.h>
+
+#include <QProcessEnvironment>
+#include <QQmlApplicationEngine>
+#include <QSequentialIterable>
+#include <QString>
+#include <QVariant>
+#include <QtCore>
+#include <QtNetwork>
+
+std::shared_ptr<spdlog::logger>
+initLogger(std::string name);
+
+#endif

src/main.cpp

@@ -4,6 +4,7 @@
 #endif
 
 #include "enums.hpp"
+#include "logger.h"
 #include "utils.hpp"
 #include <cstdlib>
 
@@ -12,6 +13,7 @@
 #include <QApplication>
 #include <QProcessEnvironment>
 #include <QQmlApplicationEngine>
+#include <QtConcurrent>
 #include <QtCore>
 #include <QtQml>
 #include <stdbool.h>
@@ -45,10 +47,50 @@ catchUnixSignals(std::initializer_list<int> quitSignals)
 }
 #endif
 
+auto qmlLogger = initLogger("qml");
+auto miscLogger = initLogger("misc");
+
+void
+spdLogger(QtMsgType type, const QMessageLogContext& context, const QString& msg)
+{
+  std::string localMsg = msg.toUtf8().constData();
+  std::shared_ptr<spdlog::logger> logger;
+  if (QString(context.category).startsWith(QString("qml"))) {
+    logger = qmlLogger;
+  } else {
+    logger = miscLogger;
+  }
+
+  switch (type) {
+    case QtDebugMsg:
+      logger->debug("{}", localMsg);
+      break;
+    case QtInfoMsg:
+      logger->info("{}", localMsg);
+      break;
+    case QtWarningMsg:
+      logger->warn("{}", localMsg);
+      break;
+    case QtCriticalMsg:
+      logger->critical("{}", localMsg);
+      break;
+    case QtFatalMsg:
+      logger->critical("{}", localMsg);
+      abort();
+  }
+}
+
 int
 main(int argc, char* argv[])
 {
 
+  qInstallMessageHandler(spdLogger);
+
+  auto launcherLogger = initLogger("launcher");
+
+  launcherLogger->info("Starting up!");
+
+  QString backendString;
 #ifdef DISABLE_MpvPlayerBackend
   Enums::Backends backend = Enums::Backends::DirectMpvBackend;
 #else
@@ -66,7 +108,6 @@ main(int argc, char* argv[])
 
   QSettings settings;
 
-#ifdef GIT_COMMIT_HASH
   bool checkForUpdates =
     settings.value("Backend/checkForUpdatesOnLaunch", false).toBool();
   for (int i = 1; i < argc; ++i) {
@@ -76,9 +117,8 @@ main(int argc, char* argv[])
   }
 
   if (checkForUpdates) {
-    Utils::checkForUpdates();
+    QtConcurrent::run(Utils::checkForUpdates);
   }
-#endif
 
   QString backendSetting = settings.value("Backend/backend", "").toString();
   if (backendSetting.length() == 0) {
@@ -88,20 +128,23 @@ main(int argc, char* argv[])
     settings.setValue("Backend/backend", "direct-mpv");
 #endif
   }
-
-  qDebug() << backendSetting;
+  backendString = backendSetting;
 
   for (int i = 1; i < argc; ++i) {
     if (!qstrcmp(argv[i], "--update")) {
       Utils::updateAppImage();
     } else if (!qstrcmp(argv[i], "--backend=mpv") || backendSetting == "mpv") {
       backend = Enums::Backends::MpvBackend;
+      backendString = QString("mpv");
     } else if (!qstrcmp(argv[i], "--backend=direct-mpv") ||
                backendSetting == "direct-mpv") {
+      backendString = QString("direct-mpv");
       backend = Enums::Backends::DirectMpvBackend;
     }
   }
 
+  launcherLogger->info("Using backend={}", backendString.toUtf8().constData());
+
   Utils::SetDPMS(false);
 
   QString newpath =
@@ -116,6 +159,7 @@ main(int argc, char* argv[])
   qRegisterMetaType<Enums::Backends>("Enums.Backends");
   qRegisterMetaType<Enums::Commands>("Enums.Commands");
   qmlRegisterType<Process>("player", 1, 0, "Process");
+
   qmlRegisterType<ThumbnailCache>("player", 1, 0, "ThumbnailCache");
 
   qmlRegisterType<UtilsClass>("player", 1, 0, "Utils");
@@ -139,6 +183,7 @@ main(int argc, char* argv[])
   }
 
   std::setlocale(LC_NUMERIC, "C");
+  launcherLogger->info("Loading player...");
 
   QQmlApplicationEngine engine;
   engine.load(QUrl(QStringLiteral("qrc:///main.qml")));

src/qml/ControlsBar.qml

@@ -36,7 +36,7 @@ Item {
 
         var component = Qt.createComponent(themeName + "ButtonLayout.qml")
         if (component.status == Component.Error) {
-            console.log("Error loading component:", component.errorString())
+            console.error("Error loading component: " + component.errorString())
         }
         component.createObject(controlsBar, {
 

src/qml/UIComponents/PlayPauseButton.qml

@@ -25,7 +25,6 @@ Button {
         target: player
         enabled: true
         onPlayStatusChanged: function (status) {
-            console.log(icon.height)
             if (status == Enums.PlayStatus.Playing) {
                 icon.source = "qrc:/icons/" + appearance.themeName + "/pause.svg"
             } else if (status == Enums.PlayStatus.Paused) {

src/qml/UIComponents/VolumeButton.qml

@@ -24,9 +24,6 @@ Button {
     }
 
     function updateStatus(status) {
-        if (volumeButton == null)
-            console.log("OwO")
-
         if (status == Enums.VolumeStatus.Muted) {
             volumeButton.icon.source = "qrc:/icons/" + appearance.themeName + "/volume-mute.svg"
         } else if (status == Enums.VolumeStatus.Low) {

src/qml/main.qml

@@ -202,6 +202,8 @@ Window {
         }
 
         function startPlayer() {
+            console.info("OwO!")
+
             var args = Qt.application.arguments
             var len = Qt.application.arguments.length
             var argNo = 0

src/utils.cpp

@@ -1,4 +1,6 @@
 #include "utils.hpp"
+#include "logger.h"
+
 #include <stdbool.h>
 
 #include <QApplication>
@@ -20,6 +22,9 @@
 #endif
 #endif
 
+auto utilsLogger = initLogger("utils");
+auto updaterLogger = initLogger("updater");
+
 namespace Utils {
 QString
 getPlatformName()
@@ -45,7 +50,8 @@ checkForUpdates()
 #else
   QString current_version = QString("Unknown");
 #endif
-  qDebug() << "Current Version: " << current_version;
+  updaterLogger->info("Current Version: {}",
+                      current_version.toUtf8().constData());
 
   QNetworkRequest request(QUrl("https://api.github.com/repos/NamedKitten/"
                                "KittehPlayer/releases/tags/continuous"));
@@ -61,8 +67,10 @@ checkForUpdates()
 
   if (json["target_commitish"].toString().length() != 0) {
     if (json["target_commitish"].toString().endsWith(current_version) == 0) {
-      qDebug() << "Latest Version: " << json["target_commitish"].toString();
-      qDebug() << "Update Available. Please update ASAP.";
+      updaterLogger->info(
+        "Latest Version: {}",
+        json["target_commitish"].toString().toUtf8().constData());
+      updaterLogger->info("Update Available. Please update ASAP.");
       QProcess notifier;
       notifier.setProcessChannelMode(QProcess::ForwardedChannels);
       notifier.start("notify-send",
@@ -72,13 +80,14 @@ checkForUpdates()
       notifier.waitForFinished();
     }
   } else {
-    qDebug() << "Couldn't check for new version.";
+    updaterLogger->error("Couldn't check for new version.");
   }
 }
 
 void
 updateAppImage()
 {
+  updaterLogger->info("Launching updater");
   QString program =
     QProcessEnvironment::systemEnvironment().value("APPDIR", "") +
     "/usr/bin/appimageupdatetool";
@@ -119,11 +128,11 @@ SetScreensaver(WId wid, bool on)
   QProcess xdgScreensaver;
   xdgScreensaver.setProcessChannelMode(QProcess::ForwardedChannels);
   if (on) {
-    qDebug() << "Enabling screensaver.";
+    utilsLogger->info("Enabling screensaver.");
     xdgScreensaver.start("xdg-screensaver",
                          QStringList() << "resume" << QString::number(wid));
   } else {
-    qDebug() << "Disabling screensaver.";
+    utilsLogger->info("Disabling screensaver.");
     xdgScreensaver.start("xdg-screensaver",
                          QStringList() << "suspend" << QString::number(wid));
   }
@@ -140,13 +149,13 @@ SetDPMS(bool on)
   QProcess xsetProcess;
   xsetProcess.setProcessChannelMode(QProcess::ForwardedChannels);
   if (on) {
-    qDebug() << "Enabled DPMS.";
+    utilsLogger->info("Enabled DPMS.");
     xsetProcess.start("xset",
                       QStringList() << "s"
                                     << "on"
                                     << "+dpms");
   } else {
-    qDebug() << "Disabled DPMS.";
+    utilsLogger->info("Disabled DPMS.");
     xsetProcess.start("xset",
                       QStringList() << "s"
                                     << "off"
@@ -154,7 +163,8 @@ SetDPMS(bool on)
   }
   xsetProcess.waitForFinished();
 #else
-  qDebug() << "Can't set DPMS for platform: " << getPlatformName();
+  utilsLogger->error("Can't set DPMS for platform: {}",
+                     getPlatformName().toUtf8().constData());
 #endif
 }
 
@@ -186,7 +196,8 @@ AlwaysOnTop(WId wid, bool on)
              &event);
 #endif
 #else
-  qDebug() << "Can't set on top for platform: " << getPlatformName();
+  utilsLogger->error("Can't set on top for platform: {}",
+                     getPlatformName().toUtf8().constData());
 #endif
 }
 }