Startup and communication bugfixes

- reduce amount of mode switched when starting and loading setups
- improve logging for errors during HIL tests
- fix small USB communication bugs

Author: jankae

Software/Integrationtests/Integrationtest.py

@@ -1,4 +1,5 @@
 import unittest
+import glob, os
 
 testmodules = [
     'tests.TestUpdate',     # Must go first because it updates the connected VNA to the firwmare which should be tested
@@ -16,6 +17,12 @@
 
 suite = unittest.TestSuite()
 
+# Clean up potential error logs from previous test runs
+for f in glob.glob("errorlog_*"):
+    os.remove(f)
+for f in glob.glob("packetlog_*"):
+    os.remove(f)
+
 for t in testmodules:
     try:
         # If the module defines a suite() function, call it to get the suite.

Software/Integrationtests/errorlog_20250106173311.txt

@@ -0,0 +1,22 @@
+     0.027: [debug] Application start
+     0.045: [info] Listening on port 19544
+     0.060: [debug] Activating mode "Vector Network Analyzer"
+     0.068: [debug] Updated device list, found 1
+     0.068: [debug] Trying to connect to "208A367A4B42"
+     0.068: [debug] Attempting to connect to device...
+     0.075: [info] USB connection established
+     0.075: [debug] Receive thread started
+     0.075: [debug] Transmission started (packet type 15 ), queue at  1
+     0.078: [info] Connected to "208A367A4B42"
+     0.079: [debug] Transmission started (packet type 26 ), queue at  1
+     0.082: [debug] No default calibration file set for this device
+     0.082: [debug] Transmission started (packet type 11 ), queue at  1
+     0.187: [debug] Transmission started (packet type 2 ), queue at  1
+     0.533: [debug] Attempting to open calibration from file "LIBRECAL.cal"
+     0.533: [debug] Associated calibration kit expected in "LIBRECAL.calkit"
+     0.533: [debug] Opening calkit to file "LIBRECAL.calkit"
+     0.533: [debug] Parsing of calibration kit failed while opening calibration file:  Unable to open file  (ignore for calibration format >= 3)
+     0.899: [debug] Transmission started (packet type 2 ), queue at  1
+     1.007: [debug] Deactivated mode "Vector Network Analyzer"
+     1.007: [debug] Transmission started (packet type 20 ), queue at  1
+     1.050: [debug] Disconnected, receive thread exiting

Software/Integrationtests/packetlog_20250106173310.vnalog

@@ -4,43 +4,72 @@
 import subprocess
 import time
 import select
+import os
 from signal import SIGINT
 
 class TestBase(unittest.TestCase):
     def setUp(self):
-        self.gui = subprocess.Popen([defs.GUI_PATH, '-p', '19544', '--reset-preferences', '--no-gui', '-platform', 'offscreen'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+        f = open("log.txt", "w")
+        self.gui = subprocess.Popen([defs.GUI_PATH, '-p', '19544', '--reset-preferences', '--no-gui', '-platform', 'offscreen'], stdout=f, stderr=subprocess.STDOUT)
 
         # wait for the SCPI server to become available
         timeout = time.time() + 3;
-        poll_obj = select.poll()
-        poll_obj.register(self.gui.stdout, select.POLLIN)
+        fread = open("log.txt", "r")
         while True:
-            poll_result = poll_obj.poll(0)
-            if poll_result:
-                line = self.gui.stdout.readline().decode().strip()
-                if "Listening on port 19544" in line:
-                    break
+            text = fread.read()
+            if text and "Listening on port 19544" in text:
+                break
             if time.time() >= timeout:
                 self.tearDown()
                 raise AssertionError("Timed out waiting for SCPI server")
 
         self.vna = libreVNA('localhost', 19544, timeout=4)
         try:
-            self.vna.cmd("*CLS;:DEV:CONN")
+            self.vna.cmd("*CLS")
         except Exception as e:
             self.tearDown()
             raise e
         if self.vna.query(":DEV:CONN?") == "Not connected":
             self.tearDown()
             raise AssertionError("Not connected")
-               
+
+
     def tearDown(self):
+        if hasattr(self._outcome, 'errors'):
+            # Python 3.4 - 3.10  (These two methods have no side effects)
+            result = self.defaultTestResult()
+            self._feedErrorsToResult(result, self._outcome.errors)
+        else:
+            # Python 3.11+
+            result = self._outcome.result
+        ok = all(test != self for test, text in result.errors + result.failures)
+
+        if not ok:
+            try:
+                # Try to grab the packet log and save it
+                packetlog = self.vna.query(":DEV:PACKETLOG?", timeout=5)
+                f = open("packetlog_"+time.strftime("%Y%m%d%H%M%S.vnalog"), "w")
+                f.write(packetlog)
+                f.close()
+            except:
+                pass
+
         # make sure the GUI did not crash during the test
-        self.assertEqual(self.gui.poll(), None)
+        crashed = self.gui.poll() is not None
         self.gui.send_signal(SIGINT)
         try:
             self.gui.wait(timeout = 3)
         except subprocess.TimeoutExpired:
             self.gui.kill()
 
+
+        if ok and not crashed:
+            # remove log file
+            os.remove("log.txt")
+        else:
+            os.rename("log.txt", "errorlog_"+time.strftime("%Y%m%d%H%M%S.txt"))
+
+        if(crashed):
+            raise Exception("GUI crashed")
+
 

Software/Integrationtests/tests/TestBase.py

@@ -29,7 +29,7 @@ CompoundDriver::CompoundDriver()
         p.load(d->driverSpecificSettings());
     }
 
-    specificSettings.push_back(Savable::SettingDescription(&compoundJSONString, "compoundDriver.compoundDeviceJSON", ""));
+    specificSettings.push_back(Savable::SettingDescription(&compoundJSONString, "compoundDriver.compoundDeviceJSON", "{}"));
     specificSettings.push_back(Savable::SettingDescription(&captureRawReceiverValues, "compoundDriver.captureRawReceiverValues", false));
     specificSettings.push_back(Savable::SettingDescription(&preservePhase, "compoundDriver.preservePhase", false));
 }
@@ -488,6 +488,10 @@ void CompoundDriver::parseCompoundJSON()
 {
     try {
         configuredDevices.clear();
+        if(compoundJSONString.isEmpty()) {
+            // empty string will fail JSON parsing. Abort now instead of running into the exception
+            return;
+        }
         nlohmann::json jc = nlohmann::json::parse(compoundJSONString.toStdString());
         for(auto j : jc) {
             auto cd = new CompoundDevice();

Software/PC_Application/LibreVNA-GUI/Device/LibreVNA/Compound/compounddriver.cpp

@@ -251,6 +251,11 @@ LibreVNADriver::LibreVNADriver()
         }
         return SCPI::getResultName(SCPI::Result::Empty);
     }, nullptr));
+
+    specificSCPIcommands.push_back(new SCPICommand("DEVice:PACKETLOG", nullptr, [=](QStringList) -> QString {
+        auto &log = DevicePacketLog::getInstance();
+        return QString::fromStdString(log.toJSON().dump());
+    }));
 }
 
 std::set<DeviceDriver::Flag> LibreVNADriver::getFlags()
@@ -407,6 +412,7 @@ QStringList LibreVNADriver::availableVNAMeasurements()
 bool LibreVNADriver::setVNA(const DeviceDriver::VNASettings &s, std::function<void (bool)> cb)
 {
     if(!supports(Feature::VNA)) {
+        qDebug() << "VNA does not support features \"VNA\" (has the DeviceInfo been received?)";
         return false;
     }
     if(s.excitedPorts.size() == 0) {

Software/PC_Application/LibreVNA-GUI/Device/LibreVNA/librevnadriver.cpp

@@ -4,6 +4,7 @@
 #include "devicepacketlog.h"
 
 #include <QTimer>
+#include <QThread>
 
 using namespace std;
 
@@ -166,9 +167,9 @@ void LibreVNAUSBDriver::ReceivedData()
     uint16_t handled_len;
 //    qDebug() << "Received data";
     do {
-//        qDebug() << "Decoding" << dataBuffer->getReceived() << "Bytes";
+        // qDebug() << "Decoding" << dataBuffer->getReceived() << "Bytes";
         handled_len = Protocol::DecodeBuffer(dataBuffer->getBuffer(), dataBuffer->getReceived(), &packet);
-//        qDebug() << "Handled" << handled_len << "Bytes, type:" << (int) packet.type;
+        // qDebug() << "Handled" << handled_len << "Bytes, type:" << (int) packet.type;
         if(handled_len > 0) {
             auto &log = DevicePacketLog::getInstance();
             if(packet.type != Protocol::PacketType::None) {
@@ -185,6 +186,8 @@ void LibreVNAUSBDriver::ReceivedData()
         case Protocol::PacketType::Nack:
             emit receivedAnswer(TransmissionResult::Nack);
             break;
+        case Protocol::PacketType::None:
+            break;
         default:
             // pass on to LibreVNADriver class
             emit receivedPacket(packet);
@@ -220,12 +223,12 @@ void LibreVNAUSBDriver::transmissionFinished(LibreVNADriver::TransmissionResult
 {
     lock_guard<mutex> lock(transmissionMutex);
     // remove transmitted packet
-//    qDebug() << "Transmission finsished (" << result << "), queue at " << transmissionQueue.size() << " Outstanding ACKs:"<<outstandingAckCount;
     if(transmissionQueue.empty()) {
         qWarning() << "transmissionFinished with empty transmission queue, stray Ack? Result:" << result;
         return;
     }
     auto t = transmissionQueue.dequeue();
+    // qDebug() << "Transmission finsished (packet type" << (int) t.packet.type <<",result" << result << "), queue at " << transmissionQueue.size();
     if(result == TransmissionResult::Timeout) {
         qWarning() << "transmissionFinished with timeout, packettype:" << (int) t.packet.type << "Device:" << serial;
     }
@@ -374,6 +377,6 @@ bool LibreVNAUSBDriver::startNextTransmission()
         return false;
     }
     transmissionTimer.start(t.timeout);
-//    qDebug() << "Transmission started, queue at " << transmissionQueue.size();
+    qDebug() << "Transmission started (packet type" << (int) t.packet.type << "), queue at " << transmissionQueue.size();
     return true;
 }

Software/PC_Application/LibreVNA-GUI/Device/LibreVNA/librevnausbdriver.cpp

@@ -340,10 +340,10 @@ SpectrumAnalyzer::SpectrumAnalyzer(AppWindow *window, QString name)
 
 void SpectrumAnalyzer::deactivate()
 {
-    setOperationPending(false);
     StoreSweepSettings();
     configurationTimer.stop();
     Mode::deactivate();
+    setOperationPending(false);
 }
 
 void SpectrumAnalyzer::initializeDevice()
@@ -588,7 +588,11 @@ void SpectrumAnalyzer::NewDatapoint(DeviceDriver::SAMeasurement m)
 
 void SpectrumAnalyzer::SettingsChanged()
 {
-    if(window->getDevice()) {
+    if(!running) {
+        // not running, no need for any communication
+        return;
+    }
+    if(isActive && window->getDevice()) {
         setOperationPending(true);
     }
     configurationTimer.start(100);
@@ -695,10 +699,15 @@ void SpectrumAnalyzer::SetSingleSweep(bool single)
 {
     if(singleSweep != single) {
         singleSweep = single;
+        if(single) {
+            Run();
+        }
         emit singleSweepChanged(single);
-    }
-    if(single) {
-        Run();
+    } else {
+        // if already set to single, a second single command triggers a new sweep
+        if(single && !running) {
+            Run();
+        }
     }
 }
 
@@ -734,7 +743,9 @@ void SpectrumAnalyzer::SetAveraging(unsigned int averages)
     average.setAverages(averages);
     emit averagingChanged(averages);
     UpdateAverageCount();
-    setOperationPending(!average.settled());
+    if(isActive && window->getDevice()) {
+        setOperationPending(!average.settled());
+    }
 }
 
 void SpectrumAnalyzer::SetTGEnabled(bool enabled)
@@ -871,6 +882,7 @@ void SpectrumAnalyzer::Stop()
 {
     running = false;
     ConfigureDevice();
+    setOperationPending(false);
 }
 
 void SpectrumAnalyzer::ConfigureDevice()
@@ -920,9 +932,6 @@ void SpectrumAnalyzer::ConfigureDevice()
 
 void SpectrumAnalyzer::ResetLiveTraces()
 {
-    if(window->getDevice()) {
-        setOperationPending(true);
-    }
     average.reset(DeviceDriver::SApoints());
     traceModel.clearLiveData();
     UpdateAverageCount();

Software/PC_Application/LibreVNA-GUI/SpectrumAnalyzer/spectrumanalyzer.cpp

@@ -745,10 +745,10 @@ QString VNA::getCalToolTip()
 
 void VNA::deactivate()
 {
-    setOperationPending(false);
     StoreSweepSettings();
     configurationTimer.stop();
     Mode::deactivate();
+    setOperationPending(false);
 }
 
 static void SetComboBoxItemEnabled(QComboBox * comboBox, int index, bool enabled)
@@ -939,9 +939,8 @@ void VNA::NewDatapoint(DeviceDriver::VNAMeasurement m)
     }
 
     // Calculate sweep time
-    if(m.pointNum == 0) {
+    if(m.pointNum == 0 && lastPoint > 0) {
         // new sweep started
-        static auto lastStart = QDateTime::currentDateTimeUtc();
         auto now = QDateTime::currentDateTimeUtc();
         auto sweepTime = lastStart.msecsTo(now);
         lastStart = now;
@@ -1042,7 +1041,6 @@ void VNA::NewDatapoint(DeviceDriver::VNAMeasurement m)
         markerModel->updateMarkers();
     }
 
-    static unsigned int lastPoint = 0;
     if(m_avg.pointNum > 0 && m_avg.pointNum != lastPoint + 1) {
         qWarning() << "Got point" << m_avg.pointNum << "but last received point was" << lastPoint << "("<<(m_avg.pointNum-lastPoint-1)<<"missed points)";
     }
@@ -1065,7 +1063,11 @@ void VNA::UpdateAverageCount()
 
 void VNA::SettingsChanged(bool resetTraces, int delay)
 {
-    if(window->getDevice()) {
+    if(!running) {
+        // not running, no need for any communication
+        return;
+    }
+    if(isActive && window->getDevice()) {
         setOperationPending(true);
     }
     configurationTimer.start(delay);
@@ -1317,7 +1319,9 @@ void VNA::SetAveraging(unsigned int averages)
     average.setAverages(averages);
     emit averagingChanged(averages);
     UpdateAverageCount();
-    setOperationPending(!average.settled());
+    if(isActive && window->getDevice()) {
+        setOperationPending(!average.settled());
+    }
 }
 
 void VNA::ExcitationRequired()
@@ -1880,10 +1884,15 @@ void VNA::SetSingleSweep(bool single)
 {
     if(singleSweep != single) {
         singleSweep = single;
+        if(single) {
+            Run();
+        }
         emit singleSweepChanged(single);
-    }
-    if(single) {
-        Run();
+    } else {
+        // if already set to single, a second single command triggers a new sweep
+        if(single && !running) {
+            Run();
+        }
     }
 }
 
@@ -1897,6 +1906,7 @@ void VNA::Stop()
 {
     running = false;
     ConfigureDevice(false);
+    setOperationPending(false);
 }
 
 void VNA::ConfigureDevice(bool resetTraces, std::function<void(bool)> cb)
@@ -1976,6 +1986,8 @@ void VNA::ConfigureDevice(bool resetTraces, std::function<void(bool)> cb)
                     cb(res);
                 }
                 changingSettings = false;
+                lastStart = QDateTime::currentDateTimeUtc();
+                lastPoint = -1;
             });
             emit sweepStarted();
         } else {
@@ -2004,7 +2016,7 @@ void VNA::ResetLiveTraces()
     traceModel.clearLiveData();
     UpdateAverageCount();
     UpdateCalWidget();
-    if(window->getDevice()) {
+    if(isActive && window->getDevice()) {
         setOperationPending(true);
     }
 }