You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@plc4x.apache.org by "Stefano Bossi (Jira)" <ji...@apache.org> on 2021/02/01 21:17:00 UTC
[jira] [Closed] (PLC4X-277) Double Reading Error
[ https://issues.apache.org/jira/browse/PLC4X-277?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Stefano Bossi closed PLC4X-277.
-------------------------------
Resolution: Fixed
Clone of plc4x-278
> Double Reading Error
> --------------------
>
> Key: PLC4X-277
> URL: https://issues.apache.org/jira/browse/PLC4X-277
> Project: Apache PLC4X
> Issue Type: Bug
> Components: Driver-S7
> Affects Versions: 0.8.0
> Environment: Client on Linux box:
> Linux RevPi33574 4.9.76-rt60-v7+ #1 SMP PREEMPT RT Tue, 12 Mar 2019 15:19:36 +0100 armv7l GNU/Linux
> PLC Siemens S7 1200 (CPU 1214C DC/DC/DC Firmware Version V1.0)
> Reporter: Stefano Bossi
> Priority: Major
> Attachments: trace-01-30-10-20-28-1611998428-drop01.pcap, trace-01-30-10-20-28-1611998428-drop01.png
>
>
> Dear developers,
> I think I have found the reason of some disconnection from the PLC (Siemens 1200 S7) I see on the logs of a software I am writing. Let me explain the scenario.
> The software reads a lot of data from the PLC a polling variable and a complete DataBlock I am using a Raspberry like a client an a Siemens S7 1200 PLC.
> The reading are usually fine but randomly I have an error in the logs coming from low level Driver.
> I am using 0.8.0-SNAPSHOT coming from [pool2|https://github.com/apache/plc4x/tree/feature/integrate-pool2] experimental feature.
> The error I read on the logs is:
> {code:txt}
> 2021-01-30 10:27:58 WARN CachedDriverManager - Watchdog detected a long borrowed connection, will be forcefully closed!
> 2021-01-30 10:27:58 WARN CachedDriverManager - Broken Connection was returned, although it is not borrowed, currently.
> 2021-01-30 10:27:58 ERROR DbFetcher - Time out Exception in reading DataBlock
> java.util.concurrent.TimeoutException: null
> at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1886) ~[?:?]
> at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2021) ~[?:?]
> at it.fox.chronos.plc.observers.DbFetcher.onObservableChanged(DbFetcher.java:92) [chronos-0.0.3.jar:0.0.3]
> at it.fox.chronos.plc.Poller.notifyObservers(Poller.java:177) [chronos-0.0.3.jar:0.0.3]
> at it.fox.chronos.plc.Poller.run(Poller.java:105) [chronos-0.0.3.jar:0.0.3]
> at java.lang.Thread.run(Thread.java:834) [?:?]
> 2021-01-30 10:27:58 INFO PlcDriverManager - Instantiating new PLC Driver Manager with class loader jdk.internal.loader.ClassLoaders$AppClassLoader@c77c2e
> 2021-01-30 10:27:58 WARN CachedPlcConnection - Request finished with exception. Reporting Connection as Broken
> java.util.concurrent.CancellationException: null
> at java.util.concurrent.CompletableFuture.cancel(CompletableFuture.java:2396) ~[?:?]
> at org.apache.plc4x.java.utils.connectionpool2.CachedPlcConnection.lambda$wrapWithTimeout$0(CachedPlcConnection.java:84) ~[plc4j-connection-cache-0.8.0-SNAPSHOT.jar:0.8.0-SNAPSHOT]
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
> at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
> at java.lang.Thread.run(Thread.java:834) ~[?:?]
> 2021-01-30 10:27:58 INFO PlcDriverManager - Registering available drivers...
> 2021-01-30 10:27:58 WARN CachedDriverManager - Broken Connection was returned, although it is not borrowed, currently.
> 2021-01-30 10:27:58 INFO PlcDriverManager - Registering driver for Protocol s7 (Siemens S7 (Basic))
> 2021-01-30 10:27:58 INFO TcpChannelFactory - Configuring Bootstrap with Configuration{local-rack=1, local-slot=1, remote-rack=0, remot-slot=0, pduSize=1024, maxAmqCaller=8, maxAmqCallee=8, controllerType='null'}
> 2021-01-30 10:27:58 INFO S7ProtocolLogic - S7 Driver running in ACTIVE mode.
> {code}
> At the first sight it seems that a connection became stale and the watchdog drop it but I think this is just the effect of an error on the wire.
> Here is the screenshot of the capture on the wire (I attach the capture to the ticket too).
> !trace-01-30-10-20-28-1611998428-drop01.png!
> At 2021-01-30 10:27:53.899233 there's a request for 7 variables in the DB2:
> {code:java}
> Frame 9: 157 bytes on wire (1256 bits), 157 bytes captured (1256 bits)
> Ethernet II, Src: KUNBUS_01:5e:53 (c8:3e:a7:01:5e:53), Dst: SiemensN_02:19:4c (00:1c:06:02:19:4c)
> Internet Protocol Version 4, Src: 192.168.1.190, Dst: 192.168.1.192
> Transmission Control Protocol, Src Port: 36240, Dst Port: 102, Seq: 94, Ack: 736, Len: 103
> TPKT, Version: 3, Length: 103
> ISO 8073/X.224 COTP Connection-Oriented Transport Protocol
> S7 Communication
> Header: (Job)
> Parameter: (Read Var)
> Function: Read Var (0x04)
> Item count: 7
> Item [1]: (DB 2.DBX 3238.0 INT 47)
> Item [2]: (DB 2.DBX 7348.0 BIT 1)
> Item [3]: (DB 2.DBX 24.0 DINT 1)
> Item [4]: (DB 2.DBX 7366.0 DINT 1)
> Item [5]: (DB 2.DBX 66.0 REAL 1)
> Item [6]: (DB 2.DBX 86.0 INT 5)
> Item [7]: (DB 2.DBX 74.0 REAL 1)
> {code}
> Without waiting the response, immediately after this request, there's an another request for an another variable, a single REAL again from the same DB2:
> {code:java}
> Frame 10: 85 bytes on wire (680 bits), 85 bytes captured (680 bits)
> Ethernet II, Src: KUNBUS_01:5e:53 (c8:3e:a7:01:5e:53), Dst: SiemensN_02:19:4c (00:1c:06:02:19:4c)
> Internet Protocol Version 4, Src: 192.168.1.190, Dst: 192.168.1.192
> Transmission Control Protocol, Src Port: 36240, Dst Port: 102, Seq: 197, Ack: 736, Len: 31
> TPKT, Version: 3, Length: 31
> ISO 8073/X.224 COTP Connection-Oriented Transport Protocol
> S7 Communication
> Header: (Job)
> Parameter: (Read Var)
> Function: Read Var (0x04)
> Item count: 1
> Item [1]: (DB 2.DBX 4938.0 REAL 24)
> {code}
> I think this is the root cause of the error and the real reason because the watchdog stand up and drop the connection.
> The PLC solicited by this double request send a couple of RST to the library and the connection dye.
> I have many of this disconnections, more or less one every 15 minutes. All the good request has a query and an answer, all the double request receive a RST from the PLC.
> My code perform only synchronous request in this way:
> {code:java}
> PlcReadResponse response = readRequest.execute().get(5000, TimeUnit.MILLISECONDS);
> {code}
> I think the double request came from the pool2 or the driver (sorry I am not able to understand that).
> Do you think is this a bug? Is it something fixable ?
> Regards,
> Stefano Bossi
--
This message was sent by Atlassian Jira
(v8.3.4#803005)