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

clubfm · December 16, 2023, 11:43am

Kurzes Update: Bisher ist weder das Problem wieder aufgetreten, noch im Log ein entsprechender Eintrag aufgetaucht. Ich habe um etwas Zeit zu gewinnen aber parallel gerade einen kleinen Versuch gestartet und die Debug Version auf einem separaten Rechner installiert.

Bei diesem habe ich 1:1 die bestehende Config des eigentlichen Senderechners importiert, sowie Datum und Uhrzeit so manipuliert, dass dieser jetzt die Playlist von Donnerstagabend ab 17:30 Uhr durchspielt, in der Hoffnung, genau diesen Fehler in dieser Konstellation reproduzieren zu können. Der Fehler ist beim Laden der 20:00 Uhr Playlist aufgetreten. Ich werde berichten

Zusätzlich habe ich ein kleines Python Script gebastelt, das im Logfile nach dem String “Rounding” sucht. Sobald dieser auftaucht, kriege ich eine Mail.

clubfm · December 16, 2023, 9:02pm

Bisher konnte ich den Fehler auch am zweiten Rechner leider trotz intensiver Bemühungen nicht reproduzieren. Bleibt aktuell also nur, abzuwarten, zwischen den ersten beiden Ausfällen verging ja auch ca. eine Woche.

Ich habe mir aber nochmal das Logfile vom Donnerstag (14.12.) angeschaut. Am Abend dieses Tages (um genau zu sein um 19:58 Uhr) kam es ja trotz gepatchter Version zu einem erneuten Falschladen der Playlist.

Was mich beim genaueren Hinsehen aber etwas stutzig macht, ist, dass um 19:58 Uhr statt der 20:00 Uhr Playlist (oder wie vorher durch den Rundungsfehler bedingt der 19:00 Uhr Playlist) diesmal sogar die 18:00 Uhr Playlist geladen wurde:

{"Timestamp":"2023-12-14T19:56:09.037","Message":"Start: Z:\\ON AIR\\IMPORT\\CLUBFM SONSTIGES\\Rotation Ergänzung 17_4_2017 08-15\\Deutsche Jahres Charts 2011\\030 Sean Paul Feat. Alexis Jordan - Got 2 Luv U.mp3","Level":"Playlist"}
{"Timestamp":"2023-12-14T19:56:13.435","Message":"Stop: Z:\\ON AIR\\STUDIO\\JINGLES\\Floyd Media - Club FM 2022\\02. Theme 02\\Theme 02 Basic ID Full Vocals.wav (11 seconds)","Level":"Playlist"}
{"Timestamp":"2023-12-14T19:58:00.057","Message":"Führe Event PLAYLIST NACHLADEN aus","Level":"Info"}
{"Timestamp":"2023-12-14T19:58:00.157","Message":"Werbecontainer untersucht: 2, geändert: 0","Level":"Info"}
{"Timestamp":"2023-12-14T19:58:00.162","Message":"Überspringe fehlerhaftes Element \"Block 1\": ","Level":"Warning"}
{"Timestamp":"2023-12-14T19:58:00.404","Message":"Fixed time reached, jump to: 14.12.2023 18:02:59.000 - News Opener","Level":"Debug"}
{"Timestamp":"2023-12-14T19:58:00.424","Message":"Datei-Recorder: Aufnahme in Z:\\ARCHIV\\NEWS\\weltnews.mp3 wurde gestartet.","Level":"Info"}
{"Timestamp":"2023-12-14T19:58:00.950","Message":"Fixed time reached, jump to: 14.12.2023 18:38:59.000 - Block 2","Level":"Debug"}
{"Timestamp":"2023-12-14T19:58:00.951","Message":"Überspringe fehlerhaftes Element \"Block 2\": ","Level":"Warning"}
{"Timestamp":"2023-12-14T19:58:01.197","Message":"Datei-Recorder: Aufnahme in Z:\\ARCHIV\\NEWS\\regionews.mp3 wurde gestartet.","Level":"Info"}
{"Timestamp":"2023-12-14T19:58:05.404","Message":"Stop: Z:\\ON AIR\\IMPORT\\CLUBFM SONSTIGES\\Rotation Ergänzung 17_4_2017 08-15\\Deutsche Jahres Charts 2011\\030 Sean Paul Feat. Alexis Jordan - Got 2 Luv U.mp3 (116 seconds)","Level":"Playlist"}
{"Timestamp":"2023-12-14T20:00:38.175","Message":"Start: Z:\\ON AIR\\STUDIO\\JINGLES\\Floyd Media - Club FM 2022\\06. Theme Top of the Hour\\Theme 06 TOH Basic ID Full Vocals.wav","Level":"Playlist"}
{"Timestamp":"2023-12-14T20:00:40.242","Message":"Datei-Recorder: Aufnahme in Z:\\ARCHIV\\NEWS\\weltnews.mp3 wurde gestoppt.","Level":"Info"}
{"Timestamp":"2023-12-14T20:00:40.253","Message":"Datei-Recorder: Aufnahme in Z:\\ARCHIV\\NEWS\\regionews.mp3 wurde gestoppt.","Level":"Info"}
{"Timestamp":"2023-12-14T20:00:40.844","Message":"Playlist-Cache für Datenbank wird aktualisiert","Level":"Debug"}

Muss nicht unbedingt relevant sein, kam mir aber komisch vor. Ich habe das vollständige Logfile vom 14.12. einfach mal in die Nextcloud geladen, falls Interesse daran besteht.

In diesem Sinne: Schönes Wochenende und bis bald, wenn der Fehler erneut auftritt, melde ich mich sofort. Vielen Dank an dieser Stelle nochmal für die ganze bisherige Unterstützung!

Radioman0410 · December 18, 2023, 12:19pm

Hier kam es soeben ab ca. 12:56 zu einem totalen Chaos. Um xx:56 wird die neue Playlist geladen. Songs wurden nur kurz angespielt, wieder abgebrochen. Der News Opener Welt gegen 12:56 abgespielt (für 13 Uhr mit weicher Fixzeit 60 sec. Fenster vorgesehen), selbiger wieder abgebrochen, 9 Sekunden ein Song gespielt woraufhin dann die Regionalnews (überhaupt nicht vorgesehen zu dieser Zeit) auch total random ausgespielt wurden. Kurzum: um 12:56 Uhr wurde die 12:00 Uhr Playlist wieder geladen.
Ich hab den Fehler dann bemerkt und die 13 Uhr Playlist um 13:04 Uhr händisch nachgeladen. Im Einsatz ist Version 7.2.4. Die volle Logdatei lade ich in die Nextcloud @Torben.

{“Timestamp”:“2023-12-18T12:56:00.041”,“Message”:“Führe Event aus”,“Level”:“Info”}
{“Timestamp”:“2023-12-18T12:56:00.134”,“Message”:“Fixed time reached, jump to: 18.12.2023 12:02:59.000 - Weltnews mit Bett”,“Level”:“Debug”}

Torben · December 18, 2023, 12:55pm

Fehlerbild identisch mit oben. 12-Uhr-Stunde geladen statt 13-Uhr-Stunde. Falsch (ab-)gerundet.

Aber noch nicht Snapshot 5435?

https://download.mairlist.com/current/mAirList/v7.2/snapshot/

Nimm den bitte mal. Da ist der Fix drin, den ich am Freitag auch @clubfm in seiner Debug-Version zur Vergügung gestellt habe (nur halt ohne Debugging).

Radioman0410 · December 18, 2023, 7:29pm

Danke Torben, ich bin jetzt auf Snapshot 5435 geschwenkt. Es war noch die 5434.

Torben · December 19, 2023, 4:07pm

Sonst keine Auffälligkeiten bisher? Dann würde ich den 5435 morgen als v7.2.5 freigeben.

clubfm · December 19, 2023, 4:35pm

Bisher läuft alles sauber, ich habe keine Probleme mehr festgestellt. Würde die Debug Version hier aber trotzdem noch laufen lassen, damit wir direkt aussagefähige Logfiles haben, sollten nochmal Fehler auftreten.

Torben · December 20, 2023, 11:12am

Ich habe heute morgen v7.2.5 sowie einen neuen Build von v7.3-beta hochgeladen, die jeweils den Fix enthalten.

Radioman0410 · December 20, 2023, 7:45pm

Perfekt! Das Update werde ich gleich installieren. Folgendes hat sich gerade um kurz vor 20 Uhr in der Version 7.2.4. Snapshot 5435 zugetragen. Die 20 Uhr Playlist wurde nicht korrekt geladen / abgespielt. Es wurde stattdessen die Notfall-Playlist geladen (was ja auch richtig ist, denn die Aktion “wenn die Playlist während(…)”) ist aktiviert. Die Playlist war leicht unterplant, was aber keine Rolle spielt, da die News in der 19 Uhr Stunde diese 2:35 Minuten auffüllen. Ich würde “Stundenende” einfach rausnehmen, in Mairlist 5 war das nie ein Thema. Nun scheint es Probleme zu bereiten?

{“Timestamp”:“2023-12-20T19:56:00.019”,“Message”:“Führe Event aus”,“Level”:“Info”}
{“Timestamp”:“2023-12-20T19:56:59.112”,“Message”:“Skipping: Stundenende”,“Level”:“Debug”}
{“Timestamp”:“2023-12-20T19:56:59.112”,“Message”:“Fixed time reached too early: target: 20.12.2023 20:00:00.000, diff: 180,888, item: Weltnews mit Bett”,“Level”:“Debug”}
{“Timestamp”:“2023-12-20T19:56:59.414”,“Message”:“Start: M:\AUDIO2\Sash! - Just Around The Hill - Radio Edit.mp3”,“Level”:“Playlist”}
{“Timestamp”:“2023-12-20T19:57:02.786”,“Message”:“Stop: M:\AUDIO\Kaptan - Jump.mp3 (193 seconds)”,“Level”:“Playlist”}
{“Timestamp”:“2023-12-20T19:58:05.320”,“Message”:“Playlist-Cache für Datenbank wird aktualisiert”,“Level”:“Debug”}
{“Timestamp”:“2023-12-20T20:00:02.182”,“Message”:“Encoding into M:\AIRCHECK\LEINEWELLE CLEANFEED\LW Clean Mitschnitt 20.12.2023 - 20.00.mp3”,“Level”:“Info”}
{“Timestamp”:“2023-12-20T20:00:24.555”,“Message”:“Start: M:\AUDIO\Don Henley - The Boys Of Summer.mp3”,“Level”:“Playlist”}
{“Timestamp”:“2023-12-20T20:00:26.945”,“Message”:“Stop: M:\AUDIO2\Sash! - Just Around The Hill - Radio Edit.mp3 (207 seconds)”,“Level”:“Playlist”}
{“Timestamp”:“2023-12-20T20:03:07.499”,“Message”:“Playlist-Cache für Datenbank wird aktualisiert”,“Level”:“Debug”}
{“Timestamp”:“2023-12-20T20:03:09.713”,“Message”:“Lösche Playlist-Cache-Datei C:\ProgramData\mAirList\7.x\PlaylistCache\359067A58CD66EDB7B7D6AF85BB5B923\1\2023-12-20-19.mlp”,“Level”:“Debug”}

clubfm · December 21, 2023, 7:09pm

Hallo zusammen,

es sah zunächst echt vielversprechend auf, leider ist derselbe Fehler jedoch gerade eben wieder aufgetreten: Um 18:58 Uhr wurde statt der 19:00 Uhr Playlist wieder die 18:00 Uhr Playlist geladen, hier ein Auszug aus dem Logfile:

{"Timestamp":"2023-12-21T18:56:58.904","Message":"Start: Z:\\ON AIR\\IMPORT\\CLUBFM CHARTS\\Charts Update 05 09 2021\\Eli & Fur ft Camden Cox - Burning [Radio Edit].mp3","Level":"Playlist"}
{"Timestamp":"2023-12-21T18:57:02.981","Message":"Stop: Z:\\ON AIR\\STUDIO\\JINGLES\\Floyd Media - Club FM 2022\\03. Theme 03\\Theme 03 Basic ID Full Vocals.wav (12 seconds)","Level":"Playlist"}
{"Timestamp":"2023-12-21T18:58:00.031","Message":"Führe Event PLAYLIST NACHLADEN aus","Level":"Info"}
{"Timestamp":"2023-12-21T18:58:00.120","Message":"Werbecontainer untersucht: 2, geändert: 0","Level":"Info"}
{"Timestamp":"2023-12-21T18:58:00.124","Message":"Überspringe fehlerhaftes Element \"Block 1\": ","Level":"Warning"}
{"Timestamp":"2023-12-21T18:58:00.368","Message":"Fixed time reached, jump to: 21.12.2023 18:02:59.000 - News Opener","Level":"Debug"}
{"Timestamp":"2023-12-21T18:58:00.387","Message":"Datei-Recorder: Aufnahme in Z:\\ARCHIV\\NEWS\\weltnews.mp3 wurde gestartet.","Level":"Info"}
{"Timestamp":"2023-12-21T18:58:00.471","Message":"Fixed time reached, jump to: 21.12.2023 18:38:59.000 - Block 2","Level":"Debug"}
{"Timestamp":"2023-12-21T18:58:00.472","Message":"Überspringe fehlerhaftes Element \"Block 2\": ","Level":"Warning"}
{"Timestamp":"2023-12-21T18:58:00.717","Message":"Datei-Recorder: Aufnahme in Z:\\ARCHIV\\NEWS\\regionews.mp3 wurde gestartet.","Level":"Info"}
{"Timestamp":"2023-12-21T18:58:05.367","Message":"Stop: Z:\\ON AIR\\IMPORT\\CLUBFM CHARTS\\Charts Update 05 09 2021\\Eli & Fur ft Camden Cox - Burning [Radio Edit].mp3 (66 seconds)","Level":"Playlist"}
{"Timestamp":"2023-12-21T18:58:22.653","Message":"Playlist-Cache für Datenbank wird aktualisiert","Level":"Debug"}
{"Timestamp":"2023-12-21T19:00:13.377","Message":"Start: Z:\\ON AIR\\STUDIO\\JINGLES\\Floyd Media - Club FM 2022\\06. Theme Top of the Hour\\Theme 06 TOH Basic ID Full Vocals.wav","Level":"Playlist"}
{"Timestamp":"2023-12-21T19:00:15.446","Message":"Datei-Recorder: Aufnahme in Z:\\ARCHIV\\NEWS\\weltnews.mp3 wurde gestoppt.","Level":"Info"}
{"Timestamp":"2023-12-21T19:00:15.460","Message":"Datei-Recorder: Aufnahme in Z:\\ARCHIV\\NEWS\\regionews.mp3 wurde gestoppt.","Level":"Info"}
{"Timestamp":"2023-12-21T19:00:22.863","Message":"Start: Z:\\ON AIR\\IMPORT\\CLUBFM CHARTS\\Charts Update 03 12 2023\\Asketa & Natan Chaim x Joanna - Want Ya.mp3","Level":"Playlist"}

Im Logfile sind leider keinerlei Eingräge bezüglich Rounding aufgetaucht. @Torben können wir irgendwie verifizieren, dass das Logging in der Debug Version tatsächlich funktioniert, wie es soll?

Besonders spannend ist:

Der Fehler ist wieder nach ziemlich genau 7 Tagen Uptime aufgetreten
Letzte Woche wurde um 19:58 Uhr sogar die 18:00 Uhr Stunde statt der 20:00 Uhr Stunde geladen
Heute wurde um 18:58 Uhr die 18:00 Stunde statt der 19:00 Uhr Stunde geladen

Der Fehler mit den nicht mehr einsehbaren Playlisten in der Sendeplanung lässt sich diesmal nicht reproduzieren - der Workaround scheint also zumindest was das betrifft zu funktionieren. Um 19:58 Uhr wurde auch korrekt die 20:00 Uhr Stunde geladen, ich habe mAirList diesmal nicht neu gestartet.

Gerne kann ich sämtliche Logfiles bereitstellen, ich lade gleich das gesamte Tageslogfile in die Nextcloud.

Irgendwo ist leider definitiv noch der Wurm drin. Wie wollen wir hier weitermachen?

Danke & viele Grüße

Peter_Schmidt · December 21, 2023, 7:26pm

@clubfm
Vielleicht liegt’s daran, das mAirList ein fehlerhaftes Element im Block 1 (Zeitstempel 18:58:00.124) und ein weiteres fehlerhaftes Element in Block 2 (Zeitstempel 18:58:00.472) überspringen musste und dadurch durcheinander gekommen ist.

Gruß Peter

Torben · December 21, 2023, 9:31pm

Wir fahren weitere Geschütze auf.

Ich habe dir in den Cloud-Ordner (Link aus der PM neulich) eine weitere Debug-Version 4 hochgeladen. Diese protokolliert jetzt bei jedem Ausführen der Playlist-Aktion alle Zeitberechnungen incl. der hexadezimalen Rohdaten der beteiligten Fließkommazahlen:

21.12.23 22:25:36	Debug	Run action: DatabaseAppendPlaylist, Rounding mode 0
21.12.23 22:25:36	Debug	Current time: 2023-12-21 22:25:36.488 (40E61C3DE703E16E)
21.12.23 22:25:36	Debug	Current hour - old method: 2023-12-21 22:00:00.000 (40E61C3D55555555)
21.12.23 22:25:36	Debug	Current hour - new method: 2023-12-21 22:00:00.000 (40E61C3D55555555)
21.12.23 22:25:36	Debug	First hour to load: 2023-12-21 23:00:00.000 (40E61C3EAAAAAAAA)
21.12.23 22:25:36	Debug	Load hour before rounding: 2023-12-21 23:00:00.000 (40E61C3EAAAAAAAA)
21.12.23 22:25:36	Debug	Load hour after rounding: 2023-12-21 23:00:00.000 (40E61C3EAAAAAAAB)

Bitte behalte das Log im Auge und schaue insbesondere, ob es irgendwo eine Abweichung zwischen den Angaben bei “Current hour - old method” und “Current hour - new method” gibt. Auch wenn alle Stunden richtig geladen wurden. Falls dort zwei unterschiedliche Stunden stehen (eine richtig, eine falsch), dann wäre das eine mögliche Fehlerursache.

clubfm · December 22, 2023, 7:34am

Moin!

vielen Dank für die angepasste Debug Version. Ich habe sie installiert und auch das Logfile Monitoring Script entsprechend angepasst. Sobald es zwischen der “old method” und der “new method” Zeit einen Unterschied gibt, kriege ich eine Mail. Ich schaue parallel aber natürlich trotzdem immer wieder auch manuell in die Logs.

Die fehlerhaften Elemente waren in diesem Fall zwei leere Werbeblöcke, einer um kurz vor Halb, einer zu Beginn der neuen Stunde, jeweils mit Backtiming zu den Nachrichten. Um 18:58 Uhr wurde die 18:00 Uhr Playlist erneut geladen.

Danke euch & bis bald, ich werde berichten

VG

Radioman0410 · December 27, 2023, 7:30pm

Ein Zwischenstand: Version 7.2.5 Build 5436 läuft bis jetzt ohne Probleme

clubfm · December 30, 2023, 9:37pm

Hallo zusammen,

ich hoffe, ihr hattet entspannte Weihnachtsfeiertage. Ich habe mAirList heute wieder bei einem erfolglosen Versuch ertappt, die Datenbankplaylist nachzuladen, und jetzt dank der erweiterten Debug Version von @Torben auch detaillierte Logfiles.

Heute um 15:28 Uhr wurde der Rounding Mode plötzlich auf 1 gesetzt, seitdem tauchen die Einträge auch kontinuierlich im Logfile auf. Zu diesem Zeitpunkt gab es keinerlei besondere Vorkommnisse/Aktionen oder sonstige Auffälligkeiten. Hier der Auszug aus dem Log:

{"Timestamp":"2023-12-30T15:28:25.632","Message":"Start: Z:\\ON AIR\\IMPORT\\CLUBFM CHARTS\\Charts Update 29 10 2023\\Raiden - Take Me Back (feat. August Rigo).mp3","Level":"Playlist"}
{"Timestamp":"2023-12-30T15:28:26.268","Message":"Playlist-Cache für Datenbank wird aktualisiert","Level":"Debug"}
{"Timestamp":"2023-12-30T15:28:27.436","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T15:28:28.436","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T15:28:29.436","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T15:28:30.000","Message":"Stop: Z:\\ON AIR\\STUDIO\\JINGLES\\Floyd Media - Club FM 2022\\01. Theme 01\\Theme 01 Hyper ID.wav (6 seconds)","Level":"Playlist"}
{"Timestamp":"2023-12-30T15:28:30.435","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T15:28:31.435","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T15:28:32.435","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T15:28:33.435","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T15:28:34.435","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T15:28:35.437","Message":"RoundingMode: 1","Level":"Info"}

Um 15:58 Uhr wurde die 15:00 Uhr Playlist erneut geladen:

{"Timestamp":"2023-12-30T15:58:00.073","Message":"Führe Event PLAYLIST NACHLADEN aus","Level":"Info"}
{"Timestamp":"2023-12-30T15:58:00.074","Message":"Run action: DatabaseAppendPlaylist, Rounding mode 0","Level":"Debug"}
{"Timestamp":"2023-12-30T15:58:00.074","Message":"Current time: 2023-12-30 15:58:00.073 (40E61D5549F66B1B)","Level":"Debug"}
{"Timestamp":"2023-12-30T15:58:00.074","Message":"Current hour - old method: 2023-12-30 15:00:00.000 (40E61D5400000000)","Level":"Debug"}
{"Timestamp":"2023-12-30T15:58:00.074","Message":"Current hour - new method: 2023-12-30 15:00:00.000 (40E61D5400000000)","Level":"Debug"}
{"Timestamp":"2023-12-30T15:58:00.074","Message":"First hour to load: 2023-12-30 15:59:59.999 (40E61D5555555555)","Level":"Debug"}
{"Timestamp":"2023-12-30T15:58:00.074","Message":"Load hour before rounding: 2023-12-30 15:59:59.999 (40E61D5555555555)","Level":"Debug"}
{"Timestamp":"2023-12-30T15:58:00.074","Message":"Load hour after rounding: 2023-12-30 15:59:59.999 (40E61D5555555555)","Level":"Debug"}
{"Timestamp":"2023-12-30T15:58:00.177","Message":"Werbecontainer untersucht: 1, geändert: 0","Level":"Info"}
{"Timestamp":"2023-12-30T15:58:00.189","Message":"After increase: 2023-12-30 16:59:59.999 (40E61D56AAAAAAAA)","Level":"Debug"}
{"Timestamp":"2023-12-30T15:58:00.202","Message":"Überspringe fehlerhaftes Element \"Block 1\": ","Level":"Warning"}
{"Timestamp":"2023-12-30T15:58:00.445","Message":"Fixed time reached, jump to: 30.12.2023 15:02:59.000 - News Opener","Level":"Debug"}
{"Timestamp":"2023-12-30T15:58:00.463","Message":"Datei-Recorder: Aufnahme in Z:\\ARCHIV\\NEWS\\weltnews.mp3 wurde gestartet.","Level":"Info"}

Um 16:58 Uhr lief dann wie immer das “Datenbank Playlist anhängen” Event, dank Workaround sogar mit Rounding Mode 0, leider war das Nachladen dennoch nicht erfolgreich, da alle nicht restlos durch 3 teilbaren Stunden wieder nicht mehr abrufbar waren (dies war auch in der Playlist-Verwaltung ersichtlich).

{"Timestamp":"2023-12-30T16:57:57.409","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T16:57:58.410","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T16:57:59.409","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T16:58:00.049","Message":"Führe Event PLAYLIST NACHLADEN aus","Level":"Info"}
{"Timestamp":"2023-12-30T16:58:00.050","Message":"Run action: DatabaseAppendPlaylist, Rounding mode 0","Level":"Debug"}
{"Timestamp":"2023-12-30T16:58:00.050","Message":"Current time: 2023-12-30 16:58:00.049 (40E61D569F4B2B4F)","Level":"Debug"}
{"Timestamp":"2023-12-30T16:58:00.050","Message":"Current hour - old method: 2023-12-30 15:59:59.999 (40E61D5555555555)","Level":"Debug"}
{"Timestamp":"2023-12-30T16:58:00.050","Message":"Current hour - new method: 2023-12-30 15:59:59.999 (40E61D5555555555)","Level":"Debug"}
{"Timestamp":"2023-12-30T16:58:00.050","Message":"First hour to load: 2023-12-30 16:59:59.999 (40E61D56AAAAAAAA)","Level":"Debug"}
{"Timestamp":"2023-12-30T16:58:00.050","Message":"Load hour before rounding: 2023-12-30 16:59:59.999 (40E61D56AAAAAAAA)","Level":"Debug"}
{"Timestamp":"2023-12-30T16:58:00.050","Message":"Load hour after rounding: 2023-12-30 16:59:59.999 (40E61D56AAAAAAAA)","Level":"Debug"}
{"Timestamp":"2023-12-30T16:58:00.056","Message":"Werbecontainer untersucht: 0, geändert: 0","Level":"Info"}
{"Timestamp":"2023-12-30T16:58:00.057","Message":"After increase: 2023-12-30 17:59:59.999 (40E61D57FFFFFFFF)","Level":"Debug"}
{"Timestamp":"2023-12-30T16:58:00.057","Message":"Fehler beim Ausführen der Aktion Datenbank-Playlist anhängen: Die aus der Datenbank geladene Playlist ist leer.","Level":"Error"}
{"Timestamp":"2023-12-30T16:58:00.410","Message":"RoundingMode: 1","Level":"Info"}
{"Timestamp":"2023-12-30T16:58:01.407","Message":"RoundingMode: 1","Level":"Info"}

Erst ein Neustart von mAirList schaffte Abhilfe. Ich habe das vollständige Logfile mal in die Nextcloud geladen und wünsche allen vorab schon mal einen guten Rutsch - vielen Dank für die Unterstützung und möge der richtige Rundungsmodus mit euch sein!

EDIT: Ergänzungen

Torben · December 31, 2023, 4:22pm

Nur ganz kurz, da ich gerade keine Zeit habe lange zu schreiben: Im Austauschordner liegt eine weitere Debug-Version 5, bitte mal mit der weitertesten.

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.