[omniORB] Sporadic CommFailure from giopStream.cc:808(0, MAYBE, COMM_FAILURE_WaitingForReply)
Goettlicher, Martin
Martin.Goettlicher at bruker.com
Wed Aug 31 16:35:33 BST 2016
Hi all,
in a client/server application I have sporadic CommFailure exceptions
as shown in the subject. Client and server both use omniORB 4.2.1
and run on the same Linux computer. The problem occurs on different
Linux distributions (testet on CentOS 7.2 and OpenSUSE 42.1).
Since I have no clue what's wrong I would like to ask if somebody on
this list could have a look into the log output with trace level 40
from client and server and give me a hint about the problem. The log
output shows a call "openPsCnt" (no arguments and an int return value)
which succeeded, followed by a call which failed, followed by a call
which succeeded again. When the call fails at the client side, the
application code in the server isn't called at all.
Many thanks for your help.
Best regards,
Martin
Client
======
omniORB: (0) 2016-08-31 16:36:47.932291: Current configuration is as follows:
omniORB: DefaultInitRef (file) =
omniORB: DefaultInitRef (args) =
omniORB: abortOnInternalError = 0
omniORB: abortOnNativeException = 0
omniORB: acceptBiDirectionalGIOP = 0
omniORB: acceptMisalignedTcIndirections = 0
omniORB: bootstrapAgentHostname =
omniORB: bootstrapAgentPort = 900
omniORB: clientCallTimeOutPeriod = 250000
omniORB: clientConnectTimeOutPeriod = 0
omniORB: clientTransportRule = localhost tcp
omniORB: clientTransportRule = 0.0.0.0/0.0.0.0 tcp,ssl
omniORB: configFile = /XXX/omniorb.conf
omniORB: connectionWatchImmediate = 0
omniORB: connectionWatchPeriod = 50000
omniORB: copyValuesInLocalCalls = 1
omniORB: diiThrowsSysExceptions = 0
omniORB: dumpConfiguration = 0
omniORB: endPoint = giop:tcp:0.0.0.0:
omniORB: endPointPublish = addr
omniORB: giopMaxMsgSize = 160000000
omniORB: giopTargetAddressMode = KeyAddr
omniORB: id = omniORB4
omniORB: idleThreadTimeout = 10
omniORB: immediateAddressSwitch = 0
omniORB: inConScanPeriod = 10
omniORB: lcdMode = 0
omniORB: listenBacklog = 128
omniORB: maxClientThreadPoolSize = 100
omniORB: maxGIOPConnectionPerServer = 5
omniORB: maxGIOPVersion = 1.2
omniORB: maxInterleavedCallsPerConnection = 5
omniORB: maxServerThreadPerConnection = 100
omniORB: maxServerThreadPoolSize = 100
omniORB: maxSocketRecv = 2147483647
omniORB: maxSocketSend = 2147483647
omniORB: nativeCharCodeSet = ISO-8859-1
omniORB: nativeWCharCodeSet = UTF-16
omniORB: objectTableSize = 0
omniORB: offerBiDirectionalGIOP = 0
omniORB: oneCallPerConnection = 1
omniORB: outConScanPeriod = 10
omniORB: poaHoldRequestTimeout = 250000
omniORB: poaUniquePersistentSystemIds = 1
omniORB: principal = [Null]
omniORB: resetTimeOutOnRetries = 0
omniORB: scanGranularity = 2
omniORB: serverCallTimeOutPeriod = 250000
omniORB: serverTransportRule = localhost tcp,ssl
omniORB: serverTransportRule = 127.0.0.1 tcp,ssl
omniORB: serverTransportRule = XXX.XXX.XXX.0/255.255.255.0 tcp,ssl
omniORB: serverTransportRule = 0.0.0.0/0.0.0.0 ssl,tcp
omniORB: socketSendBuffer = -1
omniORB: sslAcceptTimeOut = 10000
omniORB: sslCAFile = /XXX/cert_client.pem
omniORB: sslCAPath = <unset>
omniORB: sslKeyFile = /XXX/cert_server.pem
omniORB: sslKeyPassword = ****
omniORB: sslVerifyMode = peer,fail
omniORB: strictIIOP = 1
omniORB: supportBootstrapAgent = 1
omniORB: supportCurrent = 1
omniORB: supportPerThreadTimeOut = 0
omniORB: tcAliasExpand = 0
omniORB: threadPerConnectionLowerLimit = 9000
omniORB: threadPerConnectionPolicy = 1
omniORB: threadPerConnectionUpperLimit = 10000
omniORB: threadPoolWatchConnection = 1
omniORB: throwTransientOnTimeOut = 0
omniORB: traceExceptions = 1
omniORB: traceFile = [stderr]
omniORB: traceInvocationReturns = 0
omniORB: traceInvocations = 0
omniORB: traceLevel = 40
omniORB: traceLocking = 0
omniORB: traceThreadId = 1
omniORB: traceTime = 1
omniORB: unixTransportDirectory = /tmp/omni-%u
omniORB: unixTransportPermission = 777
omniORB: useTypeCodeIndirections = 1
omniORB: validateUTF8 = 0
omniORB: verifyObjectExistsAndType = 1
omniORB: (0) 2016-08-31 16:38:26.293697: Creating ref to remote: root<1>
target id : IDL:omg.org/CORBA/Object:1.0
most derived id: IDL:de/bruker/mri/generated/parx/ParameterService:1.0
omniORB: (0) 2016-08-31 16:38:26.293760: omniRemoteIdentity deleted.
omniORB: (0) 2016-08-31 16:38:26.293777: ObjRef(IDL:de/bruker/mri/generated/parx/ParameterService:1.0) -- deleted.
omniORB: (0) 2016-08-31 16:38:26.293811: sendChunk: to giop:tcp:XXX.XXX.XXX.XXX:60030 68 bytes
omniORB: (0) 2016-08-31 16:38:26.293826:
4749 4f50 0102 0100 3800 0000 0400 0000 GIOP....8.......
0300 0000 0000 3266 0e00 0000 fe5a e9c6 ......2f.....Z..
5700 0063 b700 0000 0001 3631 0d00 0000 W..c......61....
6765 744f 7065 6e50 7343 6e74 0066 3530 getOpenPsCnt.f50
0000 0000 ....
omniORB: (0) 2016-08-31 16:38:26.294283: inputMessage: from giop:tcp:XXX.XXX.XXX.XXX:60030 28 bytes
omniORB: (0) 2016-08-31 16:38:26.294328:
4749 4f50 0102 0101 1000 0000 0400 0000 GIOP............
0000 0000 0000 0000 0000 0000 ............
openPsCnt: 0
call duration of getOpenPsCnt(): 0.577574 ms
omniORB: (2) 2016-08-31 16:38:27.943362: Scan for idle connections (1472654307,943269000)
omniORB: (2) 2016-08-31 16:38:27.943420: Scavenger reduce idle count for strand 0x137b0a0 to 4
omniORB: (2) 2016-08-31 16:38:27.943437: Scan for idle connections done (1472654307,943269000).
omniORB: (2) 2016-08-31 16:38:29.943541: Scan for idle connections (1472654309,943448000)
omniORB: (2) 2016-08-31 16:38:29.943595: Scavenger reduce idle count for strand 0x137b0a0 to 3
omniORB: (2) 2016-08-31 16:38:29.943611: Scan for idle connections done (1472654309,943448000).
omniORB: (2) 2016-08-31 16:38:31.943716: Scan for idle connections (1472654311,943622000)
omniORB: (2) 2016-08-31 16:38:31.943774: Scavenger reduce idle count for strand 0x137b0a0 to 2
omniORB: (2) 2016-08-31 16:38:31.943790: Scan for idle connections done (1472654311,943622000).
omniORB: (2) 2016-08-31 16:38:33.943892: Scan for idle connections (1472654313,943801000)
omniORB: (2) 2016-08-31 16:38:33.943962: Scavenger reduce idle count for strand 0x137b0a0 to 1
omniORB: (2) 2016-08-31 16:38:33.943979: Scan for idle connections done (1472654313,943801000).
omniORB: (0) 2016-08-31 16:38:34.488354: Creating ref to remote: root<1>
target id : IDL:omg.org/CORBA/Object:1.0
most derived id: IDL:de/bruker/mri/generated/parx/ParameterService:1.0
omniORB: (0) 2016-08-31 16:38:34.488435: omniRemoteIdentity deleted.
omniORB: (0) 2016-08-31 16:38:34.488453: ObjRef(IDL:de/bruker/mri/generated/parx/ParameterService:1.0) -- deleted.
omniORB: (0) 2016-08-31 16:38:34.488485: sendChunk: to giop:tcp:XXX.XXX.XXX.XXX:60030 68 bytes
omniORB: (0) 2016-08-31 16:38:34.488500:
4749 4f50 0102 0100 3800 0000 0600 0000 GIOP....8.......
0300 0000 0000 3266 0e00 0000 fe5a e9c6 ......2f.....Z..
5700 0063 b700 0000 0001 3631 0d00 0000 W..c......61....
6765 744f 7065 6e50 7343 6e74 0066 3530 getOpenPsCnt.f50
0000 0000 ....
omniORB: (0) 2016-08-31 16:38:34.488618: Error in network receive (start of message): giop:tcp:XXX.XXX.XXX.XXX:60030
omniORB: (0) 2016-08-31 16:38:34.488638: throw giopStream::CommFailure from giopStream.cc:808(0,MAYBE,COMM_FAILURE_WaitingForReply)
omniORB: (0) 2016-08-31 16:38:34.488728: Client connection giop:tcp:XXX.XXX.XXX.XXX:60030 refcount = 0
omniORB: (0) 2016-08-31 16:38:34.488743: Client close connection to giop:tcp:XXX.XXX.XXX.XXX:60030
omniORB: (0) 2016-08-31 16:38:34.488769: throw COMM_FAILURE from omniObjRef.cc:706 (MAYBE,COMM_FAILURE_WaitingForReply)
openPsCnt failed: Corba System Exception: COMM_FAILURE: call completion indertiminante, minor = 1096024071
call getOpenPsCnt() failed after 0.711827 ms
omniORB: (2) 2016-08-31 16:38:35.944084: Scan for idle connections (1472654315,943991000)
omniORB: (2) 2016-08-31 16:38:35.944137: Scan for idle connections done (1472654315,943991000).
omniORB: (2) 2016-08-31 16:38:37.944244: Scan for idle connections (1472654317,944151000)
omniORB: (2) 2016-08-31 16:38:37.944301: Scan for idle connections done (1472654317,944151000).
omniORB: (2) 2016-08-31 16:38:39.944408: Scan for idle connections (1472654319,944315000)
omniORB: (2) 2016-08-31 16:38:39.944464: Scan for idle connections done (1472654319,944315000).
omniORB: (2) 2016-08-31 16:38:41.944567: Scan for idle connections (1472654321,944478000)
omniORB: (2) 2016-08-31 16:38:41.944615: Scan for idle connections done (1472654321,944478000).
omniORB: (0) 2016-08-31 16:38:42.685362: Creating ref to remote: root<1>
target id : IDL:omg.org/CORBA/Object:1.0
most derived id: IDL:de/bruker/mri/generated/parx/ParameterService:1.0
omniORB: (0) 2016-08-31 16:38:42.685428: omniRemoteIdentity deleted.
omniORB: (0) 2016-08-31 16:38:42.685445: ObjRef(IDL:de/bruker/mri/generated/parx/ParameterService:1.0) -- deleted.
omniORB: (0) 2016-08-31 16:38:42.685484: Send codeset service context: (ISO-8859-1,UTF-16)
omniORB: (0) 2016-08-31 16:38:42.685505: Client attempt to connect to giop:tcp:XXX.XXX.XXX.XXX:60030
omniORB: (0) 2016-08-31 16:38:42.685680: Client opened connection to giop:tcp:XXX.XXX.XXX.XXX:60030
omniORB: (0) 2016-08-31 16:38:42.685701: sendChunk: to giop:tcp:XXX.XXX.XXX.XXX:60030 88 bytes
omniORB: (0) 2016-08-31 16:38:42.685728:
4749 4f50 0102 0100 4c00 0000 0200 0000 GIOP....L.......
0300 0000 0000 0000 0e00 0000 fe5a e9c6 .............Z..
5700 0063 b700 0000 0001 0000 0d00 0000 W..c............
6765 744f 7065 6e50 7343 6e74 0000 0000 getOpenPsCnt....
0100 0000 0100 0000 0c00 0000 0100 0000 ................
0100 0100 0901 0100 ........
omniORB: (0) 2016-08-31 16:38:42.686259: inputMessage: from giop:tcp:XXX.XXX.XXX.XXX:60030 28 bytes
omniORB: (0) 2016-08-31 16:38:42.686304:
4749 4f50 0102 0101 1000 0000 0200 0000 GIOP............
0000 0000 0000 0000 0000 0000 ............
openPsCnt: 0
call duration of getOpenPsCnt(): 0.883859 ms
Server
======
omniORB: (0) 2016-08-31 16:27:38.419901: Current configuration is as follows:
omniORB: DefaultInitRef (file) =
omniORB: DefaultInitRef (args) =
omniORB: InitRef = NameService=corbaloc:iiop:1.2 at localhost:XXXXX/TNameService
omniORB: abortOnInternalError = 0
omniORB: abortOnNativeException = 0
omniORB: acceptBiDirectionalGIOP = 0
omniORB: acceptMisalignedTcIndirections = 0
omniORB: bootstrapAgentHostname =
omniORB: bootstrapAgentPort = 900
omniORB: clientCallTimeOutPeriod = 0
omniORB: clientConnectTimeOutPeriod = 0
omniORB: clientTransportRule = * unix,tcp
omniORB: configFile = /etc/omniORB.cfg
omniORB: connectionWatchImmediate = 0
omniORB: connectionWatchPeriod = 50000
omniORB: copyValuesInLocalCalls = 1
omniORB: diiThrowsSysExceptions = 0
omniORB: dumpConfiguration = 1
omniORB: endPoint = giop:tcp:XXX.XXX.XXX.XXX:60030
omniORB: endPoint = giop:tcp:127.0.0.1:60030
omniORB: endPointPublish = addr
omniORB: giopMaxMsgSize = 16777216
omniORB: giopTargetAddressMode = KeyAddr
omniORB: id = omniORB4
omniORB: idleThreadTimeout = 10
omniORB: immediateAddressSwitch = 0
omniORB: inConScanPeriod = 10
omniORB: lcdMode = 0
omniORB: listenBacklog = 128
omniORB: maxClientThreadPoolSize = 100
omniORB: maxGIOPConnectionPerServer = 5
omniORB: maxGIOPVersion = 1.2
omniORB: maxInterleavedCallsPerConnection = 5
omniORB: maxServerThreadPerConnection = 100
omniORB: maxServerThreadPoolSize = 100
omniORB: maxSocketRecv = 2147483647
omniORB: maxSocketSend = 2147483647
omniORB: nativeCharCodeSet = ISO-8859-1
omniORB: nativeWCharCodeSet = UTF-16
omniORB: objectTableSize = 0
omniORB: offerBiDirectionalGIOP = 0
omniORB: oneCallPerConnection = 1
omniORB: outConScanPeriod = 10
omniORB: poaHoldRequestTimeout = 0
omniORB: poaUniquePersistentSystemIds = 1
omniORB: principal = [Null]
omniORB: resetTimeOutOnRetries = 0
omniORB: scanGranularity = 2
omniORB: serverCallTimeOutPeriod = 0
omniORB: serverTransportRule = * unix,tcp
omniORB: socketSendBuffer = -1
omniORB: sslAcceptTimeOut = 10000
omniORB: sslCAFile = <unset>
omniORB: sslCAPath = <unset>
omniORB: sslKeyFile = <unset>
omniORB: sslKeyPassword = <unset>
omniORB: sslVerifyMode = peer,fail
omniORB: strictIIOP = 1
omniORB: supportBootstrapAgent = 0
omniORB: supportCurrent = 1
omniORB: supportPerThreadTimeOut = 0
omniORB: tcAliasExpand = 0
omniORB: threadPerConnectionLowerLimit = 9000
omniORB: threadPerConnectionPolicy = 1
omniORB: threadPerConnectionUpperLimit = 10000
omniORB: threadPoolWatchConnection = 1
omniORB: throwTransientOnTimeOut = 0
omniORB: traceExceptions = 1
omniORB: traceFile = [stderr]
omniORB: traceInvocationReturns = 0
omniORB: traceInvocations = 0
omniORB: traceLevel = 40
omniORB: traceLocking = 0
omniORB: traceThreadId = 1
omniORB: traceTime = 1
omniORB: unixTransportDirectory = /tmp/omni-%u
omniORB: unixTransportPermission = 777
omniORB: useTypeCodeIndirections = 1
omniORB: validateUTF8 = 0
omniORB: (5) 2016-08-31 16:38:26.293984: inputMessage: from giop:tcp:XXX.XXX.XXX.XXX:42299 68 bytes
omniORB: (5) 2016-08-31 16:38:26.294034:
4749 4f50 0102 0100 3800 0000 0400 0000 GIOP....8.......
0300 0000 0000 3266 0e00 0000 fe5a e9c6 ......2f.....Z..
5700 0063 b700 0000 0001 3631 0d00 0000 W..c......61....
6765 744f 7065 6e50 7343 6e74 0066 3530 getOpenPsCnt.f50
0000 0000 ....
omniORB: (5) 2016-08-31 16:38:26.294132: sendChunk: to giop:tcp:XXX.XXX.XXX.XXX:42299 28 bytes
omniORB: (5) 2016-08-31 16:38:26.294160:
4749 4f50 0102 0101 1000 0000 0400 0000 GIOP............
0000 0000 0000 0000 0000 0000 ............
omniORB: (3) 2016-08-31 16:38:26.478554: Scan for idle connections (1472654306,478464000)
omniORB: (3) 2016-08-31 16:38:26.478598: Scavenger reduce idle count for strand 0x7fcb480009f0 to 4
omniORB: (3) 2016-08-31 16:38:26.478614: Scan for idle connections done (1472654306,478464000).
omniORB: (1) 2016-08-31 16:38:27.295794: SocketCollection idle. Sleeping.
omniORB: (3) 2016-08-31 16:38:28.478721: Scan for idle connections (1472654308,478625000)
omniORB: (3) 2016-08-31 16:38:28.478769: Scavenger reduce idle count for strand 0x7fcb480009f0 to 3
omniORB: (3) 2016-08-31 16:38:28.478785: Scan for idle connections done (1472654308,478625000).
omniORB: (3) 2016-08-31 16:38:30.478892: Scan for idle connections (1472654310,478796000)
omniORB: (3) 2016-08-31 16:38:30.478939: Scavenger reduce idle count for strand 0x7fcb480009f0 to 2
omniORB: (3) 2016-08-31 16:38:30.478954: Scan for idle connections done (1472654310,478796000).
omniORB: (3) 2016-08-31 16:38:32.479063: Scan for idle connections (1472654312,478966000)
omniORB: (3) 2016-08-31 16:38:32.479112: Scavenger reduce idle count for strand 0x7fcb480009f0 to 1
omniORB: (3) 2016-08-31 16:38:32.479128: Scan for idle connections done (1472654312,478966000).
omniORB: (3) 2016-08-31 16:38:34.479234: Scan for idle connections (1472654314,479139000)
omniORB: (3) 2016-08-31 16:38:34.479282: Scavenger reduce idle count for strand 0x7fcb480009f0 to 0
omniORB: (3) 2016-08-31 16:38:34.479298: Scavenger close connection from giop:tcp:XXX.XXX.XXX.XXX:42299
omniORB: (3) 2016-08-31 16:38:34.479310: sendCloseConnection: to giop:tcp:XXX.XXX.XXX.XXX:42299 12 bytes
omniORB: (3) 2016-08-31 16:38:34.479322:
4749 4f50 0102 0105 0000 0000 GIOP........
omniORB: (3) 2016-08-31 16:38:34.479413: Scan for idle connections done (1472654314,479139000).
omniORB: (5) 2016-08-31 16:38:34.479474: Error in network receive (start of message): giop:tcp:XXX.XXX.XXX.XXX:42299
omniORB: (5) 2016-08-31 16:38:34.479515: throw giopStream::CommFailure from giopStream.cc:808(0,NO,COMM_FAILURE_UnMarshalArguments)
omniORB: (5) 2016-08-31 16:38:34.479580: Server connection giop:tcp:XXX.XXX.XXX.XXX:42299 refcount = 1
omniORB: (5) 2016-08-31 16:38:34.479634: Server connection giop:tcp:XXX.XXX.XXX.XXX:42299 refcount = 0
omniORB: (5) 2016-08-31 16:38:34.479653: Server close connection from giop:tcp:XXX.XXX.XXX.XXX:42299
omniORB: (5) 2016-08-31 16:38:34.479670: AsyncInvoker: thread id 5 finished immediate server task.
omniORB: (1) 2016-08-31 16:38:35.481051: SocketCollection idle. Sleeping.
omniORB: (3) 2016-08-31 16:38:36.479539: Scan for idle connections (1472654316,479430000)
omniORB: (3) 2016-08-31 16:38:36.479584: Scan for idle connections done (1472654316,479430000).
omniORB: (3) 2016-08-31 16:38:38.479692: Scan for idle connections (1472654318,479597000)
omniORB: (3) 2016-08-31 16:38:38.479741: Scan for idle connections done (1472654318,479597000).
omniORB: (3) 2016-08-31 16:38:40.479851: Scan for idle connections (1472654320,479755000)
omniORB: (3) 2016-08-31 16:38:40.479900: Scan for idle connections done (1472654320,479755000).
omniORB: (3) 2016-08-31 16:38:42.480013: Scan for idle connections (1472654322,479913000)
omniORB: (3) 2016-08-31 16:38:42.480079: Scan for idle connections done (1472654322,479913000).
omniORB: (1) 2016-08-31 16:38:42.685764: Server accepted connection from giop:tcp:XXX.XXX.XXX.XXX:42301
omniORB: (5) 2016-08-31 16:38:42.685893: AsyncInvoker: thread id 5 performing immediate server task.
omniORB: (5) 2016-08-31 16:38:42.685934: giopWorker task execute.
omniORB: (5) 2016-08-31 16:38:42.685962: Accepted connection from giop:tcp:XXX.XXX.XXX.XXX:42301 because of this rule: "* unix,tcp"
omniORB: (5) 2016-08-31 16:38:42.686003: inputMessage: from giop:tcp:XXX.XXX.XXX.XXX:42301 88 bytes
omniORB: (5) 2016-08-31 16:38:42.686018:
4749 4f50 0102 0100 4c00 0000 0200 0000 GIOP....L.......
0300 0000 0000 0000 0e00 0000 fe5a e9c6 .............Z..
5700 0063 b700 0000 0001 0000 0d00 0000 W..c............
6765 744f 7065 6e50 7343 6e74 0000 0000 getOpenPsCnt....
0100 0000 0100 0000 0c00 0000 0100 0000 ................
0100 0100 0901 0100 ........
omniORB: (5) 2016-08-31 16:38:42.686074: Receive codeset service context and set TCS to (ISO-8859-1,UTF-16)
omniORB: (5) 2016-08-31 16:38:42.686112: sendChunk: to giop:tcp:XXX.XXX.XXX.XXX:42301 28 bytes
omniORB: (5) 2016-08-31 16:38:42.686125:
4749 4f50 0102 0101 1000 0000 0200 0000 GIOP............
0000 0000 0000 0000 0000 0000 ............
omniORB: (1) 2016-08-31 16:38:42.735836: SocketCollection idle. Sleeping.
More information about the omniORB-list
mailing list