Sonos TTS via Azure has stopped working

RogerO · October 10, 2020, 7:33pm

Hi Patrick,
Seems that Azure TTS has stopped working on my SONOS devices.
Currently running Sonos Plugin version 2.0-hotfix20282.1145; JSUI 2.0-hotfix20282.1145. Have updated my Azure Keys and updated them in the SONOS plugin. Running on a Vera plus.
Logs entries when I test are below from an attempt using curl.
Also, I am on SONOS S1 app as I have legacy devices.

8 10/10/20 12:25:30 PM JobHandler_LuaUPnP::HandleActionRequest device: 529 service: urn:micasaverde-com:serviceId:Sonos1 action: Say <0x6d7d3520>
8 10/10/20 12:25:30 PM JobHandler_LuaUPnP::HandleActionRequest argument Text=There is someone at the front door <0x6d7d3520>
8 10/10/20 12:25:30 PM JobHandler_LuaUPnP::HandleActionRequest argument Engine=AZURE <0x6d7d3520>
8 10/10/20 12:25:30 PM JobHandler_LuaUPnP::HandleActionRequest argument Volume=60 <0x6d7d3520>
8 10/10/20 12:25:30 PM JobHandler_LuaUPnP::HandleActionRequest argument Chime=0 <0x6d7d3520>
8 10/10/20 12:25:30 PM JobHandler_LuaUPnP::HandleActionRequest argument id=action <0x6d7d3520>
8 10/10/20 12:25:30 PM JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=529 <0x6d7d3520>
8 10/10/20 12:25:30 PM JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:micasaverde-com:serviceId:Sonos1 <0x6d7d3520>
8 10/10/20 12:25:30 PM JobHandler_LuaUPnP::HandleActionRequest argument action=Say <0x6d7d3520>
50 10/10/20 12:25:30 PM luup_log:761: Sonos: Say action on device 529 text “There is someone at the front door” <0x77f7e320>
50 10/10/20 12:25:30 PM luup_log:761: Sonos: (tts debug) generate() engine Azure Speech Service text There is someone at the front door file /www/sonos/Say.529.mp3 <0x77f7e320>
50 10/10/20 12:25:30 PM luup_log:761: Sonos: (tts debug) AzureTTSEngine:say() current token assumed valid <0x77f7e320>
50 10/10/20 12:25:30 PM luup_log:761: Sonos: (tts debug) AzureTTSEngine:say() host “westus2.tts.speech.microsoft.com” payload “<speak version="1.0" xml:lang="en-US"><voice name="en-US-JessaNeural">” <0x77f7e320>
50 10/10/20 12:25:30 PM luup_log:761: Sonos: (tts debug) AzureTTSEngine:say() system LuaSec version is “0.8” <0x77f7e320>
2 10/10/20 12:25:31 PM luup_log:761: Sonos: (tts) engine Azure Speech Service error: received zero-length file <0x77f7e320>
2 10/10/20 12:25:31 PM luup_log:761: Sonos: (tts) Engine “Azure Speech Service” produced no audio <0x77f7e320>
4 10/10/20 12:25:31 PM <0x77f7e320>
Let me know what additional info you need.

Thanks,
Roger

rigpapa · October 12, 2020, 1:43pm

I’ve updated the hotfix ZIP file in the hotfix topic’s head post to include a TTS engine with a bit more debug. I’m starting to see more rumbles of this, and one user you may have seen posted a notice from Microsoft about them changing certificate authorities on their servers, and this may have something to do with it, but the nature of the beast is such that multiple issues can all cause similar symptoms, so each case needs to be examined individually.

For everyone still having Azure issues, I’d like you to install the hotfix package in the head post here and then please post the log from the invocation of a (failed) Say action to the final message. This version in particular will log messages of note in yellow in the log file, but all surrounding log entries are necessary for context, so please don’t over-redact.

Remember to hash out your API key if the log snippet you are posting contains it!

Do not PDF the log content. Just post the text here, ideally with code-block formatting (``` on a line by itself, followed by log entries, followed by ``` on a line by itself again).

Make sure you are on the released version of Sonos 2.0 before applying the hotfix package. The hotfix package will not work on versions prior to the released 2.0 (including beta/previews of 2.0–upgrade to release first). The released version is tagged 20136. If you have applied other hotfixes since, that’s OK. Just apply the new package over the old.

Get the hotfix: Hotfixes for Sonos 2.0 - Sonos - Ezlo Community

RogerO · October 12, 2020, 4:20pm

Hi Patrick,
Updated to latest hotfix, log below.

“”

50	10/12/20 9:15:44.350	luup_log:761: Sonos: (tts debug) AzureTTSEngine:say() response “eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNobWFjLXNoYTI1NiIsInR5cCI6IkpXVCJ9.eyJyZWdpb24iOiJ3ZXN0dXMyIiwic3Vic2NyaXB0aW9uLWlkIjoiMDM3N2YyY2E0NTdkNGE2YzgwMDA5YjA2YTM2NzhiZjEiLCJwcm9kdWN0LWlkIjoiQ29nbml0aXZlU2VydmljZXMuUzAiLCJjb2duaXRpdmUtc2VydmljZXMtZW5kcG9pbnQiOiJodHRwczovL2FwaS5jb2duaXRpdmUubWljcm9zb2Z0LmNvbS9pbnRlcm5hbC92MS4wLyIsImF6dXJlLXJlc291cmNlLWlkIjoiL3N1YnNjcmlwdGlvbnMvNjkyNmVkMTUtNDBmOS00N2UwLWIxYWQtNTlkOWRlMTZhZGQ5L3Jlc291cmNlR3JvdXBzL1ZlcmFfVFRTL3Byb3ZpZGVycy9NaWNyb3NvZnQuQ29nbml0aXZlU2VydmljZXMvYWNjb3VudHMvVmVyYS1Tb25vcy1UVFMiLCJzY29wZSI6WyJzcGVlY2h0b2ludGVudHMiLCJodHRwczovL2FwaS5taWNyb3NvZnR0cmFuc2xhdG9yLmNvbS8iLCJzcGVlY2hzZXJ2aWNlcyJdLCJhdWQiOlsidXJuOm1zLnNwZWVjaCIsInVybjptcy5sdWlzLndlc3R1czIiLCJ1cm46bXMubWljcm9zb2Z0dHJhbnNsYXRvciIsInVybjptcy5zcGVlY2hzZXJ2aWNlcy53ZXN0dXMyIl0sImV4cCI6MTYwMjUxOTk0NCwiaXNzIjoidXJuOm1zLmNvZ25pdGl2ZXNlcnZpY2VzIn0.hrtFvX-P-4mJCt8YvFc0D68VPq9plfc8NivlP1kw__E” <0x77fa6320>
50	10/12/20 9:15:44.351	luup_log:761: Sonos: (tts debug) AzureTTSEngine:say() acquired new token “eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNobWFjLXNoYTI1NiIsInR5cCI6IkpXVCJ9.eyJyZWdpb24iOiJ3ZXN0dXMyIiwic3Vic2NyaXB0aW9uLWlkIjoiMDM3N2YyY2E0NTdkNGE2YzgwMDA5YjA2YTM2NzhiZjEiLCJwcm9kdWN0LWlkIjoiQ29nbml0aXZlU2VydmljZXMuUzAiLCJjb2duaXRpdmUtc2VydmljZXMtZW5kcG9pbnQiOiJodHRwczovL2FwaS5jb2duaXRpdmUubWljcm9zb2Z0LmNvbS9pbnRlcm5hbC92MS4wLyIsImF6dXJlLXJlc291cmNlLWlkIjoiL3N1YnNjcmlwdGlvbnMvNjkyNmVkMTUtNDBmOS00N2UwLWIxYWQtNTlkOWRlMTZhZGQ5L3Jlc291cmNlR3JvdXBzL1ZlcmFfVFRTL3Byb3ZpZGVycy9NaWNyb3NvZnQuQ29nbml0aXZlU2VydmljZXMvYWNjb3VudHMvVmVyYS1Tb25vcy1UVFMiLCJzY29wZSI6WyJzcGVlY2h0b2ludGVudHMiLCJodHRwczovL2FwaS5taWNyb3NvZnR0cmFuc2xhdG9yLmNvbS8iLCJzcGVlY2hzZXJ2aWNlcyJdLCJhdWQiOlsidXJuOm1zLnNwZWVjaCIsInVybjptcy5sdWlzLndlc3R1czIiLCJ1cm46bXMubWljcm9zb2Z0dHJhbnNsYXRvciIsInVybjptcy5zcGVlY2hzZXJ2aWNlcy53ZXN0dXMyIl0sImV4cCI6MTYwMjUxOTk0NCwiaXNzIjoidXJuOm1zLmNvZ25pdGl2ZXNlcnZpY2VzIn0.hrtFvX-P-4mJCt8YvFc0D68VPq9plfc8NivlP1kw__E” <0x77fa6320>
50	10/12/20 9:15:44.351	luup_log:761: Sonos: (tts debug) AzureTTSEngine:say() host “westus2.tts.speech.microsoft.com” payload “<speak version="1.0" xml:lang="en-US"><voice name="en-US-JessaNeural">” <0x77fa6320>
50	10/12/20 9:15:44.351	luup_log:761: Sonos: (tts debug) AzureTTSEngine:say() system LuaSec version is “0.8” <0x77fa6320>
50	10/12/20 9:15:45.665	luup_log:761: Sonos: (tts debug) AzureTTSEngine:say() response 1, 500, { connection=“close”, content-type=“text/xml”, date=“Mon, 12 Oct 2020 16:15:45 GMT”, transfer-encoding=“chunked”, strict-transport-security=“max-age=15724800; includeSubDomains”, server=“openresty/1.15.8.2” }, “HTTP/1.1 500 Synthesis failed. StatusCode: Unknown, Details: ‘cdata’ is an unexpected token. The expected token is ‘CDATA[’. Line 1, position 155…” <0x77fa6320>
02	10/12/20 9:15:45.666	luup_log:761: Sonos: AzureTTSEngine:say() conversion request failed, 500 <0x77fa6320>
02	10/12/20 9:15:45.666	luup_log:761: Sonos: AzureTTSEngine:say() r=1 <0x77fa6320>
02	10/12/20 9:15:45.667	luup_log:761: Sonos: AzureTTSEngine:say() h=table: 0x3dbc320 <0x77fa6320>
02	10/12/20 9:15:45.667	luup_log:761: Sonos: AzureTTSEngine:say() h={ connection=“close”, content-type=“text/xml”, date=“Mon, 12 Oct 2020 16:15:45 GMT”, transfer-encoding=“chunked”, strict-transport-security=“max-age=15724800; includeSubDomains”, server=“openresty/1.15.8.2” } <0x77fa6320>
02	10/12/20 9:15:45.668	luup_log:761: Sonos: AzureTTSEngine:say() e=HTTP/1.1 500 Synthesis failed. StatusCode: Unknown, Details: ‘cdata’ is an unexpected token. The expected token is ‘CDATA[’. Line 1, position 155… <0x77fa6320>
02	10/12/20 9:15:45.668	luup_log:761: Sonos: AzureTTSEngine:say() payload=“<speak version="1.0" xml:lang="en-US"><voice name="en-US-JessaNeural">” <0x77fa6320>
02	10/12/20 9:15:45.669	luup_log:761: Sonos: (tts) engine Azure Speech Service error: request failed 500 <0x77fa6320>
02	10/12/20 9:15:45.670	luup_log:761: Sonos: (tts) Engine “Azure Speech Service” produced no audio <0x77fa6320>
04	10/12/20 9:15:45.671	<0x77fa6320>
“”

rywalters · October 22, 2020, 5:03am

This is my first attempt at retrieving and looking through logs (using the GetLogs plugin), so hopefully this is helpful. My Sonos plugin seems to be controlling Sonos just fine, but I’ve not gotten it to do TTS. Just installed it tonight, upgraded to the hotfix, and setup an Azure acct with the Translator resource.

10	10/21/20 21:54:31.576	mg_callback from IP:127.0.0.1:59842 /port_3480/data_request id=lu_action&DeviceNum=106&serviceId=urn:micasaverde-com:serviceId:Sonos1&action=Say&Text=Goodnight%20moon!&GroupZones=&Engine=AZURE&rand=0.0728634951963818 start id: 409 <0x73631520>
12	10/21/20 21:54:31.576	luvd_get_info_data_request starting /data_request?id=lu_action&DeviceNum=106&serviceId=urn:micasaverde-com:serviceId:Sonos1&action=Say&Text=Goodnight%20moon!&GroupZones=&Engine=AZURE&rand=0.0728634951963818 pMem 0x23d0000/37552128 diff: 22454272 <0x73631520>
10	10/21/20 21:54:31.577	JobHandler_LuaUPnP::HandleRequest id lu_action request pMem 0x23d0000/37552128 diff: 22454272 <0x73631520>
10	10/21/20 21:54:31.577	sbrk JobHandler_LuaUPnP::HandleActionRequest Problem with getnameinfo <0x73631520>
08	10/21/20 21:54:31.577	JobHandler_LuaUPnP::HandleActionRequest device: 106 service: urn:micasaverde-com:serviceId:Sonos1 action: e[36;1mSaye[0m <0x73631520>
08	10/21/20 21:54:31.578	JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=106 <0x73631520>
08	10/21/20 21:54:31.578	JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:micasaverde-com:serviceId:Sonos1 <0x73631520>
08	10/21/20 21:54:31.578	JobHandler_LuaUPnP::HandleActionRequest argument action=Say <0x73631520>
08	10/21/20 21:54:31.578	JobHandler_LuaUPnP::HandleActionRequest argument Text=Goodnight moon! <0x73631520>
08	10/21/20 21:54:31.578	JobHandler_LuaUPnP::HandleActionRequest argument Engine=AZURE <0x73631520>
08	10/21/20 21:54:31.579	JobHandler_LuaUPnP::HandleActionRequest argument rand=0.0728634951963818 <0x73631520>
35	10/21/20 21:54:31.579	JobHandler_LuaUPnP::ConfirmGlobalActionRules start <0x73631520>
10	10/21/20 21:54:31.579	Job::Job created <0x20c3478> name job#98 : dev:106 (0x20c3478) <0x73631520>
10	10/21/20 21:54:31.580	JobHandler::AddJob job#98 : dev:106 (0x20c3478) P:50 S:0 Id: 98 <0x20c3478>  type Lua_Job first 0 size 0 handler 0xe64200 <0x73631520>
10	10/21/20 21:54:31.580	JobHandler::PurgeCompletedJobs force 0 purge job size: 1 blocking 0 delete 1 <0x77734320>
10	10/21/20 21:54:31.580	JobHandler::PurgeCompletedJobs deleting job#81 : dev:106 (0x19d9ed0) P:50 S:4 Id: 81 force 0 status 4 <0x77734320>
10	10/21/20 21:54:31.581	Job::~Job finished <0x19d9ed0> name job#81 : dev:106 (0x19d9ed0) <0x77734320>
10	10/21/20 21:54:31.581	ThreadedClass::m_bQuit_set now 1 for 0x19d9ed0 ThreadedClass::StopThread ptr 0x19d9ed0 thread (nil) <0x77734320>
10	10/21/20 21:54:31.581	JobHandler::Run jobs 1 blocking jobs 0 handler 0xe64200 <0x77734320>
10	10/21/20 21:54:31.582	JobHandler::Run ready to run job#98 : dev:106 (0x20c3478) P:50 S:0 Id: 98  status 0 <0x20c3478> priority 50 tNextRunAttempt 0 handler 0xe64200 <0x77734320>
50	10/21/20 21:54:31.582	luup_log:102: Sonos: Say action on device 106 text "Goodnight moon!" <0x77734320>
50	10/21/20 21:54:31.586	luup_log:102: Sonos: (tts debug) generate() engine Azure Speech Service text Goodnight moon! file /www/sonos/Say.106.mp3 <0x77734320>
50	10/21/20 21:54:31.587	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() token is expired, fetching new <0x77734320>
50	10/21/20 21:54:31.587	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() "curl -s -k -o - -m 15 -X POST -H 'Content-length: 0' \\\
-H 'Content-type: application/x-www-form-urlencoded' -H 'Ocp-Apim-Subscription-Key: REMOVEDKEY' 'https://westus2.api.cognitive.microsoft.com/sts/v1.0/issueToken'" <0x77734320>
35	10/21/20 21:54:31.580	JobHandler_LuaUPnP::GlobalPostProcessingRules start <0x73631520>
10	10/21/20 21:54:31.596	luvd_get_info_data_request creating file buffer /data_request?id=lu_action&DeviceNum=106&serviceId=urn:micasaverde-com:serviceId:Sonos1&action=Say&Text=Goodnight%20moon!&GroupZones=&Engine=AZURE&rand=0.0728634951963818 pMem 0x23d0000/37552128 diff: 22454272 <0x73631520>
10	10/21/20 21:54:31.600	luvd_get_info_data_request done /data_request?id=lu_action&DeviceNum=106&serviceId=urn:micasaverde-com:serviceId:Sonos1&action=Say&Text=Goodnight%20moon!&GroupZones=&Engine=AZURE&rand=0.0728634951963818 ret 0 size 131 pMem 0x23d0000/37552128 diff: 22454272 took 0 info (nil) <0x73631520>
10	10/21/20 21:54:31.600	mg_callback /data_request stop id: 409 <0x73631520>
10	10/21/20 21:54:31.602	GlobalLog: mongoose get_socket: 0x1103238 idle: 0 threads: 3 max: 100 head: 9 tail: 9 s: d:10577 <0x73631520>
31	10/21/20 21:54:32.100	AlarmManager::Run 0xe67e68 notified of a change entry 0x1e15870 id 1440 deleted 0 <0x76a82520>
31	10/21/20 21:54:32.101	AlarmManager::Run callback for alarm 0xe67e68 entry 0x1e15870 type 51 id 1440 param=(nil) entry->when: 1603342472 time: 1603342472 tnum: 1 slow 0 tardy 0 <0x76a82520>
24	10/21/20 21:54:32.101	ZWaveJobHandler::ServicePollLoop not polling node 2 m_tLastPolled_get 40 PollTime 60 <0x76a82520>
24	10/21/20 21:54:32.102	ZWaveJobHandler::ServicePollLoop not polling node 3 m_tLastPolled_get 2227 PollTime 10800 <0x76a82520>
24	10/21/20 21:54:32.102	ZWaveJobHandler::ServicePollLoop not polling 4 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.102	ZWaveJobHandler::ServicePollLoop not polling 5 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.102	ZWaveJobHandler::ServicePollLoop not polling 6 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.102	ZWaveJobHandler::ServicePollLoop not polling 7 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.103	ZWaveJobHandler::ServicePollLoop not polling 8 bypass 0 freq 10800 listen 1 <0x76a82520>
24	10/21/20 21:54:32.103	ZWaveJobHandler::ServicePollLoop not polling 9 bypass 0 freq 10800 listen 1 <0x76a82520>
24	10/21/20 21:54:32.103	ZWaveJobHandler::ServicePollLoop not polling 10 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.103	ZWaveJobHandler::ServicePollLoop not polling node 19 m_tLastPolled_get 2128 PollTime 10800 <0x76a82520>
24	10/21/20 21:54:32.103	ZWaveJobHandler::ServicePollLoop not polling 21 bypass 0 freq 10800 listen 1 <0x76a82520>
24	10/21/20 21:54:32.104	ZWaveJobHandler::ServicePollLoop not polling node 23 m_tLastPolled_get 2077 PollTime 10800 <0x76a82520>
24	10/21/20 21:54:32.104	ZWaveJobHandler::ServicePollLoop not polling 38 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.104	ZWaveJobHandler::ServicePollLoop not polling 39 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.104	ZWaveJobHandler::ServicePollLoop not polling 41 bypass 1 freq 60 listen 0 <0x76a82520>
24	10/21/20 21:54:32.104	ZWaveJobHandler::ServicePollLoop not polling 42 bypass 0 freq 10800 listen 1 <0x76a82520>
24	10/21/20 21:54:32.105	ZWaveJobHandler::ServicePollLoop not polling 46 bypass 0 freq 0 listen 1 <0x76a82520>
24	10/21/20 21:54:32.105	ZWaveJobHandler::ServicePollLoop not polling 47 bypass 0 freq 10800 listen 1 <0x76a82520>
24	10/21/20 21:54:32.105	ZWaveJobHandler::ServicePollLoop not polling 48 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.106	ZWaveJobHandler::ServicePollLoop not polling 49 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.106	ZWaveJobHandler::ServicePollLoop not polling 51 bypass 0 freq 10800 listen 1 <0x76a82520>
24	10/21/20 21:54:32.106	ZWaveJobHandler::ServicePollLoop not polling 57 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.106	ZWaveJobHandler::ServicePollLoop not polling node 58 m_tLastPolled_get 1897 PollTime 43200 <0x76a82520>
24	10/21/20 21:54:32.106	ZWaveJobHandler::ServicePollLoop not polling node 59 m_tLastPolled_get 1867 PollTime 10800 <0x76a82520>
24	10/21/20 21:54:32.107	ZWaveJobHandler::ServicePollLoop not polling node 60 m_tLastPolled_get 1837 PollTime 10800 <0x76a82520>
24	10/21/20 21:54:32.107	ZWaveJobHandler::ServicePollLoop not polling node 61 m_tLastPolled_get 1807 PollTime 10800 <0x76a82520>
24	10/21/20 21:54:32.107	ZWaveJobHandler::ServicePollLoop not polling node 63 m_tLastPolled_get 1747 PollTime 10800 <0x76a82520>
24	10/21/20 21:54:32.107	ZWaveJobHandler::ServicePollLoop not polling 64 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.107	ZWaveJobHandler::ServicePollLoop not polling 65 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.108	ZWaveJobHandler::ServicePollLoop not polling 66 bypass 0 freq 0 listen 0 <0x76a82520>
24	10/21/20 21:54:32.108	ZWaveJobHandler::ServicePollLoop polling node 12 <0x76a82520>
10	10/21/20 21:54:32.108	Job::Job created <0x22467e0> name job#99 :pollnode #12 dev:16 (0x22467e0) <0x76a82520>
10	10/21/20 21:54:32.109	Job::m_cPriority_set job#99 :pollnode #12 dev:16 (0x22467e0) P:50 S:0 Id: 99 was 50 now 100 <0x76a82520>
24	10/21/20 21:54:32.109	sbrk ZWaveJobHandler::sbrkaddjob pMem 0x23d0000/37552128 diff: 22454272 quit 0 <0x76a82520>
10	10/21/20 21:54:32.110	JobHandler::AddJob job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:0 Id: 99 <0x22467e0> pollnode #12 type ZWJob_PollNode first 0 size 0 handler 0x133f910 <0x76a82520>
10	10/21/20 21:54:32.110	AlarmManager::AddRelativeAlarm current time 1603342472 delay 30 type 51 <0x76a82520>
31	10/21/20 21:54:32.110	AlarmManager::CancelAlarmByType_DoIt 0xe67e68 type 51/51 id 1440 entry 0x1e15870 deleted 0 waiting 1 <0x76a82520>
31	10/21/20 21:54:32.100	AlarmManager::Run 0x1682fa0 notified of a change entry 0x202bd48 id 2321 deleted 0 <0x75031520>
31	10/21/20 21:54:32.111	AlarmManager::Run callback for alarm 0x1682fa0 entry 0x202bd48 type 7 id 2321 param=0x1a65a78 entry->when: 1603342472 time: 1603342472 tnum: 0 slow 1 tardy 0 <0x75031520>
35	10/21/20 21:54:32.111	LuaInterface::CallFunction_Timer func:HH_message_loop device:83 <0x75031520>
10	10/21/20 21:54:32.112	AlarmManager::AddRelativeAlarm current time 1603342472 delay 1 type 7 <0x75031520>
10	10/21/20 21:54:32.112	AlarmManager::AddAbsoluteAlarm alarm 0x1682fa0 entry 0x1b09a68 id 2322 type 7 param=0x1a8a240 entry->when: 1603342473 time: 1603342472 bCancelFirst 0=0 <0x75031520>
31	10/21/20 21:54:32.112	AlarmManager::Run finish callback for alarm 0x1682fa0 entry 0x202bd48 type 7 id 2321 param=0x1a65a78 entry->when: 1603342472 time: 1603342472 tnum: 0 slow 1 duration 0 <0x75031520>
10	10/21/20 21:54:32.111	AlarmManager::AddAbsoluteAlarm alarm 0xe67e68 entry 0x206b9f8 id 1443 type 51 param=(nil) entry->when: 1603342502 time: 1603342472 bCancelFirst 1=1 <0x76a82520>
31	10/21/20 21:54:32.121	AlarmManager::Run finish callback for alarm 0xe67e68 entry 0x1e15870 type 51 id 1440 param=(nil) entry->when: 1603342472 time: 1603342472 tnum: 1 slow 0 duration 0 <0x76a82520>
10	10/21/20 21:54:32.121	JobHandler::PurgeCompletedJobs force 0 purge job size: 1 blocking 0 delete 10 <0x76482520>
10	10/21/20 21:54:32.132	JobHandler::PurgeCompletedJobs deleting job#89 :pollnode #24 dev:34 (0x1e5d4c0) N:24 P:100 S:2 Id: 89 force 0 status 2 <0x76482520>
24	10/21/20 21:54:32.132	ZWaveCommand::~ZWaveCommand 0x201ee78/(nil) <0x76482520>
10	10/21/20 21:54:32.132	Job::~Job finished <0x1e5d4c0> name job#89 :pollnode #24 dev:34 (0x1e5d4c0) N:24 <0x76482520>
10	10/21/20 21:54:32.133	ThreadedClass::m_bQuit_set now 1 for 0x1e5d4c0 ThreadedClass::StopThread ptr 0x1e5d4c0 thread (nil) <0x76482520>
10	10/21/20 21:54:32.133	JobHandler::Run jobs 1 blocking jobs 0 handler 0x133f910 <0x76482520>
24	10/21/20 21:54:32.133	ZWJob_PollNode::ReadyToRun job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:0 Id: 99 priority 100 can cancel <0x76482520>
10	10/21/20 21:54:32.134	JobHandler::Run ready to run job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:0 Id: 99 pollnode #12 status 0 <0x22467e0> priority 100 tNextRunAttempt 0 handler 0x133f910 <0x76482520>
24	10/21/20 21:54:32.134	ZWJob_PollNode::m_eJobStatus job job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:1 Id: 99 <0x22467e0> m_eJobStatus Running after 0.25786000 seconds <0x76482520>
24	10/21/20 21:54:32.134	ZWJob_PollNode::Run job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:1 Id: 99 node 12 size cmds 0 <0x76482520>
22	10/21/20 21:54:32.135	ZZZ-POLLING H1,H2,/1/0/0 <0x76482520>
24	10/21/20 21:54:32.135	ZWaveNode::AddPollingCommand node 12 device 16 added 12/16=0x31,12/16=0x40,12/16=0x42,12/16=0x44,12/16=0x43, <0x76482520>
24	10/21/20 21:54:32.136	ZWJob_PollNode::Run Polling job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:1 Id: 99 node 12 device 16 with command class 0x31 command 0x4 <0x76482520>
22	10/21/20 21:54:32.136	ZW_Send_Data node 12 NO ROUTE (nil) <0x76482520>
24	10/21/20 21:54:32.136	ZWJob_PollNode::m_eJobStatus job job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:7 Id: 99 <0x22467e0> m_eJobStatus PendingData after 0.27934000 seconds <0x76482520>
24	10/21/20 21:54:32.137	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x133ff98 m_p (nil) now 0x200f220 <0x76482520>
41	10/21/20 21:54:32.137	ZWaveSerial::Send XXXX  node 12 using route 0.119.240.240 autoroute: 1 direct: 0 <0x76482520>
13	10/21/20 21:54:32.137	e[32;2mZWaveSerial::DoSendFrame Send frame: 0x1 0x9 0x0 0x13 0xc 0x2 0x31 0x4 0x5 0xb9 0x62 (e[36;1m######1###be[0m)e[0m <0x76482520>
31	10/21/20 21:54:32.121	AlarmManager::Run 0xe67e68 notified of a change entry 0x21660a0 id 1419 deleted 0 <0x76c82520>
31	10/21/20 21:54:32.142	AlarmManager::Run callback for alarm 0xe67e68 entry 0x1f5de40 type 52 id 1442 param=(nil) entry->when: 1603342472 time: 1603342472 tnum: 1 slow 0 tardy 0 <0x76a82520>
10	10/21/20 21:54:32.142	UserData::SetTag LuaUPnPAlive=1603342472 <0x76a82520>
10	10/21/20 21:54:32.142	AlarmManager::AddRelativeAlarm current time 1603342472 delay 5 type 52 <0x76a82520>
10	10/21/20 21:54:32.143	AlarmManager::AddAbsoluteAlarm alarm 0xe67e68 entry 0x202bd48 id 1444 type 52 param=(nil) entry->when: 1603342477 time: 1603342472 bCancelFirst 0=0 <0x76a82520>
31	10/21/20 21:54:32.143	AlarmManager::Run finish callback for alarm 0xe67e68 entry 0x1f5de40 type 52 id 1442 param=(nil) entry->when: 1603342472 time: 1603342472 tnum: 1 slow 0 duration 0 <0x76a82520>
31	10/21/20 21:54:32.143	AlarmManager::Run 0xe67e68 notified of a change entry 0x21660a0 id 1419 deleted 0 <0x76c82520>
24	10/21/20 21:54:32.154	ZWaveSerial::Send m_iFrameID 988 type 0x0 command 0x13 sent ok waiting for 3 ulTime 2283153 timeout 2:2000 bWaitingForAck 1 abort 0 <0x76482520>
13	10/21/20 21:54:32.164	e[32;2mZWaveSerial::ReceiveData: 0x6 0x1 0x4 0x1 0x13 0x1 0xe8 (e[36;1m#######e[0m)e[0m <0x76082520>
42	10/21/20 21:54:32.164	got expected ACK <0x76082520>
24	10/21/20 21:54:32.164	ZWaveSerial::Send woke up: ulTime 2283153 ulTime_end 2283164 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x76482520>
24	10/21/20 21:54:32.165	ZWaveSerial::Send m_iFrameID 988 type 0x0 command 0x13 sent ok waiting for 3 ulTime 2283153 timeout 20:20000 bWaitingForAck 0 abort 0 <0x76482520>
24	10/21/20 21:54:32.165	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 989 gwf_sd <0x76082520>
13	10/21/20 21:54:32.175	e[32;2mZWaveSerial::SendACK: 0x6 (e[36;1m#e[0m)e[0m <0x76082520>
24	10/21/20 21:54:32.189	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 989 gwf_sd <0x76082520>
24	10/21/20 21:54:32.190	ZWaveSerial::ReceivedFrame m_iFrameID 989 gwf_sd is a response frame for m_iFrameID 988 pd_r we're waiting got ack 1 expected response 3 <0x76082520>
13	10/21/20 21:54:32.220	e[32;2mZWaveSerial::ReceiveData: 0x1 0x18 0x0 0x13 0xb9 0x0 0x0 0x2 0x0 0xae 0x7f 0x7f 0x7f 0x7f 0x0 0x1 0x3 0x0 0x0 0x0 0x0 0x2 0x1 0x0 0x0 0xe0 (e[36;1m##########################e[0m)e[0m <0x76082520>
24	10/21/20 21:54:32.221	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 990 gwf_sd <0x76082520>
13	10/21/20 21:54:32.221	e[32;2mZWaveSerial::SendACK: 0x6 (e[36;1m#e[0m)e[0m <0x76082520>
24	10/21/20 21:54:32.237	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 990 gwf_sd <0x76082520>
24	10/21/20 21:54:32.238	ZWaveSerial::ReceivedFrame m_iFrameID 990 gwf_sd is a request frame for m_iFrameID 988 pd_r we're waiting got ack 1 expected response 3 <0x76082520>
24	10/21/20 21:54:32.238	ZWaveSerial::Send woke up: ulTime 2283153 ulTime_end 2283238 TimeToWaitInMs 20000 m_pres 0x1fe3958 m_preq 0x1fdb4c8 status 1 <0x76482520>
24	10/21/20 21:54:32.238	ZWaveSerial::Send m_iFrameID 988 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x76482520>
24	10/21/20 21:54:32.238	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x133ff98 m_p 0x200f220 now (nil) <0x76482520>
10	10/21/20 21:54:32.239	Job::m_tNextRunAttempt_set job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:7 Id: 99 at 1603342492 in 20 seconds <0x76482520>
24	10/21/20 21:54:32.239	ZWJob_PollNode::m_eJobStatus job job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:5 Id: 99 <0x22467e0> m_eJobStatus Waiting after 0.130743000 seconds <0x76482520>
10	10/21/20 21:54:32.239	JobHandler::BlockAllJobs job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:5 Id: 99 <0x22467e0> pollnode #12 5 cmds type ZWJob_PollNode <0x76482520>
10	10/21/20 21:54:32.240	JobHandler::Run finished single job job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:0 Id: 99 <0x22467e0> <0x76482520>
10	10/21/20 21:54:32.240	JobHandler::PurgeCompletedJobs force 0 purge job size: 1 blocking 1 delete 9 <0x76482520>
10	10/21/20 21:54:32.240	JobHandler::Run jobs 1 blocking jobs 1 handler 0x133f910 <0x76482520>
10	10/21/20 21:54:32.240	JobHandler::Run blocking time 1603342492 job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:5 Id: 99 <0x76482520>
10	10/21/20 21:54:32.241	JobHandler::Run ready to sleep 1 for job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:5 Id: 99 Seconds 20 <0x76482520>
13	10/21/20 21:54:32.268	e[32;2mZWaveSerial::ReceiveData: 0x1 0xe 0x0 0x4 0x0 0xc 0x6 0x31 0x5 0x1 0x2a 0x2 0xbc 0xad 0x0 0xf3 (e[36;1m#######1##*#####e[0m)e[0m <0x76082520>
24	10/21/20 21:54:32.269	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 991 gwf_ach <0x76082520>
13	10/21/20 21:54:32.269	e[32;2mZWaveSerial::SendACK: 0x6 (e[36;1m#e[0m)e[0m <0x76082520>
24	10/21/20 21:54:32.285	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 991 gwf_ach <0x76082520>
24	10/21/20 21:54:32.286	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 991 gwf_ach <0x76082520>
10	10/21/20 21:54:32.286	AlarmManager::AddRelativeAlarm current time 1603342472 delay 0 type 52 <0x76082520>
10	10/21/20 21:54:32.286	AlarmManager::AddAbsoluteAlarm alarm 0xe67e68 entry 0x18cbec0 id 1445 type 52 param=0x1fb3728 entry->when: 1603342472 time: 1603342472 bCancelFirst 0=0 <0x76082520>
31	10/21/20 21:54:32.286	AlarmManager::Run 0xe67e68 notified of a change entry 0x21660a0 id 1419 deleted 0 <0x76c82520>
31	10/21/20 21:54:32.287	AlarmManager::Run 0xe67e68 notified of a change entry 0x17b4988 id 1421 deleted 0 <0x76a82520>
31	10/21/20 21:54:32.287	AlarmManager::Run callback for alarm 0xe67e68 entry 0x18cbec0 type 52 id 1445 param=0x1fb3728 entry->when: 1603342472 time: 1603342472 tnum: 1 slow 0 tardy 0 <0x76a82520>
24	10/21/20 21:54:32.287	ZWaveJobHandler::DoReceivedFrame m_iFrameID 991 gwf_ach node 12 command 0x4 data  <0x76a82520>
24	10/21/20 21:54:32.287	ZWaveJobHandler::DoReceivedFrame m_iFrameID 991 passing to job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:5 Id: 99 auto del: 1 <0x76a82520>
24	10/21/20 21:54:32.288	ZWaveNode::HandlePollUpdate node 12 device 16 class 0x31 command 0x5 m_iFrameID 991/27065744 data 0x1 0x2a 0x2 0xbc (e[34;1m#*##e[0m) <0x76a82520>
06	10/21/20 21:54:32.288	Device_Variable::m_szValue_set device: 16 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: e[35;1mCurrentTemperaturee[0m was: 70.00 now: 70.00 #hooks: 0 upnp: 0 skip: 0 v:0x11ba9a0/NONE duplicate:1 <0x76a82520>
24	10/21/20 21:54:32.288	ZWaveNode::HandlePollUpdate_SensorMultiLevel_MeterReport 0x31 node 12 device 16 child 0/0 cat 17 embed: 0 type 1 rate type 0 is 70.000000 was 70.000000 prec 1 sca 1 size 2 delta -1 previous -1.000000 len 4 <0x76a82520>
24	10/21/20 21:54:32.289	ZWJob_PollNode::ReceivedFrame -end- job job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:5 Id: 99 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 12 status 0 iOK 7 iBadTx 0 iNoReply 0 data 0x1 0x2a 0x2 0xbc (e[34;1m#*##e[0m) <0x76a82520>
10	10/21/20 21:54:32.289	Job::m_tNextRunAttempt_set job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:5 Id: 99 at 1603342474 in 2 seconds waking up was in 20 seconds <0x76a82520>
24	10/21/20 21:54:32.290	ZWJob_PollNode::m_eJobStatus job job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:0 Id: 99 <0x22467e0> m_eJobStatus Queued after 0.181227000 seconds <0x76a82520>
31	10/21/20 21:54:32.290	AlarmManager::Run finish callback for alarm 0xe67e68 entry 0x18cbec0 type 52 id 1445 param=0x1fb3728 entry->when: 1603342472 time: 1603342472 tnum: 1 slow 0 duration 0 <0x76a82520>
10	10/21/20 21:54:32.290	JobHandler::PurgeCompletedJobs force 0 purge job size: 1 blocking 1 delete 9 <0x76482520>
10	10/21/20 21:54:32.300	JobHandler::Run jobs 1 blocking jobs 1 handler 0x133f910 <0x76482520>
10	10/21/20 21:54:32.301	JobHandler::Run blocking time 1603342474 job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:0 Id: 99 <0x76482520>
10	10/21/20 21:54:32.301	JobHandler::Run ready to sleep 1 for job#99 :pollnode #12 dev:16 (0x22467e0) N:12 P:100 S:0 Id: 99 Seconds 2 <0x76482520>
50	10/21/20 21:54:32.403	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() response "eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNobWFjLXNoYTI1NiIsInR5cCI6IkpXVCJ9.eyJyZWdpb24iOiJ3ZXN0dXMyIiwic3Vic2NyaXB0aW9uLWlkIjoiNzk5M2I1YTQ2MDg4NGVjN2IzNjhiYzRkZGIxNWQ1NjgiLCJwcm9kdWN0LWlkIjoiVGV4dFRyYW5zbGF0b3IuRjAiLCJjb2duaXRpdmUtc2VydmljZXMtZW5kcG9pbnQiOiJodHRwczovL2FwaS5jb2duaXRpdmUubWljcm9zb2Z0LmNvbS9pbnRlcm5hbC92MS4wLyIsImF6dXJlLXJlc291cmNlLWlkIjoiL3N1YnNjcmlwdGlvbnMvMWI1MTQwYzgtYzE0My00MTlkLTkyMWEtMTk1YTkyOGUwNTQ1L3Jlc291cmNlR3JvdXBzL01lbGlvcmFIb21lL3Byb3ZpZGVycy9NaWNyb3NvZnQuQ29nbml0aXZlU2VydmljZXMvYWNjb3VudHMvdmVyYXZvaWNlIiwic2NvcGUiOiJodHRwczovL2FwaS5taWNyb3NvZnR0cmFuc2xhdG9yLmNvbS8iLCJhdWQiOiJ1cm46bXMubWljcm9zb2Z0dHJhbnNsYXRvciIsImV4cCI6MTYwMzM0MzA3MiwiaXNzIjoidXJuOm1zLmNvZ25pdGl2ZXNlcnZpY2VzIn0.a54b1wPF-EDj2kkjGW9zMhStCA2u83d1Go71vWxeclE" <0x77734320>
50	10/21/20 21:54:32.406	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() acquired new token "eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNobWFjLXNoYTI1NiIsInR5cCI6IkpXVCJ9.eyJyZWdpb24iOiJ3ZXN0dXMyIiwic3Vic2NyaXB0aW9uLWlkIjoiNzk5M2I1YTQ2MDg4NGVjN2IzNjhiYzRkZGIxNWQ1NjgiLCJwcm9kdWN0LWlkIjoiVGV4dFRyYW5zbGF0b3IuRjAiLCJjb2duaXRpdmUtc2VydmljZXMtZW5kcG9pbnQiOiJodHRwczovL2FwaS5jb2duaXRpdmUubWljcm9zb2Z0LmNvbS9pbnRlcm5hbC92MS4wLyIsImF6dXJlLXJlc291cmNlLWlkIjoiL3N1YnNjcmlwdGlvbnMvMWI1MTQwYzgtYzE0My00MTlkLTkyMWEtMTk1YTkyOGUwNTQ1L3Jlc291cmNlR3JvdXBzL01lbGlvcmFIb21lL3Byb3ZpZGVycy9NaWNyb3NvZnQuQ29nbml0aXZlU2VydmljZXMvYWNjb3VudHMvdmVyYXZvaWNlIiwic2NvcGUiOiJodHRwczovL2FwaS5taWNyb3NvZnR0cmFuc2xhdG9yLmNvbS8iLCJhdWQiOiJ1cm46bXMubWljcm9zb2Z0dHJhbnNsYXRvciIsImV4cCI6MTYwMzM0MzA3MiwiaXNzIjoidXJuOm1zLmNvZ25pdGl2ZXNlcnZpY2VzIn0.a54b1wPF-EDj2kkjGW9zMhStCA2u83d1Go71vWxeclE" <0x77734320>
50	10/21/20 21:54:32.407	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-BenjaminRUS\"><![CDATA[Goodnight moon!]]></voice></speak>" <0x77734320>
50	10/21/20 21:54:32.407	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() system LuaSec version is "0.8" <0x77734320>
50	10/21/20 21:54:32.569	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() response 1, 401, { connection="close", content-length="0", strict-transport-security="max-age=15724800; includeSubDomains", date="Thu, 22 Oct 2020 04:54:32 GMT", server="openresty/1.15.8.2" }, "HTTP/1.1 401 Unauthorized" <0x77734320>
50	10/21/20 21:54:32.570	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() auth fail, arming for retry <0x77734320>
50	10/21/20 21:54:32.571	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() token is expired, fetching new <0x77734320>
50	10/21/20 21:54:32.571	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() "curl -s -k -o - -m 15 -X POST -H 'Content-length: 0' \\\
-H 'Content-type: application/x-www-form-urlencoded' -H 'Ocp-Apim-Subscription-Key: REMOVEDKEY' 'https://westus2.api.cognitive.microsoft.com/sts/v1.0/issueToken'" <0x77734320>
50	10/21/20 21:54:32.882	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() response "eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNobWFjLXNoYTI1NiIsInR5cCI6IkpXVCJ9.eyJyZWdpb24iOiJ3ZXN0dXMyIiwic3Vic2NyaXB0aW9uLWlkIjoiNzk5M2I1YTQ2MDg4NGVjN2IzNjhiYzRkZGIxNWQ1NjgiLCJwcm9kdWN0LWlkIjoiVGV4dFRyYW5zbGF0b3IuRjAiLCJjb2duaXRpdmUtc2VydmljZXMtZW5kcG9pbnQiOiJodHRwczovL2FwaS5jb2duaXRpdmUubWljcm9zb2Z0LmNvbS9pbnRlcm5hbC92MS4wLyIsImF6dXJlLXJlc291cmNlLWlkIjoiL3N1YnNjcmlwdGlvbnMvMWI1MTQwYzgtYzE0My00MTlkLTkyMWEtMTk1YTkyOGUwNTQ1L3Jlc291cmNlR3JvdXBzL01lbGlvcmFIb21lL3Byb3ZpZGVycy9NaWNyb3NvZnQuQ29nbml0aXZlU2VydmljZXMvYWNjb3VudHMvdmVyYXZvaWNlIiwic2NvcGUiOiJodHRwczovL2FwaS5taWNyb3NvZnR0cmFuc2xhdG9yLmNvbS8iLCJhdWQiOiJ1cm46bXMubWljcm9zb2Z0dHJhbnNsYXRvciIsImV4cCI6MTYwMzM0MzA3MiwiaXNzIjoidXJuOm1zLmNvZ25pdGl2ZXNlcnZpY2VzIn0.a54b1wPF-EDj2kkjGW9zMhStCA2u83d1Go71vWxeclE" <0x77734320>
50	10/21/20 21:54:32.883	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() acquired new token "eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNobWFjLXNoYTI1NiIsInR5cCI6IkpXVCJ9.eyJyZWdpb24iOiJ3ZXN0dXMyIiwic3Vic2NyaXB0aW9uLWlkIjoiNzk5M2I1YTQ2MDg4NGVjN2IzNjhiYzRkZGIxNWQ1NjgiLCJwcm9kdWN0LWlkIjoiVGV4dFRyYW5zbGF0b3IuRjAiLCJjb2duaXRpdmUtc2VydmljZXMtZW5kcG9pbnQiOiJodHRwczovL2FwaS5jb2duaXRpdmUubWljcm9zb2Z0LmNvbS9pbnRlcm5hbC92MS4wLyIsImF6dXJlLXJlc291cmNlLWlkIjoiL3N1YnNjcmlwdGlvbnMvMWI1MTQwYzgtYzE0My00MTlkLTkyMWEtMTk1YTkyOGUwNTQ1L3Jlc291cmNlR3JvdXBzL01lbGlvcmFIb21lL3Byb3ZpZGVycy9NaWNyb3NvZnQuQ29nbml0aXZlU2VydmljZXMvYWNjb3VudHMvdmVyYXZvaWNlIiwic2NvcGUiOiJodHRwczovL2FwaS5taWNyb3NvZnR0cmFuc2xhdG9yLmNvbS8iLCJhdWQiOiJ1cm46bXMubWljcm9zb2Z0dHJhbnNsYXRvciIsImV4cCI6MTYwMzM0MzA3MiwiaXNzIjoidXJuOm1zLmNvZ25pdGl2ZXNlcnZpY2VzIn0.a54b1wPF-EDj2kkjGW9zMhStCA2u83d1Go71vWxeclE" <0x77734320>
50	10/21/20 21:54:32.884	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-BenjaminRUS\"><![CDATA[Goodnight moon!]]></voice></speak>" <0x77734320>
50	10/21/20 21:54:32.884	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() system LuaSec version is "0.8" <0x77734320>
50	10/21/20 21:54:33.016	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() response 1, 401, { connection="close", content-length="0", strict-transport-security="max-age=15724800; includeSubDomains", date="Thu, 22 Oct 2020 04:54:33 GMT", server="openresty/1.15.8.2" }, "HTTP/1.1 401 Unauthorized" <0x77734320>
50	10/21/20 21:54:33.017	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() auth fail, arming for retry <0x77734320>
50	10/21/20 21:54:33.017	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() token is expired, fetching new <0x77734320>
50	10/21/20 21:54:33.018	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() "curl -s -k -o - -m 15 -X POST -H 'Content-length: 0' \\\
-H 'Content-type: application/x-www-form-urlencoded' -H 'Ocp-Apim-Subscription-Key: REMOVEDKEY' 'https://westus2.api.cognitive.microsoft.com/sts/v1.0/issueToken'" <0x77734320>
31	10/21/20 21:54:33.100	AlarmManager::Run 0x1682fa0 notified of a change entry 0x1b09a68 id 2322 deleted 0 <0x75031520>
31	10/21/20 21:54:33.101	AlarmManager::Run callback for alarm 0x1682fa0 entry 0x1b09a68 type 7 id 2322 param=0x1a8a240 entry->when: 1603342473 time: 1603342473 tnum: 0 slow 1 tardy 0 <0x75031520>
35	10/21/20 21:54:33.102	LuaInterface::CallFunction_Timer func:HH_message_loop device:83 <0x75031520>
10	10/21/20 21:54:33.102	AlarmManager::AddRelativeAlarm current time 1603342473 delay 1 type 7 <0x75031520>
10	10/21/20 21:54:33.103	AlarmManager::AddAbsoluteAlarm alarm 0x1682fa0 entry 0x21af8c0 id 2323 type 7 param=0x1b8b640 entry->when: 1603342474 time: 1603342473 bCancelFirst 0=0 <0x75031520>
31	10/21/20 21:54:33.103	AlarmManager::Run finish callback for alarm 0x1682fa0 entry 0x1b09a68 type 7 id 2322 param=0x1a8a240 entry->when: 1603342473 time: 1603342473 tnum: 0 slow 1 duration 0 <0x75031520>
50	10/21/20 21:54:33.318	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() response "eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNobWFjLXNoYTI1NiIsInR5cCI6IkpXVCJ9.eyJyZWdpb24iOiJ3ZXN0dXMyIiwic3Vic2NyaXB0aW9uLWlkIjoiNzk5M2I1YTQ2MDg4NGVjN2IzNjhiYzRkZGIxNWQ1NjgiLCJwcm9kdWN0LWlkIjoiVGV4dFRyYW5zbGF0b3IuRjAiLCJjb2duaXRpdmUtc2VydmljZXMtZW5kcG9pbnQiOiJodHRwczovL2FwaS5jb2duaXRpdmUubWljcm9zb2Z0LmNvbS9pbnRlcm5hbC92MS4wLyIsImF6dXJlLXJlc291cmNlLWlkIjoiL3N1YnNjcmlwdGlvbnMvMWI1MTQwYzgtYzE0My00MTlkLTkyMWEtMTk1YTkyOGUwNTQ1L3Jlc291cmNlR3JvdXBzL01lbGlvcmFIb21lL3Byb3ZpZGVycy9NaWNyb3NvZnQuQ29nbml0aXZlU2VydmljZXMvYWNjb3VudHMvdmVyYXZvaWNlIiwic2NvcGUiOiJodHRwczovL2FwaS5taWNyb3NvZnR0cmFuc2xhdG9yLmNvbS8iLCJhdWQiOiJ1cm46bXMubWljcm9zb2Z0dHJhbnNsYXRvciIsImV4cCI6MTYwMzM0MzA3MywiaXNzIjoidXJuOm1zLmNvZ25pdGl2ZXNlcnZpY2VzIn0.shVFhg4whyQN6JOtjpwLCVJ8ULhKqf3lb5UdPgv7MO8" <0x77734320>
50	10/21/20 21:54:33.319	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() acquired new token "eyJhbGciOiJodHRwOi8vd3d3LnczLm9yZy8yMDAxLzA0L3htbGRzaWctbW9yZSNobWFjLXNoYTI1NiIsInR5cCI6IkpXVCJ9.eyJyZWdpb24iOiJ3ZXN0dXMyIiwic3Vic2NyaXB0aW9uLWlkIjoiNzk5M2I1YTQ2MDg4NGVjN2IzNjhiYzRkZGIxNWQ1NjgiLCJwcm9kdWN0LWlkIjoiVGV4dFRyYW5zbGF0b3IuRjAiLCJjb2duaXRpdmUtc2VydmljZXMtZW5kcG9pbnQiOiJodHRwczovL2FwaS5jb2duaXRpdmUubWljcm9zb2Z0LmNvbS9pbnRlcm5hbC92MS4wLyIsImF6dXJlLXJlc291cmNlLWlkIjoiL3N1YnNjcmlwdGlvbnMvMWI1MTQwYzgtYzE0My00MTlkLTkyMWEtMTk1YTkyOGUwNTQ1L3Jlc291cmNlR3JvdXBzL01lbGlvcmFIb21lL3Byb3ZpZGVycy9NaWNyb3NvZnQuQ29nbml0aXZlU2VydmljZXMvYWNjb3VudHMvdmVyYXZvaWNlIiwic2NvcGUiOiJodHRwczovL2FwaS5taWNyb3NvZnR0cmFuc2xhdG9yLmNvbS8iLCJhdWQiOiJ1cm46bXMubWljcm9zb2Z0dHJhbnNsYXRvciIsImV4cCI6MTYwMzM0MzA3MywiaXNzIjoidXJuOm1zLmNvZ25pdGl2ZXNlcnZpY2VzIn0.shVFhg4whyQN6JOtjpwLCVJ8ULhKqf3lb5UdPgv7MO8" <0x77734320>
50	10/21/20 21:54:33.320	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-BenjaminRUS\"><![CDATA[Goodnight moon!]]></voice></speak>" <0x77734320>
50	10/21/20 21:54:33.320	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() system LuaSec version is "0.8" <0x77734320>
50	10/21/20 21:54:33.448	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() response 1, 401, { connection="close", content-length="0", strict-transport-security="max-age=15724800; includeSubDomains", date="Thu, 22 Oct 2020 04:54:33 GMT", server="openresty/1.15.8.2" }, "HTTP/1.1 401 Unauthorized" <0x77734320>
50	10/21/20 21:54:33.450	luup_log:102: Sonos: (tts debug) AzureTTSEngine:say() auth fail, arming for retry <0x77734320>
02	10/21/20 21:54:33.450	e[33;1mluup_log:102: Sonos: AzureTTSEngine:say() authorization failed with Azure servicee[0m <0x77734320>
02	10/21/20 21:54:33.450	e[33;1mluup_log:102: Sonos: (tts) engine Azure Speech Service error: authorization failede[0m <0x77734320>
02	10/21/20 21:54:33.451	e[33;1mluup_log:102: Sonos: (tts) Engine "Azure Speech Service" produced no audioe[0m <0x77734320>

rigpapa · October 22, 2020, 12:49pm

Try using the Curl responder, which you select in the TTS settings tab of the Sonos master device. You’ll need to reload Luup after changing that setting.

From there, since you’re getting a token with no problem but then getting a 401 response code from the service using that token, I would regenerate the key(s). Follow the pinned setup post’s instructions. You name the Translator resource in your post, but you actually want to use the Speech resource, so I’m not sure if anything you selected along the way may have taken down the wrong road.

Also, where it shows your two keys in the Azure UI, is the first part of the hostname the same as the region name? That is, if you are using the westus2 region, the host should be https://westus2.api.cognitive.microsoft.com. If it’s not, let me know.

rywalters · October 22, 2020, 6:31pm

Thanks for your help! I did have the wrong Azure resource created, having followed some other set of instructions other than the pinned post. I created the new resource, which has an endpoint of https://MYRESOURCENAME.cognitiveservices.azure.com/. The location is westus2, but that doesn’t show up in the endpoint url.

I also did not find the Curl responder in the Settings pane of the master Sonos device.

What else should I try?

rywalters · October 22, 2020, 9:01pm

Looks to me like the “secure the controller” option in vera\users & account info\security needs to be disabled in order for a device to access the mp3 file created by the plugin. I’ve made that change and now I can directly access the generated mp3 in my web browser. The Azure connection must be working fine. Still no voice from the Sonos speaker though.

rywalters · October 22, 2020, 9:04pm

Correction. Got it to work!

lakewoodjazz · November 2, 2020, 9:40pm

Hello Patrick
I heard back from Brenton Turner from Microsoft about the Jessa Neural problem the Sonos TTS app was having and he said Microsoft did make a path change for the Jessa Neural voice about the time “non cached TTS” stopped working a while back. He has said it may have affected all the neural voice options and is willing to discuss any errors the changes have made. I have been very busy and don’t mind using the English US female Jessa standard option but thought I would forward you their reply incase you want to discuss updating the neural path if that is helpful for your app and other members of the Vera Community.
His name and contact info is in an email I sent you.

Regards
Thanks for everything you do!
Wilbur

PrincessCleavage · November 8, 2020, 10:53am

Is there currently a problem with Azure TTS? I can not get my system to say more than “Alexa”. If enter “Alex Tell” not TTS occurs but if i enter just “Alexa” TTS works. Perhaps it might be my Azure TTS account or are others having similar experience? Seems it might be only passing cached TTS. I have reset my Azure endpoint keys and still the same issue

rigpapa · November 8, 2020, 4:04pm

I just tried, no problem for me. Before you reset tokens, try simpler things like going back to the default voice. There have been issues with neural voices lately, they’re making changes and it’s a moving target (and I’m not going to chase it).

lakewoodjazz · November 8, 2020, 8:32pm

Hey Rigpapa
Did you get my PM about Brenton from Microsoft Azzure? They want to clear up the
nearal voice problems that they created.

PrincessCleavage · November 9, 2020, 9:42am

I have set to default voice and still no TTS.
Looking the logs i have found the below but i have reset the subscription key so i am not sure what might be causing this:

08	11/09/20 19:25:05.557	JobHandler_LuaUPnP::HandleActionRequest argument Engine=AZURE <0x6be0a520>
02	11/09/20 19:25:09.835	luup_log:1093: Sonos: AzureTTSEngine:say() authorization failed with Azure service <0x774e1320>
02	11/09/20 19:25:09.835	luup_log:1093: Sonos: AzureTTSEngine:say() authorization failed with Azure service <0x774e1320>
02	11/09/20 19:25:09.837	luup_log:1093: Sonos: (tts) engine Azure Speech Service error: authorization failed <0x774e1320>
02	11/09/20 19:25:09.838	luup_log:1093: Sonos: (tts) Engine “Azure Speech Service” produced no audio <0x774e1320>

rigpapa · November 9, 2020, 1:10pm

Make sure you are on the latest hotfix release (pinned post in this topic). Please turn on TTS debug (not plugin or UPnP, just TTS), reload Luup, and re-run your test. Then pull and post your logs; do not redact or cut down the logs; I need the whole thing. You can PM it to me if you’re concerned about privacy issues. Also please remind me if you are on a Plus, Edge, Secure, 3/Lite… I don’t keep everyone’s setups in memory (sheesh, I can barely keep what I need in my memory these days).

But it looks to me like your authorization key was either created for the wrong resource or you have the wrong endpoint.

PrincessCleavage · November 10, 2020, 9:21am

Thanks Rigpapa, It looks like the hotfix has resolved my issue and my previous voice selection is working again. I notice a couple of different setting in the updated version which works as expect now.

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.