search

svrooij / node-sonos-ts

:speaker: Sonos control library, use this library in your own appliction.
https://sonos-ts.svrooij.io/
MIT License
84 stars 18 forks source link

fix: TTS not playing #39

Closed besynnerlig closed 4 years ago

besynnerlig commented 4 years ago

fix: TTS not playing

Fixed #38

besynnerlig commented 4 years ago

I hope this will do. I've allow edits from maintainers in case there is something that needs to be improved.

I've noticed Sonos error on Seek , Reverting back track time failed, happens for some muic services (radio or stream).

I don't think my changes caused that. Maybe there's no delay needed just after the Sonos error on Seek occurs... I just didn't mkow how ti make that delay conditional.

I'm sorry for sending 2 commits. Maybe you'd like to squash them before committing.

It's been tested on my system. The 500 ms delay seems to be minimum to avoid all timing issues that my Sonos system has. As I said before, we might want to make this configurable so that people with faster Sonos speakers can minimize the delay.

Cheers!

EDIT: I've been testing further this evening using the code in this PR. I'm testing node-sonos-ts using a local installation of sonos2mqtt. First time seems to fail resume the stream/playlist while consequent attempts succeeds. Can't say why though...

besynnerlig commented 4 years ago

I've done some more testing this morning and made some small adjustments.

It's working fine now in my VSC debug environment.

I'd like to remove the Selecting track and Setting back time functions for stream types where we are sure that they will fail (for some muic services (radio or streams). Do we know which services and would it be easy to exclude them?

EDIT 2020-02-24 11:18 I have been testing this now in my home automation environment and notifications works fine now. It's rare but there has been few occassions though when volume and play state has not been restored after a notification. It hits me though that while this PR seems to remove the symptoms, what if there are any underlying problems that we might not be fully aware of? Are there other more appropriate ways that it can be solved? Just a thought. Maybe I shouldn't think so much 😄

svrooij commented 4 years ago

I will have a look at it next week, we are celebrating carnaval at the moment

I'd like to remove the Selecting track and Setting back time functions for stream types where we are sure that they will fail (for some muic services (radio or streams). Do we know which services and would it be easy to exclude them?

Not sure, you could check the item type in the metadata maybe. It just sends a “wrong request” error. I don’t see that as a problem. It would be worse if the check is implemented wrong and it looses functionality for some edge cases.

besynnerlig commented 4 years ago

An observation that I made today:

At occations when playing a TTS notification fails (volume is not restored afterwards and resume playing (whatever was played) won't happen), if I go to my Sonos speaker and press the physical play button, the notification is played again (expected) but also, the volume gets restored and it resumes playing my radio stream.

It feels like node-sonos-ts sometimes fails to detect that the event that TTS has played the first time. If i manually repeat the TTS by pushing the button on the speaker (if made before the timeout) node-sonos-ts detects the event and carries on to do what it should do. The question then is why node-sonos-ts failed to detect the event the first time.

svrooij commented 4 years ago

It takes some time to setup the event listener, so it might be not fast enough to setup the listener before the event already fired. That is why you can supply a timeout value. If the event isn't received before the timeout (in seconds). You will see something like this in the logging:

AsyncEvent timeout fired Error: Event didn't happen before timeout

This (probably) wont happen if the app is already subscribed to events from the sonos device.

svrooij commented 4 years ago

Could you checkout if you stiff got the issue with my branch?

https://github.com/svrooij/node-sonos-ts/tree/bug/notifications

besynnerlig commented 4 years ago

Could you checkout if you stiff got the issue with my branch?

https://github.com/svrooij/node-sonos-ts/tree/bug/notifications

Sure! I'll check this tomorrow morning. Thanks!

besynnerlig commented 4 years ago

Good morning @svrooij

I have downloaded the bug/notifications branch and started testing. I have also symlinked sonos2mqtt to that module, e.g. ln -s /opt/node-sonos-ts /usr/local/lib/node_modules/sonos2mqtt/node_modules/@svrooij/sonos.

Using sonos2mqtt, I can see that the new delay arhument is coming through all the way to node-sonos-ts: "{ \"text\": \"Hej\", \"endpoint\": \"http://MYHOST:5601/api/generate\", \"lang\": \"sv-SE\", \"gender\": \"female\", \"volume\": 40, \"onlyWhenPlaying\": false, \"delayMs\": 1000 }"

Using sonos2mqtt it works only sometimes. After the debug message Published to sonos/status/MY-ROOM/track, the sound is played but then it stops. After some time i get

  sonos:eventlistener Got event on /sonos/e03ba1e0-a1a6-714d-3669-4595ce1c2c55/ZoneGroupTopology SID: uuid:RINCON_XXXXXXXXXXXXXXX_sub0000002690 +25s
  sonos:eventlistener Subscription uuid:RINCON_XXXXXXXXXXXXXXXXXXX_sub0000002690 not found, sending 412 to stop messages +1ms
  sonos:device:192.168.4.82 EventTimeoutError: Event avtransport.CurrentTransportState.STOPPED didn't fire before timeout
  sonos:device:192.168.4.82     at Timeout.setTimeout [as _onTimeout] (/opt/node-sonos-ts/lib/helpers/async-helper.js:41:28)
  sonos:device:192.168.4.82     at ontimeout (timers.js:436:11)
  sonos:device:192.168.4.82     at tryOnTimeout (timers.js:300:5)
  sonos:device:192.168.4.82     at listOnTimeout (timers.js:263:5)
  sonos:device:192.168.4.82     at Timer.processTimers (timers.js:223:10) +2m
  sonos:device:192.168.4.82 Reverting everything back to normal +1ms

The good thing is that playing the stream resumes after the above error message. I don't recall that it did previously.

When debugging node-sonos-ts in VSC, I can't recall that it ever failed. It seems to work every time. Isn't that strange? It's the same node-sonos-ts code running but it fails sometimes when invoked by sonos2mqtt.

Below is the full debug output when running sonos2mqtt at a time that it fails: (I have added the debug line in the code starting with "Specified delay")

2020-02-28 08:53:47.019 <debug> Incoming message to sonos/set/ROOMNAME/speak "{ \"text\": \"Hej\", \"endpoint\": \"http://HOSTNAME:5601/api/generate\", \"lang\": \"sv-SE\", \"gender\": \"female\", \"volume\": 40, \"onlyWhenPlaying\": false, \"delayMs\": 1000 }"
2020-02-28 08:53:47.020 <debug> Incoming device command speak for ROOMNAME payload { "text": "Hej", "endpoint": "http://HOSTNAME:5601/api/generate", "lang": "sv-SE", "gender": "female", "volume": 40, "onlyWhenPlaying": false, "delayMs": 1000 }
  sonos:device:192.168.4.82 PlayTTS({ text: 'Hej', endpoint: 'http://HOSTNAME:5601/api/generate', lang: 'sv-SE', gender: 'female', volume: 40, onlyWhenPlaying: false, delayMs: 1000 }) +48s
  sonos:tts Getting tts uri from server http://HOSTNAME:5601/api/generate +50s
  sonos:device:192.168.4.82 PlayNotification({ text: 'Hej', endpoint: 'http://HOSTNAME:5601/api/generate', lang: 'sv-SE', gender: 'female', volume: 40, onlyWhenPlaying: false, delayMs: 1000, trackUri: 'http://HOSTNAME:5601/cache/sv-SE/5ff235aa73c2983d51c726cf65e4db4d8ab238cd.mp3', timeout: 120 }) +2ms
  sonos:device:192.168.4.82 Specified delay XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX: 1000 +0ms
  sonos:service:avtransport:192.168.4.82 GetTransportInfo({ InstanceID: 0 }) +44s
  sonos:device:192.168.4.82 Current state is PLAYING +5ms
  sonos:metadata Guessing metadata for http://HOSTNAME:5601/cache/sv-SE/5ff235aa73c2983d51c726cf65e4db4d8ab238cd.mp3 +44s
  sonos:metadata Don't support this TrackUri (yet) http://HOSTNAME:5601/cache/sv-SE/5ff235aa73c2983d51c726cf65e4db4d8ab238cd.mp3 +0ms
  sonos:service:renderingcontrol:192.168.4.82 GetVolume({ InstanceID: 0, Channel: 'Master' }) +46s
  sonos:service:avtransport:192.168.4.82 GetMediaInfo({ InstanceID: 0 }) +13ms
  sonos:metadata Parsing DIDL { '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': 'BBC Radio 6 Music', 'upnp:class': 'object.item.audioItem.audioBroadcast', desc: [Object] } } } +20ms
  sonos:service:avtransport:192.168.4.82 GetPositionInfo({ InstanceID: 0 }) +13ms
  sonos:metadata Parsing DIDL { '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: [Object], 'r:streamContent': '', 'dc:title': 'bbc_6music.m3u8', 'upnp:class': 'object.item' } } } +11ms
  sonos:service:avtransport:192.168.4.82 SetAVTransportURI({ InstanceID: 0, CurrentURI: 'http://HOSTNAME:5601/cache/sv-SE/5ff235aa73c2983d51c726cf65e4db4d8ab238cd.mp3', CurrentURIMetaData: '' }) +11ms
  sonos:service:renderingcontrol:192.168.4.82 SetVolume({ InstanceID: 0, Channel: 'Master', DesiredVolume: 40 }) +277ms
  sonos:eventlistener Got event on /sonos/RINCON_7828CA0142F601400/RenderingControl SID: uuid:RINCON_7828CA0142F601400_sub0000015228 +44s
  sonos:service:renderingcontrol:192.168.4.83 Got event +48s
2020-02-28 08:53:47.325 <debug> Published to sonos/status/ROOMNAME/volume
  sonos:eventlistener Got event on /sonos/RINCON_XXXXXXXXXXXXXXXX/AVTransport SID: uuid:RINCON_XXXXXXXXXXXXXXXX_sub0000003932 +13ms
  sonos:service:avtransport:192.168.4.82 Got event +277ms
  sonos:metadata Parsing DIDL { '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: [Object], 'r:streamContent': '', 'r:radioShowMd': '', 'dc:title': '5ff235aa73c2983d51c726cf65e4db4d8ab238cd.mp3', 'upnp:class': 'object.item.audioItem.musicTrack' } } } +281ms
2020-02-28 08:53:47.340 <debug> Published to sonos/status/ROOMNAME/state
2020-02-28 08:53:47.341 <debug> Published to sonos/status/ROOMNAME/trackUri
2020-02-28 08:53:47.341 <debug> New track data for ROOMNAME {"Title":"5ff235aa73c2983d51c726cf65e4db4d8ab238cd.mp3","UpnpClass":"object.item.audioItem.musicTrack","Duration":"0:00:00","ItemId":"-1","ParentId":"-1","TrackUri":"http://HOSTNAME:5601/cache/sv-SE/5ff235aa73c2983d51c726cf65e4db4d8ab238cd.mp3","ProtocolInfo":"http-get:*:audio/mpeg:*"}
2020-02-28 08:53:47.342 <debug> Published to sonos/status/ROOMNAME/track
  sonos:service:avtransport:192.168.4.82 Play({ InstanceID: 0, Speed: '1' }) +986ms
  sonos:device:192.168.4.82 Listener added +1s
  sonos:eventlistener Got event on /sonos/RINCON_XXXXXXXXXXXXXXXX/RenderingControl SID: uuid:RINCON_XXXXXXXXXXXXXXXX_sub0000003933 +2s
  sonos:service:renderingcontrol:192.168.4.82 Got event +2s
2020-02-28 08:53:49.567 <debug> Published to sonos/status/ROOMNAME/volume
  sonos:eventlistener Got event on /sonos/RINCON_XXXXXXXXXXXXXXXX/AVTransport SID: uuid:RINCON_XXXXXXXXXXXXXXXX_sub0000003932 +97ms
  sonos:service:avtransport:192.168.4.82 Got event +1s
  sonos:metadata Parsing DIDL { '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: [Object], 'r:streamContent': '', 'r:radioShowMd': '', 'dc:title': '5ff235aa73c2983d51c726cf65e4db4d8ab238cd.mp3', 'upnp:class': 'object.item.audioItem.musicTrack' } } } +2s
2020-02-28 08:53:49.665 <debug> New track data for ROOMNAME {"Title":"5ff235aa73c2983d51c726cf65e4db4d8ab238cd.mp3","UpnpClass":"object.item.audioItem.musicTrack","Duration":"0:00:00","ItemId":"-1","ParentId":"-1","TrackUri":"http://HOSTNAME:5601/cache/sv-SE/5ff235aa73c2983d51c726cf65e4db4d8ab238cd.mp3","ProtocolInfo":"http-get:*:audio/mpeg:*"}
2020-02-28 08:53:49.665 <debug> Published to sonos/status/ROOMNAME/track

  sonos:eventlistener Got event on /sonos/e03ba1e0-a1a6-714d-3669-4595ce1c2c55/ZoneGroupTopology SID: uuid:RINCON_7828CA20387A01400_sub0000002690 +25s
  sonos:eventlistener Subscription uuid:RINCON_7828CA20387A01400_sub0000002690 not found, sending 412 to stop messages +1ms
  sonos:device:192.168.4.82 EventTimeoutError: Event avtransport.CurrentTransportState.STOPPED didn't fire before timeout
  sonos:device:192.168.4.82     at Timeout.setTimeout [as _onTimeout] (/opt/node-sonos-ts/lib/helpers/async-helper.js:41:28)
  sonos:device:192.168.4.82     at ontimeout (timers.js:436:11)
  sonos:device:192.168.4.82     at tryOnTimeout (timers.js:300:5)
  sonos:device:192.168.4.82     at listOnTimeout (timers.js:263:5)
  sonos:device:192.168.4.82     at Timer.processTimers (timers.js:223:10) +2m
  sonos:device:192.168.4.82 Reverting everything back to normal +1ms
  sonos:service:renderingcontrol:192.168.4.82 SetVolume({ InstanceID: 0, Channel: 'Master', DesiredVolume: 15 }) +2m
  sonos:eventlistener Got event on /sonos/RINCON_7828CA0142F601400/RenderingControl SID: uuid:RINCON_7828CA0142F601400_sub0000015228 +2m
  sonos:service:renderingcontrol:192.168.4.83 Got event +2m
2020-02-28 08:55:48.354 <debug> Published to sonos/status/ROOMNAME/volume
  sonos:eventlistener Got event on /sonos/RINCON_XXXXXXXXXXXXXXXX/RenderingControl SID: uuid:RINCON_XXXXXXXXXXXXXXXX_sub0000003933 +2ms
  sonos:service:renderingcontrol:192.168.4.82 Got event +23ms
2020-02-28 08:55:48.356 <debug> Published to sonos/status/ROOMNAME/volume
  sonos:service:avtransport:192.168.4.82 SetAVTransportURI({ InstanceID: 0, CurrentURI: 'x-sonosapi-stream:s44491?sid=254&flags=8224&sn=0', CurrentURIMetaData: { Album: undefined, Artist: undefined, AlbumArtUri: undefined, Title: 'BBC Radio 6 Music', UpnpClass: 'object.item.audioItem.audioBroadcast', Duration: undefined, ItemId: '-1', ParentId: '-1', TrackUri: undefined, ProtocolInfo: undefined } }) +2m
  sonos:eventlistener Got event on /sonos/RINCON_XXXXXXXXXXXXXXXX/AVTransport SID: uuid:RINCON_XXXXXXXXXXXXXXXX_sub0000003932 +1s
  sonos:service:avtransport:192.168.4.82 Got event +282ms
  sonos:metadata Parsing DIDL { '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: [Object], 'r:streamContent': '', 'r:radioShowMd': 'Lauren Laverne,p180382', 'upnp:albumArtURI': '/getaa?s=1&amp;u=x-sonosapi-stream%3as44491%3fsid%3d254%26flags%3d8224%26sn%3d0', 'dc:title': 'BBC Radio 6 Music', 'upnp:class': 'object.item' } } } +2m
  sonos:metadata Parsing DIDL { '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': 'BBC Radio 6 Music', 'upnp:class': 'object.item.audioItem.audioBroadcast', desc: [Object] } } } +0ms
  sonos:metadata Parsing DIDL { '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': 'BBC Radio 6 Music', 'upnp:class': 'object.item.audioItem.audioBroadcast', desc: [Object] } } } +0ms
2020-02-28 08:55:49.632 <debug> Published to sonos/status/ROOMNAME/trackUri
2020-02-28 08:55:49.632 <debug> New track data for ROOMNAME {"AlbumArtUri":"http://192.168.4.82:1400/getaa?s=1&u=x-sonosapi-stream:s44491%3fsid%3d254%26flags%3d8224%26sn%3d0","Title":"BBC Radio 6 Music","UpnpClass":"object.item","ItemId":"-1","ParentId":"-1","TrackUri":"x-sonosapi-stream:s44491?sid=254&flags=8224&sn=0","ProtocolInfo":"sonos.com-http:*:application/octet-stream:*"}
2020-02-28 08:55:49.632 <debug> Published to sonos/status/ROOMNAME/track
  sonos:service:avtransport:192.168.4.82 Play({ InstanceID: 0, Speed: '1' }) +977ms
2020-02-28 08:55:52.238 <debug> Executed speak for ROOMNAME result: true
  sonos:eventlistener Got event on /sonos/RINCON_XXXXXXXXXXXXXXXX/AVTransport SID: uuid:RINCON_XXXXXXXXXXXXXXXX_sub0000003932 +3s
  sonos:service:avtransport:192.168.4.82 Got event +2s
  sonos:metadata Parsing DIDL { '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: [Object], 'r:streamContent': '', 'r:radioShowMd': 'Lauren Laverne,p180382', 'upnp:albumArtURI': '/getaa?s=1&amp;u=x-sonosapi-stream%3as44491%3fsid%3d254%26flags%3d8224%26sn%3d0', 'dc:title': 'x-sonosapi-stream:s44491?sid=254&amp;flags=8224&amp;sn=0', 'upnp:class': 'object.item' } } } +3s
  sonos:metadata Parsing DIDL { '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': 'BBC Radio 6 Music', 'upnp:class': 'object.item.audioItem.audioBroadcast', desc: [Object] } } } +0ms
2020-02-28 08:55:52.265 <debug> Published to sonos/status/ROOMNAME/state
2020-02-28 08:55:52.265 <debug> Published to sonos/status/ROOMNAME/trackUri
2020-02-28 08:55:52.265 <debug> New track data for ROOMNAME {"AlbumArtUri":"http://192.168.4.82:1400/getaa?s=1&u=x-sonosapi-stream:s44491%3fsid%3d254%26flags%3d8224%26sn%3d0","Title":"x-sonosapi-stream:s44491?sid=254&amp;flags=8224&amp;sn=0","UpnpClass":"object.item","ItemId":"-1","ParentId":"-1","TrackUri":"x-sonosapi-stream:s44491?sid=254&flags=8224&sn=0","ProtocolInfo":"sonos.com-http:*:audio/mpegurl:*"}
2020-02-28 08:55:52.265 <debug> Published to sonos/status/ROOMNAME/track
  sonos:eventlistener Got event on /sonos/RINCON_XXXXXXXXXXXXXXXX/AVTransport SID: uuid:RINCON_XXXXXXXXXXXXXXXX_sub0000003932 +3s
  sonos:service:avtransport:192.168.4.82 Got event +3s
  sonos:metadata Parsing DIDL { '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: [Object], 'r:streamContent': '', 'r:radioShowMd': 'Lauren Laverne,p180382', 'upnp:albumArtURI': '/getaa?s=1&amp;u=x-sonosapi-stream%3as44491%3fsid%3d254%26flags%3d8224%26sn%3d0', 'dc:title': 'x-sonosapi-stream:s44491?sid=254&amp;flags=8224&amp;sn=0', 'upnp:class': 'object.item' } } } +3s
  sonos:metadata Parsing DIDL { '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': 'BBC Radio 6 Music', 'upnp:class': 'object.item.audioItem.audioBroadcast', desc: [Object] } } } +2ms
2020-02-28 08:55:55.063 <debug> New track data for ROOMNAME {"AlbumArtUri":"http://192.168.4.82:1400/getaa?s=1&u=x-sonosapi-stream:s44491%3fsid%3d254%26flags%3d8224%26sn%3d0","Title":"x-sonosapi-stream:s44491?sid=254&amp;flags=8224&amp;sn=0","UpnpClass":"object.item","ItemId":"-1","ParentId":"-1","TrackUri":"x-sonosapi-stream:s44491?sid=254&flags=8224&sn=0","ProtocolInfo":"sonos.com-http:*:audio/mpegurl:*"}
2020-02-28 08:55:55.064 <debug> Published to sonos/status/ROOMNAME/track
^C2020-02-28 08:55:56.160 <info>  Shutting down listeners, please wait

What do you think of that Stephan? Is there anything else I can do to help pinpoint the problem?

besynnerlig commented 4 years ago

Some more info after testing the new version more:

The delayMs of 1000 is absolute necessary here when using node-sonos-ts through sonos2mqtt. (Using node-sonos-ts in VSC works without the delay). Without the delay, there is this short gap of silence instead of the sound.

Just for testing, FWIW I removed the await from the line await this.AVTransportService.Play({ InstanceID: 0, Speed: '1' }).catch(err => { this.debug('Play threw error, wrong url? %o', err); });. Tests running every minute using sonos2mqtt has failed only once since I did that combined with a delay...

svrooij commented 4 years ago

I never experienced this issue, so can you share more details. With my branch you can set the time delay right? so that solves the issue right?

You can also set the timeout to 30, that way if the events don't work it will just revert back after only 30 seconds instead of the 120 set by default.

besynnerlig commented 4 years ago

My sonos system consists of 2 individual Sonos Play:1 and 2 Sonos One configured as a stereo pair. The left speaker is the coordinator of the system. All speakers connects using my WiFi with strong signals. All speakers also have fixed IPs.

I normally use my stereo pair for TTS. That's what I've been testing with above.

My experience is that my stereo pair needs the delay. About 1200 ms works best. (Please increase the 1000 max limit) Without the delay the notification won't play (short gap of silence is played). Using the delay the full notification will play. Sometimes it won't "Reverting everything back to normal" until the delay has passed.

About my separate Sonos Play:1 I have connected using an ethernet cable to my LAN. It behaves differently. The delay is not needed at all but this speaker will never "Reverting everything back to normal" until the delay has passed. It always depends on the timeout to do that. That's weird.

My linux server is also attached to the same LAN using a cable.

Yes, using the delay will make my tts revert everything back to normal after the delay has passed. I'll just have to wait for the timeout. The underlaying problem is not solved though. There is a reason that TTS works flawlessly on all my speakers while debugging in VSC while it fails with short gaps of silent and timeout erros in my system when using sonos2mqtt. Of course there might be something wrong or something special with my Sonos System, I can't tell.

I appreciate your kind help in trying to resolve my issues. This PR works better on my system so I hope you will merge it. (Please allow a higher delayMs though...) If there is anything else that you can think of that I can test, just let me know. Thanks!!!

svrooij commented 4 years ago

:tada: This issue has been resolved in version 1.2.3 :tada:

The release is available on:

Your semantic-release bot :package::rocket: