Skip to content

Commit 73081ba

Browse files
AeliuxAeliux
committed
Add more logs
1 parent c507d65 commit 73081ba

File tree

4 files changed

+104
-28
lines changed

4 files changed

+104
-28
lines changed

‎src/EasySign.Cli/BundleCommandProvider.cs‎

Lines changed: 6 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -13,17 +13,18 @@ namespace SAPTeam.EasySign.Cli
1313
{
1414
internal class BundleCommandProvider : CommandProvider<Bundle>
1515
{
16-
ILogger _logger;
16+
ILogger _bundleLogger;
1717

18-
public BundleCommandProvider(ILogger logger)
18+
public BundleCommandProvider(ILogger logger, ILogger bundleLogger)
1919
{
20-
_logger = logger;
20+
Logger = logger;
21+
_bundleLogger = bundleLogger;
2122
}
2223

2324
public override void InitializeBundle(string bundlePath)
2425
{
25-
Program.Logger.Information("Initializing bundle at {bundlePath}", bundlePath);
26-
Bundle = new Bundle(bundlePath, _logger);
26+
Logger.LogInformation("Initializing bundle at {bundlePath}", bundlePath);
27+
Bundle = new Bundle(bundlePath, _bundleLogger);
2728
}
2829

2930
public override RootCommand GetRootCommand()

‎src/EasySign.Cli/Program.cs‎

Lines changed: 8 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
using Microsoft.Extensions.Logging;
1010

1111
using Serilog;
12+
using Serilog.Extensions.Logging;
1213

1314
using Spectre.Console;
1415

@@ -30,22 +31,16 @@ static int Main(string[] args)
3031
.MinimumLevel.Debug() // Minimum log level
3132
.CreateLogger();
3233

33-
var serviceCollection = new ServiceCollection();
34-
serviceCollection.AddLogging(configure =>
35-
{
36-
configure.ClearProviders(); // Clear default providers
37-
configure.AddSerilog(Log.Logger.ForContext("Context", "Bundle"));
38-
});
39-
40-
var serviceProvider = serviceCollection.BuildServiceProvider();
41-
42-
// Resolve an ILogger instance
43-
var bundleLogger = serviceProvider.GetRequiredService<ILogger<Bundle>>();
44-
4534
Logger = Log.Logger.ForContext("Context", "Main");
4635
Logger.Information("Starting EasySign CLI at {DateTime}", DateTime.Now);
4736

48-
var root = new BundleCommandProvider(bundleLogger).GetRootCommand();
37+
var bundleLogger = new SerilogLoggerFactory(Log.Logger.ForContext("Context", "Bundle"))
38+
.CreateLogger("CommandProvider");
39+
40+
var commandProviderLogger = new SerilogLoggerFactory(Log.Logger.ForContext("Context", "CommandProvider"))
41+
.CreateLogger("CommandProvider");
42+
43+
var root = new BundleCommandProvider(commandProviderLogger, bundleLogger).GetRootCommand();
4944
var exitCode = root.Invoke(args);
5045

5146
Logger.Information("Shutting down EasySign CLI at {DateTime} with exit code {ExitCode}", DateTime.Now, exitCode);

‎src/EasySign.CommandLine/BundleWorker.cs‎

Lines changed: 82 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,8 @@
33
using System.Security.Cryptography.X509Certificates;
44
using System.Text;
55

6+
using Microsoft.Extensions.Logging;
7+
68
using Spectre.Console;
79

810
namespace SAPTeam.EasySign.CommandLine
@@ -35,41 +37,55 @@ public abstract partial class CommandProvider<T>
3537
/// </param>
3638
protected virtual void RunAdd(StatusContext statusContext, bool replace, bool continueOnError)
3739
{
40+
Logger.LogInformation("Running add command");
41+
3842
if (Bundle == null)
3943
{
4044
throw new ApplicationException("Bundle is not initialized");
4145
}
4246

4347
if (!Bundle.IsLoaded && File.Exists(Bundle.BundlePath))
4448
{
49+
Logger.LogDebug("A bundle file exists, loading bundle");
4550
statusContext.Status("[yellow]Loading Bundle[/]");
4651
Bundle.LoadFromFile(false);
4752
}
4853

4954
statusContext.Status("[yellow]Adding Files[/]");
5055

56+
Logger.LogDebug("Discovering files in the directory: {RootPath}", Bundle.RootPath);
57+
var foundFiles = Utilities.SafeEnumerateFiles(Bundle.RootPath, "*");
58+
Logger.LogInformation("Discovered {FileCount} files", foundFiles.Count());
59+
60+
Logger.LogInformation("Starting file adder multi-thread task");
5161
bool errorOccurred = false;
52-
_ = Parallel.ForEach(Utilities.SafeEnumerateFiles(Bundle.RootPath, "*"), (file, state) =>
62+
_ = Parallel.ForEach(foundFiles, (file, state) =>
5363
{
5464
if (file == Bundle.BundlePath) return;
5565
var entryName = Manifest.GetNormalizedEntryName(Path.GetRelativePath(Bundle.RootPath, file));
5666

67+
Logger.LogInformation("Processing file: {EntryName}", entryName);
68+
5769
try
5870
{
5971
if (Bundle.Manifest.Entries.ContainsKey(entryName))
6072
{
6173
if (!replace)
6274
{
75+
Logger.LogWarning("Entry already exists: {EntryName}", entryName);
6376
AnsiConsole.MarkupLine($"[{Color.Orange1}]Exists:[/] {entryName}");
6477
return;
6578
}
6679

80+
Logger.LogInformation("Replacing entry: {EntryName}", entryName);
81+
6782
Bundle.DeleteEntry(entryName);
6883
Bundle.AddEntry(file);
6984
AnsiConsole.MarkupLine($"[{Color.Cyan2}]Replaced:[/] {entryName}");
7085
}
7186
else
7287
{
88+
Logger.LogInformation("Adding entry: {EntryName}", entryName);
7389
Bundle.AddEntry(file);
7490
AnsiConsole.MarkupLine($"[blue]Added:[/] {entryName}");
7591
}
@@ -78,10 +94,12 @@ protected virtual void RunAdd(StatusContext statusContext, bool replace, bool co
7894
{
7995
errorOccurred = true;
8096

97+
Logger.LogError(ex, "Error occurred while adding entry: {EntryName}", entryName);
8198
AnsiConsole.MarkupLine($"[{Color.Red}]Error:[/] {entryName} ({ex.GetType().Name}: {ex.Message})");
8299

83100
if (!continueOnError)
84101
{
102+
Logger.LogWarning("Stopping add operation due to error");
85103
state.Stop();
86104
}
87105
}
@@ -94,11 +112,13 @@ protected virtual void RunAdd(StatusContext statusContext, bool replace, bool co
94112

95113
if (!continueOnError)
96114
{
115+
Logger.LogWarning("Add operation aborted");
97116
AnsiConsole.MarkupLine("[red]No changes were made to the bundle[/]");
98117
return;
99118
}
100119
}
101120

121+
Logger.LogInformation("Saving bundle");
102122
statusContext.Status("[yellow]Saving Bundle[/]");
103123
Bundle.Update();
104124
}
@@ -110,11 +130,14 @@ protected virtual void RunAdd(StatusContext statusContext, bool replace, bool co
110130
/// <param name="certificates">The certificates.</param>
111131
protected virtual void RunSign(StatusContext statusContext, X509Certificate2Collection certificates)
112132
{
133+
Logger.LogInformation("Running sign command");
134+
113135
if (Bundle == null)
114136
{
115137
throw new ApplicationException("Bundle is not initialized");
116138
}
117139

140+
Logger.LogDebug("Loading bundle");
118141
statusContext.Status("[yellow]Loading Bundle[/]");
119142
Bundle.LoadFromFile(false);
120143

@@ -123,6 +146,7 @@ protected virtual void RunSign(StatusContext statusContext, X509Certificate2Coll
123146
{
124147
if (divider++ > 0) AnsiConsole.WriteLine();
125148

149+
Logger.LogDebug("Loading certificate information for {Cert}", cert);
126150
statusContext.Status("[yellow]Loading certificate informations[/]");
127151

128152
var grid = new Grid();
@@ -139,26 +163,35 @@ protected virtual void RunSign(StatusContext statusContext, X509Certificate2Coll
139163
AnsiConsole.Write(grid);
140164
AnsiConsole.WriteLine();
141165

166+
Logger.LogDebug("Verifying certificate {cert}", cert);
142167
statusContext.Status("[yellow]Verifying Certificate[/]");
143168

144169
bool verifyCert = VerifyCertificate(cert);
145-
if (!verifyCert) continue;
170+
if (!verifyCert)
171+
{
172+
Logger.LogWarning("Skipping signing with {cert}", cert);
173+
continue;
174+
}
146175

176+
Logger.LogDebug("Acquiring RSA private key for {cert}", cert);
147177
statusContext.Status("[yellow]Preparing for signing[/]");
148178

149179
var prvKey = cert.GetRSAPrivateKey();
150180
if (prvKey == null)
151181
{
182+
Logger.LogError("Failed to acquire RSA private key for {cert}", cert);
152183
AnsiConsole.MarkupLine($"[{Color.Green}] Failed to Acquire RSA Private Key[/]");
153184
continue;
154185
}
155186

187+
Logger.LogInformation("Signing bundle with {cert}", cert);
156188
statusContext.Status("[yellow]Signing Bundle[/]");
157189

158190
Bundle.Sign(cert, prvKey);
159191
AnsiConsole.MarkupLine($"[green] Signing Completed Successfully[/]");
160192
}
161193

194+
Logger.LogInformation("Saving bundle");
162195
statusContext.Status("[yellow]Updating Bundle[/]");
163196
Bundle.Update();
164197
}
@@ -169,6 +202,8 @@ protected virtual void RunSign(StatusContext statusContext, X509Certificate2Coll
169202
/// <param name="statusContext">The status context for interacting with <see cref="AnsiConsole.Status"/>.</param>
170203
protected virtual void RunVerify(StatusContext statusContext)
171204
{
205+
Logger.LogInformation("Running verify command");
206+
172207
if (Bundle == null)
173208
{
174209
throw new ApplicationException("Bundle is not initialized");
@@ -182,28 +217,42 @@ protected virtual void RunVerify(StatusContext statusContext)
182217
["file_error"] = Color.Red3_1,
183218
};
184219

220+
Logger.LogDebug("Loading bundle");
185221
statusContext.Status("[yellow]Loading Bundle[/]");
186222
Bundle.LoadFromFile();
187223

224+
Logger.LogInformation("Starting certificate and signature verification");
188225
statusContext.Status("[yellow]Verification Phase 1: Certificates and signatures[/]");
189226

190227
int verifiedCerts = 0;
191228
int divider = 0;
192229

193-
foreach (var cert in Bundle.Signatures.Entries.Keys)
230+
foreach (var certificateHash in Bundle.Signatures.Entries.Keys)
194231
{
195232
if (divider++ > 0) AnsiConsole.WriteLine();
196233

197-
var certificate = Bundle.GetCertificate(cert);
234+
var certificate = Bundle.GetCertificate(certificateHash);
235+
236+
Logger.LogDebug("Verifying certificate {cert}", certificate);
198237
AnsiConsole.MarkupLine($"Verifying Certificate [{Color.Teal}]{certificate.GetNameInfo(X509NameType.SimpleName, false)}[/] Issued by [{Color.Aqua}]{certificate.GetNameInfo(X509NameType.SimpleName, true)}[/]");
199238

200239
var verifyCert = VerifyCertificate(certificate);
201-
if (!verifyCert) continue;
240+
if (!verifyCert)
241+
{
242+
Logger.LogWarning("Skipping signature verification for {cert}", certificate);
243+
continue;
244+
}
202245

203-
var verifySign = Bundle.VerifySignature(cert);
246+
Logger.LogDebug("Verifying signature for certificate {cert}", certificate);
247+
var verifySign = Bundle.VerifySignature(certificateHash);
204248
AnsiConsole.MarkupLine($"[{(verifySign ? Color.Green : Color.Red)}] Signature Verification {(verifySign ? "Successful" : "Failed")}[/]");
205-
if (!verifySign) continue;
249+
if (!verifySign)
250+
{
251+
Logger.LogWarning("Signature verification failed for {cert}", certificate);
252+
continue;
253+
}
206254

255+
Logger.LogInformation("Certificate and signature verification successful for {cert}", certificate);
207256
verifiedCerts++;
208257
}
209258

@@ -212,21 +261,30 @@ protected virtual void RunVerify(StatusContext statusContext)
212261
if (verifiedCerts == 0)
213262
{
214263
if (Bundle.Signatures.Entries.Count == 0)
264+
{
265+
Logger.LogWarning("Bundle is not signed");
215266
AnsiConsole.MarkupLine($"[red]This bundle is not signed[/]");
267+
}
216268

269+
Logger.LogWarning("No certificates were verified");
217270
AnsiConsole.MarkupLine($"[red]Verification failed[/]");
218271
return;
219272
}
220273

221274
if (verifiedCerts == Bundle.Signatures.Entries.Count)
275+
{
276+
Logger.LogInformation("All certificates were verified");
222277
AnsiConsole.MarkupLine($"[{Color.Green3}]All Certificates were verified[/]");
278+
}
223279
else
224280
{
281+
Logger.LogWarning("{verifiedCerts} out of {totalCerts} certificates were verified", verifiedCerts, Bundle.Signatures.Entries.Count);
225282
AnsiConsole.MarkupLine($"[{Color.Yellow}]{verifiedCerts} out of {Bundle.Signatures.Entries.Count} Certificates were verified[/]");
226283
}
227284

228285
AnsiConsole.WriteLine();
229286

287+
Logger.LogInformation("Starting file verification for {fileCount} files in multi-thread mode", Bundle.Manifest.Entries.Count);
230288
statusContext.Status("[yellow]Verification Phase 2: Files[/]");
231289

232290
bool p2Verified = true;
@@ -236,36 +294,43 @@ protected virtual void RunVerify(StatusContext statusContext)
236294
int fm = 0;
237295
int fe = 0;
238296

239-
Parallel.ForEach(Bundle.Manifest.Entries, (entry) =>
297+
_ = Parallel.ForEach(Bundle.Manifest.Entries, (entry) =>
240298
{
241299
var verifyFile = false;
242300

301+
Logger.LogDebug("Verifying file {file}", entry.Key);
302+
243303
try
244304
{
245305
verifyFile = Bundle.VerifyFileIntegrity(entry.Key);
246306

247307
if (verifyFile)
308+
{
309+
Logger.LogInformation("File {file} verified", entry.Key);
248310
Interlocked.Increment(ref fv);
311+
}
249312
else
250313
{
314+
Logger.LogWarning("File {file} failed verification", entry.Key);
251315
Interlocked.Increment(ref ff);
252316
}
253317

254318
AnsiConsole.MarkupLine($"[{(verifyFile ? colorDict["file_verified"] : colorDict["file_failed"])}]{entry.Key}[/]");
255319
}
256320
catch (FileNotFoundException)
257321
{
322+
Logger.LogWarning("File {file} not found", entry.Key);
258323
Interlocked.Increment(ref fm);
259324
AnsiConsole.MarkupLine($"[{colorDict["file_missing"]}]{entry.Key}[/]");
260325
}
261326
catch (Exception ex)
262327
{
328+
Logger.LogError(ex, "Error occurred while verifying file {file}", entry.Key);
263329
Interlocked.Increment(ref fe);
264330
AnsiConsole.MarkupLine($"[{colorDict["file_error"]}]{entry.Key} - {ex.GetType().Name}: {ex.Message}[/]");
265331
}
266332

267-
if (!verifyFile)
268-
p2Verified = false;
333+
if (!verifyFile) p2Verified = false;
269334
});
270335

271336
AnsiConsole.WriteLine();
@@ -283,10 +348,12 @@ protected virtual void RunVerify(StatusContext statusContext)
283348

284349
if (!p2Verified)
285350
{
351+
Logger.LogWarning("File verification failed");
286352
AnsiConsole.MarkupLine($"[red]File Verification Failed[/]");
287353
return;
288354
}
289355

356+
Logger.LogInformation("Bundle verification completed successfully");
290357
AnsiConsole.MarkupLine("[green]Bundle Verification Completed Successfully[/]");
291358
}
292359

@@ -304,9 +371,11 @@ protected bool VerifyCertificate(X509Certificate2 certificate)
304371

305372
List<bool> verifyResults = new();
306373

374+
Logger.LogDebug("Verifying certificate {cert} with default verification policy", certificate);
307375
var defaultVerification = Bundle.VerifyCertificate(certificate, out X509ChainStatus[] statuses);
308376
verifyResults.Add(defaultVerification);
309377

378+
Logger.LogInformation("Certificate verification with default policy for {cert}: {result}", certificate, defaultVerification);
310379
AnsiConsole.MarkupLine($"[{(defaultVerification ? Color.Green : Color.Red)}] Certificate Verification {(defaultVerification ? "Successful" : "Failed")}[/]");
311380

312381
if (!defaultVerification)
@@ -317,12 +386,15 @@ protected bool VerifyCertificate(X509Certificate2 certificate)
317386

318387
if (timeIssue)
319388
{
389+
Logger.LogWarning("Certificate has time validity issues, retrying verification with time check disabled");
390+
320391
var policy = new X509ChainPolicy();
321392
policy.VerificationFlags |= X509VerificationFlags.IgnoreNotTimeValid;
322393

323394
var noTimeVerification = Bundle.VerifyCertificate(certificate, out X509ChainStatus[] noTimeStatuses, policy: policy);
324395
verifyResults.Add(noTimeVerification);
325396

397+
Logger.LogInformation("Certificate verification without time checking for {cert}: {result}", certificate, noTimeVerification);
326398
AnsiConsole.MarkupLine($"[{(noTimeVerification ? Color.Green : Color.Red)}] Certificate Verification without time checking {(noTimeVerification ? "Successful" : "Failed")}[/]");
327399
Utilities.EnumerateStatuses(noTimeStatuses);
328400
}

0 commit comments

Comments
 (0)