port: print sync/follow-up mismatch events

ptp4l is too silent when receiving, for whatever reason, out of order
messages. If the reordering is persistent (which is either a broken
network, or a broken kernel), the behavior looks like a complete
synchronization stall, since the application is designed to never
attempt to recover from such a condition.

At least save some people some debugging hours and print when the
application reaches this code path. Since it's a debugging tool, we
don't want to create false alarms when the occasional packet gets
reordered in a production system, but have this information readily
available when the program's log level is set to debug, instead of
having users fish for it with code instrumentation.

[ RC - corrected printf format for sequence id. ]

Signed-off-by: Vladimir Oltean <olteanv@gmail.com>
Signed-off-by: Richard Cochran <richardcochran@gmail.com>
master
Vladimir Oltean 2020-06-15 18:23:21 +03:00 committed by Richard Cochran
parent 5cca24bc07
commit bf0a644b99
1 changed files with 21 additions and 0 deletions

21
port.c
View File

@ -1215,6 +1215,23 @@ static void port_synchronize(struct port *p,
} }
} }
static void port_syfufsm_print_mismatch(struct port *p, enum syfu_event event,
struct ptp_message *m)
{
int expected_msgtype;
if (event == SYNC_MISMATCH)
expected_msgtype = FOLLOW_UP;
else
expected_msgtype = SYNC;
pr_debug("port %hu: have %s %hu, expecting %s but got %s %hu, dropping",
portnum(p), msg_type_string(msg_type(p->last_syncfup)),
p->last_syncfup->header.sequenceId,
msg_type_string(expected_msgtype),
msg_type_string(msg_type(m)), m->header.sequenceId);
}
/* /*
* Handle out of order packets. The network stack might * Handle out of order packets. The network stack might
* provide the follow up _before_ the sync message. After all, * provide the follow up _before_ the sync message. After all,
@ -1249,6 +1266,7 @@ static void port_syfufsm(struct port *p, enum syfu_event event,
case SF_HAVE_SYNC: case SF_HAVE_SYNC:
switch (event) { switch (event) {
case SYNC_MISMATCH: case SYNC_MISMATCH:
port_syfufsm_print_mismatch(p, event, m);
msg_put(p->last_syncfup); msg_put(p->last_syncfup);
msg_get(m); msg_get(m);
p->last_syncfup = m; p->last_syncfup = m;
@ -1256,6 +1274,7 @@ static void port_syfufsm(struct port *p, enum syfu_event event,
case SYNC_MATCH: case SYNC_MATCH:
break; break;
case FUP_MISMATCH: case FUP_MISMATCH:
port_syfufsm_print_mismatch(p, event, m);
msg_put(p->last_syncfup); msg_put(p->last_syncfup);
msg_get(m); msg_get(m);
p->last_syncfup = m; p->last_syncfup = m;
@ -1277,6 +1296,7 @@ static void port_syfufsm(struct port *p, enum syfu_event event,
case SF_HAVE_FUP: case SF_HAVE_FUP:
switch (event) { switch (event) {
case SYNC_MISMATCH: case SYNC_MISMATCH:
port_syfufsm_print_mismatch(p, event, m);
msg_put(p->last_syncfup); msg_put(p->last_syncfup);
msg_get(m); msg_get(m);
p->last_syncfup = m; p->last_syncfup = m;
@ -1293,6 +1313,7 @@ static void port_syfufsm(struct port *p, enum syfu_event event,
p->syfu = SF_EMPTY; p->syfu = SF_EMPTY;
break; break;
case FUP_MISMATCH: case FUP_MISMATCH:
port_syfufsm_print_mismatch(p, event, m);
msg_put(p->last_syncfup); msg_put(p->last_syncfup);
msg_get(m); msg_get(m);
p->last_syncfup = m; p->last_syncfup = m;