Copy link to clipboard
Copied
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
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.
Copy link to clipboard
Copied
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).
Copy link to clipboard
Copied
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.
Copy link to clipboard
Copied
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...
Copy link to clipboard
Copied
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
Copy link to clipboard
Copied
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.
Copy link to clipboard
Copied
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?
Copy link to clipboard
Copied
There is a setting under the datasource(s) in the ColdFusion admin to log database activity. It might depend on the drivers being used.
Copy link to clipboard
Copied
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
Copy link to clipboard
Copied
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.
Copy link to clipboard
Copied
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: FusionReactor - Copyright (C) Intergral GmbH. All Rights Reserved
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
Copy link to clipboard
Copied
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"
Copy link to clipboard
Copied
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.
Copy link to clipboard
Copied
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.
Copy link to clipboard
Copied
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.