[Coldbox 6.8.0+4] Event Caching Tomcat Error

Communities TestBox BDD
1

When I reload a page that has uses event caching, I get a tomcat error as follows:

image

The error goes away when I reinit the app, or add a query string param (which bypasses the event cache), but as soon as it tries to return the event from cachebox, I get the internal server error message.

Server: ACF 2018
Web Server: IIS
OS: Windows Server 2012 R2

Here’s an example of a the Main.cfc handler which causes the problem:

function index( event, rc, prc ) cache="true" cacheTimeout="30" {
    prc.page = pageService.getById( 1 );
    event.setView( "main/index" );
}

Removing cache="true" and cacheTimeout="30" fixes the problem.

Package List:
image

image

~Either way, I rolled back as far as 6.6.1+2 and I still receive the same error, so I do not believe this has something to do with the latest update.~

Update: I can confirm this only occurs on IIS and not with the embedded Commandbox server.

Update 2: I fired up my trusty instance of FusionReactor and took a look at one of the requests that bombed. The stack trace of the request looked like this:

"ajp-nio-127.0.0.1-8018-exec-10" Id=227 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@5ebae219 
   java.lang.Thread.State: WAITING
        at java.base@11.0.11/jdk.internal.misc.Unsafe.park(Native Method)
        - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@5ebae219
        at java.base@11.0.11/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
        at java.base@11.0.11/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
        at java.base@11.0.11/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:146)
        at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1114)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.base@11.0.11/java.lang.Thread.run(Thread.java:834)
2

I think ColdBox sends a 206 status code for cached pages. It sounds like your iis connector is getting confused by that.

3

Thanks, Brad. So does this mean that ACF 2018 + IIS may not be compatible with ColdBox’s event caching?

4

I started digging in the /coldFusion2018/config/wsconfig/ folder and found a log file for isapi_redirect.log. Inside the log were a few errors I haven’t seen before:

[Fri Aug 05 14:30:03.592 2022] [30392:1368] [error] ajp_unmarshal_response::jk_ajp_common.c (786): (cfusion) NULL status
[Fri Aug 05 14:30:03.593 2022] [30392:1368] [error] ajp_process_callback::jk_ajp_common.c (1968): (cfusion) ajp_unmarshal_response failed
[Fri Aug 05 14:30:03.594 2022] [30392:1368] [error] ajp_service::jk_ajp_common.c (2975): (cfusion) sending request to tomcat failed (unrecoverable), because of server error (attempt=1)
[Fri Aug 05 14:30:03.595 2022] [30392:1368] [error] HttpExtensionProc::jk_isapi_plugin.c (2734): service() failed with http error 500
5

What status code does FR report for the request?

6

FR reports a status code of 0.

image

7

Things get even more interesting! I rolled back ColdBox to 6.6.1, restarted CF Services, and event caching started working again. I upgraded to 6.8.0, restarted CF Services, and event caching returns the error again.

My current theory is that something changed from 6.6.1 to 6.8.0 which causes a problem within IIS and ACF.

8

I believe I figured out the problem.
This commit (COLDBOX-1100 #resolve · ColdBox/coldbox-platform@39f3480 · GitHub) was supposed to address the issue of status codes not being preserved when using event caching.

However, if you dump out the status code and abort the request, you can see that local.refResults.eventCaching.statusCode is always 0, which is not valid. This causes the IIS connector to barf. It is not clear at the moment why the original status code isn’t saved in the cache.

// Cached Status Code
if ( isNumeric( local.refResults.eventCaching.statusCode ) ) {
	writeDump( "Output Cached Status Code" );
        writeDump( local.refResults.eventCaching.statusCode );
        abort;
        event.setHTTPHeader( statusCode = local.refResults.eventCaching.statusCode );
}

Ironically (or coincidental?), the issue this commit addressed was submitted by me.
@lmajano Let me know if you want me to create a new issue. Hopefully, it’s just a quick fix to get the status code saved in local.refResults.eventCaching.

It should be noted that this issue also impacts Commandbox’s built-in server as well. The response from a cached event will not have a status code, which could be problematic for many that rely on the status code.

First Request (not-cached):
image
Second Request (cached):
image

9

Wow, good find! Interesting that it messes up IIS, but not surprising.

10

Yea please. Not sure where the code is becoming a 0

11

I added a check to make sure not only that it’s numeric, but > 0 Let’s see if this helps. I still need to find out, where the 0 came from

12

I did some more digging and it looks like when cacheEntry is built, the statusCode is set to a value of 0 (see line 356):

I do not know why getPageContextResponse().getStatus() is 0 at this point in the request.

13

Created issue: ColdBox Platform - Issues - Welcome

14

Thanks, I committed already something on Saturday to fix this. Please try be

15

Thanks @lmajano. The fix corrects the error but caused a regression in [COLDBOX-1100] - Welcome. Cached responses will always have a response code of 200 which is not good for 404 or other pages that need a different status code.