Browse Source

RPI: use logging facility instead print()

pull/409/head
Christian Ehrlicher 2 years ago
parent
commit
cbcfb8da72
  1. 6
      tools/rpi/ahoy.yml.example
  2. 7
      tools/rpi/hoymiles/__init__.py
  3. 59
      tools/rpi/hoymiles/__main__.py
  4. 55
      tools/rpi/hoymiles/decoders/__init__.py
  5. 3
      tools/rpi/hoymiles/outputs.py

6
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

7
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

59
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)

55
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

3
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)

Loading…
Cancel
Save