Fehlermeldungen SQLite / Too many open files

Levy · 2. September 2013

Hallo zusammen,

wir setzen momentan LiveConfig 1.6.4 r2509 auf einem Debian 7 (Wheezy) System ein. Die genaue Konstellation sieht dabei wie folgt aus:

LiveConfig-Server = VMware vSphere Cluster aus 2 physikalischen ProLiant-Systemen mit eigenem SAN
Datenbank-Server = VMware vSphere Cluster aus 5 physikalischen ProLiant-Systemen mit eigenem SAN
Web-Server = VMware vSphere Cluster aus 5 physikalischen ProLiant-Systemen mit eigenem SAN
Mail-Server = VMware vSphere Cluster aus 3 physikalischen ProLiant-Systemen mit eigenem SAN

Einmal am Tag hängt sich der LiveConfig-Dienst mit der nachfolgenden Fehlermeldung im Log auf:

Code

[2013/09/02 15:15:13.496767] [4240|4240] Error while accepting connection: Too many open files
[2013/09/02 15:15:13.496939] [4240|4251] (last message repeated 4 times)
[2013/09/02 15:15:13.496939] [4240|4251] ERROR: Releasing db connection, but still have running transaction (-> forcing ROLLBACK)
[2013/09/02 15:15:13.496940] [4240|4240] Error while accepting connection: Too many open files
[2013/09/02 15:15:13.497167] [4240|4251] (last message repeated 49 times)
[2013/09/02 15:15:13.497167] [4240|4251] Database exception: unable to open database file (SQL: UPDATE RRD_CPU SET RRD_VALUE1= ?, RRD_VALUE2= ?, RRD_VALUE3= ?, RRD_VALUE4= ?, RRD_VALUE5= ?, RRD_VALUE6= ?, RRD_VALUE7= ?, RRD_VALUE8= ?, RRD_VALUE9= ?, RRD_TIMESTAMP= ? WHERE ( ( RRD_ARCHIVEID = ? ) AND ( RRD_SLOTID = ? ) ))
[2013/09/02 15:15:13.497168] [4240|4240] Error while accepting connection: Too many open files
[2013/09/02 15:15:29.019941] [4241|4246] Error while connecting to MySQL server: Can't connect to local MySQL server through socket '/tmp/mysql.sock' (2)
[2013/09/02 15:15:39.432938] [4240|4250] (last message repeated 7530522 times)
[2013/09/02 15:15:39.432938] [4240|4250] ERROR: Releasing db connection, but still have open statements
[2013/09/02 15:15:39.433410] [4240|4250]        aborting SQL: 'UPDATE RRD_CPU SET RRD_VALUE1= ?, RRD_VALUE2= ?, RRD_VALUE3= ?, RRD_VALUE4= ?, RRD_VALUE5= ?, RRD_VALUE6= ?, RRD_VALUE7= ?, RRD_VALUE8= ?, RRD_VALUE9= ?, RRD_TIMESTAMP= ? WHERE ( ( RRD_ARCHIVEID = ? ) AND ( RRD_SLOTID = ? ) )'
[2013/09/02 15:15:39.433597] [4240|4250]        aborting SQL: 'SELECT RRA_ID, RRA_STEP, RRA_SIZE, RRA_SLOTPOS, RRA_LASTTS, RRA_VALUE1, RRD_VALUE1, RRA_VALUE2, RRD_VALUE2, RRA_VALUE3, RRD_VALUE3, RRA_VALUE4, RRD_VALUE4, RRA_VALUE5, RRD_VALUE5, RRA_VALUE6, RRD_VALUE6, RRA_VALUE7, RRD_VALUE7, RRA_VALUE8, RRD_VALUE8, RRA_VALUE9, RRD_VALUE9, RRD_SLOTID, RRD_TIMESTAMP FROM RRA_CPU LEFT JOIN RRD_CPU ON ( ( RRA_ID = RRD_ARCHIVEID ) AND ( RRA_SLOTPOS = RRD_SLOTID ) ) WHERE ( ( RRA_SERVERID = ? ) AND ( RRA_LEVEL = 0 ) ) ORDER BY RRA_ID ASC'

Alles anzeigen

Ab diesem Zeitpunkt ist auch das Webinterface weder über http, noch https (SSL) erreichbar.

Ist das ein Bug oder haben wir etwas falsch konfiguriert?

Insbesondere die Meldung "Error while connecting to MySQL server: Can't connect to local MySQL server through socket '/tmp/mysql.sock' (2)" macht uns sehr stutzig, da wir keinen MySQL-Server, sondern den integrierten SQLite nutzen.

Vielen Dank und beste Grüße
Levy

Levy · 3. September 2013

Ergänzung:

Wir haben gestern Nachmittag von SQLite auf MySQL umgestellt und prompt kam soeben wieder die o. g. Fehlermeldung und die LiveConfig-Dienste reagierte nicht mehr. Welche "too many open files" sind hier gemeint?

kk · 3. September 2013

Da die Meldung im Kontext von "Error while accepting connection" erscheint, tippe ich darauf, dass es (zu) viele TCP-Verbindungen gibt (wobei das auch komisch ist, da LC in so einem Fall ohnehin keine weiteren Verbindungen mehr annehmen dürfte).

Wenn Sie diesen Zustand wieder erhalten, lassen Sie sich bitte mal die Liste der offenen Netzwerkverbindungen zu LiveConfig ("netstat -tpn | grep liveconfig") und die Liste der offenen Filehandles (lsof | grep liveconfig) ausgeben.

Die MySQL-Connect-Meldung kann auftreten, wenn Sie einen MySQL-Server mit LiveConfig verwalten (Serververwaltung -> Datenbank) und die Verbindung fehlschlägt.

Viele Grüße

-Klaus Keppler

Levy · 4. September 2013

Heute Nacht um exakt 3.00 Uhr war es wieder soweit und LiveConfig versagte seinen Dienst. Hier nun die entsprechenden Ausgaben:

Code

root@server-01:~# netstat -tpn | grep liveconfig
tcp        0      0 78.138.121.20:788       78.138.121.35:42506     VERBUNDEN   13740/liveconfig
tcp        0      0 78.138.121.20:788       78.138.121.48:59450     VERBUNDEN   13740/liveconfig
tcp        0      0 78.138.121.20:788       78.138.121.45:37416     VERBUNDEN   13740/liveconfig
root@server-01:~#

Bei "lsof | grep liveconfig" sieht es dann aber übel aus. Neben dem Üblichen steht hier um die 7.000 mal das folgende drin:

Code

liveconfi 13740 13752 liveconfig 1012u     sock                0,7      0t0  160261446 can't identify protocol

Auf copy&paste für den gesamten Output wollte ich jetzt aufgrund der Menge verzichten.

Hilft das weiter?

kk · 4. September 2013

Danke, das hilft schon etwas weiter.
Die ~7000 Verbindungen sind offenbar Socket-Connections zum LiveConfig-Server-Prozess (im o.g. Beispiel mit PID 13740 - das ist der Prozess, der auch auf Port 788 horcht). Das erklärt dann auch die "Too many open files"-Fehlermeldung.

Vermutlich läuft um 03:00 Uhr irgendetwas, das LiveConfig aus dem Tritt bringt - evtl. VMWare-Snapshots, Backups o.ä.? Bislang ist uns dieses Verhalten noch nirgendwo aufgefallen oder gemeldet worden.

Könnten Sie uns bitte die letzten Log-Meldungen (/var/log/liveconfig/liveconfig.log) vor Auftreten des Problems schicken? (also alles zwischen "funktioniert noch" und dem ersten "Too many open files...").
Am besten wäre es zudem, wenn Sie beim nächsten Auftreten des Problems einen Coredump erzeugen könnten - damit können wir dann genau lokalisieren, wo etwas nicht stimmt. Hierzu gehen Sie bitte wie folgt vor:

lokalisieren Sie die PID des LiveConfig-Client-Prozesses (z.B. mit "netstat -tlpn | grep ':788'").
wechseln Sie ins Verzeichnis /root: cd /root
Starten Sie den GNU-Debugger (gdb) und verbinden sich mit diesem Prozess - z.B. "gdb --pid=13740"
erzeugen Sie den Coredump: "gcore"
beenden Sie gdb wieder: "quit"
komprimieren Sie den Core-Dump: "gzip -9 core.13740"
senden Sie die Datei dann per Mail an support@liveconfig.com (falls >20 MB, senden Sie uns ggf einen Download-Link)

Viele Grüße

-Klaus Keppler

Levy · 4. September 2013

Hallo Herr Keppler,

um 3.00 Uhr lief bzw. startete nichts besonderes auf dem System. Backups und Snapshots begannen erst zwei Stunden später. Ich habe aber gerade folgendes Verhalten festgestellt:

Code

root@server-01:~# /etc/init.d/liveconfig start && date
Starting LiveConfig Server: liveconfig.
Mi 4. Sep 10:00:38 CEST 2013


root@server-01:~# lsof | grep identify && date
liveconfi 21946       liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21952 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21953 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21954 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21956 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21957 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21958 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
Mi 4. Sep 10:01:01 CEST 2013


root@server-01:~# lsof | grep identify && date
liveconfi 21946       liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946       liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21952 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21952 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21953 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21953 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21954 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21954 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21956 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21956 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21957 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21957 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21958 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21958 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
Mi 4. Sep 10:01:35 CEST 2013


root@server-01:~# lsof | grep identify && date
liveconfi 21946       liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946       liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946       liveconfig   26u     sock                0,7      0t0 2240454630 can't identify protocol
liveconfi 21946 21952 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21952 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21952 liveconfig   26u     sock                0,7      0t0 2240454630 can't identify protocol
liveconfi 21946 21953 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21953 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21953 liveconfig   26u     sock                0,7      0t0 2240454630 can't identify protocol
liveconfi 21946 21954 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21954 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21954 liveconfig   26u     sock                0,7      0t0 2240454630 can't identify protocol
liveconfi 21946 21956 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21956 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21956 liveconfig   26u     sock                0,7      0t0 2240454630 can't identify protocol
liveconfi 21946 21957 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21957 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21957 liveconfig   26u     sock                0,7      0t0 2240454630 can't identify protocol
liveconfi 21946 21958 liveconfig   23u     sock                0,7      0t0 2240449511 can't identify protocol
liveconfi 21946 21958 liveconfig   24u     sock                0,7      0t0 2240449888 can't identify protocol
liveconfi 21946 21958 liveconfig   26u     sock                0,7      0t0 2240454630 can't identify protocol
Mi 4. Sep 10:04:24 CEST 2013

Alles anzeigen

So geht das weiter, bis irgendwann die Fehlermeldung "too many..." im liveconfig-Log erscheint.

Auszug aus liveconfig.log um 10.06 Uhr:

Code

[2013/09/04 10:00:38.702194] [21943|21943] LiveConfig 1.6.4-2509 starting...
[2013/09/04 10:00:38.705635] [21943|21943] Database driver loaded: MySQL (5.5.31)
[2013/09/04 10:00:38.711557] [21943|21943] License is valid.
[2013/09/04 10:00:38.720008] [21947|21947] Client child started...
[2013/09/04 10:00:38.720665] [21946|21946] Server child started...
[2013/09/04 10:00:38.736964] [21947|21947] Connected to LiveConfig 1.6.4
[2013/09/04 10:00:38.785293] [21947|21951] [LUA] Loading custom Lua settings from '/usr/lib/liveconfig/lua/custom.lua'
[2013/09/04 10:00:38.800876] [21947|21951] [LUA] Detected 'Debian GNU/Linux 7.1'
[2013/09/04 10:00:38.806172] [21947|21950] [LUA] Loading custom Lua settings from '/usr/lib/liveconfig/lua/custom.lua'
[2013/09/04 10:00:38.889873] [21947|21950] (last message repeated 1 times)
[2013/09/04 10:00:53.107183] [21946|21988] Connecting to update.liveconfig.com ([88.198.223.75]:443)...
[2013/09/04 10:00:58.836335] [21946|21946] Error at SSL handshake
[2013/09/04 10:01:35.839151] [21946|21946] Error at SSL handshake

Alles anzeigen

Den Core-Dump habe ich soeben per Mail an Sie versendet.

Mit besten Grüßen
Levy

kk · 4. September 2013

Hallo,

der Fehler wurde gefunden und beseitigt. Unter bestimmten Umständen wurden die Sockets von nicht erfolgreich aufgebauten LCCP-Verbindungen nicht mehr freigegeben.
Ein Update (v1.6.4-r2534) läuft derzeit durch die Buildsysteme und wird in den nächsten Stunden in den Repositories bereitgestellt.

Viele Grüße

-Klaus Keppler

Jetzt mitmachen!