Database exceptions are not logged to application.log

Hi, We’ve been noticing that our Splunk log aggregator has not been alerting us to all errors like it did in the past when we were on Adobe ColdFusion. We’ve tracked this down to the fact that Lucee does not log database related errors in Application.log. Is this a feature or a bug? Ideally anytime the user sees an application related exception I’d like to have an entry in the application.log for it.

The errors do get logged to exception.log.

This code will reproduce the issue:


<cfset myq = queryNew("foo")/>

<cfquery name="qrytest1" dbtype="query">
SELECT fooTypoDoesNotExist FROM myq
</cfquery>

OS: Windows
Java Version: 11.0.12
Tomcat Version: 9.0.53
Lucee Version: 5.3.8.206

1 Like

@Ryan_Stille Yes, Database exceptions are not logged on WEB-INFO application.log. But it logged on server application.log file. Do you please check on the application.log file located at lucee-installed-path\lucee-server\context\logs\application.log?

Yes @cfmitrah you are correct, they are logged there. Unfortunately the application name is not listed, and the CFML line number is buried amongst lucee-java stacktrace clutter, so this doesn’t really seem like a solution. It doesn’t show the full path to the error either, so I wouldn’t really know which site this error is from.

Is there a reason for deviating from the Adobe ColdFusion behavior here? From a developer’s perspective, I would like to easily find all my application errors in one place.

"ERROR","ajp-nio-127.0.0.1-8009-exec-8","12/23/2021","11:19:37","controller","Column not found: FOOTYPODOESNOTEXIST in statement [SELECT fooTypoDoesNotExist FROM myq];Column not found: FOOTYPODOESNOTEXIST in statement [SELECT fooTypoDoesNotExist FROM myq];lucee.runtime.exp.DatabaseException: Column not found: FOOTYPODOESNOTEXIST in statement [SELECT fooTypoDoesNotExist FROM myq]
	at org.hsqldb.jdbc.Util.sqlException(Unknown Source)
	at org.hsqldb.jdbc.jdbcStatement.fetchResult(Unknown Source)
	at org.hsqldb.jdbc.jdbcStatement.$fr$execute(Unknown Source)
	at org.hsqldb.jdbc.jdbcStatement.execute(Unknown Source)
	at lucee.runtime.type.util.QueryUtil.execute(QueryUtil.java:320)
	at lucee.runtime.type.QueryImpl.execute(QueryImpl.java:287)
	at lucee.runtime.type.QueryImpl.<init>(QueryImpl.java:235)
	at lucee.runtime.db.HSQLDBHandler.__execute(HSQLDBHandler.java:357)
	at lucee.runtime.db.HSQLDBHandler._execute(HSQLDBHandler.java:318)
	at lucee.runtime.db.HSQLDBHandler.execute(HSQLDBHandler.java:306)
	at lucee.runtime.tag.Query.executeQoQ(Query.java:1110)
	at lucee.runtime.tag.Query._doEndTag(Query.java:680)
	at lucee.runtime.tag.Query.doEndTag(Query.java:565)
	at schedules.ryan_cfm$cf$14.call(/schedules/ryan.cfm:6)
	at lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:1031)
	at lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:923)
	at lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:217)
	at lucee.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:44)
	at lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2457)
	at lucee.runtime.PageContextImpl._execute(PageContextImpl.java:2447)
	at lucee.runtime.PageContextImpl.executeCFML(PageContextImpl.java:2418)
	at lucee.runtime.engine.Request.exe(Request.java:44)
	at lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1179)
	at lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:1125)
	at lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:97)
	at lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
..."

2 Likes

Hope you all had a nice holiday.

@cfmitrah or @Zackster do you have any more thoughts on this? As a developer, I would like to find all my exceptions in one place. As I mentioned above, the main lucee-server application.log does not appear to be a workaround, since both the full path to the file and the application name is missing.

Question: Wouldn’t eventually a server wide/centralized custom error template or service component do that as an alternative? We do a similar task and get emailed on any error, no matter where and in which app it occurs. You could create some type of taylor made error service and add those to your apps. That you could fine tune with data just as you need. Add or dump information such as cgi data, form data, url data, stack traces, session data and much more). You could mail exceptions, text message them, or add them to a file, DB or what ever you want. Of course, that template needs to be solid proof and it doesnt always fit everywhere. Just an idea.

1 Like

This is what the CFCATCH and CFTRY tags are designed for.

<cftry>

  <cfquery datasource="#app.dsn#">yourbrokensqlquery</cfquery>

  <cfcatch type="database">
   
    Sorry, the database threw an error: #cfcatch.queryError#. 
Do something like Write to a log or EMAIL the query or something else

<cfabort>
  </cfcatch>

</cftry>

You could extend this further and do a complete DUMP of everything, then write it to a file, post it on Microsoft Teams, text you the error, or anything else. To me, just looking at some unfriendly java.log that an error happened is not useful, instead knowing exactly how the error occured and delivering it exactly the way I want it is.

1 Like

Thanks for the suggestion @Terry_Whitney but I think you are missing my point. In the ColdFusion/Lucee world, errors are logged to the application.log file. It was news to me that some are not being logged in the current version of Lucee, and I’ll bet it would come as a surprise to other developers too.

Here is another example. This code will cause the user to see an error, but no error is logged to Application.log.

<cfoutput>
#this_variable_does_not_exist#
</cfoutput>

Hey, Ryan. I’ll chime in to say that I am not seeing what you do. For that earlier Q of Q, I see lines written to the application.log, which start with:

"ERROR","http-nio-8888-exec-3","01/07/2022","16:10:20","",";lucee.runtime.exp.DatabaseException
Column not found: FOOTYPODOESNOTEXIST in statement [SELECT fooTypoDoesNotExist FROM myq];lucee.runtime.exp.DatabaseException: 

which is indeed the same error that showed on screen. Same with your last example here, when I referred to a non-existing var:

"ERROR","http-nio-8888-exec-5","01/07/2022","16:11:24","",";variable [X] doesn't exist;lucee.runtime.exp.ExpressionException: variable [X] doesn't exist

So I wonder: might you have error handling enabled? Even with ACF, if an error handler intercepted an error, then that error would NOT be logged. This is true whether using try/catch, app-level, or site-wide error handling.

And in fact, I did a blog post trying to encourage folks to always add a cflog/writelog of the error to the application log, whenever they DO enable error handling, especially if they just shunt off an email or write the error to a db. This way, others looking at the log COULD know that the error WAS happening. :slight_smile:

If you would say you are NOT doing error handling (of any kind), then I’ll just repeat how my testing of your examples DOES write to the applicationl.log. Perhaps there could be some other environmental difference to explain your observed behavior.

All that said, I can concur that those error messages above lack some of the info that CF errors in the same log would have. That said, those errors are not always accurate in their indication of the template and line number, right? :slight_smile: I would often point folks in that situation to that very exception log, where in CF it would show the stack trace for the request in error, and that WOULD tell us the EXACT template and line number with the error.

Well, note in this case that the Lucee devs opted to put that stack trace IN the application.log (and also the exception.log). I didn’t include that above (as it’s about 50 lines), but note that I said the log lines STARTED with that line I showed. So granted, that info in the application.log in Lucee is not as “simple” as CF’s error line, and it may tend to fill that log faster :-), but it may well be better for those who might leverage that stack trace to find the exact line and template in error.

Indeed, for those who may see this and be intrigued but don’t look at stack traces often (I did a preso on that many years ago), note that in my case the line within the long stack trace which tells me what line of code the error was on looked like this:

at tests.errorloggingtest_cfm$cf.call(/tests/errorloggingtest.cfm:11)

See the path in the parens. And in my case, that at /tests/errorloggingtest.cfm was in my C:\lucee\tomcat\webapps\ROOT, as that’s where I put Lucee (and I tend to use that folder for my lucee testing rather than have IIS or Apache setup to talk to Lucee.)

Hope that helps. But Ryan, I am especially curious if you may have an error handler blocking this logging, or we’ll figure out the environmental difference.

Maybe I am and maybe we are both missing each others intended communication.

When an error is thrown, I fail to see the point of just having a boring tomcat / lucee error. To me that is not helpful.

Now you have CFLOG, CFABORT, CFTRY, CFCATCH , all of which are there to do something on error.

As long as Lucee / ACF thinks that it can connect to the database, as far as ColdFusion is concerned, its not an application error.

Right or wrong, its just not an error that something produces an SQL error.

Now if you want your SQL errors to do more than be some random line in some application.log and be useful, which is what I was hinting at

My application.log would be filled with millions of lines of jibberish daily, as all kinds of SQL statements get screwed up when people close browsers hit refresh in the middle of something running, so on and so forth.

If you want, you can use logging server like splunk and just mirror your application logs with your sql server logs and do whatever you like with the data. Its better in some respects as you can then use session logs, device logs, ssl encryption info, and the like and then use all that data to build dashboards that the c-level will understand.

1 Like

Thanks @carehart. We do have some custom error handling, and we do purposefully write errors to the application.log ourselves in those error handling files.

It’s interesting that you are seeing an error get logged, perhaps we do have something going on in our environment. I will investigate further, thank you.

@Terry_Whitney the reason I want the errors logged is that I don’t want to rely on users reporting problems to us. I want to know when there is a problem on the site so I can take proactive action. Sometimes we get issues fixed before a user even submits the ticket. This makes our users happy. We use Splunk to alert us to errors when over a certain number of the same type of error is detected in the log. Even when the database has trouble (for example if another IT department changed a password without telling us) I would like errors to be logged in my Application.log so we know about it right away and can take action.

I understand, but I think there are better places than the application.log.

in my application.cfc
First I define the database connection and then call all other configuration values from the database, so literally if a database server goes down, everything goes down.

As for error handling, Its handled in 3 spots from being most specific to most general, of which further get aggrigated

First every query is wrapped on catch try, do
Second every page is wrapped on catch try do
Lastly if all else fails, the application is wrapped on catch try do

What is catch try do,
Its short code for

Specific
CFCATCH
log the error to the central database with all data (literally, CFDUMP)
TRY, what ever the query was, lots of specific fixes for that query / page call
Do, when the general try fails, Do something more drastic, such as Pull the logged DUMP query, and run the page catch, try , do. Very specific fixes
If that fails then run the general catch. try do, which we force the person to restart the task or put a timeout lock on it, flag it for further use.

Out of those three, you can further go back and run a Query of Query as scheduled task. In my case, its literally, create a TODO as a ticket Item, create a entry in splunk, so we have a nice pretty graph of what is causing the headaches, and to fully understand what is going on when someone claims they using the correct password to login, when in fact their caps lock was on and they claimed to be trying to remote in from home but in fact on an airplane.

That is why I am a fan of CFLOG, CFCATCH and CFTRY over just application logs. So much more can be done than simple boring java logs.