From bf0a644b991b42aaa56b88e2f2180b7d81318c5c Mon Sep 17 00:00:00 2001 From: Vladimir Oltean Date: Mon, 15 Jun 2020 18:23:21 +0300 Subject: [PATCH] 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 Signed-off-by: Richard Cochran --- port.c | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/port.c b/port.c index 729cbd7..fa49663 100644 --- a/port.c +++ b/port.c @@ -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 * 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: switch (event) { case SYNC_MISMATCH: + port_syfufsm_print_mismatch(p, event, m); msg_put(p->last_syncfup); msg_get(m); p->last_syncfup = m; @@ -1256,6 +1274,7 @@ static void port_syfufsm(struct port *p, enum syfu_event event, case SYNC_MATCH: break; case FUP_MISMATCH: + port_syfufsm_print_mismatch(p, event, m); msg_put(p->last_syncfup); msg_get(m); p->last_syncfup = m; @@ -1277,6 +1296,7 @@ static void port_syfufsm(struct port *p, enum syfu_event event, case SF_HAVE_FUP: switch (event) { case SYNC_MISMATCH: + port_syfufsm_print_mismatch(p, event, m); msg_put(p->last_syncfup); msg_get(m); p->last_syncfup = m; @@ -1293,6 +1313,7 @@ static void port_syfufsm(struct port *p, enum syfu_event event, p->syfu = SF_EMPTY; break; case FUP_MISMATCH: + port_syfufsm_print_mismatch(p, event, m); msg_put(p->last_syncfup); msg_get(m); p->last_syncfup = m;