REST with cfoutput returns blank first few times

Hello Lucee Devs,

Our REST endpoints will not return data the first few times when using cfoutput, while using cfreturn does return data every time consistently.

It’s a simple API endpoint, mapped, has correct handlers in IIS, etc.

For example:

<cfcomponent restpath="/api/v1/test" rest="true" httpmethod="GET">
    <cffunction name="test" access="remote" returntype="any" httpmethod="GET" produces="text/plain" returnformat="json">

        <cfoutput>test</cfoutput>
        <!--- with or without additional return directive, still inconsistent --->
        <cfreturn>

    </cffunction>
</cfcomponent>

…will return blank lines for the first 1-3 times, but after hitting it 2-4 times in succession will return the output. If I wait 30 seconds or so and try again, we’re back to blank lines until it’s “warmed up”.

Whereas a returns 100% of the time.

I’ve tested every combination of headers, caching, etc, removed all complexity (no DB, no queries, just cfoutput a string) and determined the issue to be with cfoutput. I’ve tried setting “inspect templates” = “never” in case it was a recompile issue, but that does NOT fix it. I’ve tried every combination of headers, cfsettings, processing directives, etc. It is somehow caused by the combination of a REST endpoint and cfoutput.

I’ve checked the logs and debugging, and the only references I’m seeing (with EVERYTHING at trace) is in scope.log with:

DEBUG","Thread-54734","05/30/2023","07:35:06","scope-context","use existing session scope for myRestApplication/aeec96a6-f33b-4577-8090-9c28b2b20b12 from storage memory"
"INFO","Thread-54734","05/30/2023","07:35:06","scope-context","remove memory based session scope for myRestApplication/aeec96a6-f33b-4577-8090-9c28b2b20b12"

I tried setting scope from ‘memory’ to cache, issue still persists.

The catch, or “why not just use cfreturn as it’s designed?”: CFReturn will always QUOTE the response, whereas cfoutput provides raw response without quotes. This is vital as we have 3rd party APIs which we cannot update. (This is a migration effort from ACF to Lucee and we need 100% parity on this).

Is there something I’m overlooking? Is this a lucee bug, or known issue? Has this perhaps been fixed in a newer version? Is there some combination of settings or code that will make cfoutput in a REST endpoint consistent, or alternatively to remove the quotes from a cfretrun?

Any insights or thoughts appreciated!

OS : Windows Server 2019, IIS 10
Java Version : Java 11.0.11 AdoptOpenJDK 64bit, and JRE 8 build 301 (8.0.3010.9)
Tomcat Version : Apache Tomcat 9.0.46
Lucee Version : 5.3.9.129-RC

Just some ideas:

  1. If you add returnformat=json to function, It seems correct that the data is returned to you quoted. Have you tried taking it off? or use “String”

  2. Can you try to remove double quoting from onRequestEnd()?

  3. If you can rewrite the application, you can use a proxy and remove the quote from there.

HTH

1 Like

Thank you Roberto for taking time to reply! I really appreciate it.

I have tried numerous return formats and “produces” values – including JSON, plain, string, etc. It will return JSON unquoted if I return JSON – otherwise it coerces it to string and quotes the response (e.g. if returning with a // prefix, using SecureJSON or manually serializing it).

I will try removing the double quoting.

Proxy - I was hoping not to go this route, but possibly an option.

Thanks again for the suggestions!

Alright, I found a workable solution.

Again, the root of the issue seemed to be a bug with cfoutput / writeOutput consistency, something related to memory or cache at the Lucee / Java level. I tried traces, cfflush, (non)buffered output, try/catch handlers. I even consulted with ChatGPT, which suprisingly had some better suggestions than most our devs, but also lied a few times.

So decided to upgrade - upgraded Lucee from 5.3.9.39 to 5.3.10 latest (5.3.10.120), seemed to help a little. Decided to jump to beta 6.0 (6.0.0.346-BETA).

Now, the same issue happens but with interesting differences – instead of the 1-3 blank responses per-endpoint, it will only return a single blank response, and then all endpoints will return correctly for 60 seconds, at which point whatever low-level memory flush happens “un-warms” the cfoutput on the REST endpoints.

As such, using 6.0 + a scheduled task to keep REST ‘warm’ is a workable solution for us.

hmmm, there’s a background cleanup process which runs every 60s, interesting

how many

if you bump up the log level for application.log to trace (it’s verbose don’t do it on prod) you might see some more clues.

Glad to know 6 is working better for you, that’s at least good news

Please use the latest 6.0.0.418 snapshot over the first beta, it’s about to become the second beta more or less and has a lot of bug fixes

Thank you Zackster! We will probably use latest snapshot, thanks for the heads up on that.

Further update - it’s still inconsistent, even with the scheduled job. It worked well for about 30 mins but since then getting the 2-3 blanks again.

Logs already set to trace - application log doesn’t show anything (except background job every minute), neither do other logs, except the scope.log which shows it loading / unloading from memory:

"INFO","Thread-80826","05/31/2023","09:42:06","scope-context","remove memory based session scope for [myRestApplication/064d8a53-d78c-480c-8031-71c261f9dc4d]"
"DEBUG","ajp-nio-127.0.0.1-8009-exec-4","05/31/2023","09:52:30","scope-context","create new memory based session scope for myRestApplication/064d8a53-d78c-480c-8031-71c261f9dc4d"

I’ve tried changing the scope to use cache instead, but as these are dynamically generated, it doesn’t seem to make a difference.

Low memory usage (45% of 8GB for the entire machine, Tomcat only shows 1.5GB and Lucee heap only like 50MB I think?), low CPU usage.

Tried 6.0.0.418-SNAPSHOT. Had to re-establish default caches after update from 6.0.0.342 BETA.

Interestingly, the problem is worse there - more blanks than returned data.

Reverting to 6.0.0.342 BETA.

can you start a different thread about those caches plz?

ok, the rest issue causing / hiding the problem is [LDEV-1785] - Lucee

the default cache problem is [LDEV-4342] - Lucee

what’s the status codes for the blank responses?

Zac,

The status code for blank REST responses is 200 OK.
All return headers as expected (we’ve played with cache-control, gzip, text/plain vs text/json, etc and they always return correctly, even on blank responses).

If I add a , CFtrace logs will show up even when blank - but not very helpful.

INFO","ajp-nio-127.0.0.1-8009-exec-9","06/01/2023","04:46:04","cftrace","[1456 ms (1st trace)] [C:\inetpub\wwwroot\api\v1\test.cfc @ line: 152]- [REST Migration] [RESTMigrationTrace=nullValue()]  REST Migration trace "

CallStackDump() will ONLY return if it’s a non-blank return. Blank is still blank. When the CallStackDump does return, it just shows empty:Null anyway.

If I use a try/catch with a cfthrow or otherwise force an exception, we get expected logs but nothing that further points to the issue. If I try to use an include of a template, we still get blank responses.

The REST endpoint seems fine (again, switching to a cfreturn works 100% of the time) – and a cfoutput in a non-REST endpoint works 100% of the time – so there’s something with the combination of cfoutput within REST.

Further updates: Lucee 6.0.0.346-BETA works well for about 30m to 1 hour, with a single blank return before consistent output (so combined with a call to keep the REST ‘warmed’, works OK) but after that time it devolves into the same behaviour (inconsistent returns).

Lucee 6.0.0.418 and 419 do NOT have the same “stability” as the BETA.

Unfortunately, any 6.0 branch breaks other aspects of our legacy ACF application migration with variable scope issues, even toggling some of basic settings with regards to

I have come across [LDEV-1785] - Lucee] Exceptions not raised in REST before while deep diving into this. The fact it’s from 2018 does not inspire confidence. I wish I knew more Java to be able to contribute or help!

As for the cache issue, I’m not worried about it, completely incidental to testing the new version and it’s already a known issue as you pointed out.

Thank you Zac and all the Lucee devs for your help on this!

does it reproduce standalone with just the example in the original post?

Yes, it is reproducible with the standalone example in my first post.

ok, i’ve repo-ed, it’s on my list :slight_smile:

@quantumleapchicago can you file a bug with a link to this task and your nice repo example

Done and done.

https://luceeserver.atlassian.net/browse/LDEV-4524

Thanks again for getting this on the list.

2 Likes