search

svrooij / sonos2mqtt

:speaker: Sonos mqtt controller. Control your speakers from your mqtt server. mqtt-smarthome insprired.
https://sonos2mqtt.svrooij.io/
MIT License
76 stars 18 forks source link

Spoken message appears as a short gap of silence if streaming/playing #73

Closed besynnerlig closed 4 years ago

besynnerlig commented 4 years ago

On v2.0.11

When playing an Album or when playing a Spotify playlist on the Sonos, most times the spoken message fails and is replaced with a very short period of silence. (Timing issue?) (In my Sonos app I can see the message clip file name showing up briefly) Sometimes, randomly the message gets spoken correctly. When that happens resuming the streamin/playing wont happen. Furthermore volume level is not restored to the level that was actual when streaming/playing.

FWIW I don't know anything why this happens but it sounds like a series of commands are sent to Sonos asynchronously. Maybe Sonos can not handle that. Sonos might not have a command queue and as a result discards previous commands when a new comes in. Just a thought.

svrooij commented 4 years ago

The code for the notifications is here. https://github.com/svrooij/node-sonos-ts/blob/de19aef35367bc8bda253ef89edd64c2bbf4beb2/src/sonos-device.ts#L268-L351

How short is the notification? It might just not play it and then the restore everything back to normal will not work either because it error'ed out.

besynnerlig commented 4 years ago

Thanks.

The notification is a full sentence.

MQTT Test Rule fired with payload: { "text": "Hejsan alla barn", "endpoint": "http://MYTTSSERVER:5601/api/generate","lang": "sv-SE", "gender": "female", "volume": 40, "onlyWhenPlaying": false }

EDIT:

I've installed it locally and I've figured out how to debug it. Below is the debug output. This time a short gap of ilence was heard and it managed to resume streaming afterwards. Other times streaming may not resume. I have also experienced rare cases where the texts gets spoken and everything works. It's all very random.

  sonos:device:192.168.4.82 PlayTTS({ text: 'Hejsan alla barn', endpoint: 'http://MYHOST:5601/api/generate', lang: 'sv-SE', gender: 'female', volume: 40, onlyWhenPlaying: false }) +57s
  sonos:tts Getting tts uri from server http://MYHOST:5601/api/generate +60s
  sonos:device:192.168.4.82 PlayNotification({ trackUri: 'http://MYHOST:5601/cache/sv-SE/23bfdbda9f38e60400bfd1c45621b22228d71191.mp3', onlyWhenPlaying: false, volume: 40, timeout: 120 }) +2ms
  sonos:service:avtransport:192.168.4.82 GetTransportInfo({ InstanceID: 0 }) +55s
  sonos:device:192.168.4.82 Current state is PLAYING +5ms
  sonos:metadata Guessing metadata for http://MYHOST:5601/cache/sv-SE/23bfdbda9f38e60400bfd1c45621b22228d71191.mp3 +55s
  sonos:metadata Don't support this TrackUri (yet) http://MYHOST:5601/cache/sv-SE/23bfdbda9f38e60400bfd1c45621b22228d71191.mp3 +0ms
  sonos:service:renderingcontrol:192.168.4.82 GetVolume({ InstanceID: 0, Channel: 'Master' }) +57s
  sonos:service:avtransport:192.168.4.82 GetMediaInfo({ InstanceID: 0 }) +10ms
  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] } } } +9ms
  sonos:service:avtransport:192.168.4.82 GetPositionInfo({ InstanceID: 0 }) +5ms
  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' } } } +7ms
  sonos:service:avtransport:192.168.4.82 SetAVTransportURI({ InstanceID: 0, CurrentURI: 'http://MYHOST:5601/cache/sv-SE/23bfdbda9f38e60400bfd1c45621b22228d71191.mp3', CurrentURIMetaData: '' }) +7ms
  sonos:service:renderingcontrol:192.168.4.82 SetVolume({ InstanceID: 0, Channel: 'Master', DesiredVolume: 40 }) +39ms
  sonos:service:avtransport:192.168.4.82 Play({ InstanceID: 0, Speed: '1' }) +32ms
  sonos:eventlistener Got event on /sonos/RINCON_7828CA0142F601400/RenderingControl SID: uuid:RINCON_7828CA0142F601400_sub0000013153 +55s
  sonos:service:renderingcontrol:192.168.4.83 Got event +58s
  sonos:device:192.168.4.82 Listener added +60ms
  sonos:eventlistener Got event on /sonos/RINCON_7828CXXXXXXXXXXX/AVTransport SID: uuid:RINCON_7828CXXXXXXXXXXX_sub0000181354 +24ms
  sonos:service:avtransport:192.168.4.82 Got event +29ms
  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': '23bfdbda9f38e60400bfd1c45621b22228d71191.mp3', 'upnp:class': 'object.item.audioItem.musicTrack' } } } +62ms
  sonos:device:192.168.4.82 Listener removed +19ms
  sonos:device:192.168.4.82 Reverting everything back to normal +0ms
  sonos:service:renderingcontrol:192.168.4.82 SetVolume({ InstanceID: 0, Channel: 'Master', DesiredVolume: 10 }) +40ms
  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 } }) +14ms
  sonos:eventlistener Got event on /sonos/RINCON_7828CXXXXXXXXXXX/RenderingControl SID: uuid:RINCON_7828CXXXXXXXXXXX_sub0000181355 +33ms
  sonos:service:renderingcontrol:192.168.4.82 Got event +32ms
  sonos:device:192.168.4.82 Setting back time to 0:00:55 +227ms
  sonos:service:avtransport:192.168.4.82 Seek({ InstanceID: 0, Unit: 'REL_TIME', Target: '0:00:55' }) +214ms
  sonos:eventlistener Got event on /sonos/RINCON_7828CA0142F601400/RenderingControl SID: uuid:RINCON_7828CA0142F601400_sub0000013153 +200ms
  sonos:service:renderingcontrol:192.168.4.83 Got event +257ms
  sonos:service:avtransport:192.168.4.82 Sonos error on Seek { faultcode: 's:Client', faultstring: 'UPnPError', detail: { UPnPError: { errorCode: 701 } } } +15ms
  sonos:device:192.168.4.82 Reverting back track time failed, happens for some muic services (radio or stream). { SonosError: Sonos error on Seek UPnPError 701 at AVTransportService.handleErrorResponse (/usr/local/lib/node_modules/sonos2mqtt/node_modules/@svrooij/sonos/lib/services/base-service.js:202:23) at process._tickCallback (internal/process/next_tick.js:68:7) Action: 'Seek', FaultCode: 's:Client', Fault: 'UPnPError', UpnpErrorCode: 701, name: 'SonosError' } +16ms
  sonos:service:avtransport:192.168.4.82 Play({ InstanceID: 0, Speed: '1' }) +1ms
  sonos:eventlistener Got event on /sonos/RINCON_7828CXXXXXXXXXXX/AVTransport SID: uuid:RINCON_7828CXXXXXXXXXXX_sub0000181354 +24ms
  sonos:service:avtransport:192.168.4.82 Got event +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': '', 'r:radioShowMd': 'Steve Lamacq,p180693', 'upnp:albumArtURI': '/getaa?s=1&u=x-sonosapi-stream%3as44491%3fsid%3d254%26flags%3d8224%26sn%3d0', 'dc:title': 'BBC Radio 6 Music', 'upnp:class': 'object.item' } } } +259ms
  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
  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] } } } +1ms
  sonos:eventlistener Got event on /sonos/RINCON_7828CXXXXXXXXXXX/AVTransport SID: uuid:RINCON_7828CXXXXXXXXXXX_sub0000181354 +1s
  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': 'Steve Lamacq,p180693', 'upnp:albumArtURI': '/getaa?s=1&u=x-sonosapi-stream%3as44491%3fsid%3d254%26flags%3d8224%26sn%3d0', 'dc:title': 'x-sonosapi-stream:s44491?sid=254&flags=8224&sn=0', 'upnp:class': 'object.item' } } } +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', 'dc:title': 'BBC Radio 6 Music', 'upnp:class': 'object.item.audioItem.audioBroadcast', desc: [Object] } } } +0ms
  sonos:eventlistener Got event on /sonos/RINCON_7828CXXXXXXXXXXX/AVTransport SID: uuid:RINCON_7828CXXXXXXXXXXX_sub0000181354 +111ms
  sonos:service:avtransport:192.168.4.82 Got event +115ms
  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': 'ZPSTR_CONNECTING', 'r:radioShowMd': 'Steve Lamacq,p180693', 'upnp:albumArtURI': '/getaa?s=1&u=x-sonosapi-stream%3as44491%3fsid%3d254%26flags%3d8224%26sn%3d0', 'dc:title': 'x-sonosapi-stream:s44491?sid=254&flags=8224&sn=0', 'upnp:class': 'object.item' } } } +116ms
  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
  sonos:eventlistener Got event on /sonos/RINCON_7828CXXXXXXXXXXX/AVTransport SID: uuid:RINCON_7828CXXXXXXXXXXX_sub0000181354 +38ms
  sonos:service:avtransport:192.168.4.82 Got event +35ms
  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': 'Steve Lamacq,p180693', 'upnp:albumArtURI': '/getaa?s=1&u=x-sonosapi-stream%3as44491%3fsid%3d254%26flags%3d8224%26sn%3d0', 'dc:title': 'x-sonosapi-stream:s44491?sid=254&flags=8224&sn=0', 'upnp:class': 'object.item' } } } +33ms
  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] } } } +1ms
  sonos:eventlistener Got event on /sonos/RINCON_7828CXXXXXXXXXXX/AVTransport SID: uuid:RINCON_7828CXXXXXXXXXXX_sub0000181354 +419ms
  sonos:service:avtransport:192.168.4.82 Got event +418ms
  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': 'Steve Lamacq,p180693', 'upnp:albumArtURI': '/getaa?s=1&u=x-sonosapi-stream%3as44491%3fsid%3d254%26flags%3d8224%26sn%3d0', 'dc:title': 'x-sonosapi-stream:s44491?sid=254&flags=8224&sn=0', 'upnp:class': 'object.item' } } } +415ms
  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] } } } +1ms
^C2020-02-20 17:05:35.227 <info>  Shutting down listeners, please wait

I don't know if it's helpful or not.

I've set export DEBUG=sonos:* maybe I should narrow it down?

I can add more debug messages in sonos-device.js if it can help. Please just let me know what's interesting to know.

Thank you for your kind help Stephan!

Cheers!

besynnerlig commented 4 years ago

If I add a wait statement after the TTS volume is set, things start to work. Maybe things are coming in to fast for Sonos.

In /usr/local/lib/node_modules/sonos2mqtt/node_modules/@svrooij/sonos/lib/sonos-device.js line 274:

        if (options.volume !== undefined) {
            await this.RenderingControlService.SetVolume({ InstanceID: 0, Channel: 'Master', DesiredVolume: options.volume });
            await new Promise(resolve => setTimeout(resolve, 500));
        }

Maybe it would be a good idea to add a small delay after every command that is succeeded by another one. What do you think?

Shall i make a PR for you?

svrooij commented 4 years ago

Who had ever thought that I could make it too fast.... 😁

Does that also mean that it just works if the volume isn't supplied with the PlayTTS command? That means the volume won’t get overriden, = less commands.

Yes please, the more contributors the better. Ever done development on a TypeScript library?

Can you create the async sleep method in the AsyncHelper. I would set the timeout to 200ms or even 150ms to keep the delay as short as possible.

Also the delay is probably only needed after the volume change, or maybe after commands that change stuff. Never had problem with the commands retrieving data. This is the only method that does several commands really short after each other.

besynnerlig commented 4 years ago

I'll do that tomorrow. Later, we could consider making the async sleep time configurable...

besynnerlig commented 4 years ago

Does that also mean that it just works if the volume isn't supplied with the PlayTTS command?

Actually, no it doesn't. After testing, I've found out that we do need a delay between this.AVTransportService.SetAVTransportURI and this.AVTransportService.Play.

Yes please, the more contributors the better. Ever done development on a TypeScript library?

No I haven't. I will just improvise, try it out here and trust that any mistakes will be spotted in the PR.

Can you create the async sleep method in the AsyncHelper. I would set the timeout to 200ms or even 150ms to keep the delay as short as possible.

That won't help because the AsyncHelper isn't used when setting the Volume. Maybe it should be used. However that's above my experience level.

Also the delay is probably only needed after the volume change, or maybe after commands that change stuff. Never had problem with the commands retrieving data. This is the only method that does several commands really short after each other.

Yeah, I agree.

I make that PR now so that we can discuss the specific code by reviewing the suggested code. It's easier than doing it here. Please feel free to suggest any type of changes in the PR.

Cheers!

svrooij commented 4 years ago
  1. create a fork of node-sonos-ts.
  2. run npm install in the repository
  3. Change the code you want
  4. Press F5 (in VS Code), while the play-notification sample is open.

That should build (actually transpile) the typescript to javascript, and run the current open sample. The code in the repository is only TypeScript and the lib-folder is automatically ignored.

That won't help because the AsyncHelper isn't used when setting the Volume. Maybe it should be used. However that's above my experience level.

I mean that it might be better to put the delay function in the AsyncHelper class. That code might be needed in other places in the library. Something like

static async Delay(milliseconds: number): Promise {
  return await new Promise(resolve => setTimeout(resolve, 500));
}

Then you can use it by calling:

await AsyncHelper.Delay(150);

Closing this issue, moving to https://github.com/svrooij/node-sonos-ts/issues/38

svrooij commented 4 years ago

Version 2.0.12 has a fix for this. It allows for setting a delayMs in TTS or notification that should solve the issue.

Also the reverting doesn’t try to revert the track for streaming items. That should also make up for some of the errors.