Merge pull request #12 from OpenAstroTech/bugfix/js/11-avrdude-stderr-fix

Redirect avrdude output to file, watch the file and output to log

Author: julianneswinoga

OATFWGUI/external_processes.py

@@ -1,9 +1,9 @@
 import sys
 import logging
-from typing import List, Dict, Optional
+from typing import List, Dict, Optional, Callable
 from pathlib import Path
 
-from PySide6.QtCore import Slot, QProcess, QStandardPaths
+from PySide6.QtCore import Slot, QProcess, QStandardPaths, QProcessEnvironment
 
 log = logging.getLogger('')
 
@@ -19,11 +19,19 @@ def __init__(self, proc_name, base_args):
 
         self.qproc: Optional[QProcess] = None
 
-    def start(self, extra_args: List[str], finish_signal: Optional):
+    def start(self, extra_args: List[str], finish_signal: Optional[Callable],
+              env_vars: Optional[Dict[str, str]] = None):
         self.qproc = QProcess()
         self.qproc.setProgram(self.proc_name)
         self.qproc.setArguments(self.base_args)
 
+        proc_env = QProcessEnvironment.systemEnvironment()
+        if env_vars:
+            for k, v in env_vars.items():
+                proc_env.insert(k, v)
+        log.debug(f'Process environment:{proc_env.toStringList()}')
+        self.qproc.setProcessEnvironment(proc_env)
+
         # signals
         self.qproc.readyReadStandardOutput.connect(self.handle_stdout)
         self.qproc.readyReadStandardError.connect(self.handle_stderr)
@@ -33,7 +41,7 @@ def start(self, extra_args: List[str], finish_signal: Optional):
         self.qproc.setArguments(all_args)
         if finish_signal is not None:
             self.qproc.finished.connect(finish_signal)
-        log.info(f'Starting {self.proc_name} with args: {all_args}')
+        log.info(f'Starting {self.proc_name} with args: {all_args} and env {env_vars}')
         self.qproc.start()
         # Not sure why, but the process doesn't start without these
         proc_started = self.qproc.waitForStarted(10 * 1000)

OATFWGUI/gui_logic.py

@@ -11,7 +11,7 @@
 
 import requests
 
-from log_utils import LogObject
+from log_utils import LogObject, LoggedExternalFile
 from qt_extensions import Worker, QBusyIndicatorGoodBad, BusyIndicatorState
 from external_processes import external_processes, get_install_dir
 from gui_state import LogicState, PioEnv, FWVersion
@@ -95,6 +95,9 @@ def __init__(self, main_app: 'MainWidget'):
         # Manually spawn a worker to refresh serial ports
         self.spawn_worker_thread(self.refresh_ports)()
 
+        # Need to create in the main thread else it doesn't work?
+        self.avr_dude_logwatch = LoggedExternalFile()
+
     def spawn_worker_thread(self, fn):
         @Slot()
         def worker_thread_slot():
@@ -298,6 +301,16 @@ def upload_fw(self):
             log.error(f"platformio already running! {external_processes['platformio']}")
             return
 
+        # Stupid fix for avrdude outputting to stderr by default
+        if self.logic_state.pio_env is not None and any(
+                avr_env_substr in self.logic_state.pio_env.lower()
+                for avr_env_substr in ['mksgenl', 'ramps']):
+            avrdude_logfile_name = self.avr_dude_logwatch.create_file(file_suffix='_avrdude_log')
+            # Note: avrdude doesn't strip the filename! So no spaces at the beginning
+            env_vars = {'PLATFORMIO_UPLOAD_FLAGS': f'-l{avrdude_logfile_name}'}
+        else:
+            env_vars = {}
+
         external_processes['platformio'].start(
             ['run',
              '--environment', self.logic_state.pio_env,
@@ -307,11 +320,13 @@ def upload_fw(self):
              '--upload-port', self.logic_state.upload_port,
              ],
             self.pio_upload_finished,
+            env_vars=env_vars,
         )
 
     @Slot()
     def pio_upload_finished(self):
         log.info(f'platformio upload finished')
+        self.avr_dude_logwatch.stop()
         exit_code = external_processes['platformio'].qproc.exitCode()
         if exit_code == 0:
             log.info('Normal exit')

OATFWGUI/log_utils.py

@@ -3,11 +3,12 @@
 import os
 import enum
 import html
+import tempfile
 from pathlib import Path
 from datetime import datetime
-from typing import Tuple
+from typing import Tuple, Optional
 
-from PySide6.QtCore import Signal, QObject
+from PySide6.QtCore import Slot, Signal, QObject, QFileSystemWatcher, QFile
 
 from external_processes import get_install_dir
 from platform_check import get_platform, PlatformEnum
@@ -75,6 +76,44 @@ def format(self, record):
         return log_str
 
 
+class LoggedExternalFile:
+    def __init__(self):
+        # Don't want to global the `log` variable here (idk if things will break)
+        self.log = logging.getLogger('')
+
+        self.file_watcher = QFileSystemWatcher()
+        self.file_watcher.fileChanged.connect(self.file_changed)
+
+        self.tempfile: Optional[tempfile.NamedTemporaryFile] = None
+
+    def create_file(self, file_suffix: str = '') -> Optional[str]:
+        self.tempfile = tempfile.NamedTemporaryFile(mode='r', suffix=f'{file_suffix}', delete=False)
+        self.log.debug(f'Logging external file {self.tempfile.name}')
+
+        watch_success = self.file_watcher.addPath(self.tempfile.name)
+        if not watch_success:
+            self.log.warning(f'Could not watch external file: {self.tempfile.name}')
+            return None
+        return self.tempfile.name
+
+    @Slot()
+    def file_changed(self, _path: str):
+        lines = self.tempfile.readlines()
+        for line in lines:
+            if 'error' in line.lower():
+                self.log.error(line)
+            else:
+                self.log.info(line)
+
+    def stop(self):
+        self.log.debug(f'Cleaning up logged external file {self.tempfile.name}')
+        self.tempfile.close()
+        self.file_watcher.removePath(self.tempfile.name)
+        remove_ok = QFile.remove(self.tempfile.name)
+        if not remove_ok:
+            self.log.warning(f'Could not remove temp file {self.tempfile.name}')
+
+
 def setup_logging(logger, qt_log_obj: LogObject):
     logger.setLevel(logging.DEBUG)
     # file handler