timestamp not incrementing

[js290]

Debian package got updated to 5.27.1. Noticed the timestamp format has changed, but also occasionally, the timestamp does not increment on subsequent check messages. Notice the repeating 2020-12-04T06:25:03-0500 below. It’s hard to tell if the timestamps are wrong, or if monit ran 10 checks in succession without waiting the configured timeout (default 5 seconds).

[2020-12-03T10:00:49-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 1/10)
[2020-12-03T10:00:54-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 2/10)

[2020-12-04T06:25:03-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 1/10)
[2020-12-04T06:25:03-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Connection reset by peer (attempt 2/10)
[2020-12-04T06:25:03-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- Connection refused (attempt 3/10)
[2020-12-04T06:25:03-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- Connection refused (attempt 4/10)
[2020-12-04T06:25:03-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- Connection refused (attempt 5/10)
[2020-12-04T06:25:03-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- Connection refused (attempt 6/10)
[2020-12-04T06:25:03-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- Connection refused (attempt 7/10)
[2020-12-04T06:25:03-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- Connection refused (attempt 8/10)
[2020-12-04T06:25:03-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- Connection refused (attempt 9/10)
[2020-12-04T06:25:03-0500] error    : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- Connection refused
[2020-12-04T06:25:03-0500] info     : 'pihole-FTL' start: '/usr/local/bin/pihole restartdns'
[2020-12-04T06:27:04-0500] info     : 'pihole-FTL' connection succeeded to [10.23.21.10]:53 [TCP/IP]

‌

[hauk]

This is not an error, the clue is in the attempt count in the logged string. I.e. if a connection failed Monit will retry if you have set the retry count in the test which I guess you have

[js290]

@hauk, the buggy behavior is the timestamps not incrementing on each subsequent retry not the retries themselves. Notice the first two lines where the timestamp increments by 5 seconds:

[2020-12-03T10:00:49-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 1/10)
[2020-12-03T10:00:54-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 2/10)

[js290]

Here’s an example of the timestamps incrementing by 5sec as expected, missing the info restart message, but the recovery message 2 minutes later.:

[2020-12-07T04:02:01-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 1/10)
[2020-12-07T04:02:06-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 2/10)
[2020-12-07T04:02:11-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 3/10)
[2020-12-07T04:02:16-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 4/10)
[2020-12-07T04:02:21-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 5/10)
[2020-12-07T04:02:26-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 6/10)
[2020-12-07T04:02:31-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 7/10)
[2020-12-07T04:02:36-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 8/10)
[2020-12-07T04:02:41-0500] warning  : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable (attempt 9/10)
[2020-12-07T04:02:46-0500] error    : 'pihole-FTL' failed protocol test [DNS] at [10.23.21.10]:53 [TCP/IP] -- DNS: error receiving response -- Resource temporarily unavailable
[2020-12-07T04:04:46-0500] info     : 'pihole-FTL' connection succeeded to [10.23.21.10]:53 [TCP/IP]

‌

[hauk]

If the connection fails immediately, a connection retry can happen within milliseconds, hence the log entry will have the same timestamp as log entry is only stamped with seconds resolution. Other times it seems the connection times out at 5 seconds which is the default connection timeout. Your log entry examples does not show anything out of the ordinary AFAICS