[ClusterLabs] boothd-site/boothd-arbitrator: WARN: packet timestamp older than previous one

[Nicolas Huillard]

Hello,

I have many of those above syslog messages from boothd (counting all
servers, that's nearly 1 hundred per day).
All sites are synchronized using NTP, but according to source (https://
github.com/ClusterLabs/booth/blob/master/src/transport.c), that
specific messages isn't event tied to maxtimeskew (which I forced to
120s, because I wondered it it wrongly defaulted to 0s). This message
is output unless the new timestamp is larger (>) that the previous one
from the same site).
Adding debug on the arbitrator, it appears that every exchange between
the servers is made of at least 2 messages in each direction. Could it
be that two consecutive messages have the exact same timestamp, and
thus trigger the warning?
Maybe replacing ">" with ">=" could "fix" this ? (or adding a "no more
than N identical timestamps" counter on the receiving side, or adding a
message serial number on the sending side if consecutive timestamps are
identical, or sending with "max(previous_ts + 1, current_ts)" if there
are useless trailing zeros in timestamps).
My alternative would be to just ignore those syslog mesages...

Debug info is not really useful here, because date/hour is in the exact
same second each time. Here are 3 samples though (expire is set to
300):

1) syslog on siteA vs. boothd debug on arbitrator:
Nov  6 09:50:53 siteA boothd-site: [5459]: WARN: [arbitratorIP]: packet timestamp older than previous one

Nov 06 09:50:53 arbitrator boothd-arbitrator: [9237]: debug: raft_answer:935: ticketA (Fllw/4/148993): got HrtB from [siteAIP]
Nov 06 09:50:53 arbitrator boothd-arbitrator: [9237]: debug: answer_HEARTBEAT:331: ticketA (Fllw/4/148993): heartbeat from leader: [siteAIP], have [siteAIP]; term 4 vs 4
Nov 06 09:50:53 arbitrator boothd-arbitrator: [9237]: debug: become_follower:120: ticketA (Fllw/4/148999): state transition: Fllw -> Fllw
Nov 06 09:50:53 arbitrator boothd-arbitrator: [9237]: debug: answer_HEARTBEAT:355: ticketA (Fllw/4/148999): ticket leader set to [siteAIP]
Nov 06 09:50:53 arbitrator boothd-arbitrator: [9237]: debug: raft_answer:935: ticketA (Fllw/4/148987): got UpdE from [siteAIP]
Nov 06 09:50:53 arbitrator boothd-arbitrator: [9237]: debug: process_UPDATE:377: ticketA (Fllw/4/148986): leader [siteAIP] wants to update our ticket
Nov 06 09:50:53 arbitrator boothd-arbitrator: [9237]: debug: become_follower:120: ticketA (Fllw/4/298999): state transition: Fllw -> Fllw
Nov 06 09:50:53 arbitrator boothd-arbitrator: [9237]: debug: process_UPDATE:380: ticketA (Fllw/4/298999): ticket leader set to [siteAIP]
Nov 06 09:50:53 arbitrator boothd-arbitrator: [9237]: debug: log_next_wakeup:1182: ticketA (Fllw/4/298999): set ticket wakeup in 298.999

2) syslog on siteB vs. boothd debug on arbitrator:
Nov  6 09:52:21 siteB boothd-site: [16767]: WARN: [siteAIP]: packet timestamp older than previous one

Nov 06 09:52:21 arbitrator boothd-arbitrator: [9237]: debug: raft_answer:935: ticket-web (Fllw/3/148996): got HrtB from [siteBIP]
Nov 06 09:52:21 arbitrator boothd-arbitrator: [9237]: debug: answer_HEARTBEAT:331: ticket-web (Fllw/3/148996): heartbeat from leader: [siteBIP], have [siteBIP]; term 3 vs 3
Nov 06 09:52:21 arbitrator boothd-arbitrator: [9237]: debug: become_follower:120: ticket-web (Fllw/3/148999): state transition: Fllw -> Fllw
Nov 06 09:52:21 arbitrator boothd-arbitrator: [9237]: debug: answer_HEARTBEAT:355: ticket-web (Fllw/3/148999): ticket leader set to [siteBIP]
Nov 06 09:52:21 arbitrator boothd-arbitrator: [9237]: debug: raft_answer:935: ticket-web (Fllw/3/148987): got UpdE from [siteBIP]
Nov 06 09:52:21 arbitrator boothd-arbitrator: [9237]: debug: process_UPDATE:377: ticket-web (Fllw/3/148987): leader [siteBIP] wants to update our ticket
Nov 06 09:52:21 arbitrator boothd-arbitrator: [9237]: debug: become_follower:120: ticket-web (Fllw/3/298999): state transition: Fllw -> Fllw
Nov 06 09:52:21 arbitrator boothd-arbitrator: [9237]: debug: process_UPDATE:380: ticket-web (Fllw/3/298999): ticket leader set to [siteBIP]
Nov 06 09:52:21 arbitrator boothd-arbitrator: [9237]: debug: log_next_wakeup:1182: ticket-web (Fllw/3/298999): set ticket wakeup in 298.999

3) syslog on siteB vs. boothd debug on arbitrator:
Nov  6 10:32:21 siteB boothd-site: [16767]: WARN: [arbitratorIP]:
packet timestamp older than previous one

Nov 06 10:32:21 arbitrator boothd-arbitrator: [9237]: debug: raft_answer:935: ticket-web (Fllw/3/148997): got HrtB from [siteBIP]
Nov 06 10:32:21 arbitrator boothd-arbitrator: [9237]: debug: answer_HEARTBEAT:331: ticket-web (Fllw/3/148997): heartbeat from leader: [siteBIP], have [siteBIP]; term 3 vs 3
Nov 06 10:32:21 arbitrator boothd-arbitrator: [9237]: debug: become_follower:120: ticket-web (Fllw/3/148999): state transition: Fllw -> Fllw
Nov 06 10:32:21 arbitrator boothd-arbitrator: [9237]: debug: answer_HEARTBEAT:355: ticket-web (Fllw/3/148999): ticket leader set to [siteBIP]
Nov 06 10:32:21 arbitrator boothd-arbitrator: [9237]: debug: raft_answer:935: ticket-web (Fllw/3/148987): got UpdE from [siteBIP]
Nov 06 10:32:21 arbitrator boothd-arbitrator: [9237]: debug: process_UPDATE:377: ticket-web (Fllw/3/148987): leader [siteBIP] wants to update our ticket
Nov 06 10:32:21 arbitrator boothd-arbitrator: [9237]: debug: become_follower:120: ticket-web (Fllw/3/298999): state transition: Fllw -> Fllw
Nov 06 10:32:21 arbitrator boothd-arbitrator: [9237]: debug: process_UPDATE:380: ticket-web (Fllw/3/298999): ticket leader set to [siteBIP]
Nov 06 10:32:21 arbitrator boothd-arbitrator: [9237]: debug: log_next_wakeup:1182: ticket-web (Fllw/3/298999): set ticket wakeup in 298.999

-- 
Nicolas Huillard