gustavoschewinski commented on issue #125:
URL: https://github.com/apache/plc4x-extras/issues/125#issuecomment-2338528054
Hello @chrisdutz,
I’ve found some additional logs that may be useful, but I still haven’t
identified the root cause of the problem.
As you can see, a request is made and a channel is successfully created:
```
[2024-09-09 15:56:00,606] DEBUG reading field maxRequestMessageSize
(org.apache.plc4x.java.spi.codegen.fields.FieldReaderSimple)
[2024-09-09 15:56:00,606] DEBUG Sending activate session request to
opc.tcp://Yoshi:53530/OPCUA/SimulationServer
(org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] TRACE Using Endpoint Yoshi.mshome.net 53530
/OPCUA/SimulationServer (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,607] DEBUG Submitting Transaction to TransactionManager
3, security channel 7, token 1
(org.apache.plc4x.java.opcua.context.Conversation)
[2024-09-09 15:56:00,607] DEBUG write field receiveBufferSize
(org.apache.plc4x.java.spi.codegen.fields.FieldWriterSimple)
[2024-09-09 15:56:00,607] TRACE Overflow by 15 chars
(org.apache.plc4x.java.spi.utils.ascii.AsciiBoxWriter)
```
However, after a lot of logging, the connection is established but no data
is received. Eventually, it times out:
```
[2024-09-09 15:56:00,632] DEBUG done reading field results
(org.apache.plc4x.java.spi.codegen.fields.FieldReaderArray)
[2024-09-09 15:56:00,632] DEBUG reading field noOfDiagnosticInfos
(org.apache.plc4x.java.spi.codegen.fields.FieldReaderSimple)
[2024-09-09 15:56:00,632] DEBUG reading field diagnosticInfos. Count: -1
(org.apache.plc4x.java.spi.codegen.fields.FieldReaderArray)
[2024-09-09 15:56:00,632] DEBUG done reading field diagnosticInfos
(org.apache.plc4x.java.spi.codegen.fields.FieldReaderArray)
[2024-09-09 15:56:00,632] DEBUG Scheduling session keep alive to happen
within 2700s (org.apache.plc4x.java.opcua.context.SecureChannel)
[2024-09-09 15:56:00,632] INFO Established connection to server
(org.apache.plc4x.java.opcua.protocol.OpcuaProtocolLogic)
[2024-09-09 15:56:00,632] TRACE Firing Connected!
(org.apache.plc4x.java.spi.internal.DefaultConversationContext)
[2024-09-09 15:56:01,019] DEBUG Job statistics (jobA, machineA) number of
requests: 2 (0 success, 100.0 % failed, NaN % too slow), min latency: NaN ms,
mean latency: NaN ms, median: NaN ms
(org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperImpl)
[2024-09-09 15:56:01,117] DEBUG
Job=org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScrapeJobImpl@60290d60
Task=TriggeredScraperTask{connectionManager=org.apache.plc4x.java.utils.cache.CachedPlcConnectionManager@55f4dc44,
jobName='jobA', connectionAlias='machineA',
connectionString='opcua:tcp://Yoshi:53530/OPCUA/SimulationServer?discovery=false',
requestTimeoutMs=2000,
executorService=java.util.concurrent.ThreadPoolExecutor@4e3f133f[Running, pool
size = 2, active threads = 1, queued tasks = 0, completed tasks = 1],
resultHandler=org.apache.plc4x.kafka.Plc4xSourceTask$$Lambda$1172/0x0000000101f9a440@3f54d16d,
triggerHandler=org.apache.plc4x.java.scraper.triggeredscraper.triggerhandler.TriggerHandlerImpl@13ccf5a1}
(org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperImpl)
[2024-09-09 15:56:01,118] DEBUG
Task=TriggeredScraperTask{connectionManager=org.apache.plc4x.java.utils.cache.CachedPlcConnectionManager@55f4dc44,
jobName='jobA', connectionAlias='machineA',
connectionString='opcua:tcp://Yoshi:53530/OPCUA/SimulationServer?discovery=false',
requestTimeoutMs=2000,
executorService=java.util.concurrent.ThreadPoolExecutor@4e3f133f[Running, pool
size = 2, active threads = 1, queued tasks = 0, completed tasks = 1],
resultHandler=org.apache.plc4x.kafka.Plc4xSourceTask$$Lambda$1172/0x0000000101f9a440@3f54d16d,
triggerHandler=org.apache.plc4x.java.scraper.triggeredscraper.triggerhandler.TriggerHandlerImpl@13ccf5a1}
Future=java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@4e65db69[Not
completed, task =
java.util.concurrent.Executors$RunnableAdapter@40a22d0d[Wrapped task =
TriggeredScraperTask{connectionManager=org.apache.plc4x.java.utils.cache.CachedPlcConnectionManager@55f4dc44,
jobName='jobA', connectionAlias='machineA', connectionString
='opcua:tcp://Yoshi:53530/OPCUA/SimulationServer?discovery=false',
requestTimeoutMs=2000,
executorService=java.util.concurrent.ThreadPoolExecutor@4e3f133f[Running, pool
size = 2, active threads = 1, queued tasks = 0, completed tasks = 1],
resultHandler=org.apache.plc4x.kafka.Plc4xSourceTask$$Lambda$1172/0x0000000101f9a440@3f54d16d,
triggerHandler=org.apache.plc4x.java.scraper.triggeredscraper.triggerhandler.TriggerHandlerImpl@13ccf5a1}]]
(org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperImpl)
[2024-09-09 15:56:02,018] DEBUG Job statistics (jobA, machineA) number of
requests: 2 (0 success, 100.0 % failed, NaN % too slow), min latency: NaN ms,
mean latency: NaN ms, median: NaN ms
(org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperImpl)
[2024-09-09 15:56:02,050] TRACE Additional Info from caller acquiring data
collecting connection to (machineA,jobA)
(org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperImpl)
java.util.concurrent.ExecutionException:
java.util.concurrent.TimeoutException
at
java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395)
at
java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2005)
at
org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperImpl.getPlcConnection(TriggeredScraperImpl.java:330)
at
org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperTask.run(TriggeredScraperTask.java:112)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at
java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.util.concurrent.TimeoutException
at
java.base/java.util.concurrent.CompletableFuture$Timeout.run(CompletableFuture.java:2798)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
... 3 more
[2024-09-09 15:56:02,053] WARN Exception during scraping of Job jobA,
Connection-Alias machineA: Error-message: java.util.concurrent.TimeoutException
- for stack-trace change logging to DEBUG
(org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperTask)
[2024-09-09 15:56:02,053] DEBUG Detailed exception occurred at scraping
(org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperTask)
org.apache.plc4x.java.api.exceptions.PlcRuntimeException:
java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException
at
org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperImpl.getPlcConnection(TriggeredScraperImpl.java:334)
at
org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperTask.run(TriggeredScraperTask.java:112)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at
java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.util.concurrent.ExecutionException:
java.util.concurrent.TimeoutException
at
java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395)
at
java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2005)
at
org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperImpl.getPlcConnection(TriggeredScraperImpl.java:330)
... 7 more
Caused by: java.util.concurrent.TimeoutException
at
java.base/java.util.concurrent.CompletableFuture$Timeout.run(CompletableFuture.java:2798)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
... 3 more
[2024-09-09 15:56:02,054] TRACE Check condition for task of job jobA for
connection machineA
(org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperTask)
[2024-09-09 15:56:02,054] DEBUG Trigger for job jobA and device machineA is
met ... scraping desired data
(org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperTask)
[2024-09-09 15:56:02,054] TRACE Start new scrape of task of job jobA for
connection machineA
(org.apache.plc4x.java.scraper.triggeredscraper.TriggeredScraperTask)
```
Do you think this issue could be related to an update, or is there something
else I might be overlooking? If you have any suggestions, just let me know :)
Thanks!
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
