Duplicate data

[CubicrootXYZ]

I encountered a strange behavior this night. At midnight UTC, which is also 2 am local time (at 3 am local time switched back to 2 am due to daylight saving, can not say which of the bove 2 am's it was) all the authlog metrics doubled their counters. At the same time the auth.log file rotated and was emptied.

I double checked theauth.log file and there are no authentications around that time.

Additional

Container logs:

2022/10/30 00:00:18 Re-opening moved/deleted file /var/log/auth.log ...
2022/10/30 00:00:18 Successfully reopened /var/log/auth.log

Prometheus:

[CubicrootXYZ]

I suspect either the daylight saving time switch confused some part, but all my software usually just runs in UTC. Or otherwise the auth.log rotation was not handled carefully by the exporter.

[woblerr]

Hi,
Did the situation happen again during the next log rotation?

[CubicrootXYZ]

Hi, Did the situation happen again during the next log rotation?

There was not yet a new log rotate. I will come back to you once there is one again.

[CubicrootXYZ]

I actually encountered today that the exporter is no longer updating it's data. There are clearly some authentications happening in the auth.log, but the exporter does not report any of them.

[CubicrootXYZ]

Restarted one of my 2 instances and some of the event metrics now dropped by a few thousand events (because they are no longer in the log file?).

[CubicrootXYZ]

Could be related to hpcloud/tail#189. This package is no longer supported tough and seems to be full of nasty bugs. There is a drop in replacement https://github.com/nxadm/tail.

[woblerr]

A few thoughts on the original question.

encountered a strange behavior this night. At midnight UTC, which is also 2 am local time (at 3 am local time switched back to 2 am due to daylight saving, can not say which of the bove 2 am's it was) all the authlog metrics doubled their counters. At the same time the auth.log file rotated and was emptied.

I double checked theauth.log file and there are no authentications around that time.

In the default settings logrotate for auth.log rotation (for example, in Ubuntu), the copytruncate parameter is missing. Thus, the file is recreated instead of being cleaned. This is displayed in the exporter logs.

Accordingly, when the file is recreated, it is re-read again. I may assume that due to the time switching, the file could be read 2 times, which led to duplication.

Restarted one of my 2 instances and some of the event metrics now dropped by a few thousand events (because they are no longer in the log file?).

Yes, the metric is a counter and, when the explorer is restarted, it is reset.

Could be related to hpcloud/tail#189. This package is no longer supported tough and seems to be full of nasty bugs. There is a drop in replacement https://github.com/nxadm/tail.

That makes sense, thank you!

[CubicrootXYZ]

This is displayed in the exporter logs.

I do not see anything there, this is the whole log output since I restarted it:

level=info ts=2022-11-01T16:16:01.623Z caller=authlog_exporter.go:89 msg="Starting exporter" name=authlog_exporter version=master-33a031f
level=info ts=2022-11-01T16:16:01.623Z caller=authlog_exporter.go:96 authlog=/var/log/auth.log mgs="Use port and HTTP endpoint" port=9991 endpoint=/metrics web-config=
level=info ts=2022-11-01T16:16:01.623Z caller=geo.go:44 msg="GeoIP database is not use"
level=info ts=2022-11-01T16:16:01.624Z caller=tls_config.go:195 msg="TLS is disabled." http2=false

Yes, the metric is a counter and, when the explorer is restarted, it is reset.

Totally makes sense, sorry that I did not think about that.

[woblerr]

I do not see anything there, this is the whole log output since I restarted it:

level=info ts=2022-11-01T16:16:01.623Z caller=authlog_exporter.go:89 msg="Starting exporter" name=authlog_exporter version=master-33a031f
level=info ts=2022-11-01T16:16:01.623Z caller=authlog_exporter.go:96 authlog=/var/log/auth.log mgs="Use port and HTTP endpoint" port=9991 endpoint=/metrics web-config=
level=info ts=2022-11-01T16:16:01.623Z caller=geo.go:44 msg="GeoIP database is not use"
level=info ts=2022-11-01T16:16:01.624Z caller=tls_config.go:195 msg="TLS is disabled." http2=false

At the same time, there is no rotation of the auth.log since the restart. Right?

Records of type

2022/10/30 00:00:18 Re-opening moved/deleted file /var/log/auth.log ...
2022/10/30 00:00:18 Successfully reopened /var/log/auth.log

should appear in the exporter's logs at the time of rotation auth.log, if the parameter copytruncate is not set in the logrotate config.

[CubicrootXYZ]

At the same time, there is no rotation of the auth.log since the restart. Right?

Correct

should appear in the exporter's logs at the time of rotation auth.log

Exactly what was in the logs when the rotate happened (see a few comments above).

[woblerr]

I tested the situation with log rotation. The standard settings for logrotate on ubuntu were used.

At the time of auth.log rotation, logrotate recreated the auth.log file.
There were entries in the exporter logs:

2022/11/06 00:00:22 Re-opening moved/deleted file /var/log/auth.log ...
2022/11/06 00:00:22 Successfully reopened /var/log/auth.log

At the same time, there was no doubling of metrics.

So, perhaps, the initial problem is connected with the transition to daylight saving time. With standard rotation, the exporter processes the file re-creation correctly.

Anyway, I updated dependencies for use revamped library nxadm/tail.

[CubicrootXYZ]

Thanks for investigating this further. Today there was another log rotate on one of my machines and the behavior was exactly the same, graphs doubled and no new events registered since then.

This is the complete log output of the container since it got started:

level=info ts=2022-11-02T20:46:47.635Z caller=authlog_exporter.go:89 msg="Starting exporter" name=authlog_exporter version=master-030ec5e
level=info ts=2022-11-02T20:46:47.635Z caller=authlog_exporter.go:96 authlog=/var/log/auth.log mgs="Use port and HTTP endpoint" port=9991 endpoint=/metrics web-config=
level=info ts=2022-11-02T20:46:47.635Z caller=geo.go:44 msg="GeoIP database is not use"
level=info ts=2022-11-02T20:46:47.635Z caller=tls_config.go:195 msg="TLS is disabled." http2=false
2022/11/06 00:00:20 Re-opening moved/deleted file /var/log/auth.log ...
2022/11/06 00:00:20 Successfully reopened /var/log/auth.log

I am running a quite fresh install of ubuntu 22.04.

I will update to the new version and we'll see if that fixes it.

Actually I am already running the newest version.