"Failed to register UPnP servlet!" at start of openhab2 demo - Help

The openhab 2 demo and runtime from cloudbees show an error that I did not expect. The demo works as I expected. The same error occurs when I use the runtime with my own configuration. Is this an error in the runtime or did I do something wrong ? Below is the content of my openhab.log.

Gert Könemann

2015-09-02 23:06:32.928 [INFO ] [ui.internal.servlet.PaperUIApp] - Started Paper UI at /ui
2015-09-02 23:06:33.521 [ERROR] [ServiceServletContainerAdapter] - Failed to register UPnP servlet!
org.osgi.service.http.NamespaceException: The alias ‘/upnpcallback’ is already in use.
at org.eclipse.equinox.http.servlet.internal.ProxyServlet.registerServlet(ProxyServlet.java:169) ~[na:na]
at org.eclipse.equinox.http.servlet.internal.HttpServiceImpl.registerServlet(HttpServiceImpl.java:66) ~[na:na]
at org.jupnp.transport.impl.osgi.HttpServiceServletContainerAdapter.registerServlet(HttpServiceServletContainerAdapter.java:73) ~[org.jupnp_2.0.0.201508200936.jar:na]
at org.jupnp.transport.impl.ServletStreamServerImpl.init(ServletStreamServerImpl.java:71) [org.jupnp_2.0.0.201508200936.jar:na]
at org.jupnp.transport.RouterImpl.startAddressBasedTransports(RouterImpl.java:422) [org.jupnp_2.0.0.201508200936.jar:na]
at org.jupnp.transport.RouterImpl.enable(RouterImpl.java:125) [org.jupnp_2.0.0.201508200936.jar:na]
at org.jupnp.UpnpServiceImpl.startup(UpnpServiceImpl.java:258) [org.jupnp_2.0.0.201508200936.jar:na]
at org.jupnp.UpnpServiceImpl.activate(UpnpServiceImpl.java:277) [org.jupnp_2.0.0.201508200936.jar:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_75]
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:1.7.0_75]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.7.0_75]
at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.7.0_75]
at org.eclipse.equinox.internal.ds.model.ServiceComponent.activate(ServiceComponent.java:235) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.activate(ServiceComponentProp.java:146) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.build(ServiceComponentProp.java:345) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponent(InstanceProcess.java:620) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:197) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.Resolver.getEligible(Resolver.java:343) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.SCRManager.serviceChanged(SCRManager.java:222) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.equinox.internal.ds.InstanceProcess.registerService(InstanceProcess.java:536) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:260) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.Resolver.buildNewlySatisfied(Resolver.java:473) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.Resolver.enableComponents(Resolver.java:217) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.SCRManager.performWork(SCRManager.java:816) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.SCRManager$QueuedJob.dispatch(SCRManager.java:783) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.WorkThread.run(WorkThread.java:89) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at java.lang.Thread.run(Unknown Source) [na:1.7.0_75]
2015-09-02 23:06:33.786 [INFO ] [s.c.d.internal.PersistentInbox] - Added new thing ‘ipp:printer:Officejet_Pro_8500_A910__0C5806_’ to inbox.
2015-09-02 23:06:33.864 [INFO ] [.u.d.internal.DashboardService] - Started dashboard at /start
2015-09-02 23:06:34.270 [INFO ] [.s.u.c.i.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2015-09-02 23:06:34.519 [INFO ] [.o.core.internal.CoreActivator] - openHAB runtime has been started (v2.0.0, build 201509020833).
2015-09-02 23:06:34.535 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘demo.rules’
2015-09-02 23:06:34.894 [INFO ] [s.c.d.internal.PersistentInbox] - Added new thing ‘avmfritz:fritzbox:192_168_192_101’ to inbox.
2015-09-02 23:06:35.190 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘demo.sitemap’
2015-09-02 23:06:35.315 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘demo.script’
2015-09-02 23:06:35.408 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘logging.persist’
2015-09-02 23:06:35.440 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘rrd4j.persist’
2015-09-02 23:06:35.471 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘demo.things’
2015-09-02 23:06:35.580 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘demo.items’
2015-09-02 23:06:37.811 [INFO ] [.b.a.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:sun:home
2015-09-02 23:06:37.811 [INFO ] [.b.a.handler.AstroThingHandler] - Scheduled astro PositionalJob with interval of 60 seconds for thing astro:sun:home
2015-09-02 23:06:43.992 [ERROR] [.m.r.r.i.engine.RuleEngineImpl] - Error during the execution of startup rule ‘Update max and min temperatures’: cannot invoke method public abstract org.eclipse.smarthome.core.types.State org.eclipse.smarthome.core.persistence.HistoricItem.getState() on null
2015-09-02 23:06:47.658 [ERROR] [d.YahooWeatherDiscoveryService] - Error accessing url ‘http://freegeoip.net/json/’ : Connection timed out: connect
2015-09-02 23:07:40.927 [WARN ] [.s.c.i.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.io.monitor.internal.EventLogger@155ba9c’ takes more than 5000ms.
2015-09-02 23:14:51.430 [INFO ] [ui.internal.servlet.PaperUIApp] - Started Paper UI at /ui
2015-09-02 23:14:52.023 [ERROR] [ServiceServletContainerAdapter] - Failed to register UPnP servlet!
org.osgi.service.http.NamespaceException: The alias ‘/upnpcallback’ is already in use.
at org.eclipse.equinox.http.servlet.internal.ProxyServlet.registerServlet(ProxyServlet.java:169) ~[na:na]
at org.eclipse.equinox.http.servlet.internal.HttpServiceImpl.registerServlet(HttpServiceImpl.java:66) ~[na:na]
at org.jupnp.transport.impl.osgi.HttpServiceServletContainerAdapter.registerServlet(HttpServiceServletContainerAdapter.java:73) ~[org.jupnp_2.0.0.201508200936.jar:na]
at org.jupnp.transport.impl.ServletStreamServerImpl.init(ServletStreamServerImpl.java:71) [org.jupnp_2.0.0.201508200936.jar:na]
at org.jupnp.transport.RouterImpl.startAddressBasedTransports(RouterImpl.java:422) [org.jupnp_2.0.0.201508200936.jar:na]
at org.jupnp.transport.RouterImpl.enable(RouterImpl.java:125) [org.jupnp_2.0.0.201508200936.jar:na]
at org.jupnp.UpnpServiceImpl.startup(UpnpServiceImpl.java:258) [org.jupnp_2.0.0.201508200936.jar:na]
at org.jupnp.UpnpServiceImpl.activate(UpnpServiceImpl.java:277) [org.jupnp_2.0.0.201508200936.jar:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_75]
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:1.7.0_75]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.7.0_75]
at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.7.0_75]
at org.eclipse.equinox.internal.ds.model.ServiceComponent.activate(ServiceComponent.java:235) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.activate(ServiceComponentProp.java:146) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.build(ServiceComponentProp.java:345) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponent(InstanceProcess.java:620) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:197) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.Resolver.getEligible(Resolver.java:343) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.SCRManager.serviceChanged(SCRManager.java:222) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464) [org.eclipse.osgi_3.10.2.v20150203-1939.jar:na]
at org.eclipse.equinox.internal.ds.InstanceProcess.registerService(InstanceProcess.java:536) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:260) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.Resolver.buildNewlySatisfied(Resolver.java:473) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.Resolver.enableComponents(Resolver.java:217) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.SCRManager.performWork(SCRManager.java:816) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.SCRManager$QueuedJob.dispatch(SCRManager.java:783) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at org.eclipse.equinox.internal.ds.WorkThread.run(WorkThread.java:89) [org.eclipse.equinox.ds_1.4.200.v20131126-2331.jar:na]
at java.lang.Thread.run(Unknown Source) [na:1.7.0_75]
2015-09-02 23:14:52.381 [INFO ] [.u.d.internal.DashboardService] - Started dashboard at /start
2015-09-02 23:14:52.756 [INFO ] [.s.u.c.i.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2015-09-02 23:14:52.834 [INFO ] [.o.core.internal.CoreActivator] - openHAB runtime has been started (v2.0.0, build 201509020833).
2015-09-02 23:14:52.865 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘demo.rules’
2015-09-02 23:14:53.442 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘demo.sitemap’
2015-09-02 23:14:53.551 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘demo.script’
2015-09-02 23:14:53.645 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘logging.persist’
2015-09-02 23:14:53.661 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘rrd4j.persist’
2015-09-02 23:14:53.692 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘demo.things’
2015-09-02 23:14:54.035 [INFO ] [.e.s.m.c.i.ModelRepositoryImpl] - Loading model ‘demo.items’
2015-09-02 23:14:56.157 [INFO ] [.b.a.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:sun:home
2015-09-02 23:14:56.157 [INFO ] [.b.a.handler.AstroThingHandler] - Scheduled astro PositionalJob with interval of 60 seconds for thing astro:sun:home
2015-09-02 23:15:07.077 [ERROR] [d.YahooWeatherDiscoveryService] - Error accessing url ‘http://freegeoip.net/json/’ : Connection timed out: connect

Hi Gert,
thanks for reporting that.

There were some changes in jUPnP the last weeks. Especially the PR https://github.com/openhab/jupnp/pull/24 did a major refactoring to support running jUPnP also on Servlet 2.4 based containers missing async support.

It seems that this PR missed the changes of the fix for this bug: https://github.com/openhab/jupnp/issues/18: error through multiple servlet registrations. This will happen only when using multiple network interfaces.

I will reopen the bug to apply the previous fix for master.

Bye, Jochen

Thanks @jo_hiller

Gert

I have re-applied the fix and published a new version of jUPnP. I hope that the next build (tomorrow) of openHAB 2 will work as expected again!