Hi,
Thanks for the report, I may find time another day to look at this.
The problem is more than likely within the SecureChannelTransactionManager
in this block of code. I suspect what happen is that two transactions were
submitted at similar times and the first transaction hadn't finished being
sent before the next one arrived.
There should probably be some kind of lock put in to stop the additional
transactions being sent while it is still in the process of sending one.
public void submit(Consumer<Integer> onSend, Integer transactionId) {
LOGGER.info("New Transaction Submitted {}", activeTransactionId.get());
if (activeTransactionId.get() == transactionId) {
onSend.accept(transactionId);
int newTransactionId = getActiveTransactionIdentifier();
if (!queue.isEmpty()) {
Transaction t = queue.remove(newTransactionId);
if (t == null) {
LOGGER.info("Length of Queue is {}", queue.size());
LOGGER.info("Transaction ID is {}", newTransactionId);
LOGGER.info("Map is {}", queue);
throw new PlcRuntimeException("Transaction Id not
found in queued messages {}");
}
submit(t.getConsumer(), t.getTransactionId());
}
} else {
LOGGER.info("Storing out of order transaction {}", transactionId);
queue.put(transactionId, new Transaction(onSend, transactionId));
}
}
On Mon, Dec 27, 2021 at 4:06 PM wangfei (Jira) <[email protected]> wrote:
> wangfei created PLC4X-329:
> -----------------------------
>
> Summary: OPCUA Storing out of order transaction
> Key: PLC4X-329
> URL: https://issues.apache.org/jira/browse/PLC4X-329
> Project: Apache PLC4X
> Issue Type: Bug
> Components: Driver-OPC-UA
> Affects Versions: 0.9.0
> Reporter: wangfei
>
>
> The following error occurs when using opcua with multithread：
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 883
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 883
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] i.p.a.plc.client.DefaultPlcClient : Subscription
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT82]: 75,
> EventClassName:io.prong.cloud.plc.event.TestEvent.
> [ecute-thread-10] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 884
> [ecute-thread-10] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 884
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ecute-thread-10] i.p.a.plc.client.DefaultPlcClient : Read
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT122]: 1, ResponseCode:OK.
> [ecute-thread-10] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 885
> [ecute-thread-10] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 885
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ecute-thread-10] i.p.a.plc.client.DefaultPlcClient : Write
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT124]: 10, ResponseCode:OK.
> [ecute-thread-10] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 886
> [ecute-thread-10] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 886
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 887
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 887
> [ecute-thread-10] i.p.a.plc.client.DefaultPlcClient : Write
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT84]: 75, ResponseCode:OK.
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] i.p.a.plc.client.DefaultPlcClient : Subscription
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT82]: 76,
> EventClassName:io.prong.cloud.plc.event.TestEvent.
> [xecute-thread-1] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 888
> [xecute-thread-1] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 888
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [xecute-thread-1] i.p.a.plc.client.DefaultPlcClient : Read
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT122]: 0, ResponseCode:OK.
> [xecute-thread-1] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 889
> [xecute-thread-1] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 889
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 890
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 890
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [xecute-thread-1] i.p.a.plc.client.DefaultPlcClient : Write
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT124]: 10, ResponseCode:OK.
> [xecute-thread-1] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 891
> [xecute-thread-1] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 891
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [xecute-thread-1] i.p.a.plc.client.DefaultPlcClient : Write
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT84]: 76, ResponseCode:OK.
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] i.p.a.plc.client.DefaultPlcClient : Subscription
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT82]: 77,
> EventClassName:io.prong.cloud.plc.event.TestEvent.
> [xecute-thread-2] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 892
> [xecute-thread-2] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 892
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [xecute-thread-2] i.p.a.plc.client.DefaultPlcClient : Read
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT122]: 1, ResponseCode:OK.
> [xecute-thread-2] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 893
> [xecute-thread-2] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 893
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 894
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 894
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [xecute-thread-2] i.p.a.plc.client.DefaultPlcClient : Write
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT124]: 10, ResponseCode:OK.
> [xecute-thread-2] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 895
> [xecute-thread-2] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 895
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [xecute-thread-2] i.p.a.plc.client.DefaultPlcClient : Write
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT84]: 77, ResponseCode:OK.
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] i.p.a.plc.client.DefaultPlcClient : Subscription
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT82]: 78,
> EventClassName:io.prong.cloud.plc.event.TestEvent.
> [xecute-thread-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 896
> [xecute-thread-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 896
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [xecute-thread-3] i.p.a.plc.client.DefaultPlcClient : Read
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT122]: 0, ResponseCode:OK.
> [xecute-thread-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 897
> [xecute-thread-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 897
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 898
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 898
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [xecute-thread-3] i.p.a.plc.client.DefaultPlcClient : Write
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT124]: 10, ResponseCode:OK.
> [xecute-thread-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 899
> [xecute-thread-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 899
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [xecute-thread-3] i.p.a.plc.client.DefaultPlcClient : Write
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT84]: 78, ResponseCode:OK.
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] i.p.a.plc.client.DefaultPlcClient : Subscription
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT82]: 79,
> EventClassName:io.prong.cloud.plc.event.TestEvent.
> [xecute-thread-4] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 900
> [xecute-thread-4] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 900
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 901
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [xecute-thread-4] i.p.a.plc.client.DefaultPlcClient : Read
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT122]: 1, ResponseCode:OK.
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 901
> [xecute-thread-4] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 902
> [xecute-thread-4] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 901
> [xecute-thread-4] o.a.p.java.opcua.context.SecureChannel : Storing out
> of order transaction 902
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] i.p.a.plc.client.DefaultPlcClient : Subscription
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT82]: 80,
> EventClassName:io.prong.cloud.plc.event.TestEvent.
> [xecute-thread-5] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 903
> [xecute-thread-5] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 902
> [xecute-thread-5] o.a.p.java.opcua.context.SecureChannel : Storing out
> of order transaction 903
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 904
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 902
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : Storing out
> of order transaction 904
> [ntLoopGroup-5-1] o.a.p.j.o.protocol.OpcuaProtocolLogic : Decoding
> Message with Security policy None
> [ntLoopGroup-5-1] i.p.a.plc.client.DefaultPlcClient : Subscription
> Value[ns=4;s=S7:[@LOCALSERVER]DB1,INT82]: 81,
> EventClassName:io.prong.cloud.plc.event.TestEvent.
> [xecute-thread-6] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 905
> [xecute-thread-6] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 902
> [xecute-thread-6] o.a.p.java.opcua.context.SecureChannel : Storing out
> of order transaction 905
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : Submitting
> Transaction to TransactionManager 906
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : New
> Transaction Submitted 902
> [onPool-worker-3] o.a.p.java.opcua.context.SecureChannel : Storing out
> of order transaction 906
>
>
>
>
> --
> This message was sent by Atlassian Jira
> (v8.20.1#820001)
>
