RPI:finer tuned debug logging

Description for prep RF24 and pyrf24 on debian 11 (bullseye) 64 bit OS

tools/rpi/README.md

@@ -81,14 +81,58 @@ python3 getting_started.py # to test and see whether RF24 class can be loaded as
 If there are no error messages on the last step, then the NRF24 Wrapper has been installed successfully.
 
 
-for Debian 11 (bullseye) 64 bit operating system
+Building RF24 Wrapper for Debian 11 (bullseye) 64 bit operating system
--------------------------------------------------
+----------------------------------------------------------------------
+The description above does not work on Debian 11 (bullseye) 64 bit operating system.
+There are 2 possible sollutions to install the RF24 Wrapper.
+
+ * `1. solution:`
+```code
+sudo apt install cmake git python3-dev libboost-python-dev python3-pip python3-rpi.gpio
+
+sudo ln -s $(ls /usr/lib/$(ls /usr/lib/gcc | \
+     head -1)/libboost_python3*.so | \
+     tail -1) /usr/lib/$(ls /usr/lib/gcc | \
+     head -1)/libboost_python3.so
+
+git clone https://github.com/nRF24/RF24.git
+cd RF24
+
+rm -rf build Makefile.inc 
+./configure --driver=SPIDEV
+```
+ * edit `Makefile.inc` with your prefered editor e.g. nano or vi
+ old:
+```code
+ CPUFLAGS=-marm -march=armv6zk -mtune=arm1176jzf-s -mfpu=vfp -mfloat-abi=hard
+ CFLAGS=-marm -march=armv6zk -mtune=arm1176jzf-s -mfpu=vfp -mfloat-abi=hard -Ofast -Wall -pthread
+```
+ new:
+```code
+ CPUFLAGS=
+ CFLAGS=-Ofast -Wall -pthread
+```
+ * continue with 
+```code
+make
+sudo make install
+
+cd pyRF24
+rm -r ./build/ ./dist/ ./RF24.egg-info/ ./__pycache__/ #just to make sure there is no old stuff
+python3 -m pip install --upgrade pip
+python3 -m pip install .
+python3 -m pip list #watch for RF24 module - if its there its installed
+```
+
+
+
+ * `2. solution:`
 ```code
-[ $(lscpu | grep Architecture | awk '{print $2}') != "aarch64" ]] && echo "Not a 64 bit architecture for this step!"
+sudo apt install git python3-dev libboost-python-dev python3-pip python3-rpi.gpio
 
 git clone --recurse-submodules https://github.com/nRF24/pyRF24.git
 cd pyRF24
-python -m pip install . -v     # this step takes about 5 minutes!
+python3 -m pip install . -v     # this step takes about 5 minutes on my RPI-4 !
 ```
 
 Required python modules

tools/rpi/ahoy.service

@@ -6,11 +6,10 @@
 #   WorkingDirectory         (absolute path to your private ahoy dir)
 # To change other config parameter, please consult systemd documentation
 #
-# To activate this service, create a link, enable and start the ahoy.service
+# To activate this service, create a link with enable and start the ahoy.service
-# $ mkdir -p $HOME/.config/systemd/user 
+# $ mkdir -p $HOME/.config/systemd/user
-# $ ln -sf $(pwd)/ahoy/tools/rpi/ahoy.service -t $HOME/.config/systemd/user
+# $ systemctl --user enable $(pwd)/ahoy/tools/rpi/ahoy.service
 # $ systemctl --user status ahoy
-# $ systemctl --user enable ahoy
 # $ systemctl --user start ahoy
 # $ systemctl --user status ahoy
 #

tools/rpi/hoymiles/__init__.py

@@ -12,18 +12,26 @@ from datetime import datetime
 import logging
 import crcmod
 from .decoders import *
+from os import environ
 
 try:
   # OSI Layer 2 driver for nRF24L01 on Arduino & Raspberry Pi/Linux Devices
   # https://github.com/nRF24/RF24.git
   from RF24 import RF24, RF24_PA_MIN, RF24_PA_LOW, RF24_PA_HIGH, RF24_PA_MAX, RF24_250KBPS, RF24_CRC_DISABLED, RF24_CRC_8, RF24_CRC_16
-except ModuleNotFoundError:
+  if environ.get('TERM') is not None:
+    print('Using python Module: RF24')
+except ModuleNotFoundError as e:
+  if environ.get('TERM') is not None:
+    print(f'{e} - try to use module: RF24')
   try:
     # Repo for pyRF24 package
     # https://github.com/nRF24/pyRF24.git
     from pyrf24 import RF24, RF24_PA_MIN, RF24_PA_LOW, RF24_PA_HIGH, RF24_PA_MAX, RF24_250KBPS, RF24_CRC_DISABLED, RF24_CRC_8, RF24_CRC_16
-  except ModuleNotFoundError:
+    if environ.get('TERM') is not None:
-    print("Module for RF24 not found - exit")
+      print(f'{e} - Using python Module: pyrf24')
+  except ModuleNotFoundError as e:
+    if environ.get('TERM') is not None:
+      print(f'{e} - exit')
     exit()
 
 f_crc_m = crcmod.predefined.mkPredefinedCrcFun('modbus')
@@ -171,8 +179,19 @@ class ResponseDecoder(ResponseDecoderFactory):
         command = self.request_command
 
         if HOYMILES_DEBUG_LOGGING:
-            c_datetime = self.time_rx.strftime("%Y-%m-%d %H:%M:%S.%f")
+            if   command.upper() == '01':
-            logging.info(f'{c_datetime} model_decoder: {model}Decode{command.upper()}')
+                model_desc = "Firmware version / date"
+            elif command.upper() == '02':
+                model_desc = "Inverter generic events log"
+            elif command.upper() == '0B':
+                model_desc = "mirco-inverters status data"
+            elif command.upper() == '0C':
+                model_desc = "mirco-inverters status data"
+            elif command.upper() == '11':
+                model_desc = "Inverter generic events log"
+            elif command.upper() == '12':
+                model_desc = "Inverter major events log"
+            logging.info(f'model_decoder: {model}Decode{command.upper()} - {model_desc}')
 
         model_decoders = __import__('hoymiles.decoders')
         if hasattr(model_decoders, f'{model}Decode{command.upper()}'):

tools/rpi/hoymiles/__main__.py

@@ -174,12 +174,13 @@ def poll_inverter(inverter, dtu_ser, do_init, retries):
                     response = com.get_payload()
                     payload_ttl = 0
                 except Exception as e_all:
-                    logging.error(f'Error while retrieving data: {e_all}')
+                    if hoymiles.HOYMILES_TRANSACTION_LOGGING:
+                        logging.error(f'Error while retrieving data: {e_all}')
                     pass
 
         # Handle the response data if any
         if response:
-            if hoymiles.HOYMILES_DEBUG_LOGGING:
+            if hoymiles.HOYMILES_TRANSACTION_LOGGING:
                 c_datetime = datetime.now()
                 logging.debug(f'{c_datetime} Payload: ' + hoymiles.hexify_payload(response))
 
@@ -195,8 +196,7 @@ def poll_inverter(inverter, dtu_ser, do_init, retries):
             # get decoder object
             result = decoder.decode()
             if hoymiles.HOYMILES_DEBUG_LOGGING:
-               c_datetime = datetime.now()
+               logging.info(f'Decoded: {result.__dict__()}')
-               logging.info(f'{c_datetime} Decoded: {result.__dict__()}')
 
             # check decoder object for output
             if isinstance(result, hoymiles.decoders.StatusResponse):
@@ -282,6 +282,12 @@ def init_logging(ahoy_config):
             lvl = logging.WARNING
         elif level == 'ERROR':
             lvl = logging.ERROR
+        elif level == 'FATAL':
+            lvl = logging.FATAL
+    if hoymiles.HOYMILES_TRANSACTION_LOGGING and hoymiles.HOYMILES_DEBUG_LOGGING:
+        lvl = logging.DEBUG
+    if not hoymiles.HOYMILES_TRANSACTION_LOGGING and not hoymiles.HOYMILES_DEBUG_LOGGING:
+        lvl = logging.INFO
     logging.basicConfig(filename=fn, format='%(asctime)s %(levelname)s: %(message)s', datefmt='%Y-%m-%d %H:%M:%S', level=lvl)
 
 if __name__ == '__main__':
@@ -309,15 +315,15 @@ if __name__ == '__main__':
         logging.error(f'Failed to load config file {global_config.config_file}: {e_yaml}')
         sys.exit(1)
 
-    # read AHOY configuration file and prepare logging
-    ahoy_config = dict(cfg.get('ahoy', {}))
-    init_logging(ahoy_config)
-
     if global_config.log_transactions:
         hoymiles.HOYMILES_TRANSACTION_LOGGING=True
     if global_config.verbose:
         hoymiles.HOYMILES_DEBUG_LOGGING=True
 
+    # read AHOY configuration file and prepare logging
+    ahoy_config = dict(cfg.get('ahoy', {}))
+    init_logging(ahoy_config)
+
     # Prepare for multiple transceivers, makes them configurable
     for radio_config in ahoy_config.get('nrf', [{}]):
         hmradio = hoymiles.HoymilesNRF(**radio_config)

tools/rpi/hoymiles/decoders/__init__.py

@@ -99,6 +99,7 @@ class StatusResponse(Response):
     frequency = None
     powerfactor = None
     event_count = None
+    unpack_error = False
 
     def unpack(self, fmt, base):
         """
@@ -111,6 +112,7 @@ class StatusResponse(Response):
         """
         size = struct.calcsize(fmt)
         if (len(self.response) < base+size):
+           self.unpack_error = True
            logging.error(f'base: {base} size: {size} len: {len(self.response)} fmt: {fmt} rep: {self.response}')
            return [0]
         return struct.unpack(fmt, self.response[base:base+size])
@@ -196,7 +198,8 @@ class StatusResponse(Response):
         data['event_count'] = self.event_count
         data['time'] = self.time_rx
 
-        return data
+        if not self.unpack_error:
+            return data
 
 class UnknownResponse(Response):
     """
@@ -334,12 +337,13 @@ class EventsResponse(UnknownResponse):
 
             logging.debug(' '.join([f'{byte:02x}' for byte in chunk]) + ': ')
 
-            if (len(chunk[0:6]) == 6):
+            if (len(chunk[0:6]) < 6):
-                opcode, a_code, a_count, uptime_sec = struct.unpack('>BBHH', chunk[0:6])
-                a_text = self.alarm_codes.get(a_code, 'N/A')
-                logging.debug(f' uptime={timedelta(seconds=uptime_sec)} a_count={a_count} opcode={opcode} a_code={a_code} a_text={a_text}')
-            else:
                 logging.error(f'length of chunk must be greater or equal 6 bytes: {chunk}')
+                return
+
+            opcode, a_code, a_count, uptime_sec = struct.unpack('>BBHH', chunk[0:6])
+            a_text = self.alarm_codes.get(a_code, 'N/A')
+            logging.debug(f' uptime={timedelta(seconds=uptime_sec)} a_count={a_count} opcode={opcode} a_code={a_code} a_text={a_text}')
 
             dbg = ''
             for fmt in ['BBHHHHH']:
@@ -366,12 +370,15 @@ class HardwareInfoResponse(UnknownResponse):
     def __dict__(self):
         """ Base values, availabe in each __dict__ call """
 
+        data = super().__dict__()
         responce_info = self.response
-        if (len(responce_info) >= 16):
-            logging.info(f'HardwareInfoResponse: {struct.unpack(">HHHHHHHH", responce_info)}')
-        else:
-            logging.error(f'wrong length of HardwareInfoResponse: {responce_info}')
 
+        if (len(self.response) != 16):
+            logging.error(f'HardwareInfoResponse: data length should be 16 bytes - measured {len(self.response)} bytes')
+            logging.error(f'HardwareInfoResponse: data: {self.response}')
+            return data
+
+        logging.info(f'HardwareInfoResponse: {struct.unpack(">HHHHHHHH", self.response[0:16])}')
         fw_version, fw_build_yyyy, fw_build_mmdd, fw_build_hhmm, hw_id = struct.unpack('>HHHHH', self.response[0:10])
 
         fw_version_maj = int((fw_version / 10000))
@@ -385,7 +392,6 @@ class HardwareInfoResponse(UnknownResponse):
                       f'build at {fw_build_dd:>02}/{fw_build_mm:>02}/{fw_build_yyyy}T{fw_build_HH:>02}:{fw_build_MM:>02}, '\
                       f'HW revision {hw_id}')
 
-        data = super().__dict__()
         data['FW_ver_maj'] = fw_version_maj
         data['FW_ver_min'] = fw_version_min
         data['FW_ver_pat'] = fw_version_pat

tools/rpi/hoymiles/outputs.py

@@ -9,6 +9,7 @@ import socket
 import logging
 from datetime import datetime, timezone
 from hoymiles.decoders import StatusResponse, HardwareInfoResponse
+from hoymiles import HOYMILES_TRANSACTION_LOGGING, HOYMILES_DEBUG_LOGGING
 
 class OutputPluginFactory:
     def __init__(self, **params):
@@ -277,9 +278,10 @@ class VzInverterOutput:
         self.channels = dict()
 
         for channel in config.get('channels', []):
-            uid = channel.get('uid')
+            uid = channel.get('uid', None)
             ctype = channel.get('type')
-            if uid and ctype:
+            # if uid and ctype:
+            if ctype:
                 self.channels[ctype] = uid
 
     def store_status(self, data, session):
@@ -330,10 +332,17 @@ class VzInverterOutput:
 
     def try_publish(self, ts, ctype, value):
         if not ctype in self.channels:
-            logging.warning(f'ctype \"{ctype}\" not found in ahoy.yml')
+            if HOYMILES_DEBUG_LOGGING:
+                logging.warning(f'ctype \"{ctype}\" not found in ahoy.yml')
             return
+
         uid = self.channels[ctype]
         url = f'{self.baseurl}/data/{uid}.json?operation=add&ts={ts}&value={value}'
+        if uid == None:
+            if HOYMILES_DEBUG_LOGGING:
+                logging.warning(f'ctype \"{ctype}\" has no configured uid-value in ahoy.yml')
+            return
+
         try:
             r = self.session.get(url)
             if r.status_code == 404: