private async Task <BlockHeader[]> SendRequest(GetBlockHeadersMessage message, CancellationToken token)
{
if (_headersRequests.IsAddingCompleted || _isDisposed)
{
throw new TimeoutException("Session disposed");
}
if (Logger.IsTrace)
{
Logger.Trace($"Sending headers request to {Session.Node:c}:");
Logger.Trace($" Starting blockhash: {message.StartingBlockHash}");
Logger.Trace($" Starting number: {message.StartingBlockNumber}");
Logger.Trace($" Skip: {message.Skip}");
Logger.Trace($" Reverse: {message.Reverse}");
Logger.Trace($" Max headers: {message.MaxHeaders}");
}
var request = new Request <GetBlockHeadersMessage, BlockHeader[]>(message);
_headersRequests.Add(request, token);
var perfCalcId = _perfService.StartPerfCalc();
Send(request.Message);
Task <BlockHeader[]> task = request.CompletionSource.Task;
CancellationTokenSource delayCancellation = new CancellationTokenSource();
CancellationTokenSource compositeCancellation = CancellationTokenSource.CreateLinkedTokenSource(token, delayCancellation.Token);
var firstTask = await Task.WhenAny(task, Task.Delay(Timeouts.Eth, compositeCancellation.Token));
if (firstTask.IsCanceled)
{
token.ThrowIfCancellationRequested();
}
if (firstTask == task)
{
delayCancellation.Cancel();
var latency = _perfService.EndPerfCalc(perfCalcId);
if (latency.HasValue)
{
StatsManager.ReportLatencyCaptureEvent(Session.Node, NodeLatencyStatType.BlockHeaders, latency.Value);
}
return(task.Result);
}
_perfService.EndPerfCalc(perfCalcId);
throw new TimeoutException($"{Session} Request timeout in {nameof(GetBlockHeadersMessage)} with {message.MaxHeaders} max headers");
}
public async Task StopAsync()
{
var key = _perfService.StartPerfCalc();
_appShutdownSource.Cancel();
StopDiscoveryTimer();
//StopRefreshTimer();
StopDiscoveryPersistenceTimer();
if (_storageCommitTask != null)
{
await _storageCommitTask.ContinueWith(x =>
{
if (x.IsFaulted)
{
if (_logger.IsError)
{
_logger.Error("Error during discovery persisntance stop.", x.Exception);
}
}
});
}
await StopUdpChannelAsync();
if (_logger.IsInfo)
{
_logger.Info("Discovery shutdown complete.. please wait for all components to close");
}
_perfService.EndPerfCalc(key, "Close: DiscoveryApp");
}
public async Task Shutdown()
{
var key = _perfService.StartPerfCalc();
// InternalLoggerFactory.DefaultFactory.AddProvider(new ConsoleLoggerProvider((s, level) => true, false));
await _bootstrapChannel.CloseAsync().ContinueWith(t =>
{
if (t.IsFaulted)
{
_logger.Error($"{nameof(Shutdown)} failed", t.Exception);
}
});
_logger.Debug("Closed _bootstrapChannel");
var nettyCloseTimeout = TimeSpan.FromMilliseconds(100);
var closingTask = Task.WhenAll(_bossGroup.ShutdownGracefullyAsync(nettyCloseTimeout, nettyCloseTimeout),
_workerGroup.ShutdownGracefullyAsync(nettyCloseTimeout, nettyCloseTimeout));
//we need to add additional timeout on our side as netty is not executing internal timeout properly, often it just hangs forever on closing
if (await Task.WhenAny(closingTask, Task.Delay(Timeouts.TcpClose)) != closingTask)
{
_logger.Warn($"Could not close rlpx connection in {Timeouts.TcpClose.TotalSeconds} seconds");
}
_logger.Debug("Closed _bossGroup and _workerGroup");
_perfService.EndPerfCalc(key, "Close: Rlpx");
}
public async Task StopAsync()
{
var key = _perfService.StartPerfCalc();
_appShutdown = true;
StopDiscoveryTimer();
//StopRefreshTimer();
StopDiscoveryPersistanceTimer();
if (_storageCommitTask != null)
{
await _storageCommitTask.ContinueWith(x =>
{
if (x.IsFaulted)
{
if (_logger.IsError)
{
_logger.Error("Error during discovery persisntance stop.", x.Exception);
}
}
});
}
await StopUdpChannelAsync();
_perfService.EndPerfCalc(key, "Close: DiscoveryApp");
}
private async Task <BlockHeader[]> SendRequest(GetBlockHeadersMessage message, CancellationToken token)
{
if (Logger.IsTrace)
{
Logger.Trace("Sending headers request:");
Logger.Trace($"Starting blockhash: {message.StartingBlockHash}");
Logger.Trace($"Starting number: {message.StartingBlockNumber}");
Logger.Trace($"Skip: {message.Skip}");
Logger.Trace($"Reverse: {message.Reverse}");
Logger.Trace($"Max headers: {message.MaxHeaders}");
}
var request = new Request <GetBlockHeadersMessage, BlockHeader[]>(message);
_headersRequests.Add(request, token);
var perfCalcId = _perfService.StartPerfCalc();
Send(request.Message);
Task <BlockHeader[]> task = request.CompletionSource.Task;
var firstTask = await Task.WhenAny(task, Task.Delay(Timeouts.Eth, token));
if (firstTask.IsCanceled)
{
token.ThrowIfCancellationRequested();
}
if (firstTask == task)
{
var latency = _perfService.EndPerfCalc(perfCalcId);
if (latency.HasValue)
{
P2PSession?.NodeStats.AddLatencyCaptureEvent(NodeLatencyStatType.BlockHeaders, latency.Value);
}
return(task.Result);
}
throw new TimeoutException($"{P2PSession.RemoteNodeId} Request timeout in {nameof(GetBlockHeadersMessage)}");
}
public async Task <bool> SendPing()
{
if (!_isInitialized)
{
return(true);
}
if (_pongCompletionSource != null)
{
if (Logger.IsWarn)
{
Logger.Warn($"Another ping request in process: {Session.RemoteNodeId}");
}
return(true);
}
_pongCompletionSource = new TaskCompletionSource <Packet>();
var pongTask = _pongCompletionSource.Task;
if (Logger.IsTrace)
{
Logger.Trace($"{Session} P2P sending ping on {Session.RemotePort} ({RemoteClientId})");
}
Send(PingMessage.Instance);
_nodeStatsManager.ReportEvent(Session.Node, NodeStatsEventType.P2PPingOut);
var pingPerfCalcId = _perfService.StartPerfCalc();
CancellationTokenSource delayCancellation = new CancellationTokenSource();
var firstTask = await Task.WhenAny(pongTask, Task.Delay(Timeouts.P2PPing, delayCancellation.Token));
_pongCompletionSource = null;
if (firstTask != pongTask)
{
return(false);
}
delayCancellation.Cancel();
var latency = _perfService.EndPerfCalc(pingPerfCalcId);
if (latency.HasValue)
{
_nodeStatsManager.ReportLatencyCaptureEvent(Session.Node, NodeLatencyStatType.P2PPingPong, latency.Value);
}
return(true);
}
public async Task RunPeerUpdate()
{
lock (_isPeerUpdateInProgressLock)
{
if (_isPeerUpdateInProgress)
{
return;
}
_isPeerUpdateInProgress = true;
}
var key = _perfService.StartPerfCalc();
var availibleActiveCount = _configurationProvider.ActivePeersMaxCount - _activePeers.Count;
if (availibleActiveCount <= 0)
{
return;
}
var candidates = _newPeers.OrderBy(x => x.Value.NodeStats.IsTrustedPeer)
.ThenByDescending(x => x.Value.NodeStats.CurrentNodeReputation)
.Take(availibleActiveCount).ToArray();
var newActiveNodes = 0;
for (var i = 0; i < candidates.Length; i++)
{
var candidate = candidates[i];
_newPeers.TryRemove(candidate.Key, out _);
if (!_activePeers.TryAdd(candidate.Key, candidate.Value))
{
if (_logger.IsErrorEnabled)
{
_logger.Error($"Active peer was already added to collection: {candidate.Key.ToString(false)}");
continue;
}
}
var result = await InitializePeerConnection(candidate.Value);
if (result)
{
newActiveNodes++;
}
}
if (_logger.IsInfoEnabled)
{
_logger.Info($"RunPeerUpdate | Tried: {candidates.Length}, Added {newActiveNodes} active peers, current new peers: {_newPeers.Count}, current active peers: {_activePeers.Count}");
if (_logCounter % 5 == 0)
{
//TODO Change to debug after testing
_logger.Info($"\n\nAll active peers: \n{string.Join('\n', ActivePeers.Select(x => $"{x.Node.ToString()} | P2PInitialized: {x.NodeStats.DidEventHappen(NodeStatsEvent.P2PInitialized)} | Eth62Initialized: {x.NodeStats.DidEventHappen(NodeStatsEvent.Eth62Initialized)} | ClientId: {x.NodeStats.NodeDetails.ClientId}"))} \n\n");
}
_logCounter++;
}
_perfService.EndPerfCalc(key, "RunPeerUpdate");
_isPeerUpdateInProgress = false;
}
public void LogSessionStats(IReadOnlyCollection <Peer> activePeers, IReadOnlyCollection <Peer> candidatePeers, bool logEventDetails)
{
var key = _perfService.StartPerfCalc();
var peers = activePeers.Concat(candidatePeers).GroupBy(x => x.Node.Id).Select(x => x.First()).ToArray();
var eventTypes = Enum.GetValues(typeof(NodeStatsEventType)).OfType <NodeStatsEventType>().Where(x => !x.ToString().Contains("Discovery"))
.OrderBy(x => x).ToArray();
var eventStats = eventTypes.Select(x => new
{
EventType = x.ToString(),
Count = peers.Count(y => y.NodeStats.DidEventHappen(x))
}).ToArray();
var chains = peers.Where(x => x.NodeStats.EthNodeDetails != null).GroupBy(x => x.NodeStats.EthNodeDetails.ChainId).Select(
x => new { ChainName = ChainId.GetChainName((int)x.Key), Count = x.Count() }).ToArray();
var clients = peers.Where(x => x.NodeStats.P2PNodeDetails != null).Select(x => x.NodeStats.P2PNodeDetails.ClientId).GroupBy(x => x).Select(
x => new { ClientId = x.Key, Count = x.Count() }).ToArray();
var remoteDisconnect = peers.Count(x => x.NodeStats.EventHistory.Any(y => y.DisconnectDetails != null && y.DisconnectDetails.DisconnectType == DisconnectType.Remote));
var sb = new StringBuilder();
sb.AppendLine($"Session stats | {DateTime.Now.ToString(_networkConfig.DetailedTimeDateFormat)} | Active peers: {activePeers.Count} | Candidate peers: {candidatePeers.Count}");
sb.AppendLine($"Peers count with each EVENT:{Environment.NewLine}" +
$"{string.Join(Environment.NewLine, eventStats.Select(x => $"{x.EventType.ToString()}:{x.Count}"))}{Environment.NewLine}" +
$"Remote disconnect: {remoteDisconnect}{Environment.NewLine}{Environment.NewLine}" +
$"CHAINS: {Environment.NewLine}" +
$"{string.Join(Environment.NewLine, chains.Select(x => $"{x.ChainName}:{x.Count}"))}{Environment.NewLine}{Environment.NewLine}" +
$"CLIENTS:{Environment.NewLine}" +
$"{string.Join(Environment.NewLine, clients.Select(x => $"{x.ClientId}:{x.Count}"))}{Environment.NewLine}");
var peersWithLatencyStats = peers.Where(x => x.NodeStats.LatencyHistory.Any()).ToArray();
if (peersWithLatencyStats.Any())
{
var latencyLog = GetLatencyComparisonLog(peersWithLatencyStats);
sb.AppendLine(latencyLog);
}
if (_statsConfig.CaptureNodeStatsEventHistory && logEventDetails)
{
sb.AppendLine($"All peers ({peers.Length}):");
sb.AppendLine($"{string.Join(Environment.NewLine, peers.Select(x => GetNodeLog(x.NodeStats)))}{Environment.NewLine}");
var peersWithEvents = peers.Where(x => x.NodeStats.EventHistory.Any(y => y.EventType != NodeStatsEventType.NodeDiscovered)).ToArray();
sb.AppendLine($"Logging {peersWithEvents.Length} peers log event histories");
foreach (var peer in peersWithEvents)
{
LogPeerEventHistory(peer);
}
}
else
{
sb.AppendLine($"Detailed session log disabled, CaptureNodeStatsEventHistory: {_statsConfig.CaptureNodeStatsEventHistory}, logEventDetails: {logEventDetails}");
}
sb.AppendLine();
var generalFilePath = Path.Combine(_eventLogsDirectoryPath, "generalStats.log");
var content = sb.ToString();
File.AppendAllText(generalFilePath, content);
if (_logger.IsTrace)
{
_logger.Trace(content);
}
var logTime = _perfService.EndPerfCalc(key);
if (_logger.IsDebug)
{
_logger.Debug($"LogSessionStats time: {logTime} ms");
}
}
public async Task RunPeerUpdate()
{
lock (_isPeerUpdateInProgressLock)
{
if (_isPeerUpdateInProgress)
{
return;
}
_isPeerUpdateInProgress = true;
}
var key = _perfService.StartPerfCalc();
var availibleActiveCount = _configurationProvider.ActivePeersMaxCount - _activePeers.Count;
if (availibleActiveCount <= 0)
{
return;
}
var candidates = _candidatePeers.Where(x => !_activePeers.ContainsKey(x.Key) && CheckLastDisconnect(x.Value))
.OrderBy(x => x.Value.NodeStats.IsTrustedPeer)
.ThenByDescending(x => x.Value.NodeStats.CurrentNodeReputation).ToArray();
var newActiveNodes = 0;
var tryCount = 0;
for (var i = 0; i < candidates.Length; i++)
{
if (newActiveNodes >= availibleActiveCount)
{
break;
}
var candidate = candidates[i];
tryCount++;
if (!_activePeers.TryAdd(candidate.Key, candidate.Value))
{
if (_logger.IsErrorEnabled)
{
_logger.Error($"Active peer was already added to collection: {candidate.Key}");
}
}
var result = await InitializePeerConnection(candidate.Value);
if (!result)
{
_activePeers.TryRemove(candidate.Key, out _);
continue;
}
newActiveNodes++;
}
if (_logger.IsInfoEnabled)
{
_logger.Info($"{nameof(RunPeerUpdate)} | Tried: {tryCount}, Added {newActiveNodes} active peers, current candidate peers: {_candidatePeers.Count}, current active peers: {_activePeers.Count}");
if (_logCounter % 5 == 0)
{
string nl = Environment.NewLine;
_logger.Debug($"{nl}{nl}All active peers: {nl}{string.Join(nl, ActivePeers.Select(x => $"{x.Node.ToString()} | P2PInitialized: {x.NodeStats.DidEventHappen(NodeStatsEvent.P2PInitialized)} | Eth62Initialized: {x.NodeStats.DidEventHappen(NodeStatsEvent.Eth62Initialized)} | ClientId: {x.NodeStats.NodeDetails.ClientId}"))} {nl}{nl}");
}
_logCounter++;
}
_perfService.EndPerfCalc(key, "RunPeerUpdate");
_isPeerUpdateInProgress = false;
}