[
https://issues.apache.org/jira/browse/NIFI-4073?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16061105#comment-16061105
]
ASF GitHub Bot commented on NIFI-4073:
--------------------------------------
Github user alopresto commented on the issue:
https://github.com/apache/nifi/pull/1916
Ran `contrib-check` and all tests pass. +1, merging.
I did start a two node cluster and ensure it was communicating, then used
`pf` to temporarily block the cluster port to trigger the error message. I did
not see the duplicated stack trace.
```
# Enabled port blocking
2017-06-23 11:12:55,991 INFO [Clustering Tasks Thread-1]
o.a.n.c.c.ClusterProtocolHeartbeater Heartbeat created at 2017-06-23
11:12:55,987 and sent to localhost:10000 at 2017-06-23 11:12:55,991; send took
3 millis
2017-06-23 11:12:56,561 INFO [Process Cluster Protocol Request-10]
o.a.n.c.p.impl.SocketProtocolListener Finished processing request
3ecf8509-0b0b-4602-ac55-1ec9057dc3c3 (type=HEARTBEAT, length=2344 bytes) from
localhost:8081 in 1 millis
2017-06-23 11:12:57,293 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 2 heartbeats in 6930
nanos
2017-06-23 11:13:00,433 INFO [Write-Ahead Local State Provider Maintenance]
org.wali.MinimalLockingWriteAheadLog
org.wali.MinimalLockingWriteAheadLog@7a80ebcd checkpointed with 1 Records and 0
Swap Files in 12 milliseconds (Stop-the-world time = 4 milliseconds, Clear Edit
Logs time = 4 millis), max Transaction ID 0
2017-06-23 11:13:00,998 INFO [Process Cluster Protocol Request-1]
o.a.n.c.p.impl.SocketProtocolListener Finished processing request
dc71898f-f3e6-4aaa-af2e-b0dae65e4f53 (type=HEARTBEAT, length=2344 bytes) from
localhost:8080 in 1 millis
2017-06-23 11:13:00,999 INFO [Clustering Tasks Thread-1]
o.a.n.c.c.ClusterProtocolHeartbeater Heartbeat created at 2017-06-23
11:13:00,995 and sent to localhost:10000 at 2017-06-23 11:13:00,999; send took
4 millis
2017-06-23 11:13:01,572 INFO [Process Cluster Protocol Request-2]
o.a.n.c.p.impl.SocketProtocolListener Finished processing request
83d6969d-6073-43d4-b8e3-c182d4feea48 (type=HEARTBEAT, length=2344 bytes) from
localhost:8081 in 2 millis
2017-06-23 11:13:02,296 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 2 heartbeats in 6734
nanos
2017-06-23 11:13:07,300 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 2 heartbeats in 5332
nanos
2017-06-23 11:13:12,305 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 2 heartbeats in 6497
nanos
2017-06-23 11:13:17,308 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 2 heartbeats in 5851
nanos
2017-06-23 11:13:22,314 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 2 heartbeats in 5554
nanos
2017-06-23 11:13:27,318 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 2 heartbeats in 5786
nanos
2017-06-23 11:13:32,045 WARN [Clustering Tasks Thread-1]
o.apache.nifi.controller.FlowController Failed to send heartbeat due to:
org.apache.nifi.cluster.protocol.ProtocolException: Failed to send message to
Cluster Coordinator due to: java.net.ConnectException: Operation timed out
2017-06-23 11:13:32,323 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 2 heartbeats in 6357
nanos
2017-06-23 11:13:37,328 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 2 heartbeats in 6451
nanos
2017-06-23 11:13:42,333 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 2 heartbeats in 5380
nanos
2017-06-23 11:13:42,333 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator localhost:8081 requested disconnection
from cluster due to Have not received a heartbeat from node in 40 seconds
2017-06-23 11:13:42,333 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Status of localhost:8081 changed from
NodeConnectionStatus[nodeId=localhost:8081, state=CONNECTED, updateId=125] to
NodeConnectionStatus[nodeId=localhost:8081, state=DISCONNECTED, Disconnect
Code=Lack of Heartbeat, Disconnect Reason=Have not received a heartbeat from
node in 40 seconds, updateId=126]
2017-06-23 11:13:42,334 WARN [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Event Reported for localhost:8081 -- Node
disconnected from cluster due to Have not received a heartbeat from node in 40
seconds
2017-06-23 11:13:42,334 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator localhost:8080 requested disconnection
from cluster due to Have not received a heartbeat from node in 41 seconds
2017-06-23 11:13:42,334 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Status of localhost:8080 changed from
NodeConnectionStatus[nodeId=localhost:8080, state=CONNECTED, updateId=121] to
NodeConnectionStatus[nodeId=localhost:8080, state=DISCONNECTED, Disconnect
Code=Lack of Heartbeat, Disconnect Reason=Have not received a heartbeat from
node in 41 seconds, updateId=127]
2017-06-23 11:13:42,335 WARN [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Event Reported for localhost:8080 -- Node
disconnected from cluster due to Have not received a heartbeat from node in 41
seconds
2017-06-23 11:13:54,349 INFO [NiFi Web Server-183]
o.a.n.c.m.e.NoConnectedNodesException Cluster failed processing request:
org.apache.nifi.cluster.manager.exception.NoConnectedNodesException. Returning
Internal Server Error response.
2017-06-23 11:13:54,349 INFO [NiFi Web Server-141]
o.a.n.c.m.e.NoConnectedNodesException Cluster failed processing request:
org.apache.nifi.cluster.manager.exception.NoConnectedNodesException. Returning
Internal Server Error response.
2017-06-23 11:13:54,349 INFO [NiFi Web Server-158]
o.a.n.c.m.e.NoConnectedNodesException Cluster failed processing request:
org.apache.nifi.cluster.manager.exception.NoConnectedNodesException. Returning
Internal Server Error response.
2017-06-23 11:13:54,352 INFO [NiFi Web Server-211]
o.a.n.c.m.e.NoConnectedNodesException Cluster failed processing request:
org.apache.nifi.cluster.manager.exception.NoConnectedNodesException. Returning
Internal Server Error response.
2017-06-23 11:14:03,063 WARN [Clustering Tasks Thread-1]
o.apache.nifi.controller.FlowController Failed to send heartbeat due to:
org.apache.nifi.cluster.protocol.ProtocolException: Failed to send message to
Cluster Coordinator due to: java.net.ConnectException: Operation timed out
# Disabled port blocking
2017-06-23 11:13:42,335 WARN [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Event Reported for localhost:8080 -- Node
disconnected from cluster due to Have not received a heartbeat from node in 41
seconds
2017-06-23 11:13:54,349 INFO [NiFi Web Server-183]
o.a.n.c.m.e.NoConnectedNodesException Cluster failed processing request:
org.apache.nifi.cluster.manager.exception.NoConnectedNodesException. Returning
Internal Server Error response.
2017-06-23 11:13:54,349 INFO [NiFi Web Server-141]
o.a.n.c.m.e.NoConnectedNodesException Cluster failed processing request:
org.apache.nifi.cluster.manager.exception.NoConnectedNodesException. Returning
Internal Server Error response.
2017-06-23 11:13:54,349 INFO [NiFi Web Server-158]
o.a.n.c.m.e.NoConnectedNodesException Cluster failed processing request:
org.apache.nifi.cluster.manager.exception.NoConnectedNodesException. Returning
Internal Server Error response.
2017-06-23 11:13:54,352 INFO [NiFi Web Server-211]
o.a.n.c.m.e.NoConnectedNodesException Cluster failed processing request:
org.apache.nifi.cluster.manager.exception.NoConnectedNodesException. Returning
Internal Server Error response.
2017-06-23 11:14:03,063 WARN [Clustering Tasks Thread-1]
o.apache.nifi.controller.FlowController Failed to send heartbeat due to:
org.apache.nifi.cluster.protocol.ProtocolException: Failed to send message to
Cluster Coordinator due to: java.net.ConnectException: Operation timed out
2017-06-23 11:14:05,343 INFO [pool-12-thread-1]
o.a.n.c.r.WriteAheadFlowFileRepository Initiating checkpoint of FlowFile
Repository
2017-06-23 11:14:05,523 INFO [pool-12-thread-1]
org.wali.MinimalLockingWriteAheadLog
org.wali.MinimalLockingWriteAheadLog@3f4b59fd checkpointed with 0 Records and 0
Swap Files in 180 milliseconds (Stop-the-world time = 70 milliseconds, Clear
Edit Logs time = 93 millis), max Transaction ID -1
2017-06-23 11:14:05,523 INFO [pool-12-thread-1]
o.a.n.c.r.WriteAheadFlowFileRepository Successfully checkpointed FlowFile
Repository with 0 records in 180 milliseconds
2017-06-23 11:14:34,103 WARN [Clustering Tasks Thread-1]
o.apache.nifi.controller.FlowController Failed to send heartbeat due to:
org.apache.nifi.cluster.protocol.ProtocolException: Failed to send message to
Cluster Coordinator due to: java.net.ConnectException: Operation timed out
2017-06-23 11:14:52,374 INFO [Process Cluster Protocol Request-3]
o.a.n.c.p.impl.SocketProtocolListener Finished processing request
e636ce6d-32b2-43f1-b4f5-57fcf9a31f25 (type=HEARTBEAT, length=2724 bytes) from
localhost:8080 in 1 millis
2017-06-23 11:14:52,376 INFO [Clustering Tasks Thread-1]
o.a.n.c.c.ClusterProtocolHeartbeater Heartbeat created at 2017-06-23
11:14:39,108 and sent to localhost:10000 at 2017-06-23 11:14:52,376; send took
13268 millis
2017-06-23 11:14:52,388 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Event Reported for localhost:8080 --
Received heartbeat from node previously disconnected due to Lack of Heartbeat.
Issuing reconnection request.
2017-06-23 11:14:52,388 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Event Reported for localhost:8080 --
Requesting that node connect to cluster
2017-06-23 11:14:52,388 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Status of localhost:8080 changed from
NodeConnectionStatus[nodeId=localhost:8080, state=DISCONNECTED, Disconnect
Code=Lack of Heartbeat, Disconnect Reason=Have not received a heartbeat from
node in 41 seconds, updateId=127] to
NodeConnectionStatus[nodeId=localhost:8080, state=CONNECTING, updateId=128]
2017-06-23 11:14:52,390 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.h.AbstractHeartbeatMonitor Finished processing 1 heartbeats in 1
millis
2017-06-23 11:14:52,395 INFO [Process Cluster Protocol Request-4]
o.a.n.c.p.impl.SocketProtocolListener Finished processing request
c9b89497-1cf4-452e-a7e3-92975222f0b7 (type=RECONNECTION_REQUEST, length=2217
bytes) from localhost:8080 in 2 millis
2017-06-23 11:14:52,395 INFO [Reconnect to Cluster]
o.a.nifi.controller.StandardFlowService Processing reconnection request from
manager.
2017-06-23 11:14:52,395 INFO [Reconnect to Cluster]
o.a.n.c.c.node.NodeClusterCoordinator Resetting cluster node statuses from
{localhost:8081=NodeConnectionStatus[nodeId=localhost:8081, state=DISCONNECTED,
Disconnect Code=Lack of Heartbeat, Disconnect Reason=Have not received a
heartbeat from node in 40 seconds, updateId=126],
localhost:8080=NodeConnectionStatus[nodeId=localhost:8080, state=CONNECTING,
updateId=128]} to {localhost:8081=NodeConnectionStatus[nodeId=localhost:8081,
state=DISCONNECTED, Disconnect Code=Lack of Heartbeat, Disconnect Reason=Have
not received a heartbeat from node in 40 seconds, updateId=126],
localhost:8080=NodeConnectionStatus[nodeId=localhost:8080, state=CONNECTING,
updateId=128]}
2017-06-23 11:14:52,396 INFO [Reconnect localhost:8080]
o.a.n.c.c.node.NodeClusterCoordinator Successfully requested that
localhost:8080 join the cluster
2017-06-23 11:14:52,404 INFO [Reconnect to Cluster]
o.apache.nifi.controller.FlowController Successfully synchronized controller
with proposed flow
2017-06-23 11:14:52,413 INFO [Reconnect to Cluster]
o.a.nifi.controller.StandardFlowService Setting Flow Controller's Node ID:
localhost:8080
2017-06-23 11:14:52,413 INFO [Reconnect to Cluster]
o.a.n.c.c.node.NodeClusterCoordinator This node is now connected to the
cluster. Will no longer require election of DataFlow.
2017-06-23 11:14:52,413 INFO [Reconnect to Cluster]
o.apache.nifi.controller.FlowController Starting 0 processors/ports/funnels
2017-06-23 11:14:52,414 INFO [Reconnect to Cluster]
o.apache.nifi.controller.FlowController Started 0 Remote Group Ports
transmitting
2017-06-23 11:14:52,414 INFO [Reconnect to Cluster]
o.a.n.c.c.node.NodeClusterCoordinator Resetting cluster node statuses from
{localhost:8081=NodeConnectionStatus[nodeId=localhost:8081, state=DISCONNECTED,
Disconnect Code=Lack of Heartbeat, Disconnect Reason=Have not received a
heartbeat from node in 40 seconds, updateId=126],
localhost:8080=NodeConnectionStatus[nodeId=localhost:8080, state=CONNECTING,
updateId=128]} to {localhost:8081=NodeConnectionStatus[nodeId=localhost:8081,
state=DISCONNECTED, Disconnect Code=Lack of Heartbeat, Disconnect Reason=Have
not received a heartbeat from node in 40 seconds, updateId=126],
localhost:8080=NodeConnectionStatus[nodeId=localhost:8080, state=CONNECTING,
updateId=128]}
2017-06-23 11:14:52,416 INFO [Reconnect to Cluster]
o.a.nifi.controller.StandardFlowService Node reconnected.
2017-06-23 11:14:52,977 INFO [Process Cluster Protocol Request-5]
o.a.n.c.p.impl.SocketProtocolListener Finished processing request
c42f9b35-953d-47dc-a2f9-952307c60461 (type=HEARTBEAT, length=2344 bytes) from
localhost:8081 in 1 millis
2017-06-23 11:14:57,396 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Event Reported for localhost:8081 --
Received heartbeat from node previously disconnected due to Lack of Heartbeat.
Issuing reconnection request.
2017-06-23 11:14:57,396 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Event Reported for localhost:8081 --
Requesting that node connect to cluster
2017-06-23 11:14:57,396 INFO [Heartbeat Monitor Thread-1]
o.a.n.c.c.node.NodeClusterCoordinator Status of localhost:8081 changed from
NodeConnectionStatus[nodeId=localhost:8081, state=DISCONNECTED, Disconnect
Code=Lack of Heartbeat, Disconnect Reason=Have not received a heartbeat from
node in 40 seconds, updateId=126] to
NodeConnectionStatus[nodeId=localhost:8081, state=CONNECTING, updateId=130]
```
> Duplicated stack trace in ThreadPoolRequestReplicator
> -----------------------------------------------------
>
> Key: NIFI-4073
> URL: https://issues.apache.org/jira/browse/NIFI-4073
> Project: Apache NiFi
> Issue Type: Bug
> Components: Core Framework
> Affects Versions: 1.3.0
> Reporter: Pierre Villard
> Assignee: Pierre Villard
> Priority: Trivial
>
> There is a duplicated stack trace due to the following part.
> {code:title=ThreadPoolRequestReplicator.java|borderStyle=solid}
> try {
> // create and send the request
> final WebResource.Builder resourceBuilder = createResourceBuilder();
> final String requestId = headers.get("x-nifi-request-id");
> logger.debug("Replicating request {} {} to {}", method, uri.getPath(),
> nodeId);
> nodeResponse = replicateRequest(resourceBuilder, nodeId, method, uri,
> requestId, headers, clusterResponse);
> } catch (final Exception e) {
> nodeResponse = new NodeResponse(nodeId, method, uri, e);
> logger.warn("Failed to replicate request {} {} to {} due to {}", method,
> uri.getPath(), nodeId, e);
> logger.warn("", e);
> }
> {code}
> It just requires to use {{e.toString()}}.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
