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

prithwhat

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 omitted

Another 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: 4Gi

Database 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!

mark.robustelli

@prithwhat, Are you using custom themes?

prithwhat

@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?

prithwhat

@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

prithwhat

@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

mark.robustelli

@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?

prithwhat

@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?

mark.robustelli

@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?

prithwhat

@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: 8200

Fusionauth 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^