Sonos TTS via Azure has stopped working

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:

  1. 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.

  2. So I immediately downloaded the v2.0 hotfix…but got a version conflict error.

  3. 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.

  4. Now it says I have Sonos Plugin version 2.0-20136; JSUI 2.0-20136

  5. Conflict has disappeared but same original problem happening.

  6. I checked Azure and it seems ok, but I refreshed the API and put it in the plugin anyways…no go.

  7. I enabled TTS logs and did a luup.reload() then ran a test TTS…nothing happened.

  8. 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?

Don’t use any of the neural voice choices.

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. :slight_smile:

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>

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.).

Yes its an edge…

I don’t see the Requestor option :

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.

The hotfix on its own didn’t work.

Changing the requestor to Curl did work!

Thanks Patrick! You da man!

1 Like

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

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.

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.

1 Like

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!

1 Like

Has Azure TTS stopped working for others again?

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

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?