[PLC4X-179] Initial connection terminated from PLC

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Not A Problem
• Affects Version/s: 0.5.0
• Component/s: Driver-S7
• Environment: Windows 10, jdk1.8.0_91-win64, jdk11.0.6.10
• Assignee: Christofer Dutz
• Reporter: Florian Probst
• Created: 26/Feb/20 16:08
• Updated: 25/Jan/21 10:41
• Resolved: 25/Jan/21 10:41

Description

When trying to connect our S7-400 PLC the PLC terminates the connection after the first message sent. I tried the following URLs:

• s7://192.168.3.166/0/3
• s7://192.168.3.166/0/3?controller-type=S7_400

Here is the full log that has been logged while capturing the attached wireshark trace:

16:50:40.134 [main] INFO org.apache.plc4x.java.PlcDriverManager - Instantiating new PLC Driver Manager with class loader sun.misc.Launcher$AppClassLoader@73d16e93
16:50:40.149 [main] INFO org.apache.plc4x.java.PlcDriverManager - Registering available drivers...
16:50:40.154 [main] INFO org.apache.plc4x.java.PlcDriverManager - Registering driver for Protocol s7 (Siemens S7 (Basic))
16:50:40.171 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework
16:50:40.174 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
16:50:40.175 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
16:50:40.194 [main] DEBUG io.netty.util.internal.PlatformDependent - Platform: Windows
16:50:40.196 [main] DEBUG io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
16:50:40.196 [main] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 8
16:50:40.198 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
16:50:40.199 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
16:50:40.199 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
16:50:40.200 [main] DEBUG io.netty.util.internal.PlatformDependent0 - direct buffer constructor: available
16:50:40.201 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
16:50:40.201 [main] DEBUG io.netty.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
16:50:40.201 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): available
16:50:40.201 [main] DEBUG io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available
16:50:40.202 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: C:\Users\fp\AppData\Local\Temp (java.io.tmpdir)
16:50:40.202 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
16:50:40.203 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: 3784310784 bytes
16:50:40.203 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
16:50:40.204 [main] DEBUG io.netty.util.internal.CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
16:50:40.204 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
16:50:40.205 [main] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@136432db
16:50:40.214 [main] DEBUG io.netty.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
16:50:40.302 [main] INFO org.apache.plc4x.java.s7.connection.S7PlcConnection - Setting up S7 Connection with: host-name 192.168.3.166, rack 0, slot 3, pdu-size 1024, max-amq-caller 8, max-amq-callee 8
16:50:40.316 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 16
16:50:40.337 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
16:50:40.337 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
16:50:40.342 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
16:50:40.342 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
16:50:40.394 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 7020 (auto-detected)
16:50:40.396 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: false
16:50:40.396 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false
16:50:41.030 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo (Software Loopback Interface 1, 127.0.0.1)
16:50:41.031 [main] DEBUG io.netty.util.NetUtil - Failed to get SOMAXCONN from sysctl and file \proc\sys\net\core\somaxconn. Default: 200
16:50:41.690 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 00:50:b6:ff:fe:26:ae:1f (auto-detected)
16:50:41.722 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 16
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 16
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimIntervalMillis: 0
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
16:50:41.723 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
16:50:41.729 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled
16:50:41.729 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
16:50:41.729 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
16:50:41.777 [nioEventLoopGroup-2-1] DEBUG org.apache.plc4x.java.isotp.protocol.IsoTPProtocol - ISO Transport Protocol Sending Connection Request
16:50:41.786 [nioEventLoopGroup-2-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true
16:50:41.786 [nioEventLoopGroup-2-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkBounds: true
16:50:41.786 [nioEventLoopGroup-2-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@1e25211c
16:50:41.793 [nioEventLoopGroup-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
16:50:41.793 [nioEventLoopGroup-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
16:50:41.793 [nioEventLoopGroup-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16
16:50:41.793 [nioEventLoopGroup-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8
16:50:41.798 [nioEventLoopGroup-2-1] DEBUG org.apache.plc4x.java.isoontcp.protocol.IsoOnTcpProtocol - ISO on TCP Message sent
16:50:41.805 [nioEventLoopGroup-2-1] WARN io.netty.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.io.IOException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen
	at sun.nio.ch.SocketDispatcher.read0(Native Method)
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43)
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
	at sun.nio.ch.IOUtil.read(IOUtil.java:192)
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247)
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1140)
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:697)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:632)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:549)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:511)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:745)
org.apache.plc4x.java.api.exceptions.PlcConnectionException: java.util.concurrent.ExecutionException: org.apache.plc4x.java.api.exceptions.PlcIoException: Connection terminated by remote
	at org.apache.plc4x.java.base.connection.NettyPlcConnection.connect(NettyPlcConnection.java:88)
	at org.apache.plc4x.java.PlcDriverManager.getConnection(PlcDriverManager.java:73)
	at test.ReadValue.main(ReadValue.java:21)
Caused by: java.util.concurrent.ExecutionException: org.apache.plc4x.java.api.exceptions.PlcIoException: Connection terminated by remote
	at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357)
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
	at org.apache.plc4x.java.base.connection.NettyPlcConnection.connect(NettyPlcConnection.java:79)
	... 2 more
Caused by: org.apache.plc4x.java.api.exceptions.PlcIoException: Connection terminated by remote
	at org.apache.plc4x.java.base.connection.NettyPlcConnection.lambda$connect$0(NettyPlcConnection.java:70)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:500)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:474)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:413)
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:538)
	at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:527)
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:98)
	at io.netty.channel.DefaultChannelPromise.trySuccess(DefaultChannelPromise.java:84)
	at io.netty.channel.AbstractChannel$CloseFuture.setClosed(AbstractChannel.java:1156)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.doClose0(AbstractChannel.java:758)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.close(AbstractChannel.java:734)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.close(AbstractChannel.java:605)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.closeOnRead(AbstractNioByteChannel.java:105)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.handleReadException(AbstractNioByteChannel.java:127)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:174)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:697)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:632)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:549)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:511)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:745)