Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Question] Jakarta Faces 4.0.9 on multiwar-deployment in tomcat, possible NPE when a stale cookie exists #5552

Open
DGuhr opened this issue Feb 5, 2025 · 0 comments

Comments

@DGuhr
Copy link

DGuhr commented Feb 5, 2025

porting from here by request:

Hey. So, I spent the last days wrapping my head around an error, which I hopefully solved by now, but wanted to ask if this is potentially a bug in the internals, too, so here's an Issue.

First of all, a bit about my context and setup:

  • I have little to no prior JSF experience.
  • I have a legacy app and migrating it now to use jakarta faces 4.0.9 with primefaces 14.0.6 and spring framework 6.1.16 (not spring boot, then I would've used joinfaces, but migrating to boot wasn't in scope) on tomcat 10.0.
  • I also have a login process that uses a login.xhtml in one .war - lets call it login.war - to do a "local" login that uses a viewAction. Also, and another oauth.xhtml using another viewaction in another .war - let's call it gui.war - and this led me to some problems.

The Problem:
Sometimes (not deterministic) after restarting my dockerized setup, I was not able to log in. The flow was like this:
First, the login.xhtml shows the credential form
Then, when submitting, an f:viewaction redirects to loginsuccess.xhtml which on successful login in turn redirects (via submitting a form using JS after adding params to the form, before you ask: I didn't write this, I'm just here to try to navigate the mess ;) ) to another oauth.xhtml, bundled in gui.war - which again logs in (multiple loginmodules, chosen at runtime, think oauth, saml, depends) and should redirect in the end to a dashboard.xhtml

Now this worked 98% of times, but sometimes when restarting the dockerized env, I got an JSF1094 error, that showed up for me with the error message

[http-nio-8080-exec-10] com.sun.faces.context.flash.ELFlash$PreviousNextFlashInfoManager.decode JSF1094: Could not decode flash data from incoming cookie value null.  Processing will continue, but the flash is unavailable for this request.

I looked up this error, but could only find JSF1094 errors with other error messages, and talking about using myFaces as a solution which i declined, as this was seemingly too big a task, adding to the effort and would possibly introduce other sideeffects.

After trying out multiple non-working JSF parameters like enableFlash=false (because tha app itself does not use flash externally - result: no effect at all) or forceAlwaysWriteFlashCookie=true (bc i thought maybe it is not written but should be, result: no effect, but btw thanks BalusC for this page which by now seems to be the only page listing the available params) , I tried to add a ServletFilter removing the CSFCFC cookie but the error came back again afterwards (spoiler: Might have been my misunderstanding of what's going on there). I also tried to use a setTimeout with 500ms on the 2nd loginsuccess.xhtml js-redirect, thinking that a stale FlashInfoManager might still be floating around causing this error. All to no effect, bc still in the second POST from oauth.xhtml, I got this exception in the log:

jakarta.faces.FacesException: Cannot invoke "com.sun.faces.context.flash.ELFlash$FlashInfo.getFlashMap()" because "flashInfo" is null
2025-02-03T11:59:15.584213761Z 	at com.sun.faces.lifecycle.InvokeApplicationPhase.execute(InvokeApplicationPhase.java:64)
2025-02-03T11:59:15.584222802Z 	at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:72)
2025-02-03T11:59:15.584223677Z 	at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:131)
2025-02-03T11:59:15.584224636Z 	at jakarta.faces.webapp.FacesServlet.executeLifecyle(FacesServlet.java:691)
2025-02-03T11:59:15.584225344Z 	at jakarta.faces.webapp.FacesServlet.service(FacesServlet.java:449)
2025-02-03T11:59:15.584226011Z 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:195)
2025-02-03T11:59:15.584226761Z 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
2025-02-03T11:59:15.584227511Z 	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
2025-02-03T11:59:15.584228219Z 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
2025-02-03T11:59:15.584228927Z 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
2025-02-03T11:59:15.584229636Z 	at de.myapp.mymodule.gui.view.util.MyAppOpenSessionInViewFilter.doFilterInternal(MyAppOpenSessionInViewFilter.java:91)
2025-02-03T11:59:15.584230427Z 	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
2025-02-03T11:59:15.584231136Z 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
2025-02-03T11:59:15.584231927Z 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
2025-02-03T11:59:15.584232636Z 	at de.myapp.mymodule.gui.view.util.SecurityFilter.doFilter(SecurityFilter.java:159)
2025-02-03T11:59:15.584233344Z 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
2025-02-03T11:59:15.584234011Z 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
2025-02-03T11:59:15.584234761Z 	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
2025-02-03T11:59:15.584235594Z 	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
2025-02-03T11:59:15.584237011Z 	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
2025-02-03T11:59:15.584237719Z 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
2025-02-03T11:59:15.584238427Z 	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167)
2025-02-03T11:59:15.584239177Z 	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
2025-02-03T11:59:15.584239886Z 	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:483)
2025-02-03T11:59:15.584240594Z 	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115)
2025-02-03T11:59:15.584242761Z 	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
2025-02-03T11:59:15.584243511Z 	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:663)
2025-02-03T11:59:15.584244261Z 	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
2025-02-03T11:59:15.584244969Z 	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
2025-02-03T11:59:15.584245677Z 	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:397)
2025-02-03T11:59:15.584246386Z 	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
2025-02-03T11:59:15.584247052Z 	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:905)
2025-02-03T11:59:15.584247761Z 	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1741)
2025-02-03T11:59:15.584248469Z 	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
2025-02-03T11:59:15.584249136Z 	at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
2025-02-03T11:59:15.584249886Z 	at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
2025-02-03T11:59:15.584250594Z 	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
2025-02-03T11:59:15.584251261Z 	at java.base/java.lang.Thread.run(Thread.java:1583)
2025-02-03T11:59:15.584251969Z Caused by: java.lang.NullPointerException: Cannot invoke "com.sun.faces.context.flash.ELFlash$FlashInfo.getFlashMap()" because "flashInfo" is null
2025-02-03T11:59:15.584252844Z 	at com.sun.faces.context.flash.ELFlash.loggingGetPhaseMapForWriting(ELFlash.java:818)
2025-02-03T11:59:15.584253552Z 	at com.sun.faces.context.flash.ELFlash.setKeepMessages(ELFlash.java:318)
2025-02-03T11:59:15.584254261Z 	at com.sun.faces.application.NavigationHandlerImpl.handleNavigation(NavigationHandlerImpl.java:235)
2025-02-03T11:59:15.584255136Z 	at com.sun.faces.application.NavigationHandlerImpl.handleNavigation(NavigationHandlerImpl.java:200)
2025-02-03T11:59:15.584255886Z 	at com.sun.faces.application.ActionListenerImpl.invokeNavigationHandling(ActionListenerImpl.java:93)
2025-02-03T11:59:15.584256594Z 	at com.sun.faces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:62)
2025-02-03T11:59:15.584257302Z 	at jakarta.faces.component.UIViewAction.broadcast(UIViewAction.java:506)
2025-02-03T11:59:15.584257969Z 	at jakarta.faces.component.UIViewRoot.broadcastEvents(UIViewRoot.java:858)
2025-02-03T11:59:15.584258677Z 	at jakarta.faces.component.UIViewRoot.processApplication(UIViewRoot.java:1338)
2025-02-03T11:59:15.584259344Z 	at com.sun.faces.lifecycle.InvokeApplicationPhase.execute(InvokeApplicationPhase.java:56)
2025-02-03T11:59:15.584260219Z 	... 37 common frames omitted

So, here flashInfo is null.

The workaround:
I was able to just hit enter on the oauth.xhtml, afterwards re-opening the /Login in the browser (login.xhtml) again and re-login and got successfully logged in. Afterwards, the error was gone for some time. As this unblocked me at dev time, this was surely nothing to send into prod. So, I digged further as the error started happening again.

Long story short:
After a lot of understanding and internal debugging, I think I found the problem. I summarized my debug-findings here in this picture:

Image

I found that the FlashInfoManager used in loggingGetPhaseMapForReading that it gets from getCurrentFlashManager has this state (from an exported debug logging):

getCurrentFlashManager called. Result is: previousRequestSequenceNumber: null nextRequestSequenceNumber: null create is: false contextMap is: {com.sun.faces.RESOURCE_REQUEST=false, ForceSetMaxAgeZero=true, ForceAlwaysWriteFlashCookie=false, SavedResponseCompleteFlagValue=false, PartialStateSaving=true, RequestFlashManager=previousRequestSequenceNumber: null nextRequestSequenceNumber: null, com.sun.faces.facesConfigVersion=4.0, org.primefaces.context.PrimeRequestContext=org.primefaces.context.PrimeRequestContext@73326a88, jakarta.faces.validator.ENABLE_VALIDATE_WHOLE_BEAN=false, jakarta.faces.VIEWROOT_PHASE_LISTENER_QUEUES_EXCEPTIONS=false, jakarta.faces.ALWAYS_PERFORM_VALIDATION_WHEN_REQUIRED_IS_TRUE=false}

so it is not null, but internally it seems that it doesn't have a valid state. That's because decrypt gets invalid values in this for-loop - which should have an error msg that would've spared me a lot of headaches, but somewhere in between that got lost / nulled.

My debug logs showed me what was going on, one byte had a negative value, and the exception was thrown.

So... as you can see in the picture, I am not 100% sure I solved the bug by adding a restart-surviving AES256-encrypted private key to the web.xml's of both modules, but as of now the error didn't happen again, so yay, I ... guess?

Nevertheless I wanted to ask if this execution path should be possible, so here's the ticket. My expectation would've been that
a) doFinal throws an exception if the cookie is not decryptable
b) the error would've shown the error message hinting to the problem (I spared myself to find out why it didn't up until now)
c) the checks in ELFlash would've really checked that the Manager is usable, not just != null
d) a documentation that would've mentioned that it is a good practice in some circumstances to add a private key (if it actually is, so no offense meant here, I am just very insecure here currently)

I hope this is somewhat understandable and also hope someone could answer and assure me that I did the right thing, because to this day (as you can see in the last square in the picture) I am not 100% sure I fixed the problem. Happy to provide you with more information, if needed, but for now I think what I wrote here is more than enough and hopefully someone reads through it. Thanks! 👍

edit: My confidence that adding the key actually solves this hard-to-recreate Bug just went to near 100%. I added a different secretkey value via web.xml, and the same error as before appeared. Then I left the loginpage open (so I have the old cookie still) and restarted again with the old static key, and it immediately worked again. So now I can deterministically reproduce the problem, and solve it by using the other key again. Which assures me that my fix is actually the fix :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant