Questions about TTS

[randy]

I am on the way out of the house. I'll get the log later. The Master Bedroom is wired and is the source, but the errors have happened with the Living Room as the source. I changed it for the same reason as you wanted me to - to see if it changed with the source. My network:

• Master bedroom = Play 5 with Ethernet
• Living Room = Play 5 WiFi
• Guest room, Office and Shed= Play 3 with WiFi
• Media Room = 2x Play 5 as a stereo pair with WiFi

[dcorsus]

I just enabled time announcements. The first announcement caused the same error and the Living Room and Guest Room speakers were silent. Guest Room is a Play 3, Living Room a Play 5 (Gen 1). The debug logs are attached.

I manually ran the event at 1:13 and there were no errors or skipped clients.

EDIT: sonosdebug.txt is when there was an error and sonosdebug1.txt is when the announcement worked properly.

Hi Randy,

First remark:
I noticed that you have an "empty part" in your announcement string. Can you remove the starting first | character from the announcement (|c:\Program Files (x86)\HomeSeer HS3\Wave\Chime2.wav|Good Afternoon The time is 1:13 PM the temperature is 80.6). Don't think that's the issue but I now understand why I see an announcement starting at 1:00:12 and one at 1:00:14, this is a multiple part announcement, missed that, no biggie.

It would also indicate that it is taking >12 seconds to link which is VERY long, so while you get me the full log, I'll see if I can figure out why it takes so long. Now see next question.

question:


I see a ton of these
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = WifiEnabled
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = BehindWifiExtender
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = ChannelFreq
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = HasConfiguredSSID
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = WirelessLeafOnly
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = WirelessMode
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = IsZoneBridge

If your system is at rest and the debug flag is on, do you see these continuously? If you do, then we need to focus on that because it would mean that the players are really keeping each other really busy and may explain the slowness and refusal of external commands.

Dirk

[randy]

Hi Randy,

First remark:
I noticed that you have an "empty part" in your announcement string. Can you remove the starting first | character from the announcement (|c:\Program Files (x86)\HomeSeer HS3\Wave\Chime2.wav|Good Afternoon The time is 1:13 PM the temperature is 80.6). Don't think that's the issue but I now understand why I see an announcement starting at 1:00:12 and one at 1:00:14, this is a multiple part announcement, missed that, no biggie.

It would also indicate that it is taking >12 seconds to link which is VERY long, so while you get me the full log, I'll see if I can figure out why it takes so long. Now see next question.

question:


I see a ton of these
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = WifiEnabled
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = BehindWifiExtender
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = ChannelFreq
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = HasConfiguredSSID
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = WirelessLeafOnly
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = WirelessMode
Oct-28 1:13:20 PM Sonos DevicePropertiesStateChange for ZonePlayer Media Room: Var Name = IsZoneBridge

If your system is at rest and the debug flag is on, do you see these continuously? If you do, then we need to focus on that because it would mean that the players are really keeping each other really busy and may explain the slowness and refusal of external commands.

Dirk

There is no empty part. HomeSeer does not display SAPI tags when an action is collapsed so you don't see them. I had to put a delay in before the wave file so that it will play. Without a 250ms delay, the wave file starts in the middle. I have to use the piping symbol after the SAPI delay, otherwise the path name is played as text instead of as a wave file. Here is the actual text string in the speak action.

<silence msec='250'/>|c:\Program Files (x86)\HomeSeer HS3\Wave\Chime2.wav|$$DTR:8850:<silence msec='500'/>The time is $$time <silence msec='250'/> the temperature is $$DVR:3695:

There is no Sonos activity whatsoever logged in the time between the hourly time and temperature announcements. The only Sonos activity in the HS log is relative to these announcements. While I am testing this, we are not using any of the speakers. We don't control them with the app or with HomeSeer. The only thing we we do is speak the time and temperature at the top of the hour. All other speak events are disabled for now.

Also understand that about half of the time, the speak action works perfectly, without an error. If I send several announcements to Sonos in rapid sequence, one or more of them may be skipped. If I make sure the announcements are spaced by at least a minute, there is no problem. For obvious reasons, it is difficult to control random announcements so that they are not concurrent, so I am looking into a programmatic method of holding speak events so that there is time between them.

The log file from the moment the speak action is called is attached.

[dcorsus]

I had to put a delay in before the wave file so that it will play. Without a 250ms delay, the wave file starts in the middle.

... also strange ....

So far no smoking gun but I'm zooming in to a 4 second gap where pretty much nothing happens, very strange.

Any chance to download the attached file, stop HS3, put it in your <HS root>, and try to recreate the issue. If you can recreate, get the whole log again. I wonder whether I have a SW loop in a particular routine so I added some more logging in that specific subroutine.

Thanks

Dirk

[randy]

... also strange ....

So far no smoking gun but I'm zooming in to a 4 second gap where pretty much nothing happens, very strange.

Any chance to download the attached file, stop HS3, put it in your <HS root>, and try to recreate the issue. If you can recreate, get the whole log again. I wonder whether I have a SW loop in a particular routine so I added some more logging in that specific subroutine.

Thanks

Dirk

I will do this tomorrow. Which issue do you want me to recreate? The need for the delay on a wave file or the error where some members of a linkgroup are silent due to an error?

[dcorsus]

I will do this tomorrow. Which issue do you want me to recreate? The need for the delay on a wave file or the error where some members of a linkgroup are silent due to an error?

The initial issue of getting errors when you issue an announcement + some players not participating.

Dirk

[randy]

I installed the new executable this morning. So far there have been no errors other than one unrelated to the original problem when I manually ran the time announcement.

Oct-29 11:26:14 AM Sonos Error GetVolumeLevel called for Zone - Media Room which was linked to RINCON_000E585BF1AA01400 but ended in Error: Object reference not set to an instance of an object.

I made a couple of changes to the time announcement. I removed some verbiage because it was unnecessary. I also removed the 250 millisecond delay at the beginning to see if the chime wave file ever gets partially cut off. With two event driven announcements and 4 or 5 manually run, there has been no problem with the wave file or errors as before.

I will post back if/when the error occurs.

[dcorsus]

I installed the new executable this morning. So far there have been no errors other than one unrelated to the original problem when I manually ran the time announcement.

I made a couple of changes to the time announcement. I removed some verbiage because it was unnecessary. I also removed the 250 millisecond delay at the beginning to see if the chime wave file ever gets partially cut off. With two event driven announcements and 4 or 5 manually run, there has been no problem with the wave file or errors as before.

I will post back if/when the error occurs.

How's the linking time? If it gets to 10~12 seconds again, make me a trace
Dirk

[randy]

How's the linking time? If it gets to 10~12 seconds again, make me a trace
Dirk

The total time from manually triggering the speak event until sound comes out of the speakers is always 6-7 seconds. It can take even longer if I send a second announcement too soon after the first. I am not even trying to find or replicate that.

Attached is the logging from when it failed again today. This time it was only the living room client. Note that the network configuration remains the same. The Master bedroom is the source and is the speaker that is hardwired to the network.

Later today I may reconfigure the layout to pure WiFi and change the source speaker, just for testing.

[dcorsus]

The total time from manually triggering the speak event until sound comes out of the speakers is always 6-7 seconds. It can take even longer if I send a second announcement too soon after the first. I am not even trying to find or replicate that.

Attached is the logging from when it failed again today. This time it was only the living room client. Note that the network configuration remains the same. The Master bedroom is the source and is the speaker that is hardwired to the network.

Later today I may reconfigure the layout to pure WiFi and change the source speaker, just for testing.

Nope nothing out of the ordinary, perhaps time to start looking at the connectivity.

Here's a command that can help

http://192.168.2.211:1400/support/review. Check the Ethernet port statistics of each player and check other items

Dirk

[randy]

Nope nothing out of the ordinary, perhaps time to start looking at the connectivity.

Here's a command that can help

http://192.168.2.211:1400/support/review. Check the Ethernet port statistics of each player and check other items

Dirk

For now, it is back to a pure wireless network - no Ethernet connection. I am now using the Living Room as a source. My 2:00 announcement resulted in a single error:

Oct-29 2:00:18 PM Sonos Error ERROR in SetTransportState for zoneplayer = Living Room with UPNP Error = Read only tag / Transport is locked / Access denied. Error = MyUPnPService.InvokeAction for ServiceID = http://192.168.2.211:1400/xml/AVTransport1.xml while sending Action = Pause for URI = http://192.168.2.211:1400/MediaRende...nsport/Control and Request = 0 UPNP Error = faultcode = s:Client, faultstring = UPnPError, detail = 701 with error = The remote server returned an error: (500) Internal Server Error.

The announcement to the Living Room speaker was played, despite the error. Now I am going to reboot all of the players.

I am not sure what you want me to look for on the page you suggested. I don't immediately see anything different or unusual on the Living Room speaker. I am also not sure what connectivity issue would allow the Sonos devices to work 100% of the time with the Sonos app (PC and iOS), yet fail around 25-50% of the time from the plug-in. The players that fail have been random, usually Living Room (PLay 5), Guest Room (Play 3) and Media Room (Play 5 stereo pair), but if I look at the logs, every speaker has been affected at least once.

[randy]

For now, it is back to a pure wireless network - no Ethernet connection. I am now using the Living Room as a source. My 2:00 announcement resulted in a single error:

Oct-29 2:00:18 PM Sonos Error ERROR in SetTransportState for zoneplayer = Living Room with UPNP Error = Read only tag / Transport is locked / Access denied. Error = MyUPnPService.InvokeAction for ServiceID = http://192.168.2.211:1400/xml/AVTransport1.xml while sending Action = Pause for URI = http://192.168.2.211:1400/MediaRende...nsport/Control and Request = 0 UPNP Error = faultcode = s:Client, faultstring = UPnPError, detail = 701 with error = The remote server returned an error: (500) Internal Server Error.

The announcement to the Living Room speaker was played, despite the error. Now I am going to reboot all of the players.

I am not sure what you want me to look for on the page you suggested. I don't immediately see anything different or unusual on the Living Room speaker. I am also not sure what connectivity issue would allow the Sonos devices to work 100% of the time with the Sonos app (PC and iOS), yet fail around 25-50% of the time from the plug-in. The players that fail have been random, usually Living Room (PLay 5), Guest Room (Play 3) and Media Room (Play 5 stereo pair), but if I look at the logs, every speaker has been affected at least once.

This is still an ongoing problem. I decided to leave it alone for a while, because I decided to make a complete change to my Sonos architecture. When I first encountered and posted these errors, I had a Play 1 a few PLay 5 (gen1) and a few Play 3. The errors are consistent and persistent, if I use an Ethernet connection to one of my devices to create the SonosNet. If I go to a full WiFi setup, the errors do not seem to occur. I have attached a pdf showing the errors. As you can see it is not always the same player. Also of note is that just after 10:00AM on December 31 I reverted to pure WiFi. The log capture was through about 2:00 on January 2, 2017. There has not been a single error since i went to WiFi. The errors in the log are not so bothersome, but when they occur we may get a truncated announcement, no announcement whatsoever or a few speakers that do not play the announcement. We need to count on the announcements. The problem is that when we use a pure WiFi Sonos topology we see a noticeable impact on network performance on laptops, iPads, etc that use WiFi. With a SonosNet using a single Ethernet connection our network seems unaffected by Sonos - which is how it should be.

The problem has also been persistent regardless of the device used as the Ethernet connection. It started on a PLay 5 (gen 1), then another, then a Play 5 (Gen 2). I have since gone to all ZP120s and a handful of Play 1s. The error remains in any Ethernet connected arrangement.

I will post later on why I made the changes, what the changes were and how it works now. Some might find it interesting.

I would like some suggestions as to what I can do to try to resolve this. As I said it is persistent and predictable.

The Sonos network performs flawlessly with either type of network topology, as long as I control it from their apps.

Here are screenshots of my linkgroups, players and a pdf of the errors recently.

[dcorsus]

This is still an ongoing problem. I decided to leave it alone for a while, because I decided to make a complete change to my Sonos architecture. When I first encountered and posted these errors, I had a Play 1 a few PLay 5 (gen1) and a few Play 3. The errors are consistent and persistent, if I use an Ethernet connection to one of my devices to create the SonosNet. If I go to a full WiFi setup, the errors do not seem to occur. I have attached a pdf showing the errors. As you can see it is not always the same player. Also of note is that just after 10:00AM on December 31 I reverted to pure WiFi. The log capture was through about 2:00 on January 2, 2017. There has not been a single error since i went to WiFi. The errors in the log are not so bothersome, but when they occur we may get a truncated announcement, no announcement whatsoever or a few speakers that do not play the announcement. We need to count on the announcements. The problem is that when we use a pure WiFi Sonos topology we see a noticeable impact on network performance on laptops, iPads, etc that use WiFi. With a SonosNet using a single Ethernet connection our network seems unaffected by Sonos - which is how it should be.

The problem has also been persistent regardless of the device used as the Ethernet connection. It started on a PLay 5 (gen 1), then another, then a Play 5 (Gen 2). I have since gone to all ZP120s and a handful of Play 1s. The error remains in any Ethernet connected arrangement.

I will post later on why I made the changes, what the changes were and how it works now. Some might find it interesting.

I would like some suggestions as to what I can do to try to resolve this. As I said it is persistent and predictable.

The Sonos network performs flawlessly with either type of network topology, as long as I control it from their apps.

Here are screenshots of my linkgroups, players and a pdf of the errors recently.

Randy, can you draw or describe your network setup. It smells almost 100% as a network loop issue. Make sure rstp is enabled on all involved switches. Are using VLANs anywhere? Perhaps devices that have 2 Ethernet connections for "redundancy"?

There used to be a ton of postings about SONOS and RSTP issues but that was a long time ago. I struggled with the same issue a long time ago (in previous house) and ended up taking one specific player off wired Ethernet. I always suspected that the WAP I was using might not be forwarding RSTP as it should have or participate as it should have. Perhaps you don't see it on the Sonos APPS but that doesn't mean it isn't there.

I'll look again at all the statistics you can pull out of Sonos and see if there is something of use. I know there is a topology map somewhere but seem to recall to hard for me to interpret. In the past when people had issues, they would call Sonos support who subsequently would log in remotely and usually force a port somewhere from forwarding to blocking to avoid these network loops. Perhaps you can give Sonos a call and see if they can remotely diagnose the issue or at least give us some pointers to look at.

Is the PI running in a VM? Does this HS PC have multiple Ethernet ports or perhaps a wired and wireless port? Other devices that have wired and wireless ports active at the same time?

Dirk

[dcorsus]

command is http://192.168.xx.xx:1400/support/review and then click on Network Matrix. As I wrote above, not sure myself how to interpret but a Sonos support person would.
Dirk

[randy]

Randy, can you draw or describe your network setup. It smells almost 100% as a network loop issue. Make sure rstp is enabled on all involved switches. Are using VLANs anywhere? Perhaps devices that have 2 Ethernet connections for "redundancy"?

There used to be a ton of postings about SONOS and RSTP issues but that was a long time ago. I struggled with the same issue a long time ago (in previous house) and ended up taking one specific player off wired Ethernet. I always suspected that the WAP I was using might not be forwarding RSTP as it should have or participate as it should have. Perhaps you don't see it on the Sonos APPS but that doesn't mean it isn't there.

I'll look again at all the statistics you can pull out of Sonos and see if there is something of use. I know there is a topology map somewhere but seem to recall to hard for me to interpret. In the past when people had issues, they would call Sonos support who subsequently would log in remotely and usually force a port somewhere from forwarding to blocking to avoid these network loops. Perhaps you can give Sonos a call and see if they can remotely diagnose the issue or at least give us some pointers to look at.

Is the PI running in a VM? Does this HS PC have multiple Ethernet ports or perhaps a wired and wireless port? Other devices that have wired and wireless ports active at the same time?

Dirk

It does sound like a loop, but Sonos claims to have that solved. OK here is the data. 90% of the time my HS server is a physical machine a Supermicro Xeon server running windows 10 Pro. It has 3 NICs. The first is for IPMI, assigned with a static IP and is completely isolated from the operating system, it is only for a remote management console. Some of the Supermicros have 2 nics and one can share duties between IPMI and the operating system. This is not one of those models, the IPMI NIC is dedicated. The second NIC is what I use for connection to the network. The third NIC is disabled and not connected, I did that a year ago when I was running into different HS related network problems. Long story short, the problems were the way that Z-Nets failed to reconnect after a brief loss of connection. HS finally solved that problem in August, but I have never enabled the second OS NIC. This server has no WiFi.

About 10% of the time HS may be running on a VM, still Windows 10 PRO. The server that hosts the VM is identical to the one above, except it runs Windows Server 2012r2 and hosts the HS VM under Hyper-v. This server uses both O/S NICs, one dedicated to the server O/S and the second to a Hyper-v virtual switch that is not shared with the host operating system. These symptoms with Sonos are the same and repeatable in either VM or physical machine configuration.

My network:

No VLANs.

Netgear R7000 connected to the WAN with a 4 -port switch built in. One port goes to a Cisco SG200-50P 50-Port Gigabit PoE Smart Switch and a second port goes to a SG200-26 26-Port Gigabit Smart Switch. Each run from the respective switches goes to an individual item with a single NIC. There are no devices with dual NICs. All WiFi is handled by the R7000, as is port forwarding, DHCP and DHCP reservations.

RSTP is enabled by default on the switches, and remains enabled.

My Sonos system never has more than a single Ethernet connection, the one Zone Player or Speaker that is connected by ethernet then becomes the host for SonosNet. The configurations I have tried that all failed were an Ethernet connection to a single Play 5 (Gen 1), then back to WiFi, then to a PLay 5 (Gen 2), then back to WiFi. The first play 5 was connected to the 50-port switch , the second Play 5 to a different port on the same switch. Most recently it was the Zone Player connected to the 26-port switch. There has never been more than one Sonos device connected to Ethernet, the rest are all on the SonosNet established by the one connected device. The errors and problems described in the posts above have existed in any of the 45 or 5 configurations with an Ethernet connection and I have not seen them once in a pure WiFi environment.

While I agree it seems like a Spanning Tree issue, understand that I have zero network issues of any kind, no matter how the Sonos is configured. Sonos works perfectly from an Android, iOS or PC application regardless of whether it is a pure WiFi or a SonosNet from an Ethernet connected device. We are able to stream full 1080P video from 3 different Blu-ray rips to 3 different HTPCs without even a blip of problems, all this while 13 2-4 megapixel security cameras (wired) are recording 8fps video. I record about 750gb of video per day. Sonos never has a single interruption in audio and 80% of the time announcements work fine, even with the single Ethernet connection. There are random announcements through the day and at the top of the hour between 7:00AM and 10:00PM it announces time, temperature and humidity. Most of the time it works, when it doesn't it is always the same error on a single random Sonos device "UPNP Error = Read only tag / Transport is locked / Access denied".

The only time any problem arises is with TTS through your plug-in as a linkgroup is created and an announcement is sent. During the last three months, I have rebuilt the entire portion of Sonos control for HS from scratch. Manually recreated linkgroups, etc. Also, only 1 play 1 remains from my first iteration, the rest of the Sonos equipment has been replaced.

Here is a screenshot of the STP setup from one of my switches, they are both configured exactly the same. IO suppose I could enable loopback guard, but there is no chance at all that I have an Ethernet loopback.