https://redmine.documentfoundation.org/https://redmine.documentfoundation.org/favicon.ico?16960560022015-01-07T10:36:32ZThe Document Foundation RedmineInfrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=36792015-01-07T10:36:32ZFlorian Effenbergerfloeff@documentfoundation.org
<ul></ul><p>Some ideas to debug:</p>
<ul>
<li><del>investigate top.log after crash to see if there are performance issues</del> -> update: done</li>
<li>do a daily reboot via cron to see if it's a memory leak</li>
<li><del>have monitoring in place to at least notify, ideally act when something happens</del> -> update: done, nothing suspicious it seems</li>
</ul> Infrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=37142015-01-10T11:35:31ZFlorian Effenbergerfloeff@documentfoundation.org
<ul></ul><p>Some more ideas from the admin meeting:</p>
<ul>
<li><del>apply the setterm script to ensure screen gets not blanked</del> -> update: done</li>
<li><del>set the kernel panic reboot timer via sysctl</del> -> update: done</li>
</ul> Infrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=38392015-01-13T20:48:58ZFlorian Effenbergerfloeff@documentfoundation.org
<ul></ul><p>top.log shortly after crash has been saved to ~floeff/top.log and ~floeff/top.log2, here are the extracts shortly before the crash:</p>
<pre>
top - 21:43:02 up 3 days, 1:52, 0 users, load average: 6.75, 7.79, 11.17
Tasks: 264 total, 8 running, 256 sleeping, 0 stopped, 0 zombie
%Cpu(s): 33.9 us, 3.6 sy, 0.0 ni, 61.1 id, 1.1 wa, 0.0 hi, 0.2 si, 0.0 st
KiB Mem: 4046684 total, 3122056 used, 924628 free, 39120 buffers
KiB Swap: 4190204 total, 234668 used, 3955536 free. 1341388 cached Mem
</pre>
<pre>
top - 18:52:01 up 6 days, 19:26, 0 users, load average: 9.04, 9.19, 9.31
Tasks: 244 total, 9 running, 235 sleeping, 0 stopped, 0 zombie
%Cpu(s): 39.2 us, 3.2 sy, 0.0 ni, 55.2 id, 2.2 wa, 0.0 hi, 0.2 si, 0.0 st
KiB Mem: 4046684 total, 3603176 used, 443508 free, 67532 buffers
KiB Swap: 4190204 total, 238584 used, 3951620 free. 1656852 cached Mem
</pre>
<p>Maybe a memory leak? However, 20 minutes before the crash it looks similar:</p>
<pre>
top - 18:27:01 up 6 days, 19:01, 0 users, load average: 7.93, 9.09, 9.98
Tasks: 245 total, 14 running, 231 sleeping, 0 stopped, 0 zombie
%Cpu(s): 39.1 us, 3.2 sy, 0.0 ni, 55.2 id, 2.2 wa, 0.0 hi, 0.2 si, 0.0 st
KiB Mem: 4046684 total, 3563504 used, 483180 free, 65836 buffers
KiB Swap: 4190204 total, 238644 used, 3951560 free. 1625924 cached Mem
</pre> Infrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=38402015-01-13T20:59:32ZFlorian Effenbergerfloeff@documentfoundation.org
<ul></ul><p>The syslog also looks rather unsusipcious:</p>
<pre>
Jan 13 21:23:01 vm158 CRON[6764]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:21:06 vm158 snmpd[5675]: message repeated 14 times: [ Connection from UDP: [redacted]:49320->[redacted]:161]
Jan 13 21:23:42 vm158 snmpd[5675]: Connection from UDP: [redacted]:54393->[redacted]:161
Jan 13 21:25:22 vm158 snmpd[5675]: Connection from UDP: [redacted]:35929->[redacted]:161
Jan 13 21:25:36 vm158 kernel: [264928.814514] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=40 TOS=0x00 PREC=0x00 TTL=240 ID=54321 PROTO=TCP SPT=53624 DPT=49154 WINDOW=65535 RES=0x00 SYN URGP=0
Jan 13 21:26:03 vm158 CRON[7079]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:26:57 vm158 kernel: [265009.811573] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=52 TOS=0x00 PREC=0x00 TTL=50 ID=61676 DF PROTO=TCP SPT=61808 DPT=25 WINDOW=65535 RES=0x00 SYN URGP=0
Jan 13 21:27:00 vm158 kernel: [265012.778292] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=52 TOS=0x00 PREC=0x00 TTL=50 ID=61956 DF PROTO=TCP SPT=61808 DPT=25 WINDOW=65535 RES=0x00 SYN URGP=0
Jan 13 21:27:01 vm158 CRON[7164]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:27:06 vm158 kernel: [265018.806769] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=52 TOS=0x00 PREC=0x00 TTL=50 ID=62510 DF PROTO=TCP SPT=61808 DPT=25 WINDOW=65535 RES=0x00 SYN URGP=0
Jan 13 21:28:01 vm158 CRON[7327]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:30:01 vm158 CRON[7560]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:30:16 vm158 kernel: [265208.860042] Peer redacted:49503/80 unexpectedly shrunk window 3219335626:3219373738 (repaired)
Jan 13 21:30:16 vm158 kernel: [265209.060112] Peer redacted:49491/80 unexpectedly shrunk window 4084028138:4084040474 (repaired)
Jan 13 21:30:17 vm158 kernel: [265209.372073] Peer redacted:49506/80 unexpectedly shrunk window 2495513151:2495537808 (repaired)
Jan 13 21:31:01 vm158 CRON[7642]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:25:22 vm158 snmpd[5675]: message repeated 24 times: [ Connection from UDP: [redacted]:35929->[redacted]:161]
Jan 13 21:31:06 vm158 snmpd[5675]: Connection from UDP: [redacted]:43382->[redacted]:161
Jan 13 21:32:01 vm158 CRON[7696]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:32:32 vm158 kernel: [265344.867580] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=60 TOS=0x00 PREC=0x00 TTL=50 ID=42483 DF PROTO=TCP SPT=35533 DPT=23 WINDOW=5808 RES=0x00 SYN URGP=0
Jan 13 21:32:35 vm158 kernel: [265347.866534] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=60 TOS=0x00 PREC=0x00 TTL=50 ID=42484 DF PROTO=TCP SPT=35533 DPT=23 WINDOW=5808 RES=0x00 SYN URGP=0
Jan 13 21:32:41 vm158 kernel: [265353.866495] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=60 TOS=0x00 PREC=0x00 TTL=50 ID=42485 DF PROTO=TCP SPT=35533 DPT=23 WINDOW=5808 RES=0x00 SYN URGP=0
Jan 13 21:33:01 vm158 CRON[7855]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:33:15 vm158 kernel: [265387.820707] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=60 TOS=0x00 PREC=0x00 TTL=58 ID=8368 DF PROTO=TCP SPT=39069 DPT=10000 WINDOW=5840 RES=0x00 SYN URGP=0
Jan 13 21:31:06 vm158 snmpd[5675]: message repeated 14 times: [ Connection from UDP: [redacted]:43382->[redacted]:161]
Jan 13 21:33:42 vm158 snmpd[5675]: Connection from UDP: [redacted]:48723->[redacted]:161
Jan 13 21:34:35 vm158 kernel: [265468.320399] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=48 TOS=0x00 PREC=0x00 TTL=121 ID=8188 DF PROTO=TCP SPT=58320 DPT=25 WINDOW=8192 RES=0x00 SYN URGP=0
Jan 13 21:34:38 vm158 kernel: [265471.328399] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=48 TOS=0x00 PREC=0x00 TTL=121 ID=8195 DF PROTO=TCP SPT=58320 DPT=25 WINDOW=8192 RES=0x00 SYN URGP=0
Jan 13 21:34:44 vm158 kernel: [265477.328704] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted LEN=48 TOS=0x00 PREC=0x00 TTL=121 ID=8227 DF PROTO=TCP SPT=58320 DPT=25 WINDOW=8192 RES=0x00 SYN URGP=0
Jan 13 21:35:01 vm158 CRON[8078]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:35:22 vm158 snmpd[5675]: Connection from UDP: [redacted]:34822->[redacted]:161
Jan 13 21:36:01 vm158 CRON[8167]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:37:01 vm158 CRON[8286]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:38:01 vm158 CRON[8365]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:39:01 vm158 CRON[8426]: (root) CMD ( [ -x /usr/lib/php5/maxlifetime ] && [ -x /usr/lib/php5/sessionclean ] && [ -d /var/lib/php5 ] && /usr/lib/php5/sessionclean /var/lib/php5 $(/usr/lib/php5/maxlifetime))
Jan 13 21:39:01 vm158 CRON[8428]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:40:01 vm158 CRON[8561]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:41:01 vm158 CRON[8673]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:35:22 vm158 snmpd[5675]: message repeated 24 times: [ Connection from UDP: [redacted]:34822->[redacted]:161]
Jan 13 21:41:06 vm158 snmpd[5675]: Connection from UDP: [redacted]:54895->[redacted]:161
Jan 13 21:42:01 vm158 CRON[8787]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
Jan 13 21:43:01 vm158 CRON[8851]: (root) CMD (( date; COLUMNS=156 top -b -n 1 2>&1 ) >> /var/log/top.log)
--- crash occured here ---
Jan 13 22:38:18 vm158 rsyslogd: [origin software="rsyslogd" swVersion="7.4.4" x-pid="740" x-info="http://www.rsyslog.com"] start
Jan 13 22:38:18 vm158 rsyslogd: cannot create '/var/spool/postfix/dev/log': No such file or directory
Jan 13 22:38:18 vm158 rsyslogd: rsyslogd's groupid changed to 104
Jan 13 22:38:18 vm158 rsyslogd: rsyslogd's userid changed to 101
</pre>
<p>So does the kern.log:</p>
<pre>
Jan 13 21:30:16 vm158 kernel: [265208.860042] Peer redacted:49503/80 unexpectedly shrunk window 3219335626:3219373738 (repaired)
Jan 13 21:30:16 vm158 kernel: [265209.060112] Peer redacted:49491/80 unexpectedly shrunk window 4084028138:4084040474 (repaired)
Jan 13 21:30:17 vm158 kernel: [265209.372073] Peer redacted:49506/80 unexpectedly shrunk window 2495513151:2495537808 (repaired)
Jan 13 21:32:32 vm158 kernel: [265344.867580] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted=60 TOS=0x00 PREC=0x00 TTL=50 ID=42483 DF PROTO=TCP SPT=35533 DPT=23 WINDOW=5808 RES=0x00 SYN URGP=0
Jan 13 21:32:35 vm158 kernel: [265347.866534] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted=60 TOS=0x00 PREC=0x00 TTL=50 ID=42484 DF PROTO=TCP SPT=35533 DPT=23 WINDOW=5808 RES=0x00 SYN URGP=0
Jan 13 21:32:41 vm158 kernel: [265353.866495] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted=60 TOS=0x00 PREC=0x00 TTL=50 ID=42485 DF PROTO=TCP SPT=35533 DPT=23 WINDOW=5808 RES=0x00 SYN URGP=0
Jan 13 21:33:15 vm158 kernel: [265387.820707] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted=60 TOS=0x00 PREC=0x00 TTL=58 ID=8368 DF PROTO=TCP SPT=39069 DPT=10000 WINDOW=5840 RES=0x00 SYN URGP=0
Jan 13 21:34:35 vm158 kernel: [265468.320399] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted=48 TOS=0x00 PREC=0x00 TTL=121 ID=8188 DF PROTO=TCP SPT=58320 DPT=25 WINDOW=8192 RES=0x00 SYN URGP=0
Jan 13 21:34:38 vm158 kernel: [265471.328399] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted=48 TOS=0x00 PREC=0x00 TTL=121 ID=8195 DF PROTO=TCP SPT=58320 DPT=25 WINDOW=8192 RES=0x00 SYN URGP=0
Jan 13 21:34:44 vm158 kernel: [265477.328704] Shorewall:net2fw:DROP:IN=eth0 OUT= MAC=redacted SRC=redacted DST=redacted=48 TOS=0x00 PREC=0x00 TTL=121 ID=8227 DF PROTO=TCP SPT=58320 DPT=25 WINDOW=8192 RES=0x00 SYN URGP=0
--- crash occured here ---
Jan 13 22:38:18 vm158 kernel: [ 0.000000] Initializing cgroup subsys cpuset
</pre>
<p>Similar for auth.log:</p>
<pre>
Jan 13 21:38:01 vm158 CRON[8364]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 13 21:38:01 vm158 CRON[8364]: pam_unix(cron:session): session closed for user root
Jan 13 21:39:01 vm158 CRON[8424]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 13 21:39:01 vm158 CRON[8425]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 13 21:39:02 vm158 CRON[8425]: pam_unix(cron:session): session closed for user root
Jan 13 21:39:02 vm158 CRON[8424]: pam_unix(cron:session): session closed for user root
Jan 13 21:40:01 vm158 CRON[8560]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 13 21:40:01 vm158 CRON[8560]: pam_unix(cron:session): session closed for user root
Jan 13 21:41:01 vm158 CRON[8672]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 13 21:41:01 vm158 CRON[8672]: pam_unix(cron:session): session closed for user root
Jan 13 21:42:01 vm158 CRON[8786]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 13 21:42:01 vm158 CRON[8786]: pam_unix(cron:session): session closed for user root
Jan 13 21:43:01 vm158 CRON[8850]: pam_unix(cron:session): session opened for user root by (uid=0)
Jan 13 21:43:02 vm158 CRON[8850]: pam_unix(cron:session): session closed for user root
--- crash occured here ---
Jan 13 22:38:18 vm158 systemd-logind[1014]: New seat seat0.
Jan 13 22:38:18 vm158 systemd-logind[1014]: Watching system buttons on /dev/input/event0 (Power Button)
</pre>
<p>dmesg.log doesn't show anything suspicious either:</p>
<pre>
[ 136.672661] ip_tables: (C) 2000-2006 Netfilter Core Team
[ 152.682193] Netfilter messages via NETLINK v0.30.
[ 152.767856] nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
[ 153.415271] xt_time: kernel timezone is +0100
[ 153.477146] ctnetlink v0.93: registering with nfnetlink.
[ 153.589937] ip_set: protocol 6
[ 153.623677] ipt_CLUSTERIP: ClusterIP Version 0.8 loaded successfully
[ 153.956382] ipt_ULOG: ULOG is deprecated and it will be removed soon, use NFLOG instead
[ 155.378975] u32 classifier
[ 155.378980] Actions configured
</pre> Infrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=38422015-01-14T11:33:08ZChristian Lohmaiercloph@documentfoundation.org
<ul></ul><p>Silverstripe's log shows:<br /><pre>
[13-Jan-2015 20:35:14] Warning at framework/model/MySQLDatabase.php line 68: mysqli::mysqli(): (HY000/2013): Lost connection to MySQL server at 'reading authorization packet', system error: 104 (http://de.libreoffice.org/download/libreoffice-fresh/)
[13-Jan-2015 20:35:15] Error at framework/model/MySQLDatabase.php line 598: Couldn't connect to MySQL database | Lost connection to MySQL server at 'reading authorization packet', system error: 104 (http://de.libreoffice.org/download/libreoffice-fresh/)
</pre><br />c<br />Strange thing is that it is only printed once - usually when mysql dies there are tons of those.</p> Infrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=38752015-01-15T08:48:57ZAlexander Werneralex@documentfoundation.org
<ul></ul><p>Monitoring of vm158 was expanded, for current state see:<br /><a class="external" href="https://monitoring.documentfoundation.org/tdf/thruk/#cgi-bin/status.cgi?host=vm158.documentfoundation.org">https://monitoring.documentfoundation.org/tdf/thruk/#cgi-bin/status.cgi?host=vm158.documentfoundation.org</a><br />For historical data and graphs have a look at (choose the services in the list on the right):<br /><a class="external" href="https://monitoring.documentfoundation.org/tdf/pnp4nagios/index.php/graph?host=vm158.documentfoundation.org">https://monitoring.documentfoundation.org/tdf/pnp4nagios/index.php/graph?host=vm158.documentfoundation.org</a></p> Infrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=39412015-01-19T11:05:56ZFlorian Effenbergerfloeff@documentfoundation.org
<ul><li><strong>Status</strong> changed from <i>New</i> to <i>In Progress</i></li></ul><p>Extensive monitoring didn't yield any issues either, but it might be related to one of these:</p>
<ul>
<li><a class="external" href="https://bugs.launchpad.net/ubuntu/+source/linux-lts-trusty/+bug/1333553">https://bugs.launchpad.net/ubuntu/+source/linux-lts-trusty/+bug/1333553</a></li>
<li><a class="external" href="https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1307473">https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1307473</a></li>
</ul>
<p>Options:</p>
<ol>
<li>migrate to Debian 7 => had problems with PHP and nginx</li>
<li>go with kernel PPA and Ubuntu 14.04</li>
<li>downgrade to Ubuntu 12.04 with trusty LTS enablement stack</li>
</ol>
<p>Variant #3 is combination that is working and should have most impact, so going with this first, to see if it helps. Later on, option #2 can be tried, as we would likely go with 14.04 in the end.</p> Infrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=41472015-01-26T19:16:25ZChristian Lohmaiercloph@documentfoundation.org
<ul></ul><p>vm157 is setup and runs test version of silverstripe on 12.04</p>
<p>what I noticed when trying to get it to run after installing the necessary packages:<br />silverstripe's php failed to launch, it requested tons of memory (gave up after rising the limit to 512MB and still not being enough) - turns out that trying to read some files in webroot/silverstripe-cache triggers a bug/leak in the version of php that causes it to fail.</p>
<p>There also were old files in the cache directory in the current live instance, so I deleted the directory there as well.</p>
<p>(default when it doesn't exist in the webroot is to create it in /tmp, so that's where the cache files are now)</p>
<p>Might be completely unrelated to the problem of the server just not responding anymore, but a pitfall nevertheless.</p> Infrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=41722015-01-29T20:28:20ZChristian Lohmaiercloph@documentfoundation.org
<ul></ul><p>the proxying to the 12.x based install showed that that one suffers from the segfaulting php processes just like the debian based VM did. So not really a solution either.</p>
<p>Database on the 14.04 host got damaged, resulting in mysql crashing frequently when trying to update the download lists - did uninstall and reinstall mysql and reimported fresh dumps... will undo the proxying in ~1h or so.</p> Infrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=43662015-02-13T12:18:11ZFlorian Effenbergerfloeff@documentfoundation.org
<ul></ul><p>Regular (daily) reboots of the VM seem to help indeed, which make it look like some buffer is running full, and thus it's VM guest problem, not a VM host one<br />Alex proposed to install a newer kernel from the backports repository</p> Infrastructure - Bug #988: vm158 (libreoffice.org) crashes irregularlyhttps://redmine.documentfoundation.org/issues/988?journal_id=44442015-02-27T10:20:33ZFlorian Effenbergerfloeff@documentfoundation.org
<ul><li><strong>Status</strong> changed from <i>In Progress</i> to <i>Rejected</i></li></ul><p>Rejecting due to change of platform</p>