Probleme mit MPD

[Wernieman]

Hallo Freunde,

habe hier FHEM in einen selbstgebauten Container laufen. Auf einen anderen Server läuft mpd, den ich mit dem Modul MPD steuer.

Hier das List:

Code Auswählen Erweitern


Internals:
   .album     
   .apikey    f3a26c7c8b4c4306bc382557d5c04ad5
   .artist   
   .lasterror
   .music     
   .musiclist
   .outputs   outputid: 0
outputname: My HTTP Stream
outputenabled: 1
outputid: 1
outputname: My Pulse Output
outputenabled: 1

   .password 
   .player    mpd
   .playlist 
   .playlist_crc 23566
   .playlists Kuschelrock
Radio.old
Deutsche Schlager
ndr2
Dan Brown - Das verlorene Symbol
Radio
   .reset     0
   .sMusicL   1
   .sPlayL    1
   .volume    35
   DEF        mimi.maxel.home
   DeviceName mimi.maxel.home:6600
   FUUID      603544fc-f33f-a76c-9969-741327bee7e6e553
   HOST       mimi.maxel.home
   IPID       385
   NAME       myMPD
   NR         93
   PORT       6600
   PRESENCE   present
   STATE      play
   SUBVERSION 20
   TIMEOUT    2
   TYPE       MPD
   VERSION    0.20.0
   mute       -1
   .attraggr:
   .attreocr:
     state
     error
   .attrminint:
   READINGS:
     2021-03-06 10:48:34   Album           
     2021-03-06 11:01:32   Artist          MDR SACHSEN
     2021-03-06 10:48:34   Cover           
     2021-03-06 10:48:34   Date           
     2021-03-06 10:48:34   Genre           
     2021-03-06 11:01:32   Id              3
     2021-03-06 10:48:34   Last-Modified   
     2021-03-06 11:01:32   Name            MDR SACHSEN - Regionalstudio Leipzig
     2021-03-06 11:01:32   Pos             0
     2021-03-06 11:01:32   Title           Regionalstudio Leipzig
     2021-03-06 10:48:34   Track           
     2021-03-06 10:48:30   album_image     /fhem/icons/1px-spacer
     2021-03-06 10:48:30   album_image_html
     2021-03-06 11:01:32   albums          0
     2021-03-06 10:48:30   artist_image    /fhem/icons/1px-spacer
     2021-03-06 10:48:30   artist_image_html
     2021-03-06 11:01:32   artists         0
     2021-03-06 11:01:32   audio           48000:24:2
     2021-03-06 11:01:32   bitrate         128
     2021-03-06 11:01:32   consume         0
     2021-03-06 11:01:32   currentTrackProvider Radio
     2021-03-06 11:01:32   db_playtime     0
     2021-03-06 11:01:32   db_update       1615024651
     2021-03-06 11:01:32   elapsed         14.946
     2021-03-06 11:01:32   file            http://mdr-284280-3.cast.mdr.de/mdr/284280/3/mp3/high/stream.mp3
     2021-03-06 10:57:26   last_error      IdleStart: Connection refused
     2021-03-06 11:01:32   mixrampdb       0.000000
     2021-03-06 11:01:18   mpd_event       playlist+player
     2021-02-23 19:10:09   mute            off
     2021-03-06 11:01:32   nextsong        1
     2021-03-06 11:01:32   nextsongid      4
     2021-03-06 10:42:44   outputenabled0  1
     2021-03-06 10:42:44   outputenabled1  1
     2021-03-06 10:42:44   outputname0     My HTTP Stream
     2021-03-06 10:42:44   outputname1     My Pulse Output
     2021-03-06 11:01:32   playlist        9
     2021-03-06 11:01:18   playlist_crc    23566
     2021-03-06 10:42:44   playlist_json   
     2021-03-06 10:42:44   playlist_num    -1
     2021-03-06 10:42:44   playlistcollection Kuschelrock:Radio.old:Deutsche Schlager:ndr2:Dan Brown - Das verlorene Symbol:Radio
     2021-03-06 11:01:18   playlistinfo    [{"Artist":"MDR SACHSEN","Title":"Regionalstudio Leipzig","Album":"","Time":"","File":"http://mdr-284280-3.cast.mdr.de/mdr/284280/3/mp3/high/stream.mp3","Track":"","Cover":"/fhem/icons/1px-spacer"}]
     2021-03-06 11:01:32   playlistlength  2
     2021-03-06 10:42:44   playlistname   
     2021-03-06 11:01:32   playtime        241
     2021-03-06 11:01:32   presence        present
     2021-03-06 11:01:32   random          0
     2021-03-06 11:01:32   rawTitle        MDR SACHSEN - Regionalstudio Leipzig
     2021-03-06 11:01:32   repeat          0
     2021-03-06 11:01:32   single          0
     2021-03-06 11:01:32   song            0
     2021-03-06 11:01:32   songid          3
     2021-03-06 11:01:32   songs           0
     2021-03-06 11:01:32   state           play
     2021-03-06 11:01:32   time            15:0
     2021-03-06 10:53:45   updating_db     1
     2021-03-06 11:01:32   uptime          241
     2021-03-06 11:01:32   volume          35
   helper:
     RUNNING_PID:
       abortArg   
       abortFn   
       arg        myMPD
       bc_pid     97
       finishFn   MPD_IdleDone
       fn         MPD_IdleStart
       pid        385
       timeout   
     playlistcollection:
       0          Kuschelrock
       1          Radio.old
       2          Deutsche Schlager
       3          ndr2
       4          Dan Brown - Das verlorene Symbol
       5          Radio
       val        5
Attributes:
   cache      lfm
   devStateIcon play:rc_PLAY:stop stop:rc_STOP:play pause:rc_PAUSE:pause
   event-on-change-reading state,error
   icon       it_radio
   loadPlaylists 1
   player     mpd
   room       Musik
   titleSplit 1
   unknown_artist_image /fhem/icons/1px-spacer
   userattr   room_map structexclude
   volumeStep 5


Es funktioniert auch "eigentlich", also stop/start/pause, nur bin ich heute beim Debugen eines anderen Problems darauf gestoßen, das das MPD-Modul eben nicht richtig läuft. Im Logfile von FHEM steht immer wieder:

Code Auswählen Erweitern


....
2021.03.06 11:02:32 2: myMPD, cant find idle PID 385 in process list !
2021.03.06 11:02:32 1: Timeout for MPD_IdleStart reached, terminated process 385
....


Nicht wundern, das keine Music includiert, habe beim Debuggen das Musicverzeichnis mal auf ein leeres gesetzt. Habe sehr viele Musikstücke und dachte an ein Mengenproblem. Aktuell verwende ich nur Radio-Streams. Alle notwendigen perl-Erweiterungen laut Doku wurde installiert (geprüft). Weiß jemand, wo ich noch gucken kann? Und welche Infos noch benötigt werden?

Noch Info:

Code Auswählen Erweitern

perl: v5.30.0
mpd: 0.20.18-1build1


[Wernieman]

Habe mich jetzt etwas tiefr engelesen und:
timeout erhöht -> Keine Änderung
verbose erhöht, nichts auffälliges (s.u.)

Versucht Problem nachzuvollziehen. PID existiert und wird (nach meiner Erkenntnis) trotzdem als "nicht existend" erkannt. Kann es nicht nachvolziehen, bin da nicht so der Code-Experte 

Verbode 5 Log:

Code Auswählen Erweitern


.....
2021.03.06 12:02:30 2: myMPD, cant find idle PID 1450 in process list !
2021.03.06 12:02:30 1: Timeout for MPD_IdleStart reached, terminated process 1450
2021.03.06 12:02:32 4: myMPD, Idle new PID : 1458
2021.03.06 12:02:32 5: myMPD, mpd_cmd[1] -> command_list_begin
status
stats
currentsong
command_list_end
2021.03.06 12:02:32 5: myMPD, rec: volume: 35
2021.03.06 12:02:32 5: myMPD, rec: repeat: 0
2021.03.06 12:02:32 5: myMPD, rec: random: 0
2021.03.06 12:02:32 5: myMPD, rec: single: 0
2021.03.06 12:02:32 5: myMPD, rec: consume: 0
2021.03.06 12:02:32 5: myMPD, rec: playlist: 43
2021.03.06 12:02:32 5: myMPD, rec: playlistlength: 2
2021.03.06 12:02:32 5: myMPD, rec: mixrampdb: 0.000000
2021.03.06 12:02:32 5: myMPD, rec: state: play
2021.03.06 12:02:32 5: myMPD, rec: song: 0
2021.03.06 12:02:32 5: myMPD, rec: songid: 7
2021.03.06 12:02:32 5: myMPD, rec: time: 1537:0
2021.03.06 12:02:32 5: myMPD, rec: elapsed: 1537.298
2021.03.06 12:02:32 5: myMPD, rec: bitrate: 128
2021.03.06 12:02:32 5: myMPD, rec: audio: 48000:24:2
2021.03.06 12:02:32 5: myMPD, rec: nextsong: 1
2021.03.06 12:02:32 5: myMPD, rec: nextsongid: 8
2021.03.06 12:02:32 5: myMPD, rec: uptime: 3901
2021.03.06 12:02:32 5: myMPD, rec: playtime: 3412
2021.03.06 12:02:32 5: myMPD, rec: artists: 0
2021.03.06 12:02:32 5: myMPD, rec: albums: 0
2021.03.06 12:02:32 5: myMPD, rec: songs: 0
2021.03.06 12:02:32 5: myMPD, rec: db_playtime: 0
2021.03.06 12:02:32 5: myMPD, rec: db_update: 1615024651
2021.03.06 12:02:32 5: myMPD, rec: file: http://mdr-284280-3.cast.mdr.de/mdr/284280/3/mp3/high/stream.mp3
2021.03.06 12:02:32 5: myMPD, rec: Title: MDR SACHSEN - Regionalstudio Leipzig
2021.03.06 12:02:32 5: myMPD, rec: Name: MDR SACHSEN - Regionalstudio Leipzig
2021.03.06 12:02:32 5: myMPD, rec: Pos: 0
2021.03.06 12:02:32 5: myMPD, rec: Id: 7
2021.03.06 12:02:32 5: myMPD, mpd_cmd[2] -> command_list_begin
status
stats
currentsong
command_list_end
2021.03.06 12:03:32 2: myMPD, cant find idle PID 1458 in process list !
2021.03.06 12:03:32 1: Timeout for MPD_IdleStart reached, terminated process 1458
2021.03.06 12:03:34 4: myMPD, Idle new PID : 1486
2021.03.06 12:03:34 5: myMPD, mpd_cmd[1] -> command_list_begin
....


Edit:
Es scheint wirklich ein PID-Erkennung Problem zu sein:

Code Auswählen Erweitern

2021.03.06 12:16:08 4: myMPD, Idle new PID : 48
Im 2. Fenster im Container geguckt:

Code Auswählen Erweitern

root@fhem:/# ps -e
    PID TTY          TIME CMD
      1 ?        00:00:00 sh
      9 ?        00:00:06 fhem.pl
     22 ?        00:00:00 fhem.pl
     23 ?        00:00:00 fhem.pl
     24 ?        00:00:00 fhem.pl
     48 ?        00:00:00 fhem.pl
     49 pts/0    00:00:00 bash
     57 pts/0    00:00:00 ps


trotzdem sagt das Modul (Debug ist von mir testweise reingeschrieben):

Code Auswählen Erweitern


2021.03.06 12:17:08 2: myMPD, debug: ps -e | grep '48 '
2021.03.06 12:17:08 2: myMPD, cant find idle PID 48 in process list !
2021.03.06 12:17:10 4: myMPD, Idle new PID : 69


Ich bin ratlos .....

[Wernieman]

Auch wenn ich jetzt Selbstgespräche führe, habe den Grunde gefunden ...

Im Modul steht:

Code Auswählen Erweitern

if  (index($result,"perl") == -1)
bei mir ist aber die Ausgabe:

Code Auswählen Erweitern

     19 ?        00:00:00 fhem.pl
Wenn ich also das perl gegen fhem tausche, funzt es. Da ich nicht der einzigste sein sollte, kann man es ändern? Also nicht nur auf "perl", sondern auch auf "fhem" prüfen?

[Wzut]

ja eine Altlast, das hatte ich auch 1:1 so im SIP Modul und umgebaut nach einem User Tipp für andere OS Versionen.
Hatte gar nicht mehr auf dem Radar das ich die Erkennung im MPD Modul genauso gemacht hatte.
Mal schauen ob ich übers WE ein Update nachschieben kann.

[Wernieman]

Kein Problem .. habe aktuell das Problem "gelöst" ...
Darf man fragen, wie Du jetzt die Erkennung Lösen würdest?

[Wzut]

der ganze Block sieht aktuell so aus :

Code Auswählen Erweitern


my $cmd    = "ps -e | grep '".$hash->{IPID}." '";
  my $result = qx($cmd);

  if  (index($result,"perl") == -1)
  {
   Log3 $name, 2 , $name.", cant find idle PID ".$hash->{IPID}." in process list !";
   BlockingKill($hash->{helper}{RUNNING_PID});
   delete $hash->{helper}{RUNNING_PID};
   delete $hash->{IPID};
   InternalTimer(gettimeofday()+2, "MPD_try_idle", $hash, 0);
   return;
  }
  else
  {
    Log3 $name, 5 , $name.", idle PID ".$hash->{IPID}." found";
    if ((ReadingsVal($name,"presence","") eq "present") &&
        ($hash->{STATE} eq "play") &&
        (ReadingsVal($name,"currentTrackProvider","") ne "Radio")
       )
    {
     # Wichtig um das Readings elapsed aktuell zu halten (TabletUI)
     mpd_cmd($hash, "status");
     readingsSingleUpdate($hash,"playlistname",$hash->{".playlist"},1) if ($hash->{READINGS}{"playlistname"}{VAL} ne $hash->{".playlist"});
    }
  }


analog zum SIP Modul wäre es dann :

Code Auswählen Erweitern

#my $cmd    = "ps -e | grep '".$hash->{IPID}." '";
  #my $result = qx($cmd);

  #if  (index($result,"perl") == -1)
  unless (kill 0, $hash->{IPID})
  {
   Log3 $name, 2 , $name.", cant find idle PID ".$hash->{IPID}." in process list !";
   BlockingKill($hash->{helper}{RUNNING_PID});
   delete $hash->{helper}{RUNNING_PID};
   delete $hash->{IPID};
   InternalTimer(gettimeofday()+2, "MPD_try_idle", $hash, 0);
   return;
  }
  #else
  #{
    Log3 $name, 5 , $name.", idle PID ".$hash->{IPID}." found";
    if ((ReadingsVal($name,"presence","") eq "present") &&
        ($hash->{STATE} eq "play") &&
        (ReadingsVal($name,"currentTrackProvider","") ne "Radio")
       )
    {
     # Wichtig um das Readings elapsed aktuell zu halten (TabletUI)
     mpd_cmd($hash, "status");
     readingsSingleUpdate($hash,"playlistname",$hash->{".playlist"},1) if ($hash->{READINGS}{"playlistname"}{VAL} ne $hash->{".playlist"});
    }
  #}

kannst du das bitte mal so testen ?

[Wernieman]

Sorry, Essen hatten einen höheren Stellenwert ...

Jep. habe nicht mehr die Meldung im Log mit Deiner Version. Funktionieren tut es scheinbar auch immer noch ...

[Wzut]

Danke fürs testen, habe das jetzt so im svn geändert.

[Wernieman]

Danke .. werde es dann mal morgen wieder testen ...

[Wernieman]

Also .. auch nach dem Update funktioniert alles.

Danke für den schnellen Fix

[Wzut]

keine Ursache, allerdings merkt man dem Modul extrem an das es mein erstes FHEM Modul war .....
Da versteckt sich so einiges was ich heute so auf keinen Fall mehr schreiben würde, ganz zu schweigen davon was perlcritic da noch so alles findet
Mal schauen, es wird vermutlich langsam Zeit zum zerlegen, sandstrahlen, grundieren und neu lackieren
(Obwohl ich den Oldtimer heute selbst gar nicht mehr fahre, steckt doch einiges an Herzblut in ihm und vor allem viel,viel Zeit) 

[Wernieman]

Naja .. warst damals schneller als ich ... hatten beide mit dem schreiben angefangen. Hatte nur dann nicht mehr weitergemacht. Bin doch eher Admin als Entwickler.

Fährst Du gar kein mpd mehr?

[Wzut]

Nein der MPD war lange Zeit in meinem Bastelkeller das Internet Radio (mit IR Fernbedienung), da der normale UKW Empfang dort echt bescheiden ist.
Irgendwann habe ich mal ein DAB+ Radio bekommen und das läuft seit dem mit meinem Lieblingssender recht gut.

[Wernieman]

Habe hier beides ... aber da wir "neben" dem FHEM Rechner frühstücken, wäre es blöde, dort noch ein Radio laufen zu haben ...