From 13e323cdd2ec0737be3a4a1737b3bda9718fa093 Mon Sep 17 00:00:00 2001
From: Jakob Ketterl <jakob.ketterl@gmx.de>
Date: Sat, 10 Dec 2022 19:50:26 +0100
Subject: [PATCH] show sdr device log messages in the web configuration

---
 CHANGELOG.md                       |  1 +
 debian/changelog                   |  2 ++
 htdocs/css/admin.css               |  4 +++
 htdocs/lib/settings/LogMessages.js |  5 +++
 htdocs/settings.js                 |  1 +
 owrx/controllers/assets.py         |  1 +
 owrx/controllers/settings/sdr.py   | 16 +++++++++
 owrx/log/__init__.py               | 52 ++++++++++++++++++++++++++++++
 owrx/source/__init__.py            | 47 ++++++++++++++++++++-------
 owrx/source/connector.py           |  8 ++---
 owrx/source/direct.py              |  6 +---
 owrx/source/fifi_sdr.py            | 16 ++++++---
 owrx/source/resampler.py           |  8 ++---
 13 files changed, 133 insertions(+), 34 deletions(-)
 create mode 100644 htdocs/lib/settings/LogMessages.js
 create mode 100644 owrx/log/__init__.py

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 745fb3b..735d3b9 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -1,4 +1,5 @@
 **unreleased**
+- SDR device log messages are now available in the web configuration to simplify troubleshooting
 
 **1.2.1**
 - FifiSDR support fixed (pipeline formats now line up correctly)
diff --git a/debian/changelog b/debian/changelog
index 92ffe46..6a9bd9d 100644
--- a/debian/changelog
+++ b/debian/changelog
@@ -1,4 +1,6 @@
 openwebrx (1.3.0) UNRELEASED; urgency=low
+  * SDR device log messages are now available in the web configuration to
+    simplify troubleshooting
 
  -- Jakob Ketterl <jakob.ketterl@gmx.de>  Fri, 30 Sep 2022 16:47:00 +0000
 
diff --git a/htdocs/css/admin.css b/htdocs/css/admin.css
index b956e9e..742fe32 100644
--- a/htdocs/css/admin.css
+++ b/htdocs/css/admin.css
@@ -159,4 +159,8 @@ h1 {
 
 .imageupload.is-invalid ~ .invalid-feedback {
     display: block;
+}
+
+.device-log-messages {
+    max-height: 500px;
 }
\ No newline at end of file
diff --git a/htdocs/lib/settings/LogMessages.js b/htdocs/lib/settings/LogMessages.js
new file mode 100644
index 0000000..ea2683e
--- /dev/null
+++ b/htdocs/lib/settings/LogMessages.js
@@ -0,0 +1,5 @@
+$.fn.logMessages = function() {
+    $.each(this, function(){
+        $(this).scrollTop(this.scrollHeight);
+    });
+};
\ No newline at end of file
diff --git a/htdocs/settings.js b/htdocs/settings.js
index 3a071b5..b1bc736 100644
--- a/htdocs/settings.js
+++ b/htdocs/settings.js
@@ -8,4 +8,5 @@ $(function(){
     $('.optional-section').optionalSection();
     $('#scheduler').schedulerInput();
     $('.exponential-input').exponentialInput();
+    $('.device-log-messages').logMessages();
 });
\ No newline at end of file
diff --git a/owrx/controllers/assets.py b/owrx/controllers/assets.py
index ca3e7f9..2ae1ab1 100644
--- a/owrx/controllers/assets.py
+++ b/owrx/controllers/assets.py
@@ -158,6 +158,7 @@ class CompiledAssetsController(GzipMixin, ModificationAwareController):
             "lib/settings/OptionalSection.js",
             "lib/settings/SchedulerInput.js",
             "lib/settings/ExponentialInput.js",
+            "lib/settings/LogMessages.js",
             "settings.js",
         ],
     }
diff --git a/owrx/controllers/settings/sdr.py b/owrx/controllers/settings/sdr.py
index 40c6185..1f17b46 100644
--- a/owrx/controllers/settings/sdr.py
+++ b/owrx/controllers/settings/sdr.py
@@ -12,6 +12,7 @@ from owrx.form.input import TextInput, DropdownInput, Option
 from owrx.form.input.validator import RequiredValidator
 from owrx.property import PropertyLayer
 from owrx.breadcrumb import BreadcrumbMixin, Breadcrumb, BreadcrumbItem
+from owrx.log import HistoryHandler
 from abc import ABCMeta, abstractmethod
 from uuid import uuid4
 
@@ -279,6 +280,21 @@ class SdrDeviceController(SdrFormControllerWithModal):
         config.store()
         return self.send_redirect("{}settings/sdr".format(self.get_document_root()))
 
+    def render_sections(self):
+        handler = HistoryHandler.getHandler("owrx.source.{id}".format(id=self.device_id))
+        return """
+            {sections}
+            <div class="card mt-2">
+                <div class="card-header">Recent device log messages</div>
+                <div class="card-body">
+                    <pre class="card-text device-log-messages">{messages}</pre>
+                </div>
+            </div>
+        """.format(
+            sections=super().render_sections(),
+            messages=handler.getFormattedHistory(),
+        )
+
 
 class NewSdrDeviceController(SettingsFormController):
     def __init__(self, handler, request, options):
diff --git a/owrx/log/__init__.py b/owrx/log/__init__.py
new file mode 100644
index 0000000..745a079
--- /dev/null
+++ b/owrx/log/__init__.py
@@ -0,0 +1,52 @@
+import threading
+import os
+from logging import Logger, Handler, LogRecord, Formatter
+
+
+class LogPipe(threading.Thread):
+
+    def __init__(self, level: int, logger: Logger, prefix: str = ""):
+        threading.Thread.__init__(self)
+        self.daemon = False
+        self.level = level
+        self.logger = logger
+        self.prefix = prefix
+        self.fdRead, self.fdWrite = os.pipe()
+        self.pipeReader = os.fdopen(self.fdRead)
+        self.start()
+
+    def fileno(self):
+        return self.fdWrite
+
+    def run(self):
+        for line in iter(self.pipeReader.readline, ''):
+            self.logger.log(self.level, "{}: {}".format(self.prefix, line.strip('\n')))
+
+        self.pipeReader.close()
+
+    def close(self):
+        os.close(self.fdWrite)
+
+
+class HistoryHandler(Handler):
+    handlers = {}
+
+    @staticmethod
+    def getHandler(name: str):
+        if name not in HistoryHandler.handlers:
+            HistoryHandler.handlers[name] = HistoryHandler()
+        return HistoryHandler.handlers[name]
+
+    def __init__(self, maxRecords: int = 200):
+        super().__init__()
+        self.history = []
+        self.maxRecords = maxRecords
+        self.setFormatter(Formatter(fmt="%(asctime)s - %(name)s - %(levelname)s - %(message)s"))
+
+    def emit(self, record: LogRecord) -> None:
+        self.history.append(record)
+        # truncate
+        self.history = self.history[-self.maxRecords:]
+
+    def getFormattedHistory(self) -> str:
+        return "\n".join([self.format(r) for r in self.history])
diff --git a/owrx/source/__init__.py b/owrx/source/__init__.py
index 618d773..9d4c7bb 100644
--- a/owrx/source/__init__.py
+++ b/owrx/source/__init__.py
@@ -18,6 +18,7 @@ from owrx.form.input.device import GainInput, SchedulerInput, WaterfallLevelsInp
 from owrx.form.input.validator import RequiredValidator
 from owrx.form.section import OptionalSection
 from owrx.feature import FeatureDetector
+from owrx.log import LogPipe, HistoryHandler
 from typing import List
 from enum import Enum
 
@@ -114,6 +115,10 @@ class SdrSource(ABC):
         self.commandMapper = None
         self.tcpSource = None
         self.buffer = None
+        self.logger = logger.getChild(id) if id is not None else logger
+        self.logger.addHandler(HistoryHandler.getHandler(self.logger.name))
+        self.stdoutPipe = None
+        self.stderrPipe = None
 
         self.props = PropertyStack()
 
@@ -185,17 +190,17 @@ class SdrSource(ABC):
         for id, p in self.props["profiles"].items():
             props.replaceLayer(0, p)
             if "center_freq" not in props:
-                logger.warning('Profile "%s" does not specify a center_freq', id)
+                self.logger.warning('Profile "%s" does not specify a center_freq', id)
                 continue
             if "samp_rate" not in props:
-                logger.warning('Profile "%s" does not specify a samp_rate', id)
+                self.logger.warning('Profile "%s" does not specify a samp_rate', id)
                 continue
             if "start_freq" in props:
                 start_freq = props["start_freq"]
                 srh = props["samp_rate"] / 2
                 center_freq = props["center_freq"]
                 if start_freq < center_freq - srh or start_freq > center_freq + srh:
-                    logger.warning('start_freq for profile "%s" is out of range', id)
+                    self.logger.warning('start_freq for profile "%s" is out of range', id)
 
     def isAlwaysOn(self):
         return "always-on" in self.props and self.props["always-on"]
@@ -225,11 +230,11 @@ class SdrSource(ABC):
         return [self.getCommandMapper().map(self.getCommandValues())]
 
     def activateProfile(self, profile_id):
-        logger.debug("activating profile {0} for {1}".format(profile_id, self.getId()))
+        self.logger.debug("activating profile {0} for {1}".format(profile_id, self.getId()))
         try:
             self.profileCarousel.switch(profile_id)
         except KeyError:
-            logger.warning("invalid profile %s for sdr %s. ignoring", profile_id, self.getId())
+            self.logger.warning("invalid profile %s for sdr %s. ignoring", profile_id, self.getId())
 
     def getId(self):
         return self.id
@@ -283,23 +288,37 @@ class SdrSource(ABC):
             try:
                 self.preStart()
             except Exception:
-                logger.exception("Exception during preStart()")
+                self.logger.exception("Exception during preStart()")
 
             cmd = self.getCommand()
             cmd = [c for c in cmd if c is not None]
 
+            self.stdoutPipe = LogPipe(logging.INFO, self.logger, "STDOUT")
+            self.stderrPipe = LogPipe(logging.WARNING, self.logger, "STDERR")
+
             # don't use shell mode for commands without piping
             if len(cmd) > 1:
                 # multiple commands with pipes
                 cmd = "|".join(cmd)
-                self.process = subprocess.Popen(cmd, shell=True, start_new_session=True)
+                self.process = subprocess.Popen(
+                    cmd,
+                    shell=True,
+                    start_new_session=True,
+                    stdout=self.stdoutPipe,
+                    stderr=self.stderrPipe
+                )
             else:
                 # single command
                 cmd = cmd[0]
                 # start_new_session can go as soon as there's no piped commands left
                 # the os.killpg call must be replaced with something more reasonable at the same time
-                self.process = subprocess.Popen(shlex.split(cmd), start_new_session=True)
-            logger.info("Started sdr source: " + cmd)
+                self.process = subprocess.Popen(
+                    shlex.split(cmd),
+                    start_new_session=True,
+                    stdout=self.stdoutPipe,
+                    stderr=self.stderrPipe
+                )
+            self.logger.info("Started sdr source: " + cmd)
 
             available = False
             failed = False
@@ -307,9 +326,13 @@ class SdrSource(ABC):
             def wait_for_process_to_end():
                 nonlocal failed
                 rc = self.process.wait()
-                logger.debug("shut down with RC={0}".format(rc))
+                self.logger.debug("shut down with RC={0}".format(rc))
                 self.process = None
                 self.monitor = None
+                self.stdoutPipe.close()
+                self.stdoutPipe = None
+                self.stderrPipe.close()
+                self.stderrPipe = None
                 if self.getState() is SdrSourceState.RUNNING:
                     self.fail()
                 else:
@@ -340,7 +363,7 @@ class SdrSource(ABC):
             try:
                 self.postStart()
             except Exception:
-                logger.exception("Exception during postStart()")
+                self.logger.exception("Exception during postStart()")
                 failed = True
 
         if failed:
@@ -374,7 +397,7 @@ class SdrSource(ABC):
                         self.monitor.join(10)
                         # if the monitor is still running, the process still hasn't ended, so kill it
                     if self.monitor:
-                        logger.warning("source has not shut down normally within 10 seconds, sending SIGKILL")
+                        self.logger.warning("source has not shut down normally within 10 seconds, sending SIGKILL")
                         os.killpg(os.getpgid(self.process.pid), signal.SIGKILL)
                 except ProcessLookupError:
                     # been killed by something else, ignore
diff --git a/owrx/source/connector.py b/owrx/source/connector.py
index 58c535d..7175d9b 100644
--- a/owrx/source/connector.py
+++ b/owrx/source/connector.py
@@ -6,10 +6,6 @@ from owrx.command import Flag, Option
 from typing import List
 from owrx.form.input import Input, NumberInput, CheckboxInput
 
-import logging
-
-logger = logging.getLogger(__name__)
-
 
 class ConnectorSource(SdrSource):
     def __init__(self, id, props):
@@ -40,7 +36,7 @@ class ConnectorSource(SdrSource):
         for prop, value in changes.items():
             if value is PropertyDeleted:
                 value = None
-            logger.debug("sending property change over control socket: {0} changed to {1}".format(prop, value))
+            self.logger.debug("sending property change over control socket: {0} changed to {1}".format(prop, value))
             self.controlSocket.sendall("{prop}:{value}\n".format(prop=prop, value=value).encode())
 
     def onPropertyChange(self, changes):
@@ -56,7 +52,7 @@ class ConnectorSource(SdrSource):
         self.sendControlMessage(changes)
 
     def postStart(self):
-        logger.debug("opening control socket...")
+        self.logger.debug("opening control socket...")
         self.controlSocket = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
         self.controlSocket.connect(("localhost", self.controlPort))
 
diff --git a/owrx/source/direct.py b/owrx/source/direct.py
index e8c2025..4860dd1 100644
--- a/owrx/source/direct.py
+++ b/owrx/source/direct.py
@@ -5,10 +5,6 @@ from typing import Optional
 from pycsdr.modules import Buffer
 from pycsdr.types import Format
 
-import logging
-
-logger = logging.getLogger(__name__)
-
 
 class DirectSource(SdrSource, metaclass=ABCMeta):
     def __init__(self, id, props):
@@ -16,7 +12,7 @@ class DirectSource(SdrSource, metaclass=ABCMeta):
         super().__init__(id, props)
 
     def onPropertyChange(self, changes):
-        logger.debug("restarting sdr source due to property changes: {0}".format(changes))
+        self.logger.debug("restarting sdr source due to property changes: {0}".format(changes))
         self.stop()
         self.sleepOnRestart()
         self.start()
diff --git a/owrx/source/fifi_sdr.py b/owrx/source/fifi_sdr.py
index e3999b3..24dbc45 100644
--- a/owrx/source/fifi_sdr.py
+++ b/owrx/source/fifi_sdr.py
@@ -1,16 +1,14 @@
 from owrx.command import Option
 from owrx.source.direct import DirectSource, DirectSourceDeviceDescription
+from owrx.log import LogPipe
 from subprocess import Popen
 from csdr.chain import Chain
 from pycsdr.modules import Convert, Gain
 from pycsdr.types import Format
 from typing import List
 from owrx.form.input import Input, TextInput
-
 import logging
 
-logger = logging.getLogger(__name__)
-
 
 class FifiSdrSource(DirectSource):
     def getCommandMapper(self):
@@ -29,11 +27,19 @@ class FifiSdrSource(DirectSource):
         return Chain([Convert(Format.COMPLEX_SHORT, Format.COMPLEX_FLOAT), Gain(Format.COMPLEX_FLOAT, 5.0)])
 
     def sendRockProgFrequency(self, frequency):
-        process = Popen(["rockprog", "--vco", "-w", "--freq={}".format(frequency / 1e6)])
+        stdoutPipe = LogPipe(logging.DEBUG, self.logger, "STDOUT")
+        stderrPipe = LogPipe(logging.DEBUG, self.logger, "STDERR")
+        process = Popen(
+            ["rockprog", "--vco", "-w", "--freq={}".format(frequency / 1e6)],
+            stdout=stdoutPipe,
+            stderr=stderrPipe
+        )
         process.communicate()
         rc = process.wait()
         if rc != 0:
-            logger.warning("rockprog failed to set frequency; rc=%i", rc)
+            self.logger.warning("rockprog failed to set frequency; rc=%i", rc)
+        stdoutPipe.close()
+        stderrPipe.close()
 
     def preStart(self):
         values = self.getCommandValues()
diff --git a/owrx/source/resampler.py b/owrx/source/resampler.py
index 7d45c2e..fb1c2d0 100644
--- a/owrx/source/resampler.py
+++ b/owrx/source/resampler.py
@@ -3,14 +3,10 @@ from pycsdr.modules import Buffer, FirDecimate, Shift
 from pycsdr.types import Format
 from csdr.chain import Chain
 
-import logging
-
-logger = logging.getLogger(__name__)
-
 
 class Resampler(SdrSource):
     def onPropertyChange(self, changes):
-        logger.warning("Resampler is unable to handle property changes: {0}".format(changes))
+        self.logger.warning("Resampler is unable to handle property changes: {0}".format(changes))
 
     def __init__(self, props, sdr):
         sdrProps = sdr.getProps()
@@ -41,7 +37,7 @@ class Resampler(SdrSource):
         super().stop()
 
     def activateProfile(self, profile_id=None):
-        logger.warning("Resampler does not support setting profiles")
+        self.logger.warning("Resampler does not support setting profiles")
         pass
 
     def validateProfiles(self):