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

[Dejan Muhamedagic]

Hi,

On Mon, Nov 06, 2017 at 10:52:12AM +0100, Nicolas Huillard wrote:
> 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).

Right.

> 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?

The time resolution used should be sufficiently fine (i.e.
microseconds) so that the timestamps of two consecutive packets
are not the same. At least I'd expect that to be so. Now, what is
the actual time resolution on your platform? Maybe you should
check the clocksource? Still, if these are not some special kind
of computing platform, I suppose that there shouldn't be any
surprises.

How often are these messages logged, compared to the expire (or
renewal_freq) time?

Thanks,

Dejan

> 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
> 
> _______________________________________________
> Users mailing list: Users at clusterlabs.org
> http://lists.clusterlabs.org/mailman/listinfo/users
> 
> Project Home: http://www.clusterlabs.org
> Getting started: http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf
> Bugs: http://bugs.clusterlabs.org