Massive Probleme mit der Datenbankplaylist (Playlists fehlen plötzlich mitten im laufenden Betrieb -> Sendeausfall!)

clubfm · January 5, 2024, 9:41am

Hallo zusammen und ein gesundes neues Jahr. Der Fehler ist soeben wieder aufgetreten. Um 09:58 Uhr wurde die 09:00 Uhr Playlist erneut geladen. Vollständiges Logfile in der Nextcloud.

{"Timestamp":"2024-01-05T08:58:00.045","Message":"Run action: DatabaseAppendPlaylist, Rounding mode 0","Level":"Debug"}
{"Timestamp":"2024-01-05T08:58:00.045","Message":"Current time: 2024-01-05 08:58:00.045 (40E61E0BF4A06193), Rounding Mode 0","Level":"Debug"}
{"Timestamp":"2024-01-05T08:58:00.045","Message":"Current hour - old method: 2024-01-05 08:00:00.000 (40E61E0AAAAAAAAB), Rounding Mode 0","Level":"Debug"}
{"Timestamp":"2024-01-05T08:58:00.045","Message":"Current hour - new method: 2024-01-05 08:00:00.000 (40E61E0AAAAAAAAB), Rounding Mode 0","Level":"Debug"}
{"Timestamp":"2024-01-05T08:58:00.045","Message":"First hour to load: 2024-01-05 09:00:00.000 (40E61E0C00000000), Rounding Mode 0","Level":"Debug"}
{"Timestamp":"2024-01-05T08:58:00.045","Message":"Load hour before rounding: 2024-01-05 09:00:00.000 (40E61E0C00000000), Rounding Mode 0","Level":"Debug"}
{"Timestamp":"2024-01-05T08:58:00.045","Message":"Load hour after rounding: 2024-01-05 09:00:00.000 (40E61E0C00000000), Rounding Mode 0","Level":"Debug"}
{"Timestamp":"2024-01-05T08:58:00.141","Message":"After increase: 2024-01-05 10:00:00.000 (40E61E0D55555555), Rounding Mode 0","Level":"Debug"}
{"Timestamp":"2024-01-05T09:58:00.023","Message":"Run action: DatabaseAppendPlaylist, Rounding mode 0","Level":"Debug"}
{"Timestamp":"2024-01-05T09:58:00.023","Message":"Current time: 2024-01-05 09:58:00.022 (40E61E0D49F52E34), Rounding Mode 1","Level":"Debug"}
{"Timestamp":"2024-01-05T09:58:00.023","Message":"Current hour - old method: 2024-01-05 09:00:00.000 (40E61E0C00000000), Rounding Mode 1","Level":"Debug"}
{"Timestamp":"2024-01-05T09:58:00.023","Message":"Current hour - new method: 2024-01-05 09:00:00.000 (40E61E0C00000000), Rounding Mode 1","Level":"Debug"}
{"Timestamp":"2024-01-05T09:58:00.023","Message":"First hour to load: 2024-01-05 09:59:59.999 (40E61E0D55555555), Rounding Mode 1","Level":"Debug"}
{"Timestamp":"2024-01-05T09:58:00.023","Message":"Load hour before rounding: 2024-01-05 09:59:59.999 (40E61E0D55555555), Rounding Mode 1","Level":"Debug"}
{"Timestamp":"2024-01-05T09:58:00.023","Message":"Load hour after rounding: 2024-01-05 09:59:59.999 (40E61E0D55555555), Rounding Mode 1","Level":"Debug"}
{"Timestamp":"2024-01-05T09:58:00.140","Message":"After increase: 2024-01-05 10:59:59.999 (40E61E0EAAAAAAAA), Rounding Mode 1","Level":"Debug"}

Torben · January 5, 2024, 2:04pm

Wir nähern uns langsam der Lösung - auch wenn es aktuell nur darum geht, mehr Aufschluss darüber zu bekommen, an welcher Stelle genau sich der RoundingMode ändert.

Was ich durch Tests auf jeden Fall in Erfahrung bringen konnte, ist dass der Mode von der CPU pro Thread gespeichert wird, und jeder neue Thread wieder mit dem korrekten Standard-Modus 0 startet. Die Aktionen der Events werden immer in einem frischen Thread ausgeführt, und daher steht der Modus am Anfang auch auf 0, wie man an deinem Log sieht:

{"Timestamp":"2024-01-05T09:58:00.023","Message":"Run action: DatabaseAppendPlaylist, Rounding mode 0","Level":"Debug"}

Schon recht bald springt er allerdings auf den falschen Wert 1:

{"Timestamp":"2024-01-05T09:58:00.023","Message":"Current time: 2024-01-05 09:58:00.022 (40E61E0D49F52E34), Rounding Mode 1","Level":"Debug"}

Hier mal zum Vergleich der zugehörige Delphi-Code vom Anfang der “Datenbank-Playlist anhängen”-Aktion:

  fInstance.SystemLog.LogFmt(lcDebug, 'Run action: %s, Rounding mode 0', [GetObjectClassID, ord(GetRoundMode)]);

  fnow := fInstance.FakeNow;
  DoDebugLogSlot(fnow, 'Current time');

  slot :=  trunc((fnow + ((fTimeOffset + iTimeOffset)/24/60/60)) * 24) / 24; // truncated to top of hour
  DoDebugLogSlot(slot, 'Current hour - old method');

  slot :=  TopOfTheHour(fnow + ((fTimeOffset + iTimeOffset)/24/60/60));
  DoDebugLogSlot(slot, 'Current hour - new method');

  if paoNextPlaylist in fPlaylistOptions then
    slot := slot + OneHour;

  DoDebugLogSlot(slot, 'First hour to load');

Wobei die Hilfsfunktion DoDebugLogSlot wie folgt definiert ist:

procedure DoDebugLogSlot(const iSlot: TDateTime; const iDesc: string);
begin
 fInstance.SystemLog.LogFmt(lcDebug, '%s: %s (%s), Rounding Mode %d', [iDesc, FormatDateTime('yyyy-mm-dd hh:nn:ss.zzz', iSlot), DateTimeToHex(iSlot), ord(GetRoundMode)]);
end;

Am Anfang steht der Modus noch auf 0, schon in der Ausgabe von DoDebugLogSlot(fnow, 'Current time') aber (am Ende) auf 1. Also kommen folgende Operationen in Frage:

Instance.FakeNow - das “Fake” bezieht sich hier auf die imaginäre Zeit, die sich durch Doppelklick auf die Uhrzeit unten rechts im Fenster einstellen lässt. Intern wird dazu einfach Korrekturwert gespeichert, der zur tatsächlichen Zeit (Delphi-Funktion Now) addiert wird, threadsicher durch einen Mutex abgesichert:

function TInstanceData.GetTimeCorrection: TDateTime;
begin
  TMonitor.Enter(fTimeCorrectionMutex);
  try
    Result := fTimeCorrection;
  finally
    TMonitor.Exit(fTimeCorrectionMutex);
  end;
end;

function TInstanceData.FakeNow: TDateTime;
begin
  Result := Now + GetTimeCorrection;
end;

Die Addition wird den RoundingMode nicht verändern, also könnte es allenfalls die Now-Funktion sein, die ihn verstellt.

Innerhalb von DoDebugLogSlot der Aufruf von DateTimeToHex - sehr unwahrscheinlich, denn diese Hilfsfunktion habe ich nur für das Debugging hinzugefügt, und sie macht nichts weiter, als die 64 Bit Speicherbereich des TDateTime-Wertes in Hex auszugeben:

function DateTimeToHex(const iValue: TDateTime): string;
var
  p: ^int64;
begin
  p := @iValue;
  Result := Format('%.16X', [p^]);
end;

Schließlich, ebenfalls innerhalb von DoDebugLogSlot, die FormatDateTime-Funktion von Delphi, die die Uhrzeit in einen menschenlesbaren Text umwandelt. Ich habe nachgeschaut. die ist intern sehr komplex implementiert, dort könnten tatsächlich Rundungsoperationen vorkommen - auch wenn ich auf den ersten Blick nicht erkennen kann, dass dort irgendetwas am Mode verstellt wird.

Um nun genauer herauszufinden, in welchen dieser drei Schritte es passiert, habe ich die DoDebugLogSlot-Prozedur folgendermaßen erweitert:

procedure DoDebugLogSlot(const iSlot: TDateTime; const iDesc: string);
var
  rm1, rm2, rm3: integer;
  s, shex: string;
begin
  rm1 := ord(GetRoundMode);
  s := FormatDateTime('yyyy-mm-dd hh:nn:ss.zzz', iSlot);

  rm2 := ord(GetRoundMode);
  shex := DateTimeToHex(iSlot);

  rm3 := ord(GetRoundMode);

  fInstance.SystemLog.LogFmt(lcDebug, '%s: %s (%s), Rounding Mode %d/%d/%d', [iDesc, s, shex, rm1, rm2, rm3]);
end;

Es werden also die Berechnungen/Umwandlungen Schritt für Schritt durchgeführt und zwischendurch immer wieder der RoundingMode ermittelt, und am Ende alles gesammelt protokolliert.

Das Ergebnis lade ich gleich als Debug-Version Nr. 6 in den bekannten Austauschordner.

Tondose · January 5, 2024, 3:54pm

Schön, daß wir einmal einen Einblick in das Räderwerk bekommen.

Frohes neues Jahr übrigens allen!

Torben · January 5, 2024, 6:37pm

Das wünsche ich natürlich auch!

@clubfm, sorry, hat etwas gedauert, aber jetzt liegt die v6 im Austauschordner.

clubfm · January 6, 2024, 11:36am

Vielen Dank für die ausführlichen Informationen und die neue Debug Version. Sie läuft ab sofort, ich werde berichten.

DerTimmy · January 11, 2024, 10:00pm

Bei mir treten genau die gleichen Probleme auf wie bei @clubfm, so wie hier beschrieben: Bug beim Laden der Playlist für die nächste Stunde - #8 by DerTimmy

Die Lösung mit einer abgeänderten Eventzeit für das Anfügen der nächsten Playlist, so wie ich es auf den Vorschlag von @Tondose hin ausprobiert habe, funktioniert leider auf Dauer nicht, da das Problem nach ca. zwei Tagen wieder auftritt.

Besteht auch für mich die Möglichkeit, die aktuelle Debug-Version zum Testen zu erhalten? Schon einmal vielen Dank im Voraus.

Torben · January 12, 2024, 9:27am

Ich habe dir den Link per PN geschickt.

Bitte beachte, dass diese Debug-Version keine Verbesserungen erhält sondern lediglich zusätzliche Debug-Ausgaben, die mir helfen sollen, die Ursache des Problems zu ermitteln.

Sobald es bei dir damit auftritt, poste bitte die entsprechenden Auszüge aus dem Systemprotokoll (als Text, nicht Screenshot, wenn es geht). Bitte an @clubfm orientieren, was die hervorragende Aufbereitung der Informationen angeht

Torben · January 15, 2024, 10:01am

Ist es inzwischen bei irgendwem wieder aufgetreten?

clubfm · January 15, 2024, 11:29am

Bisher noch nicht, aber wir beobachten gespannt weiter

DerTimmy · January 16, 2024, 11:16am

Bei mir gibt es auch keine besonderen Vorkommnisse - der Rounding Mode steht nach wie vor auf 0…

Torben · January 24, 2024, 8:20am

Weiterhin alles unauffällig?

PS: Habe eine neue Debug-Version 7 hochgeladen, basiert jetzt auf mAirList 7.2.6.

clubfm · January 24, 2024, 9:00am

Bisher alles (ich muss schon fast sagen leider) unauffällig. Danke für die neue Version, ich kann diese heute Abend installieren. Warum der Fehler aktuell nicht mehr auftritt, kann ich nicht sagen, das ist echt spannend.

Liam · January 24, 2024, 9:09am

[Off-Topic]

Ich find’s auch ziemlich spannend das ganze von außen zu betrachten. Mit der v7.3-beta haben wir das Problem z. B. nicht.
Dennoch interessant wie das ganze hier abgelaufen ist bis jetzt.

[/Off-Topic]

clubfm · January 26, 2024, 6:50am

Guten Morgen!

Nachdem jetzt lange Zeit nichts passiert ist, hat sich das Update auf die neuste Version oder auch der Neustart gewaltig gelohnt - gestern Abend war es wieder soweit und der Rounding Mode ist auf 1 gesprungen:

{"Timestamp":"2024-01-25T21:56:55.746","Message":"Playlist-Cache für Datenbank wird aktualisiert","Level":"Debug"}
{"Timestamp":"2024-01-25T21:58:00.088","Message":"Führe Event PLAYLIST NACHLADEN aus","Level":"Info"}
{"Timestamp":"2024-01-25T21:58:00.089","Message":"Run action: DatabaseAppendPlaylist, Rounding mode 0","Level":"Debug"}
{"Timestamp":"2024-01-25T21:58:00.089","Message":"Current time: 2024-01-25 21:58:00.089 (40E6209D49F6C851), Rounding Mode 0\/0\/0","Level":"Debug"}
{"Timestamp":"2024-01-25T21:58:00.089","Message":"Current hour - old method: 2024-01-25 21:00:00.000 (40E6209C00000000), Rounding Mode 0\/0\/0","Level":"Debug"}
{"Timestamp":"2024-01-25T21:58:00.089","Message":"Current hour - new method: 2024-01-25 21:00:00.000 (40E6209C00000000), Rounding Mode 0\/0\/0","Level":"Debug"}
{"Timestamp":"2024-01-25T21:58:00.089","Message":"First hour to load: 2024-01-25 22:00:00.000 (40E6209D55555555), Rounding Mode 0\/0\/0","Level":"Debug"}
{"Timestamp":"2024-01-25T21:58:00.089","Message":"Load hour before rounding: 2024-01-25 22:00:00.000 (40E6209D55555555), Rounding Mode 0\/0\/0","Level":"Debug"}
{"Timestamp":"2024-01-25T21:58:00.089","Message":"Load hour after rounding: 2024-01-25 22:00:00.000 (40E6209D55555555), Rounding Mode 0\/0\/0","Level":"Debug"}
{"Timestamp":"2024-01-25T21:58:00.152","Message":"Werbecontainer untersucht: 1, geändert: 0","Level":"Info"}
{"Timestamp":"2024-01-25T21:58:00.152","Message":"After increase: 2024-01-25 23:00:00.000 (40E6209EAAAAAAAA), Rounding Mode 0\/0\/0","Level":"Debug"}
{"Timestamp":"2024-01-25T21:58:00.154","Message":"Fehler beim Puffern von \"Block 1\": Container ist leer.","Level":"Warning"}
{"Timestamp":"2024-01-25T21:58:43.926","Message":"Start: Z:\\ON AIR\\STUDIO\\JINGLES\\Floyd Media - Club FM 2022\\02. Theme 02\\Theme 02 Shotgun.wav","Level":"Playlist"}
{"Timestamp":"2024-01-25T21:58:47.837","Message":"Start: Z:\\ON AIR\\IMPORT\\CLUBFM CHARTS\\Charts Update 23 02 2019\\Kurt Royce, Zwette, DJ Dark, MD DJ - I Miss U - DJ Dark & MD DJ Remix.mp3","Level":"Playlist"}
{"Timestamp":"2024-01-25T21:58:50.165","Message":"Stop: Z:\\ON AIR\\STUDIO\\CLUB FM ROTATION\\Various\\Urban Dance, Vol 12 [Explicit]\\01-18- Last Man on Earth (Radio Edit).mp3 (190 seconds)","Level":"Playlist"}
{"Timestamp":"2024-01-25T21:58:52.228","Message":"Stop: Z:\\ON AIR\\STUDIO\\JINGLES\\Floyd Media - Club FM 2022\\02. Theme 02\\Theme 02 Shotgun.wav (8 seconds)","Level":"Playlist"}
{"Timestamp":"2024-01-25T21:58:52.234","Message":"Überspringe fehlerhaftes Element \"Block 1\": ","Level":"Warning"}
{"Timestamp":"2024-01-25T22:00:00.015","Message":"Fixed time reached, jump to: 25.01.2024 22:00:00.000 - Uplifting Only","Level":"Debug"}
{"Timestamp":"2024-01-25T22:00:00.015","Message":"Start: Z:\\ON AIR\\IMPORT\\CLUBFM DJ SHOWS\\UPLIFTING ONLY\\uplifting_only_aktuell.mp3","Level":"Playlist"}
{"Timestamp":"2024-01-25T22:00:05.015","Message":"Stop: Z:\\ON AIR\\IMPORT\\CLUBFM CHARTS\\Charts Update 23 02 2019\\Kurt Royce, Zwette, DJ Dark, MD DJ - I Miss U - DJ Dark & MD DJ Remix.mp3 (77 seconds)","Level":"Playlist"}
{"Timestamp":"2024-01-25T22:01:56.852","Message":"Playlist-Cache für Datenbank wird aktualisiert","Level":"Debug"}
{"Timestamp":"2024-01-25T22:01:57.838","Message":"Lösche Playlist-Cache-Datei C:\\ProgramData\\mAirList\\7.x\\PlaylistCache\\EB052100308152185AC7D7523F835AF7\\1\\2024-01-25-21.mlp","Level":"Debug"}
{"Timestamp":"2024-01-25T22:06:57.844","Message":"Playlist-Cache für Datenbank wird aktualisiert","Level":"Debug"}
{"Timestamp":"2024-01-25T22:06:58.851","Message":"Lösche Playlist-Cache-Datei C:\\ProgramData\\mAirList\\7.x\\PlaylistCache\\EB052100308152185AC7D7523F835AF7\\1\\2024-01-25-21.mlp","Level":"Debug"}
{"Timestamp":"2024-01-25T22:11:58.857","Message":"Playlist-Cache für Datenbank wird aktualisiert","Level":"Debug"}
{"Timestamp":"2024-01-25T22:11:59.843","Message":"Lösche Playlist-Cache-Datei C:\\ProgramData\\mAirList\\7.x\\PlaylistCache\\EB052100308152185AC7D7523F835AF7\\1\\2024-01-25-21.mlp","Level":"Debug"}
{"Timestamp":"2024-01-25T22:17:09.841","Message":"Playlist-Cache für Datenbank wird aktualisiert","Level":"Debug"}
{"Timestamp":"2024-01-25T22:17:10.810","Message":"Lösche Playlist-Cache-Datei C:\\ProgramData\\mAirList\\7.x\\PlaylistCache\\EB052100308152185AC7D7523F835AF7\\1\\2024-01-25-21.mlp","Level":"Debug"}
{"Timestamp":"2024-01-25T22:22:10.816","Message":"Playlist-Cache für Datenbank wird aktualisiert","Level":"Debug"}
{"Timestamp":"2024-01-25T22:22:11.812","Message":"Lösche Playlist-Cache-Datei C:\\ProgramData\\mAirList\\7.x\\PlaylistCache\\EB052100308152185AC7D7523F835AF7\\1\\2024-01-25-21.mlp","Level":"Debug"}
{"Timestamp":"2024-01-25T22:27:11.818","Message":"Playlist-Cache für Datenbank wird aktualisiert","Level":"Debug"}
{"Timestamp":"2024-01-25T22:27:12.474","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:12.780","Message":"Lösche Playlist-Cache-Datei C:\\ProgramData\\mAirList\\7.x\\PlaylistCache\\EB052100308152185AC7D7523F835AF7\\1\\2024-01-25-21.mlp","Level":"Debug"}
{"Timestamp":"2024-01-25T22:27:13.476","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:14.475","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:15.475","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:16.477","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:17.476","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:18.477","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:19.479","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:20.480","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:21.480","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:22.483","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:23.484","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:24.474","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:25.475","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2024-01-25T22:27:26.476","Message":"RoundingMode: 1","Level":"Info"}

Dies hat über die Nacht immer wieder zum falschen Laden von Playlists geführt. Die vollständigen Logfiles für gestern und heute liegen in der Nextcloud. In diesem Sinne guten Start ins Wochenende!

Torben · January 26, 2024, 12:16pm

@clubfm Kleine (vielleicht abwegige) Frage: War das Systemprotokollfenster geöffnet und im Vordergrund?

clubfm · January 26, 2024, 12:24pm

Das Systemprotokoll war am Senderechner nicht geöffnet.

Torben · January 26, 2024, 12:56pm

Ah, vergiss das mit dem Protokollfenster, da war ich auf dem Holzweg.

Habe aber, nach etlichen Stunden Debugging in den Delphi-System-Bibliotheken (und dem Issue Tracker von Delphi) noch einen heißen Kandidaten gefunden, der das auslösen könnte.

Neue Debug-Version 8 liegt bereit, mit möglichem Fix und abermals erweiterter Debugausgabe. Ein paar Hex-Ziffern

clubfm · January 26, 2024, 1:23pm

Oh, das klingt spannend Vielen Dank, Debug Version #8 läuft. Ich beobachte.

DerTimmy · January 28, 2024, 4:10pm

Bei mir läuft die Debug-Version auch nach wie vor unauffällig.

Torben · January 30, 2024, 3:40pm

Update:

Ursache wahrscheinlich ermittelt. Wer mehr wissen will: SetRoundMode should not be used at all ;) · Issue #45 · AngusJohnson/Image32 · GitHub

Neue Builds kommen.