We have an issue with callbacks. The registration proceeds well and the callback start receiving information. However, after a while, the callback stops working. No errors are reported. Can this be related to some DCOM ping timeout? I see there is a patch for the 2min and 8min timers but I am not sure whether it is relevant. Has anybody experienced this problem? Thank you very much.
Best Regards,
AR
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Ok, here is the FINEST log. Just to clarify, I am using 2.0.8 j-interop. The svn version did not work in our case complaining about some issues in authentication. The log shows normal activity up until Dec 9, 2010 6:48:44, and after that no onEvent callback is invoked.
INFO:
Recieved REQUEST
Dec 9, 2010 6:48:42 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_RemUnknown , rpc.pdu.RequestCoPdu@e88e24 workerObject is resolver: false
Dec 9, 2010 6:48:42 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
INFO: methodDescriptor: onEvent
Dec 9, 2010 6:48:42 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
INFO: Call Back Method to be executed: public java.lang.Object org.openscada.opc.dcom.ae.impl.OPCEventCallback.onEvent(int,int,int,int,org.jinterop.dcom.core.JIArray) , to be executed on org.openscada.opc.dcom.ae.impl.OPCEventCallback@19b46dc
Dec 9, 2010 6:48:42 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_RemUnknown , rpc.pdu.ResponseCoPdu@e5376a
Dec 9, 2010 6:48:42 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
||s1|| Thu Dec 09 18:48:39 WET 2010: source:computer.clock.timer Type:OPC_SIMPLE_EVENT Cat:time tick Sev:10 Msg:The second changed
Dec 9, 2010 6:48:43 PM rpc.DefaultConnection processIncoming
INFO:
Recieved REQUEST
Dec 9, 2010 6:48:43 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_RemUnknown , rpc.pdu.RequestCoPdu@993aaa workerObject is resolver: false
Dec 9, 2010 6:48:43 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
INFO: methodDescriptor: onEvent
Dec 9, 2010 6:48:43 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
INFO: Call Back Method to be executed: public java.lang.Object org.openscada.opc.dcom.ae.impl.OPCEventCallback.onEvent(int,int,int,int,org.jinterop.dcom.core.JIArray) , to be executed on org.openscada.opc.dcom.ae.impl.OPCEventCallback@19b46dc
Dec 9, 2010 6:48:43 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_RemUnknown , rpc.pdu.ResponseCoPdu@e6235d
Dec 9, 2010 6:48:43 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
||s1|| Thu Dec 09 18:48:40 WET 2010: source:computer.clock.timer Type:OPC_SIMPLE_EVENT Cat:time tick Sev:10 Msg:The second changed
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processIncoming
INFO:
Recieved REQUEST
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_RemUnknown , rpc.pdu.RequestCoPdu@11be57f workerObject is resolver: false
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
INFO: methodDescriptor: onEvent
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
||s1|| Thu Dec 09 18:48:41 WET 2010: source:computer.clock.timer Type:OPC_SIMPLE_EVENT Cat:time tick Sev:10 Msg:The second changed
INFO: Call Back Method to be executed: public java.lang.Object org.openscada.opc.dcom.ae.impl.OPCEventCallback.onEvent(int,int,int,int,org.jinterop.dcom.core.JIArray) , to be executed on org.openscada.opc.dcom.ae.impl.OPCEventCallback@19b46dc
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_RemUnknown , rpc.pdu.ResponseCoPdu@17ee3e5
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Running ClientPingTimerTask !
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ServerPingTimerTask run
INFO: Running ServerPingTimerTask !
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 1
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.PingObject write
INFO: Simple Ping going for setId: 00000: 00 00 00 04 00 00 B5 90 |……µ. |
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$2 run
INFO: JIComOxidRuntimeHelper RemUnknownListenerjI_RemUnknownListener is purposefully closed by interruption.
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$2 run
INFO: terminating RemUnknownListener thread: jI_RemUnknownListener
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending REQUEST
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$3 run
INFO: JIComOxidRuntimeHelper RemUnknownThread (not listener)jI_RemUnknown is purposefully closed by interruption.
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processIncoming
INFO:
Recieved RESPONSE
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.PingObject read
INFO: Simple Ping Succeeded
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.seqNum 1
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 4
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.PingObject write
INFO: Simple Ping going for setId: 00000: 00 00 00 05 00 00 B5 84 |……µ. |
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending REQUEST
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processIncoming
INFO:
Recieved RESPONSE
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.PingObject read
INFO: Simple Ping Succeeded
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.seqNum 1
Dec 9, 2010 6:49:12 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: started startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:49:12 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: started new thread jI_OxidResolver_Client
Dec 9, 2010 6:49:12 PM rpc.DefaultConnection processIncoming
INFO:
Recieved BIND
Dec 9, 2010 6:49:12 PM rpc.DefaultConnection processOutgoing
INFO:
Sending BIND_ACK
Dec 9, 2010 6:49:12 PM rpc.DefaultConnection processIncoming
INFO:
Recieved REQUEST
Dec 9, 2010 6:49:12 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_OxidResolver_Client , rpc.pdu.RequestCoPdu@59e205 workerObject is resolver: true
Dec 9, 2010 6:49:12 PM org.jinterop.dcom.core.OxidResolverImpl SimplePing
INFO: Oxid Object: SimplePing
Dec 9, 2010 6:49:12 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_OxidResolver_Client , rpc.pdu.ResponseCoPdu@105c7e1
Dec 9, 2010 6:49:12 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
Dec 9, 2010 6:49:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 6:49:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: terminating startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:50:44 PM org.jinterop.dcom.core.JISession$Release_References_TimerTask run
INFO: Release_References_TimerTask: Session: 1189389498 , listOfDeferencedIpids.size(): 0
Dec 9, 2010 6:50:44 PM org.jinterop.dcom.core.JISession$Release_References_TimerTask run
INFO: Release_References_TimerTask: Session: -1432854103 , listOfDeferencedIpids.size(): 0
Dec 9, 2010 6:51:13 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: started startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:51:13 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: started new thread jI_OxidResolver_Client
Dec 9, 2010 6:51:13 PM rpc.DefaultConnection processIncoming
INFO:
Recieved BIND
Dec 9, 2010 6:51:13 PM rpc.DefaultConnection processOutgoing
INFO:
Sending BIND_ACK
Dec 9, 2010 6:51:13 PM rpc.DefaultConnection processIncoming
INFO:
Recieved REQUEST
Dec 9, 2010 6:51:13 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_OxidResolver_Client , rpc.pdu.RequestCoPdu@545646 workerObject is resolver: true
Dec 9, 2010 6:51:13 PM org.jinterop.dcom.core.OxidResolverImpl SimplePing
INFO: Oxid Object: SimplePing
Dec 9, 2010 6:51:13 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_OxidResolver_Client , rpc.pdu.ResponseCoPdu@ec2ea8
Dec 9, 2010 6:51:13 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
Dec 9, 2010 6:51:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 6:51:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: terminating startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Running ClientPingTimerTask !
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 1
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.PingObject write
INFO: Simple Ping going for setId: 00000: 00 00 00 04 00 00 B5 90 |……µ. |
Dec 9, 2010 6:52:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending REQUEST
Dec 9, 2010 6:52:44 PM rpc.DefaultConnection processIncoming
INFO:
Recieved RESPONSE
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.PingObject read
INFO: Simple Ping Succeeded
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.seqNum 1
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 4
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.PingObject write
INFO: Simple Ping going for setId: 00000: 00 00 00 05 00 00 B5 84 |……µ. |
Dec 9, 2010 6:52:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending REQUEST
Dec 9, 2010 6:52:44 PM rpc.DefaultConnection processIncoming
INFO:
Recieved RESPONSE
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.PingObject read
INFO: Simple Ping Succeeded
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.seqNum 1
Dec 9, 2010 6:53:15 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: started startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:53:15 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: started new thread jI_OxidResolver_Client
Dec 9, 2010 6:53:15 PM rpc.DefaultConnection processIncoming
INFO:
Recieved BIND
Dec 9, 2010 6:53:15 PM rpc.DefaultConnection processOutgoing
INFO:
Sending BIND_ACK
Dec 9, 2010 6:53:15 PM rpc.DefaultConnection processIncoming
INFO:
Recieved REQUEST
Dec 9, 2010 6:53:15 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_OxidResolver_Client , rpc.pdu.RequestCoPdu@e5025 workerObject is resolver: true
Dec 9, 2010 6:53:15 PM org.jinterop.dcom.core.OxidResolverImpl SimplePing
INFO: Oxid Object: SimplePing
Dec 9, 2010 6:53:15 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_OxidResolver_Client , rpc.pdu.ResponseCoPdu@1afe17b
Dec 9, 2010 6:53:15 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
Dec 9, 2010 6:53:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 6:53:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: terminating startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:53:44 PM org.jinterop.dcom.core.JISession$Release_References_TimerTask run
INFO: Release_References_TimerTask: Session: 1189389498 , listOfDeferencedIpids.size(): 0
Dec 9, 2010 6:53:44 PM org.jinterop.dcom.core.JISession$Release_References_TimerTask run
INFO: Release_References_TimerTask: Session: -1432854103 , listOfDeferencedIpids.size(): 0
Thanks a lot for your help!
Best Regards,
AR
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hi,
So there is nothing unusual that I can see here. It just seems the callbacks have stopped coming from the server itself. Do you have a native code to verify if more than one callback actually comes ? (so that we discount Server as a cause).
thanks,
best regards,
Vikram
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
We have tried two different servers from two different vendors and the result is the same. Native tools work ok, without any timeout.
Can it be related to the pinging? It seems like after the first instance of
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run INFO: Running ClientPingTimerTask !
there is no more callback activity.
Thank you very much for your support.
Best Regards,
AR
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
As I understand it (correct me if I'm wrong), COM specification is built into j-Interop in that a callback will be closed client-side if the server does not ping it every 8 minutes, and that this is unreliable from Windows to j-Interop. The answer is to turn off this mechanism client side through the method call:
JISystem.setJavaCoClassAutoCollection(false);
I'm testing it now in my program and so far so good, but I have to run. Will update later tonight.
-James
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hi,
Actually this behavior has only been noticed on some platforms, I cannot conclusively say if this is a windows issue. According to DCOM specs the run-time should ping us too.
thanks,
best regards,
Vikram
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hello,
We have an issue with callbacks. The registration proceeds well and the callback start receiving information. However, after a while, the callback stops working. No errors are reported. Can this be related to some DCOM ping timeout? I see there is a patch for the 2min and 8min timers but I am not sure whether it is relevant. Has anybody experienced this problem? Thank you very much.
Best Regards,
AR
Hi,
Can you post the log (FINEST level) here ?
thanks,
best regards,
Vikram
Hello,
Sorry for the delay, I still have no FINEST trace. The Warning logs are something like:
Dec 9, 2010 5:29:14 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 5:29:14 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Connection reset by peer , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 5:32:19 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 5:34:19 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 5:36:20 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 5:38:21 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 5:40:21 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 5:42:22 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 5:44:23 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 5:46:24 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 5:48:24 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
I will try to get the FINEST logs and post it here (the size of the message will be huge, though).
Thanks a lot for your help.
Best Regards,
AR
Hello,
Ok, here is the FINEST log. Just to clarify, I am using 2.0.8 j-interop. The svn version did not work in our case complaining about some issues in authentication. The log shows normal activity up until Dec 9, 2010 6:48:44, and after that no onEvent callback is invoked.
INFO:
Recieved REQUEST
Dec 9, 2010 6:48:42 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_RemUnknown , rpc.pdu.RequestCoPdu@e88e24 workerObject is resolver: false
Dec 9, 2010 6:48:42 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
INFO: methodDescriptor: onEvent
Dec 9, 2010 6:48:42 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
INFO: Call Back Method to be executed: public java.lang.Object org.openscada.opc.dcom.ae.impl.OPCEventCallback.onEvent(int,int,int,int,org.jinterop.dcom.core.JIArray) , to be executed on org.openscada.opc.dcom.ae.impl.OPCEventCallback@19b46dc
Dec 9, 2010 6:48:42 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_RemUnknown , rpc.pdu.ResponseCoPdu@e5376a
Dec 9, 2010 6:48:42 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
||s1|| Thu Dec 09 18:48:39 WET 2010: source:computer.clock.timer Type:OPC_SIMPLE_EVENT Cat:time tick Sev:10 Msg:The second changed
Dec 9, 2010 6:48:43 PM rpc.DefaultConnection processIncoming
INFO:
Recieved REQUEST
Dec 9, 2010 6:48:43 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_RemUnknown , rpc.pdu.RequestCoPdu@993aaa workerObject is resolver: false
Dec 9, 2010 6:48:43 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
INFO: methodDescriptor: onEvent
Dec 9, 2010 6:48:43 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
INFO: Call Back Method to be executed: public java.lang.Object org.openscada.opc.dcom.ae.impl.OPCEventCallback.onEvent(int,int,int,int,org.jinterop.dcom.core.JIArray) , to be executed on org.openscada.opc.dcom.ae.impl.OPCEventCallback@19b46dc
Dec 9, 2010 6:48:43 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_RemUnknown , rpc.pdu.ResponseCoPdu@e6235d
Dec 9, 2010 6:48:43 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
||s1|| Thu Dec 09 18:48:40 WET 2010: source:computer.clock.timer Type:OPC_SIMPLE_EVENT Cat:time tick Sev:10 Msg:The second changed
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processIncoming
INFO:
Recieved REQUEST
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_RemUnknown , rpc.pdu.RequestCoPdu@11be57f workerObject is resolver: false
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
INFO: methodDescriptor: onEvent
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JILocalCoClass invokeMethod
||s1|| Thu Dec 09 18:48:41 WET 2010: source:computer.clock.timer Type:OPC_SIMPLE_EVENT Cat:time tick Sev:10 Msg:The second changed
INFO: Call Back Method to be executed: public java.lang.Object org.openscada.opc.dcom.ae.impl.OPCEventCallback.onEvent(int,int,int,int,org.jinterop.dcom.core.JIArray) , to be executed on org.openscada.opc.dcom.ae.impl.OPCEventCallback@19b46dc
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_RemUnknown , rpc.pdu.ResponseCoPdu@17ee3e5
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Running ClientPingTimerTask !
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ServerPingTimerTask run
INFO: Running ServerPingTimerTask !
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 1
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.PingObject write
INFO: Simple Ping going for setId: 00000: 00 00 00 04 00 00 B5 90 |……µ. |
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$2 run
INFO: JIComOxidRuntimeHelper RemUnknownListenerjI_RemUnknownListener is purposefully closed by interruption.
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$2 run
INFO: terminating RemUnknownListener thread: jI_RemUnknownListener
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending REQUEST
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$3 run
INFO: JIComOxidRuntimeHelper RemUnknownThread (not listener)jI_RemUnknown is purposefully closed by interruption.
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processIncoming
INFO:
Recieved RESPONSE
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.PingObject read
INFO: Simple Ping Succeeded
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.seqNum 1
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 4
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.PingObject write
INFO: Simple Ping going for setId: 00000: 00 00 00 05 00 00 B5 84 |……µ. |
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending REQUEST
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processIncoming
INFO:
Recieved RESPONSE
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.PingObject read
INFO: Simple Ping Succeeded
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.seqNum 1
Dec 9, 2010 6:49:12 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: started startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:49:12 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: started new thread jI_OxidResolver_Client
Dec 9, 2010 6:49:12 PM rpc.DefaultConnection processIncoming
INFO:
Recieved BIND
Dec 9, 2010 6:49:12 PM rpc.DefaultConnection processOutgoing
INFO:
Sending BIND_ACK
Dec 9, 2010 6:49:12 PM rpc.DefaultConnection processIncoming
INFO:
Recieved REQUEST
Dec 9, 2010 6:49:12 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_OxidResolver_Client , rpc.pdu.RequestCoPdu@59e205 workerObject is resolver: true
Dec 9, 2010 6:49:12 PM org.jinterop.dcom.core.OxidResolverImpl SimplePing
INFO: Oxid Object: SimplePing
Dec 9, 2010 6:49:12 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_OxidResolver_Client , rpc.pdu.ResponseCoPdu@105c7e1
Dec 9, 2010 6:49:12 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
Dec 9, 2010 6:49:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 6:49:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: terminating startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:50:44 PM org.jinterop.dcom.core.JISession$Release_References_TimerTask run
INFO: Release_References_TimerTask: Session: 1189389498 , listOfDeferencedIpids.size(): 0
Dec 9, 2010 6:50:44 PM org.jinterop.dcom.core.JISession$Release_References_TimerTask run
INFO: Release_References_TimerTask: Session: -1432854103 , listOfDeferencedIpids.size(): 0
Dec 9, 2010 6:51:13 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: started startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:51:13 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: started new thread jI_OxidResolver_Client
Dec 9, 2010 6:51:13 PM rpc.DefaultConnection processIncoming
INFO:
Recieved BIND
Dec 9, 2010 6:51:13 PM rpc.DefaultConnection processOutgoing
INFO:
Sending BIND_ACK
Dec 9, 2010 6:51:13 PM rpc.DefaultConnection processIncoming
INFO:
Recieved REQUEST
Dec 9, 2010 6:51:13 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_OxidResolver_Client , rpc.pdu.RequestCoPdu@545646 workerObject is resolver: true
Dec 9, 2010 6:51:13 PM org.jinterop.dcom.core.OxidResolverImpl SimplePing
INFO: Oxid Object: SimplePing
Dec 9, 2010 6:51:13 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_OxidResolver_Client , rpc.pdu.ResponseCoPdu@ec2ea8
Dec 9, 2010 6:51:13 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
Dec 9, 2010 6:51:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 6:51:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: terminating startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Running ClientPingTimerTask !
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 1
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.PingObject write
INFO: Simple Ping going for setId: 00000: 00 00 00 04 00 00 B5 90 |……µ. |
Dec 9, 2010 6:52:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending REQUEST
Dec 9, 2010 6:52:44 PM rpc.DefaultConnection processIncoming
INFO:
Recieved RESPONSE
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.PingObject read
INFO: Simple Ping Succeeded
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.seqNum 1
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 4
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.PingObject write
INFO: Simple Ping going for setId: 00000: 00 00 00 05 00 00 B5 84 |……µ. |
Dec 9, 2010 6:52:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending REQUEST
Dec 9, 2010 6:52:44 PM rpc.DefaultConnection processIncoming
INFO:
Recieved RESPONSE
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.PingObject read
INFO: Simple Ping Succeeded
Dec 9, 2010 6:52:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run
INFO: Within ClientPingTimerTask: holder.seqNum 1
Dec 9, 2010 6:53:15 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: started startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:53:15 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: started new thread jI_OxidResolver_Client
Dec 9, 2010 6:53:15 PM rpc.DefaultConnection processIncoming
INFO:
Recieved BIND
Dec 9, 2010 6:53:15 PM rpc.DefaultConnection processOutgoing
INFO:
Sending BIND_ACK
Dec 9, 2010 6:53:15 PM rpc.DefaultConnection processIncoming
INFO:
Recieved REQUEST
Dec 9, 2010 6:53:15 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: request : jI_OxidResolver_Client , rpc.pdu.RequestCoPdu@e5025 workerObject is resolver: true
Dec 9, 2010 6:53:15 PM org.jinterop.dcom.core.OxidResolverImpl SimplePing
INFO: Oxid Object: SimplePing
Dec 9, 2010 6:53:15 PM org.jinterop.dcom.transport.JIComRuntimeEndpoint processRequests
INFO: processRequests: response : jI_OxidResolver_Client , rpc.pdu.ResponseCoPdu@1afe17b
Dec 9, 2010 6:53:15 PM rpc.DefaultConnection processOutgoing
INFO:
Sending RESPONSE
Dec 9, 2010 6:53:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
WARNING: Oxid Resolver Thread: Socket Closed , on thread Id: jI_OxidResolver_Client
Dec 9, 2010 6:53:33 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$1 run
INFO: terminating startOxid thread: jI_OxidResolver_Client
Dec 9, 2010 6:53:44 PM org.jinterop.dcom.core.JISession$Release_References_TimerTask run
INFO: Release_References_TimerTask: Session: 1189389498 , listOfDeferencedIpids.size(): 0
Dec 9, 2010 6:53:44 PM org.jinterop.dcom.core.JISession$Release_References_TimerTask run
INFO: Release_References_TimerTask: Session: -1432854103 , listOfDeferencedIpids.size(): 0
Thanks a lot for your help!
Best Regards,
AR
Hi,
So there is nothing unusual that I can see here. It just seems the callbacks have stopped coming from the server itself. Do you have a native code to verify if more than one callback actually comes ? (so that we discount Server as a cause).
thanks,
best regards,
Vikram
Hi!
We have tried two different servers from two different vendors and the result is the same. Native tools work ok, without any timeout.
Can it be related to the pinging? It seems like after the first instance of
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask run INFO: Running ClientPingTimerTask !
there is no more callback activity.
Thank you very much for your support.
Best Regards,
AR
Actually, this might be a bug. After the first SimplePing , the Server aborts the connection
<code>
INFO: JIComOxidRuntimeHelper RemUnknownListenerjI_RemUnknownListener is purposefully closed by interruption.
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$2 run
INFO: terminating RemUnknownListener thread: jI_RemUnknownListener
Dec 9, 2010 6:48:44 PM rpc.DefaultConnection processOutgoing
INFO:
Sending REQUEST
Dec 9, 2010 6:48:44 PM org.jinterop.dcom.core.JIComOxidRuntimeHelper$3 run
INFO: JIComOxidRuntimeHelper RemUnknownThread (not listener)jI_RemUnknown is purposefully closed by interruption.
</code>
Do you have Wireshark captures of Native applications you can send us ?
thanks,
best regards,
Vikram
Hi Vikram,
I sent the capture offline to you. Could you please let me if any of the patches that are available may resolve the issue? Thanks a lot for your help.
Best Regards,
AR
Hello folks. I am having the same problem. Please let me know if you come up with a solution. Thanks so much.
-James
Hello again. It looks to me like the problem is the same as it was for these guys:
http://sourceforge.net/projects/j-interop/forums/forum/600730/topic/3186565
As I understand it (correct me if I'm wrong), COM specification is built into j-Interop in that a callback will be closed client-side if the server does not ping it every 8 minutes, and that this is unreliable from Windows to j-Interop. The answer is to turn off this mechanism client side through the method call:
JISystem.setJavaCoClassAutoCollection(false);
I'm testing it now in my program and so far so good, but I have to run. Will update later tonight.
-James
Yep. That was the problem.
Cheers,
James
Hi!
James, nice catch! I can confirm that this solved the problem. Vikram, is this a problem in J-interop or on the Windows side?
Thanks a lot for the great product!
Best Regards,
AR
Hi,
Actually this behavior has only been noticed on some platforms, I cannot conclusively say if this is a windows issue. According to DCOM specs the run-time should ping us too.
thanks,
best regards,
Vikram
I have the same Problem with OPC
I think the solution is that windows do not ping the interface if a Method of it is called.
Just as Idea…
Best Regards
James solution does not work for me. Still has warinigs:
I've noticed that these warinings occured very close to 2 minutes interval, not 8 mins.
Is there any other idea how to prevent it?