Massive Probleme durch 'pipelog.pl failed unexpectedly'

X

x-mode

New Member
Hallo Freunde,
nach durchwachter Nacht brauche ich jetzt wohl doch Beistand.

Seit gestern Morgen zickt mein VServer (Debian 6.0.7) - alles begann mit einem "Cannot fork - failed to allocate memory" und seit dem treten Fehler bis hin zu Abstürzen von apache, mysql und sogar rsyslogd auf.

Im syslog taucht immer wieder in Abständen von zwei bis 30 Minuten diese Meldung auf:
Code: 
/var/log/syslog
May 26 11:01:07 vsbox mysqld_safe: Number of processes running now: 0
May 26 11:01:07 vsbox mysqld_safe: mysqld restarted
May 26 11:01:08 vsbox mysqld: 130526 11:08:08 [Note] Plugin 'FEDERATED' is disabled.
May 26 11:01:08 vsbox mysqld: 130526 11:08:08  InnoDB: Initializing buffer pool, size = 8.0M
May 26 11:01:08 vsbox mysqld: 130526 11:08:08  InnoDB: Completed initialization of buffer pool
May 26 11:01:08 vsbox mysqld: 130526 11:08:08  InnoDB: Started; log sequence number 0 45938
May 26 11:01:08 vsbox mysqld: 130526 11:08:08 [Note] Event Scheduler: Loaded 0 events
May 26 11:01:08 vsbox mysqld: 130526 11:08:08 [Note] /usr/sbin/mysqld: ready for connections.
May 26 11:01:08 vsbox mysqld: Version: '5.1.66-0+squeeze1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Debian)

Gleich im Anschluss das hier:
Code: 
/var/log/syslog
May 26 11:02:27 vsbox mysqld: 130526 11:02:27 [ERROR] /usr/sbin/mysqld: Table './usr_web2_1/wp_12_options' is marked as crashed and should be repaired
May 26 11:02:27 vsbox mysqld: 130526 11:02:27 [Warning] Checking table:   './usr_web2_1/wp_12_options'
May 26 11:02:27 vsbox mysqld: 130526 11:02:27 [ERROR] /usr/sbin/mysqld: Table './usr_web2_1/wp_181_options' is marked as crashed and should be repaired
May 26 11:02:27 vsbox mysqld: 130526 11:02:27 [Warning] Checking table:   './usr_web2_1/wp_181_options'
May 26 11:02:27 vsbox mysqld: 130526 11:02:27 [ERROR] /usr/sbin/mysqld: Table './usr_web2_1/wp_174_options' is marked as crashed and should be repaired
May 26 11:02:27 vsbox mysqld: 130526 11:02:27 [Warning] Checking table:   './usr_web2_1/wp_174_options'
May 26 11:02:27 vsbox mysqld: 130526 11:02:27 [ERROR] /usr/sbin/mysqld: Table './usr_web2_1/wp_175_options' is marked as crashed and should be repaired

Die "marked as crashed" Meldungen hören sofort auf, wenn ich manuell mysqlrepair -u root -pmeinpass -m --all-databases mache. Es dauert dann einige Minuten, bis die ganze Sache wieder von vorne startet:
Code: 
May 26 11:01:07 vsbox mysqld_safe: Number of processes running now: 0
May 26 11:01:07 vsbox mysqld_safe: mysqld restarted

Ich habe jetzt die ganze Nacht logs gelesen und versucht, die Ursache für dieses Verhalten zu finden. Im Apache Errorlog bin ich immer wieder auf diesen Eintrag gestossen:
Code: 
/var/log/apache2/error.log
piped log program '/root/confixx/pipelog.pl' failed unexpectedly

Ich habe nun beobachtet, dass die pipelog.pl Meldung im error.log gerne kurz vor der Meldung mysqld_safe: mysqld restarted im syslog erscheint.

Es mangelt an Dokuemtation zu Confixx, suche schon seit Stunden nache einer Lösung... mir stürzen in unregelmäßigen Abständen andere Prozesse ab, ohne jede Fehlermeldung im syslog - mal klinkt sich der mysqld aus, mal der apache2, sogar rsyslogd gibt manchmal den Geist auf ohne neuzustarten. Das mache ich dann manuell.

Soweit ich das überblicken kann verursacht pipelog.pl Fehler im Datenbankserver, der daraufhin neugestartet wird und alle Datenbank als gecrashed anmeckert.

Wie kann ich nun weiter vorgehen?
 
x-mode said:
alles begann mit einem "Cannot fork - failed to allocate memory" und seit dem treten Fehler bis hin zu Abstürzen von apache, mysql und sogar rsyslogd auf
Click to expand...

Wie wärs wenn du dann erstmal deine Ressourcennutzung überprüfst? Ist der Speicher voll, geht der OOM-Killer hin und schafft Platz. Welche Anwendung es dabei trifft, ist ihm egal.
 
Firewire2002 said:
der OOM-Killer
Click to expand...

Der OOM-Killer würde sein Tun im syslog dokumentieren aber da ist nichts.

Und im Moment des mysql-restart:
Code: 
root@vsbox:~# free -m
             total       used       free     shared    buffers     cached
Mem:          1280        428        851          0          0          0
-/+ buffers/cache:        428        851
Swap:            0          0          0
 
Welche Virtualisierungslösung steckt darunter? OpenVZ/VZ? Dann wären auch noch die /proc/user_beancounters interessant.
 
x-mode said:
Der OOM-Killer würde sein Tun im syslog dokumentieren aber da ist nichts.
Click to expand...

Nicht, wenn er als erstes deinen syslogd abschießt. Weiterhin hat die Fehlermeldung nicht unbedingt etwas mit dem RAM zu tun. Poste bitte mal die Ausgabe von grep -ve " 0$" /proc/user_beancounters
 
Code: 
root@vsbox:~ # uname -a
Linux vsbox 2.6.32-5-openvz-amd64 #1 SMP Sun May 6 05:21:56 UTC 2012 x86_64 GNU/Linux

root@vsbox:~# grep -ve " 0$" /proc/user_beancounters
Version: 2.5
       uid  resource                     held              maxheld              barrier                limit              failcnt
   127131:  kmemsize                 20746247             37707030             37694577             41464034                  199
            lockedpages                     0                   24                   32                   32                   15
            privvmpages                149972               363068               327680               360448                 9070
            numproc                       100                  180                  180                  180                    1
            oomguarpages                76361               245148               262144               262144                 1985
 
Firewire2002 said:
Reduzier deine Ressourcennutzung
Click to expand...

Uhm... woran macht sich das fest?

Die Kiste lief bis gestern sechs Wochen ohne jedes Zicken durch! Jetzt, in meinem "Notbetrieb" läuft nur noch der Apache und der mysqld - selbst postfix habe ich schon abgeschaltet... und 10 Surfer dürften die Kiste doch wohl nicht in den Abgrund reißen? Da war im April aber noch wesentlich mehr los, ohne dass es Probleme gab.
 
Da du stand jetzt von deinen Limits ein ganzes Stück entfernt bist, wirst aktuell wohl nicht viel sehen. Ansonsten mit ps und top schauen welche Anwendung den Speicher frisst.
Bei derartigen Schwankungen würde ich nun auf Webserver, Mailserver oder Datenbankserver tippen. Die bei falscher Konfiguration gern schnell mal das 10-fache an Speicher schlucken als normal, wenn Bots drauf trümmern.

Auch wenn der Datenbankserver von aussen nicht direkt erreichbar ist, so ist dieser indirekt über die daran angebundenen Dienste eben so betroffen.
 
Firewire2002 said:
Da du stand jetzt von deinen Limits ein ganzes Stück entfernt bist, wirst aktuell wohl nicht viel sehen. Ansonsten mit ps und top schauen welche Anwendung den Speicher frisst.
Click to expand...

Code: 
root@vsbox:~# ps -e -orss=,args= | sort -b -k1,1n | pr -TW$COLUMNS
  508 /usr/bin/dbus-daemon --system
  592 /bin/sh -c /root/confixx/pipelog.pl
  616 tail -f /var/log/syslog
  620 tail -f /var/log/apache2/error.log
  628 logger -t mysqld -p daemon.error
  700 /bin/sh /usr/bin/mysqld_safe
  792 init [2]      
  800 sort -b -k1,1n
  864 pr -TW109
  944 ps -e -orss=,args=
 1052 /usr/sbin/cron
 1132 /usr/sbin/sshd
 1360 su
 1360 su
 1360 su
 1460 proftpd: (accepting connections)
 1528 /usr/sbin/rsyslogd -c4
 1708 sshd: user@pts/3
 1840 /usr/bin/perl /root/confixx/pipelog.pl
 1840 /usr/bin/perl /root/confixx/pipelog.pl
 1840 /usr/bin/perl /root/confixx/pipelog.pl
 1844 /usr/bin/perl /root/confixx/pipelog.pl
 1844 /usr/bin/perl /root/confixx/pipelog.pl
 1844 /usr/bin/perl /root/confixx/pipelog.pl
 1844 /usr/bin/perl /root/confixx/pipelog.pl
 1844 /usr/bin/perl /root/confixx/pipelog.pl
 1844 /usr/bin/perl /root/confixx/pipelog.pl
 1856 sshd: user@pts/4
 2040 -bash
 2044 -bash
 2044 -bash
 2120 bash
 2124 bash
 2224 bash
 3172 sshd: user@pts/5
 3284 sshd: user [priv]
 3284 sshd: user [priv]
 3284 sshd: user [priv]
22188 /usr/sbin/apache2 -k start
22496 /usr/sbin/apache2 -k start
24504 /usr/sbin/apache2 -k start
39096 /usr/sbin/apache2 -k start
39468 /usr/sbin/apache2 -k start
39508 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --pid-file=/var/run/mysqld/mysqld
45888 /usr/sbin/apache2 -k start

Damit ist der Server so überfordert um das hier zu produzieren?
Code: 
May 26 12:58:13 vsbox mysqld_safe: mysqld restarted
 May 26 13:01:07 vsbox mysqld_safe: mysqld restarted
 May 26 13:01:08 vsbox mysqld_safe: mysqld restarted
 May 26 13:03:08 vsbox mysqld_safe: mysqld restarted
 May 26 13:04:48 vsbox mysqld_safe: mysqld restarted
 May 26 13:06:00 vsbox mysqld_safe: mysqld restarted
 May 26 13:15:02 vsbox mysqld_safe: mysqld restarted
 May 26 13:16:02 vsbox mysqld_safe: mysqld restarted
 May 26 13:21:02 vsbox mysqld_safe: mysqld restarted
 May 26 13:23:02 vsbox mysqld_safe: mysqld restarted
 May 26 13:31:12 vsbox mysqld_safe: mysqld restarted
 May 26 13:34:02 vsbox mysqld_safe: mysqld restarted
 May 26 13:35:01 vsbox mysqld_safe: mysqld restarted
 May 26 13:41:09 vsbox mysqld_safe: mysqld restarted
 May 26 13:44:02 vsbox mysqld_safe: mysqld restarted
 May 26 13:45:00 vsbox mysqld_safe: mysqld restarted
 May 26 13:52:01 vsbox mysqld_safe: mysqld restarted
 May 26 13:52:43 vsbox mysqld_safe: mysqld restarted
 May 26 13:54:02 vsbox mysqld_safe: mysqld restarted
 May 26 13:59:02 vsbox mysqld_safe: mysqld restarted
 May 26 14:00:24 vsbox mysqld_safe: mysqld restarted
 May 26 14:02:02 vsbox mysqld_safe: mysqld restarted
 
Ich muss zugeben, dass diese Infos böhmische Dörfer für mich sind. Worauf genau ist dabei zu achten?

Im Übrigen hab ich jetzt eben den Support meines Providers angeschrieben - evtl. liegts ja am Hostsystem.
 
Die User_Beancounters sind deine Ressourcenwerte. Wenn die Failcounter steigen, dann hast du deine Limits überschritten.
OpenVZ/Virtuozzo kennt eben noch ein paar mehr Limits als nur einfach "Ram". ;)
 
Ja ok, der oomguarpages ist doch recht schnell gewachsen, das seh ich. Aber wenn gleichzeitig 800MB RAM als frei angezeigt werden... dann liegt das doch nicht an der Konfiguration meiner Server sondern doch wohl eher an der VZ? Ich krieg ja offensichtlich nicht, was mir zusteht oder seh ich das falsch?

Ich habe mittlerweile die apach2.conf optimiert, mod_ssl deaktiviert, postfix abgeschaltet und trotzdem schlägt OOM zu - und das auf einem VServer mit 1500 MhZ CPU und 1024 MB RAM wenn sich 8 User mit einem Wordpress verbinden :(
 
Ob du das bekommst, was dir zusteht, lässt sich ohne Produktbeschreibung und den vollständigen Inhalt der UBC nicht sagen. "free" ist hier kein verlässlicher Faktor, weil der Werte bei VZ mit UBCs überhaupt keine Aussagekraft hat.
Das was da als "total" angegeben ist, ist ein reines "Anzeigelimit" ohne irgendeine technische Relevanz.
Ausschlaggebend sind ausschließlich die UBCs. Lies dir dazu bitte das Wiki von OpenVZ bezüglich UBCs durch. Die Werte sind sehr unterschiedlich definiert.
 
Ich möchte mich natürlich bei dir bedanken, du hattest vollkommen Recht mit deiner Analyse - die strikte Ressourcenüberwachung des VServers bzw. meine Ignoranz demgegenüber verursachte meine Probleme :D Für mich geht es jetzt also darum, die optimale Abstimmung für Web- und Datenbankserver zu finden.
 
You must log in or register to reply here.
Back
Top