FATAL: terminating connection due to administrator command

[Marvin G. - FZJ]

Hallo zusammen,

wir haben bei uns in unregelmäßigen Abständen das Problem, dass KIX 18 plötzlich nicht mehr erreichbar ist. Also, die Seite lässt sich öffnen, aber bis auf das Ladesymbol passiert da nichts. Heute hatten wir wieder das Problem und im Log habe ich jetzt folgendes gefunden:

Code Auswählen Erweitern

[Fri Apr 28 06:25:13 2023][Error][Kernel::System::Daemon::SchedulerDB::FutureTaskToExecute][1246] FATAL:  terminating connection due to administrator command
server closed the connection unexpectedly
 This probably means the server terminated abnormally
 before or while processing the request., SQL: '
            UPDATE scheduler_future_task
            SET lock_key = ?, lock_time =
        '2023-04-28 06:25:13'
   
            WHERE lock_key = 0 AND execution_time <= ?'
[Fri Apr 28 06:25:15 2023][Error][Kernel::System::Daemon::SchedulerDB::TaskListUnlocked][420] FATAL:  terminating connection due to administrator command
server closed the connection unexpectedly
 This probably means the server terminated abnormally
 before or while processing the request., SQL: 'SELECT id FROM scheduler_task WHERE lock_key = 0 ORDER BY id ASC'
[Fri Apr 28 06:25:15 2023][Error][Kernel::System::Daemon::SchedulerDB::RecurrentTaskUnlockExpired][2188] server closed the connection unexpectedly
 This probably means the server terminated abnormally
 before or while processing the request., SQL: '
            SELECT id, name, lock_time
            FROM scheduler_recurrent_task
            WHERE task_type = ?
                AND lock_key <> 0
            ORDER BY id ASC'
Interessanterweise passiert dies auf zwei KIX 18 Systemen, fast gleichzeitig. In den Jobs habe ich nichts gefunden, was zu dem Zeitpunkt läuft. Wenn ich die Server mit dem Restart-Skript neu starte läuft alles wieder.

 Hat jemand eine Idee, was hier das Problem ist und wie ich das unterbinden kann?

Viele Grüße
Marvin

[Benedikt Geißler]

Hallo Marvin,

falls es nochmal passiert: was steht denn im Log des Datenbank-Containers?

Code Auswählen Erweitern

docker logs kix_db_1
Wurde evtl. nach einem Reboot des Servers nicht der vollständige KIX18-Stack wieder gestartet?

Viele Grüße,
Benedikt

[Marvin G. - FZJ]

Hallo Benedikt,

jetzt ist es wieder passiert, leider aber schon am Sonntagabend und jetzt wird es auch schon schwierig mit logs, da die Container gestern Abend auch wieder neu gestartet wurden, sind die Logs von Sonntag nicht mehr da.

Bezüglich des vollständigen Restarts: Ich habe über unser gitlab einen Job laufen, der per Ansible die Container stoppt, ein Backup macht und anschließend neu startet. Das läuft jeden Tag am Abend und funktioniert auch so gut wie immer. Nur zwischendurch (es waren jetzt drei Wochen ohne Probleme) kommt es halt zu diesen Problemen. Laut dem Ansible-Playbook läuft auch alles. Das es Probleme gibt merke ich dann erst, wenn unser Monitoring ein "502 Bad Gateway" für https meldet. Wenn ich dann per Skript die Container manuell neu starte, geht es wieder. Wenn ich mir die Container aufliste, dann laufen sie auch alle. 

Ich werde es weiter beobachten und hoffentlich nächstes mal die logs bekommen, die ich brauche.

Viele Grüße
Marvin

[Marvin G. - FZJ]

Hallo Benedikt,

gestern Abend war der Fehler wieder da. Heute stand folgendes im DB-Log:

Code Auswählen Erweitern

PostgreSQL Database directory appears to contain a database; Skipping initialization

2023-05-31 06:03:58.247 GMT [1] LOG:  starting PostgreSQL 12.15 on x86_64-pc-linux-musl, compiled by gcc (Alpine 12.2.1_git20220924-r10) 12.2.1 20220924, 64-bit
2023-05-31 06:03:58.247 GMT [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-05-31 06:03:58.247 GMT [1] LOG:  listening on IPv6 address "::", port 5432
2023-05-31 06:03:58.364 GMT [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-05-31 06:03:58.790 GMT [22] LOG:  database system was shut down at 2023-05-31 06:03:21 GMT
2023-05-31 06:03:58.947 GMT [1] LOG:  database system is ready to accept connections
2023-05-31 06:05:03.161 GMT [49] ERROR:  duplicate key value violates unique constraint "service_pkey"
2023-05-31 06:05:03.161 GMT [49] DETAIL:  Key (id)=(6) already exists.
2023-05-31 06:05:03.161 GMT [49] STATEMENT:  INSERT INTO service (id, name, number, parent_id, valid_id, comments, create_time, create_by, change_time, change_by) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)

Hilft das?

Viele Grüße
Marvin

[Benedikt Geißler]

Hallo Marvin,

in dem Log sieht man, dass der PostgreSQL-Container um 06:03:21 GMT (also wohl gegen 08:03 Uhr gestoppt und kurz darauf wieder normal gestartet wurde. Dass anschließend die Primärschlüsselbedingung beim Servicekatalog verletzt wird, ist ungewöhnlich, sollte aber nicht den PostgreSQL-Dienst im Container beeinträchtigen.

Gibt es vielleicht noch relevante Einträge im Systemlog dazu? Einzusehen ist das z. B. mittels

Code Auswählen Erweitern

journalctl --since '2023-05-31 07:50' --until '2023-05-31 08:10'um etwa den Zeitraum zwischen 7:50 und 8:10 abzurufen.

Viele Grüße
Benedikt

[Marvin G. - FZJ]

Hallo Benedikt,

ich hab im journalctl jetzt nichts relevantes entdeckt. Die einzigen Fehler scheinen solche hier zu sein:

Code Auswählen Erweitern

May 31 07:59:27 kix18-prod ntpd[610]: bind(31) AF_INET6 fe80::1cb6:fdff:fe3c:35b2%139#123 flags 0x11 failed: Cannot assign requested address
May 31 07:59:27 kix18-prod ntpd[610]: unable to create socket on veth8120a57 (105) for fe80::1cb6:fdff:fe3c:35b2%139#123
Ich schätze mal, dass das nicht das Problem sein wird. Zumal diese Meldungen auch nicht um 08:21 Uhr rum kommen.

Ich hänge das log mal an.

Viele Grüße
Marvin

[Benedikt Geißler]

Hast du im docker-compose.yml auch bei allen Containern "restart: always" hinzugefügt wie hier?

 

Evtl. fehlt das noch irgendwo, sodass es erst nach manuellem Restart wieder funktioniert?

VG Benedikt

[Marvin G. - FZJ]

Hallo Benedikt,

vielen dank für den Hinweis. Das habe ich in der Tat nicht, da es in eurem compose-File von github auch nicht mit drin ist.
Ich habe das nun mal ergänzt und werde es die nächsten Tage/Wochen mal beobachten.

Viele Grüße
Marvin

[Marvin G. - FZJ]

Hallo Benedikt,

leider ist der Fehler immer noch da. Das einzige was ich jetzt noch gefunden habe, ist folgender Fehler im Frontend-Log:

Code Auswählen Erweitern

Tue Jun 27 2023 17:37:35 GMT+0000 (Coordinated Universal Time) - error: 84 - Error during HTTP (session/user) GET request.
Tue Jun 27 2023 17:37:35 GMT+0000 (Coordinated Universal Time) - error: 84 - (401) Unauthorized User is not authorized. The requested operation cannot be executed.
Tue Jun 27 2023 17:37:35 GMT+0000 (Coordinated Universal Time) - error: uncaughtException: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "#<Error>".
UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "#<Error>".
Viele Grüße
Marvin