TTS Bugs und ein mini Fix

sfields · 9. August 2023 um 16:51

Wenn DONT_ACCEPT_SAME_RFID_TWICE_ENABLE definiert ist und man die Zeit/ip via TTS aufsagen lässt, dann wird danach die Wiedergabe nicht fortgesetzt, weil die Karte abgelehnt wird (Rfid ID ist ja diesselbe).
Ein Fix könnte das Hinzufügen von 3 Zeilen sein:

		// If speech is over, go back to predefined state
		if (!gPlayProperties.currentSpeechActive && gPlayProperties.lastSpeechActive) {
			gPlayProperties.lastSpeechActive = false;
			if (gPlayProperties.playMode != NO_PLAYLIST) {
				#ifdef DONT_ACCEPT_SAME_RFID_TWICE_ENABLE
					strncpy(gOldRfidTagId, "X", cardIdStringSize-1);     // Set old rfid-id to crap in order to allow to re-apply it after speech is over
				#endif
				xQueueSend(gRfidCardQueue, gPlayProperties.playRfidTag, 0);     // Re-inject previous RFID-ID in order to continue playback
			}
		}

anstatt alt:

		// If speech is over, go back to predefined state
		if (!gPlayProperties.currentSpeechActive && gPlayProperties.lastSpeechActive) {
			gPlayProperties.lastSpeechActive = false;
			if (gPlayProperties.playMode != NO_PLAYLIST) {
				xQueueSend(gRfidCardQueue, gPlayProperties.playRfidTag, 0);     // Re-inject previous RFID-ID in order to continue playback
			}
		}

Wäre das ok? Soll ich einen MR machen?

Unabhängig davon (getestet im DEV vom 8.8.2023 natürlich ohne DONT_ACCEPT_SAME_RFID_TWICE_ENABLE) gibt es im Zusammenhang mit TTS noch folgende Fehler, die mir aufgefallen sind, aber ich verstehe nicht, wieso sie auftreten:

Wenn man (z.B.) mehrmals hintereinander die Zeit via tts aufsagen lässt (immer nachdem die normale Wiedergabe wieder aufgenommen wurde), so wird manchmal die Wiedergabe einfach nicht mehr fortgesetzt (mal passiert es nach dem zweiten Mal, mal auch erst nach dem 10. Mal).

Meldungen bei fortgesetzter Wiedergabe

[ 18232 ]  info        : Closing audio file
[ 18232][V][ssl_client.cpp:321] stop_ssl_socket(): Cleaning SSL connection.
[ 18233 ]  info        : buffers freed, free Heap: 75272 bytes
[ 18390 ]  info        : chunked data transfer
[ 18399 ]  info        : MP3Decoder has been initialized, free Heap: 46464 bytes , free stack 2948 DWORDs
[ 18399 ]  lasthost    : Es ist 18:13 Uhr
[ 18458 ]  info        : stream ready, buffer filled in 48 ms
[ 18459 ]  info        : file has no mp3 tag, skip metadata
[ 18459 ]  info        : Audio-Length: 9312
[ 18472 ]  info        : syncword found at pos 0
[ 18477 ]  info        : Channels: 1
[ 18478 ]  info        : SampleRate: 24000
[ 18478 ]  info        : BitsPerSample: 16
[ 18478 ]  info        : BitRate: 32000
[ 20804 ]  info        : End of speech: "Es ist 18:13 Uhr"
[ 20808 ]  RFID-Karte empfangen: 211127118149
[ 20810 ]  Gebe Speicher der alten Playlist frei.
[ 20810 ]  Freier Speicher nach Aufräumen: 73180
[ 20822 ]  Freier Speicher: 73036
[ 20822 ]  Playlist-Generierung
[ 20829 ]  Anzahl gültiger Files/Webstreams: 10
[ 20829 ]  build playlist from SD-card finished: 19 ms
[ 20830 ]  Modus: Alle Tracks eines Ordners sortiert (alphabetisch) in Endlosschleife
[ 20867 ]  Neue Playlist mit 10 Titel(n) empfangen
[ 20867 ]  Free heap: 73212
[ 20874][V][ssl_client.cpp:321] stop_ssl_socket(): Cleaning SSL connection.
[ 20874 ]  info        : buffers freed, free Heap: 74668 bytes
[ 20885 ]  info        : Reading file: "/mp3only/01.mp3"
[ 20894 ]  info        : MP3Decoder has been initialized, free Heap: 47160 bytes , free stack 2948 DWORDs
[ 20895 ]  '/mp3only/01.mp3' wird abgespielt (1 von 10)
[ 20912 ]  info        : Content-Length: 4427776
[ 20913 ]  info        : ID3 framesSize: 1043
[ 20913 ]  info        : ID3 version: 2.3
[ 20931 ]  info        : ID3 normal frames
[ 21064 ]  info        : Audio-Length: 4426733
[ 21217 ]  info        : stream ready
[ 21220 ]  info        : syncword found at pos 0
[ 21228 ]  info        : Channels: 2
[ 21228 ]  info        : SampleRate: 44100
[ 21228 ]  info        : BitsPerSample: 16
[ 21228 ]  info        : BitRate: 128000

Meldungen bei nicht-fortgesetzter Wiedergabe

[ 22778 ]  info        : Closing audio file
[ 22778][V][ssl_client.cpp:321] stop_ssl_socket(): Cleaning SSL connection.
[ 22779 ]  info        : buffers freed, free Heap: 75276 bytes
[ 23073 ]  info        : chunked data transfer
[ 23082 ]  info        : MP3Decoder has been initialized, free Heap: 46468 bytes , free stack 2948 DWORDs
[ 23082 ]  lasthost    : Es ist 18:13 Uhr
[ 23145 ]  info        : stream ready, buffer filled in 52 ms
[ 23146 ]  info        : file has no mp3 tag, skip metadata
[ 23147 ]  info        : Audio-Length: 9312
[ 23159 ]  info        : syncword found at pos 0
[ 23164 ]  info        : Channels: 1
[ 23165 ]  info        : SampleRate: 24000
[ 23165 ]  info        : BitsPerSample: 16
[ 23165 ]  info        : BitRate: 32000
[ 25491 ]  info        : End of speech: "Es ist 18:13 Uhr"

Es fehlt also einfach der Teil der mittels xQueueSend(gRfidCardQueue, gPlayProperties.playRfidTag, 0); zum vorherigen Zustand zurückgeht, obwohl die Bedigung if (!gPlayProperties.currentSpeechActive && gPlayProperties.lastSpeechActive) erfüllt ist. Magie…

Manchmal (aber seltener als Punkt 1) tritt folgender Fehler auf, weswegen die Wiedergabe nicht wiederaufgenommen wird (RFID-Karte wird empfangen, aber: „Abspielmodus existiert nicht!“ obwohl bei allen Tests der RFID Code immer gleich war)

...
[ 50208 ]  RFID-Karte empfangen: 211127118149
[ 50212 ]  Gebe Speicher der alten Playlist frei.
[ 50213 ]  Freier Speicher nach Aufräumen: 67428
[ 50215 ]  Freier Speicher: 67284
[ 50215 ]  Playlist-Generierung
[ 50232 ]  Anzahl gültiger Files/Webstreams: 10
[ 50232 ]  build playlist from SD-card finished: 20 ms
[ 50233 ]  Abspielmodus existiert nicht!

Manchmal kommen ganz viele dieser Meldungen (ich glaube ganz unabhängig von TTS, das ist mir auf dem master oder älteren devs noch nie aufgefallen, taucht erst seit dem dev vom 8.8. auf):

ERROR: Too many messages queued
ERROR: Too many messages queued
ERROR: Too many messages queued

Das offenbar völlig zufällige Auftreten der Fehler insb. 1. und 2. macht mich kirre. Ich habe jetzt den Code nochmal eingehend angeschaut, und finde einfach keinen Anhaltspunkt. Kann jemand die Beobachtungen unter 1) nachvollziehen? Weiß jemand einen Fix/worans liegen könnte? Ich vermute es betrifft nicht nur den Zusammenhang mit TTS.

Und dann habe ich noch eine Frage betreffend TTS:
Wenn vorher die Musik-Wiedergabe auf Pause steht, dann etwas über TTS ausgegeben wird, dann wird danach leider die Musik-Wiedergabe durch xQueueSend(...) gestartet, also nicht im Pause-Zustand gelassen. Kann man das so ändern, dass wenn Wiedergabe vor tts in pause ist, dass sie auch nach tts in pause ist?

if (!gPlayProperties.pausePlay) {
  xQueueSend(gRfidCardQueue, gPlayProperties.playRfidTag, 0);
}

ist nicht die Lösung, damit kann man mittels Pauseplay dann nicht mehr in den Play-Zustand wechseln. Hat jemand eine Idee?

Vielen Dank für Inputs jeder Art!

tueddy · 9. August 2023 um 18:15

Danke für Deinen Fehlerbericht!
Wir haben in letzter Zeit viel reingebracht & da kann es natürlich auch zu Fehlern kommen. Einige schlummern auch schon länger & werden jetzt sichtbarer.
Wenn möglich erstelle isoliert für ein Problem/Fix einen PR, dann kann man einzeln das gut testen & schnell beheben!

Auf die Schnelle kann ich nur zu diesem Punkt etwas sagen:

ERROR: Too many messages queued

Das ist ein Fehler im Websocket & wird mit dem Refactoring der Weboberfläche zusammenhängen, passt auch zeitlich mit den letzten Checkins. Die Nachrichten-Queue des Websocket kann nur 32 Nachrichten aufnehmen, wenn die voll ist kommt es zum obigen Fehler.
Hatte das vorhin einmal: In der Konsole des Browser habe ich sehr viele „Ping“/„Pong“ Meldungen gesehen. Normalerweise darf das aber nur alle 15 Sek. passieren (Heartbeat Funktion der Weboberfläche). Nache einem Reset war der Spuk vorbei.
Warum das jetzt auftritt kann ich noch nicht sagen aber in die Richtung schaue ich nochmal genauer.

Play/Pause kann man im Log schlecht sehen, in beiden Fällen steht dort „Kommando: Pause“.
Ich checke nachher dafür ein Fix ein, dann steht dort „Kommando: Pause“ / „Kommando: Fortsetzen“. Evt. hilft das auch für Fehlersuche Punkt 1&2.

Edit: „Too many messages“ Fehler scheint schon länger zu existieren.

tueddy · 11. August 2023 um 08:35

@sfields Ich konnte Deine Fehler nachstellen, allerdings noch nicht alle lösen:

ERROR: Too many messages queued

Konnte das reproduzieren wenn die Weboberfläche lange offenbleibt und sich der ESPuino zwischenzeitlich schlafenlegt. Dann scheinen sich die PING Nachrichten im Browser zu stauen. Wenn der ESP aufwacht & wieder erreichbar ist wird er mit diesen Nachrichten überflutet & will hundertfach „PONG“ zurücksenden:

Dann ist die Socket-Queue bei 32 Nachrichten am Ende.
Habe das jetzt im Frontend & Backend abgefangen:

Das Frontend leert seinen Nachrichtenpuffer beim Öffnen des Socket.
Das Backend erlaubt nur noch einen PING/PONG pro Sekunde

–

[ 50233 ] Abspielmodus existiert nicht!

Habe das Logging erweitert & bekomme dann die Meldung

Ungültiger Abspielmodus (0)

Das bedeutet nach Abspielen einer Sprachausgabe wird u.U. der Abspielmodus auf der Karte geändert zu 0=NO_PLAYLIST. Zumindest ist das bei mir dann auch im NVS geändert & die Karte dann unbrauchbar!
Aber wo kommt das Schreiben ins NVS NO_PLAYLIST= 0 her? Habe es zumindest über die Weboberfläche mit einigen zusätzlichen Prüfungen abgefangen.

Aus meiner Sicht liegt das Problem hier noch tiefer, evt. hat jemand noch eine Idee?

sfields · 11. August 2023 um 09:23

Danke für deine Rückmeldung und toll, dass du schon einen Teil der Fehler abfangen konntest. Bin gerade im Urlaub und kann nicht weiter testen, ich habe mich auch gefragt, wo wird fälschlicherweise 0 als Abspielmodus in den NVS geschrieben. Ich habe es im Code nicht gefunden (kann aber auch nicht so gut programmieren), und vor allem dass es absolut zufällig zu passieren scheint, hat mir keine Ruhe gelassen
Ich vermute auch das Problem ist tieferliegend, ich meine es ist auch schon einmal in einem anderen Zusammenhang aufgetreten.
Hast du auch den 1. Fehler nachstellen können und eine Idee? Das mit dem Abspielmodus ist ja Fehler Nr.2 (der bei mir seltener als Fehler Nr. 1 auftritt).

tueddy · 11. August 2023 um 10:33

Fehler 1 kann ich auch nachstellen, also Pausieren nach TTS-Wiedergabe.
Hängt vermutlich auch damit zusammen dass die Karte sporadisch im NVS auf NO_PLAYLIST umprogrammiert wird.

Dein Fix für DONT_ACCEPT_SAME_RFID_TWICE_ENABLE erscheint mir richtig, ich würde das aber erst einbauen wenn Fehler 1 behoben ist…

tueddy · 21. August 2023 um 19:20

Fehler noch nicht gefunden:

Nach Ende der IP-/Uhrzeitansage müsste das aktuelle Lied fortgesetzt werden. Das klappt manchmal nicht weil der Spielmodus auf NO_PLAYLIST gesetzt ist, hier:

github.com

biologist79/ESPuino/blob/a7acc175781076d7930319faa88290caa75084c0/src/AudioPlayer.cpp#L762


      
          				speechOk = audio->connecttospeech(timeStringBuff,, "en");
          			#endif
          			if (!speechOk) {
          				System_IndicateError();
          			}
          		}
          
          		// If speech is over, go back to predefined state
          		if (!gPlayProperties.currentSpeechActive && gPlayProperties.lastSpeechActive) {
          			gPlayProperties.lastSpeechActive = false;
          			if (gPlayProperties.playMode != NO_PLAYLIST) {
          				xQueueSend(gRfidCardQueue, gPlayProperties.playRfidTag, 0);     // Re-inject previous RFID-ID in order to continue playback
          			}
          		}
          
          		// Handle if mono/stereo should be changed (e.g. if plugging headphones)
          		if (gPlayProperties.newPlayMono != gPlayProperties.currentPlayMono) {
          			gPlayProperties.currentPlayMono = gPlayProperties.newPlayMono;
          			audio->forceMono(gPlayProperties.currentPlayMono);
          			if (gPlayProperties.currentPlayMono) {
          				Log_Println(newPlayModeMono, LOGLEVEL_NOTICE);

Aber wo das fehlerhaft umgestellt wurde habe ich noch nicht herausgefunden.
Vielleicht gibt es einen Experten hier?