# HG changeset patch
# User Chris Cannam
# Date 1479312762 0
# Node ID a99641535e0245756f7ddb8bfceb894bea2d844a
# Parent  abfc498c52bc42678722a70ec57cc30ddb6c8a34
Debug output improvements, and make the checker actually attempt to call the descriptor function for known plugin types

diff -r abfc498c52bc -r a99641535e02 plugin/FeatureExtractionPluginFactory.cpp
--- a/plugin/FeatureExtractionPluginFactory.cpp	Tue Nov 15 16:54:02 2016 +0000
+++ b/plugin/FeatureExtractionPluginFactory.cpp	Wed Nov 16 16:12:42 2016 +0000
@@ -34,17 +34,14 @@
 
 #ifdef HAVE_PIPER
         if (Preferences::getInstance()->getRunPluginsInProcess()) {
-            SVDEBUG << "FeatureExtractionPluginFactory: creating native instance"
-                    << endl;
+            SVDEBUG << "FeatureExtractionPluginFactory: in-process preference set, using native factory" << endl;
             instance = new NativeVampPluginFactory();
         } else {
-            SVDEBUG << "FeatureExtractionPluginFactory: creating Piper instance"
-                    << endl;
+            SVDEBUG << "FeatureExtractionPluginFactory: in-process preference not set, using Piper factory" << endl;
             instance = new PiperVampPluginFactory();
         }
 #else
-        SVDEBUG << "FeatureExtractionPluginFactory: no Piper support enabled,"
-                << " creating native instance" << endl;
+        SVDEBUG << "FeatureExtractionPluginFactory: no Piper support compiled in, using native factory" << endl;
         instance = new NativeVampPluginFactory();
 #endif
     }
diff -r abfc498c52bc -r a99641535e02 plugin/PiperVampPluginFactory.cpp
--- a/plugin/PiperVampPluginFactory.cpp	Tue Nov 15 16:54:02 2016 +0000
+++ b/plugin/PiperVampPluginFactory.cpp	Wed Nov 16 16:12:42 2016 +0000
@@ -48,7 +48,15 @@
 
 //#define DEBUG_PLUGIN_SCAN_AND_INSTANTIATE 1
 
-PiperVampPluginFactory::PiperVampPluginFactory()
+class PiperVampPluginFactory::Logger : public piper_vamp::client::LogCallback {
+protected:
+    void log(std::string message) const override {
+        SVDEBUG << "PiperVampPluginFactory: " << message << endl;
+    }
+};
+
+PiperVampPluginFactory::PiperVampPluginFactory() :
+    m_logger(new Logger)
 {
     QString serverName = "piper-vamp-simple-server";
 
@@ -69,6 +77,11 @@
     }
 }
 
+PiperVampPluginFactory::~PiperVampPluginFactory()
+{
+    delete m_logger;
+}
+
 vector<QString>
 PiperVampPluginFactory::getPluginIdentifiers(QString &errorMessage)
 {
@@ -110,10 +123,16 @@
     if (psd.pluginKey == "") {
         return 0;
     }
+
+    SVDEBUG << "PiperVampPluginFactory: Creating Piper AutoPlugin for server "
+        << m_origins[identifier] << ", identifier " << identifier << endl;
     
     auto ap = new piper_vamp::client::AutoPlugin
         (m_origins[identifier].toStdString(),
-         psd.pluginKey, float(inputSampleRate), 0);
+         psd.pluginKey,
+         float(inputSampleRate),
+         0,
+         m_logger);
     
     if (!ap->isOK()) {
         delete ap;
@@ -169,8 +188,9 @@
     auto candidateLibraries =
         scan->getCandidateLibrariesFor(PluginScan::VampPlugin);
 
+    SVDEBUG << "PiperVampPluginFactory: Populating from " << executable << endl;
     SVDEBUG << "INFO: Have " << candidateLibraries.size()
-            << " candidate Vamp plugin libraries" << endl;
+            << " candidate Vamp plugin libraries from scanner" << endl;
         
     vector<string> from;
     for (const auto &c: candidateLibraries) {
@@ -195,13 +215,14 @@
         }
     }
     
-    piper_vamp::client::ProcessQtTransport transport(executable, "capnp");
+    piper_vamp::client::ProcessQtTransport transport(executable, "capnp", m_logger);
     if (!transport.isOK()) {
+        SVDEBUG << "PiperVampPluginFactory: Failed to start Piper process transport" << endl;
         errorMessage = QObject::tr("Could not start external plugin host");
         return;
     }
 
-    piper_vamp::client::CapnpRRClient client(&transport);
+    piper_vamp::client::CapnpRRClient client(&transport, m_logger);
 
     piper_vamp::ListRequest req;
     req.from = from;
@@ -211,10 +232,12 @@
     try {
         resp = client.listPluginData(req);
     } catch (piper_vamp::client::ServerCrashed) {
+        SVDEBUG << "PiperVampPluginFactory: Piper server crashed" << endl;
         errorMessage = QObject::tr
             ("External plugin host exited unexpectedly while listing plugins");
         return;
     } catch (const std::exception &e) {
+        SVDEBUG << "PiperVampPluginFactory: Exception caught: " << e.what() << endl;
         errorMessage = QObject::tr("External plugin host invocation failed: %1")
             .arg(e.what());
         return;
diff -r abfc498c52bc -r a99641535e02 plugin/PiperVampPluginFactory.h
--- a/plugin/PiperVampPluginFactory.h	Tue Nov 15 16:54:02 2016 +0000
+++ b/plugin/PiperVampPluginFactory.h	Wed Nov 16 16:12:42 2016 +0000
@@ -35,8 +35,7 @@
 {
 public:
     PiperVampPluginFactory();
-
-    virtual ~PiperVampPluginFactory() { }
+    virtual ~PiperVampPluginFactory();
 
     virtual std::vector<QString> getPluginIdentifiers(QString &errorMessage)
         override;
@@ -59,6 +58,9 @@
 
     void populate(QString &errorMessage);
     void populateFrom(const HelperExecPath::HelperExec &, QString &errorMessage);
+
+    class Logger;
+    Logger *m_logger;
 };
 
 #endif
diff -r abfc498c52bc -r a99641535e02 plugin/PluginScan.cpp
--- a/plugin/PluginScan.cpp	Tue Nov 15 16:54:02 2016 +0000
+++ b/plugin/PluginScan.cpp	Wed Nov 16 16:12:42 2016 +0000
@@ -36,7 +36,7 @@
 {
 protected:
     void log(std::string message) {
-        SVDEBUG << "PluginScan: " << message;
+        SVDEBUG << "PluginScan: " << message << endl;
     }
 };
 
diff -r abfc498c52bc -r a99641535e02 transform/FeatureExtractionModelTransformer.cpp
--- a/transform/FeatureExtractionModelTransformer.cpp	Tue Nov 15 16:54:02 2016 +0000
+++ b/transform/FeatureExtractionModelTransformer.cpp	Wed Nov 16 16:12:42 2016 +0000
@@ -107,8 +107,8 @@
         return false;
     }
 
-    cerr << "instantiating plugin for transform in thread "
-         << QThread::currentThreadId() << endl;
+    SVDEBUG << "FeatureExtractionModelTransformer: Instantiating plugin for transform in thread "
+            << QThread::currentThreadId() << endl;
     
     m_plugin = factory->instantiatePlugin(pluginId, input->getSampleRate());
     if (!m_plugin) {
@@ -136,13 +136,13 @@
     }
 
     SVDEBUG << "Initialising feature extraction plugin with channels = "
-              << channelCount << ", step = " << primaryTransform.getStepSize()
-              << ", block = " << primaryTransform.getBlockSize() << endl;
+            << channelCount << ", step = " << primaryTransform.getStepSize()
+            << ", block = " << primaryTransform.getBlockSize() << endl;
 
     if (!m_plugin->initialise(channelCount,
                               primaryTransform.getStepSize(),
                               primaryTransform.getBlockSize())) {
-
+        
         int pstep = primaryTransform.getStepSize();
         int pblock = primaryTransform.getBlockSize();
 
@@ -154,16 +154,24 @@
 
         if (primaryTransform.getStepSize() != pstep ||
             primaryTransform.getBlockSize() != pblock) {
+
+            SVDEBUG << "Initialisation failed, trying again with default step = "
+                    << primaryTransform.getStepSize()
+                    << ", block = " << primaryTransform.getBlockSize() << endl;
             
             if (!m_plugin->initialise(channelCount,
                                       primaryTransform.getStepSize(),
                                       primaryTransform.getBlockSize())) {
 
+                SVDEBUG << "Initialisation failed again" << endl;
+                
                 m_message = tr("Failed to initialise feature extraction plugin \"%1\"").arg(pluginId);
                 return false;
 
             } else {
-
+                
+                SVDEBUG << "Initialisation succeeded this time" << endl;
+                
                 m_message = tr("Feature extraction plugin \"%1\" rejected the given step and block sizes (%2 and %3); using plugin defaults (%4 and %5) instead")
                     .arg(pluginId)
                     .arg(pstep)
@@ -174,9 +182,13 @@
 
         } else {
 
+            SVDEBUG << "Initialisation failed" << endl;
+                
             m_message = tr("Failed to initialise feature extraction plugin \"%1\"").arg(pluginId);
             return false;
         }
+    } else {
+        SVDEBUG << "Initialisation succeeded" << endl;
     }
 
     if (primaryTransform.getPluginVersion() != "") {
@@ -237,8 +249,8 @@
 void
 FeatureExtractionModelTransformer::deinitialise()
 {
-    cerr << "deleting plugin for transform in thread "
-         << QThread::currentThreadId() << endl;
+    SVDEBUG << "FeatureExtractionModelTransformer: deleting plugin for transform in thread "
+            << QThread::currentThreadId() << endl;
     
     delete m_plugin;
     for (int j = 0; j < (int)m_descriptors.size(); ++j) {
@@ -250,8 +262,6 @@
 FeatureExtractionModelTransformer::createOutputModels(int n)
 {
     DenseTimeValueModel *input = getConformingInput();
-
-//    cerr << "FeatureExtractionModelTransformer::createOutputModel: sample type " << m_descriptor->sampleType << ", rate " << m_descriptor->sampleRate << endl;
     
     PluginRDFDescription description(m_transforms[n].getPluginIdentifier());
     QString outputId = m_transforms[n].getOutput();
@@ -291,10 +301,10 @@
         //!!! the resolution appropriately.  We can't properly display
         //!!! data with a higher resolution than the base model at all
         if (outputRate > input->getSampleRate()) {
-            cerr << "WARNING: plugin reports output sample rate as "
-                 << outputRate
-                 << " (can't display features with finer resolution than the input rate of "
-                 << modelRate << ")" << endl;
+            SVDEBUG << "WARNING: plugin reports output sample rate as "
+                    << outputRate
+                    << " (can't display features with finer resolution than the input rate of "
+                    << modelRate << ")" << endl;
             outputRate = modelRate;
         }
     }
@@ -313,7 +323,7 @@
 
     case Vamp::Plugin::OutputDescriptor::FixedSampleRate:
         if (outputRate <= 0.0) {
-            cerr << "WARNING: Fixed sample-rate plugin reports invalid sample rate " << m_descriptors[n]->sampleRate << "; defaulting to input rate of " << input->getSampleRate() << endl;
+            SVDEBUG << "WARNING: Fixed sample-rate plugin reports invalid sample rate " << m_descriptors[n]->sampleRate << "; defaulting to input rate of " << input->getSampleRate() << endl;
             modelResolution = 1;
         } else {
             modelResolution = int(round(modelRate / outputRate));
@@ -736,7 +746,7 @@
                 }                    
                 error = fftModels[ch]->getError();
                 if (error != "") {
-                    cerr << "FeatureExtractionModelTransformer::run: Abandoning, error is " << error << endl;
+                    SVDEBUG << "FeatureExtractionModelTransformer::run: Abandoning, error is " << error << endl;
                     m_abandoned = true;
                     m_message = error;
                     break;
@@ -879,7 +889,7 @@
 	Vamp::Plugin::OutputDescriptor::VariableSampleRate) {
 
 	if (!feature.hasTimestamp) {
-	    cerr
+	    SVDEBUG
 		<< "WARNING: FeatureExtractionModelTransformer::addFeature: "
 		<< "Feature has variable sample rate but no timestamp!"
 		<< endl;
@@ -915,7 +925,7 @@
     }
 
     if (frame < 0) {
-        cerr
+        SVDEBUG
             << "WARNING: FeatureExtractionModelTransformer::addFeature: "
             << "Negative frame counts are not supported (frame = " << frame
             << " from timestamp " << feature.timestamp
diff -r abfc498c52bc -r a99641535e02 transform/ModelTransformerFactory.cpp
--- a/transform/ModelTransformerFactory.cpp	Tue Nov 15 16:54:02 2016 +0000
+++ b/transform/ModelTransformerFactory.cpp	Wed Nov 16 16:12:42 2016 +0000
@@ -89,12 +89,14 @@
     bool ok = true;
     QString configurationXml = m_lastConfigurations[transform.getIdentifier()];
 
-    cerr << "last configuration: " << configurationXml << endl;
+    SVDEBUG << "ModelTransformer: last configuration for identifier " << transform.getIdentifier() << ": " << configurationXml << endl;
 
     Vamp::PluginBase *plugin = 0;
 
     if (RealTimePluginFactory::instanceFor(id)) {
 
+        SVDEBUG << "ModelTransformerFactory::getConfigurationForTransform: instantiating real-time plugin" << endl;
+        
         RealTimePluginFactory *factory = RealTimePluginFactory::instanceFor(id);
 
         sv_samplerate_t sampleRate = inputModel->getSampleRate();
@@ -113,7 +115,7 @@
 
     } else {
 
-        cerr << "getConfigurationForTransform: instantiating Vamp plugin" << endl;
+        SVDEBUG << "ModelTransformerFactory::getConfigurationForTransform: instantiating Vamp plugin" << endl;
 
         Vamp::Plugin *vp =
             FeatureExtractionPluginFactory::instance()->instantiatePlugin
@@ -152,6 +154,8 @@
 
         configurationXml = PluginXml(plugin).toXmlString();
 
+        SVDEBUG << "ModelTransformerFactory::getConfigurationForTransform: got configuration, deleting plugin" << endl;
+        
         delete plugin;
     }
 
diff -r abfc498c52bc -r a99641535e02 transform/TransformFactory.cpp
--- a/transform/TransformFactory.cpp	Tue Nov 15 16:54:02 2016 +0000
+++ b/transform/TransformFactory.cpp	Wed Nov 16 16:12:42 2016 +0000
@@ -753,6 +753,9 @@
     t.setIdentifier(id);
     if (rate != 0) t.setSampleRate(rate);
 
+    SVDEBUG << "TransformFactory::getDefaultTransformFor: identifier \""
+            << id << "\"" << endl;
+    
     Vamp::PluginBase *plugin = instantiateDefaultPluginFor(id, rate);
 
     if (plugin) {
@@ -768,6 +771,9 @@
 Vamp::PluginBase *
 TransformFactory::instantiatePluginFor(const Transform &transform)
 {
+    SVDEBUG << "TransformFactory::instantiatePluginFor: identifier \""
+            << transform.getIdentifier() << "\"" << endl;
+    
     Vamp::PluginBase *plugin = instantiateDefaultPluginFor
         (transform.getIdentifier(), transform.getSampleRate());
 
@@ -791,8 +797,8 @@
 
     if (t.getType() == Transform::FeatureExtraction) {
 
-//        cerr << "TransformFactory::instantiateDefaultPluginFor: identifier \""
-//             << identifier << "\" is a feature extraction transform" << endl;
+        SVDEBUG << "TransformFactory::instantiateDefaultPluginFor: identifier \""
+                << identifier << "\" is a feature extraction transform" << endl;
         
         FeatureExtractionPluginFactory *factory =
             FeatureExtractionPluginFactory::instance();
@@ -803,8 +809,8 @@
 
     } else if (t.getType() == Transform::RealTimeEffect) {
 
-//        cerr << "TransformFactory::instantiateDefaultPluginFor: identifier \""
-//             << identifier << "\" is a real-time transform" << endl;
+        SVDEBUG << "TransformFactory::instantiateDefaultPluginFor: identifier \""
+                << identifier << "\" is a real-time transform" << endl;
 
         RealTimePluginFactory *factory = 
             RealTimePluginFactory::instanceFor(pluginId);
@@ -814,8 +820,8 @@
         }
 
     } else {
-        cerr << "TransformFactory: ERROR: transform id \""
-             << identifier << "\" is of unknown type" << endl;
+        SVDEBUG << "TransformFactory: ERROR: transform id \""
+                << identifier << "\" is of unknown type" << endl;
     }
 
     return plugin;
@@ -884,6 +890,9 @@
     Transform transform;
     transform.setIdentifier(identifier);
 
+    SVDEBUG << "TransformFactory::getTransformInputDomain: identifier \""
+            << identifier << "\"" << endl;
+    
     if (transform.getType() != Transform::FeatureExtraction) {
         return Vamp::Plugin::TimeDomain;
     }
@@ -1069,12 +1078,15 @@
 {
     QString xml;
 
+    SVDEBUG << "TransformFactory::getPluginConfigurationXml: identifier \""
+            << t.getIdentifier() << "\"" << endl;
+
     Vamp::PluginBase *plugin = instantiateDefaultPluginFor
         (t.getIdentifier(), 0);
     if (!plugin) {
-        cerr << "TransformFactory::getPluginConfigurationXml: "
-                  << "Unable to instantiate plugin for transform \""
-                  << t.getIdentifier() << "\"" << endl;
+        SVDEBUG << "TransformFactory::getPluginConfigurationXml: "
+                << "Unable to instantiate plugin for transform \""
+                << t.getIdentifier() << "\"" << endl;
         return xml;
     }
 
@@ -1091,12 +1103,15 @@
 TransformFactory::setParametersFromPluginConfigurationXml(Transform &t,
                                                           QString xml)
 {
+    SVDEBUG << "TransformFactory::setParametersFromPluginConfigurationXml: identifier \""
+            << t.getIdentifier() << "\"" << endl;
+
     Vamp::PluginBase *plugin = instantiateDefaultPluginFor
         (t.getIdentifier(), 0);
     if (!plugin) {
-        cerr << "TransformFactory::setParametersFromPluginConfigurationXml: "
-                  << "Unable to instantiate plugin for transform \""
-                  << t.getIdentifier() << "\"" << endl;
+        SVDEBUG << "TransformFactory::setParametersFromPluginConfigurationXml: "
+                << "Unable to instantiate plugin for transform \""
+                << t.getIdentifier() << "\"" << endl;
         return;
     }
 
@@ -1150,14 +1165,14 @@
     if (!m_uninstalledTransformsMutex.tryLock()) {
         // uninstalled transforms are being populated; this may take some time,
         // and they aren't critical, but we will speed them up if necessary
-        cerr << "TransformFactory::search: Uninstalled transforms mutex is held, skipping" << endl;
+        SVDEBUG << "TransformFactory::search: Uninstalled transforms mutex is held, skipping" << endl;
         m_populatingSlowly = false;
         return results;
     }
 
     if (!m_uninstalledTransformsPopulated) {
-        cerr << "WARNING: TransformFactory::search: Uninstalled transforms are not populated yet" << endl
-                  << "and are not being populated either -- was the thread not started correctly?" << endl;
+        SVDEBUG << "WARNING: TransformFactory::search: Uninstalled transforms are not populated yet" << endl
+                << "and are not being populated either -- was the thread not started correctly?" << endl;
         m_uninstalledTransformsMutex.unlock();
         return results;
     }