[velux] New OpenHAB2 binding - feedback welcome!

openhab2
binding
Tags: #<Tag:0x00007f014bc99200> #<Tag:0x00007f014bc99048>

(Guenther Schreiner) #41

Hi Johannes,

both bindings, the OH1 and the OH2, will be updated for the new protocol.
The OH1 binding is more-or-less ready to use … with the experiences it will
be much easier to integrate the complete stuff into the OH2 binding afterwards.

Regards, Guenther


(Guenther Schreiner) #42

Hi Johannes,
the main difference is the support of generic device settings, i.e. you can use the io-homecontrol devices like normal rollershutters. From the side of bindings - beside the scenes - it will look like:

// Velux Shutters

Rollershutter V_DG_M_W	"Velux DG Window Bathroom [%d]"	{ velux="thing=actuator;channel=serial#01:52:21:3E:26:0C:1B"}
Rollershutter V_DG_M_S	"Velux DG Shutter Bathroom [%d]"{ velux="thing=actuator;channel=serial#01:52:00:21:00:07:00"}

(Bert Kaufmann) #43

Hi all,

once again I need your help. I’m sorry!

Coming from old velux KLF200 firmware I updated to KLF200-v2.0.0.71.bin last weekend, placed org.openhab.binding.velux-1.13.0-SNAPSHOT.jar into addons folder, cleared all caches,
placed velux.cfg with

bridgeIPAddress=velux
bridgeProtocol=slip
bridgeTCPPort=80
bridgePassword=XXX
timeoutMsecs=2000
retries=6

into services folder, kept velux.things as it was before with

Bridge velux:klf200:home   [ bridgeIPAddress="192.168.0.37", bridgePassword=„XXX“, timeoutMsecs=2000, retries=10 ] {
 Thing   scene   scWindow000    [ sceneName="Window000" ]
 Thing   scene   scWindow007    [ sceneName="Window007" ]
 Thing   scene   scWindow020    [ sceneName="Window020" ]
 Thing   scene   scWindow050    [ sceneName="Window050" ]
 Thing   scene   scWindow080    [ sceneName="Window080" ]
 Thing   scene   scWindow100    [ sceneName="Window100" ]
 Thing   scene   scShutter000    [ sceneName="Shutter000" ]
 Thing   scene   scShutter020    [ sceneName="Shutter020" ]
 Thing   scene   scShutter050    [ sceneName="Shutter050" ]
 Thing   scene   scShutter080    [ sceneName="Shutter080" ]
 Thing   scene   scShutter100    [ sceneName="Shutter100" ]
}

and velux.items to

String  V_FIRMWARE  "Firmware [%s]" { velux="thing=bridge;channel=firmware" }
String  V_STATUS    "Status [%s]"   { velux="thing=bridge;channel=status" }
String  V_CHECK     "Velux Config Check [%s]" { velux="thing=bridge;channel=check" }

and restarted my OpenHAB 2.4.0.M5. But all without any luck. The binding can’t connect to the gateway.

My log shows following lines

2018-11-13 21:39:08.160 [INFO ] [org.openhab.binding.velux           ] - FrameworkEvent INFO - org.openhab.binding.velux
org.osgi.framework.BundleException: The bundle class path entry "lib/gson-2.2.4.jar" could not be found for the bundle "osgi.identity; type="osgi.bundle"; version:Version="1.13.0.201811051916"; osgi.identity="org.openhab.binding.velux""
	at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findClassPathEntry(ClasspathManager.java:174) ~[?:?]
	at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.buildClasspath(ClasspathManager.java:152) ~[?:?]
	at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.<init>(ClasspathManager.java:81) ~[?:?]
	at org.eclipse.osgi.internal.loader.EquinoxClassLoader.<init>(EquinoxClassLoader.java:43) ~[?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.createClassLoaderPrivledged(BundleLoader.java:316) ~[?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.getModuleClassLoader(BundleLoader.java:233) ~[?:?]
	at org.eclipse.osgi.internal.loader.BundleLoader.findEntries(BundleLoader.java:819) ~[?:?]
	at org.eclipse.osgi.container.ModuleWiring.findEntries(ModuleWiring.java:289) ~[?:?]
	at org.eclipse.osgi.storage.ManifestLocalization.findResource(ManifestLocalization.java:199) ~[?:?]
	at org.eclipse.osgi.storage.ManifestLocalization.lookupResourceBundle(ManifestLocalization.java:130) ~[?:?]
	at org.eclipse.osgi.storage.ManifestLocalization.getResourceBundle(ManifestLocalization.java:101) ~[?:?]
	at org.eclipse.osgi.storage.ManifestLocalization.getHeaders(ManifestLocalization.java:64) ~[?:?]
	at org.eclipse.osgi.storage.BundleInfo$Generation.getHeaders(BundleInfo.java:125) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.privGetHeaders(EquinoxBundle.java:462) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.getHeaders(EquinoxBundle.java:457) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.getHeaders(EquinoxBundle.java:451) ~[?:?]
	at org.apache.aries.spifly.BaseActivator.getAllHeaders(BaseActivator.java:133) ~[?:?]
	at org.apache.aries.spifly.BaseActivator.addConsumerWeavingData(BaseActivator.java:95) ~[?:?]
	at org.apache.aries.spifly.ConsumerBundleTrackerCustomizer.addingBundle(ConsumerBundleTrackerCustomizer.java:37) ~[?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:469) ~[?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:415) ~[?:?]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) ~[?:?]
	at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:183) ~[?:?]
	at org.osgi.util.tracker.BundleTracker.open(BundleTracker.java:156) ~[?:?]
	at org.apache.aries.spifly.BaseActivator.start(BaseActivator.java:79) ~[?:?]
	at org.apache.aries.spifly.dynamic.DynamicWeavingActivator.start(DynamicWeavingActivator.java:37) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:779) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1) ~[?:?]
	at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:772) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:729) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:933) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:309) ~[?:?]
	at org.eclipse.osgi.container.Module.doStart(Module.java:581) ~[?:?]
	at org.eclipse.osgi.container.Module.start(Module.java:449) ~[?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) ~[?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) ~[?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) ~[?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) ~[?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) ~[?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at     org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]
...
2018-11-13 21:39:24.252 [INFO ] [inding.velux.internal.VeluxActivator] - velux binding has been started.
2018-11-13 21:39:24.369 [INFO ] [.binding.velux.internal.VeluxBinding] - Active items are: [].
2018-11-13 21:39:24.370 [INFO ] [.binding.velux.internal.VeluxBinding] - velux refresh interval set to 15000 milliseconds.
20    18-11-13 21:39:24.374 [INFO ] [.binding.velux.internal.VeluxBinding] - veluxConfig[bridgeProtocol=slip,bridgeIPAddress=velux,bridgeTCPPort=80,bridgePassword=********,timeoutMsecs=2000,retries=6,refreshMsecs=15000,isBulkRetrievalEnabled=true]
    2018-11-13 21:39:24.379 [INFO ] [b.core.service.AbstractActiveService] - velux Refresh Service has been started
    
...

2018-11-13 21:39:39.390 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:39:41.424 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:39:45.426 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:39:53.428 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:40:09.430 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

...

2018-11-13 21:43:53.446 [INFO ] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): socket I/O failed continuously (6 times).
2018-11-13 21:43:53.447 [WARN ] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): method io() raised an error: null.
2018-11-13 21:43:53.447 [WARN ] [.velux.handler.VeluxBridgeHandlerOH1] - velux bridge login sequence failed; expecting bridge is OFFLINE.
2018-11-13 21:43:53.808 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:43:55.811 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:43:59.813 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:44:07.814 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:44:23.816 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:44:55.819 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge     connection.
2018-11-13 21:45:00.642 [INFO ] [smarthome.model.script.opensprinkler] - Rain DETECTED
2018-11-13 21:45:59.822 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:48:07.825 [INFO ] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): socket I/O failed continuously (6 times).
2018-11-13 21:48:07.826 [WARN ] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): method io() raised an error: null.
2018-11-13 21:48:07.827 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): updating of item V_STATUS (type BRIDGE_STATUS) failed.
2018-11-13 21:48:22.828 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:48:24.831 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:48:28.832 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:48:36.834 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:48:52.836 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:49:24.839 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 21:50:28.842 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

...

Can you help me with that so that I will get my window and shutter working again?

Regards,
Bert


(Guenther Schreiner) #44

Hi Bert,

one note about the new protocol: the default bridge port supporting this protocolis 51200.
Pls. change the configuration and try again (the gson.lib errors confuses me … but it should
not influence the slip connection).

Regards, Guenther


(Bert Kaufmann) #45

Fantastic!

2018-11-13 22:36:45.872 [INFO ] [.binding.velux.internal.VeluxBinding] - veluxConfig[bridgeProtocol=slip,bridgeIPAddress=velux,bridgeTCPPort=51200,bridgePassword=********,timeoutMsecs=2000,retries=6,refreshMsecs=15000,isBulkRetrievalEnabled=true]
2018-11-13 22:38:27.764 [INFO ] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): socket I/O failed continuously (6 times).
2018-11-13 22:38:27.765 [WARN ] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): method io() raised an error: null.
2018-11-13 22:38:27.765 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): updating of item V_STATUS (type BRIDGE_STATUS) failed.
2018-11-13 22:38:27.767 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-11-13 22:38:34.493 [INFO ] [ab.binding.velux.bridge.slip.SClogin] - velux bridge connection successfully established (login succeeded).
2018-11-13 22:38:40.507 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - Found velux scenes:
	Scene "Shutter050" (index 6) with non-silent mode and 0 actions
	Scene "Window000" (index 1) with non-silent mode and 0 actions
	Scene "Window100" (index 0) with non-silent mode and 0 actions
	Scene "Shutter080" (index 5) with non-silent mode and 0 actions
	Scene "Window007" (index 2) with non-silent mode and 0 actions
	Scene "Window050" (index 3) with non-silent mode and 0 actions
	Scene "Window080" (index 10) with non-silent mode and 0 actions
	Scene "Shutter100" (index 4) with non-silent mode and 0 actions
	Scene "Shutter000" (index 8) with non-silent mode and 0 actions
	Scene "Window020" (index 9) with non-silent mode and 0 actions
	Scene "Shutter020" (index 7) with non-silent mode and 0 actions	.
2018-11-13 22:38:42.513 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - Found velux actuators:
	Product "Fenster 1" / WINDOW_OPENER (bridgeIndex=1,serial=56:36:13:5A:11:1A:0D,position=F7FF)
	Product "Rollladen 1" / ROLLER_SHUTTER (bridgeIndex=0,serial=56:32:14:5A:11:05:0A,position=F7FF)	.
2018-11-13 22:38:42.513 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - velux Bridge is online, now.

Thanks a lot!


(Bert Kaufmann) #46

Guenther,

perhaps you can change the information on the slip port on GitHub. I took port 80 from there.

May I assist you with gson.lib errors? Perhaps this is because I’m running OpenHAB 2.4 Milestone 5 in a docker environment.

Best regards,
Bert


(Guenther Schreiner) #47

Couldn’ agree more: Fixed the README-v1.13.md


(Marcel) #48

Hi,
i have installed velux snapshot 2.3.0 and add a thing “Velux KLF200” via paper ui. then i have define the
ip adress in paper ui.

my actually problem is, that the velux device in openhab always switch to offline.

2018-12-02 22:45:16.532 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'velux:klf200:b158a76a' takes more than 5000ms.

2018-12-02 22:49:26.105 [INFO ] [hab.binding.velux.bridge.VeluxBridge] - io(): socket I/O failed continuously (6 times).

2018-12-02 22:49:26.111 [INFO ] [ing.velux.handler.VeluxBridgeHandler] - bridgeCommunicate(): Exception occurred on accessing http://192.168.0.177:80/api/v1/auth: java.util.concurrent.ExecutionException: java.net.ConnectException: Connection refused.

2018-12-02 22:49:26.117 [INFO ] [ing.velux.handler.VeluxBridgeHandler] - Velux veluxBridge login/logout sequence failed; expecting veluxBridge is OFFLINE.

2018-12-02 22:49:26.130 [hingStatusInfoChangedEvent] - 'velux:klf200:b158a76a' changed from INITIALIZING to OFFLINE

Openhab Version 2.3.0
Velux KLF200 connected to LAN

have anyone an idea how i can solve this problem (to set velux online) ?

thanks and best regards
marcel


(Guenther Schreiner) #49

The KLF200 seems to be unreachable for the binding. What happens if you enter the URL manually within your webbrowser? Will the login web page be displayed? (BTW: you’re running the firmware v1, are you?)


(Marcel) #50

no, when i enter manual the url http://192.168.0.177:80/api/v1/auth the klf200 is not reachable.
my klf200 has version 0.2.0.0.71.0 -> should that version be supported?


(Guenther Schreiner) #51

Alright. If you are already on firmware version 0.2.*, the SLIP protocol should be used to control the KLF200. Therefore, please use the new binding which should run under OH2 in compatibility mode (don’t forget to use bridgeProtocol=slip, bridgeTCPPort=51200)


(Marcel) #52

hi guenther

thanks for your help. on github there are 3 jar-files … is file below the right one?

org.openhab.binding.velux-1.13.0-SNAPSHOT.jar


(Guenther Schreiner) #53

Yes, the v1.13 is the latest release (yet for OH1 - but should run under OH2 as well).


(Marcel) #54

I have copied the snapshot 1.13.0 in the addon folder have created the files below

velux.cfg

bridgeIPAddress=192.168.0.177
bridgeProtocol=slip
bridgeTCPPort=51200
bridgePassword=velux123
timeoutMsecs=2000
retries=6

velux.things

Bridge velux:klf200:home   [ bridgeIPAddress="192.168.0.177", bridgePassword="velux123", timeoutMsecs=2000, retries=10 ] 
{
  //Thing   scene   scWindow000    [ sceneName="Window000" ] 
}

velux.items

String  V_FIRMWARE  "Firmware [%s]"                 { velux="thing=bridge;channel=firmware" }
String  V_STATUS    "Status [%s]"                   { velux="thing=bridge;channel=status" }
String  V_CHECK     "Velux Config Check [%s]"           { velux="thing=bridge;channel=check" }

but after this, i have the error below:

2018-12-05 21:12:14.140 [INFO ] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): socket I/O failed continuously (6 times).

2018-12-05 21:12:14.150 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Shutting down Velux bridge connection.

2018-12-05 21:12:14.158 [WARN ] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): method io() raised an error: Socket is closed.

2018-12-05 21:12:14.166 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): updating of item V_STATUS (type BRIDGE_STATUS) failed.

message after reboot

2018-12-05 21:17:23.001 [INFO ] [org.openhab.binding.velux           ] - FrameworkEvent INFO - org.openhab.binding.velux

org.osgi.framework.BundleException: The bundle class path entry "lib/gson-2.2.4.jar" could not be found for the bundle "osgi.identity; type="osgi.bundle"; version:Version="1.13.0.201811051916"; osgi.identity="org.openhab.binding.velux""
2018-12-05 21:34:16.887 [INFO ] [inding.velux.internal.VeluxActivator] - velux binding has been started.

2018-12-05 21:35:48.802 [INFO ] [.binding.velux.internal.VeluxBinding] - Active items are: [V_FIRMWARE, V_CHECK, V_STATUS].

2018-12-05 21:35:48.822 [INFO ] [.binding.velux.internal.VeluxBinding] - velux refresh interval set to 15000 milliseconds.

2018-12-05 21:35:48.836 [INFO ] [.binding.velux.internal.VeluxBinding] - veluxConfig[bridgeProtocol=slip,bridgeIPAddress=192.168.0.177,bridgeTCPPort=51200,bridgePassword=********,timeoutMsecs=2000,retries=6,refreshMsecs=15000,isBulkRetrievalEnabled=true]

2018-12-05 21:35:48.836 [INFO ] [b.core.service.AbstractActiveService] - velux Refresh Service has been started

2018-12-05 21:35:48.904 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2018-12-05 21:35:58.782 [WARN ] [.velux.handler.VeluxBridgeHandlerOH1] - velux bridge login sequence failed; expecting bridge is OFFLINE.

2018-12-05 21:36:00.804 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): updating of item V_STATUS (type BRIDGE_STATUS) failed.

2018-12-05 21:36:04.902 [WARN ] [.velux.handler.VeluxBridgeHandlerOH1] - velux bridge login sequence failed; expecting bridge is OFFLINE.

2018-12-05 21:36:06.918 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): updating of item V_STATUS (type BRIDGE_STATUS) failed.

2018-12-05 21:36:23.929 [WARN ] [.velux.handler.VeluxBridgeHandlerOH1] - velux bridge login sequence failed; expecting bridge is OFFLINE.

2018-12-05 21:36:25.943 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): updating of item V_STATUS (type BRIDGE_STATUS) failed.

2018-12-05 21:36:49.948 [WARN ] [.velux.handler.VeluxBridgeHandlerOH1] - velux bridge login sequence failed; expecting bridge is OFFLINE.

2018-12-05 21:36:51.975 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): updating of item V_STATUS (type BRIDGE_STATUS) failed.

what i’m doing wrong?

  • Ping to 192.168.0.177 is OK

(Guenther Schreiner) #55

The sequences look good - beside that the KLF200 is not responding.

Is the gateway for a longer time online already? There is an automatic sleeping mode which shuts down the SLIP port after 15 minutes not receiving a packet. Pls. try to power-cycle the KLF200 and reactivate the binding again.


(Stuart Hanlon) #56

That might explain why I’m struggling.

It’s a pretty strange thing for a manufacturer to include, oh well


(Marcel) #57

after restart the klf200 i have delete the binding in the addon folder, wait till binding stopped and copied again in the binding folder, but it doesnt connect … always login failed.

2018-12-06 20:33:38.505 [INFO ] [b.core.service.AbstractActiveService] - velux Refresh Service has been shut down

2018-12-06 20:33:47.863 [INFO ] [org.openhab.binding.velux           ] - FrameworkEvent INFO - org.openhab.binding.velux

org.osgi.framework.BundleException: The bundle class path entry "lib/gson-2.2.4.jar" could not be found for the bundle "osgi.identity; osgi.identity="org.openhab.binding.velux"; type="osgi.bundle"; version:Version="1.13.0.201811051916""

2018-12-06 20:33:47.871 [INFO ] [inding.velux.internal.VeluxActivator] - velux binding has been started.

2018-12-06 20:33:48.286 [INFO ] [.binding.velux.internal.VeluxBinding] - Active items are: [].

2018-12-06 20:33:48.296 [INFO ] [.binding.velux.internal.VeluxBinding] - velux refresh interval set to 15000 milliseconds.

2018-12-06 20:33:48.300 [INFO ] [.binding.velux.internal.VeluxBinding] - veluxConfig[bridgeProtocol=slip,bridgeIPAddress=192.168.0.177,bridgeTCPPort=51200,bridgePassword=********,timeoutMsecs=15000,retries=15,refreshMsecs=15000,isBulkRetrievalEnabled=true]

2018-12-06 20:33:48.300 [INFO ] [b.core.service.AbstractActiveService] - velux Refresh Service has been started

2018-12-06 20:34:04.212 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2018-12-06 20:34:24.265 [WARN ] [.velux.handler.VeluxBridgeHandlerOH1] - velux bridge login sequence failed; expecting bridge is OFFLINE.

2018-12-06 20:34:39.292 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): updating of item V_STATUS (type BRIDGE_STATUS) failed

i had snapshot 2.3.0 in the addon folder before … could that be a problem?


(Guenther Schreiner) #58

Please increase the log level to TRACE. Afterwards, a deactivation and reactivation of the bindung should lead to the output …

2018-12-06 21:55:40.048 [TRACE] [.o.b.v.h.VeluxBridgeHandlerOH1] - Initializing empty storage for existing scenes.
2018-12-06 21:55:40.050 [TRACE] [velux.bridge.VeluxBridgeScenes] - VeluxBridgeScenes(constructor) called.
2018-12-06 21:55:40.053 [TRACE] [b.v.things.VeluxExistingScenes] - VeluxExistingScenes() initializing.
2018-12-06 21:55:40.053 [TRACE] [.o.b.v.h.VeluxBridgeHandlerOH1] - VeluxBridgeHandlerOH1() done.
2018-12-06 21:55:40.054 [TRACE] [.b.velux.internal.VeluxBinding] - VeluxBinding(constructor) done.
2018-12-06 21:55:40.055 [TRACE] [.b.velux.internal.VeluxBinding] - setEventPublisher() called.
2018-12-06 21:55:40.056 [TRACE] [.b.velux.internal.VeluxBinding] - addBindingProvider() called.
2018-12-06 21:55:40.057 [TRACE] [.b.velux.internal.VeluxBinding] - allBindingsChanged() called.
2018-12-06 21:55:40.057 [TRACE] [.b.velux.internal.VeluxBinding] - getName() called.
2018-12-06 21:55:40.057 [TRACE] [.b.velux.internal.VeluxBinding] - getName() called.
2018-12-06 21:55:40.057 [TRACE] [.b.velux.internal.VeluxBinding] - activate() called.
2018-12-06 21:55:40.058 [TRACE] [.i.VeluxGenericBindingProvider] - getInBindingItemNames() returns [V_DG_O_S_SUNNY, V_DG_M_W, V_DG_OPEN, V_DG_O_S, V_DG_M_W_OPEN, V_DG_O_S_CLOSED, V_DG_M_W_UNLOCKED, V_ACTUATORS, V_DG_W_S, V_STATUS, V_DG_CLOSED, V_DG_SUNNY, V_DG_M_S_CLOSED, V_DG_M_W_CLOSED, V_FIRMWARE, V_CHECK, V_DG_M_S_SUNNY, V_DG_W_S_OPEN, V_DG_W_S_CLOSED, V_DG_O_S_OPEN, V_DG_M_S_OPEN, V_DG_W_S_SUNNY, V_DG_M_S].
2018-12-06 21:55:40.058 [INFO ] [.b.velux.internal.VeluxBinding] - Active items are: [V_DG_O_S_SUNNY, V_DG_M_W, V_DG_OPEN, V_DG_O_S, V_DG_M_W_OPEN, V_DG_O_S_CLOSED, V_DG_M_W_UNLOCKED, V_ACTUATORS, V_DG_W_S, V_STATUS, V_DG_CLOSED, V_DG_SUNNY, V_DG_M_S_CLOSED, V_DG_M_W_CLOSED, V_FIRMWARE, V_CHECK, V_DG_M_S_SUNNY, V_DG_W_S_OPEN, V_DG_W_S_CLOSED, V_DG_O_S_OPEN, V_DG_M_S_OPEN, V_DG_W_S_SUNNY, V_DG_M_S].
2018-12-06 21:55:40.070 [DEBUG] [.b.velux.internal.VeluxBinding] - updated() called with 8 dictionary entries.
2018-12-06 21:55:40.071 [DEBUG] [.b.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_PROTOCOL to slip.
2018-12-06 21:55:40.072 [DEBUG] [.b.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_IPADDRESS to 192.168.45.9.
2018-12-06 21:55:40.072 [DEBUG] [.b.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_TCPPORT to 51200.
2018-12-06 21:55:40.072 [DEBUG] [.b.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_PASSWORD to velux123.
2018-12-06 21:55:40.073 [DEBUG] [.b.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_TIMEOUT_MSECS to 500.
2018-12-06 21:55:40.073 [DEBUG] [.b.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_RETRIES to 16.
2018-12-06 21:55:40.073 [TRACE] [.b.velux.internal.VeluxBinding] - getName() called.
2018-12-06 21:55:40.074 [INFO ] [.b.velux.internal.VeluxBinding] - velux refresh interval set to 15000 milliseconds.
2018-12-06 21:55:40.074 [TRACE] [.b.velux.internal.VeluxBinding] - getRefreshInterval() returns 15000.
2018-12-06 21:55:40.075 [INFO ] [.service.AbstractActiveService] - velux Refresh Service has been started
2018-12-06 21:55:40.075 [INFO ] [.b.velux.internal.VeluxBinding] - veluxConfig[bridgeProtocol=slip,bridgeIPAddress=192.168.45.9,bridgeTCPPort=51200,bridgePassword=********,timeoutMsecs=500,retries=16,refreshMsecs=15000,isBulkRetrievalEnabled=true]
2018-12-06 21:55:40.076 [DEBUG] [.b.velux.internal.VeluxBinding] - execute() called.
2018-12-06 21:55:40.086 [TRACE] [.b.velux.internal.VeluxBinding] - execute(): working with VeluxBindingProvider org.openhab.binding.velux.internal.VeluxGenericBindingProvider@20ea06.
2018-12-06 21:55:40.086 [TRACE] [.i.VeluxGenericBindingProvider] - getInBindingItemNames() returns [V_DG_O_S_SUNNY, V_DG_M_W, V_DG_OPEN, V_DG_O_S, V_DG_M_W_OPEN, V_DG_O_S_CLOSED, V_DG_M_W_UNLOCKED, V_ACTUATORS, V_DG_W_S, V_STATUS, V_DG_CLOSED, V_DG_SUNNY, V_DG_M_S_CLOSED, V_DG_M_W_CLOSED, V_FIRMWARE, V_CHECK, V_DG_M_S_SUNNY, V_DG_W_S_OPEN, V_DG_W_S_CLOSED, V_DG_O_S_OPEN, V_DG_M_S_OPEN, V_DG_W_S_SUNNY, V_DG_M_S].
2018-12-06 21:55:40.087 [TRACE] [.i.VeluxGenericBindingProvider] - getConfigForItemName(V_DG_O_S_SUNNY) called.
...
2018-12-06 21:55:40.105 [TRACE] [.b.velux.internal.VeluxBinding] - execute(): refreshing item V_STATUS.
2018-12-06 21:55:40.106 [DEBUG] [.o.b.v.h.VeluxBridgeHandlerOH1] - handleCommandOnChannel(item=V_STATUS,command=null,config=org.openhab.binding.velux.internal.VeluxBindingConfig@e702f2,provider=org.openhab.binding.velux.internal.VeluxGenericBindingProvider@20ea06) called.
2018-12-06 21:55:40.106 [TRACE] [.o.b.v.h.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): work on updated bridge configuration parameters.
2018-12-06 21:55:40.107 [DEBUG] [.o.b.v.h.VeluxBridgeHandlerOH1] - bridgeParamsUpdated() called.
2018-12-06 21:55:40.107 [DEBUG] [.o.b.v.h.VeluxBridgeHandlerOH1] - bridgeParamsUpdated(): choosing SLIP as communication method.
2018-12-06 21:55:40.108 [TRACE] [nding.velux.bridge.VeluxBridge] - bridgeLogin() called.
2018-12-06 21:55:40.109 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2018-12-06 21:55:40.110 [TRACE] [.o.b.velux.bridge.slip.SClogin] - setPassword(velux123) called.
2018-12-06 21:55:40.110 [TRACE] [nding.velux.bridge.VeluxBridge] - bridgeCommunicate(Authenticate / login,unauthenticated) called.
2018-12-06 21:55:40.111 [TRACE] [nding.velux.bridge.VeluxBridge] - isAuthenticated() returns false.
2018-12-06 21:55:40.111 [TRACE] [nding.velux.bridge.VeluxBridge] - bridgeCommunicate(): no auth token available, continuing.
2018-12-06 21:55:40.112 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - bridgeAPI() called.
2018-12-06 21:55:40.112 [TRACE] [.b.v.bridge.slip.SlipBridgeAPI] - bridgeDirectCommunicate(org.openhab.binding.velux.bridge.slip.SClogin@d88176,false) called.
2018-12-06 21:55:40.113 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(Authenticate / login,unauthenticated) called.
2018-12-06 21:55:40.114 [DEBUG] [.v.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_PASSWORD_ENTER_REQ,unauthenticated) called.
2018-12-06 21:55:40.114 [DEBUG] [.v.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on request GW_PASSWORD_ENTER_REQ with 32 bytes of data.
2018-12-06 21:55:40.117 [TRACE] [o.b.v.b.slip.util.SlipEncoding] - SlipEncoding(constructor) for command 0x3000 with data size 32 called.
2018-12-06 21:55:40.123 [TRACE] [o.b.v.b.slip.util.SlipEncoding] - SlipEncoding(constructor) successfully initialized, storing bytes: 00 23 30 00 76 65 6C 75 78 31 32 33 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 51.
2018-12-06 21:55:40.127 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): transportEncoding=00 23 30 00 76 65 6C 75 78 31 32 33 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 51.
2018-12-06 21:55:40.130 [TRACE] [v.bridge.slip.util.SlipRFC1055] - encode() for data size 37 called.
2018-12-06 21:55:40.133 [TRACE] [v.bridge.slip.util.SlipRFC1055] - encode() provides transfer encoding: C0 00 23 30 00 76 65 6C 75 78 31 32 33 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 51 C0.
2018-12-06 21:55:40.134 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): sending 39 bytes to 192.168.45.9:51200.
2018-12-06 21:55:40.135 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - io(192.168.45.9,51200,39 bytes) called.
2018-12-06 21:55:40.135 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - io(): connecting to 192.168.45.9:51200.
2018-12-06 21:55:40.140 [DEBUG] [v.bridge.slip.io.SSLconnection] - SSLconnection(192.168.45.9,51200) called.
2018-12-06 21:55:40.141 [INFO ] [v.bridge.slip.io.SSLconnection] - Starting Velux bridge connection.
2018-12-06 21:55:40.142 [TRACE] [v.bridge.slip.io.SSLconnection] - SSLconnection(): creating socket...
2018-12-06 21:55:40.159 [TRACE] [v.bridge.slip.io.SSLconnection] - SSLconnection(): starting SSL handshake...
2018-12-06 21:55:44.937 [TRACE] [v.bridge.slip.io.SSLconnection] - SSLconnection() finished.
2018-12-06 21:55:44.944 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - io(): sending packet with 39 bytes: C0 00 23 30 00 76 65 6C 75 78 31 32 33 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 51 C0
2018-12-06 21:55:44.946 [TRACE] [v.bridge.slip.io.SSLconnection] - send() called, writing 39 bytes.
2018-12-06 21:55:44.954 [TRACE] [v.bridge.slip.io.SSLconnection] - send() finished after having send 39 bytes: C0 00 23 30 00 76 65 6C 75 78 31 32 33 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 51 C0 
2018-12-06 21:55:44.956 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - io(): wait time 500 msecs.
2018-12-06 21:55:45.457 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - io(): receiving bytes.
2018-12-06 21:55:45.458 [TRACE] [v.bridge.slip.io.SSLconnection] - receive() called.
2018-12-06 21:55:45.459 [TRACE] [v.bridge.slip.io.SSLconnection] - receive() finished after having read 8 bytes: C0 00 04 30 01 00 35 C0 
2018-12-06 21:55:45.461 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - io(): received packet with 8 bytes: C0 00 04 30 01 00 35 C0
2018-12-06 21:55:45.461 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - io() finished.
2018-12-06 21:55:45.462 [TRACE] [.v.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): received packet C0 00 04 30 01 00 35 C0.
2018-12-06 21:55:45.463 [TRACE] [v.bridge.slip.util.SlipRFC1055] - decode() for packet size 8 called.
2018-12-06 21:55:45.464 [TRACE] [v.bridge.slip.util.SlipRFC1055] - decode() provides payload: 00 04 30 01 00 35.
2018-12-06 21:55:45.465 [TRACE] [o.b.v.b.slip.util.SlipEncoding] - SlipEncoding(constructor) called for decoding a packet with size 6.

The interesting lines are:

[.v.bridge.slip.SlipVeluxBridge] - io(): connecting to 192.168.45.9:51200.
[v.bridge.slip.io.SSLconnection] - SSLconnection(192.168.45.9,51200) called.
[v.bridge.slip.io.SSLconnection] - Starting Velux bridge connection.
[v.bridge.slip.io.SSLconnection] - SSLconnection(): creating socket...
[v.bridge.slip.io.SSLconnection] - SSLconnection(): starting SSL handshake...
[v.bridge.slip.io.SSLconnection] - SSLconnection() finished.
[.v.bridge.slip.SlipVeluxBridge] - io(): sending packet with 39 bytes: C0 00 23 30 00 76 65 6C 75 78 31 32 33 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 51 C0
[v.bridge.slip.io.SSLconnection] - send() called, writing 39 bytes.

Let’s see, what’s happening there …


(Marcel) #59

i increase the debug level have compared with the log data of your post. it’s not the same, but i have trouble interpreting where the problem might be.
i also restarted the device before restarting the binding.

someone sees the problem in the following log-file?

2018-12-09 12:05:06.472 [INFO ] [b.core.service.AbstractActiveService] - velux Refresh Service has been shut down

2018-12-09 12:07:11.808 [DEBUG] [org.openhab.binding.velux           ] - BundleEvent INSTALLED - org.openhab.binding.velux

2018-12-09 12:07:17.178 [DEBUG] [org.openhab.binding.velux           ] - BundleEvent RESOLVED - org.openhab.binding.velux

2018-12-09 12:07:17.205 [DEBUG] [org.openhab.binding.velux           ] - BundleEvent STARTING - org.openhab.binding.velux

2018-12-09 12:07:17.229 [INFO ] [inding.velux.internal.VeluxActivator] - velux binding has been started.

2018-12-09 12:07:17.220 [INFO ] [org.openhab.binding.velux           ] - FrameworkEvent INFO - org.openhab.binding.velux

org.osgi.framework.BundleException: The bundle class path entry "lib/gson-2.2.4.jar" could not be found for the bundle "osgi.identity; osgi.identity="org.openhab.binding.velux"; type="osgi.bundle"; version:Version="1.13.0.201811051916""

2018-12-09 12:07:17.233 [DEBUG] [org.openhab.binding.velux           ] - BundleEvent STARTED - org.openhab.binding.velux

2018-12-09 12:07:17.320 [DEBUG] [org.openhab.binding.velux           ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.velux.VeluxBindingProvider}={service.id=454, service.bundleid=244, service.scope=bundle, component.name=org.openhab.binding.velux.genericbindingprovider, component.id=272} - org.openhab.binding.velux

2018-12-09 12:07:17.390 [DEBUG] [internal.VeluxGenericBindingProvider] - VeluxGenericBindingParser() channelIdentifier=firmware, channelValue=.

2018-12-09 12:07:17.405 [DEBUG] [internal.VeluxGenericBindingProvider] - validateItemType() returned w/o exception.

2018-12-09 12:07:17.412 [DEBUG] [internal.VeluxGenericBindingProvider] - VeluxGenericBindingParser() channelIdentifier=firmware, channelValue=.

2018-12-09 12:07:17.420 [DEBUG] [internal.VeluxGenericBindingProvider] - processBindingConfiguration(Z_Test.items,V_FIRMWARE,thing=bridge;channel=firmware) successfully finished.

2018-12-09 12:07:17.426 [DEBUG] [internal.VeluxGenericBindingProvider] - VeluxGenericBindingParser() channelIdentifier=status, channelValue=.

2018-12-09 12:07:17.430 [DEBUG] [internal.VeluxGenericBindingProvider] - validateItemType() returned w/o exception.

2018-12-09 12:07:17.435 [DEBUG] [internal.VeluxGenericBindingProvider] - VeluxGenericBindingParser() channelIdentifier=status, channelValue=.

2018-12-09 12:07:17.440 [DEBUG] [internal.VeluxGenericBindingProvider] - processBindingConfiguration(Z_Test.items,V_STATUS,thing=bridge;channel=status) successfully finished.

2018-12-09 12:07:17.445 [DEBUG] [internal.VeluxGenericBindingProvider] - VeluxGenericBindingParser() channelIdentifier=check, channelValue=.

2018-12-09 12:07:17.450 [DEBUG] [internal.VeluxGenericBindingProvider] - validateItemType() returned w/o exception.

2018-12-09 12:07:17.454 [DEBUG] [internal.VeluxGenericBindingProvider] - VeluxGenericBindingParser() channelIdentifier=check, channelValue=.

2018-12-09 12:07:17.459 [DEBUG] [internal.VeluxGenericBindingProvider] - processBindingConfiguration(Z_Test.items,V_CHECK,thing=bridge;channel=check) successfully finished.

2018-12-09 12:07:17.470 [DEBUG] [org.openhab.binding.velux           ] - ServiceEvent REGISTERED - {org.osgi.service.cm.ManagedService, org.osgi.service.event.EventHandler}={service.id=456, service.bundleid=244, service.scope=bundle, event.topics=openhab/*, service.pid=org.openhab.velux, component.name=org.openhab.binding.velux.binding, component.id=271} - org.openhab.binding.velux

2018-12-09 12:07:17.545 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - VeluxBridgeHandlerOH1(constructor) called.

2018-12-09 12:07:17.949 [DEBUG] [.velux.bridge.slip.SCidentifyProduct] - SCidentifyProduct(Constructor) called.

2018-12-09 12:07:17.952 [DEBUG] [.velux.bridge.slip.SCidentifyProduct] - SCidentifyProduct(): starting sessions with the random number 890.

2018-12-09 12:07:18.046 [DEBUG] [binding.velux.bridge.slip.SCrunScene] - SCrunScene(Constructor) called.

2018-12-09 12:07:18.051 [DEBUG] [binding.velux.bridge.slip.SCrunScene] - SCrunScene(): starting sessions with the random number 3954.

2018-12-09 12:07:18.084 [DEBUG] [ding.velux.bridge.slip.SCsendCommand] - SCgetProduct(Constructor) called.

2018-12-09 12:07:18.089 [DEBUG] [ding.velux.bridge.slip.SCsendCommand] - SCgetProduct(): starting sessions with the random number 610.

2018-12-09 12:07:18.144 [INFO ] [.binding.velux.internal.VeluxBinding] - Active items are: [V_FIRMWARE, V_CHECK, V_STATUS].

2018-12-09 12:07:18.154 [DEBUG] [.binding.velux.internal.VeluxBinding] - updated() called with 8 dictionary entries.

2018-12-09 12:07:18.158 [DEBUG] [.binding.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_PROTOCOL to slip.

2018-12-09 12:07:18.162 [DEBUG] [.binding.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_IPADDRESS to 192.168.0.177.

2018-12-09 12:07:18.166 [DEBUG] [.binding.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_TCPPORT to 51200.

2018-12-09 12:07:18.172 [DEBUG] [.binding.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_PASSWORD to velux123.

2018-12-09 12:07:18.178 [DEBUG] [.binding.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_TIMEOUT_MSECS to 15000.

2018-12-09 12:07:18.184 [DEBUG] [.binding.velux.internal.VeluxBinding] - updated(): adapted BRIDGE_RETRIES to 15.

2018-12-09 12:07:18.189 [INFO ] [.binding.velux.internal.VeluxBinding] - velux refresh interval set to 15000 milliseconds.

2018-12-09 12:07:18.196 [INFO ] [.binding.velux.internal.VeluxBinding] - veluxConfig[bridgeProtocol=slip,bridgeIPAddress=192.168.0.177,bridgeTCPPort=51200,bridgePassword=********,timeoutMsecs=15000,retries=15,refreshMsecs=15000,isBulkRetrievalEnabled=true]

2018-12-09 12:07:18.195 [INFO ] [b.core.service.AbstractActiveService] - velux Refresh Service has been started

2018-12-09 12:07:18.201 [DEBUG] [.binding.velux.internal.VeluxBinding] - execute() called.

2018-12-09 12:07:18.213 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(item=V_STATUS,command=null,config=org.openhab.binding.velux.internal.VeluxBindingConfig@6f4a3f,provider=org.openhab.binding.velux.internal.VeluxGenericBindingProvider@a8a4c2) called.

2018-12-09 12:07:18.216 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - bridgeParamsUpdated() called.

2018-12-09 12:07:18.219 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - bridgeParamsUpdated(): choosing SLIP as communication method.

2018-12-09 12:07:18.224 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_PASSWORD_ENTER_REQ,unauthenticated) called.

2018-12-09 12:07:18.227 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on request GW_PASSWORD_ENTER_REQ with 32 bytes of data.

2018-12-09 12:07:18.271 [DEBUG] [g.velux.bridge.slip.io.SSLconnection] - SSLconnection(192.168.0.177,51200) called.

2018-12-09 12:07:18.275 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2018-12-09 12:07:23.324 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): sending packet of size 39.

2018-12-09 12:07:38.332 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): received packet with 8 bytes.

2018-12-09 12:07:38.339 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on response GW_PASSWORD_ENTER_CFM with 1 bytes of data.

2018-12-09 12:07:38.349 [DEBUG] [ab.binding.velux.bridge.slip.SClogin] - setResponse(GW_PASSWORD_ENTER_CFM with 1 bytes of data) called.

2018-12-09 12:07:38.357 [DEBUG] [ab.binding.velux.bridge.slip.SClogin] - setResponse(): returned status: The request failed.

2018-12-09 12:07:38.360 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_PASSWORD_ENTER_REQ) returns failure.

2018-12-09 12:07:38.363 [WARN ] [.velux.handler.VeluxBridgeHandlerOH1] - velux bridge login sequence failed; expecting bridge is OFFLINE.

2018-12-09 12:07:38.373 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_PASSWORD_ENTER_REQ,unauthenticated) called.

2018-12-09 12:07:38.376 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on request GW_PASSWORD_ENTER_REQ with 32 bytes of data.

2018-12-09 12:07:38.391 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): sending packet of size 39.

2018-12-09 12:07:53.396 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): received packet with 8 bytes.

2018-12-09 12:07:53.402 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on response GW_PASSWORD_ENTER_CFM with 1 bytes of data.

2018-12-09 12:07:53.405 [DEBUG] [ab.binding.velux.bridge.slip.SClogin] - setResponse(GW_PASSWORD_ENTER_CFM with 1 bytes of data) called.

2018-12-09 12:07:53.407 [DEBUG] [ab.binding.velux.bridge.slip.SClogin] - setResponse(): returned status: The request failed.

2018-12-09 12:07:53.410 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_PASSWORD_ENTER_REQ) returns failure.

2018-12-09 12:07:53.413 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): updating of item V_STATUS (type BRIDGE_STATUS) failed.

2018-12-09 12:07:53.416 [DEBUG] [.binding.velux.internal.VeluxBinding] - execute() done.

2018-12-09 12:07:53.420 [DEBUG] [.binding.velux.internal.VeluxBinding] - execute() called.

2018-12-09 12:07:53.423 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(item=V_STATUS,command=null,config=org.openhab.binding.velux.internal.VeluxBindingConfig@6f4a3f,provider=org.openhab.binding.velux.internal.VeluxGenericBindingProvider@a8a4c2) called.

2018-12-09 12:07:53.434 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - bridgeParamsUpdated() called.

2018-12-09 12:07:53.437 [DEBUG] [.velux.handler.VeluxBridgeHandlerOH1] - bridgeParamsUpdated(): choosing SLIP as communication method.

2018-12-09 12:07:53.445 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_PASSWORD_ENTER_REQ,unauthenticated) called.

2018-12-09 12:07:53.448 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on request GW_PASSWORD_ENTER_REQ with 32 bytes of data.

2018-12-09 12:07:53.461 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): sending packet of size 39.

2018-12-09 12:08:08.489 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): received packet with 8 bytes.

2018-12-09 12:08:08.495 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on response GW_PASSWORD_ENTER_CFM with 1 bytes of data.

2018-12-09 12:08:08.498 [DEBUG] [ab.binding.velux.bridge.slip.SClogin] - setResponse(GW_PASSWORD_ENTER_CFM with 1 bytes of data) called.

2018-12-09 12:08:08.500 [DEBUG] [ab.binding.velux.bridge.slip.SClogin] - setResponse(): returned status: The request failed.

2018-12-09 12:08:08.503 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(GW_PASSWORD_ENTER_REQ) returns failure.

2018-12-09 12:08:08.506 [WARN ] [.velux.handler.VeluxBridgeHandlerOH1] - velux bridge login sequence failed; expecting bridge is OFFLINE.

Thank you very much for your help.


(Guenther Schreiner) #60

Marcel, thanks for the log file. There is one good and one bad point.

Starting with the good one:

2018-12-09 12:07:18.271 [DEBUG] [g.velux.bridge.slip.io.SSLconnection] - SSLconnection(192.168.0.177,51200) called.
2018-12-09 12:07:18.275 [INFO ] [g.velux.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2018-12-09 12:07:23.324 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): sending packet of size 39.
2018-12-09 12:07:38.332 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - io(): received packet with 8 bytes.

As you can see, the gateway is successfully receiving and responding to the inital login sequence. Therefore, the configuration part of the openHAB is completely ok.

Coming to the bad point:

2018-12-09 12:07:38.339 [DEBUG] [ng.velux.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate(): working on response GW_PASSWORD_ENTER_CFM with 1 bytes of data.
2018-12-09 12:07:38.349 [DEBUG] [ab.binding.velux.bridge.slip.SClogin] - setResponse(GW_PASSWORD_ENTER_CFM with 1 bytes of data) called.
2018-12-09 12:07:38.357 [DEBUG] [ab.binding.velux.bridge.slip.SClogin] - setResponse(): returned status: The request failed.

The gateway does not allow you to login in. Quoting the manual (KLF 200 API Version: 3.16, io-homecontrol® Gateway 02-11-2018):

Client must authenticate after TLS socket has been established, using a password.
The default password is the same as Wi-Fi password written on back side of KLF200.
The user can change the password. The password is reset to Wi-Fi password if factory
reset is requested.

Question: did you change the password via the web interface?