Warning message: Invalid timestamp in notify record

Body

Warning message: Invalid timestamp in notify record


This message can be seen when the TEMS tasks are running on systems with substantially different times.
ITM can handle a certain amount of time difference but not a lot of difference.

In this case the warnings were seen in the HUB ms logs,

in the <temsname>_ms_nnnnnnnn-0x.log :


2014/03/30 01:01:22.0000-B:kqmlog.cpp,779,"processARMeib::processRecs")
    Warning: Invalid timestamp in notify record: operation <F> id <>
    name <> timestamp <1140330020117001> user <> originnode <>


However in this case the messages were being seen on a FTO HUb pair and were filling up the logs.
 

 A number of other message in the logs allowed the issue to be traced through

:kqmibinf.cpp,1462,"getUTCdiff") local UTCdiff is <0> seconds
FTO states that this TEMS is zero hours away from UTC

and then this message showed

FTO states that the peer HUB is zero hours from UTC:

:kqmibinf.cpp,1462,"getUTCdiff") parent UTCdiff is <0> seconds

FTO also states that there no time difference between the two HUBS
(adjusted to UTC):

 :kqmibinf.cpp,1643,"getCMSTimeDiff") average CMS time difference is <0> seconds

Yet the timestamps from the peer HUB were one hour in the future:

  (2014/03/30
    01:01:22.0000-B:kqmlog.cpp,779,"processARMeib::processRecs")
    Warning: Invalid timestamp in notify record: operation <F> id <>
    name <> timestamp  user <> originnode <>

 

The timestamp "1140330020117001" equates to "2014/03/30 02:01:17.001".

These numbers  <1140330020117001> can be translated by removing the initial 1, then next 2 are the year, next 2 month , next 2 the day then the the rest are the time.

So the timestamp on the record was one hour in the future versus the current time.

With FTO machines the time is checked between the two machines to check if it matches.

The issue can happen due to the change in daylight savings
The TEMS computes the offset from UTC for itself and its peer when the TEMS starts and connects to its peer.
It then uses that offset to adjust the timestamps in records coming from the peer HUB.
When daylight savings occurs, as is the case here, the offset became off by an hour until the TEMS was recycled.

A restart of the standby HUB TEMS's  resolves the issue and no more warning messages are seen.

This can be done when needed as this is just a warning message and not causing any issue other than filling the logs.