Buffer stdout and stderr properly, and integrate with python's logging module

data/data.qrc

@@ -340,5 +340,6 @@
         <file>pythonlibs/uic/port_v2/string_io.py</file>
         <file>pythonlibs/uic/properties.py</file>
         <file>pythonlibs/uic/uiparser.py</file>
+        <file>pythonlibs/clementinelogging.py</file>
     </qresource>
 </RCC>

data/pythonlibs/clementinelogging.py

@@ -0,0 +1,14 @@
+import clementine
+import logging
+
+
+class ClementineLogHandler(logging.Handler):
+  def emit(self, record):
+    clementine.pythonengine.HandleLogRecord(
+      record.levelno, record.name, record.lineno, record.getMessage())
+
+
+def setup_logging():
+  root = logging.getLogger()
+  root.addHandler(ClementineLogHandler())
+  root.setLevel(logging.NOTSET)

scripts/digitallyimported-radio/servicebase.py

@@ -7,9 +7,13 @@ from PythonQt.QtGui     import QAction, QDesktopServices, QIcon, QMenu, \
 from PythonQt.QtNetwork import QNetworkRequest
 
 import json
+import logging
 import operator
 import os.path
 
+LOGGER = logging.getLogger("di.servicebase")
+
+
 class DigitallyImportedUrlHandler(clementine.UrlHandler):
   def __init__(self, url_scheme, service):
     clementine.UrlHandler.__init__(self, service)
@@ -33,6 +37,7 @@ class DigitallyImportedUrlHandler(clementine.UrlHandler):
       return result
 
     key = original_url.host()
+    LOGGER.info("Loading station %s", key)
     self.service.LoadStation(key)
 
     # Save the original URL so we can emit it in the finished signal later
@@ -59,6 +64,8 @@ class DigitallyImportedUrlHandler(clementine.UrlHandler):
     parser = clementine.PlaylistParser(clementine.library)
     songs = parser.LoadFromDevice(reply)
 
+    LOGGER.info("Loading station finished, got %d songs", len(songs))
+
     # Failed to get the playlist?
     if len(songs) == 0:
       self.service.StreamError("Error loading playlist '%s'" % reply.url().toString())
@@ -160,6 +167,8 @@ class DigitallyImportedServiceBase(clementine.RadioService):
     if self.task_id is not None:
       return
 
+    LOGGER.info("Getting stream list from '%s'", self.STREAM_LIST_URL)
+
     # Request the list of stations
     self.refresh_streams_reply = self.network.get(QNetworkRequest(self.STREAM_LIST_URL))
     self.refresh_streams_reply.connect("finished()", self.RefreshStreamsFinished)
@@ -188,13 +197,14 @@ class DigitallyImportedServiceBase(clementine.RadioService):
     # Sort by name
     streams = sorted(streams, key=operator.itemgetter("name"))
 
+    LOGGER.info("Loaded %d streams", len(streams))
+
     # Now we have the list of streams, so clear any existing items in the list
     # and insert the new ones
     if self.root.hasChildren():
       self.root.removeRows(0, self.root.rowCount())
 
     for stream in streams:
-      print stream
       song = clementine.Song()
       song.set_title(stream["name"])
       song.set_artist(self.SERVICE_DESCRIPTION)

src/core/logging.cpp

@@ -123,16 +123,7 @@ void SetLevels(const QString& levels) {
   }
 }
 
-QDebug CreateLogger(Level level, const char* pretty_function, int line) {
+QString ParsePrettyFunction(const char * pretty_function) {
-  // Map the level to a string
-  const char* level_name = NULL;
-  switch (level) {
-    case Level_Debug:   level_name = " DEBUG "; break;
-    case Level_Info:    level_name = " INFO  "; break;
-    case Level_Warning: level_name = " WARN  "; break;
-    case Level_Error:   level_name = " ERROR "; break;
-  }
-
   // Get the class name out of the function name.
   QString class_name = pretty_function;
   const int paren = class_name.indexOf('(');
@@ -150,6 +141,19 @@ QDebug CreateLogger(Level level, const char* pretty_function, int line) {
     class_name = class_name.mid(space+1);
   }
 
+  return class_name;
+}
+
+QDebug CreateLogger(Level level, const QString& class_name, int line) {
+  // Map the level to a string
+  const char* level_name = NULL;
+  switch (level) {
+    case Level_Debug:   level_name = " DEBUG "; break;
+    case Level_Info:    level_name = " INFO  "; break;
+    case Level_Warning: level_name = " WARN  "; break;
+    case Level_Error:   level_name = " ERROR "; break;
+  }
+
   // Check the settings to see if we're meant to show or hide this message.
   Level threshold_level = sDefaultLevel;
   if (sClassLevels && sClassLevels->contains(class_name)) {

src/core/logging.h

@@ -28,7 +28,8 @@
 #  define qLog(level) while (false) QNoDebug()
 #else
 #  define qLog(level) \
-     logging::CreateLogger(logging::Level_##level, __PRETTY_FUNCTION__, __LINE__)
+     logging::CreateLogger(logging::Level_##level, \
+         logging::ParsePrettyFunction(__PRETTY_FUNCTION__), __LINE__)
 #endif
 
 namespace logging {
@@ -48,7 +49,8 @@ namespace logging {
   void Init();
   void SetLevels(const QString& levels);
 
-  QDebug CreateLogger(Level level, const char* pretty_function, int line);
+  QString ParsePrettyFunction(const char* pretty_function);
+  QDebug CreateLogger(Level level, const QString& class_name, int line);
 
   void GLog(const char* domain, int level, const char* message, void* user_data);
 

src/scripting/python/pythonengine.cpp

@@ -76,18 +76,22 @@ bool PythonEngine::EnsureInitialised() {
   if (initialised_)
     return true;
 
-  PythonStdOut("Initialising python...");
-
   PythonQt::init(PythonQt::IgnoreSiteModule | PythonQt::RedirectStdOut);
+  PythonQt* python_qt = PythonQt::self();
+
+  // Add the Qt bindings
   PythonQt_init_QtCore(0);
   PythonQt_init_QtGui(0);
   PythonQt_init_QtNetwork(0);
 
-  PythonQt* python_qt = PythonQt::self();
+  // Set the importer to allow imports from Qt resource paths
   python_qt->installDefaultImporter();
-  python_qt->addDecorators(new ObjectDecorators);
   python_qt->addSysPath(":/pythonlibs/");
 
+  // Add some extra decorators on QObjects
+  python_qt->addDecorators(new ObjectDecorators);
+
+  // Register converters for list types
   PythonQtConv::registerMetaTypeToPythonConverter(qMetaTypeId<SongList>(),
       PythonQtConvertListOfValueTypeToPythonList<SongList, Song>);
   PythonQtConv::registerMetaTypeToPythonConverter(QMetaType::type("QList<Song>"),
@@ -106,6 +110,7 @@ bool PythonEngine::EnsureInitialised() {
   PythonQtConv::registerPythonToMetaTypeConverter(qMetaTypeId<CoverSearchResults>(),
       PythonQtConvertPythonListToListOfValueType<CoverSearchResults, CoverSearchResult>);
 
+  // Connect stdout, stderr
   connect(python_qt, SIGNAL(pythonStdOut(QString)), SLOT(PythonStdOut(QString)));
   connect(python_qt, SIGNAL(pythonStdErr(QString)), SLOT(PythonStdErr(QString)));
 
@@ -132,15 +137,17 @@ bool PythonEngine::EnsureInitialised() {
   clementine_module_.addObject("ui",           manager()->ui());
   clementine_module_.addObject("pythonengine", this);
 
+  // Set up logging integration
+  PythonQtObjectPtr logging_module = python_qt->importModule("clementinelogging");
+  logging_module.call("setup_logging");
+
   // Create a module for scripts
-  qLog(Debug) << "Creating scripts module";
   scripts_module_ = python_qt->createModuleFromScript(kScriptModulePrefix);
 
   // The modules model contains all the modules
   modules_model_->clear();
   AddModuleToModel("__main__", python_qt->getMainModule());
 
-  qLog(Debug) << "Python initialisation complete";
   initialised_ = true;
   return true;
 }
@@ -171,12 +178,42 @@ void PythonEngine::DestroyScript(Script* script) {
   delete script;
 }
 
+void PythonEngine::AddStringToBuffer(const QString& str,
+                                     const QString& buffer_name,
+                                     QString* buffer, bool error) {
+  buffer->append(str);
+
+  int index = buffer->indexOf('\n');
+  while (index != -1) {
+    const QString message = buffer->left(index);
+    buffer->remove(0, index + 1);
+    index = buffer->indexOf('\n');
+
+    logging::CreateLogger(logging::Level_Info, buffer_name, -1) <<
+        message.toUtf8().constData();
+    manager()->AddLogLine(buffer_name, str, error);
+  }
+}
+
 void PythonEngine::PythonStdOut(const QString& str) {
-  manager()->AddLogLine("Python", str, false);
+  AddStringToBuffer(str, "sys.stdout", &stdout_buffer_, false);
 }
 
 void PythonEngine::PythonStdErr(const QString& str) {
-  manager()->AddLogLine("Python", str, true);
+  AddStringToBuffer(str, "sys.stderr", &stdout_buffer_, true);
+}
+
+void PythonEngine::HandleLogRecord(int level, const QString& logger_name,
+                                   int lineno, const QString& message) {
+  logging::Level        level_name = logging::Level_Debug;
+  if      (level >= 40) level_name = logging::Level_Error;
+  else if (level >= 30) level_name = logging::Level_Warning;
+  else if (level >= 20) level_name = logging::Level_Info;
+
+  logging::CreateLogger(level_name, logger_name, lineno) <<
+      message.toUtf8().constData();
+  manager()->AddLogLine(QString("%1:%2").arg(logger_name).arg(lineno),
+                        message, level >= 30);
 }
 
 void PythonEngine::AddModuleToModel(const QString& name, PythonQtObjectPtr ptr) {

src/scripting/python/pythonengine.h

@@ -50,6 +50,10 @@ public:
   Script* CreateScript(const ScriptInfo& info);
   void DestroyScript(Script* script);
 
+public slots:
+  void HandleLogRecord(int level, const QString& logger_name, int lineno,
+                       const QString& message);
+
 private slots:
   void PythonStdOut(const QString& str);
   void PythonStdErr(const QString& str);
@@ -58,6 +62,9 @@ private:
   void AddModuleToModel(const QString& name, PythonQtObjectPtr ptr);
   void RemoveModuleFromModel(const QString& name);
 
+  void AddStringToBuffer(const QString& str, const QString& buffer_name,
+                         QString* buffer, bool error);
+
 private:
   static PythonEngine* sInstance;
   bool initialised_;
@@ -67,6 +74,9 @@ private:
 
   QMap<QString, Script*> loaded_scripts_;
   QStandardItemModel* modules_model_;
+
+  QString stdout_buffer_;
+  QString stderr_buffer_;
 };
 
 #endif // PYTHONENGINE_H

src/scripting/scriptmanager.cpp

@@ -315,8 +315,6 @@ void ScriptManager::AddLogLine(const QString& who, const QString& message, bool
     log_lines_ << html;
     log_lines_plain_ << plain;
     emit LogLineAdded(html);
-
-    qLog(Info) << plain.toLocal8Bit().constData();
   }
 }