1 2 Previous Next 16 Replies Latest reply on Jan 4, 2012 2:34 PM by asyomichev

    Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20

    edwinb1

      Greetings,

       

      During a mild load-test against a custom application I see scattered occurrences of the following HTTPD log entries:

       

       

      [error] ajp_cping_cpong: awaited CPONG, received 41 42 00 04 03

       

      [error] ajp_handle_cping_cpong: awaited CPONG, received 3

       

      [error] (20014)Internal error: proxy: AJP: cping/cpong failed to 169.70.169.127:54022 (169.70.169.127)

       

      [error] proxy: CLUSTER: (balancer://ABB-ApplicationRequestRouter). All workers are in error state

       

       

      My test client runs a request-loop with a 10sec delay between requests, yet these errors appear which sets the node status to 'NOTOK, returning 503'. A few inactive seconds later, the status reverts to 'OK'. I have yet to examine Tomcat logs to investigate, but what observations can be made from the CPONG errors listed above?

       

      It appears that ping-pong, initiated from HTTPD, produces undesirable results. Either a connection/response timeout or something on the application's side is the cause, I haven't ruled out anything yet.

       

       

      Many thanks,

      Edwin

        • 1. Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
          jfclere

          Thas is weird as if the application would go on sending data to the browser after a close.

          you should have at least 2 "AJP: cping/cpong failed" in the error_log file, could you post a longer part of the error_log file, please?

          • 2. Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
            edwinb1

            Apologies, I only provided a random sampling of log entries and the logs concur with your observation. Here's a more useful segment:

             

             

            [Sat Feb 12 18:11:32 2011] [error] ajp_handle_cping_cpong: awaited CPONG, received 3

            [Sat Feb 12 18:11:32 2011] [error] (20014)Internal error: proxy: AJP: cping/cpong failed to 169.70.169.127:54022 (169.70.169.127)

            [Sat Feb 12 18:11:55 2011] [error] ajp_cping_cpong: awaited CPONG, received 41 42 00 04 03

            [Sat Feb 12 18:12:04 2011] [error] ajp_cping_cpong: awaited CPONG, received 41 42 00 04 03

            [Sat Feb 12 18:12:04 2011] [error] proxy: CLUSTER: (balancer://ABB-ApplicationRequestRouter). All workers are in error state

            • 3. Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
              jfclere

              According to the code could have:

              [Mon Feb 14 17:42:55 2011] [error] ajp_handle_cping_cpong: awaited CPONG, received 3

              [Mon Feb 14 17:42:55 2011] [error] (20014)Internal error: proxy: AJP: cping/cpong failed to 127.0.0.1:8009 (localhost)

              twice.

              The version we bundle is 2.2.15 it seems you are using a different one, correct?

              • 4. Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                jfclere

                41 42 00 04 03 ... you are dumping the received messages, correct?

                In fact it is 3 bytes longer could you dump that 3 bytes too?

                What is the application you are testing doing? Does it use something special (like assync, AJAX etc)?

                • 5. Re: Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                  edwinb1

                  I've attached an application that can easily reproduce this symptom. I believe refreshing/resubmitting the page from the browser several times will induce it.

                  • 6. Re: Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                    jfclere

                    I am not able to reproduce the problem with latest TC amd mod_cluster. Please retry with those.

                    • 7. Re: Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                      edwinb1

                      These errors seem to appear only when APR is enabled on the Tomcat side. I have tried APR versions 1.3.9 and 1.4.5 and they both exhibit the same results for some applications. But when I disable APR by simply removing 'apr' and 'tcnative' from LD_LIBRARY_PATH, these errors disappear.

                       

                      Is there any guidance or known issues with 'mod_cluster' on APR-enabled Tomcat?

                      • 8. Re: Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                        jfclere

                        There aren't known issues for the such configuration.

                        Please retry with latest TC and mod_cluster/httpd versions.

                        • 9. Re: Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                          edwinb1

                          While 'mod_cluster' remains at version 1.1.0Final, I've upgraded Tomcat to 6.0.32, apr to 1.4.5 and tcnative to 1.1.22 and still see messages like the following in HTTPD error_log:

                           

                          [Thu Aug 25 17:31:35 2011] [error] (20014)Internal error: proxy: AJP: cping/cpong failed to 169.70.169.11:43827 (169.70.169.11)

                           

                           

                          This error occurs from a SOAP call made by 'soapUI-4.0.0' client to this application. What content could the SOAP request/response payloads carry that can interfere with 'cping/cpong' protocol? Note, disabling apr/tcnative from Tomcat still seems to solve the problem.

                           

                          • 10. Re: Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                            edwinb1

                            After upgrading mod_cluster to 1.1.3, I now have the entire stack running at the latest versions and I continue to see this AJP error intermittently when APR is enabled. I decided to switch the Tomcat connector from AJP to HTTP and occasionally see this error:

                             

                            [Wed Sep 07 10:03:14 2011] [error] [client 10.30.130.188] (104)Connection reset by peer: proxy: error reading status line from remote server 169.70.169.12
                            [Wed Sep 07 10:03:14 2011] [error] [client 10.30.130.188] proxy: Error reading from remote server returned by /CDFAccountCore/GetAccountDetails

                             

                             

                            Perhaps this is more a native library problem rather than AJP/HTTP connector related. The server is runnin "Linux 2.6.18-214.el5 #1 SMP Fri Aug 27 17:45:34 EDT 2010 x86_64 x86_64 x86_64 GNU/Linux".

                             

                             

                            Thanks again for any guidance,

                            Edwin

                            • 11. Re: Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                              jfclere

                              It could that a request is taking too much time for the timout defined in the connector on the Tomcat side.

                              • 12. Re: Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                                asyomichev

                                I captured some AJP frames with Edwin's example application above and it looks like there is an extra SEND_BODY_CHUNK (hex: 41 42 00 04 03 00 00 00) message sent by Tomcat after END_RESPONSE. To the best of my understanding, this is not conformant with AJP1.3 spec, and mod_cluster_proxy is in its right to reject that.

                                 

                                The extra body chunk message seems to be related to "explicit flush" logic in org.apache.coyote.ajp.AjpAprProtocol, introduced here: http://svn.apache.org/viewvc/tomcat/tc6.0.x/trunk/java/org/apache/coyote/ajp/AjpAprProcessor.java?r1=468936&r2=468937&

                                 

                                Is this a bug in AjpAprProtocol, or mod_proxy_cluster has to be able to ignore these out-of-band flush messages?

                                 

                                Thanks,

                                --Alexey

                                • 13. Re: Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                                  jfclere

                                  Yes that is the problem... It needs to be fixed in mod_proxy_ajp that is usd in mod_cluster

                                  • 14. Re: Error messages from 1.1.0.Final HTTPD/Tomcat 6.0.20
                                    alexey.brodovshuk

                                    I've faced the same problem. Apache error log full of such messages:

                                     

                                    [Sun Jan 01 08:13:59 2012] [error] ajp_handle_cping_cpong: awaited CPONG, received 3

                                    [Sun Jan 01 08:13:59 2012] [error] (20014)Internal error: proxy: AJP: cping/cpong failed to 192.168.189.66:8009 (192.168.189.66)

                                    [Sun Jan 01 08:35:50 2012] [error] proxy: CLUSTER: (balancer://icecluster). All workers are in error state

                                    [Sun Jan 01 08:37:53 2012] [error] proxy: CLUSTER: (balancer://icecluster). All workers are in error state

                                    [Sun Jan 01 08:43:22 2012] [error] proxy: CLUSTER: (balancer://icecluster). All workers are in error state

                                    [Sun Jan 01 09:05:49 2012] [error] proxy: CLUSTER: (balancer://icecluster). All workers are in error state

                                    [Sun Jan 01 09:11:54 2012] [error] proxy: CLUSTER: (balancer://icecluster). All workers are in error state

                                    [Sun Jan 01 09:15:37 2012] [error] ajp_handle_cping_cpong: awaited CPONG, received 3

                                    [Sun Jan 01 09:15:37 2012] [error] (20014)Internal error: proxy: AJP: cping/cpong failed to 192.168.189.66:8009 (192.168.189.66)

                                    [Sun Jan 01 09:16:08 2012] [info] [client 192.168.189.69] (32)Broken pipe: core_output_filter: writing data to the network http://my-app/app

                                    [Sun Jan 01 09:16:08 2012] [error] proxy: dialog to 192.168.189.68:8009 (192.168.189.68) failed


                                    When mod_proxy_ajp is going to be fixed and how can I track this issue?

                                    Thanks.

                                    1 2 Previous Next