MPD-Device aktualisiert nicht immer alle Readings

Begonnen von RigorM, 23 April 2024, 16:29:56

Vorheriges Thema - Nächstes Thema

RigorM

Hallo zusammen,

dies ist mein erster Beitrag im Forum, und ich bin entsprechend nervös, also seid bitte nachsichtig mit mir. falls ich einiges nicht sofort richtig mache. Ich verspreche zu lernen.

Seit sechs Jahren betreibe ich einen FHEM-Server in meinem Häuschen und habe mich bislang mithilfe dieses Forums (großes Dankeschön!) und anderer Quellen eingentlich immer gut durchgewurschtelt und alles umsetzen können, was ich wollte. Jetzt aber bin ich auf ein Problem gestoßen, das meinen Horizont überfordert und zu dem ich auch nach intensiven Recherchen keine Lösung gefunden habe, so dass ich es nunmehr einmal an die Experten heranzutragen versuche.

Folgende Situation:

FHEM läuft auf einem Raspi 2 unter Debian Raspi Linux 4.14.34-v7+.
Auf der gleichen Maschine läuft ein mpd, ein weiterer auf einem anderen Raspi im LAN (Raspi 4 unter Debian Raspi4 Linux 6.6.20+rpt-rpi-v8).
Beide mpds überwache ich in FHEM mit je einem MPD-Device.
Das MPD-Device für den lokalen mpd aktualisiert alle seine Readings zufriedenstellend.
Das für den mpd auf dem Remote-Raspi allerdings aktualisiert gewisse Readings (z. B. file & Title) nur für jedes zweite Lied.
Das Problem ist reproduzierbar in einem anderen FHEM mit frisch definiertem MPD-Device.
Eine Neuinstallation von mpd auf dem Remote-Raspi hat das Problem nicht behoben.
Ein verbose = 5 auf dem problematischen MPD-Device ergibt u. a. Folgendes (auffällige Einträge hervorgehoben):

2024.04.22 22:12:12 5: myMPD, idle PID 16142 found
2024.04.22 22:12:12 5: myMPD, mpd_cmd[1] -> status
2024.04.22 22:12:12 5: myMPD, rec: repeat: 1
2024.04.22 22:12:12 5: myMPD, rec: random: 1
2024.04.22 22:12:12 5: myMPD, rec: single: 0
2024.04.22 22:12:12 5: myMPD, rec: consume: 0
2024.04.22 22:12:12 5: myMPD, rec: partition: default
2024.04.22 22:12:12 5: myMPD, rec: playlist: 2
2024.04.22 22:12:12 5: myMPD, rec: playlistlength: 9225
2024.04.22 22:12:12 5: myMPD, rec: mixrampdb: 0
2024.04.22 22:12:12 5: myMPD, rec: state: play
2024.04.22 22:12:12 5: myMPD, rec: song: 8766
2024.04.22 22:12:12 5: myMPD, rec: songid: 8767
2024.04.22 22:12:12 5: myMPD, rec: time: 142:152
2024.04.22 22:12:12 5: myMPD, rec: elapsed: 142.254
2024.04.22 22:12:12 5: myMPD, rec: bitrate: 0
2024.04.22 22:12:12 5: myMPD, rec: duration: 152.000
2024.04.22 22:12:12 5: myMPD, rec: audio: 44100:f:2
2024.04.22 22:12:12 5: myMPD, rec: nextsong: 7925
2024.04.22 22:12:12 5: myMPD, rec: nextsongid: 7926
!--------------------------------------------------------------
2024.04.22 22:12:22 5: myMPD, MPD_EVENT : player
2024.04.22 22:12:22 4: myMPD, MPD_EVENT : player
!--------------------------------------------------------------
2024.04.22 22:12:22 5: myMPD, mpd_cmd[1] -> command_list_begin
status
stats
currentsong
command_list_end
2024.04.22 22:12:22 5: myMPD, rec: repeat: 1
2024.04.22 22:12:22 5: myMPD, rec: random: 1
2024.04.22 22:12:22 5: myMPD, rec: single: 0
2024.04.22 22:12:22 5: myMPD, rec: consume: 0
2024.04.22 22:12:22 5: myMPD, rec: partition: default
2024.04.22 22:12:22 5: myMPD, rec: playlist: 2
2024.04.22 22:12:22 5: myMPD, rec: playlistlength: 9225
2024.04.22 22:12:22 5: myMPD, rec: mixrampdb: 0
2024.04.22 22:12:22 5: myMPD, rec: state: play
2024.04.22 22:12:22 5: myMPD, rec: song: 7925
2024.04.22 22:12:22 5: myMPD, rec: songid: 7926
2024.04.22 22:12:22 5: myMPD, rec: time: 0:409
2024.04.22 22:12:22 5: myMPD, rec: elapsed: 0.000
2024.04.22 22:12:22 5: myMPD, rec: bitrate: 128
2024.04.22 22:12:22 5: myMPD, rec: duration: 408.829
2024.04.22 22:12:22 5: myMPD, rec: audio: 44100:24:2
2024.04.22 22:12:22 5: myMPD, rec: nextsong: 7288
2024.04.22 22:12:22 5: myMPD, rec: nextsongid: 7289
2024.04.22 22:12:22 5: myMPD, rec: uptime: 10734
2024.04.22 22:12:22 5: myMPD, rec: playtime: 10735
2024.04.22 22:12:22 5: myMPD, rec: artists: 2508
2024.04.22 22:12:22 5: myMPD, rec: albums: 1260
2024.04.22 22:12:22 5: myMPD, rec: songs: 9225
2024.04.22 22:12:22 5: myMPD, rec: db_playtime: 2105031
2024.04.22 22:12:22 5: myMPD, rec: db_update: 1713802306
2024.04.22 22:12:22 5: myMPD, rec: file: International/T/Type O Negative/October Rust/Type O Negative - Red Water (Christmas Mourning).mp3
2024.04.22 22:12:22 5: myMPD, rec: Last-Modified: 2020-10-29T14:51:32Z
2024.04.22 22:12:22 5: myMPD, rec: Format: 44100:24:2
2024.04.22 22:12:22 5: myMPD, rec: Artist: Type O Negative
2024.04.22 22:12:22 5: myMPD, rec: Title: Red Water (Christmas Mourning)
2024.04.22 22:12:22 5: myMPD, rec: Album: October Rust
2024.04.22 22:12:22 5: myMPD, rec: Date: 1996
2024.04.22 22:12:22 5: myMPD, rec: Genre: Rock
2024.04.22 22:12:22 5: myMPD, rec: Time: 409
2024.04.22 22:12:22 5: myMPD, rec: duration: 408.829
2024.04.22 22:12:22 5: myMPD, rec: Pos: 7925
2024.04.22 22:12:22 5: myMPD, rec: Id: 7926
!--------------------------------------------------------------
2024.04.22 22:12:22 5: myMPD, new Playlist in ->
2024.04.22 22:12:22 5: myMPD, IdleDone -> myMPD|socket error
2024.04.22 22:12:22 4: myMPD, idle error -> socket error
2024.04.22 22:12:37 4: myMPD, Idle new PID : 16558
!--------------------------------------------------------------
2024.04.22 22:12:37 5: myMPD, mpd_cmd[1] -> command_list_begin
status
stats
currentsong
command_list_end
2024.04.22 22:12:37 5: myMPD, rec: repeat: 1
2024.04.22 22:12:37 5: myMPD, rec: random: 1
2024.04.22 22:12:37 5: myMPD, rec: single: 0
2024.04.22 22:12:37 5: myMPD, rec: consume: 0
2024.04.22 22:12:37 5: myMPD, rec: partition: default
2024.04.22 22:12:37 5: myMPD, rec: playlist: 2
2024.04.22 22:12:37 5: myMPD, rec: playlistlength: 9225
2024.04.22 22:12:37 5: myMPD, rec: mixrampdb: 0
2024.04.22 22:12:37 5: myMPD, rec: state: play
2024.04.22 22:12:37 5: myMPD, rec: song: 7925
2024.04.22 22:12:37 5: myMPD, rec: songid: 7926
2024.04.22 22:12:37 5: myMPD, rec: time: 15:409
2024.04.22 22:12:37 5: myMPD, rec: elapsed: 15.124
2024.04.22 22:12:37 5: myMPD, rec: bitrate: 128
2024.04.22 22:12:37 5: myMPD, rec: duration: 408.829
2024.04.22 22:12:37 5: myMPD, rec: audio: 44100:24:2
2024.04.22 22:12:37 5: myMPD, rec: nextsong: 7288
2024.04.22 22:12:37 5: myMPD, rec: nextsongid: 7289
2024.04.22 22:12:37 5: myMPD, rec: uptime: 10749
2024.04.22 22:12:37 5: myMPD, rec: playtime: 10750
2024.04.22 22:12:37 5: myMPD, rec: artists: 2508
2024.04.22 22:12:37 5: myMPD, rec: albums: 1260
2024.04.22 22:12:37 5: myMPD, rec: songs: 9225
2024.04.22 22:12:37 5: myMPD, rec: db_playtime: 2105031
2024.04.22 22:12:37 5: myMPD, rec: db_update: 1713802306
2024.04.22 22:12:37 5: myMPD, rec: file: International/T/Type O Negative/October Rust/Type O Negative - Red Water (Christmas Mourning).mp3
2024.04.22 22:12:37 5: myMPD, rec: Last-Modified: 2020-10-29T14:51:32Z
2024.04.22 22:12:37 5: myMPD, rec: Format: 44100:24:2
2024.04.22 22:12:37 5: myMPD, rec: Artist: Type O Negative
2024.04.22 22:12:37 5: myMPD, rec: Title: Red Water (Christmas Mourning)
2024.04.22 22:12:37 5: myMPD, rec: Album: October Rust
2024.04.22 22:12:37 5: myMPD, rec: Date: 1996
2024.04.22 22:12:37 5: myMPD, rec: Genre: Rock
2024.04.22 22:12:37 5: myMPD, rec: Time: 409
2024.04.22 22:12:37 5: myMPD, rec: duration: 408.829
2024.04.22 22:12:37 5: myMPD, rec: Pos: 7925
2024.04.22 22:12:37 5: myMPD, rec: Id: 7926
2024.04.22 22:12:37 5: myMPD, mpd_cmd[2] -> command_list_begin
status
stats
currentsong
command_list_end
2024.04.22 22:12:52 5: myMPD, idle PID 16558 found
2024.04.22 22:12:52 5: myMPD, mpd_cmd[1] -> status
2024.04.22 22:12:52 5: myMPD, rec: repeat: 1
2024.04.22 22:12:52 5: myMPD, rec: random: 1
2024.04.22 22:12:52 5: myMPD, rec: single: 0
2024.04.22 22:12:52 5: myMPD, rec: consume: 0
2024.04.22 22:12:52 5: myMPD, rec: partition: default
2024.04.22 22:12:52 5: myMPD, rec: playlist: 2
2024.04.22 22:12:52 5: myMPD, rec: playlistlength: 9225
2024.04.22 22:12:52 5: myMPD, rec: mixrampdb: 0
2024.04.22 22:12:52 5: myMPD, rec: state: play
2024.04.22 22:12:52 5: myMPD, rec: song: 7925
2024.04.22 22:12:52 5: myMPD, rec: songid: 7926
2024.04.22 22:12:52 5: myMPD, rec: time: 30:409
2024.04.22 22:12:52 5: myMPD, rec: elapsed: 30.088
2024.04.22 22:12:52 5: myMPD, rec: bitrate: 128
2024.04.22 22:12:52 5: myMPD, rec: duration: 408.829
2024.04.22 22:12:52 5: myMPD, rec: audio: 44100:24:2
2024.04.22 22:12:52 5: myMPD, rec: nextsong: 7288
2024.04.22 22:12:52 5: myMPD, rec: nextsongid: 7289

Auffällig ist hier der Fehler socket_error, der aber auch bei dem anderen, unproblematischen MPD-Device regelmäßig auftritt, so dass das eigentlich kein Hinweis auf die Ursache sein kann.
Allerdings ist genau dieses Lied, bei dem der Fehler auftritt, dasjenige, dessen Readings komplett aktualisiert werden.
Beim nächsten Lied kommt dann jedoch kein MPD_EVENT : player mehr, und die Readings 'file', 'Title' und 'rawTitle' werden nicht aktualisiert.
Beim übernächsten Lied kommt es wieder - zusammen mit dem socket_error. Und nun werden auch wieder alle Readings aktualisiert.
Beim unproblematischen MPD hingegen kommt vor jedem neuen Lied ein MPD_EVENT : player.

Hier ein Auszug aus den Internals für das problematische MPD-Device:

define MPD_local MPD 192.168.178.40 6600
attr MPD_local devStateIcon play:rc_PLAY:stop stop:rc_STOP:play pause:rc_PAUSE:pause error:icoBlitz
attr MPD_local icon it_radio
attr MPD_local loadMusic 0
attr MPD_local loadPlaylists 0
attr MPD_local no_playlistcollection 1
attr MPD_local player mpd
attr MPD_local titleSplit 1
attr MPD_local unknown_artist_image /fhem/icons/1px-spacer
attr MPD_local verbose 5
attr MPD_local waits 15
#   DEF        192.168.178.40 6600
#   DeviceName 192.168.178.40:6600
#   FUUID      659c465f-f33f-3b1b-687c-9d8d598910939ba3
#   HOST       192.168.178.40
#   IPID       13129
#   NAME       MPD_local
#   NR         269
#   PORT       6600
#   PRESENCE   present
#   STATE      play
#   SUBVERSION 23
#   TIMEOUT    0.7
#   TYPE       MPD
#   VERSION    0.23.5
#   eventCount 9325
#   mute       -1
#   helper:
#     RUNNING_PID:
#       abortArg  
#       abortFn   
#       arg        MPD_local
#       bc_pid     44845
#       finishFn   MPD_IdleDone
#       fn         MPD_IdleStart
#       pid        13129
#       timeout   
#     playlistcollection:
#       val        -1

Und hier für das unproblematische:

define MPD_remote MPD
attr MPD_remote devStateIcon play:rc_PLAY:stop stop:rc_STOP:play pause:rc_PAUSE:pause error:icoBlitz
attr MPD_remote icon it_radio
attr MPD_remote loadMusic 0
attr MPD_remote loadPlaylists 0
attr MPD_remote no_playlistcollection 1
attr MPD_remote player mpd
attr MPD_remote titleSplit 1
attr MPD_remote unknown_artist_image /fhem/icons/1px-spacer
attr MPD_remote verbose 5
attr MPD_remote waits 15
#   DeviceName 127.0.0.1:6600
#   FUUID      61444f90-f33f-3b1b-5541-f87ec1b1ec77cb43
#   HOST       127.0.0.1
#   IPID       14481
#   NAME       MPD_remote
#   NR         208
#   PORT       6600
#   PRESENCE   present
#   STATE      play
#   SUBVERSION 19
#   TIMEOUT    0.7
#   TYPE       MPD
#   VERSION    0.19.0
#   eventCount 13063
#   mute       -1
#   helper:
#     RUNNING_PID:
#       abortArg  
#       abortFn   
#       arg        MPD_remote
#       bc_pid     45199
#       finishFn   MPD_IdleDone
#       fn         MPD_IdleStart
#       pid        14481
#       timeout   
#     playlistcollection:
#       val        -1

Und hier noch einige Versionsinformationen:

mpd (lokal): 0.19.21
mpd (remote, der problematische): 0.23.12

FHEM rev.: 28809
fhem.pl rev.: 28666
73_MPD.pm rev.: 27027

Hat irgendwer 'ne Ahnung, was hier vor sich gehen könnte?
Da ich persönlich eher mittelmäßig in der Materie verwurzelt bin, wäre ich für jeden Hinweis, in welche Richtung ich weitergehen sollte, dankbar.

LG
Rigor

Beta-User

Vorab mal: Willkommen im FHEM-Forum, und Danke für den vorbildlichen Post!

Habe im Hinblick darauf nochmal einen vertieften Blick in den Code und die History geworfen und dann den vorgeschlagenen Fix von
Zitat von: Medel am 02 Januar 2024, 15:05:08Habe mal in der 73_MPD.pm noch ein OK eingefügt:
1285     elsif ($_ !~ m{\Aplayer|playlist|mixer|options|update|OK\z}x){
Bisher hatte ich keinen socket error mehr und auch das Problem mit dem Play und der Aktualisierung ist weg. Wird gleich beim erstem Mal richtig angezeigt.
Bitte mal jemand der sich damit besser auskennt darüber schauen und ggf. einpflegen.
aus dem Haupt-Thread zu MPD übernommen (kommt dann mit dem morgigen update).

Bitte um Rückmeldung, falls das dein Problem (auch) behebt....
Server: HP-elitedesk@Debian 12, aktuelles FHEM@ConfigDB | CUL_HM (VCCU) | MQTT2: MiLight@ESP-GW, BT@OpenMQTTGw | MySensors: seriell, v.a. 2.3.1@RS485 | ZWave | ZigBee@deCONZ | SIGNALduino | MapleCUN | RHASSPY
svn: u.a MySensors, Weekday-&RandomTimer, Twilight,  div. attrTemplate-files

RigorM

Cool!
Habe zwar den Haupt-Thread zu MPD mehrfach auf und ab bis zur totalen Frustration durchkämmt, bis zu diesen letzten Postings bin ich aber anscheinend nie gelangt, sonst hätte ich mich da rangehängt...
Werde das Update sofort ausprobieren, wenn's kommt!

RigorM

So, habe das aktuelle Update eingespielt und getestet.

Die gute Nachricht: Kein socket_error mehr.

Die schlechte: Das Schema, nach dem sich jetzt die Readings aktualisieren, hat sich geändert, ist allerdings immer noch nicht korrekt.
Zwar wird 'file' nun bei jedem Track Change aktualisiert, nicht mehr nur bei jedem zweiten, dafür aktualisiert sich 'Title' nur noch sporadisch und 'Artist' gar nicht mehr. Zu den übrigen kann ich wenig sagen, da ich hauptsächlich die genannten im Auge behalten habe.
Und für mich persönlich ist das auch gar nicht so relevant, da ich im wesentlichen nur das Reading 'file' auswerte, das ja nun sauber reinkommt, aber richtig sieht es leider immer noch nicht aus, zumal im Device Overview nun regelmäßig Blödsinn angezeigt wird (unsinnige Kombinationen aus Artist und Title, bedingt durch das beschriebene Aktualisierungsverhalten der beiden Readings).
Im verbose 5 log tauchen jetzt die Parts mit MPD_EVENT : player und mpd_cmd[1] -> command_list_begin incl. aller auf dieses Kommando folgenden Ausgaben gar nicht mehr auf. Es wird immer nur noch der folgende Block wiederholt

2024.04.25 10:55:49 5: myMPD, idle PID 414 found
2024.04.25 10:55:49 5: myMPD, mpd_cmd[1] -> status
2024.04.25 10:55:49 5: myMPD, rec: repeat: 1
2024.04.25 10:55:49 5: myMPD, rec: random: 1
2024.04.25 10:55:49 5: myMPD, rec: single: 0
2024.04.25 10:55:49 5: myMPD, rec: consume: 0
2024.04.25 10:55:49 5: myMPD, rec: partition: default
2024.04.25 10:55:49 5: myMPD, rec: playlist: 2
2024.04.25 10:55:49 5: myMPD, rec: playlistlength: 9225
2024.04.25 10:55:49 5: myMPD, rec: mixrampdb: 0
2024.04.25 10:55:49 5: myMPD, rec: state: play
2024.04.25 10:55:49 5: myMPD, rec: song: 1418
2024.04.25 10:55:49 5: myMPD, rec: songid: 1419
2024.04.25 10:55:49 5: myMPD, rec: time: 246:261
2024.04.25 10:55:49 5: myMPD, rec: elapsed: 246.116
2024.04.25 10:55:49 5: myMPD, rec: bitrate: 128
2024.04.25 10:55:49 5: myMPD, rec: duration: 261.284
2024.04.25 10:55:49 5: myMPD, rec: audio: 44100:24:2
2024.04.25 10:55:49 5: myMPD, rec: nextsong: 3802
2024.04.25 10:55:49 5: myMPD, rec: nextsongid: 3803

wobei bei einem Track Change die Ausgabe idle PID xxx found zweimal erfolgt.
Mehr nicht.

Ich hoffe, diese Beobachtungen sind in irgendeiner Form hilfreich.

RigorM

Kurzer Nachtrag:
Nach einigen Stunden Laufzeit wird nun auch das 'file'-Reading nicht mehr aktualisiert. Die zweite Ausgabe von idle PID xxx found im verbose 5 log während eines Track Change ist auch verschwunden. Ein 'set myMPD reset' hat keine Abhilfe geschaffen, ein Reload des Moduls ebenfalls nicht, genausowenig ein Neustart von FHEM oder dem fernen mpd, und auch ein Reboot beider Raspis nicht.
Ist nur seltsam, dass es anfangs funktioniert hat...

Beta-User

Bin im Moment (leider) mit dem Thema deutlich überfragt....

Steht denn was im Reading "last_error"? Soweit ich die letzen Beiträge zum Thema MPD durchgeflözt habe, sollte das eigentlich dazu dienen relativ einfach rauszufinden, wenn was passiert, das der Code nicht kennt. Ist aber auch schon wieder sehr lange her, dass ich mich damit beschäftigt hatte.
Server: HP-elitedesk@Debian 12, aktuelles FHEM@ConfigDB | CUL_HM (VCCU) | MQTT2: MiLight@ESP-GW, BT@OpenMQTTGw | MySensors: seriell, v.a. 2.3.1@RS485 | ZWave | ZigBee@deCONZ | SIGNALduino | MapleCUN | RHASSPY
svn: u.a MySensors, Weekday-&RandomTimer, Twilight,  div. attrTemplate-files

RigorM

"last_error" gibt leider nichts her, da kommt im laufenden Betrieb nichts rein.
Bin mir inzwischen aber auch gar nicht mehr sicher, ob das Problem überhaupt bei FHEM liegt oder nicht eher bei den mpds bzw. der Art und Weise, wie FHEM mit ihnen redet und wie sie das dann interpretieren.
Deshalb hab ich mir mal 'verbose' logs beider mpds mit der alten und der neuen Version des MPD-Moduls erzeugt, um zu sehen, was auf der anderen Seite ankommt, leider werde ich aus den Resultaten noch nicht ganz schlau und werde wohl auch die nächsten Tage wenig Muße haben, mich da reinzufinden. Aber mal schauen, was sich machen läßt.
Vorläufig habe ich das Problem jedenfalls damit überbrückt, auf das 'time'-Reading des MPD-Devices, das immer zuverlässig neu befüllt wird, ein notify zu legen, das mir ein "set myMPD play" an den mpd zurückschickt und damit eine Aktualisierung aller Readings erzwingt.
Mit "waits 15" gibt das 'ne akzeptable zeitliche Auflösung.

RigorM

So, habe jetzt mal ausgiebig die verbose Logs meiner beiden mpds durchkämmt, und danach sieht es so aus, als würden beide vollkommen unterschiedlich auf die Anfragen von FHEM reagieren.
Woran das aber liegt (Timing, Konfiguration oder prinzipielle Inkompatibilität aufgrund von Versionsunterschieden), ist mir im Augenblick noch völlig schleierhaft.
Allerdings bereitet mir der zweite mpd auch anderweitig Probleme. Er verliert nämlich immer mal wieder die Verbindung zum Icecast, an den er eigentlich ausgeben soll.
Jetzt ist mir aufgefallen, dass diese Abbrüche praktisch verschwunden sind, seit ich dem mpd via FHEM alle 15 s einen "Tritt in den Hintern" verpasse.
Schläft also offenbar hin und wieder mal ein, der Gute, und vllt. ist das auch der Grund für die Schwierigkeiten, mit FHEM zu kommunizieren.
Also werde ich jetzt erst mal in diese Richtung weiterforschen.