plc4x icon indicating copy to clipboard operation
plc4x copied to clipboard
verified publisher icon apache

[Bug]: Unable to connect to PLC

Open pquiring opened this issue 1 year ago • 4 comments

What happened?

PlcConnection plcConn = PlcDriverManager.getDefault().getConnectionManager().getConnection("s7://10.48.61.20);

Method never returns. Using WireShark I can see TCP connection was established but no data is transmitted. Not sure why some output is not in english.

OS : Windows Server 2022 Java : 17 Netty : 4.1.63 (last one that included -all build -- alternative is to include 40+ deps - foobar!)

Here is log output: [2025/01/06 13:58:48] Instantiating new PLC Driver Manager with class loader {} [2025/01/06 13:58:48] Registering available drivers... [2025/01/06 13:58:48] Registering driver for Protocol {} ({}) [2025/01/06 13:58:48] Using SLF4J as the default logging framework [2025/01/06 13:58:48] Platform: Windows [2025/01/06 13:58:48] -Dio.netty.noUnsafe: {} [2025/01/06 13:58:48] sun.misc.Unsafe: unavailable (io.netty.noUnsafe) [2025/01/06 13:58:48] Java version: {} [2025/01/06 13:58:48] java.nio.DirectByteBuffer.(long, int): {} [2025/01/06 13:58:48] maxDirectMemory: {} bytes (maybe) [2025/01/06 13:58:48] -Dio.netty.tmpdir: {} (java.io.tmpdir) [2025/01/06 13:58:48] -Dio.netty.bitMode: {} (sun.arch.data.model) [2025/01/06 13:58:48] -Dio.netty.maxDirectMemory: {} bytes [2025/01/06 13:58:48] -Dio.netty.uninitializedArrayAllocationThreshold: {} [2025/01/06 13:58:48] java.nio.ByteBuffer.cleaner(): unavailable [2025/01/06 13:58:48] java.lang.UnsupportedOperationException: sun.misc.Unsafe unavailable at io.netty.util.internal.CleanerJava9.(CleanerJava9.java:68) at io.netty.util.internal.PlatformDependent.(PlatformDependent.java:193) at io.netty.util.ConstantPool.(ConstantPool.java:32) at io.netty.util.AttributeKey$1.(AttributeKey.java:27) at io.netty.util.AttributeKey.(AttributeKey.java:27) at org.apache.plc4x.java.s7.readwrite.protocol.S7HMuxImpl.(S7HMuxImpl.java:61) at org.apache.plc4x.java.s7.readwrite.protocol.S7HPlcConnection.(S7HPlcConnection.java:117) at org.apache.plc4x.java.s7.readwrite.protocol.S7HGeneratedDriverBase.getConnection(S7HGeneratedDriverBase.java:162) at org.apache.plc4x.java.DefaultPlcDriverManager.getConnection(DefaultPlcDriverManager.java:79) at javaforce.controls.Controller.connect(Controller.java:101) at javaforce.controls.ReadTag.main(ReadTag.java:21)

[2025/01/06 13:58:48] -Dio.netty.noPreferDirect: {} [2025/01/06 13:58:48] -Dio.netty.threadLocalMap.stringBuilder.initialSize: {} [2025/01/06 13:58:48] -Dio.netty.threadLocalMap.stringBuilder.maxSize: {} [2025/01/06 13:58:48] -D{}: {} [2025/01/06 13:58:48] -D{}: {} [2025/01/06 13:58:48] -Dio.netty.allocator.numHeapArenas: {} [2025/01/06 13:58:48] -Dio.netty.allocator.numDirectArenas: {} [2025/01/06 13:58:48] -Dio.netty.allocator.pageSize: {} [2025/01/06 13:58:48] -Dio.netty.allocator.maxOrder: {} [2025/01/06 13:58:48] -Dio.netty.allocator.chunkSize: {} [2025/01/06 13:58:48] -Dio.netty.allocator.smallCacheSize: {} [2025/01/06 13:58:48] -Dio.netty.allocator.normalCacheSize: {} [2025/01/06 13:58:48] -Dio.netty.allocator.maxCachedBufferCapacity: {} [2025/01/06 13:58:48] -Dio.netty.allocator.cacheTrimInterval: {} [2025/01/06 13:58:48] -Dio.netty.allocator.cacheTrimIntervalMillis: {} [2025/01/06 13:58:48] -Dio.netty.allocator.useCacheForAllThreads: {} [2025/01/06 13:58:48] -Dio.netty.allocator.maxCachedByteBuffersPerChunk: {} [2025/01/06 13:58:48] -Dio.netty.allocator.type: {} [2025/01/06 13:58:48] -Dio.netty.threadLocalDirectBufferSize: {} [2025/01/06 13:58:48] -Dio.netty.maxThreadLocalCharBufferSize: {} [2025/01/06 13:58:48] -Dio.netty.eventLoopThreads: {} [2025/01/06 13:58:48] -Dio.netty.noKeySetOptimization: {} [2025/01/06 13:58:48] -Dio.netty.selectorAutoRebuildThreshold: {} [2025/01/06 13:58:48] org.jctools-core.MpscChunkedArrayQueue: unavailable [2025/01/06 13:58:49] failed to instrument a special java.util.Set into: {} [2025/01/06 13:58:49] failed to instrument a special java.util.Set into: {} [2025/01/06 13:58:49] failed to instrument a special java.util.Set into: {} [2025/01/06 13:58:49] failed to instrument a special java.util.Set into: {} [2025/01/06 13:58:49] failed to instrument a special java.util.Set into: {} [2025/01/06 13:58:49] failed to instrument a special java.util.Set into: {} [2025/01/06 13:58:49] failed to instrument a special java.util.Set into: {} [2025/01/06 13:58:49] failed to instrument a special java.util.Set into: {} [2025/01/06 13:58:49] Configuring Bootstrap with {} [2025/01/06 13:58:49] -Dio.netty.processId: {} (auto-detected) [2025/01/06 13:58:49] -Djava.net.preferIPv4Stack: {} [2025/01/06 13:58:49] -Djava.net.preferIPv6Addresses: {} [2025/01/06 13:58:49] Loopback interface: {} ({}, {}) [2025/01/06 13:58:49] Failed to get SOMAXCONN from sysctl and file {}. Default: {} [2025/01/06 13:58:49] -Dio.netty.machineId: {} (auto-detected) [2025/01/06 13:58:49] [id: 0x53770bd9] REGISTERED [2025/01/06 13:58:49] [id: 0x53770bd9] CONNECT: /10.48.61.20:102 [2025/01/06 13:58:49] [id: 0x53770bd9, L:/10.48.61.10:49339 - R:/10.48.61.20:102] ACTIVE [2025/01/06 13:58:49] Channel was created, firing ChannelCreated Event [2025/01/06 13:58:49] [id: 0xembedded, L:embedded - R:embedded] USER_EVENT: org.apache.plc4x.java.spi.events.ConnectEvent@9f116cc [2025/01/06 13:58:49] Loaded default ResourceLeakDetector: {} [2025/01/06 13:58:49] User Event triggered {} [2025/01/06 13:58:49] S7 Driver running in ACTIVE mode. [2025/01/06 13:58:49] Sending COTP Connection Request [2025/01/06 13:58:49] Nombre tuberias: Multiplexor [2025/01/06 13:58:49] Nombre tuberias: LoggingHandler#0 [2025/01/06 13:58:49] Nombre tuberias: DefaultNettyPlcConnection$1$1#0 [2025/01/06 13:58:49] Nombre tuberias: DefaultNettyPlcConnection$1$2#0 [2025/01/06 13:58:49] Nombre tuberias: CODEC [2025/01/06 13:58:49] Nombre tuberias: EventListenerMessageCodec#0 [2025/01/06 13:58:49] Nombre tuberias: WRAPPER [2025/01/06 13:58:49] Nombre tuberias: DefaultChannelPipeline$TailContext#0 [2025/01/06 13:58:49] 13:58:49.182366800 userEventTriggered: Multiplexor Event: org.apache.plc4x.java.spi.events.ConnectEvent@9f116cc [2025/01/06 13:58:50] ************************************************* INSTAMCIA PRIMARIO : [id: 0x53770bd9, L:/10.48.61.10:49339 - R:/10.48.61.20:102] ACTIVO PRIMARIO : true INSTAMCIA SECUNDARIO : NULL ACTIVO SECUNDARIO : NULL CANAL CONECTADO? : false CANAL ESTUVO CONECTADO? : false CONTADORES : 0 : 0

[2025/01/06 13:58:51] ************************************************* INSTAMCIA PRIMARIO : [id: 0x53770bd9, L:/10.48.61.10:49339 - R:/10.48.61.20:102] ACTIVO PRIMARIO : true INSTAMCIA SECUNDARIO : NULL ACTIVO SECUNDARIO : NULL CANAL CONECTADO? : false CANAL ESTUVO CONECTADO? : false CONTADORES : 0 : 0

[2025/01/06 13:58:52] ************************************************* INSTAMCIA PRIMARIO : [id: 0x53770bd9, L:/10.48.61.10:49339 - R:/10.48.61.20:102] ACTIVO PRIMARIO : true INSTAMCIA SECUNDARIO : NULL ACTIVO SECUNDARIO : NULL CANAL CONECTADO? : false CANAL ESTUVO CONECTADO? : false CONTADORES : 0 : 0

That last message just repeats...

Version

v0.12.0

Programming Languages

  • [X] plc4j
  • [ ] plc4go
  • [ ] plc4c
  • [ ] plc4net

Protocols

  • [ ] AB-Ethernet
  • [ ] ADS /AMS
  • [ ] BACnet/IP
  • [ ] CANopen
  • [ ] DeltaV
  • [ ] DF1
  • [ ] EtherNet/IP
  • [ ] Firmata
  • [ ] KNXnet/IP
  • [ ] Modbus
  • [ ] OPC-UA
  • [X] S7

pquiring avatar Jan 06 '25 19:01 pquiring

Tried with Netty/4.1.116.Final (modules:-common,-buffer,-transport,-handler,-codec) and get different results. Now the connection fails and returns immediately.

Log output: [2025/01/09 10:06:25] Instantiating new PLC Driver Manager with class loader {} [2025/01/09 10:06:25] Registering available drivers... [2025/01/09 10:06:25] Registering driver for Protocol {} ({}) [2025/01/09 10:06:25] Using SLF4J as the default logging framework [2025/01/09 10:06:25] -Dio.netty.noUnsafe: {} [2025/01/09 10:06:25] sun.misc.Unsafe: unavailable (io.netty.noUnsafe) [2025/01/09 10:06:25] Java version: {} [2025/01/09 10:06:25] java.nio.DirectByteBuffer.(long, {int,long}): {} [2025/01/09 10:06:25] maxDirectMemory: {} bytes (maybe) [2025/01/09 10:06:25] -Dio.netty.tmpdir: {} (java.io.tmpdir) [2025/01/09 10:06:25] -Dio.netty.bitMode: {} (sun.arch.data.model) [2025/01/09 10:06:25] Platform: Windows [2025/01/09 10:06:25] -Dio.netty.maxDirectMemory: {} bytes [2025/01/09 10:06:25] -Dio.netty.uninitializedArrayAllocationThreshold: {} [2025/01/09 10:06:25] java.nio.ByteBuffer.cleaner(): unavailable [2025/01/09 10:06:25] java.lang.UnsupportedOperationException: sun.misc.Unsafe unavailable at io.netty.util.internal.CleanerJava9.(CleanerJava9.java:68) at io.netty.util.internal.PlatformDependent.(PlatformDependent.java:195) at io.netty.util.ConstantPool.(ConstantPool.java:34) at io.netty.util.AttributeKey$1.(AttributeKey.java:27) at io.netty.util.AttributeKey.(AttributeKey.java:27) at org.apache.plc4x.java.s7.readwrite.protocol.S7HMuxImpl.(S7HMuxImpl.java:61) at org.apache.plc4x.java.s7.readwrite.protocol.S7HPlcConnection.(S7HPlcConnection.java:117) at org.apache.plc4x.java.s7.readwrite.protocol.S7HGeneratedDriverBase.getConnection(S7HGeneratedDriverBase.java:162) at org.apache.plc4x.java.DefaultPlcDriverManager.getConnection(DefaultPlcDriverManager.java:79) at javaforce.controls.Controller.connect(Controller.java:101) at javaforce.controls.ReadTag.main(ReadTag.java:21)

[2025/01/09 10:06:25] -Dio.netty.noPreferDirect: {} [2025/01/09 10:06:25] -Dio.netty.threadLocalMap.stringBuilder.initialSize: {} [2025/01/09 10:06:25] -Dio.netty.threadLocalMap.stringBuilder.maxSize: {} [2025/01/09 10:06:25] -D{}: {} [2025/01/09 10:06:25] -D{}: {} [2025/01/09 10:06:25] -Dio.netty.allocator.numHeapArenas: {} [2025/01/09 10:06:25] -Dio.netty.allocator.numDirectArenas: {} [2025/01/09 10:06:25] -Dio.netty.allocator.pageSize: {} [2025/01/09 10:06:25] -Dio.netty.allocator.maxOrder: {} [2025/01/09 10:06:25] -Dio.netty.allocator.chunkSize: {} [2025/01/09 10:06:25] -Dio.netty.allocator.smallCacheSize: {} [2025/01/09 10:06:25] -Dio.netty.allocator.normalCacheSize: {} [2025/01/09 10:06:25] -Dio.netty.allocator.maxCachedBufferCapacity: {} [2025/01/09 10:06:25] -Dio.netty.allocator.cacheTrimInterval: {} [2025/01/09 10:06:25] -Dio.netty.allocator.cacheTrimIntervalMillis: {} [2025/01/09 10:06:25] -Dio.netty.allocator.useCacheForAllThreads: {} [2025/01/09 10:06:25] -Dio.netty.allocator.maxCachedByteBuffersPerChunk: {} [2025/01/09 10:06:25] -Dio.netty.allocator.disableCacheFinalizersForFastThreadLocalThreads: {} [2025/01/09 10:06:25] -Dio.netty.allocator.type: {} [2025/01/09 10:06:25] -Dio.netty.threadLocalDirectBufferSize: {} [2025/01/09 10:06:25] -Dio.netty.maxThreadLocalCharBufferSize: {} [2025/01/09 10:06:25] -Dio.netty.eventLoopThreads: {} [2025/01/09 10:06:25] -Dio.netty.globalEventExecutor.quietPeriodSeconds: {} [2025/01/09 10:06:25] -Dio.netty.noKeySetOptimization: {} [2025/01/09 10:06:25] -Dio.netty.selectorAutoRebuildThreshold: {} [2025/01/09 10:06:25] org.jctools-core.MpscChunkedArrayQueue: unavailable [2025/01/09 10:06:25] failed to instrument a special java.util.Set into: {} [2025/01/09 10:06:25] failed to instrument a special java.util.Set into: {} [2025/01/09 10:06:25] failed to instrument a special java.util.Set into: {} [2025/01/09 10:06:25] failed to instrument a special java.util.Set into: {} [2025/01/09 10:06:25] failed to instrument a special java.util.Set into: {} [2025/01/09 10:06:25] failed to instrument a special java.util.Set into: {} [2025/01/09 10:06:25] failed to instrument a special java.util.Set into: {} [2025/01/09 10:06:25] failed to instrument a special java.util.Set into: {} [2025/01/09 10:06:25] Configuring Bootstrap with {} [2025/01/09 10:06:25] -Dio.netty.processId: {} (auto-detected) [2025/01/09 10:06:25] -Djava.net.preferIPv4Stack: {} [2025/01/09 10:06:25] -Djava.net.preferIPv6Addresses: {} [2025/01/09 10:06:25] Loopback interface: {} ({}, {}) [2025/01/09 10:06:25] Failed to get SOMAXCONN from sysctl and file {}. Default: {} [2025/01/09 10:06:25] -Dio.netty.machineId: {} (auto-detected) [2025/01/09 10:06:25] -Dio.netty.bootstrap.extensions: {} [2025/01/09 10:06:25] [id: 0xa94284d6] CLOSE [2025/01/09 10:06:25] Unable to connect, shutting down worker thread. [2025/01/09 10:06:25] org.apache.plc4x.java.api.exceptions.PlcConnectionException: Error creating channel. [2025/01/09 10:06:25] [id: 0xa94284d6] REGISTERED [2025/01/09 10:06:25] Channels was not created, firing DisconnectEvent Event [2025/01/09 10:06:25] [id: 0xa94284d6] UNREGISTERED [2025/01/09 10:06:25] [id: 0xembedded, L:embedded - R:embedded] USER_EVENT: org.apache.plc4x.java.spi.events.DisconnectEvent@293a5bf6 [2025/01/09 10:06:25] 10:06:25.549068600 userEventTriggered: Multiplexor Event: org.apache.plc4x.java.spi.events.DisconnectEvent@293a5bf6 [2025/01/09 10:06:25] DisconnectEvent [2025/01/09 10:06:25] org.apache.plc4x.java.api.exceptions.PlcConnectionException: Connection is not possible. at org.apache.plc4x.java.s7.readwrite.protocol.S7HPlcConnection.connect(S7HPlcConnection.java:171) at org.apache.plc4x.java.DefaultPlcDriverManager.getConnection(DefaultPlcDriverManager.java:80) at javaforce.controls.Controller.connect(Controller.java:101) at javaforce.controls.ReadTag.main(ReadTag.java:21)

pquiring avatar Jan 09 '25 15:01 pquiring

Hi,

Please use version 0.13.0-SNAPSHOT, if you use a single CPU it should solve your problem.

I'll be looking forward to your comments,

glcj avatar Jan 09 '25 15:01 glcj

I use the maven artifacts so I can wait until 0.13 is released. Trying to debug as well in the mean time.

Thanks,

pquiring avatar Jan 09 '25 20:01 pquiring

The problem with that approach is that we can't 100% guarantee that it's fixed in 0.13.0. If you test it now, we have a chance of fixing it for the next release. Otherwise it will be a while till the next one. Snapshots are also available as maven artifacts. All you need to do is add the apache snapshot repo to your pom.

chrisdutz avatar Jan 10 '25 07:01 chrisdutz