Uploaded image for project: 'JBoss Core Services'
  1. JBoss Core Services
  2. JBCS-72

Solaris 11: Apache HTTP Server SSLProxyEngine: [proxy_http:error] End of file found

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Critical
    • httpd 2.4.23 DR1
    • httpd 2.4.6 GA
    • httpd
    • None
    • Release Notes
    • DR1
    • Hide
      When using Apache Httpd on Solaris 11 as a reverse proxy with SSLProxyEngine enabled, a [proxy_http:error] End of file found: error is thrown.

      This issue is resolved in JBoss Core Services 2.4.23.
      Show
      When using Apache Httpd on Solaris 11 as a reverse proxy with SSLProxyEngine enabled, a [proxy_http:error] End of file found: error is thrown. This issue is resolved in JBoss Core Services 2.4.23.

    Description

      During the EAP 7 x JBCS certification, I hit a problem with Solaris 11 that seems rather cryptic to me.
      I'll enable the same test for JWS and try it out with Tomcat. Take a look, please:

      TL;DR

      • client ← HTTPS → mod_proxy_http (driven by mod_cluster) ← HTTPS → worker
      • worker → balancer HTTPS MCMP communication goes well
      • client → balancer → worker ends up with HTTP 502 Proxy Error
      • just after the handshake: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits), there appears: AH01991: SSL input filter read failed. in httpd's log
      • EAP 7 spits out at the time: 
        SEND TLSv1.2 ALERT:  fatal, description = internal_error
WRITE: TLSv1.2 Alert, length = 26
called closeInbound()
fatal: engine already closed.  Rethrowing javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
      • there is a catch though: Even the good run on Solaris 10 throws a similar note on EAP side during httpd's http_cping_cpong: 
        fatal error: 80: Inbound closed before receiving peer's close_notify: possible truncation attack?
javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
%% Invalidated:  [Session-7, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256]
SEND TLSv1.2 ALERT:  fatal, description = internal_error
Exception sending alert: java.io.IOException: writer side was already closed.
called closeOutbound()
closeOutboundInternal()

        , but it does not cause any error on the httpd's side

      • I tried to set SetEnv nokeepalive ssl-unclean-shutdown for Apache, but it didn't help
      • only Soalris 11 is affected

      Solaris 11, failed run

      Apache HTTP Server access_log

      10.16.179.28 - - [21/Apr/2016:11:41:32 +0000] "GET /clusterbench/jvmroute HTTP/1.1" 502 498 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"

      Apche HTTP Server error_log

      See full log: sol11_fail_httpd_error_log.zip

      11:41:32.817671 [ssl:info] [pid 36] [client 10.16.179.28:53536] AH01964: Connection to child 0 established (server dev34-02.mw.lab.eng.bos.redhat.com:2080)
11:41:32.913556 [ssl:debug] [pid 36] ssl_engine_kernel.c(1348): [client 10.16.179.28:53536] AH02275: Certificate Verification, depth 1, CRL checking mode: none [subject: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / issuer: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / serial: C454CF9943AC167E / notbefore: Apr 20 14:44:29 2016 GMT / notafter: Apr 18 14:44:29 2026 GMT]
11:41:32.915043 [ssl:debug] [pid 36] ssl_engine_kernel.c(1348): [client 10.16.179.28:53536] AH02275: Certificate Verification, depth 0, CRL checking mode: none [subject: emailAddress=karm@redhat.com,CN=localhost,OU=javaclient,O=Red Hat Testing,L=Brno,ST=Czech,C=CZ / issuer: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / serial: 02 / notbefore: Apr 20 14:51:18 2016 GMT / notafter: Apr 18 14:51:18 2026 GMT]
11:41:32.929905 [ssl:debug] [pid 36] ssl_engine_kernel.c(1806): [client 10.16.179.28:53536] AH02041: Protocol: TLSv1, Cipher: ECDHE-RSA-AES128-SHA (128/128 bits)
11:41:32.931324 [ssl:debug] [pid 36] ssl_engine_kernel.c(217): [client 10.16.179.28:53536] AH02034: Initial (No.1) HTTPS request received for child 0 (server dev34-02.mw.lab.eng.bos.redhat.com:2080)
11:41:32.931510 [authz_core:debug] [pid 36] mod_authz_core.c(834): [client 10.16.179.28:53536] AH01628: authorization result: granted (no directives)
11:41:32.931723 [:debug] [pid 36] mod_proxy_cluster.c(2321): proxy: byrequests balancer DONE (https://10.16.179.28:8443)
11:41:32.931808 [proxy:debug] [pid 36] proxy_util.c(1833): AH00924: worker https://10.16.179.28:8443 shared already initialized
11:41:32.931846 [proxy:debug] [pid 36] proxy_util.c(1875): AH00926: worker https://10.16.179.28:8443 local already initialized
11:41:32.931879 [proxy:debug] [pid 36] mod_proxy.c(1115): [client 10.16.179.28:53536] AH01143: Running scheme balancer handler (attempt 0)
11:41:32.931915 [proxy_fcgi:debug] [pid 36] mod_proxy_fcgi.c(946): [client 10.16.179.28:53536] AH01076: url: https://10.16.179.28:8443/clusterbench/jvmroute proxyname: (null) proxyport: 0
11:41:32.931950 [proxy_fcgi:debug] [pid 36] mod_proxy_fcgi.c(951): [client 10.16.179.28:53536] AH01077: declining URL https://10.16.179.28:8443/clusterbench/jvmroute
11:41:32.931987 [proxy_wstunnel:debug] [pid 36] mod_proxy_wstunnel.c(328): [client 10.16.179.28:53536] AH02450: declining URL https://10.16.179.28:8443/clusterbench/jvmroute
11:41:32.932024 [proxy_ajp:debug] [pid 36] mod_proxy_ajp.c(713): [client 10.16.179.28:53536] AH00894: declining URL https://10.16.179.28:8443/clusterbench/jvmroute
11:41:32.932062 [proxy:debug] [pid 36] proxy_util.c(2198): AH00942: HTTPS: has acquired connection for (10.16.179.28)
11:41:32.932099 [proxy:debug] [pid 36] proxy_util.c(2252): [client 10.16.179.28:53536] AH00944: connecting https://10.16.179.28:8443/clusterbench/jvmroute to 10.16.179.28:8443
11:41:32.932138 [proxy:debug] [pid 36] proxy_util.c(2418): [client 10.16.179.28:53536] AH00947: connected /clusterbench/jvmroute to 10.16.179.28:8443
11:41:32.932424 [proxy:debug] [pid 36] proxy_util.c(2905): AH00962: HTTPS: connection complete to 10.16.179.28:8443 (10.16.179.28)
11:41:32.932485 [ssl:info] [pid 36] [remote 10.16.179.28:8443] AH01964: Connection to child 0 established (server dev34-02.mw.lab.eng.bos.redhat.com:2080)
11:41:32.985044 [ssl:debug] [pid 36] ssl_engine_kernel.c(1348): [remote 10.16.179.28:8443] AH02275: Certificate Verification, depth 1, CRL checking mode: none [subject: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / issuer: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / serial: C454CF9943AC167E / notbefore: Apr 20 14:44:29 2016 GMT / notafter: Apr 18 14:44:29 2026 GMT]
11:41:32.986476 [ssl:debug] [pid 36] ssl_engine_kernel.c(1348): [remote 10.16.179.28:8443] AH02275: Certificate Verification, depth 0, CRL checking mode: none [subject: emailAddress=karm@redhat.com,CN=localhost,OU=javaserver,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / issuer: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / serial: 01 / notbefore: Apr 20 14:49:10 2016 GMT / notafter: Apr 18 14:49:10 2026 GMT]
11:41:33.063078 [ssl:debug] [pid 36] ssl_engine_kernel.c(1806): [remote 10.16.179.28:8443] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
11:41:33.066674 [ssl:info] [pid 36] (70014)End of file found: [remote 10.16.179.28:8443] AH01991: SSL input filter read failed.
11:41:33.066745 [proxy_http:error] [pid 36] (70014)End of file found: [client 10.16.179.28:53536] AH01102: error reading status line from remote server 10.16.179.28:8443
11:41:33.066790 [proxy_http:debug] [pid 36] mod_proxy_http.c(1359): [client 10.16.179.28:53536] AH01105: NOT Closing connection to client although reading from backend server 10.16.179.28:8443 failed.
11:41:33.066835 [proxy:error] [pid 36] [client 10.16.179.28:53536] AH00898: Error reading from remote server returned by /clusterbench/jvmroute
11:41:33.066871 [proxy:debug] [pid 36] proxy_util.c(2213): AH00943: HTTPS: has released connection for (10.16.179.28)
11:41:33.067143 [:debug] [pid 36] mod_proxy_cluster.c(4042): proxy_cluster_post_request 200 for (balancer://qacluster)
11:41:33.067556 [ssl:debug] [pid 36] ssl_engine_io.c(988): [client 10.16.179.28:53536] AH02001: Connection closed to child 0 with standard shutdown (server dev34-02.mw.lab.eng.bos.redhat.com:2080)

      EAP 7.0.0.CR2 spits out

      See relevant snippet: sol11_fail_eap_server_log_snip
      See full log: sol11_fail_eap_server_log.zip

      Client receives

      11:41:33 INFO: <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>502 Proxy Error</title>
</head><body>
<h1>Proxy Error</h1>
<p>The proxy server received an invalid
response from an upstream server.<br />
The proxy server could not handle the request <em><a href="/clusterbench/jvmroute">GET&nbsp;/clusterbench/jvmroute</a></em>.<p>
Reason: <strong>Error reading from remote server</strong></p></p>
<hr>
<address>Apache/2.4.6 (Unix) Server at 10.16.179.28 Port 2443</address>
</body></html>

      Solaris 10, correct run

      Apache HTTP Server access_log

      10.16.92.19 - - [21/Apr/2016:10:49:43 -0400] "GET /clusterbench/jvmroute HTTP/1.1" 200 13 "-" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)"

      Apche HTTP Server error_log

      See full log: sol10_pass_httpd_error_log.zip

      10:49:43.822826 [ssl:info] [pid 2609] [client 10.16.92.19:58326] AH01964: Connection to child 1 established (server dev20-01.mw.lab.eng.bos.redhat.com:2080)
10:49:43.853252 [ssl:debug] [pid 2609] ssl_engine_kernel.c(1348): [client 10.16.92.19:58326] AH02275: Certificate Verification, depth 1, CRL checking mode: none [subject: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / issuer: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / serial: C454CF9943AC167E / notbefore: Apr 20 14:44:29 2016 GMT / notafter: Apr 18 14:44:29 2026 GMT]
10:49:43.853685 [ssl:debug] [pid 2609] ssl_engine_kernel.c(1348): [client 10.16.92.19:58326] AH02275: Certificate Verification, depth 0, CRL checking mode: none [subject: emailAddress=karm@redhat.com,CN=localhost,OU=javaclient,O=Red Hat Testing,L=Brno,ST=Czech,C=CZ / issuer: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / serial: 02 / notbefore: Apr 20 14:51:18 2016 GMT / notafter: Apr 18 14:51:18 2026 GMT]
10:49:43.880243 [ssl:debug] [pid 2609] ssl_engine_kernel.c(1806): [client 10.16.92.19:58326] AH02041: Protocol: TLSv1, Cipher: ECDHE-RSA-AES128-SHA (128/128 bits)
10:49:43.880924 [ssl:debug] [pid 2609] ssl_engine_kernel.c(217): [client 10.16.92.19:58326] AH02034: Initial (No.1) HTTPS request received for child 1 (server dev20-01.mw.lab.eng.bos.redhat.com:2080)
10:49:43.881008 [:debug] [pid 2609] mod_proxy_cluster.c(1053): update_workers_node starting
10:49:43.881037 [:debug] [pid 2609] mod_proxy_cluster.c(694): add_balancer_node: Create balancer balancer://qacluster
10:49:43.881110 [:debug] [pid 2609] mod_proxy_cluster.c(292): Created: worker for https://10.16.92.19:8443
10:49:43.881131 [proxy:debug] [pid 2609] proxy_util.c(1833): AH00924: worker https://10.16.92.19:8443 shared already initialized
10:49:43.881148 [proxy:debug] [pid 2609] proxy_util.c(1880): AH00927: initializing worker https://10.16.92.19:8443 local
10:49:43.881189 [proxy:debug] [pid 2609] proxy_util.c(1931): AH00931: initialized single connection worker in child 2609 for (10.16.92.19)
10:49:43.881211 [:debug] [pid 2609] mod_proxy_cluster.c(316): Created: reusing worker for https://10.16.92.19:8443
10:49:43.881228 [:debug] [pid 2609] mod_proxy_cluster.c(1065): update_workers_node done
10:49:43.881277 [authz_core:debug] [pid 2609] mod_authz_core.c(834): [client 10.16.92.19:58326] AH01628: authorization result: granted (no directives)
10:49:43.881411 [:debug] [pid 2609] mod_proxy_cluster.c(1053): update_workers_node starting
10:49:43.881428 [:debug] [pid 2609] mod_proxy_cluster.c(316): Created: reusing worker for https://10.16.92.19:8443
10:49:43.881447 [:debug] [pid 2609] mod_proxy_cluster.c(316): Created: reusing worker for https://10.16.92.19:8443
10:49:43.881456 [:debug] [pid 2609] mod_proxy_cluster.c(1065): update_workers_node done
10:49:43.881466 [:debug] [pid 2609] mod_proxy_cluster.c(2321): proxy: byrequests balancer DONE (https://10.16.92.19:8443)
10:49:43.881482 [proxy:debug] [pid 2609] proxy_util.c(1833): AH00924: worker https://10.16.92.19:8443 shared already initialized
10:49:43.881498 [proxy:debug] [pid 2609] proxy_util.c(1875): AH00926: worker https://10.16.92.19:8443 local already initialized
10:49:43.881508 [proxy:debug] [pid 2609] mod_proxy.c(1115): [client 10.16.92.19:58326] AH01143: Running scheme balancer handler (attempt 0)
10:49:43.881527 [proxy_fcgi:debug] [pid 2609] mod_proxy_fcgi.c(946): [client 10.16.92.19:58326] AH01076: url: https://10.16.92.19:8443/clusterbench/jvmroute proxyname: (null) proxyport: 0
10:49:43.881544 [proxy_fcgi:debug] [pid 2609] mod_proxy_fcgi.c(951): [client 10.16.92.19:58326] AH01077: declining URL https://10.16.92.19:8443/clusterbench/jvmroute
10:49:43.881568 [proxy_wstunnel:debug] [pid 2609] mod_proxy_wstunnel.c(328): [client 10.16.92.19:58326] AH02450: declining URL https://10.16.92.19:8443/clusterbench/jvmroute
10:49:43.881599 [proxy_ajp:debug] [pid 2609] mod_proxy_ajp.c(713): [client 10.16.92.19:58326] AH00894: declining URL https://10.16.92.19:8443/clusterbench/jvmroute
10:49:43.881654 [proxy:debug] [pid 2609] proxy_util.c(2198): AH00942: HTTPS: has acquired connection for (10.16.92.19)
10:49:43.881668 [proxy:debug] [pid 2609] proxy_util.c(2252): [client 10.16.92.19:58326] AH00944: connecting https://10.16.92.19:8443/clusterbench/jvmroute to 10.16.92.19:8443
10:49:43.881810 [proxy:debug] [pid 2609] proxy_util.c(2418): [client 10.16.92.19:58326] AH00947: connected /clusterbench/jvmroute to 10.16.92.19:8443
10:49:43.881974 [proxy:debug] [pid 2609] proxy_util.c(2905): AH00962: HTTPS: connection complete to 10.16.92.19:8443 (10.16.92.19)
10:49:43.882003 [ssl:info] [pid 2609] [remote 10.16.92.19:8443] AH01964: Connection to child 0 established (server dev20-01.mw.lab.eng.bos.redhat.com:2080)
10:49:43.926953 [ssl:debug] [pid 2609] ssl_engine_kernel.c(1348): [remote 10.16.92.19:8443] AH02275: Certificate Verification, depth 1, CRL checking mode: none [subject: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / issuer: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / serial: C454CF9943AC167E / notbefore: Apr 20 14:44:29 2016 GMT / notafter: Apr 18 14:44:29 2026 GMT]
10:49:43.927488 [ssl:debug] [pid 2609] ssl_engine_kernel.c(1348): [remote 10.16.92.19:8443] AH02275: Certificate Verification, depth 0, CRL checking mode: none [subject: emailAddress=karm@redhat.com,CN=localhost,OU=javaserver,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / issuer: emailAddress=karm@redhat.com,CN=localhost,OU=CA,O=Red Hat testing,L=Brno,ST=Czech,C=CZ / serial: 01 / notbefore: Apr 20 14:49:10 2016 GMT / notafter: Apr 18 14:49:10 2026 GMT]
10:49:43.964926 [ssl:debug] [pid 2609] ssl_engine_kernel.c(1806): [remote 10.16.92.19:8443] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
10:49:44.015420 [proxy:debug] [pid 2609] proxy_util.c(2213): AH00943: https: has released connection for (10.16.92.19)
10:49:44.015556 [:debug] [pid 2609] mod_proxy_cluster.c(4042): proxy_cluster_post_request 200 for (balancer://qacluster)
10:49:44.015656 [ssl:debug] [pid 2609] ssl_engine_io.c(988): [client 10.16.92.19:58326] AH02001: Connection closed to child 1 with standard shutdown (server dev20-01.mw.lab.eng.bos.redhat.com:2080)

      EAP 7.0.0.CR2 spits out

      See relevant snippet: sol10_pass_eap_server_log_snip
      See full log: sol10_pass_eap_server_log.zip

      Configuration and used certificates

      WDYT? Lemme remind that OpenSSL related deadly differences between Solaris 10 and Solaris 11 are not completely unheard of.

      Attachments

        1. ca-cert.jks
          4 kB
        2. client.pem
          5 kB
        3. client-cert-key.jks
          4 kB
        4. mod_cluster.conf
          2 kB
        5. myca.crt
          2 kB
        6. server.crt
          7 kB
        7. server.key
          3 kB
        8. server-cert-key.jks
          4 kB
        9. sol10_pass_eap_server_log.zip
          117 kB
        10. sol10_pass_httpd_error_log.zip
          6 kB
        11. sol11_fail_eap_server_log.zip
          191 kB
        12. sol11_fail_httpd_error_log.zip
          18 kB
        13. standalone-ha.xml
          20 kB

        Issue Links

          is cloned by

          Bug - A problem that impairs or prevents the functions of the product. JWS-398 Solaris 11: Apache HTTP Server SSLProxyEngine: [proxy_http:error] End of file found

          • Critical - To be worked on immediately following BLOCKER issues.
          • Closed

          Activity

            People

              rhn-engineering-mturk Mladen Turk
              mbabacek1@redhat.com Michal Karm
              Michal Karm Michal Karm
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: