spid: handle a control stream containing log packets

I have an MD-01 controller running firmware 2.0.237 that is connected
to the computer via the COM0 DB9 port. When it receives a control
command to move the rotator, it prints debug logs to the serial output
that look like this:

  input:
    W3600\x0A4500\x0A\x2F\x20

  output:
    W\x03\x06\x00\x00\x0A\x04\x05\x01\x00\x0A\x20
    287925671: in motion\r\n
    287925673: Change motion state M0 to mcsStart\r\n
    287925678: GO  A 0.000000 0.000000 t ---\r\n
    287925680: in motion\r\n
    287925683: Change motion state M1 to mcsStart\r\n
    287925686: GO  E 90.000000 91.000000 t ---\r\n
    287925690: distance to go M0 too small. End.\r\n
    287925694: Change motion state M0 to mcsStopped\r\n
    287925698: Stop on motor 0 on angle 0.000000\r\n
    287925703: Change motion state M1 to mcsRunning\r\n
    287926610: distance to go M1 too small. End.\r\n
    287926613: Change motion state M1 to mcsStopped\r\n
    287926617: Stop on motor 1 on angle 90.000000\r\n

Note that the response frame is not necessarily present in an specific
order relative to the log messages: I have seen it come after the logs
as well. Because the current implementation just slurps up response
bytes without checking the framing or anything, as soon as any of this
log data enters the command stream, all subsequent commands will read
completely bogus responses.

Regardless of whether it's due to a misconfiguration, a weird artifact
of the firmware, or something more sinister, the MD-01 is awkwardly
interspersing its normal fixed-size-frame response with these
line-based log messages. As shown above, the log messages appear to be
consistently of the format <timestamp>: <message>\r\n, where
<timestamp> is some kind of integer timestamp (possibly relative to
unit boot) and <message> is an ASCII string.

Due to poor(?) design decisions by the protocol designers, the frame
start and end bytes are both printable ASCII characters ('W' and ' '
respectively) and the MD-01 response frame contains no other
validation information (such as a CRC), which means that a valid log
line could fairly easily contain a character sequence that is
indistinguishable from a valid response frame, without actually being
a valid response frame.

However, since the log messages appear to be reasonably strictly
structured, we can make a small number of assumptions that will allow
us to reliably separate response frames from log lines without having
to fall back on a heuristic-based parsing strategy. These assumptions
are as follows:

1. A log line will always begin with an ASCII character in the range
   [0-9], none of which are the frame start byte.
2. A log line will never contain \r\n in the middle of the line (i.e.
   multi-line log messages do not exist). This means a log "frame" will
   always be of the form [0-9]<anything>\r\n.
3. The controller will not emit a response frame in the middle of a log
   line.
4. The operating system's serial port read buffer is large enough that
   we won't lose data while accumulating log messages between commands.

Provided the above assumptions are true, a simple state machine can be
used to parse the response by treating the log lines as a different
type of frame. This could be made much more robust by applying
additional heuristics for specific packets (e.g. get_position has some
reasonably strict numerical bounds that could be used to sanity check
the contents of the reply frame).
pull/1349/head
torque 2023-07-31 23:27:56 -07:00
rodzic 46c0649b23
commit 470c71dd93
Nie znaleziono w bazie danych klucza dla tego podpisu
1 zmienionych plików z 143 dodań i 6 usunięć

Wyświetl plik

@ -39,6 +39,143 @@ struct spid_rot2prog_priv_data
int el_resolution;
};
enum spid_rot2prog_framemagic {
ROT2PROG_FRAME_START_BYTE = 'W',
ROT2PROG_FRAME_END_BYTE = ' ',
};
enum r2p_frame_parser_state {
ROT2PROG_PARSER_EXPECT_FRAME_START,
ROT2PROG_PARSER_EXPECT_CR,
ROT2PROG_PARSER_EXPECT_LF,
ROT2PROG_PARSER_EXPECT_FRAME_END,
};
static int read_r2p_frame(hamlib_port_t *port, unsigned char *rxbuffer,
size_t count)
{
// Some MD-01 firmware can apparently print debug messages to the same
// serial port that is used for the control protocol. This awkwardly
// intersperses the normal fixed-size frame response with a line-based
// logs. Theoretically, a valid response frame will not actually be emitted
// in the middle of a log message.
//
// Log messages are of the format <timestamp>: <message>\r\n, where
// <timestamp> is a unix-ish timestamp (inasmuch as it is an integer) and
// <message> is an ASCII string.
// Due to poor(?) design decisions by the protocol designers, the frame
// start and end bytes are both printable ASCII characters ('W' and ' '
// respectively) and the MD-01 response frame contains no other validation
// information (such as a CRC), which means that a valid log line can
// contain a character sequence that is indistinguishable from a valid
// response frame, without actually being a valid response frame.
// However, since the log messages appear to be reasonably strictly
// structured, we can make a small number of assumptions that will allow us
// to reliably separate response frames from log lines without having to
// fall back on a heuristic-based parsing strategy. These assumptions are
// as follows:
// 1. A log line will always begin with an ASCII character in the range
// [0-9], none of which are the frame start byte.
// 2. A log line will never contain \r\n in the middle of the line (i.e.
// multi-line log messages do not exist). This means a log "frame" will
// always be of the form [0-9]<anything>\r\n.
// 3. The controller will not emit a response frame in the middle of a log
// line.
// 4. The operating system's serial port read buffer is large enough that we
// won't lose data while accumulating log messages between commands.
// Provided the above assumptions are true, a simple state machine can be
// used to parse the response by treating the log lines as a different type
// of frame. This could be made much more robust by applying additional
// heuristics for specific packets (e.g. get_position has some reasonably
// strict numerical bounds that could be used to sanity check the contents
// of the reply frame).
int res = 0;
unsigned char peek = 0;
enum r2p_frame_parser_state pstate = ROT2PROG_PARSER_EXPECT_FRAME_START;
while (1) {
switch (pstate)
{
case ROT2PROG_PARSER_EXPECT_FRAME_START:
res = read_block(port, &peek, 1);
if (res < 0) return res;
switch (peek)
{
case '0':
case '1':
case '2':
case '3':
case '4':
case '5':
case '6':
case '7':
case '8':
case '9': {
pstate = ROT2PROG_PARSER_EXPECT_CR;
break;
}
case ROT2PROG_FRAME_START_BYTE: {
rxbuffer[0] = peek;
pstate = ROT2PROG_PARSER_EXPECT_FRAME_END;
break;
}
default: return -RIG_EPROTO;
}
break;
case ROT2PROG_PARSER_EXPECT_CR:
res = read_block(port, &peek, 1);
if (res < 0) return res;
if (peek == '\r') pstate = ROT2PROG_PARSER_EXPECT_LF;
break;
case ROT2PROG_PARSER_EXPECT_LF:
res = read_block(port, &peek, 1);
if (res < 0) return res;
if (peek == '\n')
{
pstate = ROT2PROG_PARSER_EXPECT_FRAME_START;
}
else
{
// we have stumbled across a \r that is not immediately
// followed by \n. We could assume this is a weirdly formed
// log message, but I think it makes more sense to be
// defensive here and assume it is invalid for this to
// happen.
return -RIG_EPROTO;
}
break;
case ROT2PROG_PARSER_EXPECT_FRAME_END:
// we already read the frame start byte
res = read_block(port, rxbuffer + 1, count - 1);
if (res < 0) return res;
if (rxbuffer[count - 1] != ROT2PROG_FRAME_END_BYTE)
{
return -RIG_EPROTO;
}
// lie about the number of bytes read
return res + 1;
default: return -RIG_EINTERNAL;
}
}
}
static int spid_rot_init(ROT *rot)
{
rig_debug(RIG_DEBUG_TRACE, "%s called\n", __func__);
@ -217,7 +354,7 @@ static int spid_rot2prog_rot_set_position(ROT *rot, azimuth_t az,
}
memset(cmdstr, 0, 12);
retval = read_block(&rs->rotport, (unsigned char *) cmdstr, 12);
retval = read_r2p_frame(&rs->rotport, (unsigned char *) cmdstr, 12);
}
while (retval < 0 && retry_read++ < rot->state.rotport.retry);
@ -264,7 +401,7 @@ static int spid_rot2prog_rot_set_position(ROT *rot, azimuth_t az,
do
{
retval = read_block(&rs->rotport, (unsigned char *) cmdstr, 12);
retval = read_r2p_frame(&rs->rotport, (unsigned char *) cmdstr, 12);
}
while ((retval < 0) && (retry_read++ < rot->state.rotport.retry));
}
@ -295,12 +432,12 @@ static int spid_rot_get_position(ROT *rot, azimuth_t *az, elevation_t *el)
if (rot->caps->rot_model == ROT_MODEL_SPID_ROT1PROG)
{
retval = read_block(&rs->rotport, (unsigned char *) posbuf, 5);
retval = read_r2p_frame(&rs->rotport, (unsigned char *) posbuf, 5);
}
else if (rot->caps->rot_model == ROT_MODEL_SPID_ROT2PROG ||
rot->caps->rot_model == ROT_MODEL_SPID_MD01_ROT2PROG)
{
retval = read_block(&rs->rotport, (unsigned char *) posbuf, 12);
retval = read_r2p_frame(&rs->rotport, (unsigned char *) posbuf, 12);
}
else
{
@ -367,12 +504,12 @@ static int spid_rot_stop(ROT *rot)
if (rot->caps->rot_model == ROT_MODEL_SPID_ROT1PROG)
{
retval = read_block(&rs->rotport, (unsigned char *) posbuf, 5);
retval = read_r2p_frame(&rs->rotport, (unsigned char *) posbuf, 5);
}
else if (rot->caps->rot_model == ROT_MODEL_SPID_ROT2PROG ||
rot->caps->rot_model == ROT_MODEL_SPID_MD01_ROT2PROG)
{
retval = read_block(&rs->rotport, (unsigned char *) posbuf, 12);
retval = read_r2p_frame(&rs->rotport, (unsigned char *) posbuf, 12);
}
}
while (retval < 0 && retry_read++ < rot->state.rotport.retry);