Skip navigation
azimuthinternet
Currently Being Moderated

Daily Crash/AutoRestart: Troubleshooting (CF9 on Ubuntu 11 on EC2 M1.Small)

Apr 13, 2012 2:05 AM

Tags: #server #coldfusion #coldfusion9 #cf9 #coldfusion_9

Hello,

 

I have CF9 running on an Amazon M1.Small EC2 instance. The OS is Ubuntu 11. The instance has 1.7 GB memory and a single Xeon CPU.

 

Here is a tail of my /opt/coldfusion9/logs/cfserver.log (I've included the first 11 lines just to show that it appears nothing unusual was going on):

 

04/12 01:12:39 Information [jrpp-1079] - Starting HTTP request {URL='http://blog.[domain].com:80/mostrecent.php', method='post'}

04/12 01:12:39 Information [jrpp-1111] - HTTP request completed  {Status Code=200 ,Time taken=11894 ms}

04/12 01:12:39 Information [jrpp-1187] - HTTP request completed  {Status Code=200 ,Time taken=17524 ms}

04/12 01:12:39 Information [jrpp-1134] - HTTP request completed  {Status Code=200 ,Time taken=11768 ms}

04/12 01:12:39 Information [jrpp-1134] - Starting HTTP request {URL='http://blog.[domain].com:80/mostrecent.php', method='post'}

04/12 01:12:39 Information [jrpp-1155] - HTTP request completed  {Status Code=200 ,Time taken=12109 ms}

04/12 01:12:39 Information [jrpp-1155] - Starting HTTP request {URL='http://blog.[domain].com:80/mostrecent.php', method='post'}

04/12 01:12:39 Information [jrpp-1154] - HTTP request completed  {Status Code=200 ,Time taken=12181 ms}

04/12 01:12:41 Information [jrpp-1199] - HTTP request completed  {Status Code=200 ,Time taken=13582 ms}

04/12 01:12:42 Information [jrpp-1206] - HTTP request completed  {Status Code=200 ,Time taken=14211 ms}

04/12 01:12:42 Information [jrpp-1122] - HTTP request completed  {Status Code=200 ,Time taken=14669 ms}

 

And then, out of the blue I get a WebSitePulse alert and tail my log and it says it's restarting. Well, that's nice...hmmm.


autorestart: Restarting process

Starting Macromedia JRun 4.0 (Build 108858), coldfusion server

04/12 01:16:13 warning Unable to open /opt/coldfusion9/runtime/lib/license.properties

04/12 01:19:24 info JRun Naming Service listening on *:2932

04/12 01:22:35 error Connection refused to host: [external_ip]; nested exception is:

    java.net.ConnectException: Connection timed out

[1]java.net.ConnectException: Connection timed out

    at java.net.PlainSocketImpl.socketConnect(Native Method)

    at java.net.PlainSocketImpl.doConnect(Unknown Source)

    at java.net.PlainSocketImpl.connectToAddress(Unknown Source)

    at java.net.PlainSocketImpl.connect(Unknown Source)

    at java.net.SocksSocketImpl.connect(Unknown Source)

    at java.net.Socket.connect(Unknown Source)

    at java.net.Socket.connect(Unknown Source)

    at java.net.Socket.<init>(Unknown Source)

    at java.net.Socket.<init>(Unknown Source)

    at sun.rmi.transport.proxy.RMIDirectSocketFactory.createSocket(Unknown Source)

    at sun.rmi.transport.proxy.RMIMasterSocketFactory.createSocket(Unknown Source)

    at sun.rmi.transport.tcp.TCPEndpoint.newSocket(Unknown Source)

    at sun.rmi.transport.tcp.TCPChannel.createConnection(Unknown Source)

    at sun.rmi.transport.tcp.TCPChannel.newConnection(Unknown Source)

    at sun.rmi.server.UnicastRef.invoke(Unknown Source)

    at jrun.servlet.session.SessionReplicationService_Stub.getRemoteServerNa me(Unknown Source)

    at jrun.servlet.session.SessionReplicationService.start(SessionReplicati onService.java:53)

    at jrun.servlet.ServletEngineService.createSessionReplicationService(Ser vletEngineService.java:130)

    at jrun.servlet.ServletEngineService.start(ServletEngineService.java:112 )

    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

    at java.lang.reflect.Method.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source)

    at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source)

    at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(Unknown Source)

    at com.sun.jmx.mbeanserver.PerInterface.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.MBeanSupport.invoke(Unknown Source)

    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(Unknown Source)

    at jrunx.kernel.ServiceAdapter.invokeMethod(ServiceAdapter.java:705)

    at jrunx.kernel.JRunServiceDeployer.invokeOnServices(JRunServiceDeployer .java:460)

    at jrunx.kernel.JRunServiceDeployer.startServices(JRunServiceDeployer.ja va:312)

    at jrunx.kernel.JRunServiceDeployer.startLifecycle(JRunServiceDeployer.j ava:260)

    at jrunx.kernel.JRunServiceDeployer.deployServices(JRunServiceDeployer.j ava:87)

    at jrunx.kernel.DeploymentService.loadServices(DeploymentService.java:46 )

    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

    at java.lang.reflect.Method.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source)

    at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source)

    at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(Unknown Source)

    at com.sun.jmx.mbeanserver.PerInterface.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.MBeanSupport.invoke(Unknown Source)

    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(Unknown Source)

    at jrunx.kernel.JRun.startServer(JRun.java:575)

    at jrunx.kernel.JRun.<init>(JRun.java:493)

    at jrunx.kernel.JRun$1.run(JRun.java:346)

    at java.security.AccessController.doPrivileged(Native Method)

    at jrunx.kernel.JRun.start(JRun.java:343)

    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

    at java.lang.reflect.Method.invoke(Unknown Source)

    at jrunx.kernel.JRun.invoke(JRun.java:180)

    at jrunx.kernel.JRun.main(JRun.java:168)

[0]java.rmi.ConnectException: Connection refused to host: [external_ip]; nested exception is:

    java.net.ConnectException: Connection timed out

    at sun.rmi.transport.tcp.TCPEndpoint.newSocket(Unknown Source)

    at sun.rmi.transport.tcp.TCPChannel.createConnection(Unknown Source)

    at sun.rmi.transport.tcp.TCPChannel.newConnection(Unknown Source)

    at sun.rmi.server.UnicastRef.invoke(Unknown Source)

    at jrun.servlet.session.SessionReplicationService_Stub.getRemoteServerNa me(Unknown Source)

    at jrun.servlet.session.SessionReplicationService.start(SessionReplicati onService.java:53)

    at jrun.servlet.ServletEngineService.createSessionReplicationService(Ser vletEngineService.java:130)

    at jrun.servlet.ServletEngineService.start(ServletEngineService.java:112 )

    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

    at java.lang.reflect.Method.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source)

    at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source)

    at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(Unknown Source)

    at com.sun.jmx.mbeanserver.PerInterface.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.MBeanSupport.invoke(Unknown Source)

    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(Unknown Source)

    at jrunx.kernel.ServiceAdapter.invokeMethod(ServiceAdapter.java:705)

    at jrunx.kernel.JRunServiceDeployer.invokeOnServices(JRunServiceDeployer .java:460)

    at jrunx.kernel.JRunServiceDeployer.startServices(JRunServiceDeployer.ja va:312)

    at jrunx.kernel.JRunServiceDeployer.startLifecycle(JRunServiceDeployer.j ava:260)

    at jrunx.kernel.JRunServiceDeployer.deployServices(JRunServiceDeployer.j ava:87)

    at jrunx.kernel.DeploymentService.loadServices(DeploymentService.java:46 )

    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

    at java.lang.reflect.Method.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source)

    at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(Unknown Source)

    at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(Unknown Source)

    at com.sun.jmx.mbeanserver.PerInterface.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.MBeanSupport.invoke(Unknown Source)

    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(Unknown Source)

    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(Unknown Source)

    at jrunx.kernel.JRun.startServer(JRun.java:575)

    at jrunx.kernel.JRun.<init>(JRun.java:493)

    at jrunx.kernel.JRun$1.run(JRun.java:346)

    at java.security.AccessController.doPrivileged(Native Method)

    at jrunx.kernel.JRun.start(JRun.java:343)

    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

    at java.lang.reflect.Method.invoke(Unknown Source)

    at jrunx.kernel.JRun.invoke(JRun.java:180)

    at jrunx.kernel.JRun.main(JRun.java:168)

Caused by: java.net.ConnectException: Connection timed out

    at java.net.PlainSocketImpl.socketConnect(Native Method)

    at java.net.PlainSocketImpl.doConnect(Unknown Source)

    at java.net.PlainSocketImpl.connectToAddress(Unknown Source)

    at java.net.PlainSocketImpl.connect(Unknown Source)

    at java.net.SocksSocketImpl.connect(Unknown Source)

    at java.net.Socket.connect(Unknown Source)

    at java.net.Socket.connect(Unknown Source)

    at java.net.Socket.<init>(Unknown Source)

    at java.net.Socket.<init>(Unknown Source)

    at sun.rmi.transport.proxy.RMIDirectSocketFactory.createSocket(Unknown Source)

    at sun.rmi.transport.proxy.RMIMasterSocketFactory.createSocket(Unknown Source)

    ... 47 more

 

04/12 01:22:36 info No JDBC data sources have been configured for this server (see jrun-resources.xml)

04/12 01:22:36 info JRun Proxy Server listening on *:51800

04/12 01:22:36 info Deploying enterprise application "Adobe_ColdFusion_9" from: file:/opt/coldfusion9/

04/12 01:22:37 info Deploying web application "Adobe ColdFusion 9" from: file:/opt/coldfusion9/

04/12 01:22:41 INFO License Service: Flex 1.5 CF Edition enabled

04/12 01:22:41 INFO Starting Flex 1.5 CF Edition

04/12 01:22:42 user JSPServlet: init

04/12 01:22:43 user ColdFusionStartUpServlet: init

04/12 01:22:43 user ColdFusionStartUpServlet: ColdFusion: Starting application services

04/12 01:22:43 user ColdFusionStartUpServlet: ColdFusion: VM version = 14.3-b01

04/12 01:22:44 Information [main] - Starting logging...

04/12 01:22:44 Information [main] - Starting license...

04/12 01:22:47 Information [main] - Standard Edition enabled

04/12 01:22:47 Information [main] - Starting crypto...

04/12 01:22:47 Information [main] - Starting security...

04/12 01:22:47 Information [main] - Starting scheduler...

04/12 01:22:48 Information [main] - Starting WatchService...

04/12 01:22:48 Information [main] - Starting debugging...

04/12 01:22:48 Information [main] - Starting sql...

04/12 01:22:48 Information [main] - Pool Manager Started

04/12 01:22:48 Information [main] - Starting mail...

04/12 01:22:48 Information [main] - Starting runtime...

04/12 01:22:48 Information [main] - CORBA Configuration not enabled

04/12 01:22:48 Information [main] - Starting cron...

04/12 01:22:49 Information [main] - Starting registry...

04/12 01:22:49 Information [main] - Starting client...

04/12 01:22:49 Information [main] - Starting xmlrpc...

04/12 01:22:49 Information [main] - Starting graphing...

04/12 01:22:49 Information [main] - Starting verity...

04/12 01:22:49 Information [main] - Starting solr...

04/12 01:22:49 Information [main] - Starting archive...

04/12 01:22:49 Information [main] - Starting document...

04/12 01:22:49 Information [main] - Starting eventgateway...

04/12 01:22:50 Information [main] - Starting Event Backend Handlers.

04/12 01:22:50 Information [main] - Initialized EventRequestDispatcher with a Thread Pool size of 1.

04/12 01:22:50 Information [main] - Initializing EventRequestHandler

04/12 01:22:50 Information [main] - Starting Event Gateways.

04/12 01:22:50 Information [main] - Starting FlexAssembler...

04/12 01:22:50 Information [main] - Starting .NET...

04/12 01:22:50 Information [main] - Starting Monitoring...

04/12 01:22:51 Information [main] - ColdFusion started

04/12 01:22:51 user ColdFusionStartUpServlet: ColdFusion: application services are now available

04/12 01:22:51 user CFMxmlServlet: init

04/12 01:22:51 user CFMxmlServlet: Macromedia Flex Build: 87315.134646

04/12 01:22:51 INFO Macromedia Flex Build: 87315.134646

04/12 01:22:56 user CFSwfServlet: init

04/12 01:22:56 user CFCServlet: init

04/12 01:22:56 error There is no web application configured to service your request

04/12 01:22:56 user NoWebappServlet: init

04/12 01:22:59 user FlashGateway: init

04/12 01:23:00 user MessageBrokerServlet: init

04/12 01:23:00 user CFFormGateway: init

04/12 01:23:01 user CFInternalServlet: init

04/12 01:23:01 user WSRPProducer: init

04/12 01:23:02 user ServerCFCServlet: init

Server coldfusion ready (startup time: 602 seconds)

 

602 Seconds? That's um... 10 minutes to startup, and since I'm monitoring the server at 15 minute intervals, it logs 15 minutes of estimated downtime for my client's displeasure.

 

In the meantime (prior to the restart having completed), the server's handing out Error 500's like this:

 

Server Error

The server encountered an internal error and was unable to complete your request.

Could not connect to JRun Server.

 

So, I check /opt/coldfusion9/bin/coldfusion status and it tells me:

 

Could not contact the ColdFusion Application Server running on this machine:

     Perhaps ColdFusion is not running on this machine?

     Perhaps cfstat is not enabled from the ColdFusion administrator?

     Perhaps ColdFusion was not restarted after enabling cfstat?

     Perhaps cfstat service is not listening on default port?

       Use option -port with port number as per the cfstatport

       defined in the neo-metrics xml file.

 

Erm. Funny that that status script could contact the CAS because when I ran `top`, I could see it using up CPU and RAM, and a `ps aux` revealed it was, in fact, running...maybe it was just still starting up and wasn't ready to "talk". I'm not sure.

 

Obviously, I'm curious as to what the cause was in the first place...cfserver.log just before the `autorestart` isn't telling me much, so I tail the application.log and the exception log but there's nothing in there with a timestamp right before this mysterious autorestart.

This is weird too: I can't actually seem to stop the CF server from running:

 

root@coffeereview:~# /opt/coldfusion9/bin/coldfusion status

 

Pg/Sec  DB/Sec  CP/Sec  Reqs  Reqs  Reqs  AvgQ   AvgReq AvgDB  Bytes  Bytes

Now Hi  Now Hi  Now Hi  Q'ed  Run'g TO'ed Time   Time   Time   In/Sec Out/Sec

0   0   0   0   -1  -1  0     0     0     0      -46102960      0      0    

root@coffeereview:~# /opt/coldfusion9/bin/coldfusion stop

Stopping ColdFusion 9, please wait

Stopping coldfusion server............................................................... ................................^C

 

Here, I get tired of waiting and hit Ctrl-C, but sometimes I'll wait and wait and it never does anything other than draw dots.

 

root@coffeereview:~# /opt/coldfusion9/bin/coldfusion status

 

Pg/Sec  DB/Sec  CP/Sec  Reqs  Reqs  Reqs  AvgQ   AvgReq AvgDB  Bytes  Bytes

Now Hi  Now Hi  Now Hi  Q'ed  Run'g TO'ed Time   Time   Time   In/Sec Out/Sec

0   0   0   0   -1  -1  0     0     0     0      -11525740      0      0

 

Still running. Obviously, I could hit the PID with a kill -9, but that seems a lottle rough, and not the ideal way to go about it. Last time I force quit it that way, I think it took even longer than 10 minutes to start back up when I ran `service coldfusion9 start`.

 

So, my goal here is to figure out these 3 things:

 

1. Why is my CF server is crashing and restarting?

2. Why does it take so long to restart? and

3. Why can I not stop the CF server by normal means?

 

Any help with answering these questions would be much appreciated.

 
Replies
  • Currently Being Moderated
    Apr 17, 2012 2:08 PM   in reply to azimuthinternet

    Hello,

     

    Have you changed your database drivers?   I noticed that there doesn't seem to be a very thorough testing of the database drivers in use by the non-windows ColdFusion installs.

     

    It seems that almost every contract job I go to where they are using ColdFusion on something other than Windows, we have had to play 'musical chairs' with the drivers in a attempt to find one that works well with a particular configuration of the operating system, Java, ColdFusion and the database connection.

     

    At one of my more recent jobs, Adobe has been working with the client for months in an attempt to find a driver that will work well for that flavor of Solaris and Oracle.

     

    We used FusionReactor to help us narrow down that the data connection was dieing between ColdFusion and the Oracle database and that the 'death' of the connection would end up casuing ColdFusion to lock up.

     

    I hope you have better luck than I did at that client.  It's been four months now and quite the number of different Oracle drivers.  I just heard this morning that they are going to give the Oracle thin client driver another go.

     

    Best regards,
    KR

     
    |
    Mark as:

More Like This

  • Retrieving data ...

Bookmarked By (0)

Answers + Points = Status

  • 10 points awarded for Correct Answers
  • 5 points awarded for Helpful Answers
  • 10,000+ points
  • 1,001-10,000 points
  • 501-1,000 points
  • 5-500 points