eclipse-ee4j / mojarra

Mojarra, a Jakarta Faces implementation
Other
158 stars 108 forks source link

Thread-Safety Problem in UIComponent._isPushedAsCurrentRefCount of HtmlDoctype #5273

Closed metaxmx closed 11 months ago

metaxmx commented 1 year ago

Hi, we have encountered a problem in our JSF application, where sometimes the log get flooded by severe error messages like this: 2023-04-18 12:31:59,525 SEVERE jakarta.faces.component the component(jakarta.faces.component.html.HtmlDoctype@208172d8) is the head component of the stack, but it's _isPushedAsCurrentRefCount < 1 _isPushedAsCurrentRefCount

Upon looking into it, i found out, that there is a mechanism to check for balanced calls to pushComponentToEL and popComponentFromEL: a private property _isPushedAsCurrentRefCount of class jakarta.faces.component.UIComponent, which is increased/decreased every time pushComponentToEL/popComponentFromEL are called.

Unfortunately, _isPushedAsCurrentRefCount is a simple, unsynchronized property, and increasing/decreasing is not done in a thread-safe/atomic way. Usually this doesn't seem to be a problem, because most components in a view seem to be different object instances which are only processed and rendered by a single thread. But the component jakarta.faces.component.html.HtmlDoctype is not created every time anew, but is registered as a "singleton" by SAXCompiler.startDTD(), which means, there is only one instance of HtmlDoctype which changes its _isPushedAsCurrentRefCount across multiple threads in parallel. Sometimes, when multiple views are processed at exactly the same time (e.g. during appserver start), the concurrent changes to HtmlDoctype._isPushedAsCurrentRefCount seem to result in a wrong property value. If this value is smaller than it should be, from that point on every rendered view logs the above message, which completely spams the appserver log.

How to Reproduce

Unfortunately I don't have a simple reproducer project, due to the "random" nature of the bug. But I found out, that I could reproduce the behaviour rather often, if I have a project which has a longer initialization process (which seems to stall all incoming JSF requests until initialization finishes) and spam a lot of JSF requests during this initialization time. Then these stalled requests are processed at the exact same time, which makes it likely, that a synchronization error on the rendering of the HtmlDoctype (which is included in all our views) occurs.

Expected behavior

I believe, that changing/checking _isPushedAsCurrentRefCount somehow should be done in a thread-safe manner, which doesn't result in wrong values being written, when _isPushedAsCurrentRefCount++ and _isPushedAsCurrentRefCount-- is called across multiple threads. I'm not sure what the best technique is to achieve this, but I assume an AtomicInteger and atomic operations on it (for increasing and checking+decreasing) might do the trick. Unfortunately, simply declaring the variable as volatile didn't help.

Additional context

We encountered this bug with Mojarra 4.0.2 (Maven project org.glassfish:jakarta.faces:4.0.2). But looking at the code of UIComponent in the current main branch, the behavior still seems to be the same.

alfonx commented 1 year ago

We observe the same issue with org.glassfish:jakarta.faces:4.0.2

BalusC commented 1 year ago

Regression of https://github.com/jakartaee/faces/issues/1568.

pizzi80 commented 1 year ago

@BalusC Are we sure that your commit created a regression, or is it more likely that it uncovered a bad design choice about how the current component is saved in EL context?

It's strange that there is an integer to keep track of components that "forgot" to pop from a data structure...

BalusC commented 1 year ago

UIComponent instances are request scoped and never intended to be threadsafe. This is in the spec. Synchronization over all place in UIComponent would knock down performance and reusing UIComponent instances across different views (browser tabs/windows) would still expose 'weird' end-user behavior. See also a.o. https://stackoverflow.com/q/14911158.

Before the introduction of HtmlDoctype in https://github.com/jakartaee/faces/issues/1568, the Facelets-internal doctype was a plain vanilla String and I have overlooked that Facelet instances aren't per defninition request scoped -- that depends on project stage, FACELET_REFRESH_PERIOD and FaceletCache.