Pot. Redis Crash mit Admin-Log-Funktion
-
Hey Bluefox, hey All,
ich habe hier ein merkwürdiges Problem, aber inzwischen habe ich ne genaue Idee wo es herkommt.
Ich nutze Redis für die States-DB.
Im Rahmen der Tests mit dem InfluxDB-Adapter habe ich mal alle Datenpunkte eingeschaltet. Das sind bei mir ca. 2.800 Stück und an sich klappt das auch alles.
Wenn ich den InfluxDB-Adapter per Admin-Oberfläche neu gestartet habe, hat der Redis-Prozess plötzlich in sehr kurzer Zeit des gesamten Systemspeicher gefressen, System hat geswappt und irgendwann später (nach einigen Minuten wo nichts mehr ging) hat der OOMKiller den Redis gekillt. Danach ging alles wieder.
Ich habe lange nach der Ursache gesucht und jetzt gefunden:
Ursache ist der Redis-Client der Admin-Instanz die gerade im Browser läuft. Der Redis-Prozess hängt scheinbar bei einem "lrange"-Befehl bzw die Admin-Instanz scheint irgendwie die Antwort nicht mehr sinnvoll zu verarbeiten und damit sammeln sich die Antworten im Redis und fressen sehr schnell viele Ressourcen.
Ich habe es verifiziert indem ich den Adapter per Kommandozeile und ohne Admin-Adapter neu gestartet habe und es geht.
Der Quick-Hack ist jetzt im Redis einen Output-Buffer-Limit zu definieren.Dann wird die "hängende" Redis-verbindung gekillt wenn das Limit erreicht ist.
Log-Ausgabe wenn das passiert ist:
` > 2016-11-14 21:57:26.549 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:26.554 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:26.556 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:26.558 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:26.561 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:26.563 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:43.814 - error: host. Ready check failed: Fatal error encountert. Command aborted. It might have been processed.
2016-11-14 21:57:43.818 - error: host. AbortError: Ready check failed: Fatal error encountert. Command aborted. It might have been processed.
at RedisClient.flush_and_error (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/index.js:350:23)
at JavascriptRedisParser.Parser.returnFatalError (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/index.js:199:18)
at handleError (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:178:10)
at parseType (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:233:14)
at parseArray (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:201:20)
at parseType (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:226:14)
at JavascriptRedisParser.execute (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:421:20)
at Socket. <anonymous>(/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/index.js:267:27)
at emitOne (events.js:77:13)
at Socket.emit (events.js:169:7)
2016-11-14 21:57:43.820 - error: host. Protocol error, got "3" as reply type byte. Please report this.
2016-11-14 21:57:43.825 - error: host. ReplyError: Protocol error, got "3" as reply type byte. Please report this.
at parseType (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:230:17)
at parseArray (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:201:20)
at parseType (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:226:14)
at JavascriptRedisParser.execute (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:421:20)
at Socket. <anonymous>(/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/index.js:267:27)
at emitOne (events.js:77:13)
at Socket.emit (events.js:169:7)
at readableAddChunk (_stream_readable.js:153:18)
at Socket.Readable.push (_stream_readable.js:111:10)
at TCP.onread (net.js:537:20)
2016-11-14 21:57:54.834 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.839 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.842 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.844 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.847 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.850 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.852 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.861 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.863 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.866 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.869 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:57:54.871 - warn: host. AbortError: Redis connection lost and command aborted. It might have been processed.
2016-11-14 21:58:11.899 - error: host. Ready check failed: Fatal error encountert. Command aborted. It might have been processed.
2016-11-14 21:58:11.903 - error: host. AbortError: Ready check failed: Fatal error encountert. Command aborted. It might have been processed.
at RedisClient.flush_and_error (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/index.js:350:23)
at JavascriptRedisParser.Parser.returnFatalError (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/index.js:199:18)
at handleError (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:178:10)
at parseType (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:233:14)
at parseArray (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:201:20)
at parseType (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:226:14)
at JavascriptRedisParser.execute (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:421:20)
at Socket. <anonymous>(/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/index.js:267:27)
at emitOne (events.js:77:13)
at Socket.emit (events.js:169:7)
2016-11-14 21:58:11.904 - error: host. Protocol error, got "3" as reply type byte. Please report this.
2016-11-14 21:58:11.911 - error: host. ReplyError: Protocol error, got "3" as reply type byte. Please report this.
at parseType (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:230:17)
at parseArray (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:201:20)
at parseType (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:226:14)
at JavascriptRedisParser.execute (/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/node_modules/redis-parser/lib/parser.js:421:20)
at Socket. <anonymous>(/opt/iobroker/node_modules/iobroker.js-controller/node_modules/redis/index.js:267:27)
at emitOne (events.js:77:13)
at Socket.emit (events.js:169:7)
at readableAddChunk (_stream_readable.js:153:18)
at Socket.Readable.push (_stream_readable.js:111:10)
at TCP.onread (net.js:537:20)</anonymous></anonymous></anonymous></anonymous> `
Meine Vermutung ist: Der InflucDB-Adapter gibt, wie auch History zum Start per Loglevel Info (und ich nutze Info) alle Datenpunkte aus. Das sind also 2800 Zeilen Log-Output in sehr kurzer Zeit. Dann scheint es irgendwie bei der Verarbeitung der ganzen Logzeilen im Admin-Adapter zu Haken.
Ursache kann (wenn ich richtig gesucht habe) an sich nur die Implementierung von "delLog" in statesInRedis (Zeile 446ff) sein. Die scheint immer einzelne Logzeilen zu löschen und holt dafür alle Log-messages aus der Redis um eine zu suchen und zu löschen. Bei der Anzahl an Logzeilen (2800) und einer kleiner maximalen Loganzahl für die Anzeige endet das in ziemlichem Chaos und vielen parallel laufenden Dingen.
Da sollte man ggf was ändern …
@Bluefox: So tief kam ich, da ist jetzt grad bei mir schluss. Einzige Idee die ich habe wäre "delLog" nicht sofort abzuarbeiten sondern ein bissl zu verzögern und ggf zu sammeln was gelöscht werden soll
Ingo F
