Whiteboard Component lifecycle issue

Alain Picard

unread,

Jul 8, 2021, 7:49:15 AM7/8/21

to op...@googlegroups.com

I'm facing a problem that seems to have started after some changes that has forced changes in the startup order/timing of some components.

Using Paxweb 7.2.26 with http whiteboard. I have here a Filter component that is being bounced a few times and ultimately when page is loaded, it ends up using an instance that has been deactivated as shown below, from some key logged events, both in our code and in the AbstractTracker:

07:33:34.020 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - Service available {javax.servlet.Filter}={service.id=2672, service.bundleid=86, service.scope=prototype, service.ranking=3, osgi.http.whiteboard.context.select=(osgi.http.whiteboard.context.name=WebviewerServletContextHelper), filter.init.excludedUrls=/zkcomet, osgi.http.whiteboard.filter.pattern=/*, component.name=com.castortech.iris.ba.web.filters.TenantFilter, osgi.http.whiteboard.filter.asyncSupported=true, component.id=733}
07:33:34.049 [ConfigurationListener Event Queue] ::: TRACE c.c.iris.ba.web.filters.TenantFilter - Activating class com.castortech.iris.ba.web.filters.TenantFilter/203832382
07:33:50.118 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - Service removed {javax.servlet.Filter}={service.id=2672, service.bundleid=86, service.scope=prototype, service.ranking=3, osgi.http.whiteboard.context.select=(osgi.http.whiteboard.context.name=WebviewerServletContextHelper), filter.init.excludedUrls=/zkcomet, osgi.http.whiteboard.filter.pattern=/*, component.name=com.castortech.iris.ba.web.filters.TenantFilter, osgi.http.whiteboard.filter.asyncSupported=true, component.id=733}
07:33:50.118 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - Shared Context ...
07:33:50.118 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - ... counter:23
07:33:50.118 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - reduced counter:22
07:33:50.118 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - service can be removed: false
07:33:50.121 [ConfigurationListener Event Queue] ::: TRACE c.c.iris.ba.web.filters.TenantFilter - Deactivating class com.castortech.iris.ba.web.filters.TenantFilter/203832382
07:33:52.104 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - Service available {javax.servlet.Filter}={service.id=2941, service.bundleid=86, service.scope=prototype, service.ranking=3, osgi.http.whiteboard.context.select=(osgi.http.whiteboard.context.name=WebviewerServletContextHelper), filter.init.excludedUrls=/zkcomet, osgi.http.whiteboard.filter.pattern=/*, component.name=com.castortech.iris.ba.web.filters.TenantFilter, osgi.http.whiteboard.filter.asyncSupported=true, component.id=733}
07:33:52.110 [ConfigurationListener Event Queue] ::: TRACE c.c.iris.ba.web.filters.TenantFilter - Activating class com.castortech.iris.ba.web.filters.TenantFilter/352919773
07:33:54.579 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - Service removed {javax.servlet.Filter}={service.id=2941, service.bundleid=86, service.scope=prototype, service.ranking=3, osgi.http.whiteboard.context.select=(osgi.http.whiteboard.context.name=WebviewerServletContextHelper), filter.init.excludedUrls=/zkcomet, osgi.http.whiteboard.filter.pattern=/*, component.name=com.castortech.iris.ba.web.filters.TenantFilter, osgi.http.whiteboard.filter.asyncSupported=true, component.id=733}
07:33:54.579 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - Shared Context ...
07:33:54.579 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - ... counter:23
07:33:54.579 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - reduced counter:22
07:33:54.579 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - service can be removed: false
07:33:54.581 [ConfigurationListener Event Queue] ::: TRACE c.c.iris.ba.web.filters.TenantFilter - Deactivating class com.castortech.iris.ba.web.filters.TenantFilter/352919773
07:34:24.216 [ConfigurationListener Event Queue] ::: DEBUG o.o.p.w.e.w.i.t.AbstractTracker - Service available {javax.servlet.Filter}={service.id=3872, service.bundleid=86, service.scope=prototype, service.ranking=3, osgi.http.whiteboard.context.select=(osgi.http.whiteboard.context.name=WebviewerServletContextHelper), filter.init.excludedUrls=/zkcomet, osgi.http.whiteboard.filter.pattern=/*, component.name=com.castortech.iris.ba.web.filters.TenantFilter, osgi.http.whiteboard.filter.asyncSupported=true, component.id=733}
07:34:24.219 [ConfigurationListener Event Queue] ::: TRACE c.c.i.b.w.f.BaseSessionTenantHelper - Activating class com.castortech.iris.ba.web.filters.BaseSessionTenantHelper/1101462560
07:34:24.222 [ConfigurationListener Event Queue] ::: TRACE c.c.iris.ba.web.filters.TenantFilter - Activating class com.castortech.iris.ba.web.filters.TenantFilter/634603573

Called at page load time: 203832382 which is the first one

We can actually see 3 activations and 2 deactivation. In our log we show the identity hash code for the TenantFilter (our component). Finally when we load the page at the browser, we get an IllegalStateException from ComponentServiceObject since the CSO is deactivated. When putting a breakpoint and introspecting the TenantFilter that is active at that point, we can see that it is the very first one that has been replaced twice, but it is still being used.

I'm not sure I understand the logic with the counters and if it can be the cause. The number of 22 seems to be about right from the number of servlets and filters in that context.

Any help would be much appreciated as I'm at a total loss here.

Alain

Grzegorz Grzybek

unread,

Jul 8, 2021, 7:55:52 AM7/8/21

to op...@googlegroups.com

Hello

I'm heavily working on Pax Web 8 and I see more and more problems existing in Pax Web 7 - one of them is how prototype-scoped whiteboard services are handled. I didn't even cover all the scenarios in Pax Web 8, but it's not that easy...

In Pax Web 7 I know there's something wrong - services are obtained from the references ONCE and are not managed correctly (via ServiceObjects).

What kind of ComponentServiceObjects (CSO) are you thinking? Are you registering Whiteboard services through SCR?

regards

Grzegorz Grzybek

--
--
------------------
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+un...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/ops4j/CAAq-gCysX85S3c5LYLG7KxJ0bguQsyRci5B77vAhiJ-Tvf%3Df7A%40mail.gmail.com.

Alain Picard

unread,

Jul 9, 2021, 8:45:16 AM7/9/21

to OPS4J

Hi,

You replied very quickly but never got notified until today with the abridged summary.

Yes we are registering via SCR, there are a few filters, but here's the one I reported on:

@Component(
      service = Filter.class,
        scope = ServiceScope.PROTOTYPE,
        property = {
                HTTP_WHITEBOARD_FILTER_PATTERN + "=" + PathConstants.ROOT_PATTERN,
                HTTP_WHITEBOARD_CONTEXT_SELECT + "=(" + HTTP_WHITEBOARD_CONTEXT_NAME + "=WebviewerServletContextHelper)",
                HTTP_WHITEBOARD_FILTER_ASYNC_SUPPORTED + "=true",
                Constants.SERVICE_RANKING + ":Integer=3",
                HTTP_WHITEBOARD_FILTER_INIT_PARAM_PREFIX + "excludedUrls=" + PathConstants.ZKCOMET_PATH    //Per ZK support, do not protect zkcomet since it need to carry notification that session term on server to client (ZK-Comet and ZK-Error in the response header)
        }
)
public final class TenantFilter implements Filter {
   private static final Logger log = LoggerFactory.getLogger(TenantFilter.class);
   private List<String> excludedUrls;

   @Reference(policyOption=ReferencePolicyOption.GREEDY)
   private volatile AdminBroker adminBroker; //NOSONAR: OSGi spec

   @Reference(policyOption=ReferencePolicyOption.GREEDY)
   private volatile BaseSessionTenantHelper baseSessionTenantHelper; //NOSONAR: OSGi spec
... rest of implementation..

Here the issue is (was as I reworked code to get around this) that the baseSessionTenantHelper would get bounced and recreated and the TenantFilter was not following correctly.

Alain

Grzegorz Grzybek

unread,

Jul 9, 2021, 9:33:42 AM7/9/21

to op...@googlegroups.com

Hello

Here the issue is (was as I reworked code to get around this) that the baseSessionTenantHelper would get bounced and recreated and the TenantFilter was not following correctly.

If I understand correctly, you know that AdminBroker and BaseSessionTenantHelper OSGi services are re-registered, but there's only one TenantFilter filter, right?

This matches my understanding of Pax Web 7 (and earlier) that doesn't take the scope of Whiteboard service into account and simply gets a service from the reference ONCE... But I'd have to check the theory in more details.

Because it should be easier now to create a Pax Web ticket (after I moved the issues from Jira ot GH), please create an issue under https://github.com/ops4j/org.ops4j.pax.web/issues ok?

regards

Grzegorz Grzybek

To view this discussion on the web visit https://groups.google.com/d/msgid/ops4j/6114c322-2669-43be-ae20-b6e30a6eea2cn%40googlegroups.com.

Alain Picard

unread,

Jul 9, 2021, 9:44:57 AM7/9/21

to OPS4J

See inline

On Friday, July 9, 2021 at 9:33:42 AM UTC-4 gr.gr...@gmail.com wrote:

Hello

Here the issue is (was as I reworked code to get around this) that the baseSessionTenantHelper would get bounced and recreated and the TenantFilter was not following correctly.

If I understand correctly, you know that AdminBroker and BaseSessionTenantHelper OSGi services are re-registered, but there's only one TenantFilter filter, right?

Both of these components could possible get re-registered but here the situation was with BaseSessionTenantHelper.

In sequence, a re-registration will first trigger a deactivation, like here of TenantFilter. At that point you need to get rid of any reference to it as it has been deactivated and can't be reused, and maybe it will never get re-activated, we can't know for sure.

Later, when the service activation conditions are met again (like one service somewhere went away and is now back online), then a new TenantFilter will get activated and should become active and used by the whiteboard.

This bouncing can potentially happen many times, due to configuration changes (that was my case here), dynamically loading a new version of a service, etc.

Grzegorz Grzybek

unread,

Jul 12, 2021, 2:17:32 AM7/12/21

to op...@googlegroups.com

Hello

In Pax Web 8 `main` branch, I've createad a test + sample that attempts to match your scenario

DynamicFilter.java[1] is prototype-scoped and has greedy dependencies (@References) to two interfaces.

StableServlet.java[2] is less dynamic and mapped to "/*" and the above servlet chain-forwards to this servlet.

AbstractWhiteboardDSDynamicIntegrationTest.java[3] is an abstract integration (pax-exam) test (with subclasses for pax-web-jetty, pax-web-tomcat and pax-web-undertow) that sends real HTTP requests in 3 cases:

- by default, so only a servlet should be called

- after registering required @Referenced services

- after registering higher ranked @Reference for the filter.

The integration test results match the expectations.

Of course unless I missed something from your scenario. Please (if you have time) verify my reproducer.

kind regards

Grzegorz Grzybek

===

[1]: https://github.com/ops4j/org.ops4j.pax.web/blob/4f2dc27cbcc36bb0690399657fbbe7dabf1b8fcf/samples/samples-whiteboard/whiteboard-ds-dynamic/src/main/java/org/ops4j/pax/web/samples/whiteboard/ds/web/DynamicFilter.java

[2]: https://github.com/ops4j/org.ops4j.pax.web/blob/4f2dc27cbcc36bb0690399657fbbe7dabf1b8fcf/samples/samples-whiteboard/whiteboard-ds-dynamic/src/main/java/org/ops4j/pax/web/samples/whiteboard/ds/web/StableServlet.java

[3]: https://github.com/ops4j/org.ops4j.pax.web/blob/4f2dc27cbcc36bb0690399657fbbe7dabf1b8fcf/pax-web-itest/pax-web-itest-container/pax-web-itest-container-common/src/main/java/org/ops4j/pax/web/itest/container/whiteboard/AbstractWhiteboardDSDynamicIntegrationTest.java

pt., 9 lip 2021 o 14:45 Alain Picard <al...@benchmarkconsulting.com> napisał(a):

To view this discussion on the web visit https://groups.google.com/d/msgid/ops4j/6114c322-2669-43be-ae20-b6e30a6eea2cn%40googlegroups.com.

Alain Picard

unread,

Jul 12, 2021, 7:09:48 AM7/12/21

to op...@googlegroups.com

I reviewed the test code and it does replicate the case that I described.

Thanks for addressing it, now makes me look forward to version 8 :)

Alain

You received this message because you are subscribed to a topic in the Google Groups "OPS4J" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/ops4j/cYZ-g_RGJrY/unsubscribe.
To unsubscribe from this group and all its topics, send an email to ops4j+un...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/ops4j/CAAdXmhr_ykHtMfWDjX0NkUr1hoRLhfAFdGT0S2xmFuaPcTujGg%40mail.gmail.com.

Reply all

Reply to author

Forward