3

I have a very weird problem. Certain processes on my mail server, but not all, die periodically (every second month or so). A few of the process that die are:

  • ssh
  • dovecot
  • postfix

Processes that don't die are:

  • apache2

My system is running (Debian Wheezy):

$ uname -a
Linux hostname 3.2.0-4-amd64 #1 SMP Debian 3.2.41-2+deb7u2 x86_64 GNU/Linux

I have gone through /var/log files, but they all seem to be quite after the incident, which always happens at 6:25 in the morning.

First I thought it had something with the ntpdate daily cron to do, so I removed it and replaced it with ntpd which doesn't need cron instead. Did it help? No.

Then I thought it had something with syslogd to do. It seems that the processes who die are all trying to log using syslog. I googled around but I didn't find anyone else experiencing the same problem as me. It's really hard to find what the problem is when your logging mechanism doesn't work!

Here are all the log files that were modified around the incident time (6:25). There are no logs after that time, all logging activity ceased! Please take a look if you see something that might cause processes to die or logging to cease.

/var/log/syslog

Feb 16 06:25:01 hostname /USR/SBIN/CRON[32606]: (root) CMD (/usr/local/ispconfig/server/server.sh 2>&1 > /dev/null | while read line; do echo `/bin/date` "$line" >> /var/log/ispconfig/cron.log; done)
Feb 16 06:25:01 hostname /USR/SBIN/CRON[32607]: (getmail) CMD (/usr/local/bin/run-getmail.sh > /dev/null 2>> /dev/null)
Feb 16 06:25:01 hostname /USR/SBIN/CRON[32608]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))
Feb 16 06:25:02 hostname dovecot: imap-login: Disconnected (disconnected before greeting, waited 0 secs): user=<>, rip=127.0.0.1, lip=127.0.0.1, secured, session=<v9PKQn/y+gB/AAAB>
Feb 16 06:25:02 hostname postfix/smtpd[32647]: connect from localhost[127.0.0.1]
Feb 16 06:25:02 hostname milter-manager[2855]: [statistics] [milter][end][connect][stop][0.000481](37362): milter-greylist
Feb 16 06:25:02 hostname milter-manager[2855]: [statistics] [session][end][connect][accept][0.09962](37361)
Feb 16 06:25:02 hostname milter-manager[2855]: [statistics] [sessions][finished] 18681(+1) 0
Feb 16 06:25:02 hostname postfix/smtpd[32647]: lost connection after CONNECT from localhost[127.0.0.1]
Feb 16 06:25:02 hostname postfix/smtpd[32647]: disconnect from localhost[127.0.0.1]

/var/log/php5-fpm.log

[09-Feb-2014 06:25:07] NOTICE: error log file re-opened
[16-Feb-2014 06:25:06] NOTICE: Terminating ...
[16-Feb-2014 06:25:07] NOTICE: exiting, bye-bye!

/var/log/mail.log

Feb 16 06:25:02 hostname dovecot: imap-login: Disconnected (disconnected before greeting, waited 0 secs): user=<>, rip=127.0.0.1, lip=127.0.0.1, secured, session=<v9PKQn/y+gB/AAAB>
Feb 16 06:25:02 hostname postfix/smtpd[32647]: connect from localhost[127.0.0.1]
Feb 16 06:25:02 hostname milter-manager[2855]: [statistics] [milter][end][connect][stop][0.000481](37362): milter-greylist
Feb 16 06:25:02 hostname milter-manager[2855]: [statistics] [session][end][connect][accept][0.09962](37361)
Feb 16 06:25:02 hostname milter-manager[2855]: [statistics] [sessions][finished] 18681(+1) 0
Feb 16 06:25:02 hostname postfix/smtpd[32647]: lost connection after CONNECT from localhost[127.0.0.1]
Feb 16 06:25:02 hostname postfix/smtpd[32647]: disconnect from localhost[127.0.0.1]

/var/log/mail.info

Feb 16 06:25:02 hostname dovecot: imap-login: Disconnected (disconnected before greeting, waited 0 secs): user=<>, rip=127.0.0.1, lip=127.0.0.1, secured, session=<v9PKQn/y+gB/AAAB>
Feb 16 06:25:02 hostname postfix/smtpd[32647]: connect from localhost[127.0.0.1]
Feb 16 06:25:02 hostname milter-manager[2855]: [statistics] [milter][end][connect][stop][0.000481](37362): milter-greylist
Feb 16 06:25:02 hostname milter-manager[2855]: [statistics] [session][end][connect][accept][0.09962](37361)
Feb 16 06:25:02 hostname milter-manager[2855]: [statistics] [sessions][finished] 18681(+1) 0
Feb 16 06:25:02 hostname postfix/smtpd[32647]: lost connection after CONNECT from localhost[127.0.0.1]
Feb 16 06:25:02 hostname postfix/smtpd[32647]: disconnect from localhost[127.0.0.1]

/var/log/fail2ban.log

2014-02-16 06:25:06,899 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/error.log
2014-02-16 06:25:07,271 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/other_vhosts_access.log
2014-02-16 06:25:07,275 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/error.log
2014-02-16 06:25:07,279 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/error.log
2014-02-16 06:25:07,281 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/error.log
2014-02-16 06:25:07,283 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/other_vhosts_access.log
2014-02-16 06:25:07,269 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/other_vhosts_access.log
2014-02-16 06:25:07,287 fail2ban.server : INFO   Stopping all jails
2014-02-16 06:25:07,719 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/error.log
2014-02-16 06:25:08,461 fail2ban.jail   : INFO   Jail 'php-url-fopen' stopped
2014-02-16 06:25:08,595 fail2ban.actions: WARNING [apache-w00tw00t] Unban 178.32.243.78
2014-02-16 06:25:08,702 fail2ban.actions: WARNING [apache-w00tw00t] Unban 83.212.122.172
2014-02-16 06:25:09,270 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/error.log
2014-02-16 06:25:09,283 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/error.log
2014-02-16 06:25:09,285 fail2ban.jail   : INFO   Jail 'apache-w00tw00t' stopped
2014-02-16 06:25:09,298 fail2ban.filter : INFO   Log rotation detected for /var/log/apache2/error.log
2014-02-16 06:25:10,325 fail2ban.jail   : INFO   Jail 'apache-noscript' stopped
2014-02-16 06:25:11,361 fail2ban.jail   : INFO   Jail 'pam-generic' stopped
2014-02-16 06:25:12,330 fail2ban.jail   : INFO   Jail 'apache-badbots' stopped
2014-02-16 06:25:13,294 fail2ban.jail   : INFO   Jail 'apache-nohome' stopped
2014-02-16 06:25:14,326 fail2ban.jail   : INFO   Jail 'ssh-ddos' stopped
2014-02-16 06:25:14,827 fail2ban.jail   : INFO   Jail 'exim' stopped
2014-02-16 06:25:15,393 fail2ban.jail   : INFO   Jail 'webmin' stopped
2014-02-16 06:25:16,330 fail2ban.jail   : INFO   Jail 'apache' stopped
2014-02-16 06:25:17,296 fail2ban.jail   : INFO   Jail 'ssh' stopped
2014-02-16 06:25:18,285 fail2ban.jail   : INFO   Jail 'apache-overflows' stopped
2014-02-16 06:25:18,504 fail2ban.jail   : INFO   Jail 'dovecot' stopped
2014-02-16 06:25:19,333 fail2ban.jail   : INFO   Jail 'squirrelmail' stopped
2014-02-16 06:25:20,335 fail2ban.jail   : INFO   Jail 'apache-myadmin' stopped
2014-02-16 06:25:20,336 fail2ban.server : INFO   Exiting Fail2ban

/var/log/auth.log

Feb 16 06:25:01 hostname CRON[32604]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb 16 06:25:01 hostname CRON[32605]: pam_unix(cron:session): session opened for user getmail by (uid=0)
Feb 16 06:25:01 hostname CRON[32603]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb 16 06:25:01 hostname CRON[32605]: pam_unix(cron:session): session closed for user getmail
Feb 16 06:25:02 hostname CRON[32604]: pam_unix(cron:session): session closed for user root
4
  • Why do you have "ispconfig" installed on this machine? Feb 16, 2014 at 14:21
  • 1
    There's a very clear connection here between ispconfig and your dying processes. It happens exactly when ispconfig runs some cron jobs. You say you "need" it, but you probably don't actually need it, especially if you can't explain why. Feb 16, 2014 at 14:35
  • ispconfig runs the same cron jobs multiple times per day and the services don't die. It only happens very rarely (~every second month). I need ispconfig because I use it to configure my mail server accounts, web server accounts and other services. If I remove ispconfig I might as well make a fresh new install, which is what I want to avoid.
    – dimme
    Feb 16, 2014 at 14:39
  • 1
    It's doing something unique at 6:25 am every couple of months. I would inspect all the system cron jobs very closely. Feb 16, 2014 at 14:41

1 Answer 1

1

Firstly, your machine is doing something weird at 6:25 AM, every couple of months. I would take a look at ALL cron jobs.

Then, if nothing seems bogus, try correlating your problems with your kernel log. Issue dmesg and look for memory exhaustion problems, in this case the kernel WILL kill processes in order to avoid a situation that could generate a panic.

Also, look closely to /var/log/ispconfig/cron.log

If you suspect any unauthorized access to your box, inspect /usr/local/ispconfig/server/server.sh

P.S: I would also try to find out the first time this problem occurred, and then look for modifications made closely before that time

EDIT:

I noticed your last comment, it would be very useful to write a simple shell script to get memory usage when those jobs are running.

Example

#!/bin/sh
somefile="/your/file/path"
date >>$SomeFile
free -m >>$SomeFile

Edit cronjobs, and run this a couple of seconds BEFORE your memory consuming jobs and a couple AFTER, and then compare the results. This should help you decide whenever upgrade memory, modify software configuration, etc.

P.S: As you see this is a basic script, but as a starting point it is usable. You can improve it further

1
  • I believe that it was a memory exhaustion problem. I had "only" 1GB of RAM and no swap. I have since then configured a swap-file. It has been 10 days without a problem. I will wait 2-3 months before I get happy. Also I have inspected all cron jobs, haven't found anything suspicious so far.
    – dimme
    Feb 26, 2014 at 15:41

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .