fraport/fradrive-old
fraport/fradrive-old
Archived
3
1
Fork 0
Code Issues 65 Pull Requests 5 Actions Packages Projects Releases 197 Wiki Activity

Klärung FRADrive funktionierte nicht mehr #133

New Issue
Closed
opened 2023-11-28 13:55:56 +01:00 by jost · 28 comments
jost commented 2023-11-28 13:55:56 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Am 28.11.2023 reagierte FRADrive nicht mehr. Die Status Seite, Aktuelles und auch Druckerei funktionierten, aber sonst fast nichts mehr.

Was könnte die Ursache gewesen sein?

Wie ist ein erneutes auftreten zu verhindern?

TimeGenerated [UTC]

2023-11-28 12:45:03 +0000 [Warn#runSqlPoolRetry] [retry:12] Encountered libpq: failed (FATAL:  remaining connection slots are reserved for non-replication superuser connections
2023-11-28 12:45:03 +0000 [Error#yesod] Exception from Warp: libpq: failed (FATAL:  remaining connection slots are reserved for non-replication superuser connections
2023-11-28 12:44:55 +0000 [Warn#JobPoolManager] Moved 140 long-unadressed jobs from 4 senders to 3 receivers @(uniworx-27.4.49-AnWhSzn0HXl3cPiyDU5VOl:Jobs src/Jobs.hs:311:16)
2023-11-28 12:44:48 +0000 [Error#yesod-core] Error handler errored out: InternalError "libpq: failed (FATAL:  remaining connection slots are reserved for non-replication superuser connections\n)" @(yesod-core-1.6.20.2-7VqWGURyzmdJ8HRF4U5pfA:Yesod.Core.Internal.Run src/Yesod/Core/Internal/Run.hs:210:21)
Am 28.11.2023 reagierte FRADrive nicht mehr. Die Status Seite, Aktuelles und auch Druckerei funktionierten, aber sonst fast nichts mehr. Was könnte die Ursache gewesen sein? Wie ist ein erneutes auftreten zu verhindern? TimeGenerated \[UTC\] ```plaintext 2023-11-28 12:45:03 +0000 [Warn#runSqlPoolRetry] [retry:12] Encountered libpq: failed (FATAL: remaining connection slots are reserved for non-replication superuser connections 2023-11-28 12:45:03 +0000 [Error#yesod] Exception from Warp: libpq: failed (FATAL: remaining connection slots are reserved for non-replication superuser connections 2023-11-28 12:44:55 +0000 [Warn#JobPoolManager] Moved 140 long-unadressed jobs from 4 senders to 3 receivers @(uniworx-27.4.49-AnWhSzn0HXl3cPiyDU5VOl:Jobs src/Jobs.hs:311:16) 2023-11-28 12:44:48 +0000 [Error#yesod-core] Error handler errored out: InternalError "libpq: failed (FATAL: remaining connection slots are reserved for non-replication superuser connections\n)" @(yesod-core-1.6.20.2-7VqWGURyzmdJ8HRF4U5pfA:Yesod.Core.Internal.Run src/Yesod/Core/Internal/Run.hs:210:21) ```
jost commented 2023-11-28 13:55:57 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

assigned to @savau

assigned to @savau
jost commented 2023-11-28 13:56:34 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

mentioned in issue #2

mentioned in issue #2
jost commented 2023-11-28 13:57:33 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Log der letzten 4 Stunden, inklusive Neustart am Ende:

Azure Monitor Log Analytics Export - 2023-11-28.xlsx

Log der letzten 4 Stunden, inklusive Neustart am Ende: [Azure Monitor Log Analytics Export - 2023-11-28.xlsx](/uploads/a4ec03b8244529df5f334422050dfdb1/Azure_Monitor_Log_Analytics_Export\_-\_2023-11-28.xlsx)
jost commented 2023-11-28 14:21:13 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Probleme wurden um ca. 11:35UTC zum ersten Mal berichtet. Ab 11:30UTC häufen sich die "moved long-unadressed jobs" Meldungen in der DB, in den 24 Stunden vor 11:14UTC taucht die Meldung nicht auf.

Zuerst gesehen Meldung
12:43:56UTC FATAL: remaining connection slots are reserved for nn-replication superuser connections
11:14:01UTC Moved # long-unadressed jobs from 1 senders to 11 receivers
11:22:47 Saw nonexistant queue id: 1292888
Probleme wurden um ca. 11:35UTC zum ersten Mal berichtet. Ab 11:30UTC häufen sich die "moved long-unadressed jobs" Meldungen in der DB, in den 24 Stunden vor 11:14UTC taucht die Meldung nicht auf. | Zuerst gesehen | Meldung | |----------------|---------| | 12:43:56UTC | FATAL: remaining connection slots are reserved for nn-replication superuser connections | | 11:14:01UTC | Moved # long-unadressed jobs from 1 senders to 11 receivers | | 11:22:47 | Saw nonexistant queue id: 1292888 |
jost commented 2023-11-28 14:21:30 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

changed the severity to High - S2

changed the severity to **High - S2**
savau commented 2023-11-28 16:18:03 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Der Auszug aus dem Log (insbes. die Meldung FATAL: remaining connection slots are reserved for nn-replication superuser connections) legt nahe, dass die Datenbank-Verbindungen ausgegangen zu sein schienen.

Als Quickfix könnte es helfen, die Anzahl erlaubter paralleler Verbindungen zu erhöhen.
Dafür gibt es ein AppSetting unter database.poolsize.

Wie viele Job-Worker sind in Prod denn aktuell konfiguriert? Und entnehme ich dem Issue richtig, dass das Problem Prod betraf und Test insbes. nicht?

Der Auszug aus dem Log (insbes. die Meldung `FATAL: remaining connection slots are reserved for nn-replication superuser connections`) legt nahe, dass die Datenbank-Verbindungen ausgegangen zu sein schienen. Als Quickfix könnte es helfen, die Anzahl erlaubter paralleler Verbindungen zu erhöhen. Dafür gibt es ein AppSetting unter `database.poolsize`. Wie viele Job-Worker sind in Prod denn aktuell konfiguriert? Und entnehme ich dem Issue richtig, dass das Problem Prod betraf und Test insbes. nicht?
jost commented 2023-11-28 16:23:28 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Ja, es betraf Prod und nicht test. Ich vermute, dass die fehlenden Verbindungen nur ein Symptom sind. Zuerst tauchten ja diese long-unadressed jobs auf, welche immer häufiger wiederholt wurden.

Außerdem wurde ja deutlich vorher berichtet, dass FRADrive nicht benutzbar wäre, bevor die Log Meldungen über den Mangel der Verbindungen kamen!

Ja, es betraf Prod und nicht test. Ich vermute, dass die fehlenden Verbindungen nur ein Symptom sind. Zuerst tauchten ja diese `long-unadressed jobs` auf, welche immer häufiger wiederholt wurden. Außerdem wurde ja deutlich vorher berichtet, dass FRADrive nicht benutzbar wäre, bevor die Log Meldungen über den Mangel der Verbindungen kamen!
savau commented 2023-11-28 16:35:20 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Was ich mir auch vorstellen kann ist, dass das Jobsystem mit der Zeit bzw. mit steigender Nutzerzahl etc. zu langsam geworden ist und pro Iteration der Crontab nicht alle anstehenden Jobs berechnet/getriggert werden konnten. Die hätten sich dann über die Zeit anhäufen können, sodass sich eine Menge Retries ansammeln könnte.

Die Poolsize zu erhöhen wäre definitiv nur Symptombekämpfung, aber vielleicht einen Versuch wert wenn das nochmal auftreten sollte.
Ich kann mir wie oben erwähnt gut vorstellen, dass die Ursache in der Implementierung des alten Jobsystems liegt, die aus meiner Sicht sinnvollste Behebung wäre es, die (aktuell ja eh schon laufende) Reimplementierung des Jobsystems höher zu priorisieren.

Was ich mir auch vorstellen kann ist, dass das Jobsystem mit der Zeit bzw. mit steigender Nutzerzahl etc. zu langsam geworden ist und pro Iteration der Crontab nicht alle anstehenden Jobs berechnet/getriggert werden konnten. Die hätten sich dann über die Zeit anhäufen können, sodass sich eine Menge Retries ansammeln könnte. Die Poolsize zu erhöhen wäre definitiv nur Symptombekämpfung, aber vielleicht einen Versuch wert wenn das nochmal auftreten sollte. Ich kann mir wie oben erwähnt gut vorstellen, dass die Ursache in der Implementierung des alten Jobsystems liegt, die aus meiner Sicht sinnvollste Behebung wäre es, die (aktuell ja eh schon laufende) Reimplementierung des Jobsystems höher zu priorisieren.
jost commented 2023-11-28 16:36:37 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Aber müssten wir im Log dann nicht irgendwo den Cron Trigger sehen?

Aber müssten wir im Log dann nicht irgendwo den Cron Trigger sehen?
savau commented 2023-11-28 16:38:33 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Ja, der kann aber eine ganze Weile lang in der Vergangenheit liegen. Schau' mal nach Crontriggern in der Zeit zwischen ca. 01:00 Uhr und 04:00 Uhr nachts, da werden normalerweise die üblichen Schuldigen ausgeführt (= ressourcenaufwändigere Cleanup-Jobs).

Ja, der kann aber eine ganze Weile lang in der Vergangenheit liegen. Schau' mal nach Crontriggern in der Zeit zwischen ca. 01:00 Uhr und 04:00 Uhr nachts, da werden normalerweise die üblichen Schuldigen ausgeführt (= ressourcenaufwändigere Cleanup-Jobs).
jost commented 2023-11-28 16:39:33 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Aber woran erkenne ich denn den Schuldigen?

Aber woran erkenne ich denn den Schuldigen?
jost commented 2023-11-28 16:40:19 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Bzw. ich weiß, dass ca. 2 Stunden vorher manuell AVS Synchs für ca. 30 Nutzer ausgelöst wurden. Bei der geringen Anzahl sollten die ja locker vorher abgearbeitet worden sein.

Weiterhin sollten die Background Jobs doch nur den JobWorker lahmlegen - wieso war aber der Webserver betroffen, der keine Background Jobs ausführt?

Hat nicht jede Instanz einen eigenen DB Connection Pool?

Bzw. ich weiß, dass ca. 2 Stunden vorher manuell AVS Synchs für ca. 30 Nutzer ausgelöst wurden. Bei der geringen Anzahl sollten die ja locker vorher abgearbeitet worden sein. Weiterhin sollten die Background Jobs doch nur den JobWorker lahmlegen - wieso war aber der Webserver betroffen, der keine Background Jobs ausführt? Hat nicht jede Instanz einen eigenen DB Connection Pool?
savau commented 2023-11-28 16:46:40 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Die Crontab, d.h. die anstehenden Jobs, werden (aktuell noch) vom Webserver berechnet, nicht von den Jobworkern. Das ist auch der Grund, warum zu viele in der Vergangenheit liegen gebliebene Jobs den Webserver lahmlegen können und nicht nur die Jobworker überlasten. Im alten Jobsystem wird pro „Tick“ die Crontab vollständig neu berechnet, was mit steigender Jobzahl zunehmend rechenaufwändig wird und im Worst Case länger dauern kann als ein solcher „Tick“; dadurch wiederum steigt die Anzahl Jobs erneut. Der Webserver rechnet sich ab dann sozugagen lahm.

Auffällig wäre z.B. eine Anhäufung von „determineCrontab“-Logs dicht aufeinander, ohne sonstige Symptome tatsächlicher Abarbeitung (also Logs von Jobworkern).

Die Crontab, d.h. die anstehenden Jobs, werden (aktuell noch) vom Webserver berechnet, nicht von den Jobworkern. Das ist auch der Grund, warum zu viele in der Vergangenheit liegen gebliebene Jobs den Webserver lahmlegen können und nicht nur die Jobworker überlasten. Im alten Jobsystem wird pro „Tick“ die Crontab vollständig neu berechnet, was mit steigender Jobzahl zunehmend rechenaufwändig wird und im Worst Case länger dauern kann als ein solcher „Tick“; dadurch wiederum steigt die Anzahl Jobs erneut. Der Webserver rechnet sich ab dann sozugagen lahm. Auffällig wäre z.B. eine Anhäufung von „determineCrontab“-Logs dicht aufeinander, ohne sonstige Symptome tatsächlicher Abarbeitung (also Logs von Jobworkern).
jost commented 2023-11-28 16:55:01 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

`DetermineCrontab` sehe ich ungefähr einmal pro Minute im Log; sowohl weit vor dem Crash als auch jetzt nach dem Neustart. Um den Crash herum gibt es aber keine besondere Häufung. Manchmal sind es 3 pro Minute, aber dann meist nicht mehr in der Minute davor oder danach, also 1/Minute kommt gut hin.

\`DetermineCrontab\` sehe ich ungefähr einmal pro Minute im Log; sowohl weit vor dem Crash als auch jetzt nach dem Neustart. Um den Crash herum gibt es aber keine besondere Häufung. Manchmal sind es 3 pro Minute, aber dann meist nicht mehr in der Minute davor oder danach, also 1/Minute kommt gut hin.
savau commented 2023-11-28 18:01:31 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Was heißt denn „weit vor dem Crash“? Bereits vor heute Nacht, oder erst ab ca. 28.11. 00:00 Uhr?

Gibt es, zusätzlich zu den bis zu 3 DetermineCrontab-Logs pro Minute, zur gleichen Zeit noch „normale“ anderweitige Logs, oder ist es um die Gegend der Determine-Crontab-Logs herum auffällig still zufällig?

Was heißt denn „weit vor dem Crash“? Bereits vor heute Nacht, oder erst ab ca. 28.11. 00:00 Uhr? Gibt es, zusätzlich zu den bis zu 3 DetermineCrontab-Logs pro Minute, zur gleichen Zeit noch „normale“ anderweitige Logs, oder ist es um die Gegend der Determine-Crontab-Logs herum auffällig still zufällig?
jost commented 2023-11-28 18:03:37 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Ich würde sagen normal, also die GET Requests der Kubernetes Health Checks werden angezeigt wie üblich

Ich würde sagen normal, also die GET Requests der Kubernetes Health Checks werden angezeigt wie üblich
savau commented 2023-11-28 18:24:38 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Okay, das ist gut zu wissen. Ich würde vorschlagen, wir schauen uns den Incident auch nächsten Montag nochmal zusammen im Detail an.

Okay, das ist gut zu wissen. Ich würde vorschlagen, wir schauen uns den Incident auch nächsten Montag nochmal zusammen im Detail an.
jost commented 2023-11-28 18:51:00 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

@savau Das Problem taucht jetzt schon wieder auf! Wir können wohl nicht bis Montag warten.

Die einzige ungewöhnliche Log-Meldung ist wieder

2023-11-28 17:48:48 +0000 [Warn#JobPoolManager] Moved 2 long-unadressed jobs from 1 senders to 9 receivers @(uniworx-27.4.49-AnWhSzn0HXl3cPiyDU5VOl:Jobs src/Jobs.hs:311:16)
@savau Das Problem taucht jetzt schon wieder auf! Wir können wohl nicht bis Montag warten. Die einzige ungewöhnliche Log-Meldung ist wieder ```plaintext 2023-11-28 17:48:48 +0000 [Warn#JobPoolManager] Moved 2 long-unadressed jobs from 1 senders to 9 receivers @(uniworx-27.4.49-AnWhSzn0HXl3cPiyDU5VOl:Jobs src/Jobs.hs:311:16) ```
jost commented 2023-12-04 18:28:29 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Problem trat wieder auf, Log unauffällig; betroffene Routen: course, qualification, lms, school.

Beobachtung: DB Zugriffe per DB Visualizer auf Tabellen wie school waren auch nicht mehr möglich.

Vermutung

Aufgrund von aufwendigen Abfragen wurde das Autoscaling aktiv. Durch das hoch- und herunterfahren wurden einige DB Tabellen gelockt, da die Container nicht richtig heruntergefahren wurden.

Autoscaling wurde nun deaktiviert, wir beobachten erst einmal weiter. Autoscaling muss als eigenes Feature implementiert werden.

Problem trat wieder auf, Log unauffällig; betroffene Routen: course, qualification, lms, school. _Beobachtung:_ DB Zugriffe per DB Visualizer auf Tabellen wie `school` waren auch nicht mehr möglich. ## Vermutung Aufgrund von aufwendigen Abfragen wurde das Autoscaling aktiv. Durch das hoch- und herunterfahren wurden einige DB Tabellen gelockt, da die Container nicht richtig heruntergefahren wurden. Autoscaling wurde nun deaktiviert, wir beobachten erst einmal weiter. Autoscaling muss als eigenes Feature implementiert werden.
jost commented 2023-12-05 17:48:20 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Log der DB vom Montagabend postgreslogs.xlsx

Log der DB vom Montagabend [postgreslogs.xlsx](/uploads/c901115d3b3332b23bc968a13b3d65dd/postgreslogs.xlsx)
jost commented 2023-12-05 17:56:46 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Könnte das hier der Schuldige sein, der bei jedem Start ausgeführt wird: `2023-12-05 16:51:52 +0000 [Info#Migration] ALTER TABLE "school" ALTER COLUMN "exam_discouraged_modes" SET DEFAULT '{"dnf-terms":[]}' @(uniworx-27.4.52-6PTBos9Y81o24JudJr369Z:Model.Migration src/Model/Migration.hs:121:10)`

Könnte das hier der Schuldige sein, der bei jedem Start ausgeführt wird: \`2023-12-05 16:51:52 +0000 \[Info#Migration\] ALTER TABLE "school" ALTER COLUMN "exam_discouraged_modes" SET DEFAULT '{"dnf-terms":\[\]}' @(uniworx-27.4.52-6PTBos9Y81o24JudJr369Z:Model.Migration src/Model/Migration.hs:121:10)\`
jost commented 2023-12-12 12:33:26 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

mentioned in commit d4f0d69428

mentioned in commit d4f0d69428a4f7fc887cb6854cb59e3dea83b9bc
jost (Migrated from gitlab.uniworx.de) closed this issue 2023-12-13 16:35:45 +01:00
jost commented 2023-12-13 16:35:46 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

changed the incident status to Resolved by closing the incident

changed the incident status to **Resolved** by closing the incident
jost commented 2023-12-14 09:12:18 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Die Migration wurde offenbar wegen einem abweichenden Default versucht: Auf https://hackage.haskell.org/package/persistent-2.14.6.0/docs/Database-Persist-Quasi.html steht dazu

Note: Persistent determines whether or not to migrate a column's default value by comparing the exact string found in your models file with the one returned by the database. If a database canonicalizes the SQL FALSE from your models file to false in the database, Persistent will think the default value needs to be migrated and attempt a migration each time you start your app.

Die Migration wurde offenbar wegen einem abweichenden Default versucht: Auf https://hackage.haskell.org/package/persistent-2.14.6.0/docs/Database-Persist-Quasi.html steht dazu > Note: Persistent determines whether or not to migrate a column's default value by comparing the exact string found in your models file with the one returned by the database. If a database canonicalizes the SQL FALSE from your models file to false in the database, Persistent will think the default value needs to be migrated and attempt a migration each time you start your app.
jost (Migrated from gitlab.uniworx.de) reopened this issue 2023-12-14 09:12:20 +01:00
jost commented 2023-12-14 09:16:09 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

Our code contained default='{"dnf-terms":[]}' which postgresql changed into default='{"dnf-terms": []}' (note the differing space), which caused a migration at each start. However, persistent does not allow blanks within the default, so this is not solvable.

Our code contained `default='{"dnf-terms":[]}'` which postgresql changed into `default='{"dnf-terms": []}'` (note the differing space), which caused a migration at each start. However, persistent does not allow blanks within the default, so this is not solvable.
jost commented 2023-12-14 11:11:06 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

mentioned in commit a4b2af7f15

mentioned in commit a4b2af7f157444ead8c9df989741b266f7c2b4f2
jost commented 2023-12-14 11:11:06 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

mentioned in commit 2509358878

mentioned in commit 25093588784381a19f34e5b091677b908420ddea
jost (Migrated from gitlab.uniworx.de) closed this issue 2023-12-14 11:12:19 +01:00
jost commented 2023-12-14 11:12:20 +01:00 (Migrated from gitlab.uniworx.de)
Copy Link

changed the incident status to Resolved by closing the incident

changed the incident status to **Resolved** by closing the incident
This repo is archived. You cannot comment on issues.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels   
Aufwand: Hoch

   
Aufwand: Mittel

   
Aufwand: Niedrig

   
Blockiert

   
Diskussion

Benötigt Klärung, noch nichts zu implementieren

  
Dokumentation

Won't fix

  
Frontend

   
Konfigurationsproblem

Kubernetes, Nix, etc.

  
Prio: Angehalten

Kann jetzt noch nicht gelöst werden, da noch Abhängigkeiten bestehen

  
Prio: Blocker

   
Prio: Hoch

   
Prio: Mittel

   
Prio: Niedrig

   
Prio: Unbedeutend

   
Prüfung ausstehend

Problem vermutlich behoben, muss aber noch beobachtet oder getestet werden

  
Schnittstelle

   
Schnittstelle: APC

   
Schnittstelle: AVS

   
Schnittstelle: LMS

   
Schnittstelle: SAP

   
Uni2Work

Wird in Uni2work behoben und später portiert

  
UniWorX

Ordered from and appointed to UniWorX Systems LLC

  
Working

This issue is currently being worked on; probably within a branch

No Label
Aufwand: Hoch
Aufwand: Mittel
Aufwand: Niedrig
Blockiert
Diskussion
Dokumentation
Frontend
Konfigurationsproblem
Prio: Angehalten
Prio: Blocker
Prio: Hoch
Prio: Mittel
Prio: Niedrig
Prio: Unbedeutend
Prüfung ausstehend
Schnittstelle
Schnittstelle: APC
Schnittstelle: AVS
Schnittstelle: LMS
Schnittstelle: SAP
Uni2Work
UniWorX
Working
Milestone
Clear milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
No Assignees
1 Participants
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: fraport/fradrive-old#133
No description provided.
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?