Fehler "-2147483648 is not a valid MySQL result resource"

[DirtyHarry]

Hallo,

heute hat mich Edomi mit einem riesigen FehlerLog und nicht mehr vorhandener KNX-Kommunikation begrüßt: 4023513 Einträge im Fehler-Log. Die Logdatei hat eine Größe von 937MB...

Der Fehler fing heute morgen um kurz nach 4 an und seit dem kam immer wieder die gleiche Meldung (ca. 140x pro Sekunde).

2016-02-17 00:51:21    170305    KNX    6607    KNX-Verbindung verloren.
2016-02-23 12:36:26    316066    KNX    9843    ROUTER @ DE | TUNNELING_REQUEST / ErrMsg: SequenceCounter abweichend (ACK): Ist-Wert=125, Soll-Wert=126 / Raw: 061004200015041c7d002900bcd011364801010081
2016-02-24 04:08:12    228343    ?    9845    /usr/local/edomi/www/shared/php/base.php: Code 2 / Zeile 89 / mysql_fetch_assoc(): -2147483648 is not a valid MySQL result resource

Im Systemlog ist um 0 Uhr das Backup zu sehen und dann erst wieder der Neustart, also nichts besonderes.

Nach dem Neustart war alles wieder Ok.

Edomiversion: 1.18

[gaert]

Sieht nach einem Problem mit einem Grenzwert eines INT-Werts aus (32-bit-Wert). Ist mir noch nicht untergekommen... Was passiert denn bei Dir um kurz nach 4 Uhr?! Zeitschaltuhr oder ähnliches?

Das "?" in der Spalte "Proc" deutet darauf hin, dass der Fehler durch einen LBS verursacht wurde, bzw. durch den EXEC-Teil eines LBS... Hast Du einen Community-LBS laufen, der evtl. fehlerhaft ist?

[DirtyHarry]

Zeitschaltuhr habe ich nur eine zum was Testen. Aktuell schaltet die (falls aktiv) Mittwochs um 13:19 Ein und um 18:18 Aus. Sonstige regelmäßige Schaltungen sind eher unwahrscheinlich (und mir jetzt auch nicht bewusst), da es zum ersten mal vorgekommen ist (nicht nur insgesamt, auch beim aktuell aktivierten Projekt: Läuft seit dem 19.2.).

Community-LBS habe ich keine in Benutzung.
Verwendet habe ich Zähler, Watchdogs, ein paar Oszillatoren, ansonsten eher einfache Bausteine (UND, ODER, Sperren, etc).

Wenn mich nicht alles täuscht, war es aber die längste Zeit ohne Neustart. Ich werde mal keine Änderungen durchführen und wenn kein Stromausfall kommen sollte, Neustart des Hostes notwendig werden sollte oder ähnliches, lass ich durchlaufen bis nächste Woche Mittwoch. Wenn es bis dahin wieder vorkommt, hat es wahrescheinlich dann doch irgendwas mit der Betriebsdauer zu tun.

[gaert]

Nein... Mit der Betriebsdauer hat dies nichts zu tun. Bei mir läuft (oder lief) EDOMI seit 1/2 Jahr

Entscheidend für eine erfolgreiche Fehlersuche ist es zu wissen, unter welchen genauen Umständen der Fehler aufgetreten ist. Sonst wird's ein wildes Ratespiel... Meine Frage mit der ZSU zielte eher darauf ab, ob zu dem Zeitpunkt des Fehlers irgendwas "ungewöhnliches" geschaltet worden ist.

Ich vermute mal, dass eine Deiner Datenbanken "kaputt" ist. Vermutlich irgendwelche harten Neustarts etc...

[DirtyHarry]

Betriebsdauer alleine habe ich jetzt auch nicht erwartet, eher in Kombination mit einem Zähler, Oszillator oder ähnlichem (bzw. die Kombination von diesen).
Aber ich würde es jetzt wirklich erst mal gerne Testen, ob es bis Mittwoch nochmal vorkommt.

Aufzeichnung des KNX hab ich nicht, also ist mir nicht bekannt was genau zu der Zeit gelaufen ist. Viel mehr als ein paar Stromwerte (DPT14), die nur angezeigt werden, und ein paar Schalttelegramme die dann die Zähler und Watchdogs triggern kann nicht kommen. Es gibt nichts (mir zumindest nicht bekannt), was nur um die Uhrzeit ein Schaltvorgang (Intern, wie auch vom KNX) auslöst. (Notiz für mich selbst: Speicherkarte für den nicht mit Edomi arbeitenden Gira IP-Router besorgen, dann hab ich in Zukunft ne Aufzeichnung)

Harte Neustarts... Nach einem Update ist Edomi mal nicht ordentlich durchgestartet (könnte von 1.15 auf 1.16 gewesen sein), aber ansonsten ist mir gerade nichts bewusst. Den Host lass ich auch nur den Bildschirm ausschalten, also kein Standby oder ähnliches.
Defekte Datenbank, falls wirklich, wo und was muss ich machen?

[gaert]

Sofern noch nicht geschehen: Auf 1.18 updaten. Dann wird bei jedem Start die Datenbank untersucht und ggf. im Fehlerlog Hinweise auf Beschädigungen geloggt. Dann sehen wir weiter

[DirtyHarry]

Edomiversion: 1.18

Die letzten 3 Zeilen aus dem riesigen Fehlerlog:

2016-02-24 10:26:46 572123 ? 9845 /usr/local/edomi/www/shared/php/base.php: Code 2 / Zeile 89 / mysql_fetch_assoc(): -2147483648 is not a valid MySQL result resource ERROR
2016-02-24 10:26:46 584381 ? 9845 /usr/local/edomi/www/shared/php/base.php: Code 2 / Zeile 89 / mysql_fetch_assoc(): -2147483648 is not a valid MySQL result resource ERROR
2016-02-24 10:26:46 584703 ? 9845 /usr/local/edomi/www/shared/php/base.php: Code 2 / Zeile 89 / mysql_fetch_assoc(): -2147483648 is not a valid MySQL result resource ERROR

Die Datei hab ich dann verschoben, Browser hat sie nach 5 Minuten noch nicht vollständig angezeigt.

Die neue Datei fängt damit an:

Zeitstempel    ms    Prozess    PID    Meldung    Status
2016-02-24 13:35:56    065254    KNX    1432    ROUTER @ CE | DISCONNECT_REQUEST / Raw: 0610020900101d000801c0a8165f0e57    ERROR
2016-02-24 13:35:56    090702    KNX    1432    KNX-Verbindung verloren.    ERROR
2016-02-24 13:35:56    090949    KNX    1432    KNX-Verbindung verloren.    ERROR

Und im Systemlog ist folgendes im relavanten Zeitbereich:

2016-02-24 00:00:00    224277    MAIN    9794    CPU (aktuell): 3%    Ok
2016-02-24 00:00:00    227413    MAIN    9794    RAM (aktuell): 1019936MB / 194692MB / 19% benutzt    Ok
2016-02-24 00:00:00    231028    MAIN    9794    HDD (aktuell): 18536MB / 16447MB / 12% benutzt    Ok
2016-02-24 00:00:00    232953    MAIN    9794    CPU/RAM/HDD (Peaks: Vortag): CPU 9% / RAM 19% / HDD 12%    Ok
2016-02-24 00:00:00    234894    MAIN    9794    PHP/HTTP/SH (Peaks: Gesamt): PHP 4 / HTTP 4 / DB-Tables 63    Ok
2016-02-24 00:00:00    283210    EXEC    26664    Logs/Archive/Autobackups aufräumen    Ok
2016-02-24 00:00:00    383060    EXEC    26685    Autobackup erstellen: 2016-02-24-000000.edomibackup    Ok
2016-02-24 10:26:43    461488    MAIN    9794    Prozess MAIN beenden... (Modus 13)    Ok
2016-02-24 10:26:46    479419    KNX    9843    MAIN-SIGNAL erhalten -> Beenden...    Ok
2016-02-24 10:26:46    490271    KNX    9843    Prozess KNX beenden...    Ok
2016-02-24 10:26:46    490891    KNX    9843    mySQL disconnect    Ok
2016-02-24 10:26:46    490945    KNX    9843    Exit.    Ok
2016-02-24 10:26:46    572273    MAIN    9794    Prozess KNX (PID=9843) beenden    Ok
2016-02-24 10:26:46    576155    LOGIC    9845    MAIN-SIGNAL erhalten -> Beenden...    Ok
2016-02-24 10:26:46    586899    LOGIC    9845    Prozess LOGIC beenden...    Ok
2016-02-24 10:26:46    587083    LOGIC    9845    mySQL disconnect    Ok
2016-02-24 10:26:46    587121    LOGIC    9845    Exit.    Ok
2016-02-24 10:26:46    673989    MAIN    9794    Prozess LOGIC (PID=9845) beenden    Ok
2016-02-24 10:26:46    712121    QUEUE    9797    MAIN-SIGNAL erhalten -> Beenden...    Ok
2016-02-24 10:26:46    812786    QUEUE    9797    Prozess QUEUE beenden...    Ok
2016-02-24 10:26:46    812921    QUEUE    9797    mySQL disconnect    Ok
2016-02-24 10:26:46    812944    QUEUE    9797    Exit.    Ok
2016-02-24 10:26:46    877300    MAIN    9794    Prozess QUEUE (PID=9797) beenden    Ok
2016-02-24 10:26:46    880059    MAIN    9794    db.RAMsysInfo löschen    Ok
2016-02-24 10:26:46    881365    MAIN    9794    db.RAMcmdQueue löschen    Ok
2016-02-24 10:26:46    882389    MAIN    9794    db.RAMko löschen    Ok
2016-02-24 10:26:46    883431    MAIN    9794    db.RAMlogicElement löschen    Ok
2016-02-24 10:26:46    884291    MAIN    9794    db.RAMlogicElementVar löschen    Ok
2016-02-24 10:26:46    885179    MAIN    9794    db.RAMlogicLink löschen    Ok
2016-02-24 10:26:46    886544    MAIN    9794    db.RAMlogicCmdList löschen    Ok
2016-02-24 10:26:46    887705    MAIN    9794    db.RAMknxRead löschen    Ok
2016-02-24 10:26:46    905824    MAIN    9794    db.RAMknxWrite löschen    Ok
2016-02-24 10:26:49    908133    MAIN    9794    mySQL disconnect    Ok
2016-02-24 10:26:49    909063    MAIN    9794    sRAM 1 löschen    Ok
2016-02-24 10:26:49    909846    MAIN    9794    sRAM 2 löschen    Ok
2016-02-24 10:26:49    910610    MAIN    9794    sRAM 3 löschen    Ok
2016-02-24 10:26:49    911348    MAIN    9794    sRAM 4 löschen    Ok
2016-02-24 10:26:49    912475    MAIN    9794    sRAM 5 löschen    Ok
2016-02-24 10:26:49    913248    MAIN    9794    sRAM 6 löschen    Ok
2016-02-24 10:26:49    914022    MAIN    9794    sRAM 10 (KoMonitor) löschen    Ok
2016-02-24 10:26:49    919517    MAIN    9794    Prozess MAIN -> EXIT(13)    Ok
2016-02-24 10:27:49    167968    MAIN    1421    Prozess MAIN gestartet    Ok
2016-02-24 10:27:49    168629    MAIN    1421    EDOMI: Version 1.18    Ok
2016-02-24 10:27:49    168668    MAIN    1421    EDOMI wurde rebootet    Ok
2016-02-24 10:27:49    170633    MAIN    1421    Check: 64-Bit-System?    Ok
2016-02-24 10:27:49    170720    MAIN    1421    Check: PHP-Version 5.3.3?    Ok
2016-02-24 10:27:49    170753    MAIN    1421    PHP-Zeitzone: Europe/Berlin (Winterzeit)    Ok
2016-02-24 10:27:49    171710    MAIN    1421    mySQL: Connect    Ok
2016-02-24 10:27:49    239923    MAIN    1421    Check: 87 Datenbanken überprüft (0 Fehler)    Ok
2016-02-24 10:27:49    240042    MAIN    1421    mySQL: RAM reservieren (50 MB pro RAM-DB)    Ok
2016-02-24 10:27:49    251678    MAIN    1421    db.edomiLive erstellen    Ok
2016-02-24 10:27:49    251816    MAIN    1421    sRAM 1 löschen    Ok
2016-02-24 10:27:49    251871    MAIN    1421    sRAM 2 löschen    Ok
2016-02-24 10:27:49    251907    MAIN    1421    sRAM 3 löschen    Ok
2016-02-24 10:27:49    251935    MAIN    1421    sRAM 4 löschen    Ok
2016-02-24 10:27:49    251964    MAIN    1421    sRAM 5 löschen    Ok
2016-02-24 10:27:49    251991    MAIN    1421    sRAM 6 löschen    Ok
2016-02-24 10:27:49    252038    MAIN    1421    sRAM 1 erstellen    Ok
2016-02-24 10:27:49    252084    MAIN    1421    sRAM 2 erstellen    Ok
2016-02-24 10:27:49    252120    MAIN    1421    sRAM 3 erstellen    Ok
2016-02-24 10:27:49    252214    MAIN    1421    sRAM 4 erstellen    Ok
2016-02-24 10:27:49    252254    MAIN    1421    sRAM 5 erstellen    Ok
2016-02-24 10:27:49    252288    MAIN    1421    sRAM 6 erstellen    Ok
2016-02-24 10:27:49    253266    MAIN    1421    sRAM 10 (KoMonitor) löschen    Ok
2016-02-24 10:27:49    254292    MAIN    1421    sRAM 10 (KoMonitor) erstellen    Ok
2016-02-24 10:27:49    254494    MAIN    1421    Queue löschen    Ok
2016-02-24 10:27:49    256681    MAIN    1421    Queue erstellen    Ok
2016-02-24 10:27:49    258976    MAIN    1421    Prozess QUEUE starten    Ok
2016-02-24 10:27:49    268608    MAIN    1421    Visualisierungen inititalisieren    Ok
2016-02-24 10:27:49    272419    QUEUE    1426    Prozess QUEUE gestartet    Ok
2016-02-24 10:27:49    282869    MAIN    1421    Queue leeren    Ok
2016-02-24 10:27:49    291667    MAIN    1421    db.RAMko löschen    Ok
2016-02-24 10:27:49    294514    MAIN    1421    db.RAMko kopieren    Ok
2016-02-24 10:27:49    296928    MAIN    1421    db.RAMko modifizieren    Ok
2016-02-24 10:27:49    299433    MAIN    1421    db.RAMko index erstellen    Ok
2016-02-24 10:27:49    299545    MAIN    1421    db.RAMlogicElement löschen    Ok
2016-02-24 10:27:49    301218    MAIN    1421    db.RAMlogicElement kopieren    Ok
2016-02-24 10:27:49    302895    MAIN    1421    db.RAMlogicElement index erstellen    Ok
2016-02-24 10:27:49    302994    MAIN    1421    db.RAMlogicElementVar löschen    Ok
2016-02-24 10:27:49    304224    MAIN    1421    db.RAMlogicElementVar kopieren    Ok
2016-02-24 10:27:49    305443    MAIN    1421    db.RAMlogicElementVar index erstellen    Ok
2016-02-24 10:27:49    305517    MAIN    1421    db.RAMlogicLink löschen    Ok
2016-02-24 10:27:49    307331    MAIN    1421    db.RAMlogicLink kopieren    Ok
2016-02-24 10:27:49    309705    MAIN    1421    db.RAMlogicLink index erstellen    Ok
2016-02-24 10:27:49    309838    MAIN    1421    db.RAMlogicCmdList löschen    Ok
2016-02-24 10:27:49    311278    MAIN    1421    db.RAMlogicCmdList kopieren    Ok
2016-02-24 10:27:49    312794    MAIN    1421    db.RAMlogicCmdList index erstellen    Ok
2016-02-24 10:27:49    312918    MAIN    1421    db.RAMknxRead löschen    Ok
2016-02-24 10:27:49    313996    MAIN    1421    db.RAMknxRead erstellen    Ok
2016-02-24 10:27:49    314074    MAIN    1421    db.RAMknxWrite löschen    Ok
2016-02-24 10:27:49    315356    MAIN    1421    db.RAMknxWrite erstellen    Ok
2016-02-24 10:27:49    317734    MAIN    1421    Prozess KNX starten    Ok
2016-02-24 10:27:49    319683    MAIN    1421    Prozess LOGIC starten    Ok
2016-02-24 10:27:49    332922    KNX    1432    Prozess KNX gestartet    Ok
2016-02-24 10:27:49    334028    KNX    1432    Control-Endpoint: 192.168.22.152:50000    Ok
2016-02-24 10:27:49    334140    KNX    1432    Data-Endpoint: 192.168.22.152:50001    Ok
2016-02-24 10:27:49    339353    LOGIC    1434    Prozess LOGIC gestartet    Ok
2016-02-24 10:27:49    372581    MAIN    1421    KNX-Verbindung abwarten    Ok
2016-02-24 10:27:49    389229    KNX    1432    Tunnel-PA: 1.0.253 / Channel-ID: 29    Ok
2016-02-24 10:27:50    384005    MAIN    1421    INIT    Ok
2016-02-24 10:27:50    385416    MAIN    1421    InitSend (0 GAs)    Ok
2016-02-24 10:27:50    385514    MAIN    1421    InitScan: Abfrage 1...    Ok
2016-02-24 10:27:52    946821    MAIN    1421    InitScan: Check (max. 30 Zyklen)...    Ok
2016-02-24 10:28:23    298758    MAIN    1421    InitScan: Abfrage 2...    Ok
2016-02-24 10:28:23    912877    MAIN    1421    InitScan: Check (max. 30 Zyklen)...    Ok
2016-02-24 10:28:24    922513    MAIN    1421    InitScan (12 GAs / 2 Abfragen / 32 Checks)    Ok
2016-02-24 10:28:24    926038    MAIN    1421    Logik-Bausteine initialisieren...    Ok
2016-02-24 10:28:25    023477    LOGIC    1434    Logik-Init: Alle (317) Bausteine initialisiert    Ok
2016-02-24 10:28:25    023585    LOGIC    1434    Logik-Berechnungen werden aktiviert    Ok
2016-02-24 10:28:25    044296    MAIN    1421    START    Ok
2016-02-24 10:28:25    128627    EXEC    1552    Logs/Archive/Autobackups aufräumen    Ok
2016-02-24 13:35:56    065254    KNX    1432    ROUTER @ CE | DISCONNECT_REQUEST / Raw: 0610020900101d000801c0a8165f0e57    ERROR

Wobei die relavante Zeile im Systemlog das sein dürfte:
2016-02-24 10:27:49 239923 MAIN 1421 Check: 87 Datenbanken überprüft (0 Fehler) Ok

PS: Als ich die Datei lokal liegen hatte und versuchte sie mit FF zu öffnen, stürzte FF einfach ab. Notepad++ wollte die Datei auch nicht, nur im normalen Windowseditor ging sie auf. 937MB sind halt heftig...

[gaert]

Ich kann es mir nicht erklären... Die Fehlermeldung als solches ist schon verständlich (für mich), aber die Ursache ist mir vollkommen schleierhaft. Zumal ich während der Entwicklung schon so manches erlebt und getestet habe

Warte am Besten einfach mal die kommende 1.19 ab - da habe ich sehr viele Änderungen "an der Basis" vorgenommen (vielleicht habe ich dabei zufällig auch Deinen Fehler erwischt...).

[DirtyHarry]

Wie schon gesagt, bis Mittwoch werde ich auf alle Fälle abwarten, ohne Änderungen und ohne Neustart. Und wenn es nur aus Neugierde ist.

[gaert]

Fehler gefunden... Es war an manchen Stellen noch die alte mysql-Lib in Verwendung (gibt eine Ressource-ID zurück). Und auf manchen System führt dies irgendwann zu einem Overflow, da die ID nur 32-bittig ist. Wird mit 1.19 dann behoben - danke für den Hinweis!

[DirtyHarry]

[DirtyHarry]

Wie eigentlich schon erwartet kam gestern Abend der Fehler wieder (LOG-Datei von 2GB ).

Heute dann das Update auf 1.19 und 1.20 durchgezogen, der Fehler sollte dann ja nicht mehr kommen.

PS: Beim Update auf die 1.19 hat es die remanten Daten inkl. Daten-/Meldungsarchiven weggehauen, beim anschließenden Update auf die 1.20 hat es die 3 neuen Daten drin gelassen. Schade, aber was solls, ist ja sowieso nur zum Testen.

[gaert]

Das habe ICH nicht erwartet - denn ab Version 1.19(!) ist bereits vollständig auf mysqli umgestellt (d.h. es wird keine Ressource-ID mehr benötigt, da mysqli-Funktionen ein Objekt zurückgeben).

Das Problem mit den Archiven sollte mit 1.20 gelöst sein - siehe Changelog.

By the way: Bist Du sicher, dass Deine Plattform 64-bit-fähig ist?

[DirtyHarry]

Heute dann das Update auf 1.19 und 1.20 durchgezogen,...

Deswegen wie erwartet, war ja noch 1.18. Ich hab ja schon vorher geschrieben, ich warte aus neugierde ab...

[gaert]

Achso - ich hatte Dich so verstanden, dass die 1.19 schon installiert war...