Sonos: Neue Version vom 5.7.2017 (und vom 9.7.2017)

Begonnen von Reinerlein, 05 Juli 2017, 09:53:48

Vorheriges Thema - Nächstes Thema

Reinerlein

Hallo zusammen,

in diesem Update geht es Hauptsächlich um die "missed Beginupdate"-Problematik. Trotzdem sind auch andere Bereiche von mir überarbeitet und bereinigt worden.

Alle Punkte im Einzelnen:

  • Veralteten Mechanismus für das Unterbrechen der Sendeschleife aufgeräumt.
  • SONOS_ConvertNumToWord kann nun mit undef-Übergaben umgehen.
  • Andere Methodik zum Ermitteln von FavouriteName, RadioName und PlaylistName eingebaut.
  • Es gibt ein neues Attribut "SubProcessLogfileName". Damit kann die Logausgabe des SubProzesses in eine eigene Datei umgeleitet werden. Unter Windows z.B. gibt es sonst keine saubere Darstellungsmöglichkeit für die Logausgabe, da die beiden Prozesse sich gegenseitig die Ausgaben im Fhem-Log überschreiben. Bei Angabe von '-' wird wie bisher auf STDOUT (und damit im Fhem-Log) geloggt.
  • Kleinere Fehler bei einzelnen Reading-Aktualisierungen behoben.
  • Beim Zerlegen der MusicServicesList gab es einen Fehler, der z.B. dafür gesorgt hatte, dass Apple Music nicht erkannt wurde.
  • Umbau der Verarbeitungslogik in Richtung SubProzess. Das sollte nun schneller und sicher sequentiell verarbeitet werden.
  • Die Aktualisierung des Readings "LastProcessAnswer" wird jetzt während eines laufenden Bulkupdates auch als solches durchgeführt, und zerstört damit nicht mehr dieses laufende Update.
  • Alle noch vorhandenen ReadingsSingleUpdate-Aufrufe wurden BulkUpdate-Sicher gemacht.
  • Die prozentuale Fortschrittsanzeige hat bei Streams negative, hohe Werte angezeigt. Steht jetzt wieder auf 0.
  • Beim Löschen blieb noch die automatisch angelegte ReadingsGroup für die aktuelle Abspielliste bestehen.

Wie immer ab Morgen per Update oder ab sofort per SVN...

Grüße
Reinerlein

P.S.: Anmerkungen/Fehler zu dieser Version bitte hier in den Thread, auch wenn es thematisch in der vorherigen Version losgegangen ist...

Nobby1805

Hallo Reiner,

wobei das "missed BeginUpdate" ja eigentlich ein "doubled BeginUpdate" war  ::) ;)

Noch eine Frage zu dem Logfile. Ist das dann ein fester Logfile über die ganze Laufzeit des Prozesses oder werden die gleichen "Attribute" wie bei den anderen Logs unterstützt? Der Log wird im normalen Logverzeichnis angelegt?

Gruß Nobby
FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)

Reinerlein

Hi Nobby,

das mit dem Logfile ist eher zur kurzfristigen Fehlersuche gedacht. Es schreibt nur in diese Datei, und wechselt nichts.
Es kann aber zur Laufzeit einfach verändert werden, sodass man notfalls etwas in Fhem schreiben kann, was das Logfile wechselt (vielleicht ein Notify auf dem zentralen Logdevice, und wenn dort der Logfilename geändert wird, diesen auch, mit einem Pre- oder Suffix, am Sonos-Device setzen).
Ansonsten nur setzen, wenn man es wirklich braucht, weil man was sucht...

/Klugscheißmodus an/
Ganz genau gesagt, war es ein eingeschobenes Singleupdate anstatt eines Bulkupdates, und damit ein zu frühes, bzw. dann doppeltes, EndUpdate, oder?
Ein weiteres BeginUpdate stört ja eigentlich nicht...
/Klugscheißmodus aus/ :)

Grüße
Reiner

Nobby1805

Hi Reiner,

sollte dieser Hinweis nicht auch in der Doku stehen? Oder als Link auf deine Erläuterung hier im Forum?

Der Klugscheißer hat natürlich recht ;D
FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)

Reinerlein

Hi Nobby,

ich kann die Doku ja noch dahingehend anpassen. Das ist ja nicht in Stein gemeißelt, geht dann aber erst mit dem nächsten Update raus, im Wiki natürlich gleich...

Grüße
Reiner

mrfloppy

Danke für die neue Version

Habe sie mal aus dem SVN installiert.

Die readingsBeginUpdate Meldungen sind vorerst mal weg.

Momentan kommen aber immer diese Meldungen.
2017.07.05 16:41:06 1: SONOS0: Error during retreiving of FavouriteName: Can't use an undefined value as a HASH reference at ./FHEM/00_SONOS.pm line 1334.

2017.07.05 16:41:06 1: SONOS0: Error during retreiving of PlaylistName: Can't use an undefined value as a HASH reference at ./FHEM/00_SONOS.pm line 1352.

2017.07.05 16:41:06 1: SONOS0: Error during retreiving of RadioName: Can't use an undefined value as a HASH reference at ./FHEM/00_SONOS.pm line 1370.


Und weiterhin kommen diese upnp Meldungen.
Loading device description failed with error: 500 Can't connect to 192.168.49.1:44708 (Location: http://192.168.49.1:44708/upnp/dev/44da200e-6e9b-0a71-ffff-ffffa044fb2c/desc) at ./FHEM/00_SONOS.pm line 2458 thread 1.

Obwohl diese IP gibt es in meinem Netz nicht,
Ebenso ist die IP unter den ignored eingetragen.
Habe sie schon öfters mit oder ohne Port versch. eingetragen keine Besserung.

Danke und LG
RaspiMatic, RFXtrx433 E USB, Div. Thermostate, CUL433, Fhemduino, Signalduino, Temp/luftfeuchesensoren,Fensterkontakte,Intertechno Schalter,....... HM-IP

Reinerlein

Hi mrfloppy,

was steht denn bei dem Player im Reading Favourite. Ich hole mir das Reading mit ReadingsVal und einem Defaultwert. Das bedeutet doch eigentlich, dass es bei Nicht-Existenz des Readings den Defaultwert liefert (hier ein Leer-String).
Anschließend prüfe ich noch, ob dieser String nun leer ist, dann setze ich ein leeres Array (als String). Damit fange ich auch ab, wenn es das Reading zwar geben sollte, aber keinen Inhalt hat.

Wie kann das noch auf einen Undefined laufen? Das ist mir überhaupt nicht klar... Jemand eine Idee?

Zu dem UPNP-Error:
kannst du mal den Inhalt deines Attributs ignoredIPs posten?
Dort muss nur die IP-Adresse rein, und der SubProzess neugestartet werden.

Die IP und der Port deuten auf einen FireTV hin (zumindest ergab das eine kurze Google-Suche). Hast du sowas im Einsatz?

Grüße
Reiner

mrfloppy

reading von Sonos_player:
Internals:
   DEF        RINCON_B8E937D046C001400_MR
   NAME       Sonos_Wohnzimmer_2
   NOTIFYDEV  Sonos_Wohnzimmer_2
   NR         743
   NTFY_ORDER 50-Sonos_Wohnzimmer_2
   STATE      appeared ~ 0:00:00 / 0:00:00
   TYPE       SONOSPLAYER
   UDN        RINCON_B8E937D046C001400_MR
   Readings:
     2017-07-05 16:27:38   AlarmList       {}
     2017-07-05 16:27:38   AlarmListIDs
     2017-07-05 16:27:38   AlarmListVersion RINCON_5CAAFD4B541E01400:0
     2017-05-22 15:48:34   AlarmRunning    0
     2017-05-22 15:48:34   AlarmRunningID
     2017-07-05 16:28:08   AvailablePlayer []
     2017-05-22 15:48:32   Balance         0
     2017-05-22 15:49:55   Bass            7
     2017-05-22 15:48:34   CrossfadeMode   0
     2017-05-22 15:48:36   DailyIndexRefreshTime 09:00:00
     2017-05-22 15:48:34   DirectControlAccountID
     2017-05-22 15:48:34   DirectControlClientID
     2017-05-22 15:48:34   DirectControlIsSuspended 0
     2017-05-22 15:49:55   FavouritesVersion RINCON_5CAAFD4B541E01400,19
     2017-05-29 07:51:06   GroupMute       0
     2017-07-05 16:41:06   GroupVolume     13
     2017-05-22 15:48:34   HeadphoneConnected 0
     2017-05-22 15:48:32   IsBonded        0
     2017-06-26 15:14:22   IsMaster        1
     2017-07-05 16:40:55   LastActionResult Pause: Success!
     2017-05-22 15:49:55   Loudness        1
     2017-06-26 19:53:08   MasterPlayer    Sonos_Wohnzimmer_2
     2017-05-29 07:47:33   Mute            0
     2017-05-22 15:49:55   OutputFixed     0
     2017-05-22 15:49:55   PlaylistsVersion RINCON_B8E937D046C001400,12
     2017-06-26 20:07:18   QueueHash       9a1c7ee2c7ce38d4bbbaf29ab9f2ac1e
     2017-06-26 20:07:15   QueueVersion    1
     2017-05-22 15:49:55   RadiosVersion   RINCON_5CAAFD4B541E01400,19
     2017-05-22 15:48:34   Repeat          0
     2017-05-22 15:48:34   RepeatOne       0
     2017-05-25 08:20:14   Shuffle         0
     2017-07-05 16:28:08   SlavePlayer     ['Sonos_Wohnzimmer']
     2017-07-05 16:28:08   SlavePlayerNotBonded ['Sonos_Wohnzimmer']
     2017-05-22 15:48:34   SleepTimer      off
     2017-05-22 15:48:34   SleepTimerVersion
     2017-05-22 15:49:55   SubEnable       1
     2017-05-22 15:49:55   SubGain         0
     2017-05-22 15:49:55   SubPolarity     0
     2017-05-22 15:49:55   Treble          9
     2017-05-22 15:49:55   TruePlay        0
     2017-07-05 16:41:02   Volume          14
     2017-06-26 15:14:22   ZoneGroupID     RINCON_B8E937D046C001400:__
     2017-06-26 15:14:22   ZoneGroupName   Wohnzimmer 2 + 1
     2017-07-05 16:28:08   ZoneGroupNameDetails  + Wohnzimmer
     2017-06-26 15:14:22   ZonePlayerUUIDsInGroup RINCON_B8E937D046C001400,RINCON_5CAAFD4B541E01400
     2017-06-27 07:22:15   currentAlbum
     2017-06-22 08:19:32   currentAlbumArtURI ./www/images/default/SONOSPLAYER/Sonos_Wohnzimmer_2_AlbumArt.png
     2017-06-26 20:43:56   currentAlbumArtURL http://cdn-radiotime-logos.tunein.com/s8007g.png
     2017-06-08 12:25:38   currentAlbumArtist
     2017-06-08 12:19:29   currentArtist
     2017-06-26 19:55:50   currentEnqueuedTransportHandle x-sonosapi-stream:s8007?sid=254&flags=8224&sn=0|<DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item id="-1" parentID="-1" restricted="true"><dc:title>Hitradio Ö3</dc:title><upnp:class>object.item.audioItem.audioBroadcast</upnp:class><desc id="cdudn" nameSpace="urn:schemas-rinconnetworks-com:metadata-1-0/">SA_RINCON65031_</desc></item></DIDL-Lite>
     2017-06-26 20:43:56   currentEnqueuedTransportURI x-sonosapi-stream:s8007?sid=254&flags=8224&sn=0
     2017-05-22 15:48:34   currentFavouriteName
     2017-07-05 16:41:02   currentNormalAudio
     2017-05-25 08:20:14   currentOriginalTrackNumber
     2017-05-22 15:48:34   currentPlaylistName
     2017-05-22 15:48:34   currentRadioName
     2017-06-26 20:03:25   currentSender   Hitradio Ö3
     2017-05-22 15:48:34   currentSenderCurrent
     2017-07-05 16:41:05   currentSenderInfo
     2017-06-26 20:03:28   currentSource   Hitradio Ö3
     2017-06-26 20:04:14   currentStreamAudio 1
     2017-06-27 07:22:15   currentTitle
     2017-07-01 14:54:21   currentTrack    1
     2017-06-26 20:04:18   currentTrackDuration 0:00:00
     2017-06-26 20:03:28   currentTrackDurationSec 0
     2017-07-05 16:41:05   currentTrackHandle http://http://mp3stream7.apasf.apa.at:8000|<DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item id="-1" parentID="-1" restricted="true"><res protocolInfo="sonos.com-http:*:*:*">x-sonosapi-stream:s8007?sid=254&amp;flags=8224&amp;sn=0</res><r:streamContent></r:streamContent><r:radioShowMd></r:radioShowMd><upnp:albumArtURI>/getaa?s=1&amp;u=x-sonosapi-stream%3as8007%3fsid%3d254%26flags%3d8224%26sn%3d0</upnp:albumArtURI><dc:title>x-sonosapi-stream:s8007?sid=254&amp;flags=8224&amp;sn=0</dc:title><upnp:class>object.item</upnp:class></item></DIDL-Lite>
     2017-07-05 16:34:17   currentTrackPosition 0:00:00
     2017-07-05 16:34:17   currentTrackPositionSec 0
     2017-07-05 16:41:05   currentTrackPositionSimulated 0:00:00
     2017-07-05 16:41:02   currentTrackPositionSimulatedPercent -0.0
     2017-07-05 16:41:05   currentTrackPositionSimulatedSec 0
     2017-07-05 16:20:14   currentTrackProvider Radio
     2017-06-26 20:03:20   currentTrackProviderIconQuadraticURL /fhem/sonos/cover/tunein_quadratic.jpg
     2017-06-26 20:03:25   currentTrackProviderIconRoundURL /fhem/sonos/cover/tunein_round.png
     2017-07-05 19:56:33   currentTrackURI http://http://mp3stream7.apasf.apa.at:8000
     2017-05-22 15:48:32   fieldType
     2017-07-05 16:41:05   infoSummarize1  Hitradio Ö3:
     2017-07-05 16:41:05   infoSummarize2  STOPPED => Hitradio Ö3:
     2017-07-05 16:41:05   infoSummarize3  Lautstärke: 14 ~ Ton An ~ Balance: Mitte ~ Kein Kopfhörer
     2017-05-22 15:48:34   infoSummarize4
     2017-05-22 15:48:32   location        http://10.0.0.111:1400/xml/device_description.xml
     2017-06-08 12:19:29   nextAlbum
     2017-06-19 03:17:10   nextAlbumArtURI ./www/images/default/SONOSPLAYER/Sonos_Wohnzimmer_2_NextAlbumArt.png
     2017-06-26 20:03:20   nextAlbumArtURL /fhem/sonos/cover/empty.jpg
     2017-05-25 08:20:14   nextAlbumArtist
     2017-06-08 12:19:29   nextArtist
     2017-05-25 08:20:14   nextOriginalTrackNumber
     2017-06-08 12:19:29   nextTitle
     2017-06-08 12:19:29   nextTrackDuration
     2017-05-25 08:20:14   nextTrackDurationSec
     2017-06-26 20:03:20   nextTrackHandle |
     2017-05-25 08:20:14   nextTrackProvider
     2017-05-25 08:20:14   nextTrackProviderIconQuadraticURL
     2017-05-25 08:20:14   nextTrackProviderIconRoundURL
     2017-06-08 12:19:29   nextTrackURI
     2017-06-26 20:43:55   numberOfTracks  4
     2017-05-22 15:48:32   playerType      S3
     2017-07-05 16:27:33   presence        appeared
     2017-05-22 15:49:55   roomIcon        living
     2017-05-22 15:48:32   roomName        Wohnzimmer 2
     2017-06-26 18:36:58   roomNameAlias   Wohnzimmer 2
     2017-05-22 15:48:32   saveRoomName    Wohnzimmer_2
     2017-05-22 15:48:32   serialNum       B8-E9-37-D0-46-C0:F
     2017-06-24 09:14:45   softwareRevision 7.3
     2017-07-05 16:41:05   state           STOPPED
     2017-07-05 16:41:02   transportState  STOPPED
   Helper:
     simulateCurrentTrackPosition 0
Attributes:
   alias      Wohnzimmer 2
   generateInfoSummarize1 <NormalAudio><Artist prefix="(" suffix=")"/><Title prefix=" '" suffix="'" ifempty="[Keine Musikdatei]"/><Album prefix=" vom Album '" suffix="'"/></NormalAudio> <StreamAudio><Sender suffix=":"/><SenderCurrent prefix=" '" suffix="' -"/><SenderInfo prefix=" "/></StreamAudio>
   generateInfoSummarize2 <TransportState/><InfoSummarize1 prefix=" => "/>
   generateInfoSummarize3 <Volume prefix="Lautstärke: "/><Mute instead=" ~ Kein Ton" ifempty=" ~ Ton An" emptyval="0"/> ~ Balance: <Balance ifempty="Mitte" emptyval="0"/><HeadphoneConnected instead=" ~ Kopfhörer aktiv" ifempty=" ~ Kein Kopfhörer" emptyval="0"/>
   generateVolumeSlider 1
   getAlarms  1
   getTitleInfoFromMaster 1
   group      Wohnzimmer_2
   icon       icoSONOSPLAYER_icon-S3.png
   minVolume  0
   model      Sonos_S3
   room       Sonos
   simulateCurrentTrackPosition 1
   sortby     1
   stateFormat presence ~ currentTrackPositionSimulated / currentTrackDuration
   userReadings Favourites:LastActionResult.*?GetFavouritesWithCovers.* { if (ReadingsVal($name, "LastActionResult", "") =~ m/.*?: (.*)/) { return $1; } }, Radios:LastActionResult.*?GetRadiosWithCovers.* { if (ReadingsVal($name, "LastActionResult", "") =~ m/.*?: (.*)/) { return $1; } }, Playlists:LastActionResult.*?GetPlaylistsWithCovers.* { if (ReadingsVal($name, "LastActionResult", "") =~ m/.*?: (.*)/) { return $1; } }, Queue:LastActionResult.*?GetQueueWithCovers.* { if (ReadingsVal($name, "LastActionResult", "") =~ m/.*?: (.*)/) { return $1; } }, currentTrackPosition:LastActionResult.*?GetCurrentTrackPosition.* { if (ReadingsVal($name, "LastActionResult", "") =~ m/.*?: (.*)/) { return $1; } }
   webCmd     Volume


IgnoredIp
Attributes:
   disable    0
   ignoredIPs 192.168.49.1
   room       Sonos


Wie starte ich den SubProzess am besten neu?

FireTv habe ich. Werde ich die Tage mal deaktivieren und schauen was weiter passiert.

LG
RaspiMatic, RFXtrx433 E USB, Div. Thermostate, CUL433, Fhemduino, Signalduino, Temp/luftfeuchesensoren,Fensterkontakte,Intertechno Schalter,....... HM-IP

Reinerlein

Hi mrfloppy,

ich habe gerade nochmal eine Version eingecheckt, in der ich die Ermittlung der Favoritennamen anders prüfe.
Kannst du die mal probieren?

Danke schon mal...

Grüße
Reiner

mrfloppy

Die 3 Meldungen der Favourites usw sind weg.

Danke LG
RaspiMatic, RFXtrx433 E USB, Div. Thermostate, CUL433, Fhemduino, Signalduino, Temp/luftfeuchesensoren,Fensterkontakte,Intertechno Schalter,....... HM-IP

mrfloppy

Zu Früh gefreut!
2017.07.05 23:32:49 1: readingsUpdate(Sonos_Wohnzimmer,IsMaster,0) missed to call readingsBeginUpdate first.
2017.07.05 23:32:49 1: stacktrace:
2017.07.05 23:32:49 1:     main::readingsBulkUpdate            called by ./FHEM/00_SONOS.pm (9593)
2017.07.05 23:32:49 1:     main::SONOS_readingsBulkUpdateIfChanged called by ./FHEM/00_SONOS.pm (1226)
2017.07.05 23:32:49 1:     main::SONOS_Read                    called by fhem.pl (3412)
2017.07.05 23:32:49 1:     main::CallFn                        called by fhem.pl (686)


LG
RaspiMatic, RFXtrx433 E USB, Div. Thermostate, CUL433, Fhemduino, Signalduino, Temp/luftfeuchesensoren,Fensterkontakte,Intertechno Schalter,....... HM-IP

Nobby1805

Hallo Reiner,

ich habe nicht nachgeschaut, wie du das BeginUpdate-Problem jetzt generell gelöst hast ... aber heute Morgen, noch mit der alten Version, war es nicht die Kombination von SingleUpdate und BeginUpdate sondern wirklich 2x BeginUpdate, die das Problem ausgelöst haben

00_Sonos ... im Loop aufgrund der Nachricht BeginUpdate vom Sub-Prozess
21_SONOSPLAYER ... in TrackPositionSimulate ... dies ergab dann den "doppelte Aufruf"
Ich werde jetzt den Upadte fahren, lasse die Änderungen im fhem.pl (erst nochmal) drin

Gruß Nobby
FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)

Reinerlein

Hi Nobby,

da ein doppeltes Beginupdate keinerlei negative Auswirkung hat, habe ich das billigend in Kauf genommen, bzw. schlicht ignoriert.

Meine Anpassung führt lediglich bei einem versuchten SingleUpdate stattdessen ein Bulkupdate aus, wenn bereits ein UpdateTimeStamp am Device gesetzt ist (=BulkUpdate in Bearbeitung).
Damit reiht sich der Singleupdate dann sozusagen in den bestehenden Bulkupdate mit ein, und wird damit natürlich erst beim irgendwann kommenden EndUpdate am Device (mit-)gesetzt werden.

Was meinst du denn mit "...die das Problem ausgelöst haben"?
BeginUpdate ist Wiederholungssicher, da es ausschließlich Werte setzt, die dann beim Endupdate Verwendung finden sollen. Lediglich die beiden Timestamps werden überschreibend neu gesetzt... Der Rest sollte identisch belegt werden, bzw. im Falle der CHANGED-Auflistung übersprungen werden...

Grüße
Reiner

Nobby1805

Hallo Reiner,

ja, du hast natürlich recht  :-[ da habe ich mich sehr schludrig ausgedrückt  :-[ ...

mein Gedanke war natürlich, dass zu einem BeginUpdate immer ein EndUpdate gehört und der erste Endupdate dann den UpdateTimestamp zurücksetzt

Gruß Nobby
FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)

Reinerlein

Hi Nobby,

kein Problem... ich bin nur kritisch auf der Suche, und schließe dementsprechend meine eigene Unwissenheit natürlich nicht aus :)
Das war aber ja auch vor dem Update... schauen wir mal, was mit der neuen Version passiert.
Eine Meldung kam dazu ja bereits. Leider sieht man ja im Standardlog nur den fehlerhaften Bulkupdate und nicht den eigentlich problematischen EndUpdate davor... Da habe ich Hoffnung auf dein Log :)

Grüße
Reiner