empty onSessionEnd creating NullPointerExceptions?

[bruceb19075631]

Some background: we recently upgraded from CF 10 to CF 2016, and moved to a new server (Windows Server 2012 R2, IIS 8).  All updates are installed for all of the above (cf version 2016.0.03.300466 and jvm version: 25.72-b15).

Here's the issue:  In my Application.cfc I've got a completely empty onSessionEnd.

<cffunction name="onSessionEnd" returnType="void">

    <cfargument name="SessionScope" required="true" />

    <cfargument name="ApplicationScope" required="false" />

</cffunction>

I've got onError is currently set up to send me an email. 

I am periodically getting this:

arguments - struct

EVENTNAME	onSessionEnd
EXCEPTION	arguments - struct Cause arguments - struct Message [empty string] StackTrace java.lang.NullPointerException at coldfusion.runtime.NeoJspWriter.writeOutput(NeoJspWriter.java:228) at coldfusion.runtime.NeoJspWriter.flush(NeoJspWriter.java:362) at coldfusion.cfc.CFCProxy.flush(CFCProxy.java:357) at coldfusion.cfc.CFCProxy.doInvoke(CFCProxy.java:332) at coldfusion.cfc.CFCProxy.invoke(CFCProxy.java:302) at coldfusion.runtime.AppEventInvoker.onSessionEnd(AppEventInvoker.java:462) at coldfusion.runtime.SessionTracker.invokeOnSessinEnd(SessionTracker.java:291) at coldfusion.runtime.SessionTracker.cleanUp(SessionTracker.java:274) at coldfusion.runtime.SessionTracker.access$000(SessionTracker.java:43) at coldfusion.runtime.SessionTracker$SessionCleanUpAgent.run(SessionTracker.java:483) at coldfusion.scheduling.ThreadPool.run(ThreadPool.java:260) at coldfusion.scheduling.WorkerThread.run(WorkerThread.java:71) Suppressed arguments - array [empty] TagContext arguments - array [empty] Type java.lang.NullPointerException Detail An exception occurred while invoking an event handler method from Application.cfc. The method name is: onSessionEnd. Message Event handler exception.

I'm basically at a loss as to how it's generating a nullPointerException (which, to my understanding, can sometimes be basically a variable undefined error when encountered in onSessionEnd or onApplicationEnd which aren't handled well by onError, but as there's literally nothing in it, that's not relevant).

So I dug into the logs.

Exception log:

"Error","scheduler-2","12/02/16","15:13:59","","'' The specific sequence of files included or processed is: '''' "

java.lang.NullPointerException

    at coldfusion.runtime.NeoJspWriter.writeOutput(NeoJspWriter.java:228)

    at coldfusion.runtime.NeoJspWriter.flush(NeoJspWriter.java:362)

    at coldfusion.cfc.CFCProxy.flush(CFCProxy.java:357)

    at coldfusion.cfc.CFCProxy.doInvoke(CFCProxy.java:332)

    at coldfusion.cfc.CFCProxy.invoke(CFCProxy.java:302)

    at coldfusion.runtime.AppEventInvoker.onSessionEnd(AppEventInvoker.java:462)

    at coldfusion.runtime.SessionTracker.invokeOnSessinEnd(SessionTracker.java:291)

    at coldfusion.runtime.SessionTracker.cleanUp(SessionTracker.java:274)

    at coldfusion.runtime.SessionTracker.access$000(SessionTracker.java:43)

    at coldfusion.runtime.SessionTracker$SessionCleanUpAgent.run(SessionTracker.java:483)

    at coldfusion.scheduling.ThreadPool.run(ThreadPool.java:260)

    at coldfusion.scheduling.WorkerThread.run(WorkerThread.java:71)

application log:

"Error","scheduler-2","12/02/16","15:13:59","","'' The specific sequence of files included or processed is: '''' "

coldfusion-out log:

Dec 2, 2016 15:13:59 PM Error [scheduler-2] - '' The specific sequence of files included or processed is: ''''

Other notes: I am using J2EE session variables, and SESSSION management is enabled for the app.

My question(s): what weird thing is this scheduler thread doing, why would it be encountering a null pointer exception in onsessionend, and how would one go about stopping it from occurring again?

[BKBK]

Weird indeed. The only cause I can think of is a NULL session. Which implies no session might have been created in the first place or that an error resulted during the creation of the session.

Could you show us how you enable sessions? Also, what are your JVM parameters? Does your Coldfusion installation share JVM resources with an external application, such as FusionReactor?

[philipp40543364]

We are having the same problem, although we don't have an empty OnSessionEnd function. I'm curious about why you're asking about sharing resources with FusionReactor, what affects might that have?

Edit: @bruceb19075631​ does it happen for you every time or sporadically?

[bruceb19075631]

The problem started with a normal, full of stuff onsessionend. 

We slowly pared it down until it was completely empty and the problem still persisted/persists.

Originally I believed it was happening at the end of every session, but we eventually figured out that the error doesn't happen on normal session endings.  Only when these weird scheduler things happen.

[BKBK]

bruceb19075631 wrote:

Originally I believed it was happening at the end of every session, but we eventually figured out that the error doesn't happen on normal session endings. Only when these weird scheduler things happen.

The [scheduler-x] things are just the threads that run the onSessionEnd method. The error implies that Coldfusion encounters a null object when ending a session.

By design, when a session ends, Coldfusion calls the onSessionEnd method. When it does, it passes a session-scope struct and an application-scope struct. The logical explanation I can think of for the error is that at least one of the structs is non-existent, hence null. If true, then this is a bug. I would therefore suggest that you report a bug.

Could you show us the entire Application.cfc?

[BKBK]

philipp40543364 wrote:

I'm curious about why you're asking about sharing resources with FusionReactor, what affects might that have?

Sometimes when you instal FusionReactor the JVM settings of your Coldfusion settings change.

[BKBK]

philipp40543364 wrote:

Edit: @bruceb19075631 does it happen for you every time or sporadically?

I also wanted to ask that. The cause of the error may be a stranded scheduled task. Do you run any custom scheduled tasks?

[bruceb19075631]

We do have some scheduled tasks on the server, but they're largely once a day things, with the exception of one that runs every 30 minutes, and one every 6 hours.  The times don't remotely match up, and don't remotely conform to those intervals.

Additionally, scheduled tasks show up in the logs with a ThreadID of [DefaultQuartzScheduler_Worker-x] where x is a number, like so:

     Dec 15, 2016 16:37:00 PM Information [DefaultQuartzScheduler_Worker-4] - Task default. [NAME OF TASK] triggered.

     Dec 15, 2016 16:37:00 PM Information [DefaultQuartzScheduler_Worker-4] - Starting HTTP request {URL='[URL OF TASK]', method='get'}

     Dec 15, 2016 16:37:00 PM Information [DefaultQuartzScheduler_Worker-4] - HTTP request completed  {Status Code=200 ,Time taken=47 ms}

All the normal requests are handled via ThreadID [ajp-nio-8016-exec-x] where x is a number.

     Dec 15, 2016 16:37:53 PM Error [ajp-nio-8016-exec-6] - File not found: [NONEXISTENT FILE] The specific sequence of files included or processed is: [FILEPATH]''

     Dec 15, 2016 16:37:55 PM Information [ajp-nio-8016-exec-4] - Starting HTTP request {URL='[REMOTE URL]', method='get'}

     Dec 15, 2016 16:37:56 PM Information [ajp-nio-8016-exec-4] - HTTP request completed  {Status Code=200 ,Time taken=516 ms}

Whereas when the actual error occurs, you can see it's executed by the [scheduler-x] ThreadIDs (and then I'm promptly sent an email about it):

     Dec 15, 2016 16:46:15 PM Error [scheduler-2] - '' The specific sequence of files included or processed is: ''''

     Dec 15, 2016 16:46:24 PM Information [scheduler-0] - Mail: 'New Error' From:'site_error@[SITE].com' To:'[MY EMAIL]' was successfully sent using [MAIL SERVER]

The only thing besides sending error emails and metrics (before I disabled metrics logging so I could actually read the logs easily) that [scheduler-x] does is:

     Dec 15, 2016 15:00:05 PM Information [scheduler-0] - Run Client Storage Purge

Well, besides my lovely inexplicable

      Dec 15, 2016 14:56:02 PM Error [scheduler-0] - '' The specific sequence of files included or processed is: ''''

Thoughts?

[BKBK]

Well described, @bruceb19075631. I am looking into it some more.

Did you try out the suggestions of yesterday? If so, what did you get?

[bruceb19075631]

Sessions are enabled at top of Application.cfc, per usual.

<cfcomponent output="false">

<cfset this.name = "[applicationname]" />

<cfset this.applicationTimeout = createTimeSpan(5,0,0,0) />

<cfset this.loginStorage = "session" />

<cfset this.scriptProtect = "all" />

<cfset this.serverSideFormValidation = "no" />

<cfset this.sessioncookie.httponly = "yes" />

<cfset this.sessionManagement = "yes" />

<cfset this.sessionTimeout = createTimeSpan(0,0,30,0) />

<cfset this.setclientcookies = "no">
etc. etc.

JVM arguments: -server -XX:MaxMetaspaceSize=192m -XX:+UseParallelGC -Xbatch -Dcoldfusion.home={application.home} -Duser.language=en -Dcoldfusion.rootDir={application.home} -Dcoldfusion.libPath={application.home}/lib -Dorg.apache.coyote.USE_CUSTOM_STATUS_MSG_IN_HEADER=true -Dcoldfusion.jsafe.defaultalgo=FIPS186Random -Dorg.eclipse.jetty.util.log.class=org.eclipse.jetty.util.log.JavaUtilLog -Djava.util.logging.config.file={application.home}/lib/logging.properties

CF is the only thing using JVM on the machine.

[Steve Sommers]

Just a guess but possibly the required="true" parameter in the cfargument tag.

[BKBK]

Steve Sommers wrote:

Just a guess but possibly the required="true" parameter in the cfargument tag.

I agree. The application could be debugged as follows

<cffunction name="onSessionEnd" returnType="void">

    <cfargument name="SessionScope" required="true" />

    <cfargument name="ApplicationScope" required="true" />

<cftry>

    <cflog file="#this.Name#" type="Information" text="The session #arguments.SessionScope.sessionid# has ended">

<cfcatch type="Any">

    <cflog file="errorInOnSessionEnd" type="error" text="cfcatch.message=#cfcatch.message#">

</cfcatch>

</cftry>

</cffunction>

[Steve Sommers]

Maybe try:

<cffunction name="onSessionEnd" returnType="void">

    <cfargument name="SessionScope" required="false" />

    <cfargument name="ApplicationScope" required="false" />

<cftry>

<cfif structKeyExists(arguments,"SessionScope")>

    <cflog file="#this.Name#" type="Information" text="The session #arguments.SessionScope.sessionid# has ended" />

<cfelse>

    <cflog file="#this.Name#" type="Information" text="Unprovided session has ended" />

<cfelse>

</cfif>

<cfcatch type="Any">

    <cflog file="errorInOnSessionEnd" type="error" text="cfcatch.message=#cfcatch.message#" />

</cfcatch>

</cftry>

</cffunction>

[Terry_2011_]

Hi Bruce --

Did you ever work out a fix for this?

We are having this identical problem.   We just went from CF9 to CF2016 and have been seeing these appear in our app.log once or twice a day:

"Error","scheduler-2","08/04/17","17:51:21","","'' The specific sequence of files included or processed is: '''' "

"Error","scheduler-2","08/04/17","17:51:21","","'' The specific sequence of files included or processed is: '''' "

"Error","scheduler-2","08/04/17","17:51:21","","'' The specific sequence of files included or processed is: '''' "

There were 38 lines of this just a few minutes ago.

Each one corresponds to an exception.log error:

"Error","scheduler-2","08/04/17","17:51:21","","'' The specific sequence of files included or processed is: '''' "

java.lang.NullPointerException

        at coldfusion.runtime.NeoJspWriter.writeOutput(NeoJspWriter.java:228)

        at coldfusion.runtime.NeoJspWriter.flush(NeoJspWriter.java:362)

        at coldfusion.cfc.CFCProxy.flush(CFCProxy.java:357)

        at coldfusion.cfc.CFCProxy.doInvoke(CFCProxy.java:332)

        at coldfusion.cfc.CFCProxy.invoke(CFCProxy.java:302)

        at coldfusion.runtime.AppEventInvoker.onSessionEnd(AppEventInvoker.java:462)

        at coldfusion.runtime.SessionTracker.invokeOnSessinEnd(SessionTracker.java:292)

        at coldfusion.runtime.SessionTracker.cleanUp(SessionTracker.java:275)

        at coldfusion.runtime.SessionTracker.access$000(SessionTracker.java:43)

        at coldfusion.runtime.SessionTracker$SessionCleanUpAgent.run(SessionTracker.java:484)

        at coldfusion.scheduling.ThreadPool.run(ThreadPool.java:260)

        at coldfusion.scheduling.WorkerThread.run(WorkerThread.java:71)

This looks like your same problem.   Did you ever find a way to stop the exceptions from occurring?

[BKBK]

Chances are, there is a bug in ColdFusion 2016's session apparatus.

I have voted for your bug report, CF-4199420.