G'day:
This was going to be a footnote in the last post about Application.cfc weirdness, but I started getting shouty so I figured I'd factor it out into a different post.
I was getting some code not running in onApplicationEnd() which initially I did not think too much about because it was not central to what I was looking at.
This is the relevant code:
function onApplicationEnd(){
logIt("onApplicationEnd [#CGI.server_name#]");
}
function logIt(required string message){
param name="this.dataSource" default="NOT_SET";
writeLog(file=this.name, text="Start of logIt(). #message# [#this.dataSource#]");
try {
new Query(
sql = "
INSERT INTO t_test (
tst_data
) VALUES (
'#message#'
)
"
).execute();
}
catch (any e){
writeLog(file=this.name, text="CATCH in logIt(). #message# [#this.dataSource#] [#e.message#] [#e.detail#]");
rethrow;
}
writeLog(file=this.name, text="End of logIt(). #message# [#this.dataSource#]");
}
I was getting the first writeLog() entry, but not the second one. I was actually expecting the query call to error, so presumed it was, but I was seeing no evidence of this. Obviously there's no scope for an on-screen error for this as it's kicked off by onApplicationEnd(), which - intrinsically - does not fire from a browser request, but there was nothing in any log I could find either. Initially I did not have that try/catch in onApplictionEnd. What I was seeing was processing just stopping at the Query() call. No error, no nothing. So I put the try/catch in there to see if there was an error, and sure enough there was:
CATCH in logIt(). onApplicationEnd [none] [dsn2] [Attribute validation error for tag CFQUERY.] [The value of the attribute datasource, which is currently '', is invalid.]
Those values are coming from e.message and e.detail from an exception. Which I then rethrow. So there was definitely an error condition. And error conditions should get logged.
And when I say no error was logged... I mean nothing in any of CF's logs to suggest anything went wrong: no entry in any of these:
coldfusion-out.log
coldfusion-error.log
exception.log
application.log
(this is on CF10, it's not logged on CF9 either).
That is rubbish. I'm gonna raise a bug for that.
[pause for 30sec whilst I search the bugbase for any existing bugs for this...]
Here's the shouty bit.
OK, there already is one: 3041747 (and, ha, I've even voted for it!), but it's marked as "closed / deferred / not enough time". What, between July 8 2010, there's not been enough time? There was an entire release of ColdFusion that went out in the interim! That's really pathetic, Adobe. Sure this is not the most important bug in the world, but you seem to have time to f*ck around putting a completely pointless, unsolicited and unnecessary wrapper on ZingCharts which is actually harder to use than just... using ZingCharts directly, but you don't have time to fix stuff like this? You've known about it for two years!
Sigh. This is the sort of thing you should be going "oh yeah... that's a bit crap... better fix that!" Not just go "ah yeah, we'll close that and no-one will notice. Now... what was that about ZingCharts? ooh charts... shiny shiny charts...".
The next thing I noticed was... what's all this crap in coldfusion-error.log:
19-Sep-2012 16:37:28 org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: C:\\ColdFusion10\\cfusion\lib;C:\\ColdFusion10\\cfusion\jintegra\bin;C:\\ColdFusion10\\cfusion\jintegra\bin\international;C:\\ColdFusion10\\cfusion\lib\oosdk\classes\win
19-Sep-2012 16:37:28 org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-bio-8500"]
19-Sep-2012 16:37:28 org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-bio-8012"]
19-Sep-2012 16:37:28 org.apache.catalina.core.StandardService startInternal
INFO: Starting service Catalina
19-Sep-2012 16:37:28 org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.23
19-Sep-2012 16:37:29 org.apache.catalina.util.SessionIdGenerator createSecureRandom
INFO: Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [108] milliseconds.
19-Sep-2012 16:37:31 org.apache.catalina.core.ApplicationContext log
INFO: ColdFusionStartUpServlet: ColdFusion: Starting application services
19-Sep-2012 16:37:31 org.apache.catalina.core.ApplicationContext log
INFO: ColdFusionStartUpServlet: ColdFusion: VM version = 20.4-b02
19-Sep-2012 16:37:35 org.apache.catalina.core.ApplicationContext log
INFO: CFMxmlServlet: Macromedia Flex Build: 87315.134646
19-Sep-2012 16:37:41 org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8500"]
19-Sep-2012 16:37:41 org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8012"]
19-Sep-2012 16:37:41 com.adobe.coldfusion.launcher.Launcher run
INFO: Server startup in 13541 ms
None of that is an error. Why's that in there? That's just info. So should be in the coldfusion-out.log file.
Then I looked in the coldfusion-out.log file to see what was in there. Fairly "out"-y type stuff, so that's OK. But it's also got all the stuff I was writeLog()-ing to my other log file. What the hell is it doing that for? If I specifically say "put it in this particular log file", then that's the only place it should go. I put it in that file to stop it cluttering up the other files. This is how this stuff is supposed to work.
OK, so the exception.log file. What's in that? Some exceptions. Fair enough. But why were they not in the coldfusion-error.log file? Am I missing something? Shouldn't errors go in the error log? Is the name not a good hint (seemingly not).
And the application.log file. That's got exceptions in it too (just a single line, instead of the whole error though). So... aah... what? What are you doing, ColdFusion?
Maybe the coldfusion-out.log and coldfusion-error.log files are supposed to be relating to the server process itself, and not code stuff? Hard to tell. But the -error.log file certainly has stuff that isn't an error in it. And it's got nothing that is an error in it. And the -out.log has stuff that is generated by my code in it.
I'm confused. All I want to see is my errors when they happen. Is that too much to ask? I'm just assuming this is all a balls-up, unless someone wants to set me straight.
Oh, and I will be doing a blog entry about how crap the ZingCharts stuff added to <cfchart> is too. But not this evening.
Righto.
--
Adam
