Hey All,
I noticed the other day my mail-in-a-box server was running slow. After some research, I found that the fail2ban service was running wild with processor time (97%). Stopping the service seems to resolve the issue completely, but obviously that is not ideal. Usage metrics seem to indicate this started about a week ago. Nothing was changed at that time that I am aware of.
Looking in the fail2ban logs really shows nothing interesting at all. The auth.log showed the normal batch of people trying to get in my ssh connection, though I have now moved it to another port to help cut down on issues there. This resulted in MiaB complaining, so now SSH runs on two ports, but port 22 is limited to just my home IP and the MiaB server itself so it passes checks. The second port is open for outside access. This change did not help fail2ban.
Back on topic however, there is no real craziness with connections anywhere on the server with one possible exception, z-push/imap. As I had mentioned in a past discussion z-push when used for activesync causes about 3 local connections per active user per second and spams the log files pretty badly. I am wondering if this rapid fire is upsetting fail2ban.
I am including some log excerpts and notes below for reference, and would love any thoughts others may have in helping to clean this up a bit.
Error when starting fail2ban service, have not yet had time to investigate it.
root@mail:/var/log# service fail2ban start
Starting authentication failure monitor fail2ban
WARNING 'ignoreregex' not defined in 'Definition'. Using default one: ''
mail.log spam (for three users results in about 280MB of log file per week, mostly duplicated in syslog as well)
Aug 8 10:43:37 mail dovecot: imap-login: Login: user=<user2@domain.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=30682, TLS, session=<OL3yxs0cswB/AAAB>
Aug 8 10:43:37 mail dovecot: imap(user2@domain.com): Disconnected: Logged out in=15 out=422
Aug 8 10:43:37 mail dovecot: imap-login: Login: user=<user2@domain.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=30684, TLS, session=<ObH0xs0ctQB/AAAB>
Aug 8 10:43:37 mail dovecot: imap(user2@domain.com): Disconnected: Logged out in=15 out=422
Aug 8 10:43:37 mail dovecot: imap-login: Login: user=<user2@domain.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=30686, TLS, session=<JYb2xs0ctwB/AAAB>
Aug 8 10:43:37 mail dovecot: imap(user2@domain.com): Disconnected: Logged out in=15 out=422
Aug 8 10:43:37 mail dovecot: imap-login: Login: user=<user2@domain.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=30688, TLS, session=<Ymr4xs0cuQB/AAAB>
Aug 8 10:43:37 mail dovecot: imap(user2@domain.com): Disconnected: Logged out in=15 out=422
Aug 8 10:43:37 mail dovecot: imap-login: Login: user=<user1@domain.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=30690, TLS, session=<QpcVx80cuwB/AAAB>
Aug 8 10:43:37 mail dovecot: imap(user1@domain.com): Disconnected: Logged out in=15 out=422
Aug 8 10:43:37 mail dovecot: imap-login: Login: user=<user1@domain.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=30692, TLS, session=<v5oXx80cvQB/AAAB>
Aug 8 10:43:37 mail dovecot: imap(user1@domain.com): Disconnected: Logged out in=15 out=422
Aug 8 10:43:37 mail dovecot: imap-login: Login: user=<user1@domain.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=30694, TLS, session=<z28Zx80cvwB/AAAB>
Aug 8 10:43:37 mail dovecot: imap(user1@domain.com): Disconnected: Logged out in=15 out=422
Aug 8 10:43:37 mail dovecot: imap-login: Login: user=<user1@domain.com>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=30696, TLS, session=<TEQbx80cwQB/AAAB>
Aug 8 10:43:37 mail dovecot: imap(user1@domain.com): Disconnected: Logged out in=15 out=422
fail2ban.log
2015-08-08 10:44:00,206 fail2ban.server : INFO Changed logging target to /var/log/fail2ban.log for Fail2ban v0.8.11
2015-08-08 10:44:00,207 fail2ban.jail : INFO Creating new jail 'ssh'
2015-08-08 10:44:00,249 fail2ban.jail : INFO Jail 'ssh' uses pyinotify
2015-08-08 10:44:00,272 fail2ban.jail : INFO Initiated 'pyinotify' backend
2015-08-08 10:44:00,274 fail2ban.filter : INFO Added logfile = /var/log/auth.log
2015-08-08 10:44:00,274 fail2ban.filter : INFO Set maxRetry = 6
2015-08-08 10:44:00,275 fail2ban.filter : INFO Set findtime = 600
2015-08-08 10:44:00,275 fail2ban.actions: INFO Set banTime = 600
2015-08-08 10:44:00,301 fail2ban.jail : INFO Creating new jail 'ssh-ddos'
2015-08-08 10:44:00,302 fail2ban.jail : INFO Jail 'ssh-ddos' uses pyinotify
2015-08-08 10:44:00,304 fail2ban.jail : INFO Initiated 'pyinotify' backend
2015-08-08 10:44:00,305 fail2ban.filter : INFO Added logfile = /var/log/auth.log
2015-08-08 10:44:00,305 fail2ban.filter : INFO Set maxRetry = 6
2015-08-08 10:44:00,306 fail2ban.filter : INFO Set findtime = 600
2015-08-08 10:44:00,306 fail2ban.actions: INFO Set banTime = 600
2015-08-08 10:44:00,311 fail2ban.jail : INFO Creating new jail 'sasl'
2015-08-08 10:44:00,311 fail2ban.jail : INFO Jail 'sasl' uses pyinotify
2015-08-08 10:44:00,314 fail2ban.jail : INFO Initiated 'pyinotify' backend
2015-08-08 10:44:00,315 fail2ban.filter : INFO Added logfile = /var/log/mail.log
2015-08-08 10:44:00,316 fail2ban.filter : INFO Set maxRetry = 3
2015-08-08 10:44:00,316 fail2ban.filter : INFO Set findtime = 600
2015-08-08 10:44:00,317 fail2ban.actions: INFO Set banTime = 600
2015-08-08 10:44:00,322 fail2ban.jail : INFO Creating new jail 'dovecot'
2015-08-08 10:44:00,322 fail2ban.jail : INFO Jail 'dovecot' uses pyinotify
2015-08-08 10:44:00,324 fail2ban.jail : INFO Initiated 'pyinotify' backend
2015-08-08 10:44:00,325 fail2ban.filter : INFO Added logfile = /var/log/mail.log
2015-08-08 10:44:00,326 fail2ban.filter : INFO Set maxRetry = 20
2015-08-08 10:44:00,326 fail2ban.filter : INFO Set findtime = 30
2015-08-08 10:44:00,327 fail2ban.actions: INFO Set banTime = 600
2015-08-08 10:44:00,334 fail2ban.jail : INFO Jail 'ssh' started
2015-08-08 10:44:00,336 fail2ban.jail : INFO Jail 'ssh-ddos' started
2015-08-08 10:44:00,337 fail2ban.jail : INFO Jail 'sasl' started
2015-08-08 10:44:00,338 fail2ban.jail : INFO Jail 'dovecot' started
z-push.log (never rotates, about 1.2GB in size now. we might want to consider getting this to rotate in the future. Also, I suspect this is what may be causing z-push to rapid fire the imap connections)
08/08/2015 11:00:40 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/meetings/ (8)
08/08/2015 11:00:40 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/contact_birthdays/ (8)
08/08/2015 11:00:40 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/personal/ (8)
08/08/2015 11:00:41 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/meetings/ (8)
08/08/2015 11:00:41 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/contact_birthdays/ (8)
08/08/2015 11:00:53 [28141] [WARN] [user2@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user2@domain.com/personal/ (8)
08/08/2015 11:00:53 [28141] [WARN] [user2@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user2@domain.com/contact_birthdays/ (8)
08/08/2015 11:00:53 [28141] [WARN] [user2@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user2@domain.com/personal/ (8)
08/08/2015 11:00:53 [28141] [WARN] [user2@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user2@domain.com/contact_birthdays/ (8)
08/08/2015 11:00:56 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/personal/ (8)
08/08/2015 11:00:56 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/meetings/ (8)
08/08/2015 11:00:56 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/contact_birthdays/ (8)
08/08/2015 11:00:56 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/personal/ (8)
08/08/2015 11:00:57 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/meetings/ (8)
08/08/2015 11:00:57 [25489] [WARN] [user1@domain.com] /usr/local/lib/z-push/include/z_caldav.php:908 Undefined index: /caldav/calendars/user1@domain.com/contact_birthdays/ (8)
z-push-error.log
07/08/2015 16:19:03 [18713] [ERROR] [user2@domain.com] BackendCardDAV->ChangesSink - Error getting the changes
07/08/2015 16:22:24 [18356] [ERROR] [user1@domain.com] BackendCardDAV->GetMessageList - Error getting the vcards in 'https://localhost:443/cloud/remote.php/carddav/addressbooks/user1@domain.com/contacts/': Woops, something's gone wrong! The CardDAV server returned the http status code 0.
07/08/2015 16:22:24 [18356] [ERROR] [user1@domain.com] BackendCardDAV->GetMessageList - Error getting the vcards
07/08/2015 16:22:24 [18356] [ERROR] [user1@domain.com] BackendCardDAV->GetMessageList - Error getting the vcards in 'https://localhost:443/cloud/remote.php/carddav/addressbooks/user1@domain.com/pl/': Woops, something's gone wrong! The CardDAV server returned the http status code 0.
07/08/2015 16:22:24 [18356] [ERROR] [user1@domain.com] BackendCardDAV->GetMessageList - Error getting the vcards
07/08/2015 16:57:27 [28364] [ERROR] [user1@domain.com] BackendCardDAV->GetGALSearchResults : Error in search Woops, something's gone wrong! The CardDAV server returned the http status code 405.
07/08/2015 16:57:27 [28364] [ERROR] [user1@domain.com] BackendCardDAV->GetGALSearchResults : Error in search query. Search aborted
07/08/2015 20:36:15 [22979] [ERROR] [user1@domain.com] BackendCardDAV->GetGALSearchResults : Error in search Woops, something's gone wrong! The CardDAV server returned the http status code 405.
07/08/2015 20:36:15 [22979] [ERROR] [user1@domain.com] BackendCardDAV->GetGALSearchResults : Error in search query. Search aborted
08/08/2015 06:29:57 [21666] [ERROR] [user1@domain.com] BackendCardDAV->ChangesSink - Error resyncing vcards: Woops, something's gone wrong! The CardDAV server returned the http status code 401.
08/08/2015 06:29:57 [21666] [ERROR] [user1@domain.com] BackendCardDAV->ChangesSink - Error getting the changes
08/08/2015 06:38:18 [26768] [ERROR] [user1@domain.com] BackendCardDAV->GetGALSearchResults : Error in search Woops, something's gone wrong! The CardDAV server returned the http status code 405.
08/08/2015 06:38:18 [26768] [ERROR] [user1@domain.com] BackendCardDAV->GetGALSearchResults : Error in search query. Search aborted