IBM Support

cdinterop_cdjava.log is filling up with exceptions of failed snode sessions due to a Load Balancer hitting the CDSA adapter

Troubleshooting


Problem

After upgrading from Sterling B2B Integrator (SBI) 5.2.4 to 5.2.5_4, exceptions are posted to the cdinterop_cdjava log every 2 to 3 seconds, even though Debug is turned off for the log. The exceptions are related to failed SNODE sessions originating from the Load Balancer. This did not occur on SBI 5.2.4.

Symptom

SBI CDinterop_cdjava log, posting numerous exceptions per failed SNODE session and debug is turned off:

[2015-06-05 13:28:46.106] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: com.sterlingcommerce.cd.cdjava.CdCommIOException('JMGR012I', 'java.io.InterruptedIOException', "CdMessager.recvCommBuffer() caught: java.io.InterruptedIOException - Did not get buffer in 90000 ms")
[2015-06-05 13:28:46.106] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: v[0] Did not get buffer in 90000 ms
[2015-06-05 13:28:46.106] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: v[1] MSGID=JMGR012I,RC=8,FDBK=1,CLMTHNAME=CdMessager.sendCommBuffer, CDTXT="A communications error occurred while trying to send a message. Please retry the operation. If the problem persists contact your Connect:Direct administrator. Additional JAVA error information is ", JTXT="CdMessager.recvCommBuffer() caught: java.io.InterruptedIOException - Did not get buffer in 90000 ms"
[2015-06-05 13:28:46.106] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [0] com.sterlingcommerce.cd.cdjava.CdMessager.recvCommBuffer(CdMessager.java:421)
[2015-06-05 13:28:46.106] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [1] com.sterlingcommerce.cd.cdjava.CdMessager.recvFmh(CdMessager.java:455)
[2015-06-05 13:28:46.106] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [2] com.sterlingcommerce.cd.cdjava.CdSnApi.doFmh68(CdSnApi.java:537)
[2015-06-05 13:28:46.106] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [3] com.sterlingcommerce.cd.cdjava.CdSnApi.doFmh68Secp(CdSnApi.java:593)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [4] com.sterlingcommerce.cd.cdjava.CdSnApi.beSnodeFM68(CdSnApi.java:350)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [5] com.sterlingcommerce.cd.cdjava.CdSnApi.beSnode(CdSnApi.java:150)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [6] com.sterlingcommerce.cd.cdjava.CdSnApi.beSnode(CdSnApi.java:517)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [7] com.sterlingcommerce.cd.cdjava.CdSnApi.beSnode(CdSnApi.java:441)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [8] com.sterlingcommerce.cd.cdjava.CDApi.beSnode(CDApi.java:145)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [9] com.sterlingcommerce.cd.oemglue.SnodeSessionMediator.beTheNode(SnodeSessionMediator.java:196)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [10] com.sterlingcommerce.cd.oemglue.SnodeSessionMediator.beTheNode(SnodeSessionMediator.java:560)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [11] com.sterlingcommerce.woodstock.cdinterop.impl.serverImpl.CDServer.notify(CDServer.java:2231)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [12] com.sterlingcommerce.woodstock.cdinterop.impl.serverImpl.CDServerListener$Notifier.run(CDServerListener.java:235)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION: [13] java.lang.Thread.run(Thread.java:804)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION CAUSE: java.io.InterruptedIOException
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION CAUSE: Did not get buffer in 90000 ms
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION CAUSE: [0] com.sterlingcommerce.perimeter.api.conduit.ConduitStreamPair$ConduitInputStream.prepareCurrentByteBuffer(ConduitStreamPair.java:262)
[2015-06-05 13:28:46.107] ALL [Thread-112144/236800] 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Jun 5, 2015 1:28:46 PM: 00| EXCEPTION CAUSE: [1] com.sterlingcommerce.perimeter.api.conduit.ConduitStreamPair$ConduitInputStream.read(ConduitStreamPair.java:167)

CDinterop log:

[2015-06-05 13:27:16.093] DEBUG [001DanielCDSA_CDSERVER_ADAPTER_node1-Scheduler/776] CDServerListener.canAccept() - Accepting new connection
[2015-06-05 13:27:16.093] DEBUG [001DanielCDSA_CDSERVER_ADAPTER_node1-Scheduler/776] CDServerListener.canAccept() - Accepting new connection [Thread-112144/236800] from: 10.10.10.10
[2015-06-05 13:27:16.095] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - Received notify from Listener [Thread-112144/236800]
[2015-06-05 13:27:16.095] DEBUG [Thread-112144/236800] CDConnectionManager.createSNodeConnection() - Entering - nodeName [DanielCDSA]
[2015-06-05 13:27:16.097] DEBUG [Thread-112144/236800] RepositoryShslDB.snodeSessionCountPhase1Helper('', '001DanielCDSA') SNODE SES REQ: Local node '001DanielCDSA' session status: 0 active, 5 limit
[2015-06-05 13:27:16.097] DEBUG [Thread-112144/236800] RepositoryShslDB.snodeSessionCountPhase1Helper('', '001DanielCDSA') SNODE SES REQ: this request is within group/local's limit (0 active, 5 limit)
[2015-06-05 13:27:16.097] DEBUG [Thread-112144/236800] RepositoryShslDB.snodeSessionCountPhase1Helper('', '001DanielCDSA') SNODE SES REQ: Accepting phase (1) session...
[2015-06-05 13:27:16.098] DEBUG [Thread-112144/236800] RepositoryShslDB.snodeSessionCountPhase1Helper('', '001DanielCDSA') SNODE SES REQ: Updated local node '001DanielCDSA' session status: 1 active, 5 limit
[2015-06-05 13:27:16.099] DEBUG [Thread-112144/236800] RepositoryShslDB.acceptSnodeConnectionPhase1(001DanielCDSA) - Phase (1) snode session accepted
[2015-06-05 13:27:16.101] DEBUG [Thread-112144/236800] CDConnectionManager : name = 001DanielCDSA_CDSERVER_ADAPTER_node1 Creating SNode Connection:001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4
[2015-06-05 13:27:16.101] DEBUG [Thread-112144/236800] ConnectDirectConnection - connection state is: ACTIVE
[2015-06-05 13:27:16.104] DEBUG [Thread-112144/236800] CDConnectionManager.addNewConnection just added SNode connection with id=001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4:28927
[2015-06-05 13:27:16.104] DEBUG [Thread-112144/236800] RepositoryShslDB.getLocalNodeSessionActivityHelper('001DanielCDSA') session activity: LOCAL_NODE_ID: '001DanielCDSA' ACTIVE_PNODE_SESSIONS: '0' ACTIVE_SNODE_SESSIONS: '1'
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDConnectionManager.createSNodeConnection() - exit nodeName [DanielCDSA]
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - Created Snode Session Id= 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4:28927 on CDServer: 001DanielCDSA_CDSERVER_ADAPTER_node1 with socketReadTimeout(sec) = 90
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - Trying to start a SecurePlus Snode Session Id= 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4:28927 on 001DanielCDSA_CDSERVER_ADAPTER_node1
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - Protocol=NONE
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - System Cert=
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - Cert Common Name=null
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - CA Certs=[[]]
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - Ciphers=[[]]
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - local override=true
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - before secure beTheNode() - keyCertStream [null] - caCertSream [null]
[2015-06-05 13:27:16.105] DEBUG [Thread-112144/236800] CDConnectionManager.getConnection() called with id=001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4
[2015-06-05 13:28:46.11] DEBUG [Thread-112144/236800] ConnectDirectConnection.isSecurePlusEnabled() - ENTERING
[2015-06-05 13:28:46.111] DEBUG [Thread-112144/236800] CDConnectionManager.releaseConnectionResources(001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4) - Entry: SessionId: 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4 Adapter: 001DanielCDSA_CDSERVER_ADAPTER_node1 LocalNode: DanielCDSA RemoteNode: (9.55.70.103) UserId: 'null' PNUM: -1 PNAME:
[2015-06-05 13:28:46.111] DEBUG [Thread-112144/236800] ConnectDirectConnection.isActive() - session id: '001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4' connection state is: ACTIVE
[2015-06-05 13:28:46.111] DEBUG [Thread-112144/236800] ConnectDirectConnection.setInactive() - session id: '001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4' setting connection state to: INACTIVE
[2015-06-05 13:28:46.113] DEBUG [Thread-112144/236800] RepositoryShslDB.snodeSessionCountPhase1Helper('', '001DanielCDSA') SNODE SES REL: Local node '001DanielCDSA' session status: 1 active, 5 limit
[2015-06-05 13:28:46.113] DEBUG [Thread-112144/236800] RepositoryShslDB.snodeSessionCountPhase1Helper('', '001DanielCDSA') SNODE SES REL: Releasing the phase (1) session...
[2015-06-05 13:28:46.114] DEBUG [Thread-112144/236800] RepositoryShslDB.snodeSessionCountPhase1Helper('', '001DanielCDSA') SNODE SES REL: Updated local node '001DanielCDSA' session status: 0 active, 5 limit
[2015-06-05 13:28:46.115] DEBUG [Thread-112144/236800] RepositoryShslDB.releaseSnodeConnectionPhase1(001DanielCDSA) - Phase (1) snode session released
[2015-06-05 13:28:46.115] DEBUG [Thread-112144/236800] CDConnectionManager.releaseConnectionResources(001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4) - Exit.
[2015-06-05 13:28:46.115] DEBUG [Thread-112144/236800] CDConnectionManager.removeConnection(001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4) - local node: DanielCDSA remote node: - connection successfully removed
[2015-06-05 13:28:46.115] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - after secure beTheNode()
[2015-06-05 13:28:46.115] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - Completed Snode Session Id= 001DanielCDSA_CDSERVER_ADAPTER_node1S00000214591279L4:28927 on CDServer 001DanielCDSA_CDSERVER_ADAPTER_node1
[2015-06-05 13:28:46.115] DEBUG [Thread-112144/236800] CDServer[001DanielCDSA_CDSERVER_ADAPTER_node1].notify() - Closing down the dataConduit


Perimeter Server log, useful to see the ipaddress of the remote SNODE:

[2015-06-05 13:27:16.091] COMMTRACE <Dispatcher> Listen[0.0.0.0/0.0.0.0:52323]: accepted: /10.10.10.10:51437
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> Listen[0.0.0.0/0.0.0.0:52323]: send buffer size: 131072
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> tcp keepalive enabled for data[/1.2.3.4:52323=>/10.10.10.10:51437]
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> PhysicalConnectionManager.connectionEvent(PhysCon(-353279655): [java.nio.channels.SocketChannel[connected local=/1.2.3.4:52323 remote=/10.10.10.10:51437]], accept).
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> PhysicalConnectionManager: active connection count: 31
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> AcceptServer[port: 52323] - Accepting new connection: PhysCon(-353279655): [java.nio.channels.SocketChannel[connected local=/1.2.3.4:52323 remote=/10.10.10.10:51437]]
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> DataServer: receiveWindow: 307200
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> DataServer: windowAdjustLevel: 215040
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> Relay[local]: Sending: AcceptMessage[peerInfo:10.10.10.10|51437|1.2.3.4|52323 circuitId:252 destCircuitId:52]
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> data[/1.2.3.4:52323=>/10.10.10.10:51437].register()
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> Dispatcher.register.call()
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> Parsing frame: Frame[ACPT < A10.10.10.10|51437|1.2.3.4|52323 C25> 0]
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> Relay[local]: received: AcceptMessage[peerInfo:10.10.10.10|51437|1.2.3.4|52323 circuitId:252 destCircuitId:52]
[2015-06-05 13:27:16.092] DEBUG <Dispatcher> Relay[local]: A message [AcceptMessage[peerInfo:10.10.10.10|51437|1.2.3.4|52323 circuitId:252 destCircuitId:52]] was received for circuit 52
[2015-06-05 13:27:16.093] DEBUG <Dispatcher> AcceptClient[local BOUND,id:26,port:52323]: received AcceptMessage[peerInfo:10.10.10.10|51437|1.2.3.4|52323 circuitId:252 destCircuitId:52]
[2015-06-05 13:27:16.093] COMMTRACE <Dispatcher> Per[local] Accepted connection: /1.2.3.4:52323 => /10.10.10.10:51437
[2015-06-05 13:27:16.093] DEBUG <Dispatcher> DataClientHelper..setServerConfiguration: Window: 307200, adjustLevel: 215040

[{"Product":{"code":"SS3JSW","label":"IBM Sterling B2B Integrator"},"Business Unit":{"code":"BU048","label":"IBM Software"},"Component":"--","Platform":[{"code":"PF025","label":"Platform Independent"}],"Version":"5.2.5","Edition":"","Line of Business":{"code":"LOB77","label":"Automation Platform"}}]

Log InLog in to view more of this document

This document has the abstract of a technical article that is available to authorized users once you have logged on. Please use Log in button above to access the full document. After log in, if you do not have the right authorization for this document, there will be instructions on what to do next.

Document Information

Modified date:
18 May 2020

UID

swg21959365

Page Feedback