Copy link to clipboard
Copied
Coldfusion 10 Update 13
Windows Server Datacenter 2008 SP2
IIS7
We're having periodic issues where our Coldfusion service seems to recycle or restart, and the user will receive a 503 Error Code back from IIS.
At the time of the error, our coldfusion-out.log shows the service starting:
Sep 9, 2014 12:46:55 PM Information [pool-2-thread-1] - Starting logging...
Sep 9, 2014 12:46:55 PM Information [pool-2-thread-1] - Starting license...
Sep 9, 2014 12:46:57 PM Information [pool-2-thread-1] - Standard Edition enabled
Sep 9, 2014 12:46:57 PM Information [pool-2-thread-1] - Starting crypto...
Sep 9, 2014 12:46:57 PM Information [pool-2-thread-1] - Starting security...
Sep 9, 2014 12:46:59 PM Information [pool-2-thread-1] - Starting scheduler...
Sep 9, 2014 12:46:59 PM Information [pool-2-thread-1] - Starting WatchService...
Sep 9, 2014 12:46:59 PM Information [pool-2-thread-1] - Starting debugging...
Sep 9, 2014 12:46:59 PM Information [pool-2-thread-1] - Starting sql...
Sep 9, 2014 12:47:00 PM Information [pool-2-thread-1] - Pool Manager Started
Sep 9, 2014 12:47:00 PM Information [pool-2-thread-1] - Starting mail...
Sep 9, 2014 12:47:00 PM Information [pool-2-thread-1] - Starting runtime...
Sep 9, 2014 12:47:01 PM Information [pool-2-thread-1] - CORBA Configuration not enabled
Sep 9, 2014 12:47:01 PM Information [pool-2-thread-1] - Starting cron...
Sep 9, 2014 12:47:02 PM Information [pool-2-thread-1] - Starting registry...
Sep 9, 2014 12:47:02 PM Information [pool-2-thread-1] - Starting client...
Sep 9, 2014 12:47:02 PM Information [pool-2-thread-1] - Starting xmlrpc...
Sep 9, 2014 12:47:02 PM Information [pool-2-thread-1] - Starting jaxrs...
Sep 9, 2014 12:47:02 PM Information [pool-2-thread-1] - Starting graphing...
Sep 9, 2014 12:47:02 PM Information [pool-2-thread-1] - Starting solr...
Sep 9, 2014 12:47:02 PM Information [pool-2-thread-1] - Starting archive...
Sep 9, 2014 12:47:02 PM Information [pool-2-thread-1] - Starting document...
Sep 9, 2014 12:47:02 PM Information [pool-2-thread-1] - Starting eventgateway...
Sep 9, 2014 12:47:03 PM Information [pool-2-thread-1] - Event Gateway Disabled.
Sep 9, 2014 12:47:03 PM Information [pool-2-thread-1] - Starting FlexAssembler...
Sep 9, 2014 12:47:03 PM Information [pool-2-thread-1] - Starting .NET...
Sep 9, 2014 12:47:04 PM Information [pool-2-thread-1] - Starting Monitoring...
Sep 9, 2014 12:47:04 PM Information [pool-2-thread-1] - Starting WebSocket...
Sep 9, 2014 12:47:04 PM Information [pool-2-thread-1] - WebSocket server listens on port: 8575
Sep 9, 2014 12:47:04 PM Information [pool-2-thread-1] - ColdFusion started
Sep 9, 2014 12:47:04 PM Information [pool-2-thread-1] - ColdFusion: application services are now available
The IIS access log shows the page request followed by the 503 status code.
2014-09-09 16:46:48 10.185.130.118 POST /cart 8086 - 10.238.196.27 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+Trident/7.0;+rv
:11.0)+like+Gecko 503 0 0 2199
In the Windows Event Logs, we see the following
12:46:44PM The WinHTTP Web Proxy Auto-Discovery Service service entered the running state.
12:47:16PM The ColdFusion 10 Application Server service entered the running state.
This issue is occuring multiple times per day
From isapi_redirect.log appears tomcat at the CF10 end is failing.
Perhaps applying some of the CF tomcat tuning mentioned in this blog will help. The blog is titled CF11 however details are pertinent to CF10:
http://blogs.coldfusion.com/post.cfm/coldfusion-11-iis-connector-tuning
I discuss and demonstrate some of the CF tomcat settings here:
The connector date stamp seems correct.
HTH again, Carl.
Copy link to clipboard
Copied
Prior to CF starting any errors in coldfusion-out.log?
Any errors warnings in coldfusion-error.log at that time?
Any errors warnings in ColdFusion10\config\wsconfig\N\isapi_redirect.log ?
Where N = some number probably 1.
CF10 update 13. So likely manual step to update isapi_redirect.dll has been done however to check what is the date stamp of isapi_redirect.dll ?
HTH, Carl.
Copy link to clipboard
Copied
There are no errors in the coldfusion-out.log prior to the startup:
Sep 9, 2014 12:38:28 PM Information [scheduler-0] - Run Client Storage Purge
09/09 12:46:55 INFO License Service: Flex 1.5 CF Edition enabled
09/09 12:46:55 INFO Starting Flex 1.5 CF Edition
Sep 9, 2014 12:46:55 PM Information [pool-2-thread-1] - Starting logging...
...
These messages from coldfusion-error.log may be related, but there is no timestamp available in the log:
Sep 08, 2014 9:39:56 AM org.apache.catalina.core.ApplicationContext log
INFO: CFMxmlServlet: Macromedia Flex Build: 87315.134646
Sep 08, 2014 9:40:04 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8012"]
Sep 08, 2014 9:40:04 AM com.adobe.coldfusion.launcher.Launcher run
INFO: Server startup in 30945 ms
java.lang.NullPointerException
at coldfusion.server.jrun4.metrics.SimpleLoadMetric.run(SimpleLoadMetric.java:157)
at coldfusion.scheduling.ThreadPool.run(ThreadPool.java:211)
at coldfusion.scheduling.WorkerThread.run(WorkerThread.java:71)
...ABOVE LINE REPEATED...
Sep 09, 2014 1:32:57 PM org.apache.catalina.core.AprLifecycleListener init
isapi_redirect.log:
[Tue Sep 09 11:35:39.400 2014] [3968:2000] [info] ajp_send_request::jk_ajp_common.c (1658): (cfusion) all endpoints are disconnected, detected by connect check (3), cping (0), send (0)
[Tue Sep 09 12:46:46.059 2014] [3968:2832] [info] ajp_send_request::jk_ajp_common.c (1658): (cfusion) all endpoints are disconnected, detected by connect check (3), cping (0), send (0)
[Tue Sep 09 12:46:47.057 2014] [3968:2832] [info] jk_open_socket::jk_connect.c (626): connect to 127.0.0.1:8012 failed (errno=61)
[Tue Sep 09 12:46:47.057 2014] [3968:2832] [info] ajp_connect_to_endpoint::jk_ajp_common.c (1047): Failed opening socket to (127.0.0.1:8012) (errno=61)
[Tue Sep 09 12:46:47.057 2014] [3968:2832] [error] ajp_send_request::jk_ajp_common.c (1669): (cfusion) connecting to backend failed. Tomcat is probably not started or is listening on the wrong port (errno=61)
[Tue Sep 09 12:46:47.057 2014] [3968:2832] [info] ajp_service::jk_ajp_common.c (2692): (cfusion) sending request to tomcat failed (recoverable), because of error during request sending (attempt=1)
[Tue Sep 09 12:46:48.181 2014] [3968:2832] [info] jk_open_socket::jk_connect.c (626): connect to 127.0.0.1:8012 failed (errno=61)
[Tue Sep 09 12:46:48.212 2014] [3968:2832] [info] ajp_connect_to_endpoint::jk_ajp_common.c (1047): Failed opening socket to (127.0.0.1:8012) (errno=61)
[Tue Sep 09 12:46:48.227 2014] [3968:2832] [error] ajp_send_request::jk_ajp_common.c (1669): (cfusion) connecting to backend failed. Tomcat is probably not started or is listening on the wrong port (errno=61)
[Tue Sep 09 12:46:48.227 2014] [3968:2832] [info] ajp_service::jk_ajp_common.c (2692): (cfusion) sending request to tomcat failed (recoverable), because of error during request sending (attempt=2)
[Tue Sep 09 12:46:48.227 2014] [3968:2832] [error] ajp_service::jk_ajp_common.c (2711): (cfusion) connecting to tomcat failed.
[Tue Sep 09 12:46:48.227 2014] [3968:2832] [error] HttpExtensionProc::jk_isapi_plugin.c (2309): service() failed with http error 503
We ran the wsconfig.exe and reconfigured the connectors after the latest update was applied.
Timestamp of isapi_redirect.dll is 11/2/2013 2:12 PM
Thank you very much!
Copy link to clipboard
Copied
From isapi_redirect.log appears tomcat at the CF10 end is failing.
Perhaps applying some of the CF tomcat tuning mentioned in this blog will help. The blog is titled CF11 however details are pertinent to CF10:
http://blogs.coldfusion.com/post.cfm/coldfusion-11-iis-connector-tuning
I discuss and demonstrate some of the CF tomcat settings here:
The connector date stamp seems correct.
HTH again, Carl.
Copy link to clipboard
Copied
Hi Carl,
I've applied the settings in that article recommended for my server configuration. According to the isapi_redirect.log, everything is much more stable, however we are still seeing a few of these 503 errors.
I've also gone through your video, and have a better understanding of what is happening.
I'll continue monitoring for a few days and report back.
Regards,
Tom
Copy link to clipboard
Copied
Hi Carl,
Do the thread count settings have any bearing on Coldfusion standard edition? I notice that even under load, the server only seems to spawn 10 ajp-bio-8012-exec threads. Does the 10 CFThread limit on coldfusion standard edition also affect this thread count?
Thanks in advance,
Tom
Copy link to clipboard
Copied
Hi Tom,
Tomcat by default configures to run with 10 threads available. In server.xml that is defined as minSpareThreads, in workers.properties as connection_pool_minsize. While Official CF blog post does not give it a mention I do in my talk and I think the default setting of 10 is not adequate for production systems.
To configure a value greater than 10 then server.xml needs in connector AJP section:
minSpareThreads="N" where N=<10 EG 100
works.properties needs:
worker.cfusion.connection_pool_minsize=N where N=<10 EG 100
Above is Jvisualvm thread monitoring diagram, I can’t picture them all but 100 spare threads. You will notice AJP is using APR rather than BIO. I ran a "bad app" so I could get some more activity.
I note the slide deck mentioned in video is still present to download.
HTH again, Carl.
Copy link to clipboard
Copied
PS
showing 100 threads using JMC - Java Mission Control.
CF system has 100 tomcat threads allocated. If it didn't every time the load would go beyond 10 threads it would bottleneck, slow down or worse still crash.