[omniORB] Fallback from SSL to TCP on CA failure?

[Peter Klotz]

Hello

I have a client/server SSL setup with deliberately misconfigured
certificates.

Options -ORBclientTransportRule and -ORBserverTransportRule are '*
ssl,tcp' for client and server.

The server has a TCP and an SSL listen port who are both published in
its IOR. omniNames just uses a TCP listen port.

The server implements two servants who each have a trivial ping() method.

Calling A::ping() results in a client side TRANSIENT_ConnectFailed
exception. No fallback from SSL to TCP is performed.

Calling B::ping() works by performing a fallback to TCP (according to
tcpdump).

Following is the trace level 40 output which we redirected to our
logging framework.

Call of A::ping() which fails:

2009-10-03 23:38:03.506458 V omniORB pid: 27194 tid: 1120360768
omniORB: Scan for idle connections done (1254605883,504876000).
2009-10-03 23:38:05.445609 V omniORB pid: 27194 tid: 1118259520
omniORB: openSSL error detected in sslEndpoint::accept.
Reason: error:14094418:SSL routines:SSL3_READ_BYTES:tlsv1 alert
unknown ca
2009-10-03 23:38:05.495830 V omniORB pid: 27194 tid: 1118259520
omniORB: SocketCollection idle. Sleeping.
2009-10-03 23:38:08.507753 V omniORB pid: 27194 tid: 1120360768
omniORB: Scan for idle connections (1254605888,506495000)

Call of B::ping() which succeeds:

2009-10-03 23:40:28.576844 V omniORB pid: 27194 tid: 1120360768
omniORB: Scan for idle connections (1254606028,575725000)
2009-10-03 23:40:28.576946 V omniORB pid: 27194 tid: 1120360768
omniORB: Scan for idle connections done (1254606028,575725000).
2009-10-03 23:40:30.484465 V omniORB pid: 27194 tid: 1118259520
omniORB: openSSL error detected in sslEndpoint::accept.
Reason: error:14094418:SSL routines:SSL3_READ_BYTES:tlsv1 alert
unknown ca
2009-10-03 23:40:30.485112 V omniORB pid: 27194 tid: 1116158272
omniORB: Server accepted connection from giop:tcp:10.18.1.19:60232
2009-10-03 23:40:30.485268 V omniORB pid: 27194 tid: 1102518592
omniORB: AsyncInvoker: thread id = 57 has started. Total threads = 4
2009-10-03 23:40:30.485272 V omniORB pid: 27194 tid: 1102518592
omniORB: giopWorker task execute.
2009-10-03 23:40:30.485274 V omniORB pid: 27194 tid: 1102518592
omniORB: Accepted connection from giop:tcp:10.18.1.19:60232 because
of this rule: "* ssl,tcp"
2009-10-03 23:40:30.485451 V omniORB pid: 27194 tid: 1102518592
omniORB: inputMessage: from giop:tcp:10.18.1.19:60232 38 bytes



How can the behavior be different depending on calling A::ping() or
B::ping()?

Is it the desired behavior that omniORB (4.1.4) performs a fallback from
SSL to TCP if the CA check fails?

I assumed that client and server agree on a transport that both support
according to the published IOR and once started their communication are
unable to fallback to anything else.

Any help is highly appreciated.

Regards, Peter.

[Duncan Grisby]

On Sunday 4 October, Peter Klotz wrote:

[...]

Post by Peter Klotz
Is it the desired behavior that omniORB (4.1.4) performs a fallback
from SSL to TCP if the CA check fails?

Yes, if that's what the clientTransportRule specifies. If an object
reference contains both SSL and TCP endpoints, a client will try both
unless its clientTransportRule tells it not to. See this bit of the
manual:

http://omniorb.sourceforge.net/omni41/omniORB/omniORB008.html#toc43

Why one of your methods falls back and the other doesn't, I'm not
sure. Is it from the same client? Can you get a trace from traceLevel
25 traceInvocations 1 on the client?

Cheers,

Duncan.

[Peter Klotz]

Hello Duncan

Post by Duncan Grisby
[...]

Post by Peter Klotz
Is it the desired behavior that omniORB (4.1.4) performs a fallback
from SSL to TCP if the CA check fails?

Yes, if that's what the clientTransportRule specifies. If an object
reference contains both SSL and TCP endpoints, a client will try both
unless its clientTransportRule tells it not to. See this bit of the
http://omniorb.sourceforge.net/omni41/omniORB/omniORB008.html#toc43

Thank you for clarifying this issue. So the case where I am not seeing
fallbacks is the wrong one.

Post by Duncan Grisby
Why one of your methods falls back and the other doesn't, I'm not
sure. Is it from the same client? Can you get a trace from traceLevel
25 traceInvocations 1 on the client?

For my tests I use one client and one server that implements several
servants.

You can find the requested output attached (Client-TL25-NoFallback.txt).
TCP port is 11260, SSL port is 11261.

These lines look strange:

Switching to TCP:

omniORB: (0) 2009-10-07 14:56:55.889763: Switch rope to use address
giop:tcp:10.18.2.48:11260

Immediately afterwards failing using SSL:

omniORB: (0) 2009-10-07 14:56:55.889861: Unable to open new
connection: giop:ssl:10.18.2.48:11261

I have reduced my client to the absolute minimum and now only one usage
pattern results in a TCP fallback:

* Obtain an object reference for servant A
* Obtain an object reference for servant B
* Call a method on object reference B. This call fails without TCP fallback.
* Now calling methods on object reference A works and uses the TCP fallback

I also attached the output of this scenario (Client-TL25-Fallback.txt).

Thanks for your help so far.

Regards, Peter.
-------------- next part --------------
omniORB: (0) 2009-10-07 17:26:47.665448: Creating ref to remote: key<NameService>
target id : IDL:omg.org/CORBA/Object:1.0
most derived id:
omniORB: (0) 2009-10-07 17:26:47.665615: Initial reference `NameService' resolved from -ORBInitRef argument / ORB registration.
omniORB: (0) 2009-10-07 17:26:47.665715: Invoke '_is_a' on remote: key<NameService>
omniORB: (0) 2009-10-07 17:26:47.665899: Client attempt to connect to giop:tcp:host:7883
omniORB: (1) 2009-10-07 17:26:47.665913: AsyncInvoker: thread id = 1 has started. Total threads = 1
omniORB: (0) 2009-10-07 17:26:47.666198: Name 'host' resolved: 10.18.2.48
omniORB: (1) 2009-10-07 17:26:47.666309: Scavenger task execute.
omniORB: (0) 2009-10-07 17:26:47.667825: Client opened connection to giop:tcp:10.18.2.48:7883
omniORB: (0) 2009-10-07 17:26:47.667931: sendChunk: to giop:tcp:10.18.2.48:7883 100 bytes
omniORB: (0) 2009-10-07 17:26:47.669098: inputMessage: from giop:tcp:10.18.2.48:7883 25 bytes
omniORB: (0) 2009-10-07 17:26:47.669202: Return '_is_a' on remote: key<NameService>
omniORB: (0) 2009-10-07 17:26:47.669300: Creating ref to remote: key<NameService>
target id : IDL:omg.org/CosNaming/NamingContext:1.0
most derived id:
2009-10-07 17:26:47.669455 V NamingService pid: 13249 tid: 47877037859360
omniORB: (0) 2009-10-07 17:26:47.669595: Invoke 'resolve' on remote: key<NameService>
omniORB: (0) 2009-10-07 17:26:47.669729: sendChunk: to giop:tcp:10.18.2.48:7883 217 bytes
omniORB: (0) 2009-10-07 17:26:47.670048: inputMessage: from giop:tcp:10.18.2.48:7883 200 bytes
omniORB: (0) 2009-10-07 17:26:47.670180: Creating ref to remote: root<8>
target id : IDL:omg.org/CORBA/Object:1.0
most derived id: IDL:ico/corba/testmc/idl/Administration:1.0
omniORB: (0) 2009-10-07 17:26:47.670293: Return 'resolve' on remote: key<NameService>
omniORB: (0) 2009-10-07 17:26:47.670404: ObjRef() -- deleted.
omniORB: (0) 2009-10-07 17:26:47.670503: Initial reference `NameService' resolved from -ORBInitRef argument / ORB registration.
omniORB: (0) 2009-10-07 17:26:47.670598: Invoke '_is_a' on remote: key<NameService>
omniORB: (0) 2009-10-07 17:26:47.670691: sendChunk: to giop:tcp:10.18.2.48:7883 100 bytes
omniORB: (0) 2009-10-07 17:26:47.670948: inputMessage: from giop:tcp:10.18.2.48:7883 25 bytes
omniORB: (0) 2009-10-07 17:26:47.671038: Return '_is_a' on remote: key<NameService>
omniORB: (0) 2009-10-07 17:26:47.671130: Creating ref to remote: key<NameService>
target id : IDL:omg.org/CosNaming/NamingContext:1.0
most derived id:
2009-10-07 17:26:47.671279 V NamingService pid: 13249 tid: 47877037859360
omniORB: (0) 2009-10-07 17:26:47.671356: Invoke 'resolve' on remote: key<NameService>
omniORB: (0) 2009-10-07 17:26:47.671451: sendChunk: to giop:tcp:10.18.2.48:7883 217 bytes
omniORB: (0) 2009-10-07 17:26:47.671728: inputMessage: from giop:tcp:10.18.2.48:7883 204 bytes
omniORB: (0) 2009-10-07 17:26:47.671837: Creating ref to remote: root<2>
target id : IDL:omg.org/CORBA/Object:1.0
most derived id: IDL:ico/corba/testmc/idl/TestNativeTypes:1.0
omniORB: (0) 2009-10-07 17:26:47.671964: Return 'resolve' on remote: key<NameService>
omniORB: (0) 2009-10-07 17:26:47.672065: ObjRef() -- deleted.
omniORB: (0) 2009-10-07 17:26:47.672161: LocateRequest to remote: root<2>
omniORB: (0) 2009-10-07 17:26:47.672273: Client attempt to connect to giop:ssl:10.18.2.48:11261
omniORB: (0) 2009-10-07 17:26:47.677145: openSSL error detected in sslAddress::connect. Reason: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed
omniORB: (0) 2009-10-07 17:26:47.677324: Switch rope to use address giop:tcp:10.18.2.48:11260
omniORB: (0) 2009-10-07 17:26:47.677426: Unable to open new connection: giop:ssl:10.18.2.48:11261
omniORB: (0) 2009-10-07 17:26:47.677519: throw giopStream::CommFailure from giopStream.cc:1152(1,NO,TRANSIENT_ConnectFailed)
omniORB: (0) 2009-10-07 17:26:47.677770: throw TRANSIENT from omniObjRef.cc:1137 (NO,TRANSIENT_ConnectFailed)
omniORB: (0) 2009-10-07 17:26:47.678034: omniRemoteIdentity deleted.
omniORB: (0) 2009-10-07 17:26:47.678127: ObjRef(IDL:ico/corba/testmc/idl/TestNativeTypes:1.0) -- deleted.
omniORB: (0) 2009-10-07 17:26:47.678495: LocateRequest to remote: root<8>
omniORB: (0) 2009-10-07 17:26:47.678619: Client attempt to connect to giop:tcp:10.18.2.48:11260
omniORB: (0) 2009-10-07 17:26:47.678909: Client opened connection to giop:tcp:10.18.2.48:11260
omniORB: (0) 2009-10-07 17:26:47.679004: sendChunk: to giop:tcp:10.18.2.48:11260 38 bytes
omniORB: (0) 2009-10-07 17:26:47.680052: inputMessage: from giop:tcp:10.18.2.48:11260 20 bytes
omniORB: (0) 2009-10-07 17:26:47.680175: Invoke 'ping' on remote: root<8>
omniORB: (0) 2009-10-07 17:26:47.680277: Send codeset service context: (ISO-8859-1,UTF-16)
omniORB: (0) 2009-10-07 17:26:47.680374: sendChunk: to giop:tcp:10.18.2.48:11260 80 bytes
omniORB: (0) 2009-10-07 17:26:47.681229: inputMessage: from giop:tcp:10.18.2.48:11260 24 bytes
omniORB: (0) 2009-10-07 17:26:47.681321: Return 'ping' on remote: root<8>
omniORB: (0) 2009-10-07 17:26:47.681412: omniRemoteIdentity deleted.
omniORB: (0) 2009-10-07 17:26:47.681503: ObjRef(IDL:ico/corba/testmc/idl/Administration:1.0) -- deleted.
omniORB: (0) 2009-10-07 17:26:47.681603: Preparing to shutdown ORB.

-------------- next part --------------
omniORB: (0) 2009-10-07 14:56:55.880847: Creating ref to remote: key<NameService>
target id : IDL:omg.org/CORBA/Object:1.0
most derived id:
omniORB: (0) 2009-10-07 14:56:55.881033: Initial reference `NameService' resolved from -ORBInitRef argument / ORB registration.
omniORB: (0) 2009-10-07 14:56:55.881135: Invoke '_is_a' on remote: key<NameService>
omniORB: (0) 2009-10-07 14:56:55.881334: Client attempt to connect to giop:tcp:host:7883
omniORB: (1) 2009-10-07 14:56:55.881346: AsyncInvoker: thread id = 1 has started. Total threads = 1
omniORB: (0) 2009-10-07 14:56:55.881672: Name 'host' resolved: 10.18.2.48
omniORB: (1) 2009-10-07 14:56:55.881745: Scavenger task execute.
omniORB: (0) 2009-10-07 14:56:55.882196: Client opened connection to giop:tcp:10.18.2.48:7883
omniORB: (0) 2009-10-07 14:56:55.882302: sendChunk: to giop:tcp:10.18.2.48:7883 100 bytes
omniORB: (0) 2009-10-07 14:56:55.882783: inputMessage: from giop:tcp:10.18.2.48:7883 25 bytes
omniORB: (0) 2009-10-07 14:56:55.882905: Return '_is_a' on remote: key<NameService>
omniORB: (0) 2009-10-07 14:56:55.883016: Creating ref to remote: key<NameService>
target id : IDL:omg.org/CosNaming/NamingContext:1.0
most derived id:
omniORB: (0) 2009-10-07 14:56:55.883330: Invoke 'resolve' on remote: key<NameService>
omniORB: (0) 2009-10-07 14:56:55.883445: sendChunk: to giop:tcp:10.18.2.48:7883 217 bytes
omniORB: (0) 2009-10-07 14:56:55.883783: inputMessage: from giop:tcp:10.18.2.48:7883 200 bytes
omniORB: (0) 2009-10-07 14:56:55.884113: Creating ref to remote: root<8>
target id : IDL:omg.org/CORBA/Object:1.0
most derived id: IDL:ico/corba/testmc/idl/Administration:1.0
omniORB: (0) 2009-10-07 14:56:55.884235: Return 'resolve' on remote: key<NameService>
omniORB: (0) 2009-10-07 14:56:55.884358: ObjRef() -- deleted.
omniORB: (0) 2009-10-07 14:56:55.884461: LocateRequest to remote: root<8>
omniORB: (0) 2009-10-07 14:56:55.884582: Client attempt to connect to giop:ssl:10.18.2.48:11261
omniORB: (0) 2009-10-07 14:56:55.889571: openSSL error detected in sslAddress::connect. Reason: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed
omniORB: (0) 2009-10-07 14:56:55.889763: Switch rope to use address giop:tcp:10.18.2.48:11260
omniORB: (0) 2009-10-07 14:56:55.889861: Unable to open new connection: giop:ssl:10.18.2.48:11261
omniORB: (0) 2009-10-07 14:56:55.889953: throw giopStream::CommFailure from giopStream.cc:1152(1,NO,TRANSIENT_ConnectFailed)
omniORB: (0) 2009-10-07 14:56:55.890227: throw TRANSIENT from omniObjRef.cc:1137 (NO,TRANSIENT_ConnectFailed)
omniORB: (0) 2009-10-07 14:56:55.890545: omniRemoteIdentity deleted.
omniORB: (0) 2009-10-07 14:56:55.890656: ObjRef(IDL:ico/corba/testmc/idl/Administration:1.0) -- deleted.
omniORB: (0) 2009-10-07 14:56:55.890768: Preparing to shutdown ORB.

[Duncan Grisby]

On Wed, 2009-10-07 at 17:58 +0200, Peter Klotz wrote:

[...]

Post by Peter Klotz
omniORB: (0) 2009-10-07 14:56:55.889763: Switch rope to use address
giop:tcp:10.18.2.48:11260
omniORB: (0) 2009-10-07 14:56:55.889861: Unable to open new
connection: giop:ssl:10.18.2.48:11261

That's normal. Due to the way the exceptions are handled, the log
message to say that the "rope" (which represents communication with a
particular set of endpoints) is switched to a new address happens before
the log message to say that opening a new connection failed.

Now I look at your trace, I realise that I wasn't correct in saying that
the fallback to a second address is automatic. When opening a connection
fails, the rope is switched to the next address in the available
addresses, but the connection attempt is not automatically retried. If
you try the call again, it will try the second address. That's why you
see that when you try two calls to a particular server, the second one
succeeds after the first has failed.

It's possible to register a TRANSIENT exception handler that
automatically retries in these situations. That's why I told you the
wrong thing before -- the system I spend most of my time using does have
such a handler, and I forgot that the standard one doesn't retry.

Cheers,

Duncan.

[Peter Klotz]

Hello Duncan

Post by Duncan Grisby
Now I look at your trace, I realise that I wasn't correct in saying that
the fallback to a second address is automatic. When opening a connection
fails, the rope is switched to the next address in the available
addresses, but the connection attempt is not automatically retried. If
you try the call again, it will try the second address. That's why you
see that when you try two calls to a particular server, the second one
succeeds after the first has failed.

Thanks a lot for this explanation. Now my test results finally make sense.

Post by Duncan Grisby
It's possible to register a TRANSIENT exception handler that
automatically retries in these situations. That's why I told you the
wrong thing before -- the system I spend most of my time using does have
such a handler, and I forgot that the standard one doesn't retry.

Actually I do not want a retry in my situation. I would like to force my
clients to use SSL although the servers have to support a plain TCP
listen port for backward compatibility with legacy non SSL clients.

Currently I am forced to also allow TCP for my clients since they
contact omniNames without encryption.

I tried running omniNames with an SSL endpoint but got this error:

omniORB: ORB_init failed: unknown option (-ORBsslCAFile) in -ORB arguments
Failed to initialise the ORB / POA: INITIALIZE_InvalidORBInitArgs
Is omniNames already running?


In an SSL build of omniORB omniNames does not depend on libomnisslTP4.so.

Is it possible to encrypt the Naming Service communication?

Regards, Peter.

[Peter Klotz]

Hello Duncan

Post by Peter Klotz
Actually I do not want a retry in my situation. I would like to force my
clients to use SSL although the servers have to support a plain TCP
listen port for backward compatibility with legacy non SSL clients.
Currently I am forced to also allow TCP for my clients since they
contact omniNames without encryption.
omniORB: ORB_init failed: unknown option (-ORBsslCAFile) in -ORB arguments
Failed to initialise the ORB / POA: INITIALIZE_InvalidORBInitArgs
Is omniNames already running?
In an SSL build of omniORB omniNames does not depend on libomnisslTP4.so.
Is it possible to encrypt the Naming Service communication?

Is encryption of Naming Service communication possible with omniORB?

The only other option I can think of is to use client side interceptors
that prohibit the use of plain TCP.

Regards, Peter.

[Duncan Grisby]

Post by Peter Klotz
Currently I am forced to also allow TCP for my clients since they
contact omniNames without encryption.
omniORB: ORB_init failed: unknown option (-ORBsslCAFile) in -ORB arguments
Failed to initialise the ORB / POA: INITIALIZE_InvalidORBInitArgs
Is omniNames already running?
In an SSL build of omniORB omniNames does not depend on libomnisslTP4.so.
Is it possible to encrypt the Naming Service communication?

Yes, if you link omniNames with the omnisslTP library. omniNames isn't
linked by to the SSL transport by default for historical reasons. It
would make sense to link it if the build is building it.

If you come up with a patch I will integrate it.

Cheers,

Duncan.