Mail.log filling up

With only 1 user on the system (me!) and a few mailboxes, my mail.log file is filling up with the following entries:

Feb 25 19:27:53 imap-login: Info: Login: user=xxxx@xxxxk.org, method=LOGIN, rip=127.0.0.1, lip=127.0.0.1, mpid=326, secured, session=<9iXDVjK8MJ1/AAAB>
Feb 25 19:27:53 imap(xxxx@xxxxk.org): Info: Logged out in=28 out=788
Feb 25 19:27:53 imap-login: Info: Login: user=xxxx@xxxxk.org, method=LOGIN, rip=127.0.0.1, lip=127.0.0.1, mpid=328, secured, session=<iVPFVjK8NJ1/AAAB>
Feb 25 19:27:53 imap(xxxx@xxxxk.org): Info: Logged out in=28 out=788
Feb 25 19:27:53 imap-login: Info: Login: user=xxxx@xxxxk.org, method=LOGIN, rip=127.0.0.1, lip=127.0.0.1, mpid=330, secured, session=<XUrHVjK8OJ1/AAAB>
Feb 25 19:27:53 imap(xxxx@xxxxk.org): Info: Logged out in=28 out=788

I saw a previous discussion where entering a new password seemed to eliminate the problem. I tried that and no luck.

I also saw that the login from 127.0.0.1 is an internal login process and to review the other logs. Not sure where to start with this?? Any ideas?? Is there a way to not log “info” entries? I have no other problems with the MIAB setup, although I have not scaled.

1 Like

I see this too. For me, it’s my mail.log.1 file that is filling up with these messages. It seems tied to using z-push (Exchange ActiveSync). If I turn off ActiveSync on my mobile devices, those messages go away. Z-push seems to be very chatty and checks for new mail every few seconds, resulting in those messages in the log.

My concern is that the log file mail.log.1 keeps growing (mine is currently 92MB). I don’t know why the system is actively writing to both mail.log.1 and mail.log. Normally log files ending in .1, .2, etc. are rotated by the logrotate utility and shouldn’t be written to. Not sure why it’s configured this way. Hopefully someone more knowledgeable will chime in.

You probably have a system script running that is connecting locally from within the server. You have other applications running?

Instead of ignoring it, the mail.log did give you a warning here, and that is to figure out which of your application is trying to login to your smtp.

I’m not sure how to turn off activesync on my mobile phone since I’m not using exchange server. Is there a setting for this on iphone??

Seems like z-push is a part of the problem. Could the “couldn’t open stream” comment from the z-push log be the source of the problem?

25/02/2021 12:40:37 [21195] [WARN] [#unknown] /usr/local/lib/z-push/backend/imap/imap.php:127 imap_open(): Couldn’t open stream {127.0.0.1:993/imap/ssl/norsh/novalidate-cert} (2)
25/02/2021 12:40:37 [21195] [ERROR] [#unknown] BackendIMAP->Logon(): can’t connect as user ‘xxxx@xxxxk.org’ on ‘{127.0.0.1:993/imap/ssl/norsh/novalidate-cert}’: IMAP Authentication cancelled
25/02/2021 12:40:37 [21195] [FATAL] [#unknown] Exception: (AuthenticationRequiredException) - Access denied. Username or password incorrect.
25/02/2021 12:40:37 [21195] [WARN] [#unknown] Unknown:0 Unknown: IMAP protocol error: Authentication aborted by client. (errflg=2) (8)
25/02/2021 12:40:37 [21195] [WARN] [#unknown] Unknown:0 Unknown: IMAP Authentication cancelled (errflg=2) (8)

Entries from localhost (127.0.0.1) are also logins from Roundcube. Roundcube refreshes every minute to check for new mail.

1 Like

No errors in my roundcube log…

I also tried the fixstates command for z-push based on another comment I found on the forum and there were no errors .

I think dovecot keeps the reference to the old logfile, even though it is renamed to mail.log.1 So only on restart of the process or on command it releases the logfile.
See Dovecot Logging — Dovecot documentation where dovecot is explicitly reopening the log file after logrotate: doveadm log reopen

To stop logging INFO entries you’ll have to take a look at rsyslog: /etc/rsyslog.d/50-default.conf Unfortunately I’m not sure about the exact config to use :frowning: You can start by replacing

mail.* -/var/log/mail.log

with

mail.notice -/var/log/mail.log

which should only log entries of level notice and higher (warn, error etc). However, I have not tested this, and I don’t know if there are any side effects to this, e.g. some log analysis that will fail because of this, or missed log entries.

Thanks for that. doveadm log find shows that the log file should indeed be /var/log/mail.log. After a reboot, dovecot uses that file; however, after the first logrotate operation, it uses mail.log.1 which is incorrect. Having a look at /etc/logrotate.d/rsyslog, which defines the logrotate behavior for mail.log, the line mentioned in the article you linked (doveadm log reopen) is not present. Running that command manually causes dovecot to use mail.log again as intended.

This should be flagged as a mailinabox bug. I’ll check the proper procedure to so do.

2 Likes

Yes, I’m running into this problem too.

I still haven’t solved the problem of continuous login / logout given I have only 1 (one) user on the system. This can’t be normal.

It is if your IMAP client logs in every minute to check for new emails.

But looking at the timestamps, you have something else going on. Without seeing the entire lines, it is not possible to guess at what though.

2 Likes

As I noted in one of my previous replies, I think it’s the Z-Push (Exchange Activesync) service. I see the same behavior using my iPhone (many logins every few seconds). Do you have any devices configured for Activesync?

As a test, I turned off my mailinabox account on my iPhone and those logins stopped. As @alento mentioned, you’ll still see periodic logins from any connected IMAP clients and the integrated Roundcube Web client as well, but less often. Z-Push apparently logs in frequently, presumably to support the Push functionality.

cinergi

1 Like

@cinergi I deleted my 2 “Exchange” accounts on my ipad and iphone prior to the screen shot below. Probably ~15 minutes before the time stamps. Also, I have a PC with MS Outlook and I just booted into it and I’m writing this note on it. The point being it couldn’t have been my Outlook PC client.

All of these logins are coming from 127.0.0.1. So it’s an internal process somewhere that is constantly logging in and out of Dovecot.

I’m at a loss of what to do and how to even turn off the info log level. Otherwise, MIAB is working well. I just don’t want to add other users if this is what’s going to potentially happen.

Sadly I don’t see anything unexpected there … but it is a mystery why you are logging in up 3 times a second.

Is 127.0.0.1 the webmail login?

Probably bugged by round cube or nextcloud. try restart php?

sudo service php7.2-fpm restart

I recently encountered some import bug on roundcube causing it to flood my logs and i fixed it by doing the same.

After deleting my ipad and iphone email account profiles on the MIAB and rebooting the MIAB server, logs were quite.

I added an IMAP account profile to my iphone for the MIAB account, and immediately starting getting the same blast of multiple logins per second.

5+ minutes later, the iphone is still “updating” my MIAB emails. I don’t have that many emails on my MIAB and I have high-speed internet, 200+ mbs.

I will go back to setting up an Exchange" account with the active sync. At least that works to download and sync my email.

There’s a bug in this system somewhere and given I am new to this with a fresh install of v 0.52, I am really surprised I’m the only one with this issue.

BTW… I’ve got all “checkmarks” on my MIAB “Status Checks” dashboard.

Tried restarting PHP and still getting multiple logins / sec.

Oh for your info, just checked my mail.log and I somehow got the same sort of flooding from 127.0.0.1…hmm it could have been due to some un-ended session from round cube / next cloud since it’s only for one of the active accounts, not all my mail accounts ( so z-push is ruled out. ).

Nevertheless, a simple restart of dovecot stopped all the re-logins.

sudo tail -f /var/log/mail.log //monitor your logs
sudo service dovecot stop //stop dovecot for a while, notice the login stops.
sudo service dovecot start //no more floods.

mail.log is now happy.

Before

After

Yes, what you posted is true. I recreated the steps and had the same behavior.

That said, I did a manual refresh of my ipad email accounts, and the behavior started up again.

There is a process from roundcube/nextcloud constantly banging on the dovecot imap server. It’s beyond my ability to fix