Strange System Outage

Home » CentOS » Strange System Outage
CentOS 15 Comments

I have a CentOS 7 system that I run a home grown python daemon on. I
run this same daemon on many other systems without any incident. On this one system the daemon seems to die or be killed every day around
3:30am. There is nothing it its log or any system logs that tell me why it dies. However in /var/log/messages every day I see something like this:

May 10 03:35:58 localhost pure-ftpd: (tool@xx.xx.xx.xx) [NOTICE]
/usrMay 10 03:57:57 localhost pure-ftpd: (tool@xx.xx.xx.xx) [NOTICE]
/usr/local/motor/data//B31/today/Images/CP0982436.00C_T6PH8_M0-R_1/T6PH8_M0-RN_TT6PH8_M0-R_P4_M1_FX-1_FY4_RR1_TR1_Ver3.jpg uploaded (90666 bytes, 8322.34KB/sec)

Notice how the message that was being printed at 03:35:58 is truncated mid-message and the next message is at 03:57:57 – there are always messages like around the time when the daemon dies. What could be going on here?

15 thoughts on - Strange System Outage

  • Am 10.05.2017 um 20:40 schrieb Larry Martell:

    Have you checked /etc/cron.daily/ for a cron job to restart the pure-ftpd service? /etc/cron.daily is called from /etc/anacrontab with some randomness so that the execution time varies.

    Alexander

  • How are you starting this daemon? Can you check the journal? Perhaps you’ll see more useful information than what you see in the syslogs?

  • I will check that, but the the pure-ftpd service is not my daemon that is getting killed – I was thinking the sudden stopping of the logging and subsequent time gap would be some sort of clue as to what is happing at that time.

    This is a system I do not have remote access to and it’s in Japan so I
    have to ask someone there to do things for me. Such a pain.

  • Oh, I was assuming that since you called it a daemon, it was actually something started automatically on boot, instead of something you manually started and it daemonized.

    If it is dying, are you logged in when its running? does it require you to be connected when its running? Maybe you should run it in a screen/tmux instead of daemonizing, so you can see stderr/stdout?

  • So on all the other systems that this is deployed on it is started automatically at boot and it’s controlled with service or systemctl. On this system because I do not have remote access and I do not have a very competent set of hands over there it was never set up to run as a service. So a user manually starts it by running the daemon script.

    This had been running on the machine like that for 8 months. The nightly crash just started on April 21 and has happened every day since.

    I am not 100% sure, but I think the user sus, starts the daemon process and then exits the su.

    No. The underlying script polls dirs looking for files, and loads data into a db.

    stdout and stderr are written to a file and when the daemon gets killed or dies or whatever happens to it, the output in the file abruptly stops, just like what I showed in the messages file.

  • Could you enable core dumps (ulimit -c unlimited) then after it has died, check for core files?

  • Thank you for that suggestion. I was able to get someone to run journalctl and send me the output and it was very interesting.

    First, there is logging going on continuously during the time when logging stops in /var/log/messages.

    Second, I see messages like this periodically:

    May 10 03:57:46 localhost.localdomain python[40222]: detected unhandled Python exception in
    ‘/usr/local/motor/motor/core/data/importer.py’
    May 10 03:57:46 localhost.localdomain abrt-server[40277]: Only 0MiB is available on /var/spool/abrt May 10 03:57:46 localhost.localdomain python[40222]: error sending data to ABRT daemon:

    This happens at various times of the day, and I do not think is related to the daemon crashing.

    But I did see one occurrence of this:

    May 09 03:49:35 localhost.localdomain python[14042]: detected unhandled Python exception in
    ‘/usr/local/motor/motor/core/data/importerd.py’
    May 09 03:49:35 localhost.localdomain abrt-server[22714]: Only 0MiB is available on /var/spool/abrt May 09 03:49:35 localhost.localdomain python[14042]: error sending data to ABRT daemon:

    And that is the daemon. But I only see that on this one day, and it crashes every day.

    And I see this type of message frequently throughout the day, every day:

    May 09 03:40:01 localhost.localdomain CROND[21447]: (motor) CMD
    (python /usr/local/motor/motor/scripts/image_mover.py -v1 -d
    /usr/local/motor/data > ~/last_image_move_log.txt)
    May 09 03:40:01 localhost.localdomain abrt-server[21453]: Only 0MiB is available on /var/spool/abrt May 09 03:40:01 localhost.localdomain python[21402]: error sending data to ABRT daemon:
    May 09 03:40:01 localhost.localdomain postfix/postdrop[21456]:
    warning: uid=0: No space left on device May 09 03:40:01 localhost.localdomain postfix/sendmail[21455]: fatal:
    root(0): queue file write error May 09 03:40:01 localhost.localdomain crond[2630]: postdrop: warning:
    uid=0: No space left on device May 09 03:40:01 localhost.localdomain crond[2630]: sendmail: fatal:
    root(0): queue file write error May 09 03:40:01 localhost.localdomain CROND[21443]: (root) MAIL
    (mailed 67 bytes of output but got status 0x004b)

    So it seems there is a space issue.

    And finally, coinciding with the time that the logging resumes in
    /var/log/messages I see this every day at that time:

    May 10 03:57:57 localhost.localdomain run-parts(/etc/cron.daily)[40293]: finished mlocate May 10 03:57:57 localhost.localdomain anacron[33406]: Job `cron.daily’
    terminated (mailing output)
    May 10 03:57:57 localhost.localdomain anacron[33406]: Normal exit (1 job run)

    I need to get my remote hands to get me more info.

  • Am 11.05.2017 um 20:30 schrieb Larry Martell:

    df -hT; df -i

    There is no space left on a vital partition / logical volume.

    “Only 0MiB is available on /var/spool/abrt”

    “postdrop: warning: uid=0: No space left on device”

    Alexander

  • Yes, I saw that and assumed that was the root cause of the issue. But when I had my guy over in Japan check he found that / had 15G (of 50)
    free. We did some more investigating and it seems that when mlocate runs the disk fills up and bad things happen. Why is that happening?
    It is because 15G free space is not enough? We ran a du and most of the space on / was used by /var/log (11G), and /var/lib/mlocate (20G). Can I disable mlocate and get rid of that large dir?

  • 20GB for mlocate is absolutely (and suspiciously) huge. You must have millions and millions of files on that server. If not, then there’s something wrong with mlocate. ‘mlocate’ can be removed unless you’re using it, there’s nothing else really dependent on it in CentOS. You’d need to really evaluate if someone else is using it on that server.

    ~ Brian Mathis
    @orev

  • Yes, we do have millions and millions of files (give or take a million or so). I am going to disable mlocate and remove the db and see if this fixes the issues we’ve been having.

  • An alternative to disabling mlocate would be to add the paths with huge numbers of files to PRUNEPATHS in /etc/updatedb.conf.

  • Since disabling mlocate and removing its db we have not had the daemon crash.

    Thanks to all who helped!