Loglist fails and its logs are being flushed

[ForNeVeR]

Today loglist wasn't started, and its logs are completely empty:

$ sudo journalctl -u loglist
-- No entries --

At the same time, cor-site logs are okay from 2016-12-12:

$ sudo journalctl -u cor-site
-- Logs begin at Mon 2016-12-12 16:35:01 EST, end at Thu 2016-12-15 05:25:22 EST. --
Dec 12 17:17:48 xmpp1 dotnet[8164]: info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
Dec 12 17:17:48 xmpp1 dotnet[8164]:       Request starting HTTP/1.1 GET http://codingteam.org.ru/robots.txt
...

After I restart loglist, the logs are okay, too:

$ sudo rm /opt/loglist/RUNNING_PID
$ sudo systemctl restart loglist
$ sudo journalctl -u loglist
-- Logs begin at Mon 2016-12-12 16:35:01 EST, end at Thu 2016-12-15 05:25:38 EST. --
Dec 15 05:20:35 xmpp1 systemd[1]: Stopped loglist.net site.
Dec 15 05:20:35 xmpp1 systemd[1]: Started loglist.net site.
Dec 15 05:20:36 xmpp1 loglist-jvm[16122]: Play server process ID is 16122
Dec 15 05:20:39 xmpp1 loglist-jvm[16122]: [info] play - database [default] connected at jdbc:postgresql:loglist?user=loglist&password=xxxx
Dec 15 05:20:40 xmpp1 loglist-jvm[16122]: [info] play - Application started (Prod)
Dec 15 05:20:40 xmpp1 loglist-jvm[16122]: [info] play - Listening for HTTP on /127.0.0.1:9000

So my conslusion is that we have two problems here:

1. LogList does stop sometimes, and we don't know the reason.
2. LogList logs are being cleaned or deleted by some unknown entity (or they are configured wrong).

[ForNeVeR]

$ sudo journalctl -u loglist
-- Logs begin at Fri 2016-12-16 12:25:01 EST, end at Mon 2016-12-19 04:05:28 EST. --
Dec 18 06:47:51 xmpp1 systemd[1]: loglist.service: Main process exited, code=killed, status=9/KILL
Dec 18 06:47:51 xmpp1 systemd[1]: loglist.service: Unit entered failed state.
Dec 18 06:47:51 xmpp1 systemd[1]: loglist.service: Failed with result 'signal'.

It seems logs are flushed again?

[ForNeVeR]

Alright, my current hypothesis will be the following:

• we have a memory leak in loglist
• OOM Killer kills it sometimes, and it can't be restarted due to RUNNING_PID problems loglist#139
• I have no idea who flushes the logs; probably they're too old and cleaned up automatically

I'll check the process memory state in a day or two to see if it leaks any memory.

[ForNeVeR]

Gotcha. Linux Kernel itself kills the loglist service.

Dec 25 06:43:56 xmpp1 systemd[1]: Starting Daily apt activities...
Dec 25 06:43:57 xmpp1 systemd[1]: Started Daily apt activities.
Dec 25 06:43:57 xmpp1 systemd[1]: apt-daily.timer: Adding 8h 20min 15.320647s random time.
Dec 25 06:43:57 xmpp1 systemd[1]: apt-daily.timer: Adding 5h 42min 13.571469s random time.
Dec 25 06:45:01 xmpp1 CRON[3171]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 25 06:45:01 xmpp1 CRON[3172]: pam_unix(cron:session): session opened for user cor-site by (uid=0)
Dec 25 06:45:01 xmpp1 CRON[3173]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 25 06:45:01 xmpp1 CRON[3171]: pam_unix(cron:session): session closed for user root
Dec 25 06:45:01 xmpp1 CRON[3174]: (cor-site) CMD (cd /opt/codingteam/cor-site && bash ./src/main/bash/check.sh 2>&1 >> $HOME/check.log)
Dec 25 06:45:01 xmpp1 CRON[3172]: (CRON) info (No MTA installed, discarding output)
Dec 25 06:45:01 xmpp1 CRON[3172]: pam_unix(cron:session): session closed for user cor-site
Dec 25 06:47:01 xmpp1 CRON[3184]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 25 06:47:01 xmpp1 CRON[3185]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.weekly ))
Dec 25 06:47:47 xmpp1 kernel: select 1 (systemd), adj 0, size 545, to kill
Dec 25 06:47:47 xmpp1 kernel: select 210 (systemd-journal), adj 0, size 715, to kill
Dec 25 06:47:47 xmpp1 kernel: select 2002 (postgres), adj 0, size 860, to kill
Dec 25 06:47:47 xmpp1 kernel: select 2004 (postgres), adj 0, size 1441, to kill
Dec 25 06:47:47 xmpp1 kernel: select 3043 (lua5.1), adj 0, size 2798, to kill
Dec 25 06:47:47 xmpp1 kernel: select 8164 (dotnet), adj 0, size 19177, to kill
Dec 25 06:47:47 xmpp1 kernel: select 16704 (java), adj 0, size 40590, to kill
Dec 25 06:47:47 xmpp1 kernel: send sigkill to 16704 (java), adj 0, size 40590
Dec 25 06:47:47 xmpp1 systemd[1]: loglist.service: Main process exited, code=killed, status=9/KILL
Dec 25 06:47:47 xmpp1 systemd[1]: loglist.service: Unit entered failed state.
Dec 25 06:47:47 xmpp1 systemd[1]: loglist.service: Failed with result 'signal'.
Dec 25 06:48:20 xmpp1 kernel: select 1 (systemd), adj 0, size 457, to kill
Dec 25 06:48:20 xmpp1 kernel: select 210 (systemd-journal), adj 0, size 670, to kill
Dec 25 06:48:20 xmpp1 kernel: select 2002 (postgres), adj 0, size 841, to kill
Dec 25 06:48:20 xmpp1 kernel: select 2004 (postgres), adj 0, size 1432, to kill
Dec 25 06:48:20 xmpp1 kernel: select 3043 (lua5.1), adj 0, size 2691, to kill
Dec 25 06:48:20 xmpp1 kernel: select 8164 (dotnet), adj 0, size 19139, to kill
Dec 25 06:48:20 xmpp1 kernel: select 3192 (update-apt-xapi), adj 0, size 77898, to kill
Dec 25 06:48:20 xmpp1 kernel: send sigkill to 3192 (update-apt-xapi), adj 0, size 77898
Dec 25 06:48:21 xmpp1 CRON[3184]: (CRON) info (No MTA installed, discarding output)
Dec 25 06:48:21 xmpp1 CRON[3184]: pam_unix(cron:session): session closed for user root
Dec 25 06:50:01 xmpp1 CRON[3235]: pam_unix(cron:session): session opened for user cor-site by (uid=0)

We'll need to check the service and the environment for memory leaks. Probably something else is leaking.

[ForNeVeR]

The situation is more or less clear. We're starting our LogList JVM with -Xmx384m -Xss512k. That means it'll eventually eat up to 384 MiB of RAM. Probably just tune this amount to 200.

I have no idea why doesn't it use the swap file; we have it enabled, but its usage is zero.

[ForNeVeR]

Changed -Xmx384m to -Xmx200m in loglist.conf. Need to evaluate it again.

[ForNeVeR]

Alright, it runs for a couple of days without incidents already. To be sure, I've executed some small tests using gobench and the server is still alive (and shows good characteristics under heavy load).

I believe that the stated problem is solved.