[Bug][OPC-UA]: Connection fault after a while of inactivity
isAlreadyInUse opened this issue · 23 comments
What happened?
I connect to Ignition OPC UA, and I'm able to read data, tested with 18.000 reads each 500ms works fine.
but if connection not interact with server for a while (2/3 min), on next read I receive following error :
2023-11-17T14:58:32.253+01:00 ERROR 2742 --- [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Read request ended up with ServiceFault:
╔═ExtensionObjectDefinition/ResponseHeader══════════════════════════════════════════════════════════════════════════╗
║╔═timestamp═══════════════════════════╗╔═requestHandle╗╔═serviceResult/StatusCode/statusCode═╗ ║
║║0x01da195e260fc980 133447031117040000║║0x0000000a 10 ║║ 0x80250000 2149908480 ║ ║
║╚═════════════════════════════════════╝╚══════════════╝╚═════════════════════════════════════╝ ║
║╔═serviceDiagnostics/DiagnosticInfo═════════════════════════════════════════════════════════════╗╔═noOfStringTable╗║
║║╔═reserved╗╔═innerDiagnosticInfoSpecified╗╔═innerStatusCodeSpecified╗╔═additionalInfoSpecified╗║║ 0xffffffff -1 ║║
║║║b0 false ║║ b0 false ║║ b0 false ║║ b0 false ║║╚════════════════╝║
║║╚═════════╝╚═════════════════════════════╝╚═════════════════════════╝╚════════════════════════╝║ ║
║║╔═localeSpecified╗╔═localizedTextSpecified╗╔═namespaceURISpecified╗╔═symbolicIdSpecified╗ ║ ║
║║║ b0 false ║║ b0 false ║║ b0 false ║║ b0 false ║ ║ ║
║║╚════════════════╝╚═══════════════════════╝╚══════════════════════╝╚════════════════════╝ ║ ║
║╚═══════════════════════════════════════════════════════════════════════════════════════════════╝ ║
║╔═additionalHeader/ExtensionObject══════════════════════════════════════════════════════════════════╗ ║
║║╔═typeId/ExpandedNodeId═══════════════════════════════════════════════════════════════════════════╗║ ║
║║║╔═namespaceURISpecified╗╔═serverIndexSpecified╗╔═nodeId/NodeIdTypeDefinition════════════════════╗║║ ║
║║║║ b0 false ║║ b0 false ║║╔═nodeType/NodeIdType═══╗╔═NodeIdTwoByte═══════╗║║║ ║
║║║╚══════════════════════╝╚═════════════════════╝║║0x0 0 nodeIdTypeTwoByte║║╔═id═══╗╭┄identifier╮║║║║ ║
║║║ ║╚═══════════════════════╝║║0x00 0║┆ 0 ┆║║║║ ║
║║║ ║ ║╚══════╝╰┄┄┄┄┄┄┄┄┄┄┄╯║║║║ ║
║║║ ║ ╚═════════════════════╝║║║ ║
║║║ ╚════════════════════════════════════════════════╝║║ ║
║║║╭┄identifier╮ ║║ ║
║║║┆ 0 ┆ ║║ ║
║║║╰┄┄┄┄┄┄┄┄┄┄┄╯ ║║ ║
║║╚═════════════════════════════════════════════════════════════════════════════════════════════════╝║ ║
║║╔═encodingMask/ExtensionObjectEncodingMask═══════════╗╭┄identifier╮ ║ ║
║║║╔═reserved╗╔═typeIdSpecified╗╔═xmlbody╗╔═binaryBody╗║┆ 0 ┆ ║ ║
║║║║ 0x0 0 ║║ b0 false ║║b0 false║║ b0 false ║║╰┄┄┄┄┄┄┄┄┄┄┄╯ ║ ║
║║║╚═════════╝╚════════════════╝╚════════╝╚═══════════╝║ ║ ║
║║╚════════════════════════════════════════════════════╝ ║ ║
║╚═══════════════════════════════════════════════════════════════════════════════════════════════════╝ ║
Reopening connection immediately and read same data works.
Version
v0.11.0
Programming Languages
- plc4j
- plc4go
- plc4c
- plc4net
Protocols
- AB-Ethernet
- ADS /AMS
- BACnet/IP
- CANopen
- DeltaV
- DF1
- EtherNet/IP
- Firmata
- KNXnet/IP
- Modbus
- OPC-UA
- S7
Sure I will test!
using snapshot
i get org.apache.plc4x.java.api.exceptions.PlcConnectionException: Unsupported transport tcp
when try to connect
ConnectionString="opcua:tcp://192.168.1.1:62541?discovery=false"
Strange, I believe dependency trees are same for 0.11 and 0.12. Can you add explicit dependency to plc4j-transport-tcp in your project?
Strange, I believe dependency trees are same for 0.11 and 0.12. Can you add explicit dependency to
plc4j-transport-tcpin your project?
Just have a time to verify this with 0.12.0-SNAPSHOT. Confirm initial problem and yes, adding plc4j-transport-tcp explicitly cures that problem. Thanks.
Tried, and again same
╔═ExtensionObjectDefinition/ResponseHeader══════════════════════════════════════════════════════════════════════════╗
║╔═timestamp═══════════════════════════╗╔═requestHandle╗╔═serviceResult/StatusCode/statusCode═╗ ║
║║0x01da2e9166f1b6c6 133470340993103558║║ 0x00000004 4 ║║ 0x80250000 2149908480 ║ ║
║╚═════════════════════════════════════╝╚══════════════╝╚═════════════════════════════════════╝ ║
║╔═serviceDiagnostics/DiagnosticInfo═════════════════════════════════════════════════════════════╗╔═noOfStringTable╗║
║║╔═reserved╗╔═innerDiagnosticInfoSpecified╗╔═innerStatusCodeSpecified╗╔═additionalInfoSpecified╗║║ 0x00000000 0 ║║
║║║b0 false ║║ b0 false ║║ b0 false ║║ b0 false ║║╚════════════════╝║
║║╚═════════╝╚═════════════════════════════╝╚═════════════════════════╝╚════════════════════════╝║ ║
║║╔═localeSpecified╗╔═localizedTextSpecified╗╔═namespaceURISpecified╗╔═symbolicIdSpecified╗ ║ ║
║║║ b0 false ║║ b0 false ║║ b0 false ║║ b0 false ║ ║ ║
║║╚════════════════╝╚═══════════════════════╝╚══════════════════════╝╚════════════════════╝ ║ ║
║╚═══════════════════════════════════════════════════════════════════════════════════════════════╝ ║
║╔═additionalHeader/ExtensionObject══════════════════════════════════════════════════════════════════╗ ║
║║╔═typeId/ExpandedNodeId═══════════════════════════════════════════════════════════════════════════╗║ ║
║║║╔═namespaceURISpecified╗╔═serverIndexSpecified╗╔═nodeId/NodeIdTypeDefinition════════════════════╗║║ ║
║║║║ b0 false ║║ b0 false ║║╔═nodeType/NodeIdType═══╗╔═NodeIdTwoByte═══════╗║║║ ║
║║║╚══════════════════════╝╚═════════════════════╝║║0x0 0 nodeIdTypeTwoByte║║╔═id═══╗╭┄identifier╮║║║║ ║
║║║ ║╚═══════════════════════╝║║0x00 0║┆ 0 ┆║║║║ ║
║║║ ║ ║╚══════╝╰┄┄┄┄┄┄┄┄┄┄┄╯║║║║ ║
║║║ ║ ╚═════════════════════╝║║║ ║
║║║ ╚════════════════════════════════════════════════╝║║ ║
║║║╭┄identifier╮ ║║ ║
║║║┆ 0 ┆ ║║ ║
║║║╰┄┄┄┄┄┄┄┄┄┄┄╯ ║║ ║
║║╚═════════════════════════════════════════════════════════════════════════════════════════════════╝║ ║
║║╔═encodingMask/ExtensionObjectEncodingMask═══════════╗╭┄identifier╮ ║ ║
║║║╔═reserved╗╔═typeIdSpecified╗╔═xmlbody╗╔═binaryBody╗║┆ 0 ┆ ║ ║
║║║║ 0x0 0 ║║ b0 false ║║b0 false║║ b0 false ║║╰┄┄┄┄┄┄┄┄┄┄┄╯ ║ ║
║║║╚═════════╝╚════════════════╝╚════════╝╚═══════════╝║ ║ ║
║║╚════════════════════════════════════════════════════╝ ║ ║
║╚═══════════════════════════════════════════════════════════════════════════════════════════════════╝ ║
╚═══════════════════════════════════════════════════════════════════════════════════════════════════════════════════╝
We are facing the same issue with a subscription connection if the connection does not receive changed tags on a short time interval.
Are you using 0.12.0-SNAPSHOT or one of the last released versions? I'm asking, because a lot has changed since the last release.
We are still on release 0.11.0
Using snapshot today I receive this exception, some days ago same code with snapshot worked
java.lang.NullPointerException: cls
at java.base/java.util.Objects.requireNonNull(Objects.java:360)
at org.apache.commons.lang3.Validate.notNull(Validate.java:224)
at org.apache.commons.lang3.reflect.FieldUtils.getAllFieldsList(FieldUtils.java:216)
at org.apache.commons.lang3.reflect.FieldUtils.getAllFields(FieldUtils.java:201)
at org.apache.plc4x.java.spi.configuration.ConfigurationFactory.createConfiguration(ConfigurationFactory.java:85)
at org.apache.plc4x.java.spi.configuration.ConfigurationFactory.createTransportConfiguration(ConfigurationFactory.java:78)
at org.apache.plc4x.java.spi.connection.GeneratedDriverBase.getConnection(GeneratedDriverBase.java:350)
at org.apache.plc4x.java.spi.connection.GeneratedDriverBase.getConnection(GeneratedDriverBase.java:293)
at org.apache.plc4x.java.DefaultPlcDriverManager.getConnection(DefaultPlcDriverManager.java:79)
at com.opcua.api.opcuaapi.model.OpcConnection.initConnection(OpcConnection.java:23)
at com.opcua.api.opcuaapi.model.OpcConnection.(OpcConnection.java:16)
at com.opcua.api.opcuaapi.controller.session.InitSession.initConnection(InitSession.java:23)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
at java.base/java.lang.reflect.Method.invoke(Method.java:578)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:884)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:797)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1081)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:974)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1011)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:903)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:564)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:340)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:391)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:896)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1744)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:1589)
@chrisdutz I think that once your configuration updates got merged connection URIs have changed and what we see is probably mix of this plus new settings introduced by security PR linked earlier/. I believe this issue is pretty close to #1364
@isAlreadyInUse please update parameters to 0.12: https://plc4x.apache.org/users/protocols/opcua.html
Well ... guess if It's anything going wrong, we'll have to wait for a 0.12.1 or 0.13.0 for fixing it ... I'm literally doing the release right now.
Unfortunately, the issue is not resolved in release 0.12.0
I made a round of tests and it seems that we loose a state of pending acknowledgements which leads server to stop subscription after a while. For my test lab it happens within couple minutes. I have to find reason why we keep loosing them.