diff --git a/CHANGELOG.md b/CHANGELOG.md index 64be905..820aaef 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +- trace heartbeat and regular modbus pakets witl log level DEBUG +- GEN3PLUS: don't forward ack paket from tsun to the inverter - add allow and block filter for AT+ commands - catch all OSError errors in the read loop - log Modbus traces with different log levels diff --git a/app/src/gen3/talent.py b/app/src/gen3/talent.py index caf327d..25d15bc 100644 --- a/app/src/gen3/talent.py +++ b/app/src/gen3/talent.py @@ -52,6 +52,16 @@ class Talent(Message): # 0x78: 0x04: self.msg_inverter_data, } + self.log_lvl = { + 0x00: logging.INFO, + 0x13: logging.INFO, + 0x22: logging.INFO, + 0x71: logging.INFO, + # 0x76: + 0x77: self.get_modbus_log_lvl, + # 0x78: + 0x04: logging.INFO, + } self.modbus_elms = 0 # for unit tests ''' @@ -63,6 +73,7 @@ class Talent(Message): # so we have to erase self.switch, otherwise this instance can't be # deallocated by the garbage collector ==> we get a memory leak self.switch.clear() + self.log_lvl.clear() self.state = self.STATE_CLOSED super().close() @@ -100,7 +111,11 @@ class Talent(Message): if self.header_valid and len(self._recv_buffer) >= (self.header_len + self.data_len): - hex_dump_memory(logging.INFO, f'Received from {self.addr}:', + log_lvl = self.log_lvl.get(self.msg_id, logging.WARNING) + if callable(log_lvl): + log_lvl = log_lvl() + + hex_dump_memory(log_lvl, f'Received from {self.addr}:', self._recv_buffer, self.header_len+self.data_len) self.__set_serial_no(self.id_str.decode("utf-8")) @@ -126,7 +141,7 @@ class Talent(Message): if self.state != self.STATE_UP: return - self.__build_header(0x70, 0x77, log_lvl) + self.__build_header(0x70, 0x77) self._send_buffer += b'\x00\x01\xa3\x28' # fixme self._send_buffer += struct.pack('!B', len(modbus_pdu)) self._send_buffer += modbus_pdu @@ -217,16 +232,15 @@ class Talent(Message): self.header_valid = True return - def __build_header(self, ctrl, msg_id=None, - log_lvl: int = logging.INFO) -> None: + def __build_header(self, ctrl, msg_id=None) -> None: if not msg_id: msg_id = self.msg_id self.send_msg_ofs = len(self._send_buffer) self._send_buffer += struct.pack(f'!l{len(self.id_str)+1}pBB', 0, self.id_str, ctrl, msg_id) fnc = self.switch.get(msg_id, self.msg_unknown) - logger.log(log_lvl, self.__flow_str(self.server_side, 'tx') + - f' Ctl: {int(ctrl):#02x} Msg: {fnc.__name__!r}') + logger.info(self.__flow_str(self.server_side, 'tx') + + f' Ctl: {int(ctrl):#02x} Msg: {fnc.__name__!r}') def __finish_send_msg(self) -> None: _len = len(self._send_buffer) - self.send_msg_ofs @@ -391,6 +405,14 @@ class Talent(Message): # logger.debug(f'Modbus MsgLen: {modbus_len} Func:{result[2]}') return msg_hdr_len, modbus_len + def get_modbus_log_lvl(self) -> int: + if self.ctrl.is_req(): + return logging.INFO + elif self.ctrl.is_ind(): + if self.server_side: + return self.mb.last_log_lvl + return logging.WARNING + def msg_modbus(self): hdr_len, modbus_len = self.parse_modbus_header() data = self._recv_buffer[self.header_len: diff --git a/app/src/gen3plus/solarman_v5.py b/app/src/gen3plus/solarman_v5.py index 91ee30b..978ef78 100644 --- a/app/src/gen3plus/solarman_v5.py +++ b/app/src/gen3plus/solarman_v5.py @@ -93,6 +93,29 @@ class SolarmanV5(Message): 0x1510: self.msg_command_rsp, # from inverter # 0x0510: self.msg_command_rsp, # from inverter } + + self.log_lvl = { + + 0x4210: logging.INFO, # real time data + 0x1210: logging.INFO, # at least every 5 minutes + + 0x4710: logging.DEBUG, # heatbeat + 0x1710: logging.DEBUG, # every 2 minutes + + 0x4110: logging.INFO, # device data, sync start + 0x1110: logging.INFO, # every 3 hours + + 0x4310: logging.INFO, # regulary after 3-6 hours + 0x1310: logging.INFO, + + 0x4810: logging.INFO, # sync end + 0x1810: logging.INFO, + + # + # MODbus or AT cmd + 0x4510: logging.INFO, # from server + 0x1510: self.get_cmd_rsp_log_lvl, + } self.modbus_elms = 0 # for unit tests g3p_cnf = Config.get('gen3plus') @@ -108,6 +131,7 @@ class SolarmanV5(Message): # so we have to erase self.switch, otherwise this instance can't be # deallocated by the garbage collector ==> we get a memory leak self.switch.clear() + self.log_lvl.clear() self.state = self.STATE_CLOSED super().close() @@ -150,7 +174,10 @@ class SolarmanV5(Message): if self.header_valid and len(self._recv_buffer) >= (self.header_len + self.data_len+2): - hex_dump_memory(logging.INFO, f'Received from {self.addr}:', + log_lvl = self.log_lvl.get(self.control, logging.WARNING) + if callable(log_lvl): + log_lvl = log_lvl() + hex_dump_memory(log_lvl, f'Received from {self.addr}:', self._recv_buffer, self.header_len+self.data_len+2) if self.__trailer_is_ok(self._recv_buffer, self.header_len + self.data_len + 2): @@ -253,15 +280,15 @@ class SolarmanV5(Message): return True - def __build_header(self, ctrl, log_lvl: int = logging.INFO) -> None: + def __build_header(self, ctrl) -> None: '''build header for new transmit message''' self.send_msg_ofs = len(self._send_buffer) self._send_buffer += struct.pack( ' None: '''finish the transmit message, set lenght and checksum''' @@ -310,7 +337,7 @@ class SolarmanV5(Message): def send_modbus_cb(self, pdu: bytearray, log_lvl: int, state: str): if self.state != self.STATE_UP: return - self.__build_header(0x4510, log_lvl) + self.__build_header(0x4510) self._send_buffer += struct.pack(' int: + ftype = self._recv_buffer[self.header_len] + if ftype == self.AT_CMD: + if self.forward_at_cmd_resp: + return logging.INFO + return logging.DEBUG + elif ftype == self.MB_RTU_CMD: + if self.server_side: + return self.mb.last_log_lvl + + return logging.WARNING + def msg_command_rsp(self): data = self._recv_buffer[self.header_len: self.header_len+self.data_len] @@ -539,4 +578,4 @@ class SolarmanV5(Message): dt = datetime.fromtimestamp(ts) logger.debug(f'ts: {dt.strftime("%Y-%m-%d %H:%M:%S")}') - self.__forward_msg() + # self.__forward_msg() diff --git a/app/src/server.py b/app/src/server.py index c7ee03e..18dc401 100644 --- a/app/src/server.py +++ b/app/src/server.py @@ -83,6 +83,7 @@ if __name__ == "__main__": logging.getLogger('msg').setLevel(log_level) logging.getLogger('conn').setLevel(log_level) logging.getLogger('data').setLevel(log_level) + logging.getLogger('tracer').setLevel(log_level) # logging.getLogger('mqtt').setLevel(log_level) # read config file diff --git a/app/tests/test_solarman.py b/app/tests/test_solarman.py index 06a57f0..9deae56 100644 --- a/app/tests/test_solarman.py +++ b/app/tests/test_solarman.py @@ -949,7 +949,7 @@ def test_device_rsp(ConfigTsunInv1, DeviceRspMsg): assert m.data_len == 0x0a assert m._recv_buffer==b'' assert m._send_buffer==b'' - assert m._forward_buffer==DeviceRspMsg + assert m._forward_buffer==b'' assert m.db.stat['proxy']['Invalid_Msg_Format'] == 0 m.close() @@ -967,7 +967,7 @@ def test_inverter_rsp(ConfigTsunInv1, InverterRspMsg): assert m.data_len == 0x0a assert m._recv_buffer==b'' assert m._send_buffer==b'' - assert m._forward_buffer==InverterRspMsg + assert m._forward_buffer==b'' assert m.db.stat['proxy']['Invalid_Msg_Format'] == 0 m.close() @@ -1003,7 +1003,7 @@ def test_heartbeat_rsp(ConfigTsunInv1, HeartbeatRspMsg): assert m.data_len == 0x0a assert m._recv_buffer==b'' assert m._send_buffer==b'' - assert m._forward_buffer==HeartbeatRspMsg + assert m._forward_buffer==b'' assert m.db.stat['proxy']['Invalid_Msg_Format'] == 0 m.close() @@ -1045,7 +1045,7 @@ def test_sync_start_rsp(ConfigTsunInv1, SyncStartRspMsg): assert m.data_len == 0x0a assert m._recv_buffer==b'' assert m._send_buffer==b'' - assert m._forward_buffer==SyncStartRspMsg + assert m._forward_buffer==b'' assert m.db.stat['proxy']['Invalid_Msg_Format'] == 0 m.close() @@ -1081,7 +1081,7 @@ def test_sync_end_rsp(ConfigTsunInv1, SyncEndRspMsg): assert m.data_len == 0x0a assert m._recv_buffer==b'' assert m._send_buffer==b'' - assert m._forward_buffer==SyncEndRspMsg + assert m._forward_buffer==b'' assert m.db.stat['proxy']['Invalid_Msg_Format'] == 0 m.close()