# HG changeset patch
# User Chris Cannam
# Date 1578498058 0
# Node ID 3612bfc249508871109ade0d05a6dd4b5db3ec97
# Parent  d811380516f662af1d5234b4fcc04f0bac6222fb
More comprehensive debug output

diff -r d811380516f6 -r 3612bfc24950 main/OSCHandler.cpp
--- a/main/OSCHandler.cpp	Wed Jan 08 15:39:34 2020 +0000
+++ b/main/OSCHandler.cpp	Wed Jan 08 15:40:58 2020 +0000
@@ -33,21 +33,31 @@
 #include <bqaudioio/SystemPlaybackTarget.h>
 
 #include <QFileInfo>
+#include <QTime>
+#include <QElapsedTimer>
+
+#define NOW (QTime::currentTime().toString(Qt::ISODateWithMs))
 
 void
 MainWindow::handleOSCMessage(const OSCMessage &message)
 {
-    SVDEBUG << "OSCHandler: method = \""
-            << message.getMethod() << "\"" << endl;
+    QElapsedTimer timer;
+    timer.start();
+    
+    SVDEBUG << "OSCHandler at " << NOW << ": handling message: "
+            << message.toString() << endl;
 
     if (message.getMethod() == "open") {
 
         if (message.getArgCount() == 1 &&
             message.getArg(0).canConvert(QVariant::String)) {
             QString path = message.getArg(0).toString();
-            if (open(path, ReplaceMainModel) != FileOpenSucceeded) {
-                cerr << "OSCHandler: File open failed for path \""
-                          << path << "\"" << endl;
+            if (open(path, ReplaceMainModel) == FileOpenSucceeded) {
+                SVDEBUG << "OSCHandler: Opened path \""
+                        << path << "\"" << endl;
+            } else {
+                SVCERR << "OSCHandler: File open failed for path \""
+                       << path << "\"" << endl;
             }
             //!!! we really need to spin here and not return until the
             // file has been completely decoded...
@@ -58,8 +68,11 @@
         if (message.getArgCount() == 1 &&
             message.getArg(0).canConvert(QVariant::String)) {
             QString path = message.getArg(0).toString();
-            if (open(path, CreateAdditionalModel) != FileOpenSucceeded) {
-                cerr << "OSCHandler: File open failed for path \""
+            if (open(path, CreateAdditionalModel) == FileOpenSucceeded) {
+                SVDEBUG << "OSCHandler: Opened additional path \""
+                        << path << "\"" << endl;
+            } else {
+                SVCERR << "OSCHandler: File open failed for path \""
                           << path << "\"" << endl;
             }
         }
@@ -75,9 +88,13 @@
         }
         std::vector<QString> recent = m_recentFiles.getRecent();
         if (n >= 0 && n < int(recent.size())) {
-            if (open(recent[n], ReplaceMainModel) != FileOpenSucceeded) {
-                cerr << "OSCHandler: File open failed for path \""
-                          << recent[n] << "\"" << endl;
+            QString path = recent[n];
+            if (open(path, ReplaceMainModel) == FileOpenSucceeded) {
+                SVDEBUG << "OSCHandler: Opened recent path \""
+                        << path << "\"" << endl;
+            } else {
+                SVCERR << "OSCHandler: File open failed for path \""
+                       << path << "\"" << endl;
             }
         }
 
@@ -88,9 +105,13 @@
             message.getArg(0).canConvert(QVariant::String)) {
             path = message.getArg(0).toString();
             if (QFileInfo(path).exists()) {
-                SVDEBUG << "OSCHandler: Refusing to overwrite existing file in save" << endl;
+                SVCERR << "OSCHandler: Refusing to overwrite existing file in save" << endl;
+            } else if (saveSessionFile(path)) {
+                SVDEBUG << "OSCHandler: Saved session to path \""
+                        << path << "\"" << endl;
             } else {
-                saveSessionFile(path);
+                SVCERR << "OSCHandler: Save failed to path \""
+                       << path << "\"" << endl;
             }
         }
 
@@ -102,18 +123,21 @@
                 message.getArg(0).canConvert(QVariant::String)) {
                 path = message.getArg(0).toString();
                 if (QFileInfo(path).exists()) {
-                    SVDEBUG << "OSCHandler: Refusing to overwrite existing file in export" << endl;
+                    SVCERR << "OSCHandler: Refusing to overwrite existing file in export" << endl;
                 } else {
                     WavFileWriter writer(path,
                                          getMainModel()->getSampleRate(),
                                          getMainModel()->getChannelCount(),
                                          WavFileWriter::WriteToTemporary);
                     MultiSelection ms = m_viewManager->getSelection();
-                    if (!ms.getSelections().empty()) {
-                        //!!! todo: update WavFileWriter!
-                        writer.writeModel(getMainModel().get(), &ms);
+                    if (writer.writeModel
+                        (getMainModel().get(),
+                         ms.getSelections().empty() ? nullptr : &ms)) {
+                        SVDEBUG << "OSCHandler: Exported audio to path \""
+                                << path << "\"" << endl;
                     } else {
-                        writer.writeModel(getMainModel().get());
+                        SVCERR << "OSCHandler: Export failed to path \""
+                               << path << "\"" << endl;
                     }
                 }
             }
@@ -213,10 +237,12 @@
             if (message.getArg(0).canConvert(QVariant::String) &&
                 message.getArg(0).toString() == "similar") {
 
+                SVDEBUG << "OSCHandler: Calling ffwdSimilar" << endl;
                 ffwdSimilar();
             }
         } else {
 
+            SVDEBUG << "OSCHandler: Calling ffwd" << endl;
             ffwd();
         }
 
@@ -227,22 +253,26 @@
             if (message.getArg(0).canConvert(QVariant::String) &&
                 message.getArg(0).toString() == "similar") {
 
+                SVDEBUG << "OSCHandler: Calling rewindSimilar" << endl;
                 rewindSimilar();
             }
         } else {
 
+            SVDEBUG << "OSCHandler: Calling rewind" << endl;
             rewind();
         }
 
     } else if (message.getMethod() == "stop") {
             
-            if (m_playSource->isPlaying()) {
-                // As with play, we want to use the MainWindow
-                // function rather than call m_playSource directly
-                // because that way the audio driver suspend/resume
-                // etc is handled properly
-                MainWindow::stop();
-            }
+        if (m_playSource->isPlaying()) {
+            // As with play, we want to use the MainWindow function
+            // rather than call m_playSource directly because that way
+            // the audio driver suspend/resume etc is handled properly
+            SVDEBUG << "OSCHandler: Calling stop" << endl;
+            MainWindow::stop();
+        } else {
+            SVDEBUG << "OSCHandler: Not playing, doing nothing" << endl;
+        }
 
     } else if (message.getMethod() == "loop") {
 
@@ -251,8 +281,10 @@
 
             QString str = message.getArg(0).toString();
             if (str == "on") {
+                SVDEBUG << "OSCHandler: Enabling loop mode" << endl;
                 m_viewManager->setPlayLoopMode(true);
             } else if (str == "off") {
+                SVDEBUG << "OSCHandler: Disabling loop mode" << endl;
                 m_viewManager->setPlayLoopMode(false);
             }
         }
@@ -264,8 +296,10 @@
 
             QString str = message.getArg(0).toString();
             if (str == "on") {
+                SVDEBUG << "OSCHandler: Enabling solo mode" << endl;
                 m_viewManager->setPlaySoloMode(true);
             } else if (str == "off") {
+                SVDEBUG << "OSCHandler: Disabling solo mode" << endl;
                 m_viewManager->setPlaySoloMode(false);
             }
         }
@@ -292,6 +326,9 @@
 
                 f0 = lrint(t0 * getMainModel()->getSampleRate());
                 f1 = lrint(t1 * getMainModel()->getSampleRate());
+
+                SVDEBUG << "OSCHandler: Converted selection extents to frames "
+                        << f0 << " and " << f1 << endl;
                 
                 Pane *pane = m_paneStack->getCurrentPane();
                 Layer *layer = nullptr;
@@ -302,6 +339,11 @@
                                               Layer::SnapLeft, -1);
                     layer->snapToFeatureFrame(pane, f1, resolution,
                                               Layer::SnapRight, -1);
+
+                    SVDEBUG << "OSCHandler: Snapped selection extents to "
+                            << f0 << " and " << f1 << " for current layer \""
+                            << layer->getLayerPresentationName() << "\""
+                            << endl;
                 }
 
             } else if (message.getArgCount() == 1 &&
@@ -309,8 +351,13 @@
 
                 QString str = message.getArg(0).toString();
                 if (str == "none") {
+                    SVDEBUG << "OSCHandler: Clearing selection" << endl;
                     m_viewManager->clearSelections();
                     done = true;
+                } else if (str == "all") {
+                    SVDEBUG << "OSCHandler: Selecting all" << endl;
+                    f0 = getModelsStartFrame();
+                    f0 = getModelsEndFrame();
                 }
             }
 
@@ -321,6 +368,13 @@
                     m_viewManager->addSelection(Selection(f0, f1));
                 }
             }
+
+            SVDEBUG << "OSCHandler: Selection now is "
+                    << m_viewManager->getSelection().toString() << endl;
+
+        } else {
+            SVCERR << "OSCHandler: No main model, can't modify selection"
+                   << endl;
         }
 
     } else if (message.getMethod() == "add") {
@@ -336,7 +390,7 @@
                     channel = message.getArg(0).toInt();
                     if (channel < -1 ||
                         channel > int(getMainModel()->getChannelCount())) {
-                        cerr << "WARNING: OSCHandler: channel "
+                        SVCERR << "WARNING: OSCHandler: channel "
                                   << channel << " out of range" << endl;
                         channel = -1;
                     }
@@ -348,28 +402,33 @@
                     LayerFactory::getInstance()->getLayerTypeForName(str);
 
                 if (type == LayerFactory::UnknownLayer) {
-                    cerr << "WARNING: OSCHandler: unknown layer "
-                              << "type " << str << endl;
+                    SVCERR << "WARNING: OSCHandler: unknown layer "
+                           << "type " << str << endl;
                 } else {
 
                     LayerConfiguration configuration(type,
                                                      getMainModelId(),
                                                      channel);
+
+                    QString pname = LayerFactory::getInstance()->
+                        getLayerPresentationName(type);
                     
-                    addPane(configuration,
-                            tr("Add %1 Pane")
-                            .arg(LayerFactory::getInstance()->
-                                 getLayerPresentationName(type)));
+                    addPane(configuration, tr("Add %1 Pane") .arg(pname));
+
+                    SVDEBUG << "OSCHandler: Added pane \"" << pname
+                            << "\"" << endl;
                 }
             }
         }
 
     } else if (message.getMethod() == "undo") {
 
+        SVDEBUG << "OSCHandler: Calling undo" << endl;
         CommandHistory::getInstance()->undo();
 
     } else if (message.getMethod() == "redo") {
 
+        SVDEBUG << "OSCHandler: Calling redo" << endl;
         CommandHistory::getInstance()->redo();
 
     } else if (message.getMethod() == "set") {
@@ -474,12 +533,21 @@
         if (paneIndex >= 0 && paneIndex < m_paneStack->getPaneCount()) {
             Pane *pane = m_paneStack->getPane(paneIndex);
             m_paneStack->setCurrentPane(pane);
+            SVDEBUG << "OSCHandler: Set current pane to index "
+                    << paneIndex << " (pane id " << pane->getId()
+                    << ")" << endl;
             if (layerIndex >= 0 && layerIndex < pane->getLayerCount()) {
                 Layer *layer = pane->getFixedOrderLayer(layerIndex);
                 m_paneStack->setCurrentLayer(pane, layer);
+                SVDEBUG << "OSCHandler: Set current layer to index "
+                        << layerIndex << " (layer \""
+                        << layer->getLayerPresentationName() << "\")" << endl;
             } else if (wantLayer && layerIndex == -1) {
                 m_paneStack->setCurrentLayer(pane, nullptr);
-            }
+            } else if (wantLayer) {
+                SVCERR << "OSCHandler: Layer index "
+                       << layerIndex << " out of range for pane" << endl;
+            }                
         }
 
     } else if (message.getMethod() == "delete") {
@@ -491,15 +559,18 @@
 
             if (target == "pane") {
 
+                SVDEBUG << "OSCHandler: Calling deleteCurrentPane" << endl;
                 deleteCurrentPane();
 
             } else if (target == "layer") {
 
+                SVDEBUG << "OSCHandler: Calling deleteCurrentLayer" << endl;
                 deleteCurrentLayer();
 
             } else {
                 
-                cerr << "WARNING: OSCHandler: Unknown delete target " << target << endl;
+                SVCERR << "WARNING: OSCHandler: Unknown delete target \""
+                       << target << "\"" << endl;
             }
         }
 
@@ -530,7 +601,12 @@
                                           int(round(1.0 / level)));
                 }
                 if (currentPane) {
+                    SVDEBUG << "OSCHandler: Setting zoom level to "
+                            << zoomLevel << endl;
                     currentPane->setZoomLevel(zoomLevel);
+                } else {
+                    SVCERR << "OSCHandler: No current pane, can't set zoom"
+                           << endl;
                 }
             }
         }
@@ -601,31 +677,43 @@
 
     } else if (message.getMethod() == "transform") {
 
-        Pane *pane = m_paneStack->getCurrentPane();
-
-        if (getMainModel() &&
-            pane &&
-            message.getArgCount() == 1 &&
+        if (message.getArgCount() == 1 &&
             message.getArg(0).canConvert(QVariant::String)) {
 
-            TransformId transformId = message.getArg(0).toString();
+            Pane *pane = m_paneStack->getCurrentPane();
+            
+            if (getMainModel() && pane) {
 
-            Transform transform = TransformFactory::getInstance()->
-                getDefaultTransformFor(transformId);
+                TransformId transformId = message.getArg(0).toString();
+
+                Transform transform = TransformFactory::getInstance()->
+                    getDefaultTransformFor(transformId);
+
+                SVDEBUG << "OSCHandler: Running transform on main model:"
+                        << transform.toXmlString() << endl;
             
-            Layer *newLayer = m_document->createDerivedLayer
-                (transform, getMainModelId());
-
-            if (newLayer) {
-                m_document->addLayerToView(pane, newLayer);
-                m_recentTransforms.add(transformId);
-                m_paneStack->setCurrentLayer(pane, newLayer);
+                Layer *newLayer = m_document->createDerivedLayer
+                    (transform, getMainModelId());
+                
+                if (newLayer) {
+                    m_document->addLayerToView(pane, newLayer);
+                    m_recentTransforms.add(transformId);
+                    m_paneStack->setCurrentLayer(pane, newLayer);
+                } else {
+                    SVCERR << "OSCHandler: Transform failed to run" << endl;
+                }
+            } else {
+                SVCERR << "OSCHandler: Lack main model or pane, "
+                       << "can't run transform" << endl;
             }
-        }
+        }            
 
     } else {
-        cerr << "WARNING: OSCHandler: Unknown or unsupported "
+        SVCERR << "WARNING: OSCHandler: Unknown or unsupported "
                   << "method \"" << message.getMethod()
                   << "\"" << endl;
     }
+
+    SVDEBUG << "OSCHandler at " << NOW << ": finished message: "
+            << message.toString() << " in " << timer.elapsed() << "ms" << endl;
 }