Skip to content

Optimize: use Serilog instead #1013

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
Wi1l-B0t wants to merge 10 commits into
base: master-n3
Choose a base branch
from
Open

Optimize: use Serilog instead #1013

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
e4d8cc7
Optimize: user Serilog instead
Wi1l-B0t Mar 13, 2026
38578e7
test: cover consensus service message routing
Jim8y Mar 17, 2026
9b6cb70
test: exercise consensus send and check paths
Jim8y Mar 17, 2026
7ce1450
test: cover consensus warning and lifecycle paths
Jim8y Mar 17, 2026
41b50ed
test: cover plugin logging and password guards
Jim8y Mar 17, 2026
b94e875
test: stabilize consensus lifecycle coverage
Jim8y Mar 17, 2026
5583dbe
test: cover cli log directory startup
Jim8y Mar 17, 2026
7a5a953
style: format cli wallet tests
Jim8y Mar 17, 2026
115116f
Merge branch 'master-n3' into optimize.use-serilog-instead
shargon Mar 18, 2026
ec792d4
Update plugins/OracleService/Protocols/OracleNeoFSProtocol.cs
Jim8y Mar 18, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion plugins/DBFTPlugin/Consensus/ConsensusContext.MakePayload.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ private void SignPayload(ExtensiblePayload payload)
}
catch (InvalidOperationException ex)
{
Utility.Log(nameof(ConsensusContext), LogLevel.Debug, ex.ToString());
DBFTPlugin.PluginLogger?.Information("Error signing payload {Exception}", ex.ToString());
return;
}
}
Expand Down
6 changes: 3 additions & 3 deletions plugins/DBFTPlugin/Consensus/ConsensusContext.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -124,8 +124,8 @@ public ConsensusContext(NeoSystem neoSystem, DbftSettings settings, ISigner sign
string defaultPath = settings.RecoveryLogs.Contains("{0}") ? settings.RecoveryLogs : $"{settings.RecoveryLogs}_{{0}}";
var pluginPath = string.Format(defaultPath, networkId);
var path = PluginHelper.ApplyUnifiedStoragePath(pluginPath);
var fullPath = System.IO.Path.GetFullPath(path);
System.IO.Directory.CreateDirectory(fullPath);
var fullPath = Path.GetFullPath(path);
Directory.CreateDirectory(fullPath);
store = neoSystem.LoadStore(fullPath);
}
}
Expand Down Expand Up @@ -193,7 +193,7 @@ public bool Load()
}
catch (Exception exception)
{
Utility.Log(nameof(ConsensusContext), LogLevel.Debug, exception.ToString());
DBFTPlugin.PluginLogger?.Information("Error loading consensus context {Exception}", exception.ToString());
return false;
}
return true;
Expand Down
18 changes: 11 additions & 7 deletions plugins/DBFTPlugin/Consensus/ConsensusService.Check.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -30,14 +30,14 @@ private bool CheckPrepareResponse()
// Check maximum block size via Native Contract policy
if (context.GetExpectedBlockSize() > dbftSettings.MaxBlockSize)
{
Log($"Rejected block: {context.Block.Index} The size exceed the policy", LogLevel.Warning);
DBFTPlugin.PluginLogger?.Warning("Rejected block: {Index} The size exceed the policy", context.Block.Index);
RequestChangeView(ChangeViewReason.BlockRejectedByPolicy);
return false;
}
// Check maximum block system fee via Native Contract policy
if (context.GetExpectedBlockSystemFee() > dbftSettings.MaxBlockSystemFee)
{
Log($"Rejected block: {context.Block.Index} The system fee exceed the policy", LogLevel.Warning);
DBFTPlugin.PluginLogger?.Warning("Rejected block: {Index} The system fee exceed the policy", context.Block.Index);
RequestChangeView(ChangeViewReason.BlockRejectedByPolicy);
return false;
}
Expand All @@ -46,7 +46,8 @@ private bool CheckPrepareResponse()
// around 2*15/M=30.0/5 ~ 40% block time (for M=5)
ExtendTimerByFactor(2);

Log($"Sending {nameof(PrepareResponse)}");
DBFTPlugin.PluginLogger?.Information("Sending PrepareResponse height={Index} view={ViewNumber}",
context.Block.Index, context.ViewNumber);
localNode.Tell(new LocalNode.SendDirectly(context.MakePrepareResponse()));
CheckPreparations();
}
Expand All @@ -55,11 +56,13 @@ private bool CheckPrepareResponse()

private void CheckCommits()
{
if (context.CommitPayloads.Count(p => context.GetMessage(p)?.ViewNumber == context.ViewNumber) >= context.M && context.TransactionHashes.All(p => context.Transactions.ContainsKey(p)))
if (context.CommitPayloads.Count(p => context.GetMessage(p)?.ViewNumber == context.ViewNumber) >= context.M
&& context.TransactionHashes.All(p => context.Transactions.ContainsKey(p)))
{
block_received_index = context.Block.Index;
Block block = context.CreateBlock();
Log($"Sending {nameof(Block)}: height={block.Index} hash={block.Hash} tx={block.Transactions.Length}");
DBFTPlugin.PluginLogger?.Information("Sending Block: height={Index} hash={Hash} tx={TransactionsLength}",
block.Index, block.Hash, block.Transactions.Length);
blockchain.Tell(block);
}
}
Expand All @@ -85,10 +88,11 @@ private void CheckExpectedView(byte viewNumber)

private void CheckPreparations()
{
if (context.PreparationPayloads.Count(p => p != null) >= context.M && context.TransactionHashes.All(p => context.Transactions.ContainsKey(p)))
if (context.PreparationPayloads.Count(p => p != null) >= context.M
&& context.TransactionHashes.All(p => context.Transactions.ContainsKey(p)))
{
ExtensiblePayload payload = context.MakeCommit();
Log($"Sending {nameof(Commit)}");
DBFTPlugin.PluginLogger?.Information("Sending Commit: height={BlockIndex} view={ViewNumber}", context.Block.Index, context.ViewNumber);
context.Save();
localNode.Tell(new LocalNode.SendDirectly(payload));
// Set timer, so we will resend the commit in case of a networking issue
Expand Down
58 changes: 42 additions & 16 deletions plugins/DBFTPlugin/Consensus/ConsensusService.OnMessage.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@ private void OnConsensusPayload(ExtensiblePayload payload)
}
catch (Exception ex)
{
Utility.Log(nameof(ConsensusService), LogLevel.Debug, ex.ToString());
DBFTPlugin.PluginLogger?.Information("Error getting message {Exception}", ex.ToString());
return;
}

Expand All @@ -44,7 +44,7 @@ private void OnConsensusPayload(ExtensiblePayload payload)
{
if (context.Block.Index < message.BlockIndex)
{
Log($"Chain is behind: expected={message.BlockIndex} current={context.Block.Index - 1}", LogLevel.Warning);
DBFTPlugin.PluginLogger?.Warning("Chain is behind: expected={Expected} current={Current}", message.BlockIndex, context.Block.Index - 1);
}
return;
}
Expand Down Expand Up @@ -80,16 +80,19 @@ private void OnPrepareRequestReceived(ExtensiblePayload payload, PrepareRequest
if (message.ValidatorIndex != context.Block.PrimaryIndex || message.ViewNumber != context.ViewNumber) return;
if (message.Version != context.Block.Version || message.PrevHash != context.Block.PrevHash) return;
if (message.TransactionHashes.Length > neoSystem.Settings.MaxTransactionsPerBlock) return;
Log($"{nameof(OnPrepareRequestReceived)}: height={message.BlockIndex} view={message.ViewNumber} index={message.ValidatorIndex} tx={message.TransactionHashes.Length}");
if (message.Timestamp <= context.PrevHeader.Timestamp || message.Timestamp > TimeProvider.Current.UtcNow.AddMilliseconds(8 * context.TimePerBlock.TotalMilliseconds).ToTimestampMS())

DBFTPlugin.PluginLogger?.Information("OnPrepareRequestReceived: height={BlockIndex} view={ViewNumber} index={ValidatorIndex} tx={TransactionHashesLength}",
message.BlockIndex, message.ViewNumber, message.ValidatorIndex, message.TransactionHashes.Length);
if (message.Timestamp <= context.PrevHeader.Timestamp
|| message.Timestamp > TimeProvider.Current.UtcNow.AddMilliseconds(8 * context.TimePerBlock.TotalMilliseconds).ToTimestampMS())
{
Log($"Timestamp incorrect: {message.Timestamp}", LogLevel.Warning);
DBFTPlugin.PluginLogger?.Warning("Timestamp incorrect: {Timestamp}", message.Timestamp);
return;
}

if (message.TransactionHashes.Any(p => NativeContract.Ledger.ContainsTransaction(context.Snapshot, p)))
{
Log($"Invalid request: transaction already exists", LogLevel.Warning);
DBFTPlugin.PluginLogger?.Warning("Invalid request: transaction already exists");
return;
}

Expand All @@ -107,15 +110,24 @@ private void OnPrepareRequestReceived(ExtensiblePayload payload, PrepareRequest
context.Transactions = new Dictionary<UInt256, Transaction>();
context.VerificationContext = new TransactionVerificationContext();
for (int i = 0; i < context.PreparationPayloads.Length; i++)
{
if (context.PreparationPayloads[i] != null)
{
if (!context.GetMessage<PrepareResponse>(context.PreparationPayloads[i]).PreparationHash.Equals(payload.Hash))
context.PreparationPayloads[i] = null;
}
}

context.PreparationPayloads[message.ValidatorIndex] = payload;
byte[] hashData = context.EnsureHeader().GetSignData(neoSystem.Settings.Network);
for (int i = 0; i < context.CommitPayloads.Length; i++)
{
if (context.GetMessage(context.CommitPayloads[i])?.ViewNumber == context.ViewNumber)
{
if (!Crypto.VerifySignature(hashData, context.GetMessage<Commit>(context.CommitPayloads[i]).Signature.Span, context.Validators[i]))
context.CommitPayloads[i] = null;
}
}

if (context.TransactionHashes.Length == 0)
{
Expand All @@ -133,7 +145,7 @@ private void OnPrepareRequestReceived(ExtensiblePayload payload, PrepareRequest
{
if (NativeContract.Ledger.ContainsConflictHash(context.Snapshot, hash, tx.Signers.Select(s => s.Account), mtb))
{
Log($"Invalid request: transaction has on-chain conflict", LogLevel.Warning);
DBFTPlugin.PluginLogger?.Warning("Invalid request: transaction has on-chain conflict");
return;
}

Expand All @@ -146,16 +158,19 @@ private void OnPrepareRequestReceived(ExtensiblePayload payload, PrepareRequest
{
if (NativeContract.Ledger.ContainsConflictHash(context.Snapshot, hash, tx.Signers.Select(s => s.Account), mtb))
{
Log($"Invalid request: transaction has on-chain conflict", LogLevel.Warning);
DBFTPlugin.PluginLogger?.Warning("Invalid request: transaction has on-chain conflict");
return;
}
unverified.Add(tx);
}
}
}

foreach (Transaction tx in unverified)
{
if (!AddTransaction(tx, true))
return;
}
if (context.Transactions.Count < context.TransactionHashes.Length)
{
UInt256[] hashes = context.TransactionHashes.Where(i => !context.Transactions.ContainsKey(i)).ToArray();
Expand All @@ -167,14 +182,18 @@ private void OnPrepareResponseReceived(ExtensiblePayload payload, PrepareRespons
{
if (message.ViewNumber != context.ViewNumber) return;
if (context.PreparationPayloads[message.ValidatorIndex] != null || context.NotAcceptingPayloadsDueToViewChanging) return;
if (context.PreparationPayloads[context.Block.PrimaryIndex] != null && !message.PreparationHash.Equals(context.PreparationPayloads[context.Block.PrimaryIndex].Hash))
if (context.PreparationPayloads[context.Block.PrimaryIndex] != null
&& !message.PreparationHash.Equals(context.PreparationPayloads[context.Block.PrimaryIndex].Hash))
{
return;
}

// Timeout extension: prepare response has been received with success
// around 2*15/M=30.0/5 ~ 40% block time (for M=5)
ExtendTimerByFactor(2);

Log($"{nameof(OnPrepareResponseReceived)}: height={message.BlockIndex} view={message.ViewNumber} index={message.ValidatorIndex}");
DBFTPlugin.PluginLogger?.Information("OnPrepareResponseReceived: height={BlockIndex} view={ViewNumber} index={ValidatorIndex}",
message.BlockIndex, message.ViewNumber, message.ValidatorIndex);
context.PreparationPayloads[message.ValidatorIndex] = payload;
if (context.WatchOnly || context.CommitSent) return;
if (context.RequestSentOrReceived)
Expand All @@ -192,7 +211,8 @@ private void OnChangeViewReceived(ExtensiblePayload payload, ChangeView message)
if (message.NewViewNumber <= expectedView)
return;

Log($"{nameof(OnChangeViewReceived)}: height={message.BlockIndex} view={message.ViewNumber} index={message.ValidatorIndex} nv={message.NewViewNumber} reason={message.Reason}");
DBFTPlugin.PluginLogger?.Information("OnChangeViewReceived: height={BlockIndex} view={ViewNumber} index={ValidatorIndex} nv={NewViewNumber} reason={Reason}",
message.BlockIndex, message.ViewNumber, message.ValidatorIndex, message.NewViewNumber, message.Reason);
context.ChangeViewPayloads[message.ValidatorIndex] = payload;
switch (message.Reason)
{
Expand All @@ -217,7 +237,8 @@ private void OnCommitReceived(ExtensiblePayload payload, Commit commit)
if (existingCommitPayload != null)
{
if (existingCommitPayload.Hash != payload.Hash)
Log($"Rejected {nameof(Commit)}: height={commit.BlockIndex} index={commit.ValidatorIndex} view={commit.ViewNumber} existingView={context.GetMessage(existingCommitPayload).ViewNumber}", LogLevel.Warning);
DBFTPlugin.PluginLogger?.Warning("Rejected Commit: height={BlockIndex} index={ValidatorIndex} view={ViewNumber} existingView={ExistingView}",
commit.BlockIndex, commit.ValidatorIndex, commit.ViewNumber, context.GetMessage(existingCommitPayload).ViewNumber);
return;
}

Expand All @@ -227,7 +248,8 @@ private void OnCommitReceived(ExtensiblePayload payload, Commit commit)
// around 4*15s/M=60.0s/5=12.0s ~ 80% block time (for M=5)
ExtendTimerByFactor(4);

Log($"{nameof(OnCommitReceived)}: height={commit.BlockIndex} view={commit.ViewNumber} index={commit.ValidatorIndex} nc={context.CountCommitted} nf={context.CountFailed}");
DBFTPlugin.PluginLogger?.Information("OnCommitReceived: height={BlockIndex} view={ViewNumber} index={ValidatorIndex} committed={CountCommitted} failed={CountFailed}",
commit.BlockIndex, commit.ViewNumber, commit.ValidatorIndex, context.CountCommitted, context.CountFailed);

byte[] hashData = context.EnsureHeader()?.GetSignData(neoSystem.Settings.Network);
if (hashData == null)
Expand Down Expand Up @@ -255,7 +277,8 @@ private void OnRecoveryMessageReceived(RecoveryMessage message)
int validChangeViews = 0, totalChangeViews = 0, validPrepReq = 0, totalPrepReq = 0;
int validPrepResponses = 0, totalPrepResponses = 0, validCommits = 0, totalCommits = 0;

Log($"{nameof(OnRecoveryMessageReceived)}: height={message.BlockIndex} view={message.ViewNumber} index={message.ValidatorIndex}");
DBFTPlugin.PluginLogger?.Information("OnRecoveryMessageReceived: height={BlockIndex} view={ViewNumber} index={ValidatorIndex}",
message.BlockIndex, message.ViewNumber, message.ValidatorIndex);
try
{
if (message.ViewNumber > context.ViewNumber)
Expand Down Expand Up @@ -293,7 +316,9 @@ private void OnRecoveryMessageReceived(RecoveryMessage message)
}
finally
{
Log($"Recovery finished: (valid/total) ChgView: {validChangeViews}/{totalChangeViews} PrepReq: {validPrepReq}/{totalPrepReq} PrepResp: {validPrepResponses}/{totalPrepResponses} Commits: {validCommits}/{totalCommits}");
DBFTPlugin.PluginLogger?.Information("Recovery finished: (valid/total) ChangeViews: {ValidChangeViews}/{TotalChangeViews} " +
"PrepRequests: {ValidPrepReq}/{TotalPrepReq} PrepResponses: {ValidPrepResponses}/{TotalPrepResponses} Commits: {ValidCommits}/{TotalCommits}",
validChangeViews, totalChangeViews, validPrepReq, totalPrepReq, validPrepResponses, totalPrepResponses, validCommits, totalCommits);
isRecovering = false;
}
}
Expand All @@ -308,7 +333,8 @@ private void OnRecoveryRequestReceived(ExtensiblePayload payload, ConsensusMessa
// additional recovery message response.
if (!knownHashes.Add(payload.Hash)) return;

Log($"{nameof(OnRecoveryRequestReceived)}: height={message.BlockIndex} index={message.ValidatorIndex} view={message.ViewNumber}");
DBFTPlugin.PluginLogger?.Information("OnRecoveryRequestReceived: height={BlockIndex} index={ValidatorIndex} view={ViewNumber}",
message.BlockIndex, message.ValidatorIndex, message.ViewNumber);
if (context.WatchOnly) return;
if (!context.CommitSent)
{
Expand Down
Loading
Loading