[SamsungTV] Binding does not recover from communication error (Legacy Mode)

[MHerbst]

Expected Behavior

After a communication error happened the binding should detect when the device is online again and work again correctly.

Current Behavior

Binding does not recover from communication error and even a restart of the bundle does not completely solve the problem.

Possible Solution

Restart openHAB (not really a solution)

Steps to Reproduce (for Bugs)

1. Turned the TV off
2. Binding remains in state "Online"
3. Tried to send a comand to the TV => Thing state changed to state "Offline - Communication Error"

2020-02-22 20:41:45.093 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Error was reported: Cannot connect to remote control service
org.openhab.binding.samsungtv.internal.protocol.RemoteControllerException: Connection failed
	at org.openhab.binding.samsungtv.internal.protocol.RemoteControllerLegacy.openConnection(RemoteControllerLegacy.java:98) ~[?:?]
	at org.openhab.binding.samsungtv.internal.service.RemoteControllerService.start(RemoteControllerService.java:228) ~[?:?]
	at org.openhab.binding.samsungtv.internal.handler.SamsungTvHandler.startService(SamsungTvHandler.java:291) ~[?:?]
	at org.openhab.binding.samsungtv.internal.handler.SamsungTvHandler.createService(SamsungTvHandler.java:243) ~[?:?]
	at org.openhab.binding.samsungtv.internal.handler.SamsungTvHandler.checkAndCreateServices(SamsungTvHandler.java:217) ~[?:?]
	at org.openhab.binding.samsungtv.internal.handler.SamsungTvHandler.thingDiscovered(SamsungTvHandler.java:333) ~[?:?]
	at org.eclipse.smarthome.config.discovery.internal.DiscoveryServiceRegistryImpl.lambda$1(DiscoveryServiceRegistryImpl.java:189) ~[?:?]

4. Switched the TV on again. Thing remains in state "Offline - ..." even after I have waited several seconds.
5. Send "Mute" command to the TV. Command was sent correctly, but binding state die not change.
6. Restarted SamsungTV bundle => Thing state changed to "Online"
7. I can send commands to the TV but the binding does not react on changes, e.g. I can change the channel but the displayed channel and source does not change.

Excerpt from the log file:
samsungtv.log

There are also some messages regarding an unknown device:

2020-02-22 20:41:45.676 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Check and create missing UPnP services
2020-02-22 20:41:45.682 [TRACE] [tv.internal.handler.SamsungTvHandler] - Skipping unknown UPnP service: UE40ES6300, dialreceiver (0a21fe80-00aa-1000-8bb9-1c5a3ede70f5)

But a some seconds before this message the log contains this message

2020-02-22 20:41:44.280 [DEBUG] [covery.SamsungTvDiscoveryParticipant] - Retrieved Thing UID for a Samsung TV '[TV] Samsung' model 'UE40ES6300' thing with UDN '0f7f4900_0004_1000_8162_1c5a3ede70f5'
2020-02-22 20:41:44.284 [DEBUG] [covery.SamsungTvDiscoveryParticipant] - Created a DiscoveryResult for device 'UE40ES6300' with UDN '0f7f4900-0004-1000-8162-1c5a3ede70f5' and properties: {hostName=192.168.2.96}
2020-02-22 20:41:44.331 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Create a Samsung TV Handler for thing 'samsungtv:tv:0f7f4900_0004_1000_8162_1c5a3ede70f5'
2020-02-22 20:41:44.492 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Initializing Samsung TV handler for uid 'samsungtv:tv:0f7f4900_0004_1000_8162_1c5a3ede70f5'
2020-02-22 20:41:44.496 [TRACE] [tv.internal.handler.SamsungTvHandler] - channelLinked: samsungtv:tv:0f7f4900_0004_1000_8162_1c5a3ede70f5:volume
2020-02-22 20:41:44.497 [DEBUG] [tv.internal.handler.SamsungTvHandler] - thingDiscovered: 192.168.2.96, DiscoveryResult [thingUID=samsungtv:tv:0f7f4900_0004_1000_8162_1c5a3ede70f5, properties={hostName=192.168.2.96}, representationProperty=null, flag=NEW, label=[TV] Samsung, bridgeUID=null, ttl=-1, timestamp=1582400242874]
2020-02-22 20:41:44.500 [DEBUG] [tv.internal.handler.SamsungTvHandler] - thingDiscovered, thingUID=samsungtv:tv:0f7f4900_0004_1000_8162_1c5a3ede70f5, discoveredUID=samsungtv:tv:0f7f4900_0004_1000_8162_1c5a3ede70f5

Your Environment

• Version used: openHAB 2.5.2
• Samsung TV: UE40ES6300
• Raspberry Pi with Raspbian Stretch

[jaywiseman1971]

There is some fundamental issues with the SamsungTV binding and jUpNp right now.

#5892

Best, Jay

[jlaur]

I have the same problem with legacy protocol. Binding restart, TV initially offline:

2021-10-30 22:05:59.404 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Check and create missing UPnP services
2021-10-30 22:05:59.406 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Device was NOT online
2021-10-30 22:05:59.410 [DEBUG] [rnal.service.RemoteControllerService] - Creating a Samsung TV RemoteController service: false
2021-10-30 22:05:59.411 [INFO ] [rnal.service.RemoteControllerService] - Using Legacy interface
2021-10-30 22:05:59.412 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'samsungtv:tv:office' changed from UNKNOWN to OFFLINE
2021-10-30 22:05:59.413 [DEBUG] [rnal.protocol.RemoteControllerLegacy] - Open connection to host '192.168.0.41:55000'
2021-10-30 22:05:59.915 [DEBUG] [rnal.protocol.RemoteControllerLegacy] - Cannot connect to Legacy Remote Controller: connect timed out
2021-10-30 22:05:59.917 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Error was reported: Cannot connect to remote control service
org.openhab.binding.samsungtv.internal.protocol.RemoteControllerException: Connection failed

Polling job working after this:

2021-10-30 22:05:59.921 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Start refresh task, interval=1000
...
2021-10-30 21:51:54.692 [DEBUG] [rnal.service.RemoteControllerService] - getSupportedChannelNames: [keyCode, volume, mute, power, channel] 
2021-10-30 21:51:54.695 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: keyCode, command: REFRESH
2021-10-30 21:51:54.697 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: volume, command: REFRESH
2021-10-30 21:51:54.699 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: mute, command: REFRESH
2021-10-30 21:51:54.701 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: power, command: REFRESH
2021-10-30 21:51:54.704 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: channel, command: REFRESH
2021-10-30 21:51:55.706 [DEBUG] [rnal.service.RemoteControllerService] - getSupportedChannelNames: [keyCode, volume, mute, power, channel] 
2021-10-30 21:51:55.708 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: keyCode, command: REFRESH
2021-10-30 21:51:55.711 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: volume, command: REFRESH
2021-10-30 21:51:55.713 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: mute, command: REFRESH
2021-10-30 21:51:55.715 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: power, command: REFRESH
2021-10-30 21:51:55.717 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: channel, command: REFRESH

TV turned on:

2021-10-30 21:51:56.513 [DEBUG] [tv.internal.handler.SamsungTvHandler] - remoteDeviceAdded: RemoteControlReceiver, http://192.168.0.41:52235/rcr/RemoteControlReceiver.xml
2021-10-30 21:51:56.515 [DEBUG] [tv.internal.handler.SamsungTvHandler] - remoteDeviceAdded, upnpUDN=xxxxxxxx_xxxx_xxxx_xxxx_xxxxxxxxxxxx
2021-10-30 21:51:56.516 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Check and create missing UPnP services
2021-10-30 21:51:56.518 [DEBUG] [rnal.service.RemoteControllerService] - Creating a Samsung TV RemoteController service: true
2021-10-30 21:51:56.519 [INFO ] [rnal.service.RemoteControllerService] - Using Legacy interface
2021-10-30 21:51:56.527 [DEBUG] [rnal.protocol.RemoteControllerLegacy] - Open connection to host '192.168.0.41:55000'
2021-10-30 21:51:56.529 [DEBUG] [rnal.protocol.RemoteControllerLegacy] - Connection successfully opened...querying access
2021-10-30 21:51:56.558 [DEBUG] [tv.internal.handler.SamsungTvHandler] - remoteDeviceAdded: MainTVServer2, http://192.168.0.41:52235/MainTVServer2/MainTVServer2Desc.xml
2021-10-30 21:51:56.560 [DEBUG] [tv.internal.handler.SamsungTvHandler] - remoteDeviceAdded, upnpUDN=xxxxxxxx_xxxx_xxxx_xxxx_xxxxxxxxxxxx
2021-10-30 21:51:56.562 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Check and create missing UPnP services
2021-10-30 21:51:56.635 [DEBUG] [rnal.protocol.RemoteControllerLegacy] - Access granted
2021-10-30 21:51:56.638 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Restarting service in UPnP mode for: UE55D8000, RemoteControlReceiver (xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx)
2021-10-30 21:51:56.640 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Device was online
2021-10-30 21:51:56.640 [DEBUG] [internal.service.MainTVServerService] - Creating a Samsung TV MainTVServer service
2021-10-30 21:51:56.643 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Started service for: UE55D8000, MainTVServer2 (xxxxxxxx-xxxx-xxxx-xxxx-xxxxexxxxxxx)
2021-10-30 21:51:56.645 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Service rediscovered, clearing caches: UE55D8000, RemoteControlReceiver (xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx)
2021-10-30 21:51:56.647 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Device was online
2021-10-30 21:51:56.671 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'samsungtv:tv:office' changed from OFFLINE (COMMUNICATION_ERROR): Cannot connect to remote control service to ONLINE 

TV turned off:

2021-10-30 21:52:33.852 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Device removed: udn=xxxxxxxx_xxxx_xxxx_xxxx_xxxxxxxxxxxx 
2021-10-30 21:52:33.852 [DEBUG] [internal.service.MainTVServerService] - onStatusChanged: status=false
2021-10-30 21:52:33.854 [DEBUG] [tv.internal.handler.SamsungTvHandler] - Shutdown all Samsung services
2021-10-30 21:52:33.861 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'samsungtv:tv:office' changed from ONLINE to OFFLINE

After this no more polling and nothing happens. When TV is turned on again, this is not detected.

I briefly looked at the code, but found it hard to understand at first sight. However, this "shutdown" message made me curious, so tried to track it.

shutdown() stops all services (including event listeners), and it's called from dispose(), which seems appropriate, but also remoteDeviceRemoved.

So tracked what starts services: initialize(), which seems appropriate, and also remoteDeviceAdded. I'm not sure if this is fully needed or just some kind of reinitialization.

I tried to remove the shutdown() call from remoteDeviceRemoved to see what happens, and this resulted in the polling job continuing and being able to detect whenever TV goes offline or back online. I'm not sure this is the correct fix, but it might give some ideas about the problem.

[jlaur]

JAR from current main branch with shutdown() call from remoteDeviceRemoved() deleted: https://drive.google.com/file/d/1fG2pukbBj5z7XujGfRZ9a8O4_mVNh9CK/view?usp=sharing