fail2ban.datedetector gives wrong year by date-times, that are logged within invalid time-zone

[adrianrudnik]

Environment:

Fail2Ban v0.10.2
[x] Fail2Ban installed via OS/distribution mechanisms
[x] You have not applied any additional foreign patches to the codebase
[x] Some customizations were done to the configuration (provide details below is so)

The issue:

Nothing gets banned.

I did a preliminary check with fail2ban-regex /var/log/auth.log /etc/fail2ban/filter.d/sshd.conf and got the result Lines: 16964 lines, 0 ignored, 9022 matched, 7942 missed which seemed fine for me. Still nothing got banned, did not find anyhting in DEBUG mode, so I switched to HEAVYDEBUG mode.

The following entries catched my eye:

2018-06-06 10:57:29,753 fail2ban.datedetector   [25668]: Level 6   got time 1496753849.000000 for 'Jun  6 12:57:29' using template {^LN-BEG}(?:DAY )?MON Day %k:Minute:Second(?:\.Microseconds)?(?: ExYear)?
2018-06-06 10:57:29,753 fail2ban.filter         [25668]: HEAVY   Ignore line since time 1496753849.0 < 1528282649.7536376 - 1800

So the line got ignored because it is the wrong year I guess? The difference between the timestamps is exactly 31528800 which is a year. Not sure why the template converts "Jun 6 12:57:29" to 2017 instead of today.

The machine is configured to

root@edged ~ # cat /etc/timezone 
Etc/UTC
root@edged ~ # date
Mi 6. Jun 11:10:09 UTC 2018

Steps to reproduce

Maybe use the same timezone and set a matching log entry to the same date as given above? Only have this machine for tests sadly.

Expected behavior

Should ban.

Observed behavior

Did not ban.

Any additional information

Here is are some matching lines from my regex comparison:

|  Jun  6 13:11:50 edged sshd[6711]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=211.57.1.1 user=root
|  Jun  6 13:11:51 edged sshd[6610]: Failed password for root from 42.7.1.1 port 58593 ssh2
|  Jun  6 13:11:52 edged sshd[6711]: Failed password for root from 211.57.1.1 port 50441 ssh2
|  Jun  6 13:11:54 edged sshd[6610]: Failed password for root from 42.7.1.1 port 58593 ssh2

I remember that the machine blocked entries while NOT being configured to UTC, it remember it working yesterday when the machine was still on Europe/Berlin, but since the dpkg-reconfigure tzdata to Etc/UTC it stopped working I think.

Configuration, dump and another helpful excerpts

Any customizations done to /etc/fail2ban/ configuration

[DEFAULT]
ignoreip = 127.0.0.1/8

bantime = 1h
findtime = 30m
maxretry = 2

[sshd]
enabled = true

[nginx-http-auth]
enabled = true

[php-url-fopen]
enabled = true
logpath = %(nginx_access_log)s

[adrianrudnik]

Just confirmed that reconfiguring the machine back

root@edged ~ # cat /etc/timezone 
Europe/Berlin
root@edged ~ # date
Mi 6. Jun 13:29:32 CEST 2018

triggered all jails and banned correctly.

[sebres]

The machine is configured to Etc/UTC (Mi 6. Jun 11:10:09 UTC 2018)

Well, this looks like pretty good example for the TZ-issue.
Possibly as you configured it to UTC, you've not restarted several services (e. g. sshd and/or rsyslog, etc.), resp. this are configured to log within another time-zone (looks like CET).

Just see the dates, you've got in logs:

13:11:50 (logged from sshd, Jun  6 13:11:50 edged sshd[6711]) ... # looks like CET
# vs
10:57:29 (logged from F2B, 2018-06-06 10:57:29) # looks like GMT/UTC

The year is not present there (date-pattern without explicit year).
In this case fail2ban find the time from the future, and because it is impossible, fail2ban assumes the old entries (even from the last year).

We've already several duplicates like this #1959, #1804 (comment) etc.

Thus closed as incorrect.

[sebres]

BTW. Very good possibility to check TZ-issue without debugging:

 $ date
 Wed Jun  6 14:05:58 CEST 2018

-$ str='Jun  6 13:11:51 srv sshd[6610]: Failed password for root from 1.2.3.4 port 58593 ssh2'
+$ str='Jun  6 23:11:51 srv sshd[6610]: Failed password for root from 1.2.3.4 port 58593 ssh2'
 $ fail2ban-regex -v "$str" sshd | grep 1.2.3.4
-|      1.2.3.4  Wed Jun 06 13:11:51 2018
+|      1.2.3.4  Tue Jun 06 23:11:51 2017

[adrianrudnik]

Thanks for the feedback and help! Gonna try this and integrate it to the small setup script to make sure that does not happen again. Sadly ubuntu (or even debian) defaults to the datetime without year it seems for auth.log / syslog, might as well change that as a precaution.

[sebres]

You're welcome.
Well, the putting of the year alone does not really help.
Yes then it can not be mistakenly switched anymore, but the recognized time (if within invalid zone yet) can be still wrong (in this case can cause the deviation by now - findtime, so e. g. fail2ban could too early forget the failure, etc).
So be always careful with time-zones :)

[adrianrudnik]

Yeah, gotta put some more thoughts into it, because its roots are in the setup. I get minimal server, use ansible to correct any misconfigurations, restart services and so on, but that never leads to an actual restart so the tz problem escalates down to fail2ban. Gonna make the reboot mandatory. Just tried it again in a small vm and it worked after a reboot, and failed without one.

[sebres]

the tz problem escalates down to fail2ban.

Is rather a problem of rsyslog (or other logger that your services use). For example like rsyslog/rsyslog#424
Anyway, this is always service related, because if I remember me correctly, the systemd-journal follows the time zone changes in logs on the fly (however some system settings could cause the non-compliance of the change, especially some "dirty" hacks e. g. to improve perfomance, see for example How setting the TZ environment variable avoids thousands of system calls).

Gonna make the reboot mandatory.

I'm pretty sure it would be possibe without reboot.
For example, is the simple restart of rsyslog-service not helpfull by TZ-switch (service rsyslog restart)?