Openhab-addons: [samsungtv] Binding not working with latest snapshot

Created on 4 Jan 2018  Â·  70Comments  Â·  Source: openhab/openhab-addons

The Samsung TV Binding seems to no longer works as intended. Currently this happened after the update to the newest stable release 2.2. Other people have reported the same behaviour.

Expected Behavior

Samsung TV Thing should be Online and operational by Basic UI and habPanel etc.

Current Behavior

Currently the Samsung Binding shows my tv as Offline and I can't control any of the controls that was working before the upgrade from 2.1 and also 2.2 snapshots.

Possible Solution

I really hope this can be fixed, because it was working nicely before.

Steps to Reproduce (for Bugs)

https://community.openhab.org/t/samsung-tv-binding-not-working-with-latest-snapshot/37820

Errors from logs:
2017-12-29 20:55:17.404 [WARN ] [g.samsungtv.handler.SamsungTvHandler] - Channel 'samsungtv:tv:livingroom:sourceName' not supported

When it loads:
2017-12-29 21:53:36.993 [hingStatusInfoChangedEvent] - 'samsungtv:tv:livingroom' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-12-29 21:53:59.961 [hingStatusInfoChangedEvent] - 'samsungtv:tv:livingroom' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING

Context

I am trying to add my Samsung TV's into Openhab which is also possible, but when it finds the TV it states that it is Offline and I can control or retrieve information from the TV's.

Your Environment

Openhabian 2.2 stable Release
RPi3

PR pending awaiting feedback bug

All 70 comments

Could you run in debug an provide more logging?

Till what 2.2.0 snapshot it worked? I did some changes which were merged on 23 of november https://github.com/openhab/openhab2-addons/pull/2357

Hi Martin,

I'm fairly new to this, so how do I do the debug in order to provide you the necessary information?
As far as I can see it was working on 2.2.0 Build #1099. Then I started to have some problems with another binding and then I switched back to a backup RPi3 with the former stable release 2.1 where both was working.

If you can try log:set TRACE org.openhab.binding.samsungtv on the karaf console it should give some hints. If in doubt you can mail the logs to [email protected]

I will try - haven't used that console before. I'm sorry :)

If you uninstall the binding through the paperUI you can unzip the attached jar and put the jar (which is inside the zip) in your addons foldre, it will then automaticly be installed. If you enable logging I hope that we have enough now to resolve the problems.

Iorg.openhab.binding.samsungtv-2.3.0-SNAPSHOT.jar.zip

My TV model is UN60ES7150 which part of the 6500 series and I have a similar problem where the Source Name is not working. I removed the binding from my openhab2.3 installation and installed the one you reference above. Attached is the log output showing the error. Let me know if you have more questions.

SamsungTVbinding.log

Update: My apologies. I forgot to delete the Smart TV thing and that is why it did not communicate with the TV. Once I deleted the old entry, I searched and found a new entry in the inbox. I just verify that I'm able to switch sources. Thanks again.

Okay, so today I noticed that SamsungTV was offline so I started to capture the logs. I restarted the bundle from Karaf and it went online but changing the source did not change. Mute and volume did work. I rebooted and SourceName started again. After a while, it went offline again. Attached are the logs.

samsungtv.log

It shows in the log:

10-Jan-2018 14:41:59.432 [DEBUG] [openhab.binding.samsungtv.handler.SamsungTvHandler] - thingRemoved: samsungtv:tv:0d1cef00_00dc_1000_a28a_1c5a3ecb143d
10-Jan-2018 14:41:59.435 [DEBUG] [openhab.binding.samsungtv.handler.SamsungTvHandler] - Shutdown all Samsung services

Did you really remove it or is that maybe the cause of the problem?

And does it appear OFFLINE or does it not function, or are both states properly aligned?

Please note that it uses upnp discovery to find devices so that is why it takes time after you restarted the binding.

Some of Samsung TV's have a badly implemented UPnP server, which doesn't send regular alive heartbeat multicast messages as it should. Therefore openHAB UPnP stack remove it from UPnP registry, which then cause this kind of problems. I haven't had time to check how we could change the UPnP stack configuration and could it solve this kind of problems.

http://4thline.org/projects/cling/core/manual/cling-core-manual.xhtml#section.RemoteMaxAge

Thanks for the heads up!

Here is a chronology of events in the samsungtv.log I attached previously.

10-Jan-2018 13:40:58.296 Manually restarted bundle via Karaf
SourceName not working
10-Jan-2018 13:44:17.012 Manually stopped and then started bundle via Karaf
Key Mute working
Keep getting "One or more services are already registered"
SourceName not working
10-Jan-2018 14:09:32.278 Rebooted Openhabianpi
10-Jan-2018 14:12:15.086 Source Name is working
10-Jan-2018 14:33:14.940 "One or more services are already registered" begins
Soon after that, the Samsung TV goes offline

One or more services are already registered is a good thing it means it does not try to switch to non-upnp mode. The problem is somehow that the upnp framework inside openHAB forgets about this device. I'll try to take a look at this part tonight when at home.

thx

I fear that to fix the binding we have to fix https://github.com/openhab/openhab2-addons/issues/2916

If I remember correctly, communication via UPnP library to TV doesn't work (library prevent it) if TV is removed from UPnP registry, so I have doubt that #2916 will not fix this problem.

Then I hope that @2delarosa is willing to be a guinea pig ;-)

org.openhab.binding.samsungtv-2.3.0-SNAPSHOT.jar.zip

I added a zip which might work, especially given the suggestion of @paulianttila above I have my doubts. As you might expect I'm highly interested in the logging.

You might need to rediscover your tv because I added the UDN as a configuration property.

So to test this, I will remove the SamsungTV, and replace the jar file over to addons directory. Do I need to reboot?

Restarting should not be needed.

So far so good. No problems detected so far. Will continue to test.
samsungtv.log

I finally got an error. I was messing around with transforms on the http binding and then I noticed the SamsungTV was offline. So I turned it back on and I tested it and got this error. Logs are also attached.
samsungtv.log

> `2018-01-12 08:40:07.679 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.samsungtv.handler.SamsungTvHandler@5de648': null
> 
> java.lang.NullPointerException: null
> 
>   at org.openhab.binding.samsungtv.internal.service.MainTVServerService.setSourceName(MainTVServerService.java:240) [228:org.openhab.binding.samsungtv:2.3.0.201801111957]
> 
>   at org.openhab.binding.samsungtv.internal.service.MainTVServerService.handleCommand(MainTVServerService.java:151) [228:org.openhab.binding.samsungtv:2.3.0.201801111957]
> 
>   at org.openhab.binding.samsungtv.handler.SamsungTvHandler.handleCommand(SamsungTvHandler.java:98) [228:org.openhab.binding.samsungtv:2.3.0.201801111957]
> 
>   at sun.reflect.GeneratedMethodAccessor103.invoke(Unknown Source) ~[?:?]
> 
>   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
> 
>   at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
> 
>   at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [111:org.eclipse.smarthome.core:0.10.0.201712141004]
> 
>   at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [111:org.eclipse.smarthome.core:0.10.0.201712141004]
> 
>   at com.sun.proxy.$Proxy177.handleCommand(Unknown Source) [228:org.openhab.binding.samsungtv:2.3.0.201801111957]
> 
>   at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:72) [118:org.eclipse.smarthome.core.thing:0.10.0.201712141004]
> 
>   at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [118:org.eclipse.smarthome.core.thing:0.10.0.201712141004]
> 
>   at sun.reflect.GeneratedMethodAccessor101.invoke(Unknown Source) ~[?:?]
> 
>   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
> 
>   at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
> 
>   at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [111:org.eclipse.smarthome.core:0.10.0.201712141004]
> 
>   at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [111:org.eclipse.smarthome.core:0.10.0.201712141004]
> 
>   at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
> 
>   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
> 
>   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
> 
>   at java.lang.Thread.run(Thread.java:748) [?:?]`

Thanks for sharing this, we do receive some error from the framework we use for UPNP but fail to process that properly, I changed the code to allow better processing of that error.

org.openhab.binding.samsungtv-2.3.0-SNAPSHOT.jar.zip

Lets see what we get this time, btw I'm also curious whether its able to recover the connection, because as @paulianttila suggested above Samsung implementation seems to be weak.

Did not discover it nor did I create a thing manually

samsungtv.log

The socket timeout seems to suggest that the tv is not properly listening did it go into standby?

Nope. I'll try again later this afternoon.

This build appears to be finickly. I rebooted and it did not discovered it. So I entered it manually and voila, my inbox has the discovered version. I delete the manual entry I created and I switch the Source Name. All good so far. I turned it off and it is showing online whereas the previous would show up offline whenever it was turned off. Also, it appears to be more responsive when change the source.

Here are the latest logs since the reboot.

samsungtv.log.log

I turned it off and it is showing online whereas the previous would show up offline whenever it was turned off.

This is a consequence of not responding when its (temporarily) lost from the internal repository now it will most likely only switch to OFFLINE once you try to do something.

This morning it was offline and the sourceName was no longer working.
samsungtv.log

First of all I again want to mention, that I own an older TV model (LE40C650L1W). I'm not sure if my tests should be a base for further decisions. Here are my test results from today.

Thing Status changes from ONLINE to OFFLINE and vice versa every time I switched the TV on and off. The same result appears to the power channel. The following channels did work without a problem:

  • volume
  • brightness
  • contrast
  • sharpness
  • colortemperature

For one shot I got the message that my TV wants to add OH2 as remote control after sending a command to the keycode channel. I'm not sure if I allowed or declined the access. The following commands to this channel resulted in a warning (see below).

binding version

241 │ Active    │  80 │ 2.2.0                  │ Samsung Tv Binding

openhab.log

2018-01-14 15:46:58.588 [WARN ] [g.samsungtv.handler.SamsungTvHandler] - Channel 'samsungtv:tv:713f3c3d_bfc0_477e_4a66_b9748b8e68b1:power' not supported
2018-01-14 15:46:58.599 [WARN ] [g.samsungtv.handler.SamsungTvHandler] - Channel 'samsungtv:tv:713f3c3d_bfc0_477e_4a66_b9748b8e68b1:mute' not supported
2018-01-14 15:46:58.603 [WARN ] [g.samsungtv.handler.SamsungTvHandler] - Channel 'samsungtv:tv:713f3c3d_bfc0_477e_4a66_b9748b8e68b1:keyCode' not supported

This was the state of the art. Now I downloaded the latest modified version (https://github.com/openhab/openhab2-addons/issues/3075#issuecomment-357345171) provided by @martinvw. Thanks for your work.

Some more channels are working, but a big disadvantage was that after powering the TV off in any way the Thing never came back ONLINE after turning the TV on again.

  • volume
  • mute
  • brightness
  • contrast
  • sharpness
  • colortemperature
  • keycode (most of them, I have to figure out the mappings to use them in a proper way ;-))
  • power

binding version

256 │ Active    │  80 │ 2.3.0.201801122017     │ Samsung Tv Binding

openhab.log (an extract, I didn't activate DEBUG logging at all, if you need more information, don't hesitate to ask)

2018-01-14 16:13:11.626 [INFO ] [g.samsungtv.handler.SamsungTvHandler] - Error was reported: Could not send command to device on 192.168.178.45:55000
org.openhab.binding.samsungtv.internal.protocol.RemoteControllerException: Connection failed
        at org.openhab.binding.samsungtv.internal.protocol.RemoteController.openConnection(RemoteController.java:95) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
        at org.openhab.binding.samsungtv.internal.protocol.RemoteController.sendKey(RemoteController.java:200) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
        at org.openhab.binding.samsungtv.internal.service.RemoteControllerService.sendKeyCode(RemoteControllerService.java:194) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
        at org.openhab.binding.samsungtv.internal.service.RemoteControllerService.handleCommand(RemoteControllerService.java:138) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
        at org.openhab.binding.samsungtv.handler.SamsungTvHandler.handleCommand(SamsungTvHandler.java:98) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [109:org.eclipse.smarthome.core:0.10.0.b1]
        at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [109:org.eclipse.smarthome.core:0.10.0.b1]
        at com.sun.proxy.$Proxy146.handleCommand(Unknown Source) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
        at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:72) [116:org.eclipse.smarthome.core.thing:0.10.0.b1]
        at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [116:org.eclipse.smarthome.core.thing:0.10.0.b1]
        at sun.reflect.GeneratedMethodAccessor52.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [109:org.eclipse.smarthome.core:0.10.0.b1]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [109:org.eclipse.smarthome.core:0.10.0.b1]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.net.SocketTimeoutException: connect timed out
        at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:?]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:?]
        at java.net.Socket.connect(Socket.java:589) ~[?:?]
        at org.openhab.binding.samsungtv.internal.protocol.RemoteController.openConnection(RemoteController.java:93) ~[?:?]
        ... 22 more
...
2018-01-14 16:17:50.982 [WARN ] [shd.server.session.ServerSessionImpl] - exceptionCaught(ServerSessionImpl[openhab@/127.0.0.1:36734])[state=Opened] InterruptedByTimeoutException: null

but a big disadvantage was that after powering the TV off in any way the Thing never came back ONLINE after turning the TV on again.

Do you mean the status online or did it never function again?

Did you see that the scheduled job was terminated either from:

https://github.com/martinvw/openhab2-addons/blob/feature/samsungtv-fix/addons/binding/org.openhab.binding.samsungtv/src/main/java/org/openhab/binding/samsungtv/handler/SamsungTvHandler.java#L182-L184

https://github.com/martinvw/openhab2-addons/blob/feature/samsungtv-fix/addons/binding/org.openhab.binding.samsungtv/src/main/java/org/openhab/binding/samsungtv/handler/SamsungTvHandler.java#L254

2018-01-14 16:13:11.626 [INFO ] [g.samsungtv.handler.SamsungTvHandler] - Error was reported: Could not send command to device on 192.168.178.45:55000
org.openhab.binding.samsungtv.internal.protocol.RemoteControllerException: Connection failed

Was this with the TV on or off?

Do you mean the status online or did it never function again?

I talked about the Thing Status. To clarify the situation:

  1. Thing Status was ONLINE, power channel was Ã’N.
  2. I turned off the TV with my remote controller or sending an OFF command to the power channel: Thing Status changed to OFFLINE, power channel changed to Ã’FF.

While I was typing my reply the Thing Status changed back to ONLINE whereas the power channel remains OFF. I guess this should be the expected behavior. Maybe it could be more clearly if only the power channel changes.

Was this with the TV on or off?

I have to double check that. I'll be back in a minute. ;-)

Here you are in detail. TV was off.

2018-01-14 17:11:33.981 [DEBUG] [g.samsungtv.handler.SamsungTvHandler] - Received channel: samsungtv:tv:713f3c3d_bfc0_477e_4a66_b9748b8e68b1:power, command: ON
2018-01-14 17:11:33.984 [DEBUG] [rnal.service.RemoteControllerService] - Received channel: power, command: ON
2018-01-14 17:11:33.990 [DEBUG] [v.internal.protocol.RemoteController] - Try to send command: KEY_POWERON
2018-01-14 17:11:33.992 [DEBUG] [v.internal.protocol.RemoteController] - Open connection to host '192.168.178.45:55000'
2018-01-14 17:11:34.497 [INFO ] [g.samsungtv.handler.SamsungTvHandler] - Error was reported: Could not send command to device on 192.168.178.45:55000
org.openhab.binding.samsungtv.internal.protocol.RemoteControllerException: Connection failed
    at org.openhab.binding.samsungtv.internal.protocol.RemoteController.openConnection(RemoteController.java:95) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
    at org.openhab.binding.samsungtv.internal.protocol.RemoteController.sendKey(RemoteController.java:200) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
    at org.openhab.binding.samsungtv.internal.service.RemoteControllerService.sendKeyCode(RemoteControllerService.java:194) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
    at org.openhab.binding.samsungtv.internal.service.RemoteControllerService.handleCommand(RemoteControllerService.java:138) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
    at org.openhab.binding.samsungtv.handler.SamsungTvHandler.handleCommand(SamsungTvHandler.java:98) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
    at sun.reflect.GeneratedMethodAccessor55.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
    at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [109:org.eclipse.smarthome.core:0.10.0.b1]
    at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [109:org.eclipse.smarthome.core:0.10.0.b1]
    at com.sun.proxy.$Proxy146.handleCommand(Unknown Source) [256:org.openhab.binding.samsungtv:2.3.0.201801122017]
    at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:72) [116:org.eclipse.smarthome.core.thing:0.10.0.b1]
    at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [116:org.eclipse.smarthome.core.thing:0.10.0.b1]
    at sun.reflect.GeneratedMethodAccessor52.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
    at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [109:org.eclipse.smarthome.core:0.10.0.b1]
    at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [109:org.eclipse.smarthome.core:0.10.0.b1]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.net.SocketTimeoutException: connect timed out
    at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
    at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:?]
    at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:?]
    at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:?]
    at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:?]
    at java.net.Socket.connect(Socket.java:589) ~[?:?]
    at org.openhab.binding.samsungtv.internal.protocol.RemoteController.openConnection(RemoteController.java:93) ~[?:?]
    ... 21 more

After that the Thing Status changed to OFFLINE -> COMMUNICATION_ERROR 'Could not send command to device on 192.168.178.45:55000' and never back to ONLINE again - even if the TV is on.

@2delarosa did it recover again (without any restarts?)

Nope, and I upgraded the snapshot today.
samsungtv.log

@kaikreuzer spotted the error why it could never recover and please note that the snapshot build 1186 (https://community.openhab.org/t/first-major-update-in-2-3-0-snapshot/38801/7?u=martinvw) of two days ago was completely broken.

org.openhab.binding.samsungtv-2.3.0-SNAPSHOT.jar.zip

Still failing. I installed it and it did not work. So I removed the SamsungTV thing and rediscovered it. It worked and then I left the TV for several hours. I came back and I was unable to change the source.
samsungtv.log

I reached a state where I fear that changes in upnp implementation might be related can you also enable debug logging for org.jupnp

I also added some more debug logging to the binding, thank you so much for your assistance.

org.openhab.binding.samsungtv-2.3.0-SNAPSHOT.jar.zip

@martinvw Thanks for your work. Any updates on the RemoteControllerException? Shall I do some test as well?

That build did not work. Attached is the samsungtv.log. I rather not post the jupnp logs unsecured for privacy or security reasons. Please email me a password you want me to use and I post them then. check your email.
samsungtv.log

@2delarosa feel free to mail me the logs but please note that the error "RemoteControllerException: Connection failed" just means it cannot connect, can it be that there is just something flaky going on in your network. Please note that I can only build the connection if my television is ON, I assume you're aware of that.

You can quickly check this from bash (linux / Mac or nowadays even in Windows) by making the following call:

telnet 192.168.128.75 55000

@cweitkamp

@martinvw Thanks for your work. Any updates on the RemoteControllerException? Shall I do some test as well?

The RemoteControllerException is logged as trace because its just to see that the connection failed, but as long as your tv is not On / connected that is completely expected behavior so that is not the thing I'm trying to debug, especially the disconnections and failure to reconnect the UPNP connection is worying me.

I was not aware that the TV needed to be ON to be discovered. I turned it on and I experienced the same behavior. It could not discover the TV. So I reinstalled the binding. I forwarded the logs to your email and attached is the samsungtv log
samsungtv.log

P.S. I could not run telnet on the raspberry pi, windows, or mac either because I don't have the path set up correctly or I don't have it installed.

You are right telnet is not available by default anymore, such a pity, if you use a package manager such as brew on your mac you can install it through that, if not we should try if from your pi.

With Windows you can also do it through Putty, choose the option telnet instead of ssh and fill in 55000 as port.

For the the pi it would be sudo apt-get install telnet its just the client so it should be safe and just use some very small amount of space.

Lets first make sure we can actually connect otherwise we might be chasing a ghost.

My apologies. Saturday, I switched the network cable from the TV to the Chromecast Ultra and I completely forgot. Traveling this week but I'll try to do some remote testing.

Looking at the last log you send me via mail (thanks for that), I see the following.

Your tv with udn "*-1c5a3ecb143d" is discovered for the last time at '24-Jan-2018 20:07:11.692' your time after that I cannot find it in the logs anymore. But I can still see that the binding tries to poll the device. I will now add something to kill the connection if we have failure and hope that it will help in reconnecting.

About your jupnp logging, please note it rotated so I only have one hour of upnp data and miss most interesting parts to relate with the other log.

I added more debug logging and some of might not have been active yet, so I hope this will give some new insights and I would assume now that it should fine, or we are being blacklisted by the tv for polling too much....?

org.openhab.binding.samsungtv-2.3.0-SNAPSHOT.jar.zip

Martin, I sent you the logs for the above snapshot. Was there anything pending from my side?

@cweitkamp "keycode (most of them, I have to figure out the mappings to use them in a proper way ;-))"

How do you figure out these mappings?

@yveshanoulle To be honest, I used a fundamental method of problem solving: Trial and error. I didn't write down notes on what I found, sry.

@cweitkamp I'm ok with that, I just have no idea what to try.
is this numeric, is this alphanumeric, is there a limit of characters etc etc...

I assume you have a script where you are using the codes that you are interested in?

@yveshanoulle the type for the item to link with the channel should be String. You can for example use a Selection element in a sitemap or directly send String commands in rules to it. See here for a list of possible options.

perfect. Exactly what I need.

Is the problem solved with the samsungtv-2.3.0 binding?
My Samsung UE55ES8000 is no longer found when I wanted to add a samsungtv thing with openhab 2.2.01 und openhab-addons-2.2.0. it was detected in an earlier version.
I have copied the org.openhab.binding.samsungtv-2.3.0-SNAPSHOT.jar in the addon directory /usr/share/openhab2/addons but it is not listed for installation. I have also no list of seperate bindings but just one bundle/package called openhab-addons-2.2.0.kar.

Is the problem solved with the samsungtv-2.3.0 binding?

No sorry, I have not been able to pinpoint it yet, the only thing I see with @2delarosa is that his upnp subscription expires and that it fails after that. Does yours fail immediately?

Did you try installing the old binding?

Now we are getting somewhere, can you still see the samsungtv1 binding in the bindings which can be installed? Because I also first used that one because initially the support for my old tv, was way better (reason of that is that it uses a different technology).

I cannot find it and so maybe other users can also not find it anymore but where actually still using that one? Or not? @wborn can you still see the old samsungtv1 binding?

Maybe some people can test whether the old 2.1 bindings the current openHAB makes a difference but I cannot yet find any reason in the binding code which would break it in this way.

This should be the one packaged with 2.1:

https://dl.bintray.com/openhab/mvn/org/openhab/binding/org.openhab.binding.samsungtv/2.1.0/:org.openhab.binding.samsungtv-2.1.0.jar

I cannot find it and so maybe other users can also not find it anymore but where actually still using that one? Or not? @wborn can you still see the old samsungtv1 binding?

Looks like there was never a feature for the openHAB 1 Samsung TV Binding so it will not be installable via Paper UI.

But you can try org.openhab.binding.samsungtv-1.11.0.jar from openhab-1.11.0-addons.zip.
The latest development version is org.openhab.binding.samsungtv-1.12.0-SNAPSHOT.jar.
See also this documentation page: https://docs.openhab.org/addons/bindings/samsungtv1/readme.html

I don't use the binding or a Samsung TV myself.

Thanks! That is interesting I thought I used the old one when running an early OH2 snapshot, but I created a PR to include it:

https://github.com/openhab/openhab1-addons/pull/5564

Tonight I plan to take another look at the binding and most recent logs of @2delarosa

If someone can test the 2.1 binding (or someone new test the latest jar I posted) that would be great, otherwise I will as a start wrap up the pending PR so that the small improvement and bug fixes will be included in the snapshot.

Can someone please help me to answer my second question how to install a seperate jar file if the installation has only one big kar file for all addons? I have not found an answer so far in the web or help. I only read in this thread, that the single binding shall be copied to the addons directory. That is what I did but openhab seem to see only the addons in the large kar packe and not the seperate smsong binding ja file. Thus I can't try the new 2.3 nor an older 2.1 version.

I copied the statement from my posting above:
" have copied the org.openhab.binding.samsungtv-2.3.0-SNAPSHOT.jar in the addon directory /usr/share/openhab2/addons but it is not listed for installation. I have also no list of seperate bindings but just one bundle/package called openhab-addons-2.2.0.kar"

I never used the kar file maybe @lolodomo or @kaikreuzer can answer this?

I don't know about how to NOT get a kar file, that was a stadad openhab2 installation and created exactly that setup. How can I prevent to create a kar file during installtion and rather seperate jar files? Or can I extract the kar file?

You can have the kar file + any other binding as jar file in the addons directory. After startup, run bundle:list command in the console and you will see your binding corresponding to your jar file in the list. But this binding will not appear as an add-ons in Paper UI.
It might be a little more difficult in case you want to have a jar file of a binding that is included in the kar file too. In this case, you have to take care to not start the two versions of the binding.

I have extracted the kar file with unzip (keeping the directory structure), created a new subdir v2.3.0for the samsung binding, replaced added the file in the old V2.2.0 dir, repalced/renamed the file (of course renaed the kar file), restarted openhab2 several times but it does not offere the new 2.3 binding always installs the 2.2 and it also does no longer find the Samsung UE55ES8090 (which worked a while ago). I give up after several hours reaseach and testing.

@2delarosa sorry for the great delay, I have been taking another look at your logs.

Martin, I sent you the logs for the above snapshot. Was there anything pending from my side?

I will use (update) this message to summaries what I find/found.

  • It seems that the subscription in the upnp registry expires and that that might cause the disconnection. In the logs I see that at '26-Jan-2018 07:02:54.730' the jupnp code loges that it will expire in -1 seconds (after going down to this in a normal rate).

  • Another note worthy thing is the following log-fragment:

26-Jan-2018 07:02:00.132 [WARN ] [org.jupnp.transport.spi.StreamClient              ] - HTTP request failed: (OutgoingActionRequestMessage) POST http://192.1
68.128.75:7676/smp_20_
java.net.SocketTimeoutException: Connect Timeout
        at org.eclipse.jetty.io.ManagedSelector$ConnectTimeout.run(ManagedSelector.java:672) [81:org.eclipse.jetty.io:9.3.22.v20171030]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
26-Jan-2018 07:02:00.132 [WARN ] [org.jupnp.transport.spi.StreamClient              ] - HTTP request failed: (OutgoingActionRequestMessage) POST http://192.1
68.128.75:7676/smp_12_
java.net.SocketTimeoutException: Connect Timeout
        at org.eclipse.jetty.io.ManagedSelector$ConnectTimeout.run(ManagedSelector.java:672) [81:org.eclipse.jetty.io:9.3.22.v20171030]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
26-Jan-2018 07:02:00.133 [TRACE] [org.jupnp.transport.Router                        ] - Releasing router lock: ReadLock
26-Jan-2018 07:02:00.133 [TRACE] [org.jupnp.transport.Router                        ] - Releasing router lock: ReadLock
26-Jan-2018 07:02:00.134 [TRACE] [org.jupnp.protocol.sync.SendingAction             ] - No connection or no no response received, returning null
26-Jan-2018 07:02:00.134 [TRACE] [org.jupnp.protocol.sync.SendingAction             ] - No connection or no no response received, returning null
  • The tv is discovered: Discovered a Samsung TV '[TV]UN60ES7150' model 'UN60ES7150' thing with UDN '0d1cef00_00dc_1000_a28a_1c5a3ecb143d'

  • Note that not only the samsung tv is kicked from the registry but almost all other devices as well:

jupnp.log:26-Jan-2018 07:02:54.740 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:829cc674-a407-eab8-8035-adec958f74e3, Descriptor: http://192.168.128.24:8008/ssdp/device-desc.xml, Root: true
jupnp.log:26-Jan-2018 07:02:54.746 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:0b532b80-00be-1000-861a-1c5a3ecb143d, Descriptor: http://192.168.128.75:7676/smp_6_, Root: true
jupnp.log:26-Jan-2018 07:02:55.778 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:0a21fe80-00aa-1000-b47c-1c5a3ecb143d, Descriptor: http://192.168.128.75:7676/smp_2_, Root: true
jupnp.log:26-Jan-2018 07:02:57.824 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:bb579125-48ff-02f7-c0f2-8784bf5b1c11, Descriptor: http://192.168.128.229:32469/DeviceDescription.xml, Root: true
jupnp.log:26-Jan-2018 07:02:57.834 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:0d1cef00-00dc-1000-a28a-1c5a3ecb143d, Descriptor: http://192.168.128.75:7676/smp_18_, Root: true
jupnp.log:26-Jan-2018 07:02:58.858 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:0c845880-00d2-1000-be2c-1c5a3ecb143d, Descriptor: http://192.168.128.75:7676/smp_10_, Root: true
jupnp.log:26-Jan-2018 07:02:58.868 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:5f9ec1b3-ed59-1900-4530-00a0dea8b8a6, Descriptor: http://192.168.128.199:8080/MediaRenderer/desc.xml, Root: true
jupnp.log:26-Jan-2018 07:03:06.002 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:4d696e69-444c-164e-9d41-00089bc4d4cd, Descriptor: http://192.168.128.244:8200/rootDesc.xml, Root: true
jupnp.log:26-Jan-2018 07:03:06.012 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:4d696e69-444c-164e-9d41-00089be9d654, Descriptor: http://192.168.128.229:8200/rootDesc.xml, Root: true
jupnp.log:26-Jan-2018 07:03:08.052 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:16a65700-00c6-1000-8823-b4b676ab83c1, Descriptor: http://192.168.128.86:7676/smp_6_, Root: true
jupnp.log:26-Jan-2018 07:03:08.060 [TRACE] [org.jupnp.registry.Registry                       ] - Removing expired: (RemoteDevice) Identity: (RemoteDeviceIdentity) UDN: uuid:55076f6e-6b79-1d65-a4eb-00089bc4d4cd, Descriptor: http://192.168.128.244:9000/dev0/desc.xml, Root: true

Shortly after the expiry I also see another failure to connect:

26-Jan-2018 07:02:54.852 [WARN ] [org.jupnp.transport.spi.StreamClient              ] - HTTP request failed: (OutgoingActionRequestMessage) POST http://192.1
68.128.75:7676/smp_20_
java.net.SocketTimeoutException: Connect Timeout
        at org.eclipse.jetty.io.ManagedSelector$ConnectTimeout.run(ManagedSelector.java:672) [81:org.eclipse.jetty.io:9.3.22.v20171030]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
26-Jan-2018 07:02:54.853 [TRACE] [org.jupnp.transport.Router                        ] - Releasing router lock: ReadLock
26-Jan-2018 07:02:54.854 [TRACE] [org.jupnp.protocol.sync.SendingAction             ] - No connection or no no response received, returning null
  • I see the following devices:
Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/0a21fe80-00aa-1000-b47c-1c5a3ecb143d/svc/samsung.com/MultiScreenService/event/cb
Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/0b532b80-00be-1000-861a-1c5a3ecb143d/svc/dial-multiscreen-org/dial/event/cb
Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/0c845880-00d2-1000-be2c-1c5a3ecb143d/svc/samsung.com/MainTVAgent2/event/cb
Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/0d1cef00-00dc-1000-a28a-1c5a3ecb143d/svc/upnp-org/AVTransport/event/cb
Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/0d1cef00-00dc-1000-a28a-1c5a3ecb143d/svc/upnp-org/ConnectionManager/event/cb
Discovered: (ServiceEventCallbackResource) URI: /upnpcallback/dev/0d1cef00-00dc-1000-a28a-1c5a3ecb143d/svc/upnp-org/RenderingControl/event/cb

Its bizarre that no one yet reported the binding to still be functional but I do not see how my changes would cause this? So please test the 2.1 binding preferably in openHAB 2.2 because I think that either

  • a bug in my code or the upnp lib crashes in the internal upnp from the TV
  • a timeout which is not set/handled correctly, this could maybe be checked by manually connecting to tv using telnet or something similar.
  • a change in the upnp library effected the garbage collection and now it cleans record to soon, but this is not what I read from the logs

@2delarosa I completed the analysis, conclusion I still do not know what is wrong but there some things which you can test:

  • Does the 2.1 binding (insides the openHAB 2.2) work?
  • can you connect to the ports of the tv if it just dropped the connection?
  • do you use other upnp devices inside openHAB do they have problems?

Thanks for your time and sorry that it took me so long.

@ others feel free to test this jar for extra regressions if its better then we have now I would like to merge it :-)

org.openhab.binding.samsungtv-2.3.0-SNAPSHOT.zip

I would like to test but was not able to make it visible for the Bindings Installation (as described above, I've tried a lot but it's not offered in the OpenHAB Bindings installation screen).
JUst copying did not work.
Not sure if somebody can give a hint what I'm doing wrong.

If you put a binding's jar file into the addons folder it will be automatically installed and won't appear in the installation screen. You can check whether the binding was loaded on the Karaf console with following command:
bundle:list | grep Samsung

I'm running the 2.4.0 snapshot, trying to control a Samsung UE50MU6120 (reported by the binding as "Samsung 6 Series (50)").

I don't see all the channels referenced in the binding web page - in the "Control" page of the Paper UI I get only:

  • Volume
  • Mute
  • Source Name
  • Channel
  • Program Title
  • Channel Name
  • Key Code
  • Power

Crucially, only Volume, Mute and Power are populated. All the others are blank.

Mute and Volume function OK, but Power fails to do anything, and reports in the log:
2018-07-05 19:23:31.808 [DEBUG] [v.internal.protocol.RemoteController] - Try to send command: KEY_POWEROFF
2018-07-05 19:23:31.811 [DEBUG] [v.internal.protocol.RemoteController] - Open connection to host '192.168.0.34:55000'
2018-07-05 19:23:31.826 [INFO ] [g.samsungtv.handler.SamsungTvHandler] - Error was reported: Could not send command to device on 192.168.0.34:55000

I also have the "samsungctl" utility, and "KEY_POWEROFF" also fails with that, but "KEY_POWER" (as a toggle) works just fine, including for power on.

Should I expect to be able to get values for the rest of the channels I find?
Should I also be able to find the other channels?
Is there any way to have the binding send "KEY_POWER" instead of "KEY_POWEROFF" and "KEY_POWERON"?

Thanks

@martinvw Have you merged your changes in the meantime?

No I think #4169 is its mental predecessor, let me close my PR.

A pull request has just been merged which should address your issues. You can try the latest snapshot built (tomorrow) or try the jar I uploaded to: org.openhab.binding.samsungtv-2.5.0-SNAPSHOT.jar

Was this page helpful?
0 / 5 - 0 ratings