public void If_comes_back_empty_then_it_can_be_reused()
{
LoadScenario(_1024BodiesWithOneTxEach);
ReceiptsSyncBatch batch = _feed.PrepareRequest().Result;
SyncResponseHandlingResult handlingResult = _feed.HandleResponse(batch);
handlingResult.Should().Be(SyncResponseHandlingResult.NotAssigned);
ReceiptsSyncBatch batch2 = _feed.PrepareRequest().Result;
batch2.Should().BeSameAs(batch);
batch2.Retries.Should().Be(1);
}
public void If_comes_back_filled_with_empty_responses_then_it_can_be_reused()
{
LoadScenario(_1024BodiesWithOneTxEach);
ReceiptsSyncBatch batch = _feed.PrepareRequest().Result;
batch.Response = new TxReceipt[batch.Request.Length][];
SyncResponseHandlingResult handlingResult = _feed.HandleResponse(batch);
handlingResult.Should().Be(SyncResponseHandlingResult.NoProgress);
ReceiptsSyncBatch batch2 = _feed.PrepareRequest().Result;
batch2.Should().BeSameAs(batch);
batch2.Retries.Should().Be(1);
}
public void If_only_one_valid_item_comes_back_then_we_create_a_filler_batch()
{
LoadScenario(_1024BodiesWithOneTxEach);
ReceiptsSyncBatch batch = _feed.PrepareRequest().Result;
batch.Response = new TxReceipt[batch.Request.Length][];
batch.Response[0] = new [] { Build.A.Receipt.TestObject };
SyncResponseHandlingResult handlingResult = _feed.HandleResponse(batch);
handlingResult.Should().Be(SyncResponseHandlingResult.OK);
ReceiptsSyncBatch batch2 = _feed.PrepareRequest().Result;
batch2.Request.Length.Should().Be(batch.Request.Length - 1);
}
public void If_receipts_root_comes_invalid_then_reports_breach_of_protocol()
{
LoadScenario(_1024BodiesWithOneTxEach);
ReceiptsSyncBatch batch = _feed.PrepareRequest().Result;
batch.Response = new TxReceipt[batch.Request.Length][];
// default receipts that we use when constructing receipt root for tests have stats code 0
// so by using 1 here we create a different tx root
batch.Response[0] = new [] { Build.A.Receipt.WithStatusCode(1).TestObject };
PeerInfo peerInfo = new PeerInfo(Substitute.For <ISyncPeer>());
batch.ResponseSourcePeer = peerInfo;
SyncResponseHandlingResult handlingResult = _feed.HandleResponse(batch);
handlingResult.Should().Be(SyncResponseHandlingResult.NoProgress);
_syncPeerPool.Received().ReportBreachOfProtocol(peerInfo, Arg.Any <string>());
}
public override SyncResponseHandlingResult HandleResponse(StateSyncBatch batch)
{
if (batch == EmptyBatch)
{
_logger.Error("Received empty batch as a response");
}
if (!_pendingRequests.TryRemove(batch, out _))
{
if (_logger.IsDebug)
{
_logger.Debug($"Cannot remove pending request {batch}");
}
return(SyncResponseHandlingResult.OK);
}
else
{
if (_logger.IsTrace)
{
_logger.Trace($"Removing pending request {batch}");
}
}
int requestLength = batch.RequestedNodes?.Length ?? 0;
int responseLength = batch.Responses?.Length ?? 0;
void AddAgainAllItems()
{
for (int i = 0; i < requestLength; i++)
{
AddNodeToPending(batch.RequestedNodes[i], null, "missing", true);
}
}
try
{
lock (_handleWatch)
{
if (DateTime.UtcNow - _lastReview > TimeSpan.FromSeconds(60))
{
_lastReview = DateTime.UtcNow;
string reviewMessage = _pendingItems.RecalculatePriorities();
if (_logger.IsInfo)
{
_logger.Info(reviewMessage);
}
}
_handleWatch.Restart();
bool requestWasMade = batch.Responses != null;
if (!requestWasMade)
{
AddAgainAllItems();
if (_logger.IsTrace)
{
_logger.Trace($"Batch was not assigned to any peer.");
}
Interlocked.Increment(ref _data.NotAssignedCount);
return(SyncResponseHandlingResult.NotAssigned);
}
bool isMissingRequestData = batch.RequestedNodes == null;
bool isMissingResponseData = batch.Responses == null;
bool hasValidFormat = !isMissingRequestData && !isMissingResponseData;
if (!hasValidFormat)
{
_hintsToResetRoot++;
AddAgainAllItems();
if (_logger.IsWarn)
{
_logger.Warn($"Batch response had invalid format");
}
Interlocked.Increment(ref _data.InvalidFormatCount);
return(isMissingRequestData ? SyncResponseHandlingResult.InternalError : SyncResponseHandlingResult.NotAssigned);
}
if (_logger.IsTrace)
{
_logger.Trace($"Received node data - {responseLength} items in response to {requestLength}");
}
int nonEmptyResponses = 0;
int invalidNodes = 0;
for (int i = 0; i < batch.RequestedNodes.Length; i++)
{
StateSyncItem currentStateSyncItem = batch.RequestedNodes[i];
/* if the peer has limit on number of requests in a batch then the response will possibly be
* shorter than the request */
if (batch.Responses.Length < i + 1)
{
AddNodeToPending(currentStateSyncItem, null, "missing", true);
continue;
}
/* if the peer does not have details of this particular node */
byte[] currentResponseItem = batch.Responses[i];
if (currentResponseItem == null)
{
AddNodeToPending(batch.RequestedNodes[i], null, "missing", true);
continue;
}
/* node sent data that is not consistent with its hash - it happens surprisingly often */
if (!ValueKeccak.Compute(currentResponseItem).BytesAsSpan.SequenceEqual(currentStateSyncItem.Hash.Bytes))
{
AddNodeToPending(currentStateSyncItem, null, "missing", true);
if (_logger.IsTrace)
{
_logger.Trace($"Peer sent invalid data (batch {requestLength}->{responseLength}) of length {batch.Responses[i]?.Length} of type {batch.RequestedNodes[i].NodeDataType} at level {batch.RequestedNodes[i].Level} of type {batch.RequestedNodes[i].NodeDataType} Keccak({batch.Responses[i].ToHexString()}) != {batch.RequestedNodes[i].Hash}");
}
invalidNodes++;
continue;
}
nonEmptyResponses++;
NodeDataType nodeDataType = currentStateSyncItem.NodeDataType;
if (nodeDataType == NodeDataType.Code)
{
SaveNode(currentStateSyncItem, currentResponseItem);
continue;
}
HandleTrieNode(currentStateSyncItem, currentResponseItem, ref invalidNodes);
}
Interlocked.Add(ref _data.ConsumedNodesCount, nonEmptyResponses);
StoreProgressInDb();
if (_logger.IsTrace)
{
_logger.Trace($"After handling response (non-empty responses {nonEmptyResponses}) of {batch.RequestedNodes.Length} from ({_pendingItems.Description}) nodes");
}
/* magic formula is ratio of our desired batch size - 1024 to Geth max batch size 384 times some missing nodes ratio */
bool isEmptish = (decimal)nonEmptyResponses / Math.Max(requestLength, 1) < 384m / 1024m * 0.75m;
if (isEmptish)
{
Interlocked.Increment(ref _hintsToResetRoot);
Interlocked.Increment(ref _data.EmptishCount);
}
else
{
Interlocked.Exchange(ref _hintsToResetRoot, 0);
}
/* here we are very forgiving for Geth nodes that send bad data fast */
bool isBadQuality = nonEmptyResponses > 64 && (decimal)invalidNodes / Math.Max(requestLength, 1) > 0.50m;
if (isBadQuality)
{
Interlocked.Increment(ref _data.BadQualityCount);
}
bool isEmpty = nonEmptyResponses == 0 && !isBadQuality;
if (isEmpty)
{
if (_logger.IsDebug)
{
_logger.Debug($"Peer sent no data in response to a request of length {batch.RequestedNodes.Length}");
}
return(SyncResponseHandlingResult.NoProgress);
}
if (!isEmptish && !isBadQuality)
{
Interlocked.Increment(ref _data.OkCount);
}
SyncResponseHandlingResult result = isEmptish
? SyncResponseHandlingResult.Emptish
: isBadQuality
? SyncResponseHandlingResult.LesserQuality
: SyncResponseHandlingResult.OK;
_data.DisplayProgressReport(_pendingRequests.Count, _logger);
long total = _handleWatch.ElapsedMilliseconds + _networkWatch.ElapsedMilliseconds;
if (total != 0)
{
// calculate averages
if (_logger.IsTrace)
{
_logger.Trace($"Prepare batch {_networkWatch.ElapsedMilliseconds}ms ({(decimal) _networkWatch.ElapsedMilliseconds / total:P0}) - Handle {_handleWatch.ElapsedMilliseconds}ms ({(decimal) _handleWatch.ElapsedMilliseconds / total:P0})");
}
}
if (_handleWatch.ElapsedMilliseconds > 250)
{
if (_logger.IsDebug)
{
_logger.Debug($"Handle watch {_handleWatch.ElapsedMilliseconds}, DB reads {_data.DbChecks - _data.LastDbReads}, ratio {(decimal) _handleWatch.ElapsedMilliseconds / Math.Max(1, _data.DbChecks - _data.LastDbReads)}");
}
}
_data.LastDbReads = _data.DbChecks;
_data.AverageTimeInHandler = (_data.AverageTimeInHandler * (_data.ProcessedRequestsCount - 1) + _handleWatch.ElapsedMilliseconds) / _data.ProcessedRequestsCount;
Interlocked.Add(ref _data.HandledNodesCount, nonEmptyResponses);
return(result);
}
}
catch (Exception e)
{
_logger.Error("Error when handling state sync response", e);
return(SyncResponseHandlingResult.InternalError);
}
finally
{
_handleWatch.Stop();
}
}
