CF MX 6.1 Auto Restarting

Report · May 24, 2006

We have a CF MX 6.1 (Jrun 4) server on Windows 2000 with IIS 5 that appears to be restarting automaically. We are having trouble determining what is triggering these restarts. Below is an excerpt from the server.log file.

"Information","scheduler-0","05/24/06","08:08:28",,"Starting license..."
"Information","scheduler-0","05/24/06","08:08:28",,"Starting License server ..."
"Information","scheduler-0","05/24/06","08:08:29",,"Starting scheduler..."
"Information","scheduler-0","05/24/06","08:08:29",,"Starting debugging..."
"Information","scheduler-0","05/24/06","08:08:29",,"Starting sql..."
"Information","scheduler-0","05/24/06","08:08:30",,"Pool Manager Started"
"Information","scheduler-0","05/24/06","08:08:30",,"Starting mail..."
"Information","scheduler-0","05/24/06","08:08:31",,"CORBA Configuration not enabled"
"Information","scheduler-0","05/24/06","08:08:31",,"Starting cron..."
"Information","scheduler-0","05/24/06","08:08:31",,"Starting registry..."
"Information","scheduler-0","05/24/06","08:08:31",,"Starting client..."
"Information","scheduler-0","05/24/06","08:08:31",,"Starting xmlrpc..."
"Information","scheduler-0","05/24/06","08:08:32",,"Starting graphing..."
"Information","scheduler-0","05/24/06","08:08:32",,"Starting verity..."
"Information","scheduler-0","05/24/06","08:08:34",,"Starting archive..."
"Information","scheduler-0","05/24/06","08:08:34",,"ColdFusion started"

The curious thing is that the log indicates "scheduler-0", but we have not found anything that is scheduled (However most of our restart do occur in the morning over a 2 hour time span.) We can not find anything in the logs indicating that any exceptions or other errors are occuring at the same time as these resarts. Has anyone come across anything like this before?

Report · May 24, 2006

Have you checked the server event logs to see if there is anything there?

-Randy

Report · May 24, 2006

Yes I have. Nothing there.

Report · May 25, 2006

I've been having the same problems with CFMX 7.01 on IIS6, except it's from "main". At times it reboots like every 10 minutes. Other times a couple hours. Haven't found any reason for it yet.

"Information","main","05/25/06","14:18:30",,"Starting verity..."
"Information","main","05/25/06","14:18:30",,"Starting archive..."
"Information","main","05/25/06","14:18:30",,"Starting document..."
"Information","main","05/25/06","14:18:31",,"Starting eventgateway..."
"Information","main","05/25/06","14:18:32",,"ColdFusion started"

Report · May 25, 2006

I found a coldfusion-out.log file which seems to have a little more info. It shows an error of not being able to open the license.properties file. I checked the folder it's looking in and there is no license.properties file there. The service proceeds to reboot. This happens many times a day. Anyone know what this is?

Starting Macromedia JRun 4.0 (Build 92909), coldfusion server
05/25 12:25:16 warning Unable to open D:\CFusionMX7\runtime/lib/license.properties
05/25 12:25:18 info JRun Naming Service listening on *:2920
05/25 12:25:18 warning No sessionSecret has been specified in jrun.xml. Installing a self generated sessionSecret.
05/25 12:25:19 info No JDBC data sources have been configured for this server (see jrun-resources.xml)
05/25 12:25:19 info JRun Proxy Server listening on *:51011
05/25 12:25:19 info Deploying enterprise application "Macromedia ColdFusion MX" from: file:/D:/CFusionMX7/
05/25 12:25:20 info Deploying web application "Macromedia Coldfusion MX" from: file:/D:/CFusionMX7/
05/25 12:25:22 INFO License Service: Flex 1.5 CF Edition enabled
05/25 12:25:22 INFO Starting Flex 1.5 CF Edition
05/25 12:25:23 user JSPServlet: init
05/25 12:25:23 user CFMxmlServlet: init
05/25 12:25:23 user CFMxmlServlet: Macromedia Flex Build: 87315.134646
05/25 12:25:23 INFO Macromedia Flex Build: 87315.134646
05/25 12:25:26 user ColdFusionStartUpServlet: init
05/25 12:25:26 user ColdFusionStartUpServlet: ColdFusion MX: Starting application services
05/25 12:25:26 user ColdFusionStartUpServlet: ColdFusion MX: VM version = 1.4.2_05-b04
05/25 12:25:26 Information [main] - Starting logging...
05/25 12:25:26 Information [main] - Starting crypto...
05/25 12:25:28 Information [main] - Starting license...
05/25 12:25:28 Information [main] - Starting License server ...
05/25 12:25:28 Information [main] - Starting scheduler...
05/25 12:25:28 Information [main] - Starting WatchService...
05/25 12:25:28 Information [main] - Starting debugging...
05/25 12:25:28 Information [main] - Starting sql...
05/25 12:25:34 Information [main] - Pool Manager Started
05/25 12:25:34 Information [main] - Starting mail...
05/25 12:25:35 Information [main] - CORBA Configuration not enabled
05/25 12:25:35 Information [main] - Starting cron...
05/25 12:25:35 Information [main] - Starting registry...
05/25 12:25:35 Information [main] - Starting client...
05/25 12:25:35 Information [main] - Starting xmlrpc...
05/25 12:25:36 Information [main] - Starting graphing...
05/25 12:25:36 Information [main] - Starting verity...
05/25 12:25:36 Information [main] - Starting archive...
05/25 12:25:36 Information [main] - Starting document...
05/25 12:25:38 Information [main] - Starting eventgateway...
05/25 12:25:39 Information [main] - Starting Event Backend Handlers
05/25 12:25:39 Information [main] - Initialized EventRequestDispatcher with a Thread Pool size of 10
05/25 12:25:39 Information [main] - Initializing EventRequestHandler
05/25 12:25:39 Information [main] - Starting Event Gateways
05/25 12:25:39 Information [main] - ColdFusion started
05/25 12:25:39 user ColdFusionStartUpServlet: ColdFusion MX: application services are now available
05/25 12:25:39 user CFSwfServlet: init
05/25 12:25:39 user CFCServlet: init
05/25 12:25:40 user FlashGateway: init
05/25 12:25:40 user CFFormGateway: init
05/25 12:25:40 user CFInternalServlet: init
Server coldfusion ready (startup time: 27 seconds)

Report · May 26, 2006

Well I'll chime in also. Same issue, absolutely nothing logged anywhere in CF or JRUN. Just the simple fact of CF starting without having stopped. Been happening for about 3 weeks. My tech ^%^@#$'ers still won't let me look at "their" server, so I have no clue via Event Viewer if it's crashing and restarting per Service settings, or simply restarting itself on it's own. Users get the standard unavailable or busy restarting message. It only happens in the "wee" hours after our 2:00 am CF Recycle (btw, think we should recycle IIS also? We never have. Should we stop recycling now that MX7? We continued this from our CF4.5 days where it was most definitely needed). Has anyone tried the JRUN metrics trick. I haven't bothered yet. This is an Intranet with "nobody" on when it first occurs so it's not volume related and I hesitate to add runtime overhead. I'm thinking it MUST be Session/Cookie/Application/CFLOGIN timeout/corruption related. The really bizarre thing is that it goes away by itself and never recurs until after the next recycle.

Also how about the timing? Our first occurence was April 28th. Anyone else same time frame?. Might it be from a Microsoft Patch? This would explain same symptoms/different CF versions. Our Specs:

Server Details
Server Product ColdFusion MX
Version 7,0,1,116466
Edition Standard
Serial Number xxxx-xxxx-xxxx-xxxx-xxx
Operating System Windows 2003
OS Version 5.2

JVM Details
Java Version 1.4.2_05
Java Vendor Sun Microsystems Inc.
Java Vendor URL http://java.sun.com/
Java Home D:\CFusionMX7\runtime\jre
Java File Encoding Cp1252

Report · May 26, 2006

A little more info for potential commonality of symptoms.
Our intranet runs both public pages and "protected", <CFNTAuthenticate> pages. Public pages continue to run fine during the period. Protected pages cause the restart as soon as the Password is entered when the CFNTAuthenticate command will occur. However, naturally, it's inside a <cflogin> so I'm not sure if NTAuth is causing the restart or perhaps a corrupt/timed out CFAPPLICATION due to the intervening recycle. We have loginstorage=cookie, session timeout 20 minutes, application timeout 1 day, and cflogin idletimeout 2 hours. I'm going to bump session to 2 hours to match idle. Seems like it should anyway, although it's probably not the issue.

Report · May 26, 2006

In looking through more logs, I have found something that may be a coincidence, but I'll mention it anyway. For one of our Jrun instances, we had no restarts (manual, scheduled, etc) for about 2 months. Then, on 8/25/2005 we install security patch MS05-039 from Microsoft. That morning, the pattern or restarts seems to start up averaging bewteen 1 and 2 restarts per day (with sometimes days or weeks between restarts)

Like I said, it may be a coincidence, but is probably worth mentioning.

Report · Jun 16, 2006

Bump. Anybody find anything? We were fine for almost two weeks and then got hammered again last night. This time I had the Jrun Metrics turned on. Total Memory immediately after the 2:00 recycle seemed lighter than normal, 14000's vs the 17000's on "good nights". Problem seemed to end when one of our scheduled jobs (<cflogin bypassed) ran and kicked it up to 21000. Ran across some good old messages (seemingly too generic) in the \CFusionMX7\runtime\lib\wsconfig\1\LogFiles area, pasted at bottom.

One other thought. This is a "virtual" server. Has anyone ran across problems running on a virtual server?

I have no clue what's really physically going on on the box. Could it be that something's happening and CF/JRUN can't get the memory they truly need to run (or perform the <cflogin command) but a straight HTML crunching page can demand the memory so it'll be ready for the next true user?

Logs (in fact the ONLY things seen anywhere in the system, other than out-of-the-blu starting up log entries):

2006-06-16 02:01:52 jrISAPI[4592:420] command error: Connection reset by peer <- [624]
2006-06-16 02:01:52 jrISAPI[4592:420] returning error page for Connection reset by peer
2006-06-16 02:01:52 jrISAPI[8736:420] command error: Connection reset by peer <- [616]
2006-06-16 02:01:52 jrISAPI[8736:420] returning error page for Connection reset by peer
2006-06-16 02:02:09 jrISAPI[6784:420] 127.0.0.1:51011 connect failed: 10060 Connection timed out
2006-06-16 02:02:09 jrISAPI[6784:420] returning error page for Connection timed out
2006-06-16 02:02:12 jrISAPI[4832:420] 127.0.0.1:51011 connect failed: 10060 Connection timed out
2006-06-16 02:02:12 jrISAPI[4832:420] returning error page for Connection timed out
2006-06-16 02:02:21 jrISAPI[ 928:420] command error: Connection reset by peer <- [604]
2006-06-16 02:02:21 jrISAPI[ 928:420] returning error page for Connection reset by peer
2006-06-16 02:03:43 jrISAPI[8976:420] command error: Connection reset by peer <- [604]
2006-06-16 02:03:43 jrISAPI[8976:420] returning error page for Connection reset by peer
2006-06-16 02:06:06 jrISAPI[7024:420] command error: Connection reset by peer <- [604]
2006-06-16 02:06:06 jrISAPI[7024:420] returning error page for Connection reset by peer
2006-06-16 02:11:54 jrISAPI[2880:420] command error: Connection reset by peer <- [588]
2006-06-16 02:11:54 jrISAPI[2880:420] returning error page for Connection reset by peer
2006-06-16 02:16:31 jrISAPI[5072:420] command error: Connection reset by peer <- [588]
2006-06-16 02:16:31 jrISAPI[5072:420] returning error page for Connection reset by peer
2006-06-16 02:16:51 jrISAPI[3120:420] 127.0.0.1:51011 connect failed: 10060 Connection timed out
2006-06-16 02:16:51 jrISAPI[3120:420] returning error page for Connection timed out

Report · Jun 16, 2006

Here is some tidbits that I found helped us out when we had unstability on our server.

1. MySQL INNODB database type is a memory HOG. I changed all our innodb tables over to MyISAM and that helped.

2. Create a separate Application pool in IIS for trouble domains

3. I bought a couple IIS Administration books that showed how to setup the application pools.

4. we also edited the jrun memory variables in administrator to allow more memory being allocated at startup for CF

5. We fixed a couple queries that had bugs in them that if somebody hit next page 10 times the query was so big that mysql and CF would start going hog wild until I restarted mysql or killed the process

I

Report · Jun 16, 2006

Randy,
Thanks for taking the time. Only 2, 3, and 4 would be applicable to our tiny Intranet with Access, SQL Server and Oracle. Our JVM heaps are sitting at the defaults, blank and 128. Highest observed metric so far was 80000. Will probably try 128 and 128 (some cf lit says make em the same) on Monday (we don't do changes on fridays <gr>). The pool stuff I'm somewhat aware of but wouldn't be allowed to touch. That's for the tech Gods. I ran across some allusions to IIS 6.0, via Pool settings, being able to instruct an application to restart itself. If this were happening would it be in an IIS log somewhere? I was able to talk them into mailing me a copy of the http.sys log which was empty (really surprising since the basic IIS Log that I can look at has a 503 on each and every crash instigating page request and I expected to see further diagnostics there)

Report · Jun 16, 2006

If you are using access database make sure this is not checked in your dsn connections:

Maintain Connections -- Maintain connections across client requests.

You do not want access databases maintaining connections.

How many access databases are you using?

-Randy

PS here is a 503 error:

10.5.4 503 Service Unavailable

The server is currently unable to handle the request due to a temporary overloading or maintenance of the server. The implication is that this is a temporary condition which will be alleviated after some delay. If known, the length of the delay MAY be indicated in a Retry-After header. If no Retry-After is given, the client SHOULD handle the response as it would for a 500 response.

Note: The existence of the 503 status code does not imply that a
server must use it when becoming overloaded. Some servers may wish
to simply refuse the connection.

Report · Jun 19, 2006

Perhaps a dozen Access DB's, none with Maintain. In fact at point of failure in latest incident, no Access at all. The instigating page was using Oracle. We've seen all DB flavors of instigators. We've also seen them with and without CFLOGIN and NTAUTHENTICATE, my original suspicions.

Incidents are always shortly after a nightly recycle at 2:00 of everything except IIS. They (so far, knock on wood) have always magically straightened themselves out, sometimes within 20 minutes, sometimes 3 hours. Nobody's here doing much on this teeny Intranet site at that time of night so we might get 3 or 6 or 12 restarts before it stops. People used to call in a ticket when it first started, back in late April. Now, as seen in the IIS logs, they pretty much ignore it and simply try every once in awhile until it's back up.

Except for those "reset by peers" in wsconfig logs, which seem to be from IIS rather than CF, we have never seen a CF error logged anywhere nor any Event Viewer errors.

Your sample 503 error, was that out of http.sys error log or on the Browser? Our http is empty except for scattered "Timer_ConnectionIdle" and "1 Connection_Dropped DefaultAppPool", a dozen per day or less, especially of the latter. Did our techy or CF Install blow the http.sys error log setup?

I misread our Heap setting, it was actually blank and 512 not 128. I plan to try 32 and 512 tonight even though CF literature suggests making them the same. I have no clue what the "physical" might actually be for the "virtual" server and hesitate to mess with the max that CF presumably calculated at install. At least it'll be guaranteed to have a lot more that it ever did before at startup. What do you think?

Report · Jun 19, 2006

I had a similar problem, it was partially because I had my client storage set to registry instead of datasource. My cf.registry was getting too big for my server to read it efficiently. So created a datasource and set client storage to datasource. Also, had to put command "-server -Xint " in my JVM Arguments settings on CF Admin.

Report · Jun 19, 2006

Thanks for contributing JT. We don't use Client Storage at all. I've run across the -Xint principle in my searches but have so far hesitated to interfere with the bowels of the Java machine in production. It doesn't seem to have hurt anything on my lap top so I'm inclined. I plan to try the 32MB tonight, and the -Xint if it happens again. Were you still getting unlogged mystery restarts prior to the -Xint change?

Report · Jun 20, 2006

After I changed the cf.registry the server was stable for maybe 24 hours, then about every 12 hours after that it would restart or completely die. Haven't had the problem since putting in the -Xint flag. Without the option we were bounding out of memory.

Report · Jun 23, 2006

Update for followers. Turned on a 32MB minimum heap last Monday, no issues. However, also no help. Got hit again 7 more times this morning. Will be trying the -Xint next Monday.

Report · Sep 27, 2006

We are having the same issue as described in this thread, are to the point of moving everything we can from CF. There does not seem to have been a resolution in the thread above. Do we need to open a paid incident to get some attention to this?