Can anyone advise how can we prevent the inline logging of SQL requests to the lucee trace.log? Running on Lucee 5.3.10.120 When investigating a recurring issue with blocked threads (and we believe DB Deadlocks) within one of our client’s applications, we keep seeing something similar to the attached image with Fusion Reactor Profile for the blocked requests. Specifically we are seeing close to 100% of the profiled time for the request being taken up within a call to log4j from within the cfquery tag. This was somewhat unexpected, as we have not opted to perform any logging from within the cfquery tag. When checking the lucee log files within our hosting environment, we could see several log entries made to lucee trace.log similar to the following:

"WARN","XNIO-1 task-17","06/07/2023","12:31:57","cftrace","[1686137517872 ms (1st trace)] [/usr/local/lib/serverHome/WEB-INF/lucee-web/components/org/lucee/cfml/Query.cfc @ line: 30]- [arguments.sql=""{EXAMPLE SQL}""] "

This does not appear to be every trace which is logged - however it is significant enough for us to see over 2.47 Million requests logged in the last 4 weeks on one of the busier applications we host! Can anyone advise what we can do stop this being logged? Also -

1686137517872 ms

which this query has been logged as taking, equates to ~53.5 years… which is quite impressive… I hadn’t realised our application had been running that long! (or that Lucee was that old… or AWS… or the internet in general really!!!) Digging into the code for the cfquery tag,I did find the following lines - but they appear to be in a different format, and appear to be referring to and writing to datasource.log https://github.com/lucee/Lucee/blob/5.3.10.120/core/src/main/java/lucee/runtime/tag/Query.java#L778-L782 datasource.log??? Well, that’s not something which we have configured within log shipping for our production environments - as this was not a file which Lucee produced by default at the time we initially configured our log shipping with an earlier version of lucee (probably 1 5.1 variant) So I fired up a new local instance of the application, and then checked the lucee web logs folder… and… 82,000 log file lines just from starting the app and hitting a few pages. This does indeed appear to be logging every single SQL request to to the datasource log file. Looking at the the following logic from Lucee’s Query.java:

Log log = ThreadLocalPageContext.getLog(pageContext, "datasource");
if (log.getLogLevel() >= Log.LEVEL_INFO) {
	<http://log.info|log.info>("query tag", "executed [" + sqlQuery.toString().trim() + "] in " + DecimalFormat.call(pageContext, exe / 1000000D) + " ms");
}

Ok, so If I read this correctly… It appears that • Lucee is retrieving the log object for datasource.log • Lucee is comparing the configured logLevel for datasource.log to Log.LEVEL_INFO and if datasource.log logLevel is higher than Info, then write the query to the datasource.log file Ok - so, next I look at the implementation of the Log interface to see how the log levels would be compared: https://github.com/lucee/Lucee/blob/5.3.10.120/loader/src/main/java/lucee/commons/io/log/Log.java#L24-L46 Ok - so,

LEVEL_INFO = 1;

So if the datasource.log log level is set to anything other than

LEVEL_TRACE

then every SQL statement needs to be logged to datasource.log??????? 🤦 So - please tell me, am I interpreting that correctly? If datasource.log is configured to LEVEL_TRACE then nothing will be logged, but if it’s configured to LEVEL_INFO / LEVEL_DEBUG / LEVEL_WARN / LEVEL_ERROR / LEVEL_FATAL then nothing will be logged??? If that’s correct, then isn’t that the wrong way round - if we set a log level to LEVEL_WARN - doesn’t that mean “only log entries to the file which are of LEVEL_WARN or above?” I.e. the higher the value, the less should be logged? It feels like there is a bug with the logic here… and the condition has been reversed. Can I just get confirmation that my understanding (not being primarily a java developer) is correct here? I suspect that a similar logic error may be responsible for the copious (all though not as extensive) logging to the trace.log - but haven’t identified the specific location where that takes place… if anyone can enlighten me, that would be appreciated.

this was fixed in 5.4 and 5.3.10.125, just try that or the latest 5.3.10 snapshot

Ok… good to hear… 5.3.10.120 is the latest release version showing on http://stable.lucee.org/download/ - and 5.3.10.125 is a snapshot build, not even RC I see 5.4.0.65 is now available as an RC - but not a release. We would not normally deploy non release builds to prod environment - can you advise on status and ETA’s of when release builds for either are likely to be available?

everything in 5.3.10.139 is in 5.4-RC https://github.com/lucee/Lucee/compare/5.3.10.120..5.3.10.139

Ok - will there be another 5.3.10 release build? Or just 5.4.x from now on?

gotcha - so, looking at the ticket, combination of reverting a change to the default logging level, and threadsafing within ResoruceAppender ? So… as a quick fx while we evaluate and test 5.4, setting the default log level for datasource and trace log files to error (we are using cfconfig so looks like that default not set may apply to us) could poitentially resolve the majority of the issues we are experienceing?

i'd definately go to 5.3.10.125 as a minimum, but you need to test 😉

We may be ok to do that with the client experiencing the most issues (really strange - it’s happening most on a much less busy client - one with more activity, despite massive logs, is not having the timeout issues we are seeing with less issues) - but the red tape we would need to go through with some of our clients to get approval to put a snapshot version on.. yeah… probably not worth it 😂

reducing the log level will help

yeah - that will be my immediate rec - gives us time to test and address the other issues

no worries, if you don't already, we'd love some support https://opencollective.com/lucee