Sonos things are offline

yes, I have it on 1078. However, it does come online now, but I get quite a lot of error messages:

‘sonos:CONNECT:RINCON_949F3E20’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): The Sonos player RINCON_949F3E20 is not available in local network.

and:

[ERROR] [rg.jupnp.protocol.sync.ReceivingEvent] - Invalid subscription ID, no active subscription: (IncomingEventRequestMessage) NOTIFY /upnpcallback/dev/RINCON_000E58D12EBC01400/svc/upnp-org/AudioIn/event/cb SEQUENCE: 0

I think any UPnP call can randomly fail with the new library. So the problem could happen when you request a command from OH like a pause command for example.

I’m trying to DEBUG sonos because of the same issue and have added this to “org.ops4j.pax.logging.cfg”:

Custom Loggers

log4j2.logger.sonos.name = org.openhab.binding.sonos
log4j2.logger.sonos.level = DEBUG
log4j2.logger.sonos.additivity = false
log4j2.logger.sonos.appenderRefs = sonos
log4j2.logger.sonos.appenderRef.sonos.ref = sonos

Appenders configuration

Custom Appenders

log4j2.appender.sonos.name = sonos
log4j2.appender.sonos.type = RollingRandomAccessFile
log4j2.appender.sonos.fileName = /var/log/openhab2/sonos.log
log4j2.appender.sonos.filePattern = /var/log/openhab2/sonos.log.%i
log4j2.appender.sonos.immediateFlush = true
log4j2.appender.sonos.append = true
log4j2.appender.sonos.layout.type = PatternLayout
log4j2.appender.sonos.layout.pattern = %d{dd-MMM-yyyy HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - %m%n
log4j2.appender.sonos.policies.type = Policies
log4j2.appender.sonos.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.sonos.policies.size.size = 10MB
log4j2.appender.sonos.strategy.type = DefaultRolloverStrategy
log4j2.appender.sonos.strategy.max = 10

But it doesn’t log anything :frowning: The file “sonos.log” is there but keeps empty. Tried the same with homematic instead of sonos and this is working as expected…so…cfg-file should be OK. I’m lost. Any ideas what’s wrong here?

Thanks
Michael

I see that @Kai posted this comment in another thread…does anyone know if the incorporated changes from ESH fix the SONOS issue?

no, the issue still exists. i did the update and this is the status of my sonos devices:

image

I’m curious as to why some of your SONOS units are online and others are not?

It happens randomly… :wink: And then it goes offline.

Hello,
with 2.1.0 release build, Sonos devices are well discovered , i haven’t go further

The problem is clearly in library jUPnP and the result of the move from v2.2 to v2.3.
We have to be patient and wait for a fix in that library. If noone is able or interested to fix it, I hope there will be a brillant decision by the staff to revert to v2.2.
More you will be to complain, more it could help Kai to take the right decision.

Thanks - yes, otherwise I’ll just have to stick to the old openHAB snapshot. I use Sonos for notifications around the house, so without a functional binding my system is essentially broken.

Dan

No need to blindly update and hope that anything has changed. If you are interested in the progress, simply follow the issue. As long as it is not solved, you should not expect that any newer openHAB build will have it miraculously fixed.

Hi,
I just upgraded to build #1084, since that would fix the Sonos issue. First of all, thanks Kai for all your time on this!

But now I noticed that I’m unable to send any commands to my Sonos anymore (before it worked in 50% of the cases). It least I can now say the behaviour is more consistent. :slight_smile:

Sending any command (play, pause, increase/decrease volume) does not work. Also reading current track is not working anymore.

I tried restarting OH, without success. I also removed my two Sonos things and added them again. No result. My Things and Items are associated correctly.

Is there anything else I can try?

Openhab.log doesn’t show anything strange. New elements I noticed in my log compared to previous snapshot version are:

2017-11-19 09:45:33.377 [INFO ] [thome.model.lsp.internal.ModelServer] - Language Server started on port 5007
2017-11-19 09:45:46.879 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=52, service.id=149, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201711182209 [111])] due to timeout!

Not sure if that is related.

Sonos binding is up-to-date. Karaf:

207 | Active   |  80 | 0.9.0.201711182209     | Sonos Binding

before I upgrade: is anyone else having Sonos problems with the new snapshot?

Hi Dan,

The Sonos-issue I was having by upgrading to #1084 was not a Sonos specific issue. Actually, none of my bindings worked anymore. :thinking: I was able to find the solution (read here). So currently, I have a reliable Sonos binding. :slight_smile: However, I would recommend to read that entire topic (not just my post), since various people had some trouble with this upgrade.

thanks!

On OH 2.3.0, Snapshot #1281 my things still go offline:

2018-05-20 09:21:30.267 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:PLAY1' thing with UDN 'RINCON_949F3E050F7XXXXXX'
2018-05-20 09:21:30.268 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:21:30.345 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Created a DiscoveryResult for device '192.168.1.253 - Sonos PLAY:1' with UDN 'RINCON_949F3E050F7XXXXXX'
2018-05-20 09:21:30.373 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscribing to service DeviceProperties...
2018-05-20 09:21:30.426 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscribing to service AVTransport...
2018-05-20 09:21:30.456 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscribing to service ZoneGroupTopology...
2018-05-20 09:21:30.507 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscribing to service GroupManagement...
2018-05-20 09:21:30.562 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscribing to service RenderingControl...
2018-05-20 09:21:30.619 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscribing to service AudioIn...
2018-05-20 09:21:30.656 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscribing to service HTControl...
2018-05-20 09:21:30.714 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service RenderingControl succeeded
2018-05-20 09:21:30.748 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service GroupManagement succeeded
2018-05-20 09:21:30.780 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service ZoneGroupTopology succeeded
2018-05-20 09:21:30.836 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service AVTransport succeeded
2018-05-20 09:21:30.869 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service DeviceProperties succeeded
2018-05-20 09:21:52.221 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:22:52.328 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:23:52.436 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:24:52.572 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:25:52.680 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:26:52.783 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:27:52.891 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:28:53.006 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:29:53.109 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:30:53.215 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:31:53.324 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:32:53.440 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:33:53.560 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:34:53.667 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:35:53.016 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service AVTransport succeeded
2018-05-20 09:35:53.066 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service RenderingControl succeeded
2018-05-20 09:35:53.777 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:36:32.038 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service AVTransport succeeded
2018-05-20 09:36:32.082 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service RenderingControl succeeded
2018-05-20 09:36:53.883 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:37:54.017 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:38:54.154 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:39:54.290 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:40:54.410 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:41:54.523 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:42:54.670 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:43:54.767 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:44:54.881 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:45:55.001 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:46:55.110 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:47:55.229 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:48:55.359 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:49:55.468 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:50:54.321 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service AVTransport succeeded
2018-05-20 09:50:54.358 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E050F7XXXXXX: Subscription to service RenderingControl succeeded
2018-05-20 09:50:55.589 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:51:31.302 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:PLAY1' thing with UDN 'RINCON_949F3E050F7XXXXXX'
2018-05-20 09:51:55.690 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:51:55.710 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3E050F7XXXXXX not yet registered
2018-05-20 09:52:55.747 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:52:55.770 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3E050F7XXXXXX not yet registered
2018-05-20 09:53:55.798 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:53:55.820 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3E050F7XXXXXX not yet registered
2018-05-20 09:54:55.848 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2018-05-20 09:54:55.868 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3E050F7XXXXXX not yet registered

The thing comes online after manually triggering thing discovering. Then goes offline 30 to 90 mins later.

Ok. It always happens after 30 mins now. Always after the device has been discovered a second time. Is there any possibility to disable UPnP auto-discovery?

Edit: The device has an MaxAge set to 1800s. After that the RemoteDevice expires and is removed from Registry.RemoteItems, which seems ok. But it is not added after the device was rediscovered, unless the disovery was triggered manually. I don’t have much knowledge of UPnP, should the expiry timer reset after each communication with the device? That is not the case.

I believe there are two problems.

The first one is probably very special in my setup. My Sonos is in another subnet than my OH instance (192.168.1.253 and 192.168.0.58). The OH machine has two network interfaces (eth0 and eth0.105).

Using tcpdump -i eth0 -A dst 239.255.255.250 and port 1900 I can see the alive messages from the sonos device. I see alive messages from other devices as well. I set org.jupnp.transport.spi.MulticastReceiver to DEBUG logging and now the strange thing happens: I only see alive messages from devices in the 192.168.0.0 network, not from the 192.168.1.1 network.

I see the same behaviour in a test program, if I use s.joinGroup(multicastAddress, networkInterface); ,which is done in MulticastReceiverImpl of jupnp. If I use s.joinGroup(InetAddress.getByName(group)); I can see all messages. I have no idea where to go from here. @Kai, @sjka any suggestions?

The second problem is that if the device gets removed, from RemoteItems it never gets added back again, even if the device is discovered automatically later on. And the service subscriptions don’t get removed.

Finally I solved it. After I found out that even with s.joinGroup(InetAddress.getByName(group)); some packets are lost and that waiting a long time in rare cases s.joinGroup(multicastAddress, networkInterface); catches packets (not from my Sonos but from UPnP devices in the other network), I did have a closer look with Wireshark on the packets. The problem seems to be that Sonos sends the packets with a low TTL. After increasing the TTL on the router with a mangle rule I now see all Sonos traffic. Shall we add a not to the binding documentation that the low TTL might cause problems with multicast traffic across subnet borders?

Best, Jay