[pax-web] 6.0.2 issues registering servlet filters

[Lukas Rohner]

Hi all

After updating pax-web from 4.2.8 to 6.0.2 by using Karaf 4.1.0 I have problem with the whiteboard extender. I see intermittent issues with registering servlet filters. Any ideas why this happens? Maybe it's a regression.

Lukas

2017-03-10 08:27:42,545 | ERROR | (Felix) - Bundle org.ops4j.pax.web.pax-web-extender-whiteboard [298] EventDispatcher: Error during dispatch. (java.lang.IllegalArgumentException: Filter [org.opencastproject.kernel.rest.CleanSessionsFilter@374df63 is not currently registered in any context)

java.lang.IllegalArgumentException: Filter [org.opencastproject.kernel.rest.CleanSessionsFilter@374df63 is not currently registered in any context

at org.ops4j.pax.web.service.spi.model.ServiceModel.removeFilter(ServiceModel.java:196) [302:org.ops4j.pax.web.pax-web-spi:6.0.2]

at org.ops4j.pax.web.service.internal.HttpServiceStarted.unregisterFilter(HttpServiceStarted.java:620) [301:org.ops4j.pax.web.pax-web-runtime:6.0.2]

at org.ops4j.pax.web.service.internal.HttpServiceProxy.unregisterFilter(HttpServiceProxy.java:241) [301:org.ops4j.pax.web.pax-web-runtime:6.0.2]

at org.ops4j.pax.web.extender.whiteboard.internal.element.FilterWebElement.unregister(FilterWebElement.java:74) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at org.ops4j.pax.web.extender.whiteboard.internal.WebApplication.unregisterWebElement(WebApplication.java:406) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$$Lambda$227/1119206991.accept(Unknown Source) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at java.util.ArrayList.forEach(ArrayList.java:1249) [?:?]

at org.ops4j.pax.web.extender.whiteboard.internal.WebApplication.addWebElement(WebApplication.java:171) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at org.ops4j.pax.web.extender.whiteboard.internal.tracker.AbstractTracker.addingService(AbstractTracker.java:154) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at org.ops4j.pax.web.extender.whiteboard.internal.tracker.AbstractTracker.addingService(AbstractTracker.java:41) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) [?:?]

at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) [?:?]

at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) [?:?]

at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) [?:?]

at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901) [?:?]

at org.apache.felix.framework.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:990) [?:?]

at org.apache.felix.framework.EventDispatcher.fireEventImmediately(EventDispatcher.java:838) [?:?]

at org.apache.felix.framework.EventDispatcher.fireServiceEvent(EventDispatcher.java:545) [?:?]

at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4557) [?:?]

at org.apache.felix.framework.Felix.registerService(Felix.java:3549) [?:?]

at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:348) [?:?]

at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:322) [?:?]

at org.opencastproject.kernel.rest.RestPublisher.createEndpoint(RestPublisher.java:278) [77:matterhorn-kernel:2.2.0.SNAPSHOT]

at org.opencastproject.kernel.rest.RestPublisher$JaxRsServiceTracker.addingService(RestPublisher.java:427) [77:matterhorn-kernel:2.2.0.SNAPSHOT]

at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) [?:?]

at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) [?:?]

at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) [?:?]

at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) [?:?]

at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901) [?:?]

at org.apache.felix.framework.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:990) [?:?]

at org.apache.felix.framework.EventDispatcher.fireEventImmediately(EventDispatcher.java:838) [?:?]

at org.apache.felix.framework.EventDispatcher.fireServiceEvent(EventDispatcher.java:545) [?:?]

at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4557) [?:?]

at org.apache.felix.framework.Felix.registerService(Felix.java:3549) [?:?]

at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:348) [?:?]

at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:887) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:874) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:941) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:741) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:675) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:430) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:657) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:341) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:390) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.Activator.access$200(Activator.java:54) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:265) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:254) [186:org.apache.felix.scr:2.0.8]

at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:227) [186:org.apache.felix.scr:2.0.8]

at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) [?:?]

at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) [?:?]

at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [?:?]

at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) [?:?]

at org.apache.felix.framework.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:915) [?:?]

at org.apache.felix.framework.EventDispatcher.fireEventImmediately(EventDispatcher.java:834) [?:?]

at org.apache.felix.framework.EventDispatcher.fireBundleEvent(EventDispatcher.java:516) [?:?]

at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541) [?:?]

at org.apache.felix.framework.Felix.startBundle(Felix.java:2172) [?:?]

at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:998) [?:?]

at org.apache.felix.framework.BundleImpl.start(BundleImpl.java:984) [?:?]

at org.apache.karaf.features.internal.service.FeaturesServiceImpl.startBundle(FeaturesServiceImpl.java:1281) [9:org.apache.karaf.features.core:4.1.0]

at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:890) [9:org.apache.karaf.features.core:4.1.0]

at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1170) [9:org.apache.karaf.features.core:4.1.0]

at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$0(FeaturesServiceImpl.java:1069) [9:org.apache.karaf.features.core:4.1.0]

at org.apache.karaf.features.internal.service.FeaturesServiceImpl$$Lambda$12/540415842.call(Unknown Source) [9:org.apache.karaf.features.core:4.1.0]

at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]

at java.lang.Thread.run(Thread.java:745) [?:?]

[Achim Nierbeck]

Hi Lukas, 

a) is there anything special about your filter? 

b) can you turn on Debug Logging and show us the stack before the exception? 

regards, Achim 

--
--
------------------
OPS4J - http://www.ops4j.org - op...@googlegroups.com

---
You received this message because you are subscribed to the Google Groups "OPS4J" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ops4j+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Apache Member

Apache Karaf <http://karaf.apache.org/> Committer & PMC
OPS4J Pax Web <http://wiki.ops4j.org/display/paxweb/Pax+Web/> Committer & Project Lead
blog <http://notizblog.nierbeck.de/>

Co-Author of Apache Karaf Cookbook <http://bit.ly/1ps9rkS>

Software Architect / Project Manager / Scrum Master 

[Lukas Rohner]

Hi Achim

Here the debug logs before the exception is thrown:

2017-03-13 09:38:29,595 | DEBUG | (AbstractTracker) - Service available [javax.servlet.Servlet]

2017-03-13 09:38:29,595 | DEBUG | (ServletTracker) - Creating web element for service 415 [javax.servlet.Servlet] (org.opencastproject.oaipmh.server.OaiPmhServer@2eb3f91).

2017-03-13 09:38:29,596 | DEBUG | (WebApplication) - de-registering 9 servlet filters

2017-03-13 09:38:29,596 | DEBUG | (HttpServiceProxy) - Unregistering filter [org.opencastproject.kernel.rest.CleanSessionsFilter@780c587e]

2017-03-13 09:38:29,597 | DEBUG | (JettyServerImpl) - Removing filter model [FilterModel{id=org.ops4j.pax.web.service.spi.model.FilterModel-144,urlPatterns=[*],servletNames=null,filter=org.opencastproject.kernel.rest.CleanSessionsFilter@780c587e,filterClass=null,context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-17,name=,httpContext=org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$2@4dc08f85,contextParams={},virtualHosts={},connectors={}}}]

2017-03-13 09:38:29,602 | DEBUG | (JettyServerWrapper) - ServletContextHandler for HTTP context [org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$2@4dc08f85] referenced [42] times.

2017-03-13 09:38:29,602 | DEBUG | (HttpServiceProxy) - Unregistering filter [org.opencastproject.kernel.filter.https.HttpsFilter@5af7452d]

2017-03-13 09:38:29,603 | DEBUG | (JettyServerImpl) - Removing filter model [FilterModel{id=org.ops4j.pax.web.service.spi.model.FilterModel-145,urlPatterns=[*],servletNames=null,filter=org.opencastproject.kernel.filter.https.HttpsFilter@5af7452d,filterClass=null,context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-17,name=,httpContext=org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$2@4dc08f85,contextParams={},virtualHosts={},connectors={}}}]

2017-03-13 09:38:29,603 | DEBUG | (JettyServerWrapper) - ServletContextHandler for HTTP context [org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$2@4dc08f85] referenced [41] times.

2017-03-13 09:38:29,603 | DEBUG | (HttpServiceProxy) - Unregistering filter [org.opencastproject.kernel.rest.JsonpFilter@5fe89572]

2017-03-13 09:38:29,603 | DEBUG | (AbstractTracker) - Service available [javax.servlet.Servlet]

2017-03-13 09:38:29,604 | DEBUG | (JettyServerImpl) - Removing filter model [FilterModel{id=org.ops4j.pax.web.service.spi.model.FilterModel-146,urlPatterns=[*],servletNames=null,filter=org.opencastproject.kernel.rest.JsonpFilter@5fe89572,filterClass=null,context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-17,name=,httpContext=org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$2@4dc08f85,contextParams={},virtualHosts={},connectors={}}}]

2017-03-13 09:38:29,604 | DEBUG | (JettyServerWrapper) - ServletContextHandler for HTTP context [org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$2@4dc08f85] referenced [40] times.

2017-03-13 09:38:29,604 | DEBUG | (HttpServiceProxy) - Unregistering filter [org.opencastproject.kernel.security.OrganizationFilter@2d379537]

2017-03-13 09:38:29,604 | DEBUG | (ServletTracker) - Creating web element for service 416 [javax.servlet.Servlet] (org.opencastproject.kernel.rest.RestPublisher$RestServlet@16f9ae4d).

2017-03-13 09:38:29,604 | DEBUG | (JettyServerImpl) - Removing filter model [FilterModel{id=org.ops4j.pax.web.service.spi.model.FilterModel-147,urlPatterns=[*],servletNames=null,filter=org.opencastproject.kernel.security.OrganizationFilter@2d379537,filterClass=null,context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-17,name=,httpContext=org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$2@4dc08f85,contextParams={},virtualHosts={},connectors={}}}]

2017-03-13 09:38:29,605 | DEBUG | (JettyServerWrapper) - ServletContextHandler for HTTP context [org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$2@4dc08f85] referenced [39] times.

2017-03-13 09:38:29,605 | DEBUG | (WebApplication) - de-registering 9 servlet filters

2017-03-13 09:38:29,605 | DEBUG | (HttpServiceProxy) - Unregistering filter [org.opencastproject.kernel.security.SecurityFilter@4de5b748]

2017-03-13 09:38:29,605 | DEBUG | (JettyServerImpl) - Removing filter model [FilterModel{id=org.ops4j.pax.web.service.spi.model.FilterModel-148,urlPatterns=[*],servletNames=null,filter=org.opencastproject.kernel.security.SecurityFilter@4de5b748,filterClass=null,context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-17,name=,httpContext=org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$2@4dc08f85,contextParams={},virtualHosts={},connectors={}}}]

2017-03-13 09:38:29,605 | DEBUG | (HttpServiceProxy) - Unregistering filter [org.opencastproject.kernel.rest.CleanSessionsFilter@780c587e]

2017-03-13 09:38:29,606 | DEBUG | (JettyServerWrapper) - ServletContextHandler for HTTP context [org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$2@4dc08f85] referenced [38] times.

2017-03-13 09:38:29,606 | DEBUG | (HttpServiceProxy) - Unregistering filter [org.opencastproject.kernel.filter.proxy.TransparentProxyFilter@70343f1b]

It seems like every time when the AbstractTracker finds a new servlet to register it de-registers all already existing filters and registers it again. If in the time of de-registering the tracker again finds a new servlet to register it executes the de-registration again without waiting for the previous running task to finish. So I think de-registring should be tread safe.

BTW I got another NullPointerException this time:

2017-03-13 09:31:55,941 | ERROR | (Felix) - Bundle org.ops4j.pax.web.pax-web-extender-whiteboard [298] EventDispatcher: Error during dispatch. (java.lang.NullPointerException)

java.lang.NullPointerException

at org.ops4j.pax.web.service.jetty.internal.JettyServerImpl.removeFilter(JettyServerImpl.java:628) [299:org.ops4j.pax.web.pax-web-jetty:6.0.2]

at org.ops4j.pax.web.service.jetty.internal.ServerControllerImpl$Started.removeFilter(ServerControllerImpl.java:319) [299:org.ops4j.pax.web.pax-web-jetty:6.0.2]

at org.ops4j.pax.web.service.jetty.internal.ServerControllerImpl.removeFilter(ServerControllerImpl.java:150) [299:org.ops4j.pax.web.pax-web-jetty:6.0.2]

at org.ops4j.pax.web.service.internal.HttpServiceStarted.unregisterFilter(HttpServiceStarted.java:623) [301:org.ops4j.pax.web.pax-web-runtime:6.0.2]

at org.ops4j.pax.web.service.internal.HttpServiceProxy.unregisterFilter(HttpServiceProxy.java:241) [301:org.ops4j.pax.web.pax-web-runtime:6.0.2]

at org.ops4j.pax.web.extender.whiteboard.internal.element.FilterWebElement.unregister(FilterWebElement.java:74) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at org.ops4j.pax.web.extender.whiteboard.internal.WebApplication.unregisterWebElement(WebApplication.java:406) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at org.ops4j.pax.web.extender.whiteboard.internal.WebApplication$$Lambda$201/1704051900.accept(Unknown Source) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at java.util.ArrayList.forEach(ArrayList.java:1249) [?:?]

at org.ops4j.pax.web.extender.whiteboard.internal.WebApplication.addWebElement(WebApplication.java:171) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at org.ops4j.pax.web.extender.whiteboard.internal.tracker.AbstractTracker.addingService(AbstractTracker.java:154) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at org.ops4j.pax.web.extender.whiteboard.internal.tracker.AbstractTracker.addingService(AbstractTracker.java:41) [298:org.ops4j.pax.web.pax-web-extender-whiteboard:6.0.2]

at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) [?:?]

at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) [?:?]

at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) [?:?]

at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229) [?:?]

at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901) [?:?]

at org.apache.felix.framework.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:990) [?:?]

Lukas

To unsubscribe from this group and stop receiving emails from it, send an email to ops4j+un...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Achim Nierbeck]

Hi Lukas, 

that's it :-)

thanks. 

Yes the registering and de-registering needs to be thread safe. 

Could you open an issue for it? Thanks. 

Btw. this needs to be done to make sure all filters are registered after the Servlet is registered, otherwise a connection between the filters and servlets won't work. 

regards, Achim 

To unsubscribe from this group and stop receiving emails from it, send an email to ops4j+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Lukas Rohner]

I don't have a Jira account yet on the pax web project and it seems I need to ask here for creating one for me. I'm also fine if someone else create the ticket for me.

Lukas

[Achim Nierbeck]

nah nah ... you should receive your invitation mail for jira right now. 

Welcome aboard :)

regards, Achim 

To unsubscribe from this group and stop receiving emails from it, send an email to ops4j+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Lukas Rohner]

Thanks!

The tickets have been created. I hope they can be fixed within the next 6.0.3 release.

https://ops4j1.jira.com/browse/PAXWEB-1073

https://ops4j1.jira.com/browse/PAXWEB-1074

Lukas

[Achim Nierbeck]

Hi Lukas, 

thanks. I wouldn't bet on it ... depends on my personal schedule :D

And how easy a fix may be. 

regards, Achim 

To unsubscribe from this group and stop receiving emails from it, send an email to ops4j+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.