Autelis works in OH1 not OH2

@digitaldan

I’m trying my best to migrate over to OH2. My first attempt has been to get my pool control working in OH2. I have added the Autelis binding, and added the details it requires in the configuration portion - but the device always stays offline or offline-communication error. I am using the same settings (ip address, un, pw, etc) in OH1 and everything connects fine…

Any guidance on what I may be doing wrong? Do I manually have to create a thing? When I added the binding and filled out the configuration information a pool control thing is now present.

The lack of documentation for OH2 is really frustrating…

OH2 status:

OH1 status:

Can you check the log file for errors or any other messages?

@digitaldan

Here’s the output of the log file…

2016-10-29 16:03:21.959 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from UNINITIALIZED to INITIALIZING
2016-10-29 16:03:21.959 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from INITIALIZING to ONLINE
2016-10-29 16:03:21.975 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR)
2016-10-29 16:03:22.225 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from OFFLINE (CONFIGURATION_ERROR) to OFFLINE (COMMUNICATION_ERROR)
2016-10-29 16:04:37.026 [ThingUpdatedEvent         ] - Thing 'autelis:poolcontrol:0eaefaf7' has been updated.
2016-10-29 16:04:37.026 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2016-10-29 16:04:37.026 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR)
2016-10-29 16:04:39.647 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from OFFLINE (CONFIGURATION_ERROR) to OFFLINE (COMMUNICATION_ERROR)
2016-10-29 16:12:03.208 [ItemCommandEvent          ] - Item 'autelis_poolcontrol_0eaefaf7_equipment_circuit2' received command ON
2016-10-29 16:12:03.208 [ItemStateChangedEvent     ] - autelis_poolcontrol_0eaefaf7_equipment_circuit2 changed from NULL to ON
2016-10-29 16:12:04.284 [ItemCommandEvent          ] - Item 'autelis_poolcontrol_0eaefaf7_equipment_circuit2' received command OFF
2016-10-29 16:12:04.284 [ItemStateChangedEvent     ] - autelis_poolcontrol_0eaefaf7_equipment_circuit2 changed from ON to OFF
2016-10-29 16:27:01.769 [ThingUpdatedEvent         ] - Thing 'autelis:poolcontrol:0eaefaf7' has been updated.
2016-10-29 16:27:01.773 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2016-10-29 16:27:01.780 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from OFFLINE (CONFIGURATION_ERROR) to OFFLINE (COMMUNICATION_ERROR)
2016-10-29 16:27:01.780 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR)
2016-10-29 16:27:28.692 [ThingUpdatedEvent         ] - Thing 'autelis:poolcontrol:0eaefaf7' has been updated.
2016-10-29 16:27:28.692 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2016-10-29 16:27:28.708 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR)
2016-10-29 16:27:28.882 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from OFFLINE (CONFIGURATION_ERROR) to OFFLINE (COMMUNICATION_ERROR)
2016-10-29 16:27:28.897 [ThingUpdatedEvent         ] - Thing 'autelis:poolcontrol:0eaefaf7' has been updated.
2016-10-29 16:27:28.897 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from OFFLINE (CONFIGURATION_ERROR) to ONLINE
2016-10-29 16:27:28.913 [hingStatusInfoChangedEvent] - 'autelis:poolcontrol:0eaefaf7' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR)

Anyone have any thoughts???

@digitaldan

Sorry! I am traveling to a conference this week and not very responsive. In the paper UI if you go to Configuration -> Things -> Autelis Pool Control and click edit, do the config fields there all look ok? Also is that the openhab.log file or the event.log file? I would expect INFO DEBUG or WARN messages printed there, can you make sure you are looking at openhab.log vs events?

@digitaldan

Everything looks good in the configuration

Sorry I did post the event log, not openhab…see contents below.

2016-11-04 20:51:24.582 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2016-11-04 20:51:24.629 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-11-04 20:51:24.660 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-11-04 20:51:24.691 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-11-04 20:51:24.722 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-package-standard': Error restarting bundles
2016-11-04 20:51:24.722 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-package-standard': Error restarting bundles
2016-11-04 20:52:42.181 [INFO ] [assic.internal.servlet.WebAppServlet] - Stopped Classic UI
2016-11-04 20:52:42.235 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2016-11-04 20:52:42.616 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-11-04 20:52:42.681 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app

I see nothing referencing Autelis

I just did a fresh install of OH2 B4 to make sure I had a virgin palette to work on. I only added the Autelis binding and wind up with the same results.

Here’s the new log file

2016-11-04 21:12:59.610 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-11-04 21:12:59.657 [INFO ] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-package-standard'
2016-11-04 21:12:59.657 [INFO ] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-package-standard'
2016-11-04 21:12:59.751 [INFO ] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-package-standard'
2016-11-04 21:13:44.273 [WARN ] [.service.internal.HttpServiceStopped] - Http service has already been stopped
2016-11-04 21:13:44.273 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2016-11-04 21:13:44.273 [ERROR] [org.apache.felix.scr                ] - Error while disposing components of bundle org.eclipse.smarthome.ui.paper/180
java.lang.IllegalStateException: BundleContext is no longer valid
	at org.eclipse.osgi.internal.framework.BundleContextImpl.checkValid(BundleContextImpl.java:983)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.ungetService(BundleContextImpl.java:659)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.osgi.util.tracker.ServiceTracker.removedService(ServiceTracker.java:459)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:967)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.untrack(AbstractTracked.java:341)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker.close(ServiceTracker.java:377)[org.osgi.core-6.0.0.jar:]
	at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:549)
	at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:414)
	at org.apache.felix.scr.impl.Activator.access$300(Activator.java:53)
	at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:273)
	at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)[:1.8.0_111]
	at java.util.concurrent.FutureTask.run(Unknown Source)[:1.8.0_111]
	at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)
	at org.apache.felix.utils.extender.AbstractExtender.stop(AbstractExtender.java:125)
	at org.apache.felix.scr.impl.Activator.stop(Activator.java:179)
	at org.eclipse.osgi.internal.framework.BundleContextImpl$4.run(BundleContextImpl.java:827)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl$4.run(BundleContextImpl.java:1)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_111]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.stop(BundleContextImpl.java:820)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.stopWorker0(EquinoxBundle.java:950)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.stopWorker(EquinoxBundle.java:324)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.doStop(Module.java:626)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1623)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1542)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:248)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:145)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.doStop(Module.java:626)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:186)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:160)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.lang.Thread.run(Unknown Source)[:1.8.0_111]
2016-11-04 21:14:13.675 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-11-04 21:14:13.767 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-11-04 21:14:13.845 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-11-04 21:14:13.894 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start

Can you run the console client to enable debug logging? On linux this would be something like:

/usr/share/openhab2/runtime/karaf/bin/client

or depending on how you install openhab, maybe

/usr/local/openhab2/runtime/karaf/bin/client

Once that loads enter

log:set DEBUG org.openhab.binding.autelis

to exit use ctrl-d

That should produce more logging, you can either restart openHAB or use the cli client above to restart the bundle, like

bundle:list
bundle:restart xxx

where xxx is the bundle id for the autelis binding from the bundle:list command above.

@digitaldan

Hi Dan -

I’ve done as you’ve asked…here’s whats in the log file since the restart of the binding

2016-11-04 21:14:13.675 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-11-04 21:14:13.767 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-11-04 21:14:13.845 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-11-04 21:14:13.894 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2016-11-05 13:08:06.784 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:08:11.806 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:08:16.782 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:08:21.790 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:08:26.782 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:08:31.789 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:08:36.798 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:08:41.790 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:08:46.782 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:08:51.789 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:08:56.781 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:01.789 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:06.781 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:11.793 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:16.785 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:21.808 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:23.805 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.DiscoveryService}={component.name=org.openhab.binding.autelis.discovery.AutelisDiscoveryService, component.id=155, service.id=285, service.bundleid=188, service.scope=bundle} - org.openhab.binding.autelis
2016-11-05 13:09:23.805 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.autelis.internal.AutelisHandlerFactory, component.id=156, service.id=286, service.bundleid=188, service.scope=bundle} - org.openhab.binding.autelis
2016-11-05 13:09:23.821 [DEBUG] [nding.autelis.handler.AutelisHandler] - Handler disposed.
2016-11-05 13:09:23.836 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=autelis:poolcontrol, thing.id=autelis:poolcontrol:e0459fe4, service.id=287, service.bundleid=188, service.scope=singleton} - org.openhab.binding.autelis
2016-11-05 13:09:23.836 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent STOPPING - org.openhab.binding.autelis
2016-11-05 13:09:23.836 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent STOPPED - org.openhab.binding.autelis
2016-11-05 13:09:23.836 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent STARTING - org.openhab.binding.autelis
2016-11-05 13:09:23.857 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={component.name=org.openhab.binding.autelis.discovery.AutelisDiscoveryService, component.id=157, service.id=288, service.bundleid=188, service.scope=bundle} - org.openhab.binding.autelis
2016-11-05 13:09:23.863 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=autelis:poolcontrol, thing.id=autelis:poolcontrol:e0459fe4, service.id=290, service.bundleid=188, service.scope=singleton} - org.openhab.binding.autelis
2016-11-05 13:09:23.864 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.autelis.internal.AutelisHandlerFactory, component.id=158, service.id=289, service.bundleid=188, service.scope=bundle} - org.openhab.binding.autelis
2016-11-05 13:09:23.865 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent STARTED - org.openhab.binding.autelis
2016-11-05 13:09:23.896 [DEBUG] [nding.autelis.handler.AutelisHandler] - Autelius binding configured with base url http://10.5.1.30:80 and refresh period of 5
2016-11-05 13:09:24.102 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:26.461 [DEBUG] [is.discovery.AutelisDiscoveryService] - Error accessing url 'http://poolcontrol/app.html' : poolcontrol 
2016-11-05 13:09:29.082 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:34.090 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:39.082 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:44.081 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-05 13:09:49.071 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found

@digitaldan

Dan - Any advice?

Sorry, not multitasking very well, what happens when you try and hit “http://poolcontrol/app.html” in your browser or better yet using curl or wget from the box running openhab? Is “poolcontrol” the correct hostname for your controller? BTW I need to go back and implement proper discovery of the Autelis device, at the time I did not realize that Autelis supported UPNP. My first thought is that whatever that host is resolving to on your box is not the actually Autelis device.

@digitaldan

Dan - appreciate your help and time.

My Autelis has never responded to http://poolcontrol. I have a static IP address configured for it and it has it’s own FQDN which is resolved via my own DNS server at the house. I have added both the IP address and the FQDN pool.xxx.xxx to the Configuration Parameters of the binding via Paper UI and it looks like those parameters are ignored.

If i enter:

http://10.5.1.30/app.html
-or-
http://pool.xxx.xxx/app.html

The page is displayed properly…is your binding not looking at the configuration parameters?

I just tried on my system, and it definitely respects the host option. I have an updated version of the binding that uses proper UPNP to discover the device, let me test that today and I will post an updated jar for you. Just to be clear, if you enter 10.5.1.30 in that field (no http:// prefifix) you get the same error?

@digitaldan

Is it respecting the host option if http://poolcontrol works?? - just a thought

Yes, if I enter either the IP address, 10.5.1.30 or the domain name neither works - I get the communication error…what’s really weird is this works in OH1.

Happy to try any options you may have.

Thanks for your help in looking into this.

I went ahead and added proper UPNP discovery to the binding, you can wait for it to getinto the nightlies or grab a version here:

Let me know if this helps at all, I’m not sure whats going on with you setup. Actually, can you describe what your oh2 environment looks like and if it differs from your OH1 instance?

Dan -

I’ve added the new snapshot along with the UPNP jar and unfortunately am still having no luck.

Here’s the log:

2016-11-11 18:37:58.415 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-11-11 18:37:58.540 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-11-11 18:37:58.821 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-11-11 18:37:58.930 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2016-11-11 18:37:59.008 [INFO ] [ulation.internal.HueEmulationServlet] - Started Hue Emulation service at /api
2016-11-11 18:37:59.070 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent STARTING - org.openhab.binding.autelis
2016-11-11 18:37:59.086 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={component.name=org.openhab.binding.autelis.discovery.AutelisDiscoveryService, component.id=154, service.id=284, service.bundleid=190, service.scope=bundle} - org.openhab.binding.autelis
2016-11-11 18:37:59.102 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.autelis.internal.AutelisHandlerFactory, component.id=155, service.id=286, service.bundleid=190, service.scope=bundle} - org.openhab.binding.autelis
2016-11-11 18:37:59.102 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent STARTED - org.openhab.binding.autelis
2016-11-11 18:37:59.211 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2016-11-11 18:39:28.827 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=autelis:poolcontrol, thing.id=autelis:poolcontrol:a3da2858, service.id=297, service.bundleid=190, service.scope=singleton} - org.openhab.binding.autelis
2016-11-11 18:39:28.874 [DEBUG] [nding.autelis.handler.AutelisHandler] - Autelius binding configured with base url http://10.5.1.30:80 and refresh period of 5
2016-11-11 18:39:29.141 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-11 18:39:34.054 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-11 18:39:39.054 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-11 18:39:44.053 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found
2016-11-11 18:39:49.081 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed: 404 Not found

If I point my browser to: http://10.5.1.30/app.html I get the webpage…see below

Environment is a Windows 2008R2 server, running OHB4

Any thoughts?

yes this is very strange, can you try downloading the jar again from https://github.com/digitaldan/openhab2-addons/releases/tag/autelis-upnp ? Kai fixed that missing dependency issue ( i broke the build!) and I added some additional logging to see what URL’s we are attempting to hit when we get that 404 message.

Dan -

I’ve downloaded the new jar and run:

Here is the log:

2016-11-12 09:13:01.368 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent UNRESOLVED - org.openhab.binding.autelis
2016-11-12 09:13:01.384 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent UPDATED - org.openhab.binding.autelis
2016-11-12 09:13:01.477 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent RESOLVED - org.openhab.binding.autelis
2016-11-12 09:13:01.477 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent STARTING - org.openhab.binding.autelis
2016-11-12 09:13:01.477 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent STARTED - org.openhab.binding.autelis
2016-11-12 09:13:01.493 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={component.name=org.openhab.binding.autelis.discovery.AutelisDiscoveryService, component.id=72, service.id=184, service.bundleid=190, service.scope=bundle} - org.openhab.binding.autelis
2016-11-12 09:13:01.509 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.autelis.internal.AutelisHandlerFactory, component.id=76, service.id=188, service.bundleid=190, service.scope=bundle} - org.openhab.binding.autelis
2016-11-12 09:13:04.535 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=autelis:poolcontrol, thing.id=autelis:poolcontrol:a3da2858, service.id=217, service.bundleid=190, service.scope=singleton} - org.openhab.binding.autelis
2016-11-12 09:13:04.582 [DEBUG] [nding.autelis.handler.AutelisHandler] - Autelius binding configured with base url http://10.5.1.30:80 and refresh period of 5
2016-11-12 09:13:04.847 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed for http://10.5.1.30:80/chem.xml?timestamp=1478963584816 : 404 Not found
2016-11-12 09:13:05.908 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-11-12 09:13:06.438 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-11-12 09:13:06.547 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-11-12 09:13:06.735 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2016-11-12 09:13:06.937 [INFO ] [ulation.internal.HueEmulationServlet] - Started Hue Emulation service at /api
2016-11-12 09:13:07.312 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2016-11-12 09:13:09.777 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed for http://10.5.1.30:80/chem.xml?timestamp=1478963589745 : 404 Not found
2016-11-12 09:13:14.769 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed for http://10.5.1.30:80/chem.xml?timestamp=1478963594753 : 404 Not found

Attempting to browse to http://10.5.1.30/chem.xml does indeed return a 404 error. I’ve never seen the http://10.5.1.30/chem.xml page I’ve only known of the http://10.5.1.30/status.xml could this be a rev of firmware on the Autelis?

I think I have it! Can you try downloading again? You will still see the chem 404 errors under debug logging, but it should ignore those now

Lots more stuff in the log…

2016-11-12 09:54:04.549 [WARN ] [org.apache.felix.fileinstall        ] - Failed to update artifact C:\OpenHab\addons\org.openhab.binding.autelis-2.0.0-SNAPSHOT.jar
org.osgi.framework.BundleException: A bundle is already installed with the name "org.openhab.binding.autelis" and version "2.0.0.201611121528"
	at org.eclipse.osgi.container.ModuleContainer.update(ModuleContainer.java:327)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.storage.Storage.update(Storage.java:713)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.update(EquinoxBundle.java:439)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.update(DirectoryWatcher.java:1128)[8:org.apache.felix.fileinstall:3.5.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.update(DirectoryWatcher.java:900)[8:org.apache.felix.fileinstall:3.5.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:481)[8:org.apache.felix.fileinstall:3.5.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:358)[8:org.apache.felix.fileinstall:3.5.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:310)[8:org.apache.felix.fileinstall:3.5.0]
2016-11-12 09:54:04.627 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent UNRESOLVED - org.openhab.binding.autelis
2016-11-12 09:54:04.642 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent RESOLVED - org.openhab.binding.autelis
2016-11-12 09:54:04.658 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent STARTING - org.openhab.binding.autelis
2016-11-12 09:54:04.705 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={component.name=org.openhab.binding.autelis.discovery.AutelisDiscoveryService, component.id=0, service.id=122, service.bundleid=193, service.scope=bundle} - org.openhab.binding.autelis
2016-11-12 09:54:04.736 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.autelis.internal.AutelisHandlerFactory, component.id=1, service.id=123, service.bundleid=193, service.scope=bundle} - org.openhab.binding.autelis
2016-11-12 09:54:04.751 [DEBUG] [org.openhab.binding.autelis         ] - BundleEvent STARTED - org.openhab.binding.autelis
2016-11-12 09:54:04.876 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/C:/OpenHab/addons/org.openhab.binding.autelis-2.0.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.autelis [190]
  Another singleton bundle selected: osgi.identity; osgi.identity="org.openhab.binding.autelis"; type="osgi.bundle"; version:Version="2.0.0.201611121528"; singleton:="true"

	at org.eclipse.osgi.container.Module.start(Module.java:434)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:393)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1245)[8:org.apache.felix.fileinstall:3.5.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1217)[8:org.apache.felix.fileinstall:3.5.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startAllBundles(DirectoryWatcher.java:1207)[8:org.apache.felix.fileinstall:3.5.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:504)[8:org.apache.felix.fileinstall:3.5.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:358)[8:org.apache.felix.fileinstall:3.5.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:310)[8:org.apache.felix.fileinstall:3.5.0]
2016-11-12 09:54:09.088 [DEBUG] [org.openhab.binding.autelis         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=autelis:poolcontrol, thing.id=autelis:poolcontrol:a3da2858, service.id=222, service.bundleid=193, service.scope=singleton} - org.openhab.binding.autelis
2016-11-12 09:54:09.104 [DEBUG] [nding.autelis.handler.AutelisHandler] - Autelius binding configured with base url http://10.5.1.30:80 and refresh period of 5
2016-11-12 09:54:09.447 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed for http://10.5.1.30:80/chem.xml?timestamp=1478966049416 : 404 Not found
2016-11-12 09:54:09.478 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed for http://10.5.1.30:80/pumps.xml?timestamp=1478966049447 : 404 Not found
2016-11-12 09:54:10.227 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-11-12 09:54:10.711 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-11-12 09:54:11.662 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-11-12 09:54:12.551 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2016-11-12 09:54:12.629 [INFO ] [ulation.internal.HueEmulationServlet] - Started Hue Emulation service at /api
2016-11-12 09:54:12.957 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2016-11-12 09:54:13.066 [ERROR] [org.openhab.binding.autelis         ] - FrameworkEvent ERROR - org.openhab.binding.autelis
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.autelis [190]
  Another singleton bundle selected: osgi.identity; osgi.identity="org.openhab.binding.autelis"; type="osgi.bundle"; version:Version="2.0.0.201611121528"; singleton:="true"

	at org.eclipse.osgi.container.Module.start(Module.java:434)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1582)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1562)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1533)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1476)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
2016-11-12 09:54:14.314 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed for http://10.5.1.30:80/chem.xml?timestamp=1478966054283 : 404 Not found
2016-11-12 09:54:14.330 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed for http://10.5.1.30:80/pumps.xml?timestamp=1478966054314 : 404 Not found
2016-11-12 09:54:19.291 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed for http://10.5.1.30:80/chem.xml?timestamp=1478966059259 : 404 Not found
2016-11-12 09:54:19.322 [DEBUG] [nding.autelis.handler.AutelisHandler] - Method failed for http://10.5.1.30:80/pumps.xml?timestamp=1478966059291 : 404 Not found