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