changeset 6:61dbb18f2369

Logging, timeouts

--- a/checker.cpp	Wed Apr 13 12:06:26 2016 +0100
+++ b/checker.cpp	Wed Apr 13 18:41:49 2016 +0100
@@ -33,10 +33,17 @@
 
 using namespace std;
 
+struct LogCallback : PluginCandidates::LogCallback {
+    virtual void log(string message) {
+        cerr << "checker: log: " << message;
+    }
+};
+
 int main(int, char **)
 {
-    KnownPlugins kp;
-
+    LogCallback cb;
+    KnownPlugins kp("./helper", &cb); //!!!
+    
     for (auto t: kp.getKnownPluginTypes()) {
 	cout << "successful libraries for plugin type \""
 	     << kp.getTagFor(t) << "\":" << endl;

--- a/helper.cpp	Wed Apr 13 12:06:26 2016 +0100
+++ b/helper.cpp	Wed Apr 13 18:41:49 2016 +0100
@@ -74,6 +74,8 @@
 #include <string>
 #include <iostream>
 
+#include <unistd.h>
+
 using namespace std;
 
 string error()
@@ -85,23 +87,17 @@
 
 string check(string soname, string descriptor)
 {
-//    cerr << "helper: trying: " << soname << endl;
-    
     void *handle = DLOPEN(soname, RTLD_NOW | RTLD_LOCAL);
     if (!handle) {
-//	cerr << "helper: failed to open" << endl;
 	return "Unable to open plugin library: " + error();
     }
 
     void *fn = DLSYM(handle, descriptor);
     if (!fn) {
-//	cerr << "helper: failed to find descriptor" << endl;
 	return "Failed to find plugin descriptor " + descriptor +
 	    " in library: " + error();
     }
 
-//    cerr << "helper: succeeded" << endl;
-    
     return "";
 }
 

--- a/knownplugins.cpp	Wed Apr 13 12:06:26 2016 +0100
+++ b/knownplugins.cpp	Wed Apr 13 18:41:49 2016 +0100
@@ -39,9 +39,12 @@
 #define PATH_SEPARATOR ':'
 #endif
 
-KnownPlugins::KnownPlugins() :
-    m_candidates("./helper") //!!!??? wot to do
+KnownPlugins::KnownPlugins(string helperExecutableName,
+                           PluginCandidates::LogCallback *cb) :
+    m_candidates(helperExecutableName)
 {
+    m_candidates.setLogCallback(cb);
+    
     m_known = {
 	{
 	    VampPlugin,

--- a/knownplugins.h	Wed Apr 13 12:06:26 2016 +0100
+++ b/knownplugins.h	Wed Apr 13 18:41:49 2016 +0100
@@ -47,7 +47,8 @@
 	DSSIPlugin
     };
 
-    KnownPlugins();
+    KnownPlugins(std::string helperExecutableName,
+                 PluginCandidates::LogCallback *cb = 0);
 
     std::vector<PluginType> getKnownPluginTypes() const {
 	return { VampPlugin, LADSPAPlugin, DSSIPlugin };

--- a/plugincandidates.cpp	Wed Apr 13 12:06:26 2016 +0100
+++ b/plugincandidates.cpp	Wed Apr 13 18:41:49 2016 +0100
@@ -35,6 +35,7 @@
 
 #include <QProcess>
 #include <QDir>
+#include <QTime>
 
 #if defined(_WIN32)
 #define PLUGIN_GLOB "*.dll"
@@ -47,10 +48,17 @@
 using namespace std;
 
 PluginCandidates::PluginCandidates(string helperExecutableName) :
-    m_helper(helperExecutableName)
+    m_helper(helperExecutableName),
+    m_logCallback(0)
 {
 }
 
+void
+PluginCandidates::setLogCallback(LogCallback *cb)
+{
+    m_logCallback = cb;
+}
+
 vector<string>
 PluginCandidates::getCandidateLibrariesFor(string tag) const
 {
@@ -65,6 +73,12 @@
     else return m_failures.at(tag);
 }
 
+void
+PluginCandidates::log(string message)
+{
+    if (m_logCallback) m_logCallback->log("PluginCandidates: " + message);
+}
+
 vector<string>
 PluginCandidates::getLibrariesInPath(vector<string> path)
 {
@@ -72,9 +86,7 @@
 
     for (string dirname: path) {
 
-//#ifdef DEBUG_PLUGIN_SCAN_AND_INSTANTIATE
-        cerr << "getLibrariesInPath: scanning directory " << dirname << endl;
-//#endif
+        log("scanning directory " + dirname + "\n");
 
         QDir dir(dirname.c_str(), PLUGIN_GLOB,
 		 QDir::Name | QDir::IgnoreCase,
@@ -111,10 +123,9 @@
 	    // with the plugin following the last one it reported
 	    // on. Add a failure entry for that one and continue with
 	    // the following ones.
-            cerr << "shortfall = " << shortfall << " (of " << remaining.size() << ")" << endl;
-	    result.push_back("FAILURE|" +
-                             *(remaining.rbegin() + shortfall - 1) +
-                             "|Plugin load check failed");
+            string failed = *(remaining.rbegin() + shortfall - 1);
+            log("helper output ended before result for plugin " + failed + "\n");
+	    result.push_back("FAILURE|" + failed + "|Plugin load check failed or timed out");
             remaining = vector<string>
                 (remaining.rbegin(), remaining.rbegin() + shortfall - 1);
 	}
@@ -128,8 +139,9 @@
 PluginCandidates::runHelper(vector<string> libraries, string descriptor)
 {
     vector<string> output;
-//    cerr << "running helper with following library list:" << endl;
-//    for (auto &lib: libraries) cerr << lib << endl;
+
+    log("running helper with following library list:\n");
+    for (auto &lib: libraries) log(lib + "\n");
 
     QProcess process;
     process.setReadChannel(QProcess::StandardOutput);
@@ -144,6 +156,10 @@
 	process.write("\n", 1);
     }
 
+    QTime t;
+    t.start();
+    int timeout = 3000; // ms
+
     int buflen = 4096;
     bool done = false;
     
@@ -155,12 +171,22 @@
             done = (output.size() == libraries.size());
         } else if (linelen < 0) {
             // error case
+            log("received error code while reading from helper\n");
             done = true;
 	} else {
             // no error, but no line read (could just be between
             // lines, or could be eof)
             done = (process.state() == QProcess::NotRunning);
-            if (!done) process.waitForReadyRead(100);
+            if (!done) {
+                if (t.elapsed() > timeout) {
+                    // this is purely an emergency measure
+                    log("timeout: helper took too long, killing it\n");
+                    process.kill();
+                    done = true;
+                } else {
+                    process.waitForReadyRead(200);
+                }
+            }
         }
     }
 
@@ -179,8 +205,11 @@
 
         QString s(r.c_str());
         QStringList bits = s.split("|");
+
+        log("read output line from helper: " + r);
+        
         if (bits.size() < 2 || bits.size() > 3) {
-            cerr << "Invalid helper output line: \"" << r << "\"" << endl;
+            log("invalid output line (wrong number of |-separated fields)\n");
             continue;
         }
 
@@ -199,8 +228,7 @@
             m_failures[tag].push_back({ library, message });
 
         } else {
-            cerr << "Unexpected status " << status
-                 << " in helper output line: \"" << r << "\"" << endl;
+            log("unexpected status \"" + status + "\" in output line\n");
         }
     }
 }

--- a/plugincandidates.h	Wed Apr 13 12:06:26 2016 +0100
+++ b/plugincandidates.h	Wed Apr 13 18:41:49 2016 +0100
@@ -46,13 +46,21 @@
 class PluginCandidates
 {
     typedef std::vector<std::string> stringlist;
-    
+
 public:
     /** Construct a PluginCandidates scanner that uses the given
      *  executable as its load check helper.
      */
     PluginCandidates(std::string helperExecutableName);
 
+    struct LogCallback {
+        virtual void log(std::string) = 0;
+    };
+    
+    /** Set a callback to be called for log output.
+     */
+    void setLogCallback(LogCallback *cb);
+
     /** Scan the libraries found in the given plugin path (i.e. list
      *  of plugin directories), checking that the given descriptor
      *  symbol can be looked up in each. Store the results
@@ -85,10 +93,12 @@
     std::string m_helper;
     std::map<std::string, stringlist> m_candidates;
     std::map<std::string, std::vector<FailureRec> > m_failures;
+    LogCallback *m_logCallback;
 
     stringlist getLibrariesInPath(stringlist path);
     stringlist runHelper(stringlist libraries, std::string descriptor);
     void recordResult(std::string tag, stringlist results);
+    void log(std::string);
 };
 
 #endif