Since I have upgraded from 2.4.0 snapshot to 2.4.0 stable I have a strange behaviour with the sonos binding:
When I switch off the power of the sonos amp and switch it on I see in the openhab log with stable 2.4.0 and latest snapshot:
2019-01-01 14:20:07.058 [hingStatusInfoChangedEvent] - 'sonos:CONNECTAMP:celler' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (COMMUNICATION_ERROR): Der UPnP
Speaker RINCON_000E58D0E73001400 ist nicht registriert.
2019-01-01 14:20:08.189 [hingStatusInfoChangedEvent] - 'sonos:CONNECTAMP:celler' changed from OFFLINE (COMMUNICATION_ERROR): Der UPnP Speaker RINCON_000E58D0E73001400
ist nicht registriert. to ONLINE
2019-01-01 14:20:08.211 [hingStatusInfoChangedEvent] - 'sonos:CONNECTAMP:celler' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Der Sonos Speaker RINCON_000E58D
0E73001400 ist nicht im Netzwerk verfĂŒgbar.
It is ONLINE and immediately it goes OFFLINE.
Only a restart of openhab helps to get it online (or I wait 10 minutes). But when I switch off the power and switch it on I have the same behaviour again.
The old and correct behaviour (2.4.0 snapshot):
2019-01-01 14:08:19.986 [hingStatusInfoChangedEvent] - 'sonos:CONNECTAMP:RINCON_000E58D0E73001400' changed from OFFLINE (COMMUNICATION_ERROR): Der Sonos Speaker RINCON
_000E58D0E73001400 ist nicht im Netzwerk verfĂŒgbar. to OFFLINE (COMMUNICATION_ERROR)
2019-01-01 14:08:22.940 [hingStatusInfoChangedEvent] - 'sonos:CONNECTAMP:RINCON_000E58D0E73001400' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
I have already posted this in this thread, but in the meantime I am not sure if this "[WARN ] [e.jetty.util.thread.ThreadPoolBudget] " problem belongs to my problem.
I can confirm the issue.
Considering only the logs and the code, my analysis is that the UPnP discovery code notifies the binding that the Sonos device is present; then any invocation of the action DeviceProperties:GetZoneInfo by the binding is failing !
It looks like a bug in the jUPnP library.
I will investigate a little more.
The problem is that error: âCurrent state of service prevents invoking that actionâ.
What I can see 4 seconds before in the logs:
22:05:26.332 [DEBUG] [covery.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:PLAY5' thing with UDN 'RINCON_000E588EAE6601400'
22:05:26.329 [DEBUG] [sport.upnp.internal.UpnpIOServiceImpl] - A GENA subscription 'ZoneGroupTopology' for device 'uuid:RINCON_000E588EAE6601400' was ended
22:05:26.329 [DEBUG] [sport.upnp.internal.UpnpIOServiceImpl] - A GENA subscription 'AudioIn' for device 'uuid:RINCON_000E588EAE6601400' was ended
22:05:26.323 [DEBUG] [sport.upnp.internal.UpnpIOServiceImpl] - A GENA subscription 'DeviceProperties' for device 'uuid:RINCON_000E588EAE6601400' was ended
22:05:26.347 [DEBUG] [sport.upnp.internal.UpnpIOServiceImpl] - Device 'RINCON_000E588EAE6601400' reachability status changed to 'false'
As soon as the device is detected through UPnP, some subscriptions are ended and the current state is first set to not reachable.
4 seconds later, the state is set to reachable but action invocation fails and I donât know why.
I think it could be a problem either in the jUPnP library.
Thanks to @Lolodomo I got the information that the jUPnP bundle is somehow broken - see ESH issue above.
So I was able to implement a hopefully temporary () workaround:
I implemented a rule which always restarts the jUPnP bundle when the sonos Thing goes offline.
This is working because the first time after a power on the sonos thing is always recognized immediately. The problem starts with the next power off/on. You then can either restart openhab or just restart the jUPnP bundle - that fixes the behaviour.
General question: How is the status regarding a possible jUPnP fix, does anybody know?
I would be interessted in some more details about your workaround - is there a chance you share it here? I guess an offical fix will definetly take some time and I would like to see if this could help me too.
Iâm in the same situation like you, since I updated to OH2.4 my Sonos speakers can no longer be controlled in a stable way via Basic UI.
My log is flooded ramdonly with below errors for any of my speakers:
[hingStatusInfoChangedEvent] - âsonos:PLAY3:XYZâ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): The Sonos player RINCON_XBE932481F6601400 is not available in local network.
[hingStatusInfoChangedEvent] - âsonos:PLAY3:XYZâ changed from OFFLINE (COMMUNICATION_ERROR): The Sonos player RINCON_XBE932481F6601400 is not available in local network. to ONLINE
It looks even like the error message is partially upside down with that âto ONLINEâ statement at the end of the string.
rule "jupnp bundle restart"
when
Thing "sonos:CONNECTAMP:amp" changed from ONLINE to OFFLINE
then
executeCommandLine("sudo -u openhab ssh -p 8101 -i /home/openhabian/rsh/openhab.id_rsa openhab@localhost bundle:restart org.jupnp",6000)
end
I am using openhabian on an raspberry pi 3.
That the rule is able to call the karaf call without entering a password you have to generate a ssh key.
I used this tutorial
I created a directory called rsh: mkdir /home/openhabian/rsh
enter the directory and generate ssh key: sudo -u openhab ssh-keygen -t rsa -f openhab.id_rsa
Add content of the public key file to /srv/openhab2-userdata/etc/keys.properties openhab=<yourkey>,_g_:admingroup
Additionally to the tutorial I had to do the following, that I was able to restart the bundle without entering a password:
First reset root password: sudo passwd root
Next, add openhab to sudoers file: su - visudo
Finally add openhab user to sudoers file: add: openhab ALL=(ALL) ALL
Then I was able to restart the bundle from the rule
Iâm having a similar but slightly different issue. My sonos speakers come on relatively quickly. After a few days they all go offline and stay offline. A reload of org.jupnp as mentioned above resolves the issue for a few days. I have a rule now that monitors the thing state as mentioned above and reloads it when the crash happens. I noticed this happened when I moved from 2.5.0M1 to one of the recent nightly builds.
jwiseman
(Mr. Wiseman (OH 4.2 Snapshot on Pi4))
21
I decided to turn on jupnp debugging for a few minutes while my Sonos PlayBar was in a bad state. Every second I get this message set:
2020-02-02 13:40:34.657 [DEBUG] [org.jupnp.transport.Router ] - Sending via TCP unicast stream: (OutgoingActionRequestMessage) POST http://REDACTED:1400/DeviceProperties/Control
2020-02-02 13:40:34.657 [DEBUG] [org.jupnp.transport.spi.StreamClient] - Will not attempt request because it failed in the last 600 seconds: (OutgoingActionRequestMessage) POST http://REDACTED:1400/DeviceProperties/Control
Then, every 600 seconds I get:
2020-02-02 13:44:11.804 [DEBUG] [org.jupnp.transport.Router ] - Sending via TCP unicast stream: (OutgoingActionRequestMessage) POST http://REDACTED:1400/DeviceProperties/Control
2020-02-02 13:44:21.804 [INFO ] [org.jupnp.transport.spi.StreamClient] - Timeout of 10 seconds while waiting for HTTP request to complete, aborting: (OutgoingActionRequestMessage) POST http://REDACTED:1400/DeviceProperties/Control
2020-02-02 13:54:22.222 [DEBUG] [org.jupnp.transport.Router ] - Sending via TCP unicast stream: (OutgoingActionRequestMessage) POST http://REDACTED:1400/DeviceProperties/Control
2020-02-02 13:54:32.222 [INFO ] [org.jupnp.transport.spi.StreamClient] - Timeout of 10 seconds while waiting for HTTP request to complete, aborting: (OutgoingActionRequestMessage) POST http://REDACTED:1400/DeviceProperties/Control
A CURL (with POST) to the URL gives me:
<s:Envelope xmlns:s=âhttp://schemas.xmlsoap.org/soap/envelope/â s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><s:Fault>s:ClientUPnPError401</s:Fault></s:Body></s:Envelope>
NOTE: I get this from ALL Sonos speakers I have. Iâm not sure if Iâm missing something on the query to get a bad authentication.
I have verified that I have <1ms ping times to the bar (no packet loss) and they are on the same network so the Sonos TTL=1 is not an issue here.
I let this go for about an hour with the same result. Then I restarted OH2. All of my speakers immediately came online and are stable. Given this, I do NOT believe the issue to be the Sonos itself as a ârandomâ restart of OH2 should not clear out the issue on the Sonos.
Going through the debug of the OH2 restart it looks like OH2 effectively registers as an endpoint with the Sonos speaker. My assumption (since I canât just make one fail at will) is that this registration becomes invalid at some point. Assuming that this theory is correct, at this point I would suggest that the Sonos binding be modified to detect this issue and âself healâ by restarting the registration process with that specific speaker when the HTTP request to the control URL fails to reply.
) workaround: