Certain pages taking a lot of time to load and throwing an error in background after migration from 1.36.6 to 1.54.0
-
So as the title states, we migrated our FA from version 1.36.6 to 1.54.0 with silentMode: true for the db migrations to run in the background
Everything seemed okay at first but I noticed that some pages, namely:
admin/users (About ~7000 users) and all pages under reports seem to take a lot of time to load and eventually it does load but I see an error in the container logs
025-03-25 11:04:44.483 AM ERROR org.primeframework.mvc.PrimeMVCRequestHandler - Error encounteredorg.primeframework.mvc.PrimeException: io.fusionauth.http.ConnectionClosedException: java.lang.InterruptedException at org.primeframework.mvc.control.FreeMarkerBodyProxy.render(FreeMarkerBodyProxy.java:43) at
Whole log line
025-03-25 11:04:44.483 AM ERROR org.primeframework.mvc.PrimeMVCRequestHandler - Error encounteredorg.primeframework.mvc.PrimeException: io.fusionauth.http.ConnectionClosedException: java.lang.InterruptedException at org.primeframework.mvc.control.FreeMarkerBodyProxy.render(FreeMarkerBodyProxy.java:43) at org.primeframework.mvc.control.AbstractControl.renderBody(AbstractControl.java:78) at org.primeframework.mvc.control.FreeMarkerControlProxy.execute(FreeMarkerControlProxy.java:63) at freemarker.core.Environment.visit(Environment.java:461) at freemarker.core.UnifiedCall.accept(UnifiedCall.java:101) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.Environment.invokeMacroOrFunctionCommonPart(Environment.java:886) at freemarker.core.Environment.invokeMacro(Environment.java:822) at freemarker.core.UnifiedCall.accept(UnifiedCall.java:83) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.Environment.invokeNestedContent(Environment.java:630) at freemarker.core.BodyInstruction.accept(BodyInstruction.java:60) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.Environment.invokeMacroOrFunctionCommonPart(Environment.java:886) at freemarker.core.Environment.invokeMacro(Environment.java:822) at freemarker.core.UnifiedCall.accept(UnifiedCall.java:83) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.Environment.invokeNestedContent(Environment.java:630) at freemarker.core.BodyInstruction.accept(BodyInstruction.java:60) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.Environment.invokeMacroOrFunctionCommonPart(Environment.java:886) at freemarker.core.Environment.invokeMacro(Environment.java:822) at freemarker.core.UnifiedCall.accept(UnifiedCall.java:83) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.Environment.invokeNestedContent(Environment.java:630) at freemarker.core.BodyInstruction.accept(BodyInstruction.java:60) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.Environment.invokeMacroOrFunctionCommonPart(Environment.java:886) at freemarker.core.Environment.invokeMacro(Environment.java:822) at freemarker.core.UnifiedCall.accept(UnifiedCall.java:83) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.Environment.invokeNestedContent(Environment.java:630) at freemarker.core.BodyInstruction.accept(BodyInstruction.java:60) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.Environment.invokeMacroOrFunctionCommonPart(Environment.java:886) at freemarker.core.Environment.invokeMacro(Environment.java:822) at freemarker.core.UnifiedCall.accept(UnifiedCall.java:83) at freemarker.core.Environment.visit(Environment.java:344) at freemarker.core.Environment.visit(Environment.java:350) at freemarker.core.Environment.process(Environment.java:323) at freemarker.template.Template.process(Template.java:383) at org.primeframework.mvc.freemarker.DefaultFreeMarkerService.render(DefaultFreeMarkerService.java:76) at org.primeframework.mvc.action.result.AbstractForwardResult.execute(AbstractForwardResult.java:92) at org.primeframework.mvc.action.result.DefaultResultInvocationWorkflow.perform(DefaultResultInvocationWorkflow.java:105) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.scope.DefaultScopeStorageWorkflow.perform(DefaultScopeStorageWorkflow.java:60) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.action.DefaultActionInvocationWorkflow.perform(DefaultActionInvocationWorkflow.java:64) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.message.DefaultMessageWorkflow.perform(DefaultMessageWorkflow.java:50) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.validation.DefaultValidationWorkflow.perform(DefaultValidationWorkflow.java:45) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.security.DefaultSecurityWorkflow.perform(DefaultSecurityWorkflow.java:79) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.parameter.DefaultPostParameterWorkflow.perform(DefaultPostParameterWorkflow.java:49) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.content.DefaultContentWorkflow.perform(DefaultContentWorkflow.java:74) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.parameter.DefaultParameterWorkflow.perform(DefaultParameterWorkflow.java:58) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.parameter.DefaultURIParameterWorkflow.perform(DefaultURIParameterWorkflow.java:92) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.scope.DefaultScopeRetrievalWorkflow.perform(DefaultScopeRetrievalWorkflow.java:50) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.action.DefaultActionMappingWorkflow.perform(DefaultActionMappingWorkflow.java:119) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.security.DefaultSavedRequestWorkflow.perform(DefaultSavedRequestWorkflow.java:65) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.cors.CORSRequestWorkflow.perform(CORSRequestWorkflow.java:68) at org.primeframework.mvc.workflow.SubWorkflowChain.continueWorkflow(SubWorkflowChain.java:50) at org.primeframework.mvc.workflow.DefaultMVCWorkflow.perform(DefaultMVCWorkflow.java:108) at org.primeframework.mvc.PrimeMVCRequestHandler.handle(PrimeMVCRequestHandler.java:73) at io.fusionauth.http.server.HTTPWorker.run(HTTPWorker.java:50) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) at java.base/java.lang.Thread.run(Thread.java:1583)Caused by: io.fusionauth.http.ConnectionClosedException: java.lang.InterruptedException at io.fusionauth.http.io.BlockingByteBufferOutputStream.addBuffer(BlockingByteBufferOutputStream.java:163) at io.fusionauth.http.io.BlockingByteBufferOutputStream.write(BlockingByteBufferOutputStream.java:141) at java.base/java.util.zip.DeflaterOutputStream.deflate(DeflaterOutputStream.java:261) at java.base/java.util.zip.DeflaterOutputStream.write(DeflaterOutputStream.java:210) at java.base/java.util.zip.GZIPOutputStream.write(GZIPOutputStream.java:148) at io.fusionauth.http.io.DelegatingOutputStream.write(DelegatingOutputStream.java:103) at java.base/sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:309) at java.base/sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:381) at java.base/sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:357) at java.base/sun.nio.cs.StreamEncoder.lockedWrite(StreamEncoder.java:158) at java.base/sun.nio.cs.StreamEncoder.write(StreamEncoder.java:139) at java.base/sun.nio.cs.StreamEncoder.write(StreamEncoder.java:167) at java.base/java.io.OutputStreamWriter.write(OutputStreamWriter.java:237) at freemarker.template.utility.StringUtil.XMLOrHTMLEnc(StringUtil.java:231) at freemarker.template.utility.StringUtil.XHTMLEnc(StringUtil.java:107) at freemarker.core.HTMLOutputFormat.output(HTMLOutputFormat.java:62) at freemarker.core.DollarVariable.accept(DollarVariable.java:68) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.IteratorBlock$IterationContext.executedNestedContentForCollOrSeqListing(IteratorBlock.java:291) at freemarker.core.IteratorBlock$IterationContext.executeNestedContent(IteratorBlock.java:271) at freemarker.core.IteratorBlock$IterationContext.accept(IteratorBlock.java:244) at freemarker.core.Environment.visitIteratorBlock(Environment.java:654) at freemarker.core.IteratorBlock.acceptWithResult(IteratorBlock.java:108) at freemarker.core.IteratorBlock.accept(IteratorBlock.java:94) at freemarker.core.Environment.visit(Environment.java:344) at freemarker.core.Environment.visit(Environment.java:350) at freemarker.core.Environment.process(Environment.java:323) at freemarker.template.Template.process(Template.java:383) at org.primeframework.mvc.freemarker.DefaultFreeMarkerService.render(DefaultFreeMarkerService.java:76) at org.primeframework.mvc.control.AbstractControl.renderEnd(AbstractControl.java:92) at org.primeframework.mvc.control.FreeMarkerControlProxy.execute(FreeMarkerControlProxy.java:64) at freemarker.core.Environment.visit(Environment.java:461) at freemarker.core.UnifiedCall.accept(UnifiedCall.java:101) at freemarker.core.Environment.visit(Environment.java:380) at freemarker.core.Environment$NestedElementTemplateDirectiveBody.render(Environment.java:3458) at org.primeframework.mvc.control.FreeMarkerBodyProxy.render(FreeMarkerBodyProxy.java:41) ... 78 common frames omittedCaused by: java.lang.InterruptedException: null at java.base/java.util.concurrent.locks.ReentrantLock$Sync.lockInterruptibly(ReentrantLock.java:159) at java.base/java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:372) at java.base/java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:332) at io.fusionauth.http.io.BlockingByteBufferOutputStream.addBuffer(BlockingByteBufferOutputStream.java:159) ... 113 common frames omittedAnother observation is that whenever one of the above mentioned pages are opened there is a sharp spike in the CPU of the deployment which then goes back to normal once the page is loaded
The app has been deployed via helmchart in a K8s environment
These are the some key configs
- name: SEARCH_TYPE value: database - name: FUSIONAUTH_APP_MEMORY value: 3072M - name: FUSIONAUTH_APP_RUNTIME_MODE value: production resources: limits: cpu: 4000m memory: 5Gi requests: cpu: 2000m memory: 4GiDatabase being a gcp managed postgres instance running postgres 11
The app and container cpu/memory values are the result of me experimenting around as I thought that resource starvation could be one of the issues
Any help in this debugging would be great, thanks!
-
@prithwhat, Are you using custom themes?
-
@mark-robustelli Yes we are
Also while I was validating this, I realized I am no longer able to save themes even though I have the global admin permission
I get the error "You are not authorized to take that action."
Are both of these issues related?
-
@mark-robustelli On further exploration I've realized that I'm getting an unauthorized screen for almost every update action i.e application, tenant, user. This seems like a larger issue
-
@mark-robustelli Update: The issue where I was unable to save any details is resolved now, it was due to misconfiguration of my headers which was reported earlier as well by someone else
I'm still facing the original thread issue for now
-
@prithwhat Glad you got the saving issue resolved. I'm not sure if this is caused by a custom theme or not. I do see a lot of references to FreeMarker in the error message, so it may be work while see if you are still having the same problem if you remove the theme. Is that possible to try?
-
@mark-robustelli it'd be quite a task since the theme has been applied to all tenants (Around ~8000) and I thought I could just simply delete the theme but it does not let me as it is in use by all of those tenants
Are there any other things that I should be looking at?
-
@prithwhat It is tough to troubleshoot without isolating the issues. You could use the APIs to remove the theme.
Not real sure where to go other than that right now. How many users and apps do you have configured? What kind of hardware is FusionAuth running on?
-
@mark-robustelli Before I move to this activity, I wanted to share an observation that I made just now
So turns out that the error that I posted doesn't turn up every time I open up one of those pages
It occurs when I open those pages consecutively and the CPU spikes to the "requests" range
So to give you an example:
Click on Users -> Takes around 20s to load -> CPU Spike observed but within request range -> No error in container logs
Click on Users -> Immediately click on Reports/Login -> Move to Reports/Registration -> CPU spikes above request range -> Error in Container logs
So could this be a performance tuning issue?
As for your query about the config
Users: 7061
Applications: 6700
Tenants: 8200Fusionauth is running on GKE on an n2d-standard-8 (8 vCPU, 32 GB RAM) nodepool, I've already mentioned the resources allocated to the deployment via the helmchart in the original thread message^
