Unexpected Exception (0x80004005) after some Minutes Runtime

263 views
Skip to first unread message

fpatd...@googlemail.com

unread,
Apr 7, 2014, 7:23:10 AM4/7/14
to open...@googlegroups.com
Hi,

we are using the openSCADA utgard library to communicate with an OPC sever via DCOM. A patch has been applied to the openSCADA library (org.openscada.opc.lib.da.Server) to activate the NTLMv2 and Session Security of the JISession. I made a small project based on the Utgard Tutorial with a runtime of one hour (i took the example which writes values). It starts without problems and writes values to the PLC.

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

The first exception occures while a ping some minutes ago:

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. 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?

I posted the same topic at the sourcefoge discussion page on j-interop but they referred on your project, so hopefully somebody can help me on this issue!

Responses are much appreciated!

Kind regards,
Florian

Jens Reimann

unread,
Apr 7, 2014, 10:37:10 AM4/7/14
to open...@googlegroups.com

Hi,

This looks rather strange.

Can you reconnect after the connection broke?

What Windows and Java version are you using?

Jens

...

fpatd...@googlemail.com

unread,
Apr 9, 2014, 10:06:25 AM4/9/14
to open...@googlegroups.com
Hi Jens,

We are using Java 6 Update 20 on a Windows Server 2008 R2 SP1 machine.
After the "Received fault" the items are still getting refreshed until the unexpected exception occurs.
With j-interop 3.0 we have no problems. What can you say about the compatibility of utgart to that version?
Unfortanetly we can't test without NTLMv2 because the security refuses a NTLMv1 login.

Kind regards,
Florian


Am Montag, 7. April 2014 13:23:10 UTC+2 schrieb fpatd...@googlemail.com:
Hi,

we are using the openSCADA utgard library to communicate with an OPC sever via DCOM. A patch has been applied to the openSCADA library (org.openscada.opc.lib.da.Server) to activate the NTLMv2 and Session Security of the JISession. I made a small project based on the Utgard Tutorial with a runtime of one hour (i took the example which writes values). It starts without problems and writes values to the PLC.

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

The first exception occures while a ping some minutes ago:

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]<span style="color: #000;" class="styled
...
Reply all
Reply to author
Forward
0 new messages