7 Replies Latest reply on Sep 16, 2014 9:41 PM by carl type3

    Coldfusion 10 Update 13 IIS7 503 Service Unavailable

    retfird

      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

        • 1. Re: Coldfusion 10 Update 13 IIS7 503 Service Unavailable
          carl type3 Level 4

          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.

          • 2. Re: Re: Coldfusion 10 Update 13 IIS7 503 Service Unavailable
            retfird Level 1

            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!

            • 3. Re: Re: Coldfusion 10 Update 13 IIS7 503 Service Unavailable
              carl type3 Level 4

              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:

               

              http://vimeo.com/67571552

               

              The connector date stamp seems correct.


              HTH again, Carl.

              • 4. Re: Coldfusion 10 Update 13 IIS7 503 Service Unavailable
                retfird Level 1

                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

                • 5. Re: Coldfusion 10 Update 13 IIS7 503 Service Unavailable
                  retfird Level 1

                  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

                   

                  threads.png

                  • 6. Re: Coldfusion 10 Update 13 IIS7 503 Service Unavailable
                    carl type3 Level 4

                    Capture.JPG

                    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.

                    • 7. Re: Coldfusion 10 Update 13 IIS7 503 Service Unavailable
                      carl type3 Level 4

                      Capture.JPG

                      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.