[
https://issues.apache.org/jira/browse/PLC4X-179?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17047359#comment-17047359
]
Christofer Dutz commented on PLC4X-179:
---------------------------------------
Hi Florian,
this is really strange ... the S7 seems to be reacting in an unusual way.
The connection is created correctly as I can see in the first 6 exchanged
packets. Also does the read request look absolutely normal.
Same with the response ... however the response is simply completely empty. The
return codes imply everything is ok, but parameter and payload contain 0 bytes.
Could you please try the requests with each only one of the addresses you are
querying? Perhaps we didn't get all of the codes correctly. Perhaps this way we
can find out what's going wrong.
Please note the S7 is almost the only driver there is no specification
available for so the current state is based on reverse-engineering ... no
guarantee we got everything right but together we can improve it more and more.
Chris
> Initial connection terminated from PLC
> --------------------------------------
>
> Key: PLC4X-179
> URL: https://issues.apache.org/jira/browse/PLC4X-179
> Project: Apache PLC4X
> Issue Type: Bug
> Components: Driver-S7
> Affects Versions: 0.5.0
> Environment: Windows 10, jdk1.8.0_91-win64, jdk11.0.6.10
> Reporter: Florian Probst
> Assignee: Christofer Dutz
> Priority: Major
> Attachments: responseTimeout.txt, s7_400_connectionTerminated.pcapng,
> s7_400_reponseTimeout.pcapng
>
>
> 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:
> {noformat}
> 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)
> {noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
