search

teragrep / rlp_03

Java RELP Server library
GNU Affero General Public License v3.0
1 stars 5 forks source link

Server processings gets stuck if SequencingDelegate throws #169

Closed StrongestNumber9 closed 5 months ago

StrongestNumber9 commented 5 months ago

Describe the bug

While investigating #168 I noticed that the test never stops

First connection is just fine

15.05.2024 10:31:20.477 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] readyKeys <1>
15.05.2024 10:31:20.478 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKeys <[channel=sun.nio.ch.ServerSocketChannelImpl[/[0:0:0:0:0:0:0:0]:1601], selector=sun.nio.ch.EPollSelectorImpl@4e5ce127, interestOps=16, readyOps=16]> 
15.05.2024 10:31:20.478 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKey <channel=sun.nio.ch.ServerSocketChannelImpl[/[0:0:0:0:0:0:0:0]:1601], selector=sun.nio.ch.EPollSelectorImpl@4e5ce127, interestOps=16, readyOps=16>: isValid <true>, isConnectable <false>, isAcceptable <true>, isReadable <false>, isWritable <false>
15.05.2024 10:31:20.478 [DEBUG] [com.teragrep.rlp_03.channel.context.ListenContext] [Thread-0] ServerSocket </[0:0:0:0:0:0:0:0]:1601> accepting ClientSocket </127.0.0.1:60496> 
15.05.2024 10:31:20.483 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] readyKeys <1>
15.05.2024 10:31:20.483 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKeys <[channel=java.nio.channels.SocketChannel[connected local=/127.0.0.1:1601 remote=/127.0.0.1:60496], selector=sun.nio.ch.EPollSelectorImpl@4e5ce127, interestOps=1, readyOps=1]> 
15.05.2024 10:31:20.483 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKey <channel=java.nio.channels.SocketChannel[connected local=/127.0.0.1:1601 remote=/127.0.0.1:60496], selector=sun.nio.ch.EPollSelectorImpl@4e5ce127, interestOps=1, readyOps=1>: isValid <true>, isConnectable <false>, isAcceptable <false>, isReadable <true>, isWritable <false>
15.05.2024 10:31:20.483 [DEBUG] [com.teragrep.rlp_03.channel.context.EstablishedContextImpl] [Thread-0] handleEvent taking read
15.05.2024 10:31:20.483 [DEBUG] [com.teragrep.rlp_03.channel.context.InterestOpsImpl] [Thread-0] Removing op <1> from currentOps <0>, newOps <0>, keyOps <1>, validOps <13>
15.05.2024 10:31:20.483 [DEBUG] [com.teragrep.rlp_03.channel.context.InterestOpsImpl] [Thread-0] Removed op <1>, currentOps <0>, keyOps <0>, validOps <13>
15.05.2024 10:31:20.483 [DEBUG] [com.teragrep.rlp_03.channel.context.EstablishedContextImpl] [Thread-0] handleEvent submitting new runnable for read
15.05.2024 10:31:20.484 [DEBUG] [com.teragrep.rlp_03.channel.context.EstablishedContextImpl] [Thread-0] handleEvent exiting read
15.05.2024 10:31:20.484 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] readyKeys <0>
15.05.2024 10:31:20.484 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKeys <[]> 
15.05.2024 10:31:20.484 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] run entry!
15.05.2024 10:31:20.484 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] run lock! with activeBuffers.size() <0>
15.05.2024 10:31:20.484 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] run loop start
15.05.2024 10:31:20.486 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] requesting take with size <4>
15.05.2024 10:31:20.487 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] returning bufferLease id <1> with refs <1> at buffer position <0>
15.05.2024 10:31:20.487 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferContainerImpl] [pool-1-thread-1] id <1>
15.05.2024 10:31:20.488 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] establishedContext.read got <97> bytes from socket
15.05.2024 10:31:20.488 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] submitting buffer <com.teragrep.rlp_03.channel.buffer.BufferLeaseImpl@1b880e45> from activeBuffers <[]> to relpFrame
15.05.2024 10:31:20.488 [TRACE] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] received relpFrame <[RelpFrameLeaseful{relpFrame=RelpFrameImpl{txn=1, command=open, payloadLength=86, payload=relp_version=0
relp_software=librelp,1.10.0,http://librelp.adiscon.com
commands=syslog, endOfTransfer=
}, leaseSet=REMOVED}]>
15.05.2024 10:31:20.488 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] frame complete, activeBuffers <[]>
15.05.2024 10:31:20.489 [TRACE] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] Accepting <[[1 rsp 86 200 OK
relp_version=0
relp_software=RLP-01,1.0.1,https://teragrep.com
commands=syslog
]]>
15.05.2024 10:31:20.490 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] sendFrame frameTXOptional.isPresent() <true>
15.05.2024 10:31:20.490 [TRACE] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] sendFrame <1 rsp 86 200 OK
relp_version=0
relp_software=RLP-01,1.0.1,https://teragrep.com
commands=syslog
>
15.05.2024 10:31:20.490 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] complete write
15.05.2024 10:31:20.490 [DEBUG] [com.teragrep.rlp_03.frame.RelpFrameLeaseful] [pool-1-thread-1] releasing id <1> with refs <1>
15.05.2024 10:31:20.490 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferContainerImpl] [pool-1-thread-1] id <1>
15.05.2024 10:31:20.490 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] offer complete, queueSegments <1>, queueBytes <4096>
15.05.2024 10:31:20.491 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] processed txFrame.
15.05.2024 10:31:20.491 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] loop done!
15.05.2024 10:31:20.491 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] run loop start
15.05.2024 10:31:20.491 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] requesting take with size <4>
15.05.2024 10:31:20.491 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] returning bufferLease id <1> with refs <1> at buffer position <0>
15.05.2024 10:31:20.491 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferContainerImpl] [pool-1-thread-1] id <1>
15.05.2024 10:31:20.491 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] establishedContext.read got <14> bytes from socket
15.05.2024 10:31:20.491 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] submitting buffer <com.teragrep.rlp_03.channel.buffer.BufferLeaseImpl@57984212> from activeBuffers <[]> to relpFrame
15.05.2024 10:31:20.491 [TRACE] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] received relpFrame <[RelpFrameLeaseful{relpFrame=RelpFrameImpl{txn=2, command=syslog, payloadLength=2, payload=1
, endOfTransfer=
}, leaseSet=REMOVED}]>
15.05.2024 10:31:20.491 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] frame complete, activeBuffers <[]>
15.05.2024 10:31:20.491 [TRACE] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] Accepting <[[2 rsp 6 200 OK]]>
15.05.2024 10:31:20.491 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] sendFrame frameTXOptional.isPresent() <true>
15.05.2024 10:31:20.492 [TRACE] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] sendFrame <2 rsp 6 200 OK>
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] complete write
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.frame.RelpFrameLeaseful] [pool-1-thread-1] releasing id <1> with refs <1>
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferContainerImpl] [pool-1-thread-1] id <1>
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] offer complete, queueSegments <1>, queueBytes <4096>
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] processed txFrame.
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] loop done!
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] run loop start
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] requesting take with size <4>
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] returning bufferLease id <1> with refs <1> at buffer position <0>
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferContainerImpl] [pool-1-thread-1] id <1>
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] establishedContext.read got <10> bytes from socket
15.05.2024 10:31:20.492 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] submitting buffer <com.teragrep.rlp_03.channel.buffer.BufferLeaseImpl@21e3604b> from activeBuffers <[]> to relpFrame
15.05.2024 10:31:20.494 [TRACE] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] received relpFrame <[RelpFrameLeaseful{relpFrame=RelpFrameImpl{txn=3, command=close, payloadLength=0, payload=, endOfTransfer=
}, leaseSet=REMOVED}]>
15.05.2024 10:31:20.494 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] frame complete, activeBuffers <[]>
15.05.2024 10:31:20.494 [DEBUG] [com.teragrep.rlp_03.frame.delegate.event.RelpEventClose] [pool-1-thread-1] received close on txn <[3]>
15.05.2024 10:31:20.494 [TRACE] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] Accepting <[[3 rsp 0 , 0 serverclose 0 ]]>
15.05.2024 10:31:20.494 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] sendFrame frameTXOptional.isPresent() <true>
15.05.2024 10:31:20.494 [TRACE] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] sendFrame <3 rsp 0 >
15.05.2024 10:31:20.494 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] complete write
15.05.2024 10:31:20.494 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] sendFrame frameTXOptional.isPresent() <true>
15.05.2024 10:31:20.494 [TRACE] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] sendFrame <0 serverclose 0 >
15.05.2024 10:31:20.495 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] complete write
15.05.2024 10:31:20.495 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpWriteImpl] [pool-1-thread-1] Sent command <serverclose>, Closing connection to  PeerAddress </127.0.0.1> PeerPort <60496>
15.05.2024 10:31:20.495 [DEBUG] [com.teragrep.rlp_03.channel.context.InterestOpsImpl] [pool-1-thread-1] Removing all currentOps <0>, newOps <0>, keyOps <0>, validOps <13>
15.05.2024 10:31:20.496 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] readyKeys <0>
15.05.2024 10:31:20.496 [DEBUG] [com.teragrep.rlp_03.channel.context.InterestOpsImpl] [pool-1-thread-1] Removed all ops. currentOps <0>, keyOps <0>, validOps <13>
15.05.2024 10:31:20.496 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKeys <[]> 
15.05.2024 10:31:20.496 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] close called
15.05.2024 10:31:20.496 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] closing in offer
15.05.2024 10:31:20.496 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] offer complete, queueSegments <0>, queueBytes <0>
15.05.2024 10:31:20.496 [DEBUG] [com.teragrep.rlp_03.frame.RelpFrameLeaseful] [pool-1-thread-1] releasing id <1> with refs <1>
15.05.2024 10:31:20.497 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferContainerImpl] [pool-1-thread-1] id <1>
15.05.2024 10:31:20.497 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] closing in offer
15.05.2024 10:31:20.497 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] offer complete, queueSegments <0>, queueBytes <0>
15.05.2024 10:31:20.497 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] processed txFrame.

No more relp connections can be opened once thrown as offer frame is never sent

15.05.2024 10:31:23.403 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] readyKeys <1>
15.05.2024 10:31:23.404 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKeys <[channel=sun.nio.ch.ServerSocketChannelImpl[/[0:0:0:0:0:0:0:0]:1601], selector=sun.nio.ch.EPollSelectorImpl@4e5ce127, interestOps=16, readyOps=16]> 
15.05.2024 10:31:23.404 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKey <channel=sun.nio.ch.ServerSocketChannelImpl[/[0:0:0:0:0:0:0:0]:1601], selector=sun.nio.ch.EPollSelectorImpl@4e5ce127, interestOps=16, readyOps=16>: isValid <true>, isConnectable <false>, isAcceptable <true>, isReadable <false>, isWritable <false>
15.05.2024 10:31:23.404 [DEBUG] [com.teragrep.rlp_03.channel.context.ListenContext] [Thread-0] ServerSocket </[0:0:0:0:0:0:0:0]:1601> accepting ClientSocket </127.0.0.1:60502> 
15.05.2024 10:31:23.404 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] readyKeys <1>
15.05.2024 10:31:23.404 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKeys <[channel=java.nio.channels.SocketChannel[connected local=/127.0.0.1:1601 remote=/127.0.0.1:60502], selector=sun.nio.ch.EPollSelectorImpl@4e5ce127, interestOps=1, readyOps=1]> 
15.05.2024 10:31:23.404 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKey <channel=java.nio.channels.SocketChannel[connected local=/127.0.0.1:1601 remote=/127.0.0.1:60502], selector=sun.nio.ch.EPollSelectorImpl@4e5ce127, interestOps=1, readyOps=1>: isValid <true>, isConnectable <false>, isAcceptable <false>, isReadable <true>, isWritable <false>
15.05.2024 10:31:23.404 [DEBUG] [com.teragrep.rlp_03.channel.context.EstablishedContextImpl] [Thread-0] handleEvent taking read
15.05.2024 10:31:23.404 [DEBUG] [com.teragrep.rlp_03.channel.context.InterestOpsImpl] [Thread-0] Removing op <1> from currentOps <0>, newOps <0>, keyOps <1>, validOps <13>
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.context.InterestOpsImpl] [Thread-0] Removed op <1>, currentOps <0>, keyOps <0>, validOps <13>
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.context.EstablishedContextImpl] [Thread-0] handleEvent submitting new runnable for read
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.context.EstablishedContextImpl] [Thread-0] handleEvent exiting read
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] run entry!
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] readyKeys <0>
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] run lock! with activeBuffers.size() <0>
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.eventloop.EventLoop] [Thread-0] selectionKeys <[]> 
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] run loop start
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] requesting take with size <4>
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferLeasePool] [pool-1-thread-1] returning bufferLease id <1> with refs <1> at buffer position <0>
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.buffer.BufferContainerImpl] [pool-1-thread-1] id <1>
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] establishedContext.read got <97> bytes from socket
15.05.2024 10:31:23.405 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] submitting buffer <com.teragrep.rlp_03.channel.buffer.BufferLeaseImpl@4f06e867> from activeBuffers <[]> to relpFrame
15.05.2024 10:31:23.406 [TRACE] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] received relpFrame <[RelpFrameLeaseful{relpFrame=RelpFrameImpl{txn=1, command=open, payloadLength=86, payload=relp_version=0
relp_software=librelp,1.10.0,http://librelp.adiscon.com
commands=syslog, endOfTransfer=
}, leaseSet=REMOVED}]>
15.05.2024 10:31:23.406 [DEBUG] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] frame complete, activeBuffers <[]>
15.05.2024 10:31:23.406 [ERROR] [com.teragrep.rlp_03.channel.context.RelpReadImpl] [pool-1-thread-1] run() threw java.lang.IllegalArgumentException: frame txn not sequencing
        at com.teragrep.rlp_03.frame.delegate.SequencingDelegate.accept(SequencingDelegate.java:85)
        at com.teragrep.rlp_03.frame.delegate.DefaultFrameDelegate.accept(DefaultFrameDelegate.java:77)
        at com.teragrep.rlp_03.channel.context.RelpReadImpl.processFrame(RelpReadImpl.java:234)
        at com.teragrep.rlp_03.channel.context.RelpReadImpl.run(RelpReadImpl.java:147)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1583)

Expected behavior

Recovers and continues normally

How to reproduce

Cause SequencingDelegate to throw

java.lang.IllegalArgumentException: Frame txn not sequencing
    at com.teragrep.rlp_03.frame.delegate.SequencingDelegate.accept(SequencingDelegate.java:85)
    at com.teragrep.rlp_03.frame.delegate.DefaultFrameDelegate.accept(DefaultFrameDelegate.java:77)

Easy nc command to trigger it with negative txn id

echo -e "1 open 63 relp_version=0\nrelp_software=relp-checker,1.0.0\ncommands=syslog\n-1 syslog 1 X\n" | nc 127.0.0.1 1601

Software version

rlp_03 7.0.2

Additional context

168