I have a project I started two years ago in which I am finally trying to eliminate an error that is consistently getting thrown, though it results in no issues in the site’s performance.
For every page load on the site, I get a series of entries in the coldfusion-out.log like this:
`
174102 Jan 12, 2017 14:55:59 PM Error [ajp-bio-8014-exec-1] - 174103 Jan 12, 2017 14:55:59 PM Error [ajp-bio-8014-exec-1] - 174104 Jan 12, 2017 14:55:59 PM Error [ajp-bio-8014-exec-1] - 174105 Jan 12, 2017 14:55:59 PM Error [ajp-bio-8014-exec-1] - 174106 Jan 12, 2017 14:56:00 PM Error [ajp-bio-8014-exec-1] -
`
The series is actually much longer, between 30 and 40 such lines for each page load.
For each such individual log entry in the coldfusion-out.log, there are two corresponding entries in the exception.log:
`
61920 “Error”,“ajp-bio-8014-exec-1”,“01/12/17”,“14:56:00”,"" 61921 java.lang.NullPointerException
`
So for the series of 30-40 entries per page load, there are 30-40 such pairs in the exception.log. There are no further entries in the exception.log per each individual error. I have been trying to determine the source of the error for a while. Previously (before I began working on tracking this down) each such coldfusion-out.log entry had a stack trace in the exception.log. Those stack traces ended as follows:
`
405 “Error”,“ajp-bio-8014-exec-2”,“01/12/17”,“12:22:12”,"" 406 java.lang.NullPointerException 407 at coldfusion.util.Utils.getServletPath(Utils.java:108) 408 at coldfusion.util.Utils.getServletPath(Utils.java:98) 409 at coldfusion.util.Utils.getBaseTemplatePath(Utils.java:461) 410 at coldfusion.runtime.TemplateProxyFactory.getTemplateFileHelper(TemplateProxyFactory.java:1595) 411 at coldfusion.runtime.MetadataUtils.getComponentMetadata(MetadataUtils.java:134) 412 at coldfusion.runtime.CfJspPage.GetComponentMetadata(CfJspPage.java:2945) 413 at coldfusion.runtime.TemplateProxy.getRuntimeComponentMetadata(TemplateProxy.java:1933) 414 at coldfusion.runtime.TemplateProxy.getRuntimeMetadata(TemplateProxy.java:1792) 415 at coldfusion.runtime.MetadataUtils.getMetaData(MetadataUtils.java:55) 416 at coldfusion.runtime.CfJspPage.GetMetadata(CfJspPage.java:2918) 417 at cfContentBoxOverrides2ecfc2104071172$funcAFTERINSTANCECREATION.runFunction(C:\inetpub\wwwroot[APPLICATION DIRECTORY]\modules\contentbox\modules[CUSTOM MODULE NAME]\interceptors\interceptor.cfc:43)
`
The full trace is 400 lines, but the final lines above are the key.
Looking in my interceptor I found that the referenced line was this:
`
var objectName = GetMetaData(interceptData.target).name;
`
That’s it.
My ContentBox site includes five custom modules. Two of these modules have interceptors for afterInstanceCreation. I use the interceptors to point certain events to my custom handlers. The code I use to do this is as follows:
`
public void function afterInstanceCreation(event,interceptData,buffer) output=“true” {
var handlerService = “”;
var objectName = GetMetaData(interceptData.target).name;
objectName = REReplace(objectName,"^(" & application.root.NameSpace & “)?modules.”,"");
switch(objectName){
case “contentbox-ui.handlers.page”:
handlerService = controller.getHandlerService();
interceptData.target = handlerService.gethandler(handlerService.getRegisteredHandler("[CUSTOM MODULE NAME]:page.init"),controller.getRequestService().getContext());
break;
default:
return;
}
}
`
Each interceptor has a different series of cases in the switch/case block, but otherwise they are the same.
I added logging as follows so I could add some identifying log entries before and after the errors to confirm the offending line and determine which case(s) caused the issue:
`
public void function afterInstanceCreation(event,interceptData,buffer) output=“true” {
var handlerService = “”;
if (structKeyExists(url, “showMe”))
{
WriteLog("---------------------------------");
WriteLog(“START (Module A)”);
}
var objectName = GetMetaData(interceptData.target).name;
if (structKeyExists(url, “showMe”))
{
WriteLog(“objectName: #objectName#”);
WriteLog("---------------------------------");
}
objectName = REReplace(objectName,"^(" & application.root.NameSpace & “)?modules.”,"");
switch(objectName){
case “contentbox-ui.handlers.page”:
handlerService = controller.getHandlerService();
interceptData.target = handlerService.gethandler(handlerService.getRegisteredHandler("[CUSTOM MODULE NAME]:page.init"),controller.getRequestService().getContext());
break;
default:
return;
}
}
`
Looking at the resulting log entries, I found that the errors only happen when GetMetaData(interceptData.target).name equals contentbox.model.content.ContentVersionService.
`
174036 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - --------------------------------- 174037 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - START (Module B) 174038 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - objectName: contentbox.model.content.ContentService 174039 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - --------------------------------- 174040 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - --------------------------------- 174041 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - START (Module A) 174042 Jan 12, 2017 14:41:59 PM Error [ajp-bio-8014-exec-1] - 174043 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - objectName: contentbox.model.content.ContentVersionService 174044 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - --------------------------------- 174045 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - --------------------------------- 174046 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - START (Module B) 174047 Jan 12, 2017 14:41:59 PM Error [ajp-bio-8014-exec-1] - 174048 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - objectName: contentbox.model.content.ContentVersionService 174049 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - --------------------------------- 174050 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - --------------------------------- 174051 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - START (Module A) 174052 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - objectName: coldbox.system.plugins.Utilities 174053 Jan 12, 2017 14:41:59 PM Information [ajp-bio-8014-exec-1] - ---------------------------------
`
I of course looked at memory, but with my JVM Heap Size max at 8192, the Windows Task Manager Performance monitoring of memory shows that overall physical memory usage holds steady at 18-19 GB during a page load. ColdFusion’s physical memory usage holds steady around 2,400,000KB. The CPU usage spikes to anywhere from 50-100%, then returns to its normal 10-20%.
So something in GetMetaData(interceptData.target).name is throwing what is obviously a caught error (since the application continues to run and the function returns a value). While my site works despite this error, I would love to prevent it from happening so my logs are not cluttered with all of these entries.
Any thoughts/help would be appreciated.
The issue occurs in both dev and production. Here are the dev specs:
ContentBox: v.2.1.0.00122
ColdBox v.3.8.1.00076
Windows 10 64-bit
IIS 7.5
ColdFusion 11,0,11,301867
Java version 1.8.0_25