glassfish
  1. glassfish
  2. GLASSFISH-6465

SSL Connection failed during longevity test

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Cannot Reproduce
    • Affects Version/s: 9.1.1
    • Fix Version/s: V3
    • Component/s: web_container
    • Labels:
      None
    • Environment:

      Operating System: other
      Platform: Sun

    • Issuezilla Id:
      6,465

      Description

      Build: GlassFish V2.1 B53
      Application: Richaccess
      Suse Linux 10
      JDK1.5.0_16 B02

      When running longevity test using Richaccess application, the Silkperformer
      client crashed at the 6th day. This is on Suse linux with load of 400 users in a
      4 instance cluster. There are no exceptions in the appserver logs. There are
      only errors in webserver and the client machine.

      I had seen this same error from webserver in B50 and the client also crashed
      after 6th day. But I didn't have the error file logging enabled on client
      machine at that time.

      Error from webserver
      ********************
      [30/Sep/2008:19:21:09] info ( 1805): CORE3274: successful server startup
      [06/Oct/2008:23:36:39] warning ( 1805): reports: lb.runtime: ROUT1014:
      Non-idempotent request /richAccess/ cannot be retried.
      [06/Oct/2008:23:36:39] info ( 1805): reports: lb.runtime: RNTM3003 : Error
      servicing the request : selected server could not service, server:
      https://10.5.220.68:38181
      [06/Oct/2008:23:36:39] failure ( 1805): HTTP3068: Error receiving request from
      10.4.118.236 (SSL_ERROR_CLIENT_KEY_EXCHANGE_FAILURE: Unspecified failure while
      processing SSL Client Key Exchange handshake.)
      [06/Oct/2008:23:36:39] warning ( 1805): reports: lb.runtime: ROUT1014:
      Non-idempotent request /richAccess cannot be retried.

      Client error log shows this:
      ****************************
      Message(1,Security):
      {
      Transaction : TMAIN, line: 37, call: 120372
      Time : 23:36:58
      Severity : error
      Internal Error : 10
      Native Error : 0
      Message : WebPageUrl(Security: 10 - SSL connection failed, SSLConnect)
      }
      Message(2,HTTP):
      {
      Transaction : TMAIN, line: 41, call: 120372
      Time : 23:36:58
      Severity : error
      Internal Error : 1062
      Native Error : 0
      Message : WebPageSubmit(HTTP: 1062 - HTML form not found., "Submit")
      }
      Message(3,HTTP):
      {
      Transaction : TMAIN, line: 45, call: 120372
      Time : 23:36:58
      Severity : error
      Internal Error : 1062
      Native Error : 0
      Message : WebPageSubmit(HTTP: 1062 - HTML form not found., "Checkout")
      }
      Message(4,HTTP):
      {
      Transaction : TMAIN, line: 49, call: 120372
      Time : 23:36:59
      Severity : error
      Internal Error : 1062
      Native Error : 0
      Message : WebPageSubmitBin(HTTP: 1062 - HTML form not found., "Send Order")
      }
      Message(5,Security):
      {
      Transaction : TMAIN, line: 37, call: 120373
      Time : 23:36:59
      Severity : error
      Internal Error : 10
      Native Error : 0
      Message : WebPageUrl(Security: 10 - SSL connection failed, SSLConnect)
      }

      The webserver machine is a V240 which has 2 CPUs, 8GB RAM and speed of 1503MHz.
      The client machine has 2 CPUs, 1GB RAM and speed of 2.80GHz.

      All the appserver, webserver and client machines are in the same subnet.

      This Richaccess SSL test on Suse was last run on B39. All the machines were the
      same except for the webserver machine. But at that time, the run was for 3 days
      and not 7 days.

      I am filing this bug for monitoring purpose as this test is not able to meet the
      7 days criteria and it has twice terminated at the 6th day.

        Activity

        Hide
        meenap added a comment -

        After setting appserver log to FINE, I manually tried accessing all the 4
        instances with HTTPS ports, I am not getting any fine logs in appserver logs.
        The HTTP port is working fine for all 4 instances.

        This is what I get on the browser when accessing HTTPS port:
        ************************************************************
        The Proxy Was Unable to Fulfill Your Request

        The proxy was unable to fulfill your request because the computer at
        10.5.220.68:38181 does not appear to be functioning properly. While attempting
        to communicate with 10.5.220.68:38181, the proxy encountered the following
        error: HTTP7765: error reading response header (Server closed connection)

        If you typed the web address, please check for typographical errors. If the
        address is correct and later attempts to access this website are still
        unsuccessful, you may wish to contact the website's administrator.

        Sun Java System Web Proxy Server at cache1mpk.sfbay.Sun.COM:8080

        Show
        meenap added a comment - After setting appserver log to FINE, I manually tried accessing all the 4 instances with HTTPS ports, I am not getting any fine logs in appserver logs. The HTTP port is working fine for all 4 instances. This is what I get on the browser when accessing HTTPS port: ************************************************************ The Proxy Was Unable to Fulfill Your Request The proxy was unable to fulfill your request because the computer at 10.5.220.68:38181 does not appear to be functioning properly. While attempting to communicate with 10.5.220.68:38181, the proxy encountered the following error: HTTP7765: error reading response header (Server closed connection) If you typed the web address, please check for typographical errors. If the address is correct and later attempts to access this website are still unsuccessful, you may wish to contact the website's administrator. Sun Java System Web Proxy Server at cache1mpk.sfbay.Sun.COM:8080
        Hide
        meenap added a comment -

        netstat -a shows 38181 is in LISTEN state.

        Active Internet connections (servers and established)
        Proto Recv-Q Send-Q Local Address Foreign Address State
        tcp 0 0 :38080 *: LISTEN
        tcp 0 0 :33920 *: LISTEN
        tcp 0 0 :12992 *: LISTEN
        tcp 0 0 :37346 *: LISTEN
        tcp 0 0 :43810 *: LISTEN
        tcp 0 0 :57027 *: LISTEN
        tcp 0 0 :33700 *: LISTEN
        tcp 0 0 :38181 *: LISTEN

        Show
        meenap added a comment - netstat -a shows 38181 is in LISTEN state. Active Internet connections (servers and established) Proto Recv-Q Send-Q Local Address Foreign Address State tcp 0 0 :38080 *: LISTEN tcp 0 0 :33920 *: LISTEN tcp 0 0 :12992 *: LISTEN tcp 0 0 :37346 *: LISTEN tcp 0 0 :43810 *: LISTEN tcp 0 0 :57027 *: LISTEN tcp 0 0 :33700 *: LISTEN tcp 0 0 :38181 *: LISTEN
        Hide
        meenap added a comment -

        I re-ran the test with following debug flag enabled and setting Security and
        WebContainer to FINEST log level.

        <jvm-options>-Djavax.net.debug=all, ssl</jvm-options>

        With debug flag enabled turned, the ave response time per transaction was
        925-1052 secs which is extremely slow. In normal working condition, it is around
        6.45 seconds per transaction.

        I restarted the run after removing the debug flag. At the beginning of the run,
        the ave response time was about 18 seconds. But now at 89 hours into the run,
        the ave response time is about 23 seconds. I am seeing lots of these errors in
        the server logs.

        [#|2008-10-13T11:55:35.063-0700|FINE|sun-appserver9.1|javax.enterprise.system.container.web|_ThreadID=107;_ThreadName=httpSSLWorkerThread-38181-4;ClassName=com.sun.enterprise.web.connector.grizzly.ssl.SSLByteBufferInputStream;MethodName=doRead;_RequestID=1b1219ba-e38d-41e9-b4ec-3d78cd2dca11;|SSLUtils.unwrapAll
        java.io.IOException: Unwrap error: CLOSED
        at
        com.sun.enterprise.web.connector.grizzly.ssl.SSLUtils.unwrapAll(SSLUtils.java:226)
        at
        com.sun.enterprise.web.connector.grizzly.ssl.SSLByteBufferInputStream.doRead(SSLByteBufferInputStream.java:79)
        at
        com.sun.enterprise.web.connector.grizzly.ByteBufferInputStream.read(ByteBufferInputStream.java:167)
        at
        org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:744)
        at
        org.apache.coyote.http11.InternalInputBuffer.parseRequestLine(InternalInputBuffer.java:418)
        at
        com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.parseRequest(DefaultProcessorTask.java:684)
        at
        com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.doProcess(DefaultProcessorTask.java:567)
        at
        com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.process(DefaultProcessorTask.java:821)
        at
        com.sun.enterprise.web.connector.grizzly.DefaultReadTask.executeProcessorTask(DefaultReadTask.java:341)
        at
        com.sun.enterprise.web.connector.grizzly.ssl.SSLReadTask.process(SSLReadTask.java:440)
        at
        com.sun.enterprise.web.connector.grizzly.ssl.SSLReadTask.doTask(SSLReadTask.java:228)
        at com.sun.enterprise.web.connector.grizzly.TaskBase.run(TaskBase.java:265)
        at
        com.sun.enterprise.web.connector.grizzly.ssl.SSLWorkerThread.run(SSLWorkerThread.java:106)

        #]

        [#|2008-10-13T11:55:35.064-0700|FINEST|sun-appserver9.1|javax.enterprise.system.container.web|_ThreadID=107;_ThreadName=httpSSLWorkerThread-38181-4;ClassName=com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask;MethodName=parseRequest;_RequestID=1b1219ba-e38d-41e9-b4ec-3d78cd2dca11;|WEB0777:
        Unblocking keep-alive exception
        java.io.EOFException: PWC4661: Unexpected EOF read on the socket
        at
        org.apache.coyote.http11.InternalInputBuffer.parseRequestLine(InternalInputBuffer.java:419)
        at
        com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.parseRequest(DefaultProcessorTask.java:684)
        at
        com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.doProcess(DefaultProcessorTask.java:567)
        at
        com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.process(DefaultProcessorTask.java:821)
        at
        com.sun.enterprise.web.connector.grizzly.DefaultReadTask.executeProcessorTask(DefaultReadTask.java:341)
        at
        com.sun.enterprise.web.connector.grizzly.ssl.SSLReadTask.process(SSLReadTask.java:440)
        at
        com.sun.enterprise.web.connector.grizzly.ssl.SSLReadTask.doTask(SSLReadTask.java:228)
        at com.sun.enterprise.web.connector.grizzly.TaskBase.run(TaskBase.java:265)
        at
        com.sun.enterprise.web.connector.grizzly.ssl.SSLWorkerThread.run(SSLWorkerThread.java:106)

        #]
        Show
        meenap added a comment - I re-ran the test with following debug flag enabled and setting Security and WebContainer to FINEST log level. <jvm-options>-Djavax.net.debug=all, ssl</jvm-options> With debug flag enabled turned, the ave response time per transaction was 925-1052 secs which is extremely slow. In normal working condition, it is around 6.45 seconds per transaction. I restarted the run after removing the debug flag. At the beginning of the run, the ave response time was about 18 seconds. But now at 89 hours into the run, the ave response time is about 23 seconds. I am seeing lots of these errors in the server logs. [#|2008-10-13T11:55:35.063-0700|FINE|sun-appserver9.1|javax.enterprise.system.container.web|_ThreadID=107;_ThreadName=httpSSLWorkerThread-38181-4;ClassName=com.sun.enterprise.web.connector.grizzly.ssl.SSLByteBufferInputStream;MethodName=doRead;_RequestID=1b1219ba-e38d-41e9-b4ec-3d78cd2dca11;|SSLUtils.unwrapAll java.io.IOException: Unwrap error: CLOSED at com.sun.enterprise.web.connector.grizzly.ssl.SSLUtils.unwrapAll(SSLUtils.java:226) at com.sun.enterprise.web.connector.grizzly.ssl.SSLByteBufferInputStream.doRead(SSLByteBufferInputStream.java:79) at com.sun.enterprise.web.connector.grizzly.ByteBufferInputStream.read(ByteBufferInputStream.java:167) at org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:744) at org.apache.coyote.http11.InternalInputBuffer.parseRequestLine(InternalInputBuffer.java:418) at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.parseRequest(DefaultProcessorTask.java:684) at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.doProcess(DefaultProcessorTask.java:567) at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.process(DefaultProcessorTask.java:821) at com.sun.enterprise.web.connector.grizzly.DefaultReadTask.executeProcessorTask(DefaultReadTask.java:341) at com.sun.enterprise.web.connector.grizzly.ssl.SSLReadTask.process(SSLReadTask.java:440) at com.sun.enterprise.web.connector.grizzly.ssl.SSLReadTask.doTask(SSLReadTask.java:228) at com.sun.enterprise.web.connector.grizzly.TaskBase.run(TaskBase.java:265) at com.sun.enterprise.web.connector.grizzly.ssl.SSLWorkerThread.run(SSLWorkerThread.java:106) #] [#|2008-10-13T11:55:35.064-0700|FINEST|sun-appserver9.1|javax.enterprise.system.container.web|_ThreadID=107;_ThreadName=httpSSLWorkerThread-38181-4;ClassName=com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask;MethodName=parseRequest;_RequestID=1b1219ba-e38d-41e9-b4ec-3d78cd2dca11;|WEB0777: Unblocking keep-alive exception java.io.EOFException: PWC4661: Unexpected EOF read on the socket at org.apache.coyote.http11.InternalInputBuffer.parseRequestLine(InternalInputBuffer.java:419) at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.parseRequest(DefaultProcessorTask.java:684) at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.doProcess(DefaultProcessorTask.java:567) at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.process(DefaultProcessorTask.java:821) at com.sun.enterprise.web.connector.grizzly.DefaultReadTask.executeProcessorTask(DefaultReadTask.java:341) at com.sun.enterprise.web.connector.grizzly.ssl.SSLReadTask.process(SSLReadTask.java:440) at com.sun.enterprise.web.connector.grizzly.ssl.SSLReadTask.doTask(SSLReadTask.java:228) at com.sun.enterprise.web.connector.grizzly.TaskBase.run(TaskBase.java:265) at com.sun.enterprise.web.connector.grizzly.ssl.SSLWorkerThread.run(SSLWorkerThread.java:106) #]
        Hide
        meenap added a comment -

        Created an attachment (id=1961)
        Attaching last server log

        Show
        meenap added a comment - Created an attachment (id=1961) Attaching last server log
        Hide
        kumarjayanti added a comment -

        reassign to grizzly since the exception is in Grizzly.

        Show
        kumarjayanti added a comment - reassign to grizzly since the exception is in Grizzly.
        Hide
        jfarcand added a comment -

        Looks like the client closed the connection before Grizzly has a chance to read
        it, hence the exception is expected as adding the security javax.debug makes GF
        acting really slow.

        Meena, can you increase the timeout value on the client side. I suspect the
        client is closing the connection because GF is too slow.

        Show
        jfarcand added a comment - Looks like the client closed the connection before Grizzly has a chance to read it, hence the exception is expected as adding the security javax.debug makes GF acting really slow. Meena, can you increase the timeout value on the client side. I suspect the client is closing the connection because GF is too slow.
        Hide
        harpreet added a comment -

        Please scrub issue and see if it is critical to v2.1.

        Show
        harpreet added a comment - Please scrub issue and see if it is critical to v2.1.
        Hide
        meenap added a comment -

        The SSL test on Suse Linux has passed 24X7 on B55 after the client thinktime was
        increased from 1 sec to 2 secs. Marking bug as resolved.

        Show
        meenap added a comment - The SSL test on Suse Linux has passed 24X7 on B55 after the client thinktime was increased from 1 sec to 2 secs. Marking bug as resolved.
        Hide
        meenap added a comment -

        Closing Bug

        Show
        meenap added a comment - Closing Bug

          People

          • Assignee:
            oleksiys
            Reporter:
            meenap
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: