Coldfusion automatically restarted - tracking the cause

Report · Nov 27, 2012

Coldfusion is automatically restarting, a lot. It comes in waves, everything seems fine for a while then the server struggles for a few minutes, restarts a lot then settles down again.

I have Fusion Reactor installed, but when CF goes down FR stops logging so it's not really helping. Looking through the archived logs just shows gaps in the logs.

These are all the occourances of the phrase "Coldfusion started" today.

[root@server2 logs]# grep -i "Coldfusion started" server.log | grep "11/27/12"

"Information","main","11/27/12","01:49:35",,"ColdFusion started"

"Information","main","11/27/12","01:50:46",,"ColdFusion started"

"Information","main","11/27/12","01:52:39",,"ColdFusion started"

"Information","main","11/27/12","01:54:08",,"ColdFusion started"

"Information","main","11/27/12","01:55:12",,"ColdFusion started"

"Information","main","11/27/12","01:56:29",,"ColdFusion started"

"Information","main","11/27/12","01:57:36",,"ColdFusion started"

"Information","main","11/27/12","01:58:57",,"ColdFusion started"

"Information","main","11/27/12","01:59:56",,"ColdFusion started"

"Information","main","11/27/12","02:01:38",,"ColdFusion started"

"Information","main","11/27/12","02:03:11",,"ColdFusion started"

"Information","main","11/27/12","02:04:41",,"ColdFusion started"

"Information","main","11/27/12","02:07:53",,"ColdFusion started"

"Information","main","11/27/12","02:10:45",,"ColdFusion started"

"Information","main","11/27/12","02:11:49",,"ColdFusion started"

"Information","main","11/27/12","02:13:09",,"ColdFusion started"

"Information","main","11/27/12","02:14:18",,"ColdFusion started"

"Information","main","11/27/12","02:15:44",,"ColdFusion started"

"Information","main","11/27/12","02:17:06",,"ColdFusion started"

"Information","main","11/27/12","02:34:19",,"ColdFusion started"

"Information","main","11/27/12","03:01:20",,"ColdFusion started"

"Information","main","11/27/12","05:25:59",,"ColdFusion started"

"Information","main","11/27/12","06:30:48",,"ColdFusion started"

"Information","main","11/27/12","06:36:20",,"ColdFusion started"

"Information","main","11/27/12","09:34:07",,"ColdFusion started"

"Information","main","11/27/12","09:35:39",,"ColdFusion started"

"Information","main","11/27/12","09:36:41",,"ColdFusion started"

"Information","main","11/27/12","09:39:15",,"ColdFusion started"

"Information","main","11/27/12","09:40:42",,"ColdFusion started"

"Information","main","11/27/12","09:42:55",,"ColdFusion started"

"Information","main","11/27/12","09:44:23",,"ColdFusion started"

"Information","main","11/27/12","09:46:18",,"ColdFusion started"

"Information","main","11/27/12","09:47:35",,"ColdFusion started"

"Information","main","11/27/12","09:48:53",,"ColdFusion started"

"Information","main","11/27/12","09:50:04",,"ColdFusion started"

"Information","main","11/27/12","09:51:51",,"ColdFusion started"

"Information","main","11/27/12","09:53:05",,"ColdFusion started"

"Information","main","11/27/12","09:54:24",,"ColdFusion started"

"Information","main","11/27/12","09:55:28",,"ColdFusion started"

"Information","main","11/27/12","09:56:38",,"ColdFusion started"

"Information","main","11/27/12","09:58:03",,"ColdFusion started"

"Information","main","11/27/12","09:59:03",,"ColdFusion started"

"Information","main","11/27/12","10:04:37",,"ColdFusion started"

"Information","main","11/27/12","12:04:02",,"ColdFusion started"

I've been looking at the live server metrics in FR on a second screen all day, the CPU, Memory and requests all seemed fine about 12 midday, then the server rebooted.

Looking at the logs for the hour between 9am and 10am (more than 15 restarts in the hour), the CPU never went over 44% usage and the Memory never exceeded 53% usage - in the recorded stats at least.

There is no JDBC tracking at the moment, so I'll add that to tracking and see if it's MySQL causing a problem, but can anyone help me narrow down the problem, what would cause Cold Fusion to auto restart, and I'm assuming the auto restart is only happening because Fusion Reactor is installed.

It's a Red Hat 5 LAMP stack running Coldfusion 9 and Fusion Reactor 4.5.2

Report · Nov 27, 2012

Is this a new server, upgraded server, changed server?

Just trying to determine if the server restarting is a new thing on this server or if it has been doing this all along (recently built).

Report · Nov 27, 2012

It's about 2 years old. It's had updates applied to it, but nothing recently.

CF Version : 9,0,2,282541

The only major change I've added recently was installing Fusion Reactor, but the problems were already occuring before that.

Report · Nov 27, 2012

I have not used Fusion Reactor but since it is a server monitoring tool it seems odd that it is not logging anything. Before installing Fusion Reactor was ColdFusion restarting or just stopping? I'm not pointing to Fusion Reactor as the culprit but just thinking that if it is not helping you then perhaps you can disable it until the next ColdFusion failure. Maybe then you will see something in the logs. Or can you check previous logs before you installed Fusion Reactor to see what ColdFusion was reporting (if anything).

Just thinking out loud here...

Report · Nov 27, 2012

I think Fusion Reactor is triggering the restart - prior to that it would just throw a 500 error which would appear in the browser. The trouble is the user still gets a 500 while the server restarts.

FR doesn't log anytrhing while CF is booting up - it stores logs since the server startup.

I'll try disabling the autorestart, or possibly just FR completly and look at the the cfserver.log

I've still got the problem os something is crashing in my Coldfusion application either way

Report · Nov 27, 2012

The ColdFusion server log doesn't generally report much. I'm not sure on Linux installs but does the JRun4/logs directory still contain the cfusion-out.log file? That log file shows a much broader picture of what is happening.

Report · Nov 27, 2012

I have no idea where the JRun logs are, I will try and find them and look in there.

Is there a way I can log data source activity?

Report · Nov 27, 2012

There is a setting under the datasource(s) in the ColdFusion admin to log database activity. It might depend on the drivers being used.

Report · Nov 27, 2012

PeteComcar wrote:
I have no idea where the JRun logs are, I will try and find them and look in there.

I found this regarding the JRun logfiles http://helpx.adobe.com/legacy/kb/jrun-4-0-configuring-java.html

Report · Nov 27, 2012

PeteComcar wrote:
I have no idea where the JRun logs are, I will try and find them and look in there.

I think you will find what you're looking for in {CF_INSTALLATION_DIR}/runtime/logs. However, my feeling is that we will get clues by examining exception.log, application.log, coldfusion-out.log and server.log. They are located in {CF_INSTALLATION_DIR}/logs.

Report · Nov 28, 2012

I don't have a cfusion-out.log file in {CF_INSTALLATION_DIR}/runtime/logs, but I do have coldfusion-event.log (and archived version).

How much of the logs should I paste up, they're obviously all huge?

There is nothing in the application.log after 3:26 this morning, the server rebooted at 06:28 and at 09:15 so I can't see application.log having anything useful

Here's 50 lines of the cfserver.log, with the 09:15 restart in the middle:

11/28 09:09:17 Information [jrpp-16] - HTTP request completed {Status Code=200 ,Time taken=54 ms}

11/28 09:09:17 Information [jrpp-3] - Starting HTTP request {URL='http://www.nissan.co.uk:80/flash/navAS3_HTML_V2/en_GB/vehicles/links.xml', method='get'}

11/28 09:09:17 Information [jrpp-3] - HTTP request completed {Status Code=200 ,Time taken=27 ms}

11/28 09:09:50 Information [jrpp-11] - Starting HTTP request {URL='http://www.nissan.co.uk:80/flash/navAS3_HTML_V2/en_GB/vehicles/links.xml', method='get'}

11/28 09:09:50 Information [jrpp-11] - HTTP request completed {Status Code=200 ,Time taken=47 ms}

11/28 09:13:42 error Cannot create cookie: , CFID = 10620790

11/28 09:13:42 error Cannot create cookie: , CFID = 10620791

11/28 09:13:43 error Cannot create cookie: , CFID = 10620792

11/28 09:13:43 error Cannot create cookie: , CFID = 10620794

11/28 09:13:44 error Cannot create cookie: , CFID = 10620795

11/28 09:13:45 error Cannot create cookie: , CFID = 10620796

11/28 09:13:46 error Cannot create cookie: , CFID = 10620797

11/28 09:13:46 error Cannot create cookie: , CFID = 10620799

11/28 09:13:47 error Cannot create cookie: , CFID = 10620801

11/28 09:13:48 error Cannot create cookie: , CFID = 10620802

11/28 09:13:48 error Cannot create cookie: , CFID = 10620803

11/28 09:14:55 error Cannot create cookie: , CFID = 10620804

11/28 09:14:56 error Cannot create cookie: , CFID = 10620850

11/28 09:14:57 error Cannot create cookie: , CFID = 10620851

11/28 09:14:58 error Cannot create cookie: , CFID = 10620853

11/28 09:14:58 error Cannot create cookie: , CFID = 10620854

11/28 09:14:59 error Cannot create cookie: , CFID = 10620855

11/28 09:14:59 error Cannot create cookie: , CFID = 10620856

11/28 09:15:00 error Cannot create cookie: , CFID = 10620858

11/28 09:15:01 error Cannot create cookie: , CFID = 10620861

11/28 09:15:29 Information [jrpp-0] - Starting HTTP request {URL='http://www.nissan.co.uk:80/flash/navAS3_HTML_V2/en_GB/vehicles/links.xml', method='get'}

11/28 09:15:29 Information [jrpp-0] - HTTP request completed {Status Code=200 ,Time taken=69 ms}

autorestart: Restarting process

Starting Macromedia JRun 4.0 (Build 108858), coldfusion server

11/28 09:16:40 warning Unable to open /opt/coldfusion9/runtime/lib/license.properties

11/28 09:16:40 info JRun Naming Service listening on *:2932

11/28 09:16:42 info No JDBC data sources have been configured for this server (see jrun-resources.xml)

11/28 09:16:42 info JRun Proxy Server listening on *:51800

11/28 09:16:42 info Deploying enterprise application "Adobe_ColdFusion_9" from: file:/opt/coldfusion9/

11/28 09:16:42 info Deploying web application "Adobe ColdFusion 9" from: file:/opt/coldfusion9/

11/28 09:16:43 INFO License Service: Flex 1.5 CF Edition enabled

11/28 09:16:43 INFO Starting Flex 1.5 CF Edition

11/28 09:16:43 user FusionReactor Framework Host Manager - Initializing

11/28 09:16:43 user INFO FusionReactor FW: Initializing framework.

11/28 09:16:43 user INFO FusionReactor FW: Loading Framework Configuration from /opt/fusionreactor/instance/coldfusion.cfmx9.server2/osgi/fr-osgi.conf

11/28 09:16:43 user INFO Logging at level INFO

11/28 09:16:43 user INFO FusionReactor FW: --------------------------------------------------------------------------------------

11/28 09:16:43 user INFO FusionReactor FW: Revision: fusionreactor-core 4.5.2

11/28 09:16:43 user INFO FusionReactor FW: --------------------------------------------------------------------------------------

11/28 09:16:43 user INFO FusionReactor FW: Installing AutoStart bundles.

11/28 09:16:43 error There is no web application configured to service your request

11/28 09:16:43 user NoWebappServlet: init

11/28 09:16:44 user INFO FusionReactor FW: Installing Plugin bundles.

11/28 09:16:44 user INFO FusionReactor FW: Bootstrap: Ascending to runlevel 2

11/28 09:16:44 user INFO FusionReactor FW: Bootstrap: Runlevel 2 achieved.

11/28 09:16:44 error There is no web application configured to service your request

Report · Nov 28, 2012

Ok there is nothing after 3:36 in the exception.log either, but this is the last 30 lines of the server.log:

$ tail -n 30 server.log

"Information","main","11/28/12","06:38:11",,"Starting FlexAssembler..."

"Information","main","11/28/12","06:38:11",,"Starting .NET..."

"Information","main","11/28/12","06:38:11",,"Starting Monitoring..."

"Information","main","11/28/12","06:38:11",,"ColdFusion started"

"Information","main","11/28/12","09:16:46",,"Starting logging..."

"Information","main","11/28/12","09:16:46",,"Starting license..."

"Information","main","11/28/12","09:16:47",,"Standard Edition enabled"

"Information","main","11/28/12","09:16:47",,"Starting crypto..."

"Information","main","11/28/12","09:16:47",,"Starting security..."

"Information","main","11/28/12","09:16:47",,"Starting scheduler..."

"Information","main","11/28/12","09:16:47",,"Starting WatchService..."

"Information","main","11/28/12","09:16:47",,"Starting debugging..."

"Information","main","11/28/12","09:16:47",,"Starting sql..."

"Information","main","11/28/12","09:16:47",,"Pool Manager Started"

"Information","main","11/28/12","09:16:47",,"Starting mail..."

"Information","main","11/28/12","09:16:47",,"Starting runtime..."

"Information","main","11/28/12","09:16:48",,"CORBA Configuration not enabled"

"Information","main","11/28/12","09:16:48",,"Starting cron..."

"Information","main","11/28/12","09:16:48",,"Starting registry..."

"Information","main","11/28/12","09:16:48",,"Starting client..."

"Information","main","11/28/12","09:16:48",,"Starting xmlrpc..."

"Information","main","11/28/12","09:16:48",,"Starting graphing..."

"Information","main","11/28/12","09:16:48",,"Starting solr..."

"Information","main","11/28/12","09:16:48",,"Starting archive..."

"Information","main","11/28/12","09:16:48",,"Starting document..."

"Information","main","11/28/12","09:16:48",,"Starting eventgateway..."

"Information","main","11/28/12","09:16:48",,"Starting FlexAssembler..."

"Information","main","11/28/12","09:16:48",,"Starting .NET..."

"Information","main","11/28/12","09:16:48",,"Starting Monitoring..."

"Information","main","11/28/12","09:16:48",,"ColdFusion started"

Report · Nov 28, 2012

I've found this command in a ps.log file - which comes from my /etc/init.d/coldfusion9, so I at least now see that the autorestart is part of CF9 :

apache 16919 0.0 0.0 8372 696 ? S Nov27 0:00 /opt/coldfusion9/runtime/bin/coldfusion9 -jar jrun.jar -autorestart -start coldfusion

Now just got to find the cause.

Report · Nov 28, 2012

PeteComcar wrote:
11/28 09:13:42 error Cannot create cookie: , CFID = 10620790

We can at least debug this one. It very likely occurs because you have, in your cookie code, given a cookie a name that is a reserved word. See Jochem van Dieten's article on using reserved names for cookies. So review your code for places where cookies are named.

Report · Dec 03, 2012

We had to get some external help to fix this - David Stockton from CFConsultand.com - so I can't really post the solution, but it was a very specific page that only caused a problem if the right URL params were passed in.

It caused a recursive function to be called without exiting.

Adobe Community

Coldfusion automatically restarted - tracking the cause

1 Correct answer