[
https://issues.apache.org/jira/browse/GEODE-9349?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17357729#comment-17357729
]
Louis R. Jacome commented on GEODE-9349:
----------------------------------------
The test appears to proceed as normal before we see the first message detecting
a wake-up delay of 4.3 seconds on vm0 and 5.8 seconds from vm2. There's also a
couple of unexpected socket timeouts to a1da16412bb2:20084 (PoolImpl uses a
default 5 seconds idle socket timeout). Presumably while vm0 is collecting
function execution results to send to a client, several sockets timed out due
to insufficient resources. As a result vm0 hit a FunctionException as it could
not send results to the client (caused by closed socket connection).
{code:java}
[vm0] [warn 2021/04/26 18:05:44.071 GMT <StatSampler> tid=0x753]
Statistics sampling thread detected a wakeup delay of 4336 ms, indicating a
possible resource issue. Check the GC, memory, and CPU statistics.
[vm3] [info 2021/04/26 18:05:44.343 GMT <Cache Client Updater Thread on
172.17.0.13(250)<v122>:41003 port 25629> tid=0x286] Cache client
updater for Queue on endpoint a1da16412bb2:25629 exiting. Scheduling recovery.
[vm3] [warn 2021/04/26 18:05:44.346 GMT
<poolTimer-PRClientServerTestBase-7> tid=0x28b] Pool unexpected socket
timed out on client
connection=SubscriptionConnectionImpl[a1da16412bb2:20084:closed]). Server
unreachable: could not connect after 1 attempts
[vm3] [warn 2021/04/26 18:05:44.346 GMT
<poolTimer-PRClientServerTestBase-8> tid=0x28c] Pool unexpected socket
timed out on client
connection=SubscriptionConnectionImpl[a1da16412bb2:25629:closed]). Server
unreachable: could not connect after 1 attempts
[vm3] [info 2021/04/26 18:05:44.350 GMT <Cache Client Updater Thread on
172.17.0.13(241)<v118>:41001 port 20084> tid=0x287] Cache client
updater for Queue on endpoint a1da16412bb2:20084 exiting. Scheduling recovery.
[vm0] [warn 2021/04/26 18:05:44.357 GMT <ServerConnection on port 20084
Thread 3> tid=0x780] Server connection from
[identity(172.17.0.13(255:loner):49444:8f9e5b0f,connection=1; port=49444]:
connection disconnect detected by EOF.
[vm0] [warn 2021/04/26 18:05:44.378 GMT <ServerConnection on port 20084
Thread 4> tid=0x786] Server connection from
[identity(172.17.0.13(255:loner):49444:8f9e5b0f,connection=1; port=49464]:
connection disconnect detected by EOF.
[vm3] [warn 2021/04/26 18:05:44.389 GMT <RMI TCP
Connection(1)-172.17.0.13> tid=0x20] Pool unexpected SocketException
connection=Pooled Connection to a1da16412bb2:20084: Connection[DESTROYED]).
Server unreachable: could not connect after 1 attempts
[vm1] [info 2021/04/26 18:05:44.379 GMT <ServerConnection on port 23943
Thread 2> tid=0x79e] Entry expiry tasks disabled because the queue became
primary. Old messageTimeToLive was: 180
[vm2] [warn 2021/04/26 18:05:45.194 GMT <StatSampler> tid=0x7a6]
Statistics sampling thread detected a wakeup delay of 5814 ms, indicating a
possible resource issue. Check the GC, memory, and CPU statistics.
[vm2] [warn 2021/04/26 18:05:45.278 GMT <ServerConnection on port 25629
Thread 3> tid=0x7c4] Server connection from
[identity(172.17.0.13(255:loner):49444:8f9e5b0f,connection=1; port=48628]:
connection disconnect detected by EOF.
[vm2] [warn 2021/04/26 18:05:45.292 GMT <ServerConnection on port 25629
Thread 4> tid=0x7cd] Server connection from
[identity(172.17.0.13(255:loner):49444:8f9e5b0f,connection=1; port=48644]:
connection disconnect detected by EOF.
[vm2] [warn 2021/04/26 18:05:45.296 GMT <ServerConnection on port 25629
Thread 5> tid=0x7cf] Server connection from
[identity(172.17.0.13(255:loner):49444:8f9e5b0f,connection=1; port=48630]:
connection disconnect detected by EOF.
...
...
...
[vm0] [fatal 2021/04/26 18:05:49.309 GMT <Pooled High Priority Message
Processor 2> tid=0x75e] Uncaught exception processing
org.apache.geode.internal.cache.FunctionStreamingReplyMessage(processorId=1821
from 172.17.0.13(250)<v122>:41003;msgNum 0;lastMsg=true)
[vm0] org.apache.geode.cache.execute.FunctionException: IOException while
sending the last chunk to client
[vm0] at
org.apache.geode.internal.cache.execute.ServerToClientFunctionResultSender65.lastResult(ServerToClientFunctionResultSender65.java:164)
[vm0] at
org.apache.geode.internal.cache.execute.PartitionedRegionFunctionResultSender.lastClientSend(PartitionedRegionFunctionResultSender.java:377)
[vm0] at
org.apache.geode.internal.cache.execute.PartitionedRegionFunctionResultSender.lastResult(PartitionedRegionFunctionResultSender.java:298)
[vm0] at
org.apache.geode.internal.cache.execute.PartitionedRegionFunctionResultWaiter.processData(PartitionedRegionFunctionResultWaiter.java:117)
[vm0] at
org.apache.geode.internal.cache.execute.FunctionStreamingResultCollector.process(FunctionStreamingResultCollector.java:516)
[vm0] at
org.apache.geode.distributed.internal.ReplyMessage.process(ReplyMessage.java:213)
[vm0] at
org.apache.geode.distributed.internal.ReplyMessage.dmProcess(ReplyMessage.java:197)
[vm0] at
org.apache.geode.distributed.internal.ReplyMessage.process(ReplyMessage.java:190)
[vm0] at
org.apache.geode.distributed.internal.DistributionMessage.scheduleAction(DistributionMessage.java:376)
[vm0] at
org.apache.geode.distributed.internal.DistributionMessage$1.run(DistributionMessage.java:440)
[vm0] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[vm0] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[vm0] at
org.apache.geode.distributed.internal.ClusterOperationExecutors.runUntilShutdown(ClusterOperationExecutors.java:441)
[vm0] at
org.apache.geode.distributed.internal.ClusterOperationExecutors.doHighPriorityThread(ClusterOperationExecutors.java:399)
[vm0] at
org.apache.geode.logging.internal.executors.LoggingThreadFactory.lambda$newThread$0(LoggingThreadFactory.java:119)
[vm0] at java.lang.Thread.run(Thread.java:748)
[vm0] Caused by: java.io.IOException: Broken pipe
[vm0] at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
[vm0] at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
[vm0] at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
[vm0] at sun.nio.ch.IOUtil.write(IOUtil.java:51)
[vm0] at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:470)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.Message.flushBuffer(Message.java:655)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.Message.sendBytes(Message.java:636)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.ChunkedMessage.sendChunk(ChunkedMessage.java:311)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.ChunkedMessage.sendChunk(ChunkedMessage.java:320)
[vm0] at
org.apache.geode.internal.cache.execute.ServerToClientFunctionResultSender65.lastResult(ServerToClientFunctionResultSender65.java:158)
[vm0] ... 15 more
[vm0] [warn 2021/04/26 18:05:49.310 GMT <ServerConnection on port 20084 Thread
2> tid=0x77f] Exception on server while executing function :
SocketTimeOutFunction
[vm0] org.apache.geode.cache.execute.FunctionException: IOException while
sending the last chunk to client
[vm0] at
org.apache.geode.internal.cache.execute.ServerToClientFunctionResultSender65.lastResult(ServerToClientFunctionResultSender65.java:164)
[vm0] at
org.apache.geode.internal.cache.execute.PartitionedRegionFunctionResultSender.lastClientSend(PartitionedRegionFunctionResultSender.java:377)
[vm0] at
org.apache.geode.internal.cache.execute.PartitionedRegionFunctionResultSender.lastResult(PartitionedRegionFunctionResultSender.java:298)
[vm0] at
org.apache.geode.internal.cache.execute.PartitionedRegionFunctionResultWaiter.processData(PartitionedRegionFunctionResultWaiter.java:117)
[vm0] at
org.apache.geode.internal.cache.execute.FunctionStreamingResultCollector.process(FunctionStreamingResultCollector.java:516)
[vm0] at
org.apache.geode.distributed.internal.ReplyMessage.process(ReplyMessage.java:213)
[vm0] at
org.apache.geode.distributed.internal.ReplyMessage.dmProcess(ReplyMessage.java:197)
[vm0] at
org.apache.geode.distributed.internal.ReplyMessage.process(ReplyMessage.java:190)
[vm0] at
org.apache.geode.distributed.internal.DistributionMessage.scheduleAction(DistributionMessage.java:376)
[vm0] at
org.apache.geode.distributed.internal.DistributionMessage$1.run(DistributionMessage.java:440)
[vm0] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[vm0] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[vm0] at
org.apache.geode.distributed.internal.ClusterOperationExecutors.runUntilShutdown(ClusterOperationExecutors.java:441)
[vm0] at
org.apache.geode.distributed.internal.ClusterOperationExecutors.doHighPriorityThread(ClusterOperationExecutors.java:399)
[vm0] at
org.apache.geode.logging.internal.executors.LoggingThreadFactory.lambda$newThread$0(LoggingThreadFactory.java:119)
[vm0] at java.lang.Thread.run(Thread.java:748)
[vm0] Caused by: java.io.IOException: Broken pipe
[vm0] at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
[vm0] at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
[vm0] at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
[vm0] at sun.nio.ch.IOUtil.write(IOUtil.java:51)
[vm0] at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:470)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.Message.flushBuffer(Message.java:655)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.Message.sendBytes(Message.java:636)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.ChunkedMessage.sendChunk(ChunkedMessage.java:311)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.ChunkedMessage.sendChunk(ChunkedMessage.java:320)
[vm0] at
org.apache.geode.internal.cache.execute.ServerToClientFunctionResultSender65.lastResult(ServerToClientFunctionResultSender65.java:158)
[vm0] ... 15 more
[vm0] [warn 2021/04/26 18:05:49.313 GMT <ServerConnection on port 20084 Thread
2> tid=0x77f] Server connection from
[identity(172.17.0.13(255:loner):49444:8f9e5b0f,connection=1; port=49446]:
Unexpected IOException:
[vm0] java.io.IOException: Broken pipe
[vm0] at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
[vm0] at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
[vm0] at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
[vm0] at sun.nio.ch.IOUtil.write(IOUtil.java:51)
[vm0] at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:470)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.Message.flushBuffer(Message.java:655)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.ChunkedMessage.sendHeader(ChunkedMessage.java:285)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.command.ExecuteRegionFunction66.writeFunctionResponseException(ExecuteRegionFunction66.java:476)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.command.ExecuteRegionFunction66.sendException(ExecuteRegionFunction66.java:422)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.command.ExecuteRegionFunction66.cmdExecute(ExecuteRegionFunction66.java:224)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.BaseCommand.execute(BaseCommand.java:183)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.doNormalMessage(ServerConnection.java:848)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.OriginalServerConnection.doOneMessage(OriginalServerConnection.java:72)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.ServerConnection.run(ServerConnection.java:1181)
[vm0] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[vm0] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[vm0] at
org.apache.geode.internal.cache.tier.sockets.AcceptorImpl.lambda$initializeServerConnectionThreadPool$3(AcceptorImpl.java:676)
[vm0] at
org.apache.geode.logging.internal.executors.LoggingThreadFactory.lambda$newThread$0(LoggingThreadFactory.java:119)
[vm0] at java.lang.Thread.run(Thread.java:748)
{code}
> CI Failure: PRClientServerRegionFunctionExecutionSelectorNoSingleHopDUnitTest
> > testServerSingleKeyExecution_SocketTimeOut[ExecuteFunctionByObject]
> ---------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: GEODE-9349
> URL: https://issues.apache.org/jira/browse/GEODE-9349
> Project: Geode
> Issue Type: Bug
> Components: functions
> Affects Versions: 1.12.3
> Reporter: Kirk Lund
> Assignee: Louis R. Jacome
> Priority: Major
> Labels: blocks-1.12.4
>
> {noformat}
> > Task :geode-core:distributedTest
> org.apache.geode.internal.cache.execute.PRClientServerRegionFunctionExecutionSelectorNoSingleHopDUnitTest
> > testServerSingleKeyExecution_SocketTimeOut[ExecuteFunctionByObject] FAILED
> java.lang.AssertionError: Suspicious strings were written to the log
> during this run.
> Fix the strings or use IgnoredException.addIgnoredException to ignore.
> -----------------------------------------------------------------------
> Found suspect string in log4j at line 4431
> [fatal 2021/04/26 18:05:49.309 GMT <Pooled High Priority Message
> Processor 2> tid=1886] Uncaught exception processing
> org.apache.geode.internal.cache.FunctionStreamingReplyMessage(processorId=1821
> from 172.17.0.13(250)<v122>:41003;msgNum 0;lastMsg=true)
> org.apache.geode.cache.execute.FunctionException: IOException while
> sending the last chunk to client
> at
> org.apache.geode.internal.cache.execute.ServerToClientFunctionResultSender65.lastResult(ServerToClientFunctionResultSender65.java:164)
> at
> org.apache.geode.internal.cache.execute.PartitionedRegionFunctionResultSender.lastClientSend(PartitionedRegionFunctionResultSender.java:377)
> at
> org.apache.geode.internal.cache.execute.PartitionedRegionFunctionResultSender.lastResult(PartitionedRegionFunctionResultSender.java:298)
> at
> org.apache.geode.internal.cache.execute.PartitionedRegionFunctionResultWaiter.processData(PartitionedRegionFunctionResultWaiter.java:117)
> at
> org.apache.geode.internal.cache.execute.FunctionStreamingResultCollector.process(FunctionStreamingResultCollector.java:516)
> at
> org.apache.geode.distributed.internal.ReplyMessage.process(ReplyMessage.java:213)
> at
> org.apache.geode.distributed.internal.ReplyMessage.dmProcess(ReplyMessage.java:197)
> at
> org.apache.geode.distributed.internal.ReplyMessage.process(ReplyMessage.java:190)
> at
> org.apache.geode.distributed.internal.DistributionMessage.scheduleAction(DistributionMessage.java:376)
> at
> org.apache.geode.distributed.internal.DistributionMessage$1.run(DistributionMessage.java:440)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at
> org.apache.geode.distributed.internal.ClusterOperationExecutors.runUntilShutdown(ClusterOperationExecutors.java:441)
> at
> org.apache.geode.distributed.internal.ClusterOperationExecutors.doHighPriorityThread(ClusterOperationExecutors.java:399)
> at
> org.apache.geode.logging.internal.executors.LoggingThreadFactory.lambda$newThread$0(LoggingThreadFactory.java:119)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: java.io.IOException: Broken pipe
> at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
> at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
> at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
> at sun.nio.ch.IOUtil.write(IOUtil.java:51)
> at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:470)
> at
> org.apache.geode.internal.cache.tier.sockets.Message.flushBuffer(Message.java:655)
> at
> org.apache.geode.internal.cache.tier.sockets.Message.sendBytes(Message.java:636)
> at
> org.apache.geode.internal.cache.tier.sockets.ChunkedMessage.sendChunk(ChunkedMessage.java:311)
> at
> org.apache.geode.internal.cache.tier.sockets.ChunkedMessage.sendChunk(ChunkedMessage.java:320)
> at
> org.apache.geode.internal.cache.execute.ServerToClientFunctionResultSender65.lastResult(ServerToClientFunctionResultSender65.java:158)
> ... 15 more
> 8778 tests completed, 1 failed, 458 skipped
> {noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
