Sonos TTS via Azure has stopped working

tbully · November 14, 2020, 5:39am

Hello -

I’ve been struggling to get TTS working again this evening. I’m able to control my Sonos via Vera but unable to play TTS messages via scenes or through the test window.

I’m currently running 20314.1625; JSUI 2.0-hotfix20314.1625 (which I think is the latest?)

No UPNP Proxy is running for now (although I did try to install it)

I was getting an Azure Auth error in the logs so I regen’d my keys which I think took care of that. I’ve tried several voices to no avail.

Below are my logs:
04 11/14/20 0:44:34.664 08 11/14/20 0:44:36.968 08 11/14/20 0:44:36.969 08 11/14/20 0:44:36.969 08 11/14/20 0:44:36.969 08 11/14/20 0:44:36.969 08 11/14/20 0:44:36.969 08 11/14/20 0:44:36.970 50 11/14/20 0:44:36.972 50 11/14/20 0:44:36.975 50 11/14/20 0:44:36.976 50 11/14/20 0:44:36.976 50 11/14/20 0:44:36.977 -H ‘Content-type: 50 11/14/20 0:44:37.705 50 11/14/20 0:44:37.706 50 11/14/20 0:44:37.707 50 11/14/20 0:44:37.708 50 11/14/20 0:44:38.113 50 11/14/20 0:44:38.115 50 11/14/20 0:44:38.116 01 11/14/20 0:44:38.606 02 11/14/20 0:44:38.607 [string “–[[…”]:265: [string “–[[…”]:289: (tail call): ?
[string “–[[…”]:3398: [string “–[[…”]:3460: [string “–[[…”]:3769: (tail call): ? <0x77969320>
04 11/14/20 0:44:38.785 06 11/14/20 0:44:38.849 06 11/14/20 0:44:38.959 06 11/14/20 0:44:39.336 06 11/14/20 0:44:39.373 06 11/14/20 0:44:39.373 06 11/14/20 0:44:39.426 06 11/14/20 0:44:39.427 06 11/14/20 0:44:39.428 06 11/14/20 0:44:39.431 06 11/14/20 0:44:39.432 06 11/14/20 0:44:39.433 06 11/14/20 0:44:39.433 06 11/14/20 0:44:39.434 06 11/14/20 0:44:39.435 06 11/14/20 0:44:39.889 50 11/14/20 0:44:41.243 50 11/14/20 0:44:41.276 ^C
root@MiOS_55001685:/tmp/log/cmh# <0x76cb6520>
JobHandler_LuaUPnP::HandleActionRequest device: 160 service: urn:micasaverde-com:serviceId:Sonos1 action: Say <0x6e28c520>
JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=160 <0x6e28c520>
JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:micasaverde-com:serviceId:Sonos1 <0x6e28c520>
JobHandler_LuaUPnP::HandleActionRequest argument action=Say <0x6e28c520>
JobHandler_LuaUPnP::HandleActionRequest argument Text=Test message <0x6e28c520>
JobHandler_LuaUPnP::HandleActionRequest argument Engine=AZURE <0x6e28c520>
JobHandler_LuaUPnP::HandleActionRequest argument rand=0.8020652632912324 <0x6e28c520>
luup_log:487: Sonos: Say action on device 160 text “Test message” <0x77969320>
luup_log:487: Sonos: (tts debug) generate() engine Azure Speech Service text Test message file /www/sonos/Say.160.mp3 <0x77969320>
luup_log:487: Sonos: (tts debug) AzureTTSEngine:say() token is expired, fetching new (engine 20314) <0x77969320>
luup_log:487: Sonos: (tts debug) AzureTTSEngine:say() using provided endpoint “https://eastus2.api.cognitive.microsoft.com/” <0x77969320>
luup_log:487: Sonos: (tts debug) AzureTTSEngine:say() “curl -s -k -o - -m 15 -X POST -H ‘Content-length: 0’ \
application/x-www-form-urlencoded’ -H ‘Ocp-Apim-Subscription-Key: XXXXXXXXX’ ‘https://eastus2.api.cognitive.microsoft.com/sts/v1.0/issueToken’” <0x77969320>
luup_log:487: Sonos: (tts debug) AzureTTSEngine:say() response “eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNobWFjLXNoYTI1NiIsInR5cCI6IkpXVCJ9.eyJyZWdpb24iOiJlYXN0dXMyIiwic3Vic2NyaXB0aW9uLWlkIjoiNzk4NzI3YmU2NjhhNGU1NzgyYzI3N2RlNzVhOWZiOGUiLCJwcm9kdWN0LWlkIjoiQ29nbml0aXZlU2VydmljZXMuUzAiLCJjb2duaXRpdmUtc2VydmljZXMtZW5kcG9pbnQiOiJodHRwczovL2FwaS5jb2duaXRpdmUubWljcm9zb2Z0LmNvbS9pbnRlcm5hbC92MS4wLyIsImF6dXJlLXJlc291cmNlLWlkIjoiL3N1YnNjcmlwdGlvbnMvODM4MzAwYWMtMmEwOS00N2JmLWJiZjItYWJmNzIzMDVhOWViL3Jlc291cmNlR3JvdXBzL1ZlcmEvcHJvdmlkZXJzL01pY3Jvc29mdC5Db2duaXRpdmVTZXJ2aWNlcy9hY2NvdW50cy9WZXJhVFRTIiwic2NvcGUiOlsic3BlZWNodG9pbnRlbnRzIiwiaHR0cHM6Ly9hcGkubWljcm9zb2Z0dHJhbnNsYXRvci5jb20vIiwic3BlZWNoc2VydmljZXMiXSwiYXVkIjpbInVybjptcy5zcGVlY2giLCJ1cm46bXMubHVpcy5lYXN0dXMyIiwidXJuOm1zLm1pY3Jvc29mdHRyYW5zbGF0b3IiLCJ1cm46bXMuc3BlZWNoc2VydmljZXMuZWFzdHVzMiJdLCJleHAiOjE2MDUzMzMyNzcsImlzcyI6InVybjptcy5jb2duaXRpdmVzZXJ2aWNlcyJ9.oo1S9XBVTXZhbjm03H4dp3_T1eA1kWbKvkLakroAFDM” <0x77969320>
luup_log:487: Sonos: (tts debug) AzureTTSEngine:say() acquired new token “eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNobWFjLXNoYTI1NiIsInR5cCI6IkpXVCJ9.eyJyZWdpb24iOiJlYXN0dXMyIiwic3Vic2NyaXB0aW9uLWlkIjoiNzk4NzI3YmU2NjhhNGU1NzgyYzI3N2RlNzVhOWZiOGUiLCJwcm9kdWN0LWlkIjoiQ29nbml0aXZlU2VydmljZXMuUzAiLCJjb2duaXRpdmUtc2VydmljZXMtZW5kcG9pbnQiOiJodHRwczovL2FwaS5jb2duaXRpdmUubWljcm9zb2Z0LmNvbS9pbnRlcm5hbC92MS4wLyIsImF6dXJlLXJlc291cmNlLWlkIjoiL3N1YnNjcmlwdGlvbnMvODM4MzAwYWMtMmEwOS00N2JmLWJiZjItYWJmNzIzMDVhOWViL3Jlc291cmNlR3JvdXBzL1ZlcmEvcHJvdmlkZXJzL01pY3Jvc29mdC5Db2duaXRpdmVTZXJ2aWNlcy9hY2NvdW50cy9WZXJhVFRTIiwic2NvcGUiOlsic3BlZWNodG9pbnRlbnRzIiwiaHR0cHM6Ly9hcGkubWljcm9zb2Z0dHJhbnNsYXRvci5jb20vIiwic3BlZWNoc2VydmljZXMiXSwiYXVkIjpbInVybjptcy5zcGVlY2giLCJ1cm46bXMubHVpcy5lYXN0dXMyIiwidXJuOm1zLm1pY3Jvc29mdHRyYW5zbGF0b3IiLCJ1cm46bXMuc3BlZWNoc2VydmljZXMuZWFzdHVzMiJdLCJleHAiOjE2MDUzMzMyNzcsImlzcyI6InVybjptcy5jb2duaXRpdmVzZXJ2aWNlcyJ9.oo1S9XBVTXZhbjm03H4dp3_T1eA1kWbKvkLakroAFDM” <0x77969320>
luup_log:487: Sonos: (tts debug) AzureTTSEngine:say() host “eastus2.tts.speech.microsoft.com” url “https://eastus2.tts.speech.microsoft.com/cognitiveservices/v1” payload “<speak version="1.0" xml:lang="en-US"><voice name="en-US-BenjaminRUS">” <0x77969320>
luup_log:487: Sonos: (tts debug) AzureTTSEngine:say() system LuaSec version is “0.8”, engine is 20314 <0x77969320>
luup_log:487: Sonos: (tts debug) AzureTTSEngine:say() response 1, 200, { connection=“close”, content-type=“audio/mpeg”, date=“Sat, 14 Nov 2020 05:44:38 GMT”, transfer-encoding=“chunked”, strict-transport-security=“max-age=15724800; includeSubDomains”, server=“openresty/1.15.8.2” }, “HTTP/1.1 200 OK” <0x77969320>
luup_log:487: Sonos: (tts debug) AzureTTSEngine:say() received 14112 byte response via socket.http <0x77969320>
luup_log:487: Sonos: (TTS) Engine “Azure Speech Service” created “http://192.168.34.3:80/sonos/Say.160.mp3” <0x77969320>
luup_log:487: Sonos: UPnP_request (Pause, urn:schemas-upnp-org:service:AVTransport:1): status=1 statusMsg=500 result=[<s:Envelope xmlns:s=“http://schemas.xmlsoap.org/soap/envelope/” s:encodingStyle=“http://schemas.xmlsoap.org/soap/encoding/”><s:Body><s:Fault>s:ClientUPnPError701</s:Fault></s:Body></s:Envelope>] <0x77969320>
luup_log:487: stack traceback:
in function ‘error’
in function <[string “–[[…”]:169>
in function ‘sayOrAlert’
in function ‘queueAlert’
in function <[string “–[[…”]:3743>
<0x77969320>
Device_Variable::m_szValue_set device: 487 service: urn:toggledbits-com:serviceId:SonosSystem1 variable: zoneInfo was: { “zones”: { “RINCON_B8E937B6577E01400”: { “Location”: “http://192.168.34.50:1400/xml/device_description.xml”, “Group”: “RINCON_B8E937B6577E01400:292”, “UUID”: “RINCON_B8E937B6577E01400”, “ZoneName”: “Bathroom” } }, “groups”: { “RINCON_B8E937B6577E01400:292”: { “members”: [ “RINCON_B8E937B6577E01400” ], “UUID”: “RINCON_B8E937B6577E01400:292”, “Coordinator”: “RINCON_B8E937B6577E01400” } } } now: { “zones”: { “RINCON_B8E937B6577E01400”: { “Location”: “http://192.168.34.50:1400/xml/device_description.xml”, “Group”: “RINCON_B8E937B6577E01400:293”, “UUID”: “RINCON_B8E937B6577E01400”, “ZoneName”: “Bathroom” } }, “groups”: { “RINCON_B8E937B6577E01400:293”: { “members”: [ “RINCON_B8E937B6577E01400” ], “UUID”: “RINCON_B8E937B6577E01400:293”, “Coordinator”: “RINCON_B8E937B6577E01400” } } } #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: TransportState was: STOPPED now: PLAYING #hooks: 0 upnp: 0 skip: 0 v:0x15ac978/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: CurrentTransportActions was: Set, Stop, Pause, Play, X_DLNA_SeekTime, Next, X_DLNA_SeekTrackNr now: Set, Stop, Pause, Play, X_DLNA_SeekTime, X_DLNA_SeekTrackNr #hooks: 0 upnp: 0 skip: 0 v:0x1540c00/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: NumberOfTracks was: 12 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0x15be980/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: AVTransportURI was: x-rincon-queue:RINCON_B8E937B6577E01400#0 now: http://192.168.34.3:80/sonos/Sonos_chime.mp3 #hooks: 0 upnp: 0 skip: 0 v:0x15b4198/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: CurrentTrackDuration was: 0:03:59 now: 0:00:02 #hooks: 0 upnp: 0 skip: 0 v:0x15bb810/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: CurrentTrackURI was: x-sonos-http:library%2ftracks%2fbb5dd461-ddf2-4ae5-8aa2-e8467f81d9b2%2f.mp3?sid=201&flags=0&sn=7 now: http://192.168.34.3:80/sonos/Sonos_chime.mp3 #hooks: 0 upnp: 0 skip: 0 v:0x15bc3d8/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: CurrentTrackMetaData was: x-sonos-http:library%2ftracks%2fbb5dd461-ddf2-4ae5-8aa2-e8467f81d9b2%2f.mp3?sid=201&flags=0&sn=7<r:streamContent></r:streamContent>upnp:albumArtURI/getaa?s=1&u=x-sonos-http%3alibrary%252ftracks%252fbb5dd461-ddf2-4ae5-8aa2-e8467f81d9b2%252f.mp3%3fsid%3d201%26flags%3d0%26sn%3d7</upnp:albumArtURI>dc:titleFlesh And Bone</dc:title>upnp:classobject.item.audioItem.musicTrack</upnp:class>dc:creatorThe Killers</dc:creator>upnp:albumBattle Born</upnp:album> now: http://192.168.34.3:80/sonos/Sonos_chime.mp3<r:streamContent></r:streamContent>dc:titleSonos_chime.mp3</dc:title>upnp:classobject.item.audioItem.musicTrack</upnp:class> #hooks: 0 upnp: 0 skip: 0 v:0x15bbdf0/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:micasaverde-com:serviceId:Sonos1 variable: CurrentService was: Amazon Music now: #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: CurrentStatus was: Amazon Music: Flesh And Bone: (The Killers, Battle Born) now: Sonos_chime.mp3 #hooks: 0 upnp: 0 skip: 0 v:0x15b5838/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: CurrentTitle was: Flesh And Bone now: Sonos_chime.mp3 #hooks: 0 upnp: 0 skip: 0 v:0x15b65a8/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: CurrentArtist was: The Killers now: #hooks: 0 upnp: 0 skip: 0 v:0x15b84d8/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: CurrentAlbum was: Battle Born now: #hooks: 0 upnp: 0 skip: 0 v:0x15bacf0/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:upnp-org:serviceId:AVTransport variable: CurrentAlbumArt was: http://192.168.34.50:1400/getaa?s=1&u=x-sonos-http%3Alibrary%252ftracks%252fbb5dd461-ddf2-4ae5-8aa2-e8467f81d9b2%252f.mp3%3Fsid%3D201%26flags%3D0%26sn%3D7 now: …/…/…/icons/Sonos.png #hooks: 0 upnp: 0 skip: 0 v:0x15bb060/NONE duplicate:0 <0x718b6520>
Device_Variable::m_szValue_set device: 160 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1605332666 now: 1605332679 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x718b6520>
luup_log:267: G550> Battery level info updated <0x72cb6520>
luup_log:267: G550> Storage level info updated <0x72cb6520>

PrincessCleavage · November 14, 2020, 7:32am

You probably should not post your azure keys (shown in log)

rigpapa · November 14, 2020, 5:51pm

What else have you modified? Did you change any of the TTS configuration state variables?

Edit: by the way, the log shows that it is generating a speech file, which you might be able to play on your desktop with this link: http://192.168.34.3/sonos/Say.160.mp3 (local access only; if you’ve played with it since, it will contain the most recently generated attempt). The error that is logged is just that the Sonos won’t pause because it’s already paused; that’s benign. But Azure is working. There’s no volume control in your TTS request… are you sure it’s high enough to hear/not muted?

tbully · November 15, 2020, 8:29pm

Hey Rigpapa - Thanks for the response. I think my UPNP proxy was messed up. Prior to your response, I did start checking out that link to see if I could playback the MP3 and was successful. This made me think Azure was OK so I started looking in to connectivity to the Sonos.

Ultimately, a complete removal of the UPNP plugin, reboot, reinstall, reboot took care of my issue. I’m unsure why, to be honest, because I know the Sonos plugin can technically work without it.

Anyway. Thanks again for your continued support of this plugin and the people using it.

rigpapa · November 15, 2020, 11:01pm

The UPnP Proxy plugin is one of the odd ducks in the store in that it requires a full reboot of the system (not just a Luup reload) at install to come up working. But I agree the Sonos plugin should run fine even if the proxy wasn’t running/properly started, and I test for that (I keep one Vera with the proxy, one without, and my openLuup dev system can do either). Maybe I’ll have to get a bit more diabolical with my testing.

The other thing that can creep up is that if you only have one zone player and you use DHCP dynamic addressing, it’s possible for it to get a different IP address than what the plugin knows it was last using, and this generally takes rediscovery to fix. It’s less of a problem if you have multiple units, as they tend not to change all at once, and as long as we can talk to one, we can figure out where the rest are. And of course, if your addressing is static or reserved (recommended), that’s not an issue either.

And of course, the Sonos itself runs on software, too, and I have crashed them (made them unresponsive), even using their app. Rebooting them, of course, fixes it.

w1se · December 17, 2020, 6:09am

Hi all,

I just noticed my TTS is not working. It took a while because all my existing ones were cached. I just created a new TTS with RS and it didn’t work.

I have 6 Sonos ONEs. Some are Gen 1 and some are Gen 2. I did update to the S2 unfortunately.

I started reading through the forums and noticed to update. Here is what I did so far:

I’m not 100% sure what version I was on because in the settings page of the plugin I’m fairly sure it said 2.0.
So I immediately downloaded the v2.0 hotfix…but got a version conflict error.
Saw in another thread that I could see version on the apps download > details page, there it said version 1.5. So downloaded newest version from there. Waited 15 mins.
Now it says I have Sonos Plugin version 2.0-20136; JSUI 2.0-20136
Conflict has disappeared but same original problem happening.
I checked Azure and it seems ok, but I refreshed the API and put it in the plugin anyways…no go.
I enabled TTS logs and did a luup.reload() then ran a test TTS…nothing happened.
I noticed this in the log:

02	12/17/20 0:28:33.172	luup_log:99: Sonos: AzureTTSEngine:say() authorization failed with Azure service <0x77c4a000>
02	12/17/20 0:28:33.173	luup_log:99: Sonos: (tts) engine Azure Speech Service error: authorization failed <0x77c4a000>
02	12/17/20 0:28:33.174	luup_log:99: Sonos: (tts) Engine "Azure Speech Service" produced no audio <0x77c4a000>

Any ideas?

lakewoodjazz · December 17, 2020, 6:50am

Don’t use any of the neural voice choices.

rigpapa · December 17, 2020, 2:34pm

Please post more of the log before an error message. Posting just the error message is kind of like looking at the dead body on the sidewalk and having no witnesses around.

w1se · December 17, 2020, 5:40pm

I’m using the voice: English (US), female (Zira)

Sorry I did try the first time but always have problems when posting logs due to character limit. Is this enough?

10	12/17/20 12:35:36.481	ThreadedClass::m_bQuit_set now 1 for 0x1db7aa0 ThreadedClass::StopThread ptr 0x1db7aa0 thread (nil) <0x77096000>
10	12/17/20 12:35:36.481	JobHandler::PurgeCompletedJobs deleting job#14 : dev:103 (0x1a5fc50) P:50 S:4 Id: 14 force 0 status 4 <0x77096000>
10	12/17/20 12:35:36.482	Job::~Job finished <0x1a5fc50> name job#14 : dev:103 (0x1a5fc50) <0x77096000>
10	12/17/20 12:35:36.482	ThreadedClass::m_bQuit_set now 1 for 0x1a5fc50 ThreadedClass::StopThread ptr 0x1a5fc50 thread (nil) <0x77096000>
10	12/17/20 12:35:36.483	JobHandler::PurgeCompletedJobs deleting job#15 : dev:103 (0xfcd658) P:50 S:4 Id: 15 force 0 status 4 <0x77096000>
10	12/17/20 12:35:36.483	Job::~Job finished <0xfcd658> name job#15 : dev:103 (0xfcd658) <0x77096000>
10	12/17/20 12:35:36.484	ThreadedClass::m_bQuit_set now 1 for 0xfcd658 ThreadedClass::StopThread ptr 0xfcd658 thread (nil) <0x77096000>
10	12/17/20 12:35:36.484	JobHandler::PurgeCompletedJobs deleting job#16 : dev:104 (0x210f590) P:50 S:4 Id: 16 force 0 status 4 <0x77096000>
10	12/17/20 12:35:36.485	Job::~Job finished <0x210f590> name job#16 : dev:104 (0x210f590) <0x77096000>
10	12/17/20 12:35:36.486	ThreadedClass::m_bQuit_set now 1 for 0x210f590 ThreadedClass::StopThread ptr 0x210f590 thread (nil) <0x77096000>
10	12/17/20 12:35:36.486	JobHandler::PurgeCompletedJobs deleting job#17 : dev:104 (0x1a5b4b0) P:50 S:4 Id: 17 force 0 status 4 <0x77096000>
10	12/17/20 12:35:36.487	Job::~Job finished <0x1a5b4b0> name job#17 : dev:104 (0x1a5b4b0) <0x77096000>
10	12/17/20 12:35:36.487	ThreadedClass::m_bQuit_set now 1 for 0x1a5b4b0 ThreadedClass::StopThread ptr 0x1a5b4b0 thread (nil) <0x77096000>
10	12/17/20 12:35:36.488	JobHandler::Run jobs 1 blocking jobs 0 handler 0xca3e30 <0x77096000>
10	12/17/20 12:35:36.488	JobHandler::Run ready to run job#28 : dev:44 (0x1e51bf0) P:50 S:0 Id: 28  status 0 <0x1e51bf0> priority 50 tNextRunAttempt 0 handler 0xca3e30 <0x77096000>
35	12/17/20 12:35:36.469	JobHandler_LuaUPnP::GlobalPostProcessingRules start <0x72941520>
10	12/17/20 12:35:36.490	luvd_get_info_data_request creating file buffer /data_request pMem 0x22e6000/36593664 diff: 23330816 <0x72941520>
10	12/17/20 12:35:36.491	luvd_get_info_data_request done /data_request ret 0 size 131 pMem 0x22e6000/36593664 diff: 23330816 took 0 info (nil) <0x72941520>
10	12/17/20 12:35:36.491	mg_callback /data_request stop id: 80 <0x72941520>
10	12/17/20 12:35:36.492	GlobalLog: mongoose get_socket: 0x10106f8 idle: 1 threads: 3 max: 100 head: 4 tail: 4 s: d:9755 <0x72941520>
50	12/17/20 12:35:36.495	luup_log:99: Sonos: Say action on device 44 text "TV Room auto lights have been disabled until 10am." <0x77096000>
50	12/17/20 12:35:36.498	luup_log:99: Sonos: (tts debug) generate() engine Azure Speech Service text TV Room auto lights have been disabled until 10am. file /www/sonos/Say.44.mp3 <0x77096000>
50	12/17/20 12:35:36.498	luup_log:99: Sonos: (tts debug) AzureTTSEngine:say() token is expired, fetching new <0x77096000>
50	12/17/20 12:35:36.893	luup_log:99: Sonos: (tts debug) AzureTTSEngine:say() host "eastus.tts.speech.microsoft.com" payload "<speak version=\"1.0\" xml:lang=\"en-US\"><voice name=\"en-US-ZiraRUS\">TV Room auto lights have been disabled until 10am.</voice></speak>" <0x77096000>
50	12/17/20 12:35:36.895	luup_log:99: Sonos: (tts debug) AzureTTSEngine:say() LuaSec "0.5.PR", using protocol "tlsv1_2" for request <0x77096000>
31	12/17/20 12:35:37.100	AlarmManager::Run 0x15600a0 notified of a change entry 0x202b380 id 281 deleted 0 <0x7587c520>
31	12/17/20 12:35:37.101	AlarmManager::Run callback for alarm 0x15600a0 entry 0x202b380 type 7 id 281 param=0x107caa0 entry->when: 1608226537 time: 1608226537 tnum: 0 slow 1 tardy 0 <0x7587c520>
35	12/17/20 12:35:37.101	LuaInterface::CallFunction_Timer func:HH_message_loop device:21 <0x7587c520>
10	12/17/20 12:35:37.102	AlarmManager::AddRelativeAlarm current time 1608226537 delay 1 type 7 <0x7587c520>
10	12/17/20 12:35:37.102	AlarmManager::AddAbsoluteAlarm alarm 0x15600a0 entry 0x20cc1f8 id 282 type 7 param=0x18fb578 entry->when: 1608226538 time: 1608226537 bCancelFirst 0=0 <0x7587c520>
31	12/17/20 12:35:37.103	AlarmManager::Run finish callback for alarm 0x15600a0 entry 0x202b380 type 7 id 281 param=0x107caa0 entry->when: 1608226537 time: 1608226537 tnum: 0 slow 1 duration 0 <0x7587c520>
50	12/17/20 12:35:37.230	luup_log:99: Sonos: (tts debug) AzureTTSEngine:say() auth fail, arming for retry <0x77096000>
50	12/17/20 12:35:37.231	luup_log:99: Sonos: (tts debug) AzureTTSEngine:say() token is expired, fetching new <0x77096000>
50	12/17/20 12:35:37.523	luup_log:99: Sonos: (tts debug) AzureTTSEngine:say() host "eastus.tts.speech.microsoft.com" payload "<speak version=\"1.0\" xml:lang=\"en-US\"><voice name=\"en-US-ZiraRUS\">TV Room auto lights have been disabled until 10am.</voice></speak>" <0x77096000>
50	12/17/20 12:35:37.524	luup_log:99: Sonos: (tts debug) AzureTTSEngine:say() LuaSec "0.5.PR", using protocol "tlsv1_2" for request <0x77096000>
50	12/17/20 12:35:37.762	luup_log:99: Sonos: (tts debug) AzureTTSEngine:say() auth fail, arming for retry <0x77096000>
02	12/17/20 12:35:37.763	luup_log:99: Sonos: AzureTTSEngine:say() authorization failed with Azure service <0x77096000>
02	12/17/20 12:35:37.764	luup_log:99: Sonos: (tts) engine Azure Speech Service error: authorization failed <0x77096000>
02	12/17/20 12:35:37.765	luup_log:99: Sonos: (tts) Engine "Azure Speech Service" produced no audio <0x77096000>
10	12/17/20 12:35:37.766	UserData::m_iDataVersion_Variables_incr jobst user data 226243044 variables 226243596 <0x77096000>
10	12/17/20 12:35:37.768	Job::m_eJobStatus job job#28 : dev:44 (0x1e51bf0) P:50 S:4 Id: 28 dataversion 226243596 <0x1e51bf0> m_eJobStatus Successful after 1.309871000 seconds callback:0 <0x77096000>
04	12/17/20 12:35:37.769	<Job ID="28" Name="" Device="44" Created="2020-12-17 12:35:36" Started="2020-12-17 12:35:36" Completed="2020-12-17 12:35:37" Duration="1.309871000" Runtime="1.280554000" Status="Successful" LastNote=""/> <0x77096000>
10	12/17/20 12:35:37.786	luvd_get_info_data_request creating file buffer /data_request?id=lu_status&DataVersion=226243595&MinimumDelay=1000&Timeout=60&LoadTime=1608226243&rand=0.31779539569710025 pMem 0x22e6000/36593664 diff: 23330816 <0x72341520>
10	12/17/20 12:35:37.789	luvd_get_info_data_request done /data_request?id=lu_status&DataVersion=226243595&MinimumDelay=1000&Timeout=60&LoadTime=1608226243&rand=0.31779539569710025 ret 0 size 606 pMem 0x22e6000/36593664 diff: 23330816 took 0 info (nil) <0x72341520>
10	12/17/20 12:35:37.790	mg_callback /data_request stop id: 80 <0x72341520>
10	12/17/20 12:35:37.792	GlobalLog: mongoose get_socket: 0x10106f8 idle: 2 threads: 3 max: 100 head: 4 tail: 4 s: d:9755 <0x72341520>
10	12/17/20 12:35:37.790	Job::m_tNextRunAttempt_set job#28 : dev:44 (0x1e51bf0) P:50 S:4 Id: 28 at 1608226537 in 0 seconds <0x77096000>
25	12/17/20 12:35:37.801	LuaInterface::CallFunction_Job device 44 job 28 set to status 4 seconds 0 proc -1 <0x77096000>
10	12/17/20 12:35:37.801	JobHandler::Run finished single job job#28 : dev:44 (0x1e51bf0) P:50 S:0 Id: 28 <0x1e51bf0> <0x77096000>
10	12/17/20 12:35:37.802	JobHandler::PurgeCompletedJobs force 0 purge job size: 1 blocking 0 delete 0 <0x77096000>
10	12/17/20 12:35:37.802	JobHandler::PurgeCompletedJobs purge job#28 : dev:44 (0x1e51bf0) P:50 S:4 Id: 28  status 4 autodelete 1 <0x77096000>
10	12/17/20 12:35:37.803	ThreadedClass::m_bQuit_set now 1 for 0x1e51bf0 ThreadedClass::StopThread ptr 0x1e51bf0 thread (nil) <0x77096000>
10	12/17/20 12:35:37.803	JobHandler::Run jobs 0 blocking jobs 0 handler 0xca3e30 <0x77096000>
10	12/17/20 12:35:37.804	JobHandler::Run ready to sleep jobs: 0 pJob_SingleThreaded: (nil) pJob_Next_Timed (nil) m_cQuitAfterThisJob 0 <0x77096000>
31	12/17/20 12:35:38.100	AlarmManager::Run 0x15600a0 notified of a change entry 0x20cc1f8 id 282 deleted 0 <0x7587c520>
31	12/17/20 12:35:38.101	AlarmManager::Run callback for alarm 0x15600a0 entry 0x20cc1f8 type 7 id 282 param=0x18fb578 entry->when: 1608226538 time: 1608226538 tnum: 0 slow 1 tardy 0 <0x7587c520>
35	12/17/20 12:35:38.101	LuaInterface::CallFunction_Timer func:HH_message_loop device:21 <0x7587c520>
10	12/17/20 12:35:38.102	AlarmManager::AddRelativeAlarm current time 1608226538 delay 1 type 7 <0x7587c520>
10	12/17/20 12:35:38.102	AlarmManager::AddAbsoluteAlarm alarm 0x15600a0 entry 0x1a35978 id 283 type 7 param=0x20d32c0 entry->when: 1608226539 time: 1608226538 bCancelFirst 0=0 <0x7587c520>
31	12/17/20 12:35:38.103	AlarmManager::Run finish callback for alarm 0x15600a0 entry 0x20cc1f8 type 7 id 282 param=0x18fb578 entry->when: 1608226538 time: 1608226538 tnum: 0 slow 1 duration 0 <0x7587c520>
31	12/17/20 12:35:38.104	AlarmManager::Run 0x14467e8 notified of a change entry 0x1e78678 id 33 deleted 0 <0x74e7c520>
31	12/17/20 12:35:38.104	AlarmManager::Run callback for alarm 0x14467e8 entry 0x1e78678 type 7 id 33 param=0x190f750 entry->when: 1608226538 time: 1608226538 tnum: 0 slow 1 tardy 0 <0x74e7c520>
35	12/17/20 12:35:38.104	LuaInterface::CallFunction_Timer func:refreshDevices device:112 <0x74e7c520>

rigpapa · December 17, 2020, 7:20pm

That’s perfect!

Hmmm… looks like… Edge.

Try using the Curl responder (Sonos System master device, Settings tab, “Requestor” – change it to “Curl”, save config changes, reload Luup, give it another try.).

w1se · December 17, 2020, 8:21pm

Yes its an edge…

I don’t see the Requestor option :

rigpapa · December 17, 2020, 8:40pm

You need to first get on the hotfix version: Hotfixes for Sonos 2.0 - Sonos - Ezlo Community

Upgrade to that, and try your TTS before changing requestor.

w1se · December 18, 2020, 5:01pm

The hotfix on its own didn’t work.

Changing the requestor to Curl did work!

Thanks Patrick! You da man!

rigpapa · June 16, 2021, 8:47pm

A post was split to a new topic: Music not resuming after TTS

rywalters · April 12, 2022, 9:23pm

I had Sonos TTS working great on Vera but it’s no longer able to get new messages from Azure. These log entries seem relevant:

10	04/12/22 13:23:44.353	GlobalLog: mongoose get_socket: 0xe96bc0 idle: 1 threads: 3 max: 100 head: 16 tail: 16 s: d:14553 <0x723bf520>
50	04/12/22 13:23:44.853	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() host "westus2.tts.speech.microsoft.com" payload "<speak version=\"1.0\" xml:lang=\"en-US\"><voice name=\"en-US-JessaRUS\">Now hear this. The French Doors have been left open for 3 minutes.</voice></speak>" <0x77cc3320>
50	04/12/22 13:23:44.855	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() LuaSec "0.8", using protocol "any" for request <0x77cc3320>
50	04/12/22 13:23:44.983	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() auth fail, arming for retry <0x77cc3320>
50	04/12/22 13:23:44.984	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() token is expired, fetching new <0x77cc3320>
31	04/12/22 13:23:45.100	AlarmManager::Run 0xad5e68 notified of a change entry 0x1338fb8 id 460 deleted 0 <0x77010520>
31	04/12/22 13:23:45.101	AlarmManager::Run callback for alarm 0xad5e68 entry 0x1338fb8 type 52 id 460 param=(nil) entry->when: 1649795025 time: 1649795025 tnum: 1 slow 0 tardy 0 <0x77010520>

I regenerated my key on Azure (and input into the Sonos device); no improvement. I note that Azure reports my endpoint should be https://verasonostexttospeech.cognitiveservices.azure.com…not sure if that’s changed from the previous working configuration.

rigpapa · April 13, 2022, 11:55am

Make sure you’re on the latest hotfix version (see that linked post for instructions). There’s an endpoint field in the configuration page (on the Sonos plugin’s master device) in that version and you can set the endpoint to whatever Azure requires.

When posting logs, it’s better to post several lines, even a dozen or more, before the part that got your attention, to create context.

rywalters · April 13, 2022, 4:18pm

The hotfix fixed it, with no further reconfiguration required. I’ve bookmarked that page, thank you! You’re doing great work for this community, @rigpapa!

PrincessCleavage · March 20, 2023, 4:32am

Has Azure TTS stopped working for others again?

w1se · March 22, 2023, 4:30am

Mine was working today. But it’s possible it was the TTS stored in memory.

PrincessCleavage · April 9, 2023, 9:26am

My SONOS app controls seem to be working but i can not get Azure TTS to work. Created new resource and copied key but still no joy, which TTS do you use?