Service Virtualization

============================================================================

| javax.net.ssl.SSLException: Received fatal alert: unexpected_message

============================================================================

| Step:       Virtual HTTPS Live Invocation

----------------------------------------------------------------------------

| Message:     Received fatal alert: unexpected_message

----------------------------------------------------------------------------

| Trapped Exception: Received fatal alert: unexpected_message

| Trapped Message:   javax.net.ssl.SSLException: Received fatal alert: unexpected_message

----------------------------------------------------------------------------

STACK TRACE

javax.net.ssl.SSLException: Received fatal alert: unexpected_message

      at sun.security.ssl.Alerts.getSSLException(Unknown Source)

      at sun.security.ssl.Alerts.getSSLException(Unknown Source)

      at sun.security.ssl.SSLSocketImpl.recvAlert(Unknown Source)

      at sun.security.ssl.SSLSocketImpl.readRecord(Unknown Source)

      at sun.security.ssl.SSLSocketImpl.performInitialHandshake(Unknown Source)

      at sun.security.ssl.SSLSocketImpl.writeRecord(Unknown Source)

      at sun.security.ssl.AppOutputStream.write(Unknown Source)

      at java.io.OutputStream.write(Unknown Source)

      at com.itko.lisa.vse.stateful.protocol.http.HttpLiveInvocationStep.writeRequest(HttpLiveInvocationStep.java:638)

      at com.itko.lisa.vse.stateful.protocol.http.HttpLiveInvocationStep.execute(HttpLiveInvocationStep.java:465)

      at com.itko.lisa.test.TestNode.executeNode(TestNode.java:981)

      at com.itko.lisa.test.TestCase.execute(TestCase.java:1280)

      at com.itko.lisa.test.TestCase.execute(TestCase.java:1195)

      at com.itko.lisa.test.TestCase.executeNextNode(TestCase.java:1180)

      at com.itko.lisa.test.TestCase.executeTest(TestCase.java:1124)

      at com.itko.lisa.coordinator.Instance.run(Instance.java:204)

============================================================================

Unfortunately, the exception does not really help, as it is thrown after the error, and gives no indication as to the SSL steps that took place to get there.

You can get more information by setting the below property in your vmoptions file for the VSE, and restarting it

-Djavax.net.debug=all

Note, though, that this setting is for the JVM, and cannot be set for a particular services (the SSL protocol is handled by Java, after all) and you will want to make sure that no other SSL traffic is being handled by the VSE when you do your testing. 

The above will let you examine how far your handshake got, and hopefully show you what went wrong

Hi Dave,

as per your suggetion, I have added -Djavax.net.debug=all this property in VSE and restarted it. But I did not find any difference between inspection view log information and VSE log information.

Inspection View Long Info:

============================================================================ | javax.net.ssl.SSLException: Received fatal alert: unexpected_message ============================================================================ | Step: Virtual HTTPS Live Invocation  ---------------------------------------------------------------------------- | Message: Received fatal alert: unexpected_message ---------------------------------------------------------------------------- | Trapped Exception: Received fatal alert: unexpected_message | Trapped Message: javax.net.ssl.SSLException: Received fatal alert: unexpected_message ---------------------------------------------------------------------------- STACK TRACE javax.net.ssl.SSLException: Received fatal alert: unexpected_message at sun.security.ssl.Alerts.getSSLException(Unknown Source) at sun.security.ssl.Alerts.getSSLException(Unknown Source) at sun.security.ssl.SSLSocketImpl.recvAlert(Unknown Source) at sun.security.ssl.SSLSocketImpl.readRecord(Unknown Source) at sun.security.ssl.SSLSocketImpl.performInitialHandshake(Unknown Source) at sun.security.ssl.SSLSocketImpl.writeRecord(Unknown Source) at sun.security.ssl.AppOutputStream.write(Unknown Source) at java.io.OutputStream.write(Unknown Source) at com.itko.lisa.vse.stateful.protocol.http.HttpLiveInvocationStep.writeRequest(HttpLiveInvocationStep.java:638) at com.itko.lisa.vse.stateful.protocol.http.HttpLiveInvocationStep.execute(HttpLiveInvocationStep.java:465) at com.itko.lisa.test.TestNode.executeNode(TestNode.java:981) at com.itko.lisa.test.TestCase.execute(TestCase.java:1280) at com.itko.lisa.test.TestCase.execute(TestCase.java:1195) at com.itko.lisa.test.TestCase.executeNextNode(TestCase.java:1180) at com.itko.lisa.test.TestCase.executeTest(TestCase.java:1124) at com.itko.lisa.coordinator.Instance.run(Instance.java:204) ============================================================================

- Allow unsafe renegotiation: false
2018-01-18 16:22:51,897Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Allow legacy hello messages: true
2018-01-18 16:22:51,897Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Is initial handshake: true
2018-01-18 16:22:51,897Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Is secure renegotiation: false
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Allow unsafe renegotiation: false
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Allow legacy hello messages: true
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Is initial handshake: true
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Is secure renegotiation: false
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384 for SSLv2Hello
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384 for SSLv2Hello
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_RSA_WITH_AES_256_CBC_SHA256 for SSLv2Hello
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384 for SSLv2Hello
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384 for SSLv2Hello
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256 for SSLv2Hello
2018-01-18 16:22:51,898Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DHE_DSS_WITH_AES_256_CBC_SHA256 for SSLv2Hello
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384 for SSLv3
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384 for SSLv3
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_RSA_WITH_AES_256_CBC_SHA256 for SSLv3
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384 for SSLv3
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384 for SSLv3
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256 for SSLv3
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DHE_DSS_WITH_AES_256_CBC_SHA256 for SSLv3
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384 for TLSv1
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384 for TLSv1
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_RSA_WITH_AES_256_CBC_SHA256 for TLSv1
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384 for TLSv1
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384 for TLSv1
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256 for TLSv1
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DHE_DSS_WITH_AES_256_CBC_SHA256 for TLSv1
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_RSA_WITH_AES_256_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DHE_DSS_WITH_AES_256_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_RSA_WITH_AES_128_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DHE_DSS_WITH_AES_128_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DH_anon_WITH_AES_256_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_DH_anon_WITH_AES_128_CBC_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Ignoring unsupported cipher suite: TLS_RSA_WITH_NULL_SHA256
2018-01-18 16:22:51,899Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - %% No cached client session
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - *** ClientHello, TLSv1
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - RandomCookie: 
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Session ID:  {}
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Cipher Suites:
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - _SHA, TLS_KRB5_EXPORT_WITH_RC4_40_MD5]
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Compression Methods:  { 0 }
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Extension elliptic_curves, curve names: {secp256r1, sect163k1, sect163r2, secp192r1, secp224r1, sect233k1, sect233r1, sect283k1, sect283r1, secp384r1, sect409k1, sect409r1, secp521r1, sect571k1, sect571r1, secp160k1, secp160r1, secp160r2, sect163r1, secp192k1, sect193r1, sect193r2, secp224k1, sect239k1, secp256k1}
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Extension ec_point_formats, formats: [uncompressed]
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - Extension server_name, server_name: [host_name: aaa.bbbb.com]
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - ***
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - [write] MD5 and SHA1 hashes:  len = 276
2018-01-18 16:22:51,900Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     -                                         .._=
2018-01-18 16:22:51,901Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - newimage2 [VS_newimage2_Run]/1, WRITE: SSLv2 client hello message, length = 260
2018-01-18 16:22:51,902Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     -                                              ..
2018-01-18 16:22:51,903Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - newimage2 [VS_newimage2_Run]/1, READ: TLSv1.2 Alert, length = 2
2018-01-18 16:22:51,903Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - newimage2 [VS_newimage2_Run]/1, RECV TLSv1 ALERT:  fatal, unexpected_message
2018-01-18 16:22:51,903Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - newimage2 [VS_newimage2_Run]/1, called closeSocket()
2018-01-18 16:22:51,904Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - newimage2 [VS_newimage2_Run]/1, handling exception: javax.net.ssl.SSLException: Received fatal alert: unexpected_message
2018-01-18 16:22:51,904Z (08:22) [newimage2 [VS_newimage2_Run]/1] ERROR com.itko.lisa.vse.stateful.protocol.http.HttpLiveInvocationStep - Received fatal alert: unexpected_message
javax.net.ssl.SSLException: Received fatal alert: unexpected_message
 at sun.security.ssl.Alerts.getSSLException(Unknown Source)
 at sun.security.ssl.Alerts.getSSLException(Unknown Source)
 at sun.security.ssl.SSLSocketImpl.recvAlert(Unknown Source)
 at sun.security.ssl.SSLSocketImpl.readRecord(Unknown Source)
 at sun.security.ssl.SSLSocketImpl.performInitialHandshake(Unknown Source)
 at sun.security.ssl.SSLSocketImpl.writeRecord(Unknown Source)
 at sun.security.ssl.AppOutputStream.write(Unknown Source)
 at java.io.OutputStream.write(Unknown Source)
 at com.itko.lisa.vse.stateful.protocol.http.HttpLiveInvocationStep.writeRequest(HttpLiveInvocationStep.java:638)
 at com.itko.lisa.vse.stateful.protocol.http.HttpLiveInvocationStep.execute(HttpLiveInvocationStep.java:465)
 at com.itko.lisa.test.TestNode.executeNode(TestNode.java:981)
 at com.itko.lisa.test.TestCase.execute(TestCase.java:1280)
 at com.itko.lisa.test.TestCase.execute(TestCase.java:1195)
 at com.itko.lisa.test.TestCase.executeNextNode(TestCase.java:1180)
 at com.itko.lisa.test.TestCase.executeTest(TestCase.java:1124)
 at com.itko.lisa.coordinator.Instance.run(Instance.java:204)
2018-01-18 16:22:51,905Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - newimage2 [VS_newimage2_Run]/1, called close()
2018-01-18 16:22:51,905Z (08:22) [newimage2 [VS_newimage2_Run]/1] INFO  System.out                     - newimage2 [VS_newimage2_Run]/1, called closeInternal(true)

So, you are sending a SSLv2 Hello, and receiving a TLSv1.2 alert.

Try adding

-Dhttps.protocols=TLSv1.2,TLSv1.1,TLSv1

To the vmoptions file.

Note that the TLS/SSL implementation is that of Java - so it is Java that we have to persuade to play nicely.

issue got resolved.

Thanks Dave for your help.

Glad it is resolved!