diff --git a/tools/rpi/ahoy.yml.example b/tools/rpi/ahoy.yml.example index 58866816..04da1f18 100644 --- a/tools/rpi/ahoy.yml.example +++ b/tools/rpi/ahoy.yml.example @@ -2,6 +2,12 @@ ahoy: interval: 5 + + logging: + filename: 'hoymiles.log' + # DEBUG, INFO, WARNING, ERROR, FATAL + level: 'INFO' + sunset: disabled: false latitude: 51.799118 diff --git a/tools/rpi/hoymiles/__init__.py b/tools/rpi/hoymiles/__init__.py index 5892e9a0..c02a0c71 100644 --- a/tools/rpi/hoymiles/__init__.py +++ b/tools/rpi/hoymiles/__init__.py @@ -9,6 +9,7 @@ import struct import time import re from datetime import datetime +import logging import crcmod 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 from .decoders import * @@ -573,7 +574,7 @@ class InverterTransaction: if HOYMILES_TRANSACTION_LOGGING: c_datetime = datetime.now().strftime("%Y-%m-%d %H:%M:%S.%f") - print(f'{c_datetime} Transmit {len(packet)} | {hexify_payload(packet)}') + logging.debug(f'{c_datetime} Transmit {len(packet)} | {hexify_payload(packet)}') self.radio.transmit(packet, txpower=self.txpower) @@ -581,14 +582,14 @@ class InverterTransaction: try: for response in self.radio.receive(): if HOYMILES_TRANSACTION_LOGGING: - print(response) + logging.debug(response) self.frame_append(response) wait = True except TimeoutError: pass except BufferError as e: - print(f'Buffer error {e}') + logging.warning(f'Buffer error {e}') pass return wait diff --git a/tools/rpi/hoymiles/__main__.py b/tools/rpi/hoymiles/__main__.py index ec228d26..0e5c60d5 100644 --- a/tools/rpi/hoymiles/__main__.py +++ b/tools/rpi/hoymiles/__main__.py @@ -19,6 +19,7 @@ import yaml from yaml.loader import SafeLoader import paho.mqtt.client import hoymiles +import logging class InfoCommands(IntEnum): InverterDevInform_Simple = 0 # 0x00 @@ -49,7 +50,7 @@ class SunsetHandler: altitude = sunset_config.get('altitude') self.suntimes = SunTimes(longitude=longitude, latitude=latitude, altitude=altitude) self.nextSunset = self.suntimes.setutc(datetime.utcnow()) - print (f'Todays sunset is at {self.nextSunset} UTC') + logging.info (f'Todays sunset is at {self.nextSunset} UTC') def checkWaitForSunrise(self): if not self.suntimes: @@ -61,11 +62,11 @@ class SunsetHandler: tomorrow = now + timedelta(days=1) nextSunrise = self.suntimes.riseutc(tomorrow) self.nextSunset = self.suntimes.setutc(tomorrow) - time_to_sleep = (nextSunrise - datetime.now()).total_seconds() - print (f'Waiting for sunrise at {nextSunrise} UTC ({time_to_sleep} seconds)') + time_to_sleep = int((nextSunrise - datetime.now()).total_seconds()) + logging.info (f'Waiting for sunrise at {nextSunrise} UTC ({time_to_sleep} seconds)') if time_to_sleep > 0: time.sleep(time_to_sleep) - print (f'Woke up... next sunset is at {self.nextSunset} UTC') + logging.info (f'Woke up... next sunset is at {self.nextSunset} UTC') def main_loop(ahoy_config): """Main loop""" @@ -86,12 +87,10 @@ def main_loop(ahoy_config): for inverter in inverters: if hoymiles.HOYMILES_DEBUG_LOGGING: - print(f'Poll inverter {inverter["serial"]}') + logging.debug(f'Poll inverter {inverter["serial"]}') poll_inverter(inverter, dtu_ser, do_init, 3) do_init = False - print('', end='', flush=True) - if loop_interval > 0: time_to_sleep = loop_interval - (time.time() - t_loop_start) if time_to_sleep > 0: @@ -100,8 +99,8 @@ def main_loop(ahoy_config): except KeyboardInterrupt: sys.exit() except Exception as e: - print ('Exception catched: %s' % e) - print (traceback.print_exc()) + logging.fatal('Exception catched: %s' % e) + logging.fatal(traceback.print_exc()) raise @@ -147,14 +146,14 @@ def poll_inverter(inverter, dtu_ser, do_init, retries): response = com.get_payload() payload_ttl = 0 except Exception as e_all: - print(f'Error while retrieving data: {e_all}') + logging.error(f'Error while retrieving data: {e_all}') pass # Handle the response data if any if response: c_datetime = datetime.now() if hoymiles.HOYMILES_DEBUG_LOGGING: - print(f'{c_datetime} Payload: ' + hoymiles.hexify_payload(response)) + logging.debug(f'{c_datetime} Payload: ' + hoymiles.hexify_payload(response)) decoder = hoymiles.ResponseDecoder(response, request=com.request, inverter_ser=inverter_ser @@ -164,18 +163,17 @@ def poll_inverter(inverter, dtu_ser, do_init, retries): data = result.__dict__() if hoymiles.HOYMILES_DEBUG_LOGGING: - print(f'{c_datetime} Decoded: temp={data["temperature"]}, total={data["energy_total"]/1000:.3f}', end='') + logging.debug(f'{c_datetime} Decoded: temp={data["temperature"]}, total={data["energy_total"]/1000:.3f}', end='') if data['powerfactor'] is not None: - print(f', pf={data["powerfactor"]}', end='') + logging.debug(f', pf={data["powerfactor"]}', end='') phase_id = 0 for phase in data['phases']: - print(f' phase{phase_id}=voltage:{phase["voltage"]}, current:{phase["current"]}, power:{phase["power"]}, frequency:{data["frequency"]}', end='') + logging.debug(f' phase{phase_id}=voltage:{phase["voltage"]}, current:{phase["current"]}, power:{phase["power"]}, frequency:{data["frequency"]}', end='') phase_id = phase_id + 1 string_id = 0 for string in data['strings']: - print(f' string{string_id}=voltage:{string["voltage"]}, current:{string["current"]}, power:{string["power"]}, total:{string["energy_total"]/1000}, daily:{string["energy_daily"]}', end='') + logging.debug(f' string{string_id}=voltage:{string["voltage"]}, current:{string["current"]}, power:{string["power"]}, total:{string["energy_total"]/1000}, daily:{string["energy_daily"]}', end='') string_id = string_id + 1 - print() if 'event_count' in data: if event_message_index[inv_str] < data['event_count']: @@ -256,7 +254,7 @@ def mqtt_on_command(client, userdata, message): inverter_ser = next( item[0] for item in mqtt_command_topic_subs if item[1] == message.topic) except StopIteration: - print('Unexpedtedly received mqtt message for {message.topic}') + logging.warning('Unexpedtedly received mqtt message for {message.topic}') if inverter_ser: p_message = message.payload.decode('utf-8').lower() @@ -274,14 +272,31 @@ def mqtt_on_command(client, userdata, message): command_queue[str(inverter_ser)].append( hoymiles.frame_payload(payload[1:])) +def init_logging(ahoy_config): + log_config = ahoy_config.get('logging') + fn = 'hoymiles.log' + lvl = logging.ERROR + if log_config: + fn = log_config.get('filename', fn) + level = log_config.get('level', 'ERROR') + if level == 'DEBUG': + lvl = logging.DEBUG + elif level == 'INFO': + lvl = logging.INFO + elif level == 'WARNING': + lvl = logging.WARNING + elif level == 'ERROR': + lvl = logging.ERROR + logging.basicConfig(filename=fn, format='%(asctime)s %(levelname)s: %(message)s', datefmt='%Y-%m-%d %H:%M:%S', level=lvl) + if __name__ == '__main__': parser = argparse.ArgumentParser(description='Ahoy - Hoymiles solar inverter gateway', prog="hoymiles") parser.add_argument("-c", "--config-file", nargs="?", required=True, help="configuration file") parser.add_argument("--log-transactions", action="store_true", default=False, - help="Enable transaction logging output") + help="Enable transaction logging output (loglevel must be DEBUG)") parser.add_argument("--verbose", action="store_true", default=False, - help="Enable debug output") + help="Enable detailed debug output (loglevel must be DEBUG)") global_config = parser.parse_args() # Load ahoy.yml config file @@ -293,13 +308,14 @@ if __name__ == '__main__': with open('ahoy.yml', 'r') as fh_yaml: cfg = yaml.load(fh_yaml, Loader=SafeLoader) except FileNotFoundError: - print("Could not load config file. Try --help") + logging.error("Could not load config file. Try --help") sys.exit(2) except yaml.YAMLError as e_yaml: - print('Failed to load config frile {global_config.config_file}: {e_yaml}') + logging.error('Failed to load config file {global_config.config_file}: {e_yaml}') sys.exit(1) ahoy_config = dict(cfg.get('ahoy', {})) + init_logging(ahoy_config) # Prepare for multiple transceivers, makes them configurable (currently # only one supported) @@ -366,4 +382,5 @@ if __name__ == '__main__': mqtt_client.subscribe(topic_item[1]) mqtt_command_topic_subs.append(topic_item) + logging.info(f'Starting main_loop with inverter(s) {g_inverters}') main_loop(ahoy_config) diff --git a/tools/rpi/hoymiles/decoders/__init__.py b/tools/rpi/hoymiles/decoders/__init__.py index 19062419..bae51686 100644 --- a/tools/rpi/hoymiles/decoders/__init__.py +++ b/tools/rpi/hoymiles/decoders/__init__.py @@ -8,6 +8,7 @@ Hoymiles Micro-Inverters decoder library import struct from datetime import datetime, timedelta import crcmod +import logging f_crc_m = crcmod.predefined.mkPredefinedCrcFun('modbus') f_crc8 = crcmod.mkCrcFun(0x101, initCrc=0, xorOut=0) @@ -44,17 +45,17 @@ def print_table_unpack(s_fmt, payload, cw=6): l_hexlified = [f'{byte:02x}' for byte in payload] - print(f'{"Pos": <{cw}}', end='') - print(''.join([f'{num: >{cw}}' for num in range(0, len(payload))])) - print(f'{"Hex": <{cw}}', end='') - print(''.join([f'{byte: >{cw}}' for byte in l_hexlified])) + logging.debug(f'{"Pos": <{cw}}', end='') + logging.debug(''.join([f'{num: >{cw}}' for num in range(0, len(payload))])) + logging.debug(f'{"Hex": <{cw}}', end='') + logging.debug(''.join([f'{byte: >{cw}}' for byte in l_hexlified])) l_fmt = struct.calcsize(s_fmt) if len(payload) >= l_fmt: for offset in range(0, l_fmt): - print(f'{s_fmt: <{cw}}', end='') - print(' ' * cw * offset, end='') - print(''.join( + logging.debug(f'{s_fmt: <{cw}}', end='') + logging.debug(' ' * cw * offset, end='') + logging.debug(''.join( [f'{num[0]: >{cw*l_fmt}}' for num in g_unpack(s_fmt, payload[offset:])])) class Response: @@ -299,7 +300,7 @@ class EventsResponse(UnknownResponse): crc_valid = self.validate_crc_m() if crc_valid: - #print(' payload has valid modbus crc') + #logging.debug(' payload has valid modbus crc') self.response = self.response[:-2] status = struct.unpack('>H', self.response[:2])[0] @@ -310,16 +311,16 @@ class EventsResponse(UnknownResponse): for i_chunk in range(2, len(self.response), chunk_size): chunk = self.response[i_chunk:i_chunk+chunk_size] - print(' '.join([f'{byte:02x}' for byte in chunk]) + ': ') + logging.debug(' '.join([f'{byte:02x}' for byte in chunk]) + ': ') opcode, a_code, a_count, uptime_sec = struct.unpack('>BBHH', chunk[0:6]) a_text = self.alarm_codes.get(a_code, 'N/A') - print(f' uptime={timedelta(seconds=uptime_sec)} a_count={a_count} opcode={opcode} a_code={a_code} a_text={a_text}') + logging.debug(f' uptime={timedelta(seconds=uptime_sec)} a_count={a_count} opcode={opcode} a_code={a_code} a_text={a_text}') for fmt in ['BBHHHHH']: - print(f' {fmt:7}: ' + str(struct.unpack('>' + fmt, chunk))) - print(end='', flush=True) + logging.debug(f' {fmt:7}: ' + str(struct.unpack('>' + fmt, chunk))) + logging.debug(end='', flush=True) class HardwareInfoResponse(UnknownResponse): def __init__(self, *args, **params): @@ -340,8 +341,8 @@ class HardwareInfoResponse(UnknownResponse): fw_version_pat = int((fw_version % 100)) fw_build_mm = int(fw_build_mmdd / 100) fw_build_dd = int(fw_build_mmdd % 100) - print() - print(f'Firmware: {fw_version_maj}.{fw_version_min}.{fw_version_pat} build at {fw_build_dd}/{fw_build_mm}/{fw_build_yyyy}, HW revision {hw_id}') + logging.debug() + logging.debug(f'Firmware: {fw_version_maj}.{fw_version_min}.{fw_version_pat} build at {fw_build_dd}/{fw_build_mm}/{fw_build_yyyy}, HW revision {hw_id}') class DebugDecodeAny(UnknownResponse): """Default decoder""" @@ -351,40 +352,40 @@ class DebugDecodeAny(UnknownResponse): crc8_valid = self.validate_crc8() if crc8_valid: - print(' payload has valid crc8') + logging.debug(' payload has valid crc8') self.response = self.response[:-1] crc_valid = self.validate_crc_m() if crc_valid: - print(' payload has valid modbus crc') + logging.debug(' payload has valid modbus crc') self.response = self.response[:-2] l_payload = len(self.response) - print(f' payload has {l_payload} bytes') + logging.debug(f' payload has {l_payload} bytes') - print() - print('Field view: int') + logging.debug() + logging.debug('Field view: int') print_table_unpack('>B', self.response) - print() - print('Field view: shorts') + logging.debug() + logging.debug('Field view: shorts') print_table_unpack('>H', self.response) - print() - print('Field view: longs') + logging.debug() + logging.debug('Field view: longs') print_table_unpack('>L', self.response) try: if len(self.response) > 2: - print(' type utf-8 : ' + self.response.decode('utf-8')) + logging.debug(' type utf-8 : ' + self.response.decode('utf-8')) except UnicodeDecodeError: - print(' type utf-8 : utf-8 decode error') + logging.debug(' type utf-8 : utf-8 decode error') try: if len(self.response) > 2: - print(' type ascii : ' + self.response.decode('ascii')) + logging.debug(' type ascii : ' + self.response.decode('ascii')) except UnicodeDecodeError: - print(' type ascii : ascii decode error') + logging.debug(' type ascii : ascii decode error') # 1121-Series Intervers, 1 MPPT, 1 Phase diff --git a/tools/rpi/hoymiles/outputs.py b/tools/rpi/hoymiles/outputs.py index 7223a287..a365033a 100644 --- a/tools/rpi/hoymiles/outputs.py +++ b/tools/rpi/hoymiles/outputs.py @@ -6,6 +6,7 @@ Hoymiles output plugin library """ import socket +import logging from datetime import datetime, timezone from hoymiles.decoders import StatusResponse @@ -310,4 +311,4 @@ class VolkszaehlerOutputPlugin(OutputPluginFactory): try: output.store_status(data, self.session) except ValueError as e: - print('Could not send data to volkszaehler instance: %s' % e) + logging.warning('Could not send data to volkszaehler instance: %s' % e)