def query_object(sock, parameter):
# query information about an object ID:
object_info = R.get_by_name(parameter)
# construct a byte stream that will send a read command for the object ID we want, and send it
send_frame = make_frame(command=Command.READ, id=object_info.object_id)
sock.send(send_frame)
# loop until we got the entire response frame
frame = ReceiveFrame()
while True:
ready_read, _, _ = select.select([sock], [], [], 2.0)
if sock in ready_read:
# receive content of the input buffer
buf = sock.recv(256)
# if there is content, let the frame consume it
if len(buf) > 0:
frame.consume(buf)
# if the frame is complete, we're done
if frame.complete():
break
else:
# the socket was closed by the device, exit
sys.exit(1)
# decode the frames payload
value = decode_value(object_info.response_data_type, frame.data)
return value
def test_read_standard_nopayload(self, data_in: str, result: dict) -> None:
'''
Tests that payloadless data can be read.
'''
data = bytearray.fromhex(data_in)
frame = ReceiveFrame()
assert frame.consume(data) == len(data), 'The frame should consume all the data'
assert frame.complete(), 'The frame should be complete'
assert frame.command == result['cmd']
assert frame.id == result['id']
assert frame.address == 0, 'Standard frames have no address'
assert frame.data == b'', 'No data was attached, so the shouldn\'t be any'
def test_read_standard_int(self) -> None:
'''
Tests that a integer payload can be read. The data has a leading NULL byte, too. Response for
`display_struct.brightness` from a real device.
'''
data = bytearray.fromhex('002b050529bda75fffb8d2')
frame = ReceiveFrame()
assert frame.consume(data) == len(data), 'The frame should consume all the data'
assert frame.complete(), 'The frame should be complete'
assert frame.command == Command.RESPONSE
assert frame.id == 0x29bda75f
assert frame.address == 0, 'Standard frames have no address'
assert frame.data == b'\xff'
def test_read_standard_string(self) -> None:
'''
Tests that a larger string can be read. Response for `android_name` from a real device.
'''
data = bytearray.fromhex('002b0544ebc62737505320362e30204241334c0000000000000000000000000000000000000000000000'
'000000000000000000000000000000000000000000000000000000000000476c')
frame = ReceiveFrame()
assert frame.consume(data) == len(data), 'The frame should consume all the data'
assert frame.complete(), 'The frame should be complete'
assert frame.command == Command.RESPONSE
assert frame.id == 0xebc62737
assert frame.address == 0, 'Standard frames have no address'
assert frame.data == bytearray.fromhex('505320362e30204241334c000000000000000000000000000000000000000000000000'
'0000000000000000000000000000000000000000000000000000000000')
async def _read_object(self, reader: StreamReader, writer: StreamWriter,
object_id: int):
object_name = REGISTRY.get_by_id(object_id).name
read_command_frame = SendFrame(command=Command.READ, id=object_id)
_LOGGER.debug("Requesting RCT Power data for object %x (%s)...",
object_id, object_name)
request_time = datetime.now()
try:
async with async_timeout.timeout(READ_TIMEOUT):
await writer.drain()
writer.write(read_command_frame.data)
# loop until we return or time out
while True:
response_frame = ReceiveFrame()
while not response_frame.complete() and not reader.at_eof(
):
raw_response = await reader.read(1)
if len(raw_response) > 0:
response_frame.consume(raw_response)
if response_frame.is_complete():
response_object_info = REGISTRY.get_by_id(
response_frame.id)
data_type = response_object_info.response_data_type
received_object_name = response_object_info.name
# ignore, if this is not the answer to the latest request
if object_id != response_frame.id:
_LOGGER.debug(
"Mismatch of requested and received object ids: requested %x (%s), but received %x (%s)",
object_id,
object_name,
response_frame.id,
received_object_name,
)
continue
decoded_value = decode_value(data_type,
response_frame.data)
_LOGGER.debug(
"Decoded data for object %x (%s): %s",
response_frame.id,
received_object_name,
decoded_value,
)
return ValidApiResponse(
object_id=object_id,
time=request_time,
value=decoded_value,
)
else:
_LOGGER.debug(
"Error decoding object %x (%s): %s",
object_id,
object_name,
response_frame._data,
)
return InvalidApiResponse(object_id=object_id,
time=request_time,
cause="INCOMPLETE")
except TimeoutError as exc:
_LOGGER.debug("Error reading object %x (%s): %s", object_id,
object_name, exc)
return InvalidApiResponse(
object_id=object_id,
time=request_time,
cause="OBJECT_READ_TIMEOUT",
)
except FrameCRCMismatch as exc:
_LOGGER.debug("Error reading object %x (%s): %s", object_id,
object_name, exc)
return InvalidApiResponse(object_id=object_id,
time=request_time,
cause="CRC_ERROR")
except struct.error as exc:
_LOGGER.debug("Error reading object %x (%s): %s", object_id,
object_name, exc)
return InvalidApiResponse(object_id=object_id,
time=request_time,
cause="PARSING_ERROR")
except Exception as exc:
_LOGGER.debug("Error reading object %x (%s): %s", object_id,
object_name, exc)
return InvalidApiResponse(object_id=object_id,
time=request_time,
cause="UNKNOWN_ERROR")
def timeseries2csv(host: str, port: int, output: Optional[str],
no_headers: bool, time_zone: str, quiet: bool,
resolution: str, count: int, day_before_today: int) -> None:
'''
Extract time series data from an RCT device. The tool works similar to the official App, but can be run
independantly, it is designed to be run from a cronjob or as part of a script.
The output format is CSV. If --output is not given, then a name is constructed from the resolution and the current
date. Specify "-" to have the tool print the table to standard output, for use with other tools. Unless
--no-headers is set, the first line contains the column headers.
Data is queried into the past, by specifying the latest point in time for which data should be queried. Thus,
DAYS_BEFORE_TODAY selects the last second of the day that is the given amount in the past. 0 therefor is the
incomplete current day, 1 is the end of yesterday etc.
The device has multiple sampling memories at varying sampling intervals. The resolution can be selected using
--resolution, which supports "minutes" (which is at 5 minute intervals), day, month and year. The amount of time
to cover (back from the end of DAY_BEFORE_TODAY) can be selected using --count:
* For --resolution=minute, if DAY_BEFORE_TODAY is 0 it selects the last --count hours up to the current time.
* For --resolution=minute, if DAY_BEFORE_TODAY is greater than 0, it selects --count days back.
* For all the other resolutions, --count selects the amount of days, months and years to go back, respectively.
Note that the tool does not remove extra information: If the device sends more data than was requested, that extra
data is included.
Examples:
* The previous 3 hours at finest resolution: --resolution=minutes --count=3 0
* A whole day, 3 days ago, at finest resolution: --resolution=minutes --count=24 3
* 4 Months back, at 1 month resolution: --resolution=month --count=4 0
'''
global be_quiet
be_quiet = quiet
if count < 1:
cprint('Error: --count must be a positive integer')
sys.exit(1)
timezone = pytz.timezone(time_zone)
now = datetime.now()
if resolution == 'minutes':
oid_names = [
'logger.minutes_ubat_log_ts', 'logger.minutes_ul3_log_ts',
'logger.minutes_ub_log_ts', 'logger.minutes_temp2_log_ts',
'logger.minutes_eb_log_ts', 'logger.minutes_eac1_log_ts',
'logger.minutes_eext_log_ts', 'logger.minutes_ul2_log_ts',
'logger.minutes_ea_log_ts', 'logger.minutes_soc_log_ts',
'logger.minutes_ul1_log_ts', 'logger.minutes_eac2_log_ts',
'logger.minutes_eac_log_ts', 'logger.minutes_ua_log_ts',
'logger.minutes_soc_targ_log_ts',
'logger.minutes_egrid_load_log_ts',
'logger.minutes_egrid_feed_log_ts', 'logger.minutes_eload_log_ts',
'logger.minutes_ebat_log_ts', 'logger.minutes_temp_bat_log_ts',
'logger.minutes_eac3_log_ts', 'logger.minutes_temp_log_ts'
]
# the prefix is cut from the front of individual oid_names to produce the name (the end is cut off, too)
name_prefix = 'logger.minutes_'
# one sample every 5 minutes
timediff = relativedelta(minutes=5)
# select whole days when not querying the current day
if day_before_today > 0:
# lowest timestamp that's of interest
ts_start = (now - timedelta(days=day_before_today)).replace(
hour=0, minute=0, second=0, microsecond=0)
# highest timestamp, we stop when this is reached
ts_end = ts_start.replace(hour=23,
minute=59,
second=59,
microsecond=0)
else:
ts_start = ((now - (now - datetime.min) % timedelta(minutes=30)) - timedelta(hours=count)) \
.replace(second=0, microsecond=0)
ts_end = now.replace(second=59, microsecond=0)
elif resolution == 'day':
oid_names = [
'logger.day_ea_log_ts', 'logger.day_eac_log_ts',
'logger.day_eb_log_ts', 'logger.day_eext_log_ts',
'logger.day_egrid_feed_log_ts', 'logger.day_egrid_load_log_ts',
'logger.day_eload_log_ts'
]
name_prefix = 'logger.day_'
# one sample every day
timediff = relativedelta(days=1)
# <count> days
ts_start = (now - timedelta(days=day_before_today + count)) \
.replace(hour=0, minute=59, second=59, microsecond=0)
ts_end = (now - timedelta(days=day_before_today)).replace(
hour=23, minute=59, second=59, microsecond=0)
elif resolution == 'month':
oid_names = [
'logger.month_ea_log_ts', 'logger.month_eac_log_ts',
'logger.month_eb_log_ts', 'logger.month_eext_log_ts',
'logger.month_egrid_feed_log_ts', 'logger.month_egrid_load_log_ts',
'logger.month_eload_log_ts'
]
name_prefix = 'logger.month_'
# one sample per month
timediff = relativedelta(months=1)
# <count> months
ts_start = (now - timedelta(days=day_before_today) - relativedelta(months=count)) \
.replace(day=2, hour=0, minute=59, second=59, microsecond=0)
if ts_start.year < 2000:
ts_start = ts_start.replace(year=2000)
ts_end = (now - timedelta(days=day_before_today)).replace(
day=2, hour=23, minute=59, second=59, microsecond=0)
elif resolution == 'year':
oid_names = [
'logger.year_ea_log_ts', 'logger.year_eac_log_ts',
'logger.year_eb_log_ts', 'logger.year_eext_log_ts',
'logger.year_egrid_feed_log_ts', 'logger.year_egrid_load_log_ts',
'logger.year_eload_log_ts'
] # , 'logger.year_log_ts']
name_prefix = 'logger.year_'
# one sample per year
timediff = relativedelta(years=1)
# <count> years
ts_start = (now - timedelta(days=day_before_today) - relativedelta(years=count)) \
.replace(month=1, day=2, hour=0, minute=59, second=59, microsecond=0)
ts_end = (now - timedelta(days=day_before_today)) \
.replace(month=1, day=2, hour=23, minute=59, second=59, microsecond=0)
else:
cprint('Unsupported resolution')
sys.exit(1)
if day_before_today < 0:
cprint('DAYS_BEFORE_TODAY must be a positive number')
sys.exit(1)
if day_before_today > 365:
cprint('DAYS_BEFORE_TODAY must be less than a year ago')
sys.exit(1)
oids = [x for x in R.all() if x.name in oid_names]
sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
try:
sock.connect((host, port))
except ConnectionRefusedError:
cprint('Device refused connection')
sys.exit(2)
datetable: Dict[datetime, Dict[str, int]] = {
dt: dict()
for dt in datetime_range(ts_start, ts_end, timediff)
}
for oid in oids:
name = oid.name.replace(name_prefix, '').replace('_log_ts', '')
cprint(f'Requesting {name}')
# set to true if the current time series reached its end, e.g. year 2000 for "year" resolution
iter_end = False
highest_ts = ts_end
while highest_ts > ts_start and not iter_end:
cprint(f'\ttimestamp: {highest_ts}')
sock.send(
make_frame(command=Command.WRITE,
id=oid.object_id,
payload=encode_value(DataType.INT32,
int(highest_ts.timestamp()))))
rframe = ReceiveFrame()
while True:
try:
rread, _, _ = select.select([sock], [], [], 2)
except select.error as exc:
cprint(f'Select error: {str(exc)}')
raise
if rread:
buf = sock.recv(1024)
if len(buf) > 0:
try:
rframe.consume(buf)
except FrameCRCMismatch:
cprint('\tCRC error')
break
if rframe.complete():
break
else:
cprint('Device closed connection')
sys.exit(2)
else:
cprint('\tTimeout, retrying')
break
if not rframe.complete():
cprint('\tIncomplete frame, retrying')
continue
# in case something (such as a "net.package") slips in, make sure to ignore all irelevant responses
if rframe.id != oid.object_id:
cprint(f'\tGot unexpected frame oid 0x{rframe.id:08X}')
continue
try:
_, table = decode_value(DataType.TIMESERIES, rframe.data)
except (AssertionError, struct.error):
# the device sent invalid data with the correct CRC
cprint('\tInvalid data received, retrying')
continue
# work with the data
for t_ts, t_val in table.items():
# set the "highest" point in time to know what to request next when the day is not complete
if t_ts < highest_ts:
highest_ts = t_ts
# break if we reached the end of the day
if t_ts < ts_start:
cprint('\tReached limit')
break
# Check if the timestamp fits the raster, adjust depending on the resolution
if t_ts not in datetable:
if resolution == 'minutes':
# correct up to one full minute
nt_ts = t_ts.replace(second=0)
if nt_ts not in datetable:
nt_ts = t_ts.replace(second=0,
minute=t_ts.minute + 1)
if nt_ts not in datetable:
cprint(
f'\t{t_ts} does not fit raster, skipped')
continue
t_ts = nt_ts
elif resolution in ['day', 'month']:
# correct up to one hour
nt_ts = t_ts.replace(hour=0)
if nt_ts not in datetable:
nt_ts = t_ts.replace(hour=t_ts.hour + 1)
if nt_ts not in datetable:
cprint(
f'\t{t_ts} does not fit raster, skipped')
continue
t_ts = nt_ts
datetable[t_ts][name] = t_val
# year statistics stop at 2000-01-02 00:59:59, so if the year hits 2000 we know we're done
if resolution == 'year' and t_ts.year == 2000:
iter_end = True
if output is None:
output = f'data_{resolution}_{ts_start.isoformat("T")}.csv'
if output == '-':
fd = sys.stdout
else:
filedes, filepath = mkstemp(dir=os.path.dirname(output), text=True)
fd = open(filedes, 'wt')
writer = csv.writer(fd)
names = [
oid.name.replace(name_prefix, '').replace('_log_ts', '')
for oid in oids
]
if not no_headers:
writer.writerow(['timestamp'] + names)
for bts, btval in datetable.items():
if btval: # there may be holes in the data
writer.writerow([timezone.localize(bts).isoformat('T')] +
[str(btval[name]) for name in names])
if output != '-':
fd.flush()
os.fsync(fd.fileno())
try:
os.rename(filepath, output)
except OSError as exc:
cprint(f'Could not move destination file: {str(exc)}')
try:
os.unlink(filepath)
except Exception:
cprint(f'Could not remove temporary file {filepath}')
sys.exit(1)
class Daemon:
'''
Daemon implementation. The daemon runs continuously in a 1 second tight loop. It requests payloads from the
DeviceManager at periodic intervals and dispatches the received frames back to it.
'''
#: Set this to True to stop the loop (e.g. to terminate the program).
_stop: bool
#: timestamp when the last set of frames was assembled by the device manager and put into the send buffer
_ts_last_frame_sent: datetime
#: communication socket, do not use if _connected is False
_socket: socket.socket
#: Device manager
_device_manager: DeviceManager
#: Whether debug mode is on
_debug: bool
#: Buffer for to-be-sent data
_send_buf: bytes
#: Buffer for received data
_recv_buf: bytes
#: Whether the connection to the device is established
_connected: bool
#: Buffer for decoding received data
_current_frame: Optional[ReceiveFrame]
#: Instance of the settings
_settings: RctMonConfig
_influx: InfluxDB
def __init__(self, settings: RctMonConfig, debug: bool = False) -> None:
log.info('Daemon initializing')
self._settings = settings
self._debug = debug
self._stop = False
self._send_buf = b''
self._recv_buf = b''
self._current_frame = None
self._connected = False
self._influx = InfluxDB(self._settings.influxdb)
self._device_manager = DeviceManager(self._influx)
self._ts = TSCollection()
signal.signal(signal.SIGTERM, self.signal_handler)
if self._settings.prometheus.exposition:
self._settings.prometheus.enable = True
if self._settings.prometheus.enable:
log.info('Prometheus endpoint is at http://%s:%d/metrics',
self._settings.prometheus.bind_address,
self._settings.prometheus.bind_port)
setup_monitoring(self._settings.prometheus)
if HAVE_SYSTEMD:
log.info('Signaling readiness')
systemd.daemon.notify('READY=1')
log.info('Ready to start the main loop')
def signal_handler(self, signum, _frame):
'''
Signal handler, called by the interpreter if a signal is received which was selected using the
``signal.signal`` function before.
* ``SIGTERM`` causes the main loop to terminate gracefully.
'''
if signum == signal.SIGTERM:
log.info('Caught SIGTERM, shutting down')
if HAVE_SYSTEMD:
systemd.daemon.notify('STOPPING=1')
self._stop = True
else:
log.warning('Caught signal %d, no handler, ignoring', signum)
def cleanup(self) -> None:
'''
Cleanup code. This is called after the main loop ends before the program terminates.
'''
self._socket_disconnect()
def _socket_connect(self) -> None:
self._ts.last_contact_attempt = datetime.utcnow()
log.debug('Creating socket: %s:%d', self._settings.device.host,
self._settings.device.port)
self._connected = False
self._socket = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
self._socket.setblocking(False)
err = self._socket.connect_ex(
(self._settings.device.host, self._settings.device.port))
if err != errno.EINPROGRESS:
if err == errno.ECONNREFUSED:
socklog.warning('Connection refused')
else:
socklog.warning('Socket error: %s', err)
else:
socklog.debug('Connection established')
self._connected = True
def _socket_disconnect(self) -> None:
self._connected = False
self._send_buf = b''
if self._socket:
# self._socket.shutdown(socket.SHUT_RDWR)
self._socket.close()
socklog.info('Socket disconnected')
self._connected = False
def _handle_socket_read(self) -> None:
'''
Handles reading from the socket. Called when select() returns our socket as having data to read.
'''
socklog.debug('socket is readable')
try:
recv_data = self._socket.recv(4096)
except ConnectionRefusedError:
socklog.warning('Socket receive: Connection refused')
self._socket_disconnect()
except ConnectionResetError:
socklog.warning('Socket receive: Connection reset')
self._socket_disconnect()
except TimeoutError:
socklog.warning('Socket receive: Connection timed out')
self._socket_disconnect()
else:
recv_len = len(recv_data)
socklog.debug('Got %d from socket', recv_len)
if recv_len == 0:
socklog.warning('Socket disconnected (empty recv)')
self._socket_disconnect()
else:
MON_BYTES_RECEIVED.inc(len(recv_data))
self._recv_buf += recv_data
def _handle_socket_writable(self) -> None:
'''
Handles writing data from the buffer to the socket. Called when select indicates that the socket can be written
to.
'''
socklog.debug('socket is writable')
if len(self._send_buf) > 0:
socklog.debug('send buf contains %d bytes', len(self._send_buf))
try:
num_sent = self._socket.send(self._send_buf)
MON_BYTES_SENT.inc(num_sent)
socklog.debug('Sent %d bytes via socket', num_sent)
if num_sent == 0:
socklog.warning('Socket disconnected (no data was sent)')
self._socket_disconnect()
else:
# total_sent += num_sent
self._send_buf = self._send_buf[num_sent:]
socklog.debug('After sending, buffer contains %d bytes',
len(self._send_buf))
except socket.error as exc:
if exc.errno != errno.EAGAIN:
socklog.exception(exc)
socklog.error(
'Got unexpected exception when sending: errno=%d: %s',
exc.errno, str(exc))
self._socket_disconnect()
def run(self) -> None:
'''
Main loop implementation. Set ``self._stop`` to `False` to have it terminate at the next iteration. This
function does not return unless an exception is not caught or ``self._stop`` is set to false. It calls the
cleanup function before returning.
'''
log.info('Starting main loop')
sockets_read: List[socket.socket] = list()
sockets_write: List[socket.socket] = list()
sockets_exc: List[socket.socket] = list()
while not self._stop:
sockets_read.clear()
sockets_write.clear()
sockets_exc.clear()
if not self._connected:
MON_DEVICE_UP.set(0)
if self._ts.last_contact_attempt < datetime.utcnow(
) - timedelta(seconds=60):
self._ts.last_contact_attempt = datetime.utcnow()
log.info('Time to attempt reconnection')
self._socket_connect()
elif self._ts.last_data_received < datetime.utcnow() - timedelta(
seconds=180):
socklog.warning(
'No data received for 180 seconds, disconnecting')
self._socket_disconnect()
else:
MON_DEVICE_UP.set(1)
sockets_read = [self._socket]
sockets_exc = [self._socket]
if self._ts.last_frame_sent <= datetime.utcnow() - timedelta(
seconds=1):
self._ts.last_frame_sent = datetime.utcnow()
# TODO change to request "the next" OID and enforce a limit here
# while i < 5:
# next_frame = self._device_manager.next_frame_to_send()
# MON_FRAMES_SENT.inc()
# # done in next_frame: next_frame.in_flight = True
# self._send_buf += next_frame.payload()
self._send_buf += self._device_manager.payloads()
# print(f'send_buf: {self._send_buf.hex()}')
if len(self._send_buf) > 0:
sockets_write = [self._socket]
try:
sock_readable, sock_writable, sock_exceptions = select.select(
sockets_read, sockets_write, sockets_exc, 1)
except KeyboardInterrupt:
# this is reached when someone presses Ctrl+c at the terminal
log.info('Got keyboard interrupt, shutting down')
self._stop = True
if self._socket in sock_exceptions:
socklog.warning(
'Got socket exception from select(), disconnecting')
self._socket_disconnect()
sockets_read.clear()
sockets_write.clear()
sockets_exc.clear()
continue
if self._socket in sock_readable:
self._handle_socket_read()
if self._socket in sock_writable and self._connected:
self._handle_socket_writable()
if len(self._recv_buf) > 0:
self._ts.last_data_received = datetime.utcnow()
self._handle_received_data()
if self._ts.last_influx_collect < datetime.utcnow() - timedelta(
seconds=5):
self._ts.last_influx_collect = datetime.utcnow()
self._device_manager.collect_influx(self._influx)
if self._ts.last_influx_flush < datetime.utcnow() - timedelta(
seconds=5):
self._ts.last_influx_flush = datetime.utcnow()
self._influx.flush()
log.info('End main loop, shutting down')
if HAVE_SYSTEMD:
systemd.daemon.notify('STOPPING=1')
self.cleanup()
def _handle_received_data(self) -> None:
while len(self._recv_buf) > 0:
if not self._current_frame:
self._current_frame = ReceiveFrame()
try:
consumed = self._current_frame.consume(self._recv_buf)
except FrameCRCMismatch as exc:
framelog.warning(
'CRC mismatch received, consumed %d bytes. Got %s but calculated %s',
exc.consumed_bytes, exc.received_crc, exc.calculated_crc)
self._current_frame = None
consumed = exc.consumed_bytes
MON_DECODE_ERROR.labels('crc').inc()
except InvalidCommand as exc:
framelog.warning(
'Invalid command 0x%x received, consumed %d bytes',
exc.command, exc.consumed_bytes)
self._current_frame = None
consumed = exc.consumed_bytes
MON_DECODE_ERROR.labels('command').inc()
except FrameLengthExceeded as exc:
framelog.warning(
'Frame consumed more than its advertised length, dropping')
self._current_frame = None
consumed = exc.consumed_bytes
MON_DECODE_ERROR.labels('length').inc()
if self._current_frame:
if self._current_frame.complete():
framelog.debug('Frame complete, consumed %d bytes',
consumed)
MON_FRAMES_RECEIVED.inc()
# frame complete
self._device_manager.on_frame(self._current_frame)
self._current_frame = None
else:
framelog.debug(
'Frame consumed %d bytes, not complete. id: 0x%x, length: %d, command: %02x',
consumed, self._current_frame.id,
self._current_frame.frame_length,
self._current_frame.command)
# filter frames that are broken, invalid or not of interest.
# test 1: unsupported frames (plant communication) and commands we're not interested in
if self._current_frame.command != Command._NONE: # pylint: disable=protected-access
# filter frame types we are not interested in as early as possible
if Command.is_plant(self._current_frame.command):
framelog.warning(
'Received plant command %s (0x%x), not supporting these, aborting frame',
self._current_frame.command.name,
self._current_frame.command)
self._current_frame = None
elif self._current_frame.command not in (
Command.RESPONSE, Command.LONG_RESPONSE):
framelog.warning(
'Received non-response command %s (0x%x), aborting frame',
self._current_frame.command.name,
self._current_frame.command)
self._current_frame = None
if self._current_frame and self._current_frame.id > 0:
try:
dtype = R.get_by_id(
self._current_frame.id).response_data_type
except KeyError:
# test 2: OID has been parsed (>0) and is not in REGISTRY
framelog.warning(
'Incomplete frame has unknown oid 0x%X, aborting frame',
self._current_frame.id)
self._current_frame = None
# test 3: try to find frames that are advertising extensive lengths for their type
else:
if dtype in (DataType.UINT8, DataType.INT8,
DataType.UINT16, DataType.INT16,
DataType.UINT32, DataType.INT32,
DataType.FLOAT):
if self._current_frame.frame_length > 30:
# max frame size for these types is 18 (PLANT frames with float). Give it some
# leeway to account for previous InvalidCommands that only consumed two bytes.
framelog.warning(
'Numbers frame is suspiciously long (length %d > 30), aborting '
'frame and skipping 2 bytes ahead',
self._current_frame.frame_length)
self._current_frame = None
consumed = 2
elif self._current_frame.consumed_bytes > 30:
# frame has consumed way too much data
framelog.warning(
'Numbers frame consumed suspicious amounts of data (%d > 30), '
'aborting frame and skipping 2 bytes ahead',
self._current_frame.consumed_bytes)
self._current_frame = None
consumed = 2
elif dtype == DataType.STRING and not Command.is_long(self._current_frame.command) and \
self._current_frame.frame_length > 251:
# long replies are allowed to return more than 251 bytes
framelog.warning(
'String frame is suspiciously long (%s > 251 and not LONG command), '
'aborting frame and skipping 2 bytes ahead',
self._current_frame.frame_length)
self._current_frame = None
consumed = 2
# not checking for types we aren't using (yet): time series and event table
self._recv_buf = self._recv_buf[consumed:]
def _handle_received_data(self) -> None:
while len(self._recv_buf) > 0:
if not self._current_frame:
self._current_frame = ReceiveFrame()
try:
consumed = self._current_frame.consume(self._recv_buf)
except FrameCRCMismatch as exc:
framelog.warning(
'CRC mismatch received, consumed %d bytes. Got %s but calculated %s',
exc.consumed_bytes, exc.received_crc, exc.calculated_crc)
self._current_frame = None
consumed = exc.consumed_bytes
MON_DECODE_ERROR.labels('crc').inc()
except InvalidCommand as exc:
framelog.warning(
'Invalid command 0x%x received, consumed %d bytes',
exc.command, exc.consumed_bytes)
self._current_frame = None
consumed = exc.consumed_bytes
MON_DECODE_ERROR.labels('command').inc()
except FrameLengthExceeded as exc:
framelog.warning(
'Frame consumed more than its advertised length, dropping')
self._current_frame = None
consumed = exc.consumed_bytes
MON_DECODE_ERROR.labels('length').inc()
if self._current_frame:
if self._current_frame.complete():
framelog.debug('Frame complete, consumed %d bytes',
consumed)
MON_FRAMES_RECEIVED.inc()
# frame complete
self._device_manager.on_frame(self._current_frame)
self._current_frame = None
else:
framelog.debug(
'Frame consumed %d bytes, not complete. id: 0x%x, length: %d, command: %02x',
consumed, self._current_frame.id,
self._current_frame.frame_length,
self._current_frame.command)
# filter frames that are broken, invalid or not of interest.
# test 1: unsupported frames (plant communication) and commands we're not interested in
if self._current_frame.command != Command._NONE: # pylint: disable=protected-access
# filter frame types we are not interested in as early as possible
if Command.is_plant(self._current_frame.command):
framelog.warning(
'Received plant command %s (0x%x), not supporting these, aborting frame',
self._current_frame.command.name,
self._current_frame.command)
self._current_frame = None
elif self._current_frame.command not in (
Command.RESPONSE, Command.LONG_RESPONSE):
framelog.warning(
'Received non-response command %s (0x%x), aborting frame',
self._current_frame.command.name,
self._current_frame.command)
self._current_frame = None
if self._current_frame and self._current_frame.id > 0:
try:
dtype = R.get_by_id(
self._current_frame.id).response_data_type
except KeyError:
# test 2: OID has been parsed (>0) and is not in REGISTRY
framelog.warning(
'Incomplete frame has unknown oid 0x%X, aborting frame',
self._current_frame.id)
self._current_frame = None
# test 3: try to find frames that are advertising extensive lengths for their type
else:
if dtype in (DataType.UINT8, DataType.INT8,
DataType.UINT16, DataType.INT16,
DataType.UINT32, DataType.INT32,
DataType.FLOAT):
if self._current_frame.frame_length > 30:
# max frame size for these types is 18 (PLANT frames with float). Give it some
# leeway to account for previous InvalidCommands that only consumed two bytes.
framelog.warning(
'Numbers frame is suspiciously long (length %d > 30), aborting '
'frame and skipping 2 bytes ahead',
self._current_frame.frame_length)
self._current_frame = None
consumed = 2
elif self._current_frame.consumed_bytes > 30:
# frame has consumed way too much data
framelog.warning(
'Numbers frame consumed suspicious amounts of data (%d > 30), '
'aborting frame and skipping 2 bytes ahead',
self._current_frame.consumed_bytes)
self._current_frame = None
consumed = 2
elif dtype == DataType.STRING and not Command.is_long(self._current_frame.command) and \
self._current_frame.frame_length > 251:
# long replies are allowed to return more than 251 bytes
framelog.warning(
'String frame is suspiciously long (%s > 251 and not LONG command), '
'aborting frame and skipping 2 bytes ahead',
self._current_frame.frame_length)
self._current_frame = None
consumed = 2
# not checking for types we aren't using (yet): time series and event table
self._recv_buf = self._recv_buf[consumed:]
def main():
packets = rdpcap(sys.argv[1])
streams = dict()
i = 0
pl = b''
for name, stream in packets.sessions().items():
print(f'Stream {i:4} {name} {stream} ', end='')
length = 0
streams[i] = dict()
for k in stream:
if TCP in k:
if len(k[TCP].payload) > 0:
if k[TCP].sport == 8899 or k[TCP].dport == 8899:
payload = bytes(k[TCP].payload)
# skip AT+ keepalive and app serial "protocol switch"
if payload == b'AT+\r' or payload == bytearray.fromhex(
'2b3ce1'):
continue
ptime = float(k.time)
if ptime not in streams[i]:
streams[i][ptime] = b''
streams[i][ptime] += payload
length += len(payload)
print(f'{length} bytes')
i += 1
frame = None
for _, data in streams.items():
for ts, pl in data.items():
while len(pl) > 0:
if not frame:
frame = ReceiveFrame()
try:
i = frame.consume(pl)
except FrameCRCMismatch as exc:
if frame.command == Command.EXTENSION:
print(
'Frame is an extension frame and we don\'t know how to parse it'
)
else:
print(
f'Frame {frame.id} CRC mismatch, got 0x{exc.received_crc:X} but calculated '
f'0x{exc.calculated_crc:X}. Buffer: {frame._buffer.hex()}'
)
print(pl[0:2].hex())
if pl[0:2] == bytearray.fromhex('002b'):
i = 2
else:
i = exc.consumed_bytes
pl = pl[i:]
print(f'frame consumed {i} bytes, {len(pl)} remaining')
if frame.complete():
if frame.id == 0:
print(
f'Frame complete: {frame} Buffer: {frame._buffer.hex()}'
)
else:
print(f'Frame complete: {frame}')
try:
rid = R.get_by_id(frame.id)
except KeyError:
print('Could not find ID in registry')
else:
if frame.command == Command.READ:
print(
f'Received read : {rid.index:4} {rid.name:40}')
else:
if frame.command in [
Command.RESPONSE, Command.LONG_RESPONSE
]:
dtype = rid.response_data_type
else:
dtype = rid.request_data_type
try:
value = decode_value(dtype, frame.data)
except struct.error as exc:
print(f'Could not decode value: {str(exc)}')
print(
f'Received reply: {rid.index:4} {rid.name:40} type: {dtype.name:17} value: '
'UNKNOWN')
except UnicodeDecodeError as exc:
print(f'Could not decode value: {str(exc)}')
print(
f'Received reply: {rid.index:4} {rid.name:40} type: {dtype.name:17} value: '
'UNKNOWN')
else:
if dtype == DataType.ENUM:
try:
value = rid.enum_str(value)
except RctClientException as exc:
print(
f'ENUM mapping failed: {str(exc)}')
except KeyError:
print('ENUM value out of bounds')
print(
f'Received reply: {rid.index:4} {rid.name:40} type: {dtype.name:17} value: '
f'{value}')
frame = None
def main():
''' Main program '''
packets = rdpcap(sys.argv[1])
streams = dict()
i = 0
for name, stream in packets.sessions().items():
print(f'Stream {i:4} {name} {stream} ', end='')
length = 0
streams[i] = dict()
for k in stream:
if TCP in k:
if len(k[TCP].payload) > 0:
if k[TCP].sport == 8899 or k[TCP].dport == 8899:
payload = bytes(k[TCP].payload)
# skip AT+ keepalive and app serial "protocol switch" '2b3ce1'
if payload in [b'AT+\r', b'+<\xe1']:
continue
ptime = float(k.time)
if ptime not in streams[i]:
streams[i][ptime] = b''
streams[i][ptime] += payload
length += len(payload)
print(f'{length} bytes')
i += 1
frame = None
sid = 0
for _, data in streams.items():
print(f'\nNEW STREAM #{sid}\n')
for timestamp, data_item in data.items():
print(f'NEW INPUT: {datetime.fromtimestamp(timestamp):%Y-%m-%d %H:%M:%S.%f} | {data_item.hex()}')
# frames should not cross segments (though it may be valid, but the devices haven't been observed doing
# that). Sometimes, the device sends invalid data with a very high length field, causing the code to read
# way byond the end of the actual data, causing it to miss frames until its length is satisfied. This way,
# if the next segment starts with the typical 0x002b used by the devices, the current frame is dropped.
# This way only on segment is lost.
if frame and data_item[0:2] == b'\0+':
print('Frame not complete at segment start, starting new frame.')
print(f'command: {frame.command}, length: {frame.frame_length}, oid: 0x{frame.id:X}')
frame = None
while len(data_item) > 0:
if not frame:
frame = ReceiveFrame()
try:
i = frame.consume(data_item)
except InvalidCommand as exc:
if frame.command == Command.EXTENSION:
print('Frame is an extension frame and we don\'t know how to parse it')
else:
print(f'Invalid command 0x{exc.command:x} received after consuming {exc.consumed_bytes} bytes')
i = exc.consumed_bytes
except FrameCRCMismatch as exc:
print(f'CRC mismatch, got 0x{exc.received_crc:X} but calculated '
f'0x{exc.calculated_crc:X}. Buffer: {frame._buffer.hex()}')
i = exc.consumed_bytes
except struct.error as exc:
print(f'skipping 2 bytes ahead as struct could not unpack: {str(exc)}')
i = 2
frame = ReceiveFrame()
data_item = data_item[i:]
print(f'frame consumed {i} bytes, {len(data_item)} remaining')
if frame.complete():
if frame.id == 0:
print(f'Frame complete: {frame} Buffer: {frame._buffer.hex()}')
else:
print(f'Frame complete: {frame}')
try:
rid = R.get_by_id(frame.id)
except KeyError:
print('Could not find ID in registry')
else:
if frame.command == Command.READ:
print(f'Received read : {rid.name:40}')
else:
if frame.command in [Command.RESPONSE, Command.LONG_RESPONSE]:
dtype = rid.response_data_type
else:
dtype = rid.request_data_type
is_write = frame.command in [Command.WRITE, Command.LONG_WRITE]
try:
value = decode_value(dtype, frame.data)
except (struct.error, UnicodeDecodeError) as exc:
print(f'Could not decode value: {str(exc)}')
if is_write:
print(f'Received write : {rid.name:40} type: {dtype.name:17} value: UNKNOWN')
else:
print(f'Received reply : {rid.name:40} type: {dtype.name:17} value: UNKNOWN')
except KeyError:
print('Could not decode unknown type')
if is_write:
print(f'Received write : {rid.name:40} value: 0x{frame.data.hex()}')
else:
print(f'Received reply : {rid.name:40} value: 0x{frame.data.hex()}')
else:
if dtype == DataType.ENUM:
try:
value = rid.enum_str(value)
except RctClientException as exc:
print(f'ENUM mapping failed: {str(exc)}')
except KeyError:
print('ENUM value out of bounds')
if is_write:
print(f'Received write : {rid.name:40} type: {dtype.name:17} value: {value}')
else:
print(f'Received reply : {rid.name:40} type: {dtype.name:17} value: {value}')
frame = None
print()
print('END OF INPUT-SEGMENT')
sid += 1
async def _write_object(self, reader: StreamReader, writer: StreamWriter,
object_id: int, value):
oinfo = REGISTRY.get_by_id(object_id)
object_name = oinfo.name
payload = encode_value(oinfo.request_data_type, value)
send_command_frame = SendFrame(command=Command.WRITE,
id=object_id,
payload=payload)
self.logger.debug(
"Writing RCT Power data (%s) for object %x (%s)...",
str(value),
object_id,
object_name,
)
request_time = datetime.now()
try:
async with async_timeout.timeout(READ_TIMEOUT):
await writer.drain()
writer.write(send_command_frame.data)
# loop until we return or time out
while True:
response_frame = ReceiveFrame()
while not response_frame.complete() and not reader.at_eof(
):
raw_response = await reader.read(1)
if len(raw_response) > 0:
response_frame.consume(raw_response)
if response_frame.complete():
response_object_info = REGISTRY.get_by_id(
response_frame.id)
data_type = response_object_info.response_data_type
received_object_name = response_object_info.name
# ignore, if this is not the answer to the latest request
if object_id != response_frame.id:
self.logger.debug(
"Mismatch of requested and received object ids: requested %x (%s), but received %x (%s)",
object_id,
object_name,
response_frame.id,
received_object_name,
)
continue
decoded_value: Union[
bool, bytes, float, int, str, Tuple[datetime,
Dict[datetime,
int]],
Tuple[datetime,
Dict[datetime,
EventEntry]], ] = decode_value(
data_type,
response_frame.data) # type: ignore
self.logger.debug(
"Decoded data for object %x (%s): %s",
response_frame.id,
received_object_name,
decoded_value,
)
return ValidApiResponse(
object_id=object_id,
object_name=object_name,
time=request_time,
value=decoded_value,
)
else:
self.logger.debug(
"Error decoding object %x (%s): %s",
object_id,
object_name,
response_frame.data,
)
return InvalidApiResponse(
object_id=object_id,
object_name=object_name,
time=request_time,
cause="INCOMPLETE",
)
except TimeoutError as exc:
self.logger.debug("Error reading object %x (%s): %s", object_id,
object_name, str(exc))
return InvalidApiResponse(
object_id=object_id,
object_name=object_name,
time=request_time,
cause="OBJECT_READ_TIMEOUT",
)
except FrameCRCMismatch as exc:
self.logger.debug("Error reading object %x (%s): %s", object_id,
object_name, str(exc))
return InvalidApiResponse(
object_id=object_id,
object_name=object_name,
time=request_time,
cause="CRC_ERROR",
)
except FrameLengthExceeded as exc:
self.logger.debug("Error reading object %x (%s): %s", object_id,
object_name, str(exc))
return InvalidApiResponse(
object_id=object_id,
object_name=object_name,
time=request_time,
cause="FRAME_LENGTH_EXCEEDED",
)
except InvalidCommand as exc:
self.logger.debug("Error reading object %x (%s): %s", object_id,
object_name, str(exc))
return InvalidApiResponse(
object_id=object_id,
object_name=object_name,
time=request_time,
cause="INVALID_COMMAND",
)
except struct.error as exc:
self.logger.debug("Error reading object %x (%s): %s", object_id,
object_name, str(exc))
return InvalidApiResponse(
object_id=object_id,
object_name=object_name,
time=request_time,
cause="PARSING_ERROR",
)
except Exception as exc:
self.logger.debug("Error reading object %x (%s): %s", object_id,
object_name, str(exc))
return InvalidApiResponse(
object_id=object_id,
object_name=object_name,
time=request_time,
cause="UNKNOWN_ERROR",
)