Unexpected Exception after some Minutes

2014-04-07
2014-04-07
  • Florian Probst
    Florian Probst
    2014-04-07

    Hi,

    we are using thie openSCADA utgard library and therefore j-interop to communicate with an OPC sever via DCOM. A patch has been applied to the openSCADA library to activate the NTLMv2 and Session Security of the JISession. A short test programm starts with no problems:

    08:39:48.465 [main] INFO  org.openscada.opc.lib.da.Server - Socket timeout: 0 
    08:39:48.514 [main] INFO  org.jinterop.dcom.core.JISession - Created Session: -1310170806
    08:39:48.538 [Timer-2] INFO  o.j.dcom.core.JIComOxidRuntime - Running ServerPingTimerTask !
    08:39:48.539 [Timer-1] INFO  o.j.dcom.core.JIComOxidRuntime - Running ClientPingTimerTask !
    08:39:48.539 [Timer-0] INFO  org.jinterop.dcom.core.JISession - Release_References_TimerTask:[RUN] Session:  -1310170806 , listOfDeferencedIpids.size(): 0
    08:39:48.545 [main] DEBUG o.j.dcom.transport.JIComTransport - Opening socket on /127.0.0.1:135
    

    With the first ping comes an exception:

    08:43:48.514 [Timer-1] INFO  o.j.dcom.core.JIComOxidRuntime - Running ClientPingTimerTask !
    08:43:48.516 [Timer-1] INFO  o.j.dcom.core.JIComOxidRuntime - Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 2
    08:43:48.517 [Timer-1] DEBUG o.j.dcom.transport.JIComTransport - Opening socket on /192.168.3.45:135
    08:43:48.837 [Timer-1] INFO  org.jinterop.dcom.core.PingObject - Complex Ping going for the first time, will get the setId as response of this call
    08:43:48.837 [Timer-1] INFO  org.jinterop.dcom.core.PingObject - Complex ping going : listOfAdds -> Size : 2 , [{ IPID ref count is 2 } and OID in bytes[] 00000: E4 15 63 74 F9 66 0D B7                          |ä.ctùf.        |
    , hasExpired false } , { IPID ref count is 3 } and OID in bytes[] 00000: AE DF DF 58 B6 CE 1D 66                          |®ßßX¶Î.f        |
    , hasExpired false } ]
    08:43:48.837 [Timer-1] INFO  org.jinterop.dcom.core.PingObject - listOfDels -> Size : 0 , []
    Value: [[false]], Timestamp: Fr Apr 04 08:43:48 MESZ 2014, Quality: 192, ErrorCode: 00000000
    08:43:48.889 [Timer-1] WARN  org.jinterop.dcom.core.JIComOxidStub - call
    rpc.FaultException: Received fault. (unknown)
        at rpc.ConnectionOrientedEndpoint.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
        at rpc.Stub.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
        at org.jinterop.dcom.core.JIComOxidStub.call(Unknown Source) [org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask.run(Unknown Source) [org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at java.util.TimerThread.mainLoop(Timer.java:512) [na:1.6.0_20]
        at java.util.TimerThread.run(Timer.java:462) [na:1.6.0_20]
    08:43:48.889 [Timer-1] INFO  o.j.dcom.core.JIComOxidRuntime - Within ClientPingTimerTask: holder.seqNum 1
    

    And the second ping causes an abort of the connection:

    08:47:48.513 [Timer-1] INFO  o.j.dcom.core.JIComOxidRuntime - Running ClientPingTimerTask !
    08:47:48.513 [Timer-1] INFO  o.j.dcom.core.JIComOxidRuntime - Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 2
    08:47:48.513 [Timer-1] INFO  org.jinterop.dcom.core.PingObject - Simple Ping going for setId: 00000: 00 00 00 00 00 00 00 00                          |........        |
    08:47:48.515 [Timer-1] WARN  org.jinterop.dcom.core.JIComOxidStub - call
    java.io.IOException: An established connection was abourted by the software in your host machine
        at sun.nio.ch.SocketDispatcher.read0(Native Method) ~[na:1.6.0_20]
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:25) ~[na:1.6.0_20]
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) ~[na:1.6.0_20]
        at sun.nio.ch.IOUtil.read(IOUtil.java:206) ~[na:1.6.0_20]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) ~[na:1.6.0_20]
        at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:176) ~[na:1.6.0_20]
        at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:86) ~[na:1.6.0_20]
        at org.jinterop.dcom.transport.JIComTransport.receive(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at rpc.DefaultConnection.receiveFragment(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
        at rpc.DefaultConnection.receive(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
        at rpc.ConnectionOrientedEndpoint.receive(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
        at rpc.ConnectionOrientedEndpoint.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
        at rpc.Stub.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
        at org.jinterop.dcom.core.JIComOxidStub.call(Unknown Source) [org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask.run(Unknown Source) [org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at java.util.TimerThread.mainLoop(Timer.java:512) [na:1.6.0_20]
        at java.util.TimerThread.run(Timer.java:462) [na:1.6.0_20]
    08:47:48.515 [Timer-1] INFO  o.j.dcom.core.JIComOxidRuntime - Within ClientPingTimerTask: holder.seqNum 1
    08:47:48.515 [Timer-2] INFO  o.j.dcom.core.JIComOxidRuntime - Running ServerPingTimerTask !
    

    And the final exit with an unexpected exception some minutes ago:

    > 08:49:54.780 [UtgardSyncReader] ERROR org.openscada.opc.lib.da.SyncAccess - Sync read failed
    org.jinterop.dcom.common.JIException: Unspecified Error. [0x80004005]
        at org.jinterop.dcom.core.JIComServer.call(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at org.jinterop.dcom.core.JIComServer.call(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at org.jinterop.dcom.core.JIComObjectImpl.call(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at org.jinterop.dcom.core.JIComObjectImpl.call(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at org.openscada.opc.dcom.common.impl.Helper.callRespectSFALSE(Helper.java:41) ~[org.openscada.opc.dcom_1.0.0.201303051455.jar:na]
        at org.openscada.opc.dcom.da.impl.OPCSyncIO.read(OPCSyncIO.java:65) ~[org.openscada.opc.dcom_1.0.0.201303051455.jar:na]
        at org.openscada.opc.lib.da.Group.read(Group.java:368) ~[org.openscada.opc.lib_1.0.0.201303051455.jar:na]
        at org.openscada.opc.lib.da.SyncAccess.runOnce(SyncAccess.java:92) ~[org.openscada.opc.lib_1.0.0.201303051455.jar:na]
        at org.openscada.opc.lib.da.SyncAccess.run(SyncAccess.java:54) ~[org.openscada.opc.lib_1.0.0.201303051455.jar:na]
        at java.lang.Thread.run(Thread.java:619) [na:1.6.0_20]
    Caused by: org.jinterop.dcom.common.JIRuntimeException: Unspecified Error. [0x80004005]
        at org.jinterop.dcom.core.JICallBuilder.readResult(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at org.jinterop.dcom.core.JICallBuilder.read(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
        at ndr.NdrObject.decode(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
        at rpc.ConnectionOrientedEndpoint.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
        at rpc.Stub.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
        ... 10 common frames omitted
    

    After that exception the DCOM connection is unusable. We are using a Windows Server 2008 R2 SP1. As you can see the j-interop Version 2.0.8 is used by openSCADA. I tried the same program with the latest j-interop 3.0 library without any exceptions for hours.
    So my question is, can we simply change the j-interop library? Is the code backwards compatible so we should not expect any other issues in the openSCADA library? Do you see any reasons for the unexpected exceptions?

    Responses are much appreciated!

    Kind regards,
    Florian

     
    • Dear Florian,

      You need to reach the openScada guys for this. They made a bunch of changes
      we are not aware of and cannot comment on.

      best regards,
      Vikram

      On Mon, Apr 7, 2014 at 1:32 PM, Florian Probst probstl@users.sf.net wrote:

      Hi,

      we are using thie openSCADA utgard library and therefore j-interop to
      communicate with an OPC sever via DCOM. A patch has been applied to the
      openSCADA library to activate the NTLMv2 and Session Security of the
      JISession. A short test programm starts with no problems:

      08:39:48.465 [main] INFO org.openscada.opc.lib.da.Server - Socket timeout: 0 08:39:48.514 [main] INFO org.jinterop.dcom.core.JISession - Created Session: -131017080608:39:48.538 [Timer-2] INFO o.j.dcom.core.JIComOxidRuntime - Running ServerPingTimerTask !08:39:48.539 [Timer-1] INFO o.j.dcom.core.JIComOxidRuntime - Running ClientPingTimerTask !08:39:48.539 [Timer-0] INFO org.jinterop.dcom.core.JISession - Release_References_TimerTask:[RUN] Session: -1310170806 , listOfDeferencedIpids.size(): 008:39:48.545 [main] DEBUG o.j.dcom.transport.JIComTransport - Opening socket on /127.0.0.1:135

      With the first ping comes an exception:

      08:43:48.514 [Timer-1] INFO o.j.dcom.core.JIComOxidRuntime - Running ClientPingTimerTask !08:43:48.516 [Timer-1] INFO o.j.dcom.core.JIComOxidRuntime - Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 208:43:48.517 [Timer-1] DEBUG o.j.dcom.transport.JIComTransport - Opening socket on /192.168.3.45:13508:43:48.837 [Timer-1] INFO org.jinterop.dcom.core.PingObject - Complex Ping going for the first time, will get the setId as response of this call08:43:48.837 [Timer-1] INFO org.jinterop.dcom.core.PingObject - Complex ping going : listOfAdds -> Size : 2 , [{ IPID ref count is 2 } and OID in bytes[] 00000: E4 15 63 74 F9 66 0D B7 |ä.ctùf.* |, hasExpired false } , { IPID ref count is 3 } and OID in bytes[] 00000: AE DF DF 58 B6 CE 1D 66 |(R)ßßX¶Î.f |, hasExpired false } ]08:43:48.837 [Timer-1] INFO org.jinterop.dcom.core.PingObject - listOfDels -> Size : 0 , []Value: [[false]], Timestamp: Fr Apr 04 08:43:48 MESZ 2014, Quality: 192, ErrorCode: 0000000008:43:48.889 [Timer-1] WARN org.jinterop.dcom.core.JIComOxidStub - callrpc.FaultException: Received fault. (unknown)
      at rpc.ConnectionOrientedEndpoint.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
      at rpc.Stub.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
      at org.jinterop.dcom.core.JIComOxidStub.call(Unknown Source) [org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask.run(Unknown Source) [org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at java.util.TimerThread.mainLoop(Timer.java:512) [na:1.6.0_20]
      at java.util.TimerThread.run(Timer.java:462) [na:1.6.0_20]08:43:48.889 [Timer-1] INFO o.j.dcom.core.JIComOxidRuntime - Within ClientPingTimerTask: holder.seqNum 1

      And the second ping causes an abort of the connection:

      08:47:48.513 [Timer-1] INFO o.j.dcom.core.JIComOxidRuntime - Running ClientPingTimerTask !08:47:48.513 [Timer-1] INFO o.j.dcom.core.JIComOxidRuntime - Within ClientPingTimerTask: holder.currentSetOIDs, current size of which is 208:47:48.513 [Timer-1] INFO org.jinterop.dcom.core.PingObject - Simple Ping going for setId: 00000: 00 00 00 00 00 00 00 00 |........ |08:47:48.515 [Timer-1] WARN org.jinterop.dcom.core.JIComOxidStub - calljava.io.IOException: An established connection was abourted by the software in your host machine
      at sun.nio.ch.SocketDispatcher.read0(Native Method) ~[na:1.6.0_20]
      at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:25) ~[na:1.6.0_20]
      at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) ~[na:1.6.0_20]
      at sun.nio.ch.IOUtil.read(IOUtil.java:206) ~[na:1.6.0_20]
      at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) ~[na:1.6.0_20]
      at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:176) ~[na:1.6.0_20]
      at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:86) ~[na:1.6.0_20]
      at org.jinterop.dcom.transport.JIComTransport.receive(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at rpc.DefaultConnection.receiveFragment(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
      at rpc.DefaultConnection.receive(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
      at rpc.ConnectionOrientedEndpoint.receive(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
      at rpc.ConnectionOrientedEndpoint.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
      at rpc.Stub.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
      at org.jinterop.dcom.core.JIComOxidStub.call(Unknown Source) [org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at org.jinterop.dcom.core.JIComOxidRuntime$ClientPingTimerTask.run(Unknown Source) [org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at java.util.TimerThread.mainLoop(Timer.java:512) [na:1.6.0_20]
      at java.util.TimerThread.run(Timer.java:462) [na:1.6.0_20]08:47:48.515 [Timer-1] INFO o.j.dcom.core.JIComOxidRuntime - Within ClientPingTimerTask: holder.seqNum 108:47:48.515 [Timer-2] INFO o.j.dcom.core.JIComOxidRuntime - Running ServerPingTimerTask !

      And the final exit with an unexpected exception some minutes ago:

      08:49:54.780 [UtgardSyncReader] ERROR org.openscada.opc.lib.da.SyncAccess - Sync read failedorg.jinterop.dcom.common.JIException: Unspecified Error. [0x80004005]
      at org.jinterop.dcom.core.JIComServer.call(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at org.jinterop.dcom.core.JIComServer.call(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at org.jinterop.dcom.core.JIComObjectImpl.call(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at org.jinterop.dcom.core.JIComObjectImpl.call(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at org.openscada.opc.dcom.common.impl.Helper.callRespectSFALSE(Helper.java:41) ~[org.openscada.opc.dcom_1.0.0.201303051455.jar:na]
      at org.openscada.opc.dcom.da.impl.OPCSyncIO.read(OPCSyncIO.java:65) ~[org.openscada.opc.dcom_1.0.0.201303051455.jar:na]
      at org.openscada.opc.lib.da.Group.read(Group.java:368) ~[org.openscada.opc.lib_1.0.0.201303051455.jar:na]
      at org.openscada.opc.lib.da.SyncAccess.runOnce(SyncAccess.java:92) ~[org.openscada.opc.lib_1.0.0.201303051455.jar:na]
      at org.openscada.opc.lib.da.SyncAccess.run(SyncAccess.java:54) ~[org.openscada.opc.lib_1.0.0.201303051455.jar:na]
      at java.lang.Thread.run(Thread.java:619) [na:1.6.0_20]Caused by: org.jinterop.dcom.common.JIRuntimeException: Unspecified Error. [0x80004005]
      at org.jinterop.dcom.core.JICallBuilder.readResult(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at org.jinterop.dcom.core.JICallBuilder.read(Unknown Source) ~[org.openscada.jinterop.core_2.0.8.201303051454.jar:na]
      at ndr.NdrObject.decode(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
      at rpc.ConnectionOrientedEndpoint.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
      at rpc.Stub.call(Unknown Source) ~[org.openscada.jinterop.deps_1.0.0.201303051454.jar:na]
      ... 10 common frames omitted

      After that exception the DCOM connection is unusable. We are using a
      Windows Server 2008 R2 SP1. As you can see the j-interop Version 2.0.8 is
      used by openSCADA. I tried the same program with the latest j-interop 3.0
      library without any exceptions for hours.
      So my question is, can we simply change the j-interop library? Is the code
      backwards compatible so we should not expect any other issues in the
      openSCADA library? Do you see any reasons for the unexpected exceptions?

      Responses are much appreciated!

      Kind regards,
      Florian


      Unexpected Exception after some Minuteshttps://sourceforge.net/p/j-interop/discussion/600729/thread/71637ca8/?limit=25#188c

      Sent from sourceforge.net because you indicated interest in
      https://sourceforge.net/p/j-interop/discussion/600729/

      To unsubscribe from further messages, please visit
      https://sourceforge.net/auth/subscriptions/

      --
      The Mind is a place of its own. It can make a heaven out of hell or a hell
      out of heaven. Attitude is everything. No matter how adverse conditions
      maybe, one has the capacity to turn things around by one's Determination,
      Perseverance and Hardwork.

      John Milton
      (Paradise Lost)

       
  • Florian Probst
    Florian Probst
    2014-04-07

    Hi Vikram,
    thank you so much for the quick reply!
    I will ask them on the Google Groups site.
    King regards,
    Florian