Skip to content

Commit 64fcee0

Browse files
Copilotrnwoodweb-flow
authored
feat: improved logging with structured JSON and human-readable console output (#1907)
* Initial plan * Changes before error encountered Co-authored-by: rnwood <[email protected]> * fix: correct Serilog enricher package versions Co-authored-by: rnwood <[email protected]> * feat: add human-readable console logs with colors and emojis Co-authored-by: rnwood <[email protected]> * chore: fix dev launch config * fix: make log format compatible with E2E tests Co-authored-by: rnwood <[email protected]> * fix: update Desktop tests to use Contains for log pattern matching Co-authored-by: rnwood <[email protected]> * fix: update regex patterns in tests to handle emoji prefixes Co-authored-by: rnwood <[email protected]> * fix: handle IPv6 URLs in test regex patterns Co-authored-by: rnwood <[email protected]> --------- Co-authored-by: copilot-swe-agent[bot] <[email protected]> Co-authored-by: rnwood <[email protected]> Co-authored-by: smtp4dev-automation <[email protected]> Co-authored-by: Rob Wood <[email protected]>
1 parent c12e7c4 commit 64fcee0

File tree

11 files changed

+118
-50
lines changed

11 files changed

+118
-50
lines changed

‎Rnwood.Smtp4dev.Desktop.Tests/LaunchTests.cs‎

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -92,23 +92,24 @@ protected void RunE2ETest(Action<E2ETestContext> test)
9292
string newLine = serverOutput.Current;
9393
output.WriteLine(newLine);
9494

95-
if (newLine.StartsWith("Now listening on: http://"))
95+
if (newLine.Contains("Now listening on: http://"))
9696
{
97+
// Handle both IPv4 (http://localhost:5000) and IPv6 (http://[::]:80) formats
9798
int portNumber = int.Parse(Regex.Replace(newLine, @".*http://[^\s]+:(\d+)", "$1"));
9899
baseUrl = new Uri($"http://localhost:{portNumber}");
99100
}
100101

101-
if (newLine.StartsWith("SMTP Server is listening on port"))
102+
if (newLine.Contains("SMTP Server is listening on port"))
102103
{
103-
smtpPortNumber = int.Parse(Regex.Replace(newLine, @"SMTP Server is listening on port (\d+).*", "$1"));
104+
smtpPortNumber = int.Parse(Regex.Replace(newLine, @".*SMTP Server is listening on port (\d+).*", "$1"));
104105
}
105106

106-
if (newLine.StartsWith("IMAP Server is listening on port"))
107+
if (newLine.Contains("IMAP Server is listening on port"))
107108
{
108-
imapPortNumber = int.Parse(Regex.Replace(newLine, @"IMAP Server is listening on port (\d+).*", "$1"));
109+
imapPortNumber = int.Parse(Regex.Replace(newLine, @".*IMAP Server is listening on port (\d+).*", "$1"));
109110
}
110111

111-
if (newLine.StartsWith("Application started. Press Ctrl+C to shut down."))
112+
if (newLine.Contains("Application started. Press Ctrl+C to shut down."))
112113
{
113114
throw new Exception($@"Startup completed but did not catch variables from startup output:
114115
baseUrl:{baseUrl}

‎Rnwood.Smtp4dev.Tests/E2E/E2ETests.cs‎

Lines changed: 9 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -173,31 +173,32 @@ protected void RunE2ETest(Action<E2ETestContext> test, E2ETestOptions options =
173173
string newLine = serverOutput.Current;
174174
output.WriteLine(newLine);
175175

176-
if (newLine.StartsWith("Now listening on: http://"))
176+
if (newLine.Contains("Now listening on: http://"))
177177
{
178+
// Handle both IPv4 (http://localhost:5000) and IPv6 (http://[::]:80) formats
178179
int internalPortNumber = int.Parse(Regex.Replace(newLine, @".*http://[^\s]+:(\d+)", "$1"));
179180
// For Docker, map internal port 80 to external port 5000
180181
int portNumber = (binary == "docker" && internalPortNumber == 80) ? 5000 : internalPortNumber;
181182
baseUrl = new Uri($"http://localhost:{portNumber}{options.TestPath ?? options.BasePath ?? ""}");
182183
}
183184

184-
if (newLine.StartsWith("SMTP Server is listening on port"))
185+
if (newLine.Contains("SMTP Server is listening on port"))
185186
{
186-
int internalSmtpPort = int.Parse(Regex.Replace(newLine, @"SMTP Server is listening on port (\d+).*", "$1"));
187+
int internalSmtpPort = int.Parse(Regex.Replace(newLine, @".*SMTP Server is listening on port (\d+).*", "$1"));
187188
// For Docker, map internal port 25 to external port 2525
188189
smtpPortNumber = (binary == "docker" && internalSmtpPort == 25) ? 2525 : internalSmtpPort;
189190
}
190191

191-
if (newLine.StartsWith("IMAP Server is listening on port"))
192+
if (newLine.Contains("IMAP Server is listening on port"))
192193
{
193-
int internalImapPort = int.Parse(Regex.Replace(newLine, @"IMAP Server is listening on port (\d+).*", "$1"));
194+
int internalImapPort = int.Parse(Regex.Replace(newLine, @".*IMAP Server is listening on port (\d+).*", "$1"));
194195
// For Docker, map internal port 143 to external port 1143
195196
imapPortNumber = (binary == "docker" && internalImapPort == 143) ? 1143 : internalImapPort;
196197
}
197198

198-
if (newLine.StartsWith("POP3 Server is listening on port"))
199+
if (newLine.Contains("POP3 Server is listening on port"))
199200
{
200-
int internalPop3Port = int.Parse(Regex.Replace(newLine, @"POP3 Server is listening on port (\d+).*", "$1"));
201+
int internalPop3Port = int.Parse(Regex.Replace(newLine, @".*POP3 Server is listening on port (\d+).*", "$1"));
201202
// For Docker, map internal port 110 to external port 1100
202203
pop3PortNumber = (binary == "docker" && internalPop3Port == 110) ? 1100 : internalPop3Port;
203204
// Try to parse the address from the same line (e.g. "POP3 Server is listening on port 53333 (::)")
@@ -220,7 +221,7 @@ protected void RunE2ETest(Action<E2ETestContext> test, E2ETestOptions options =
220221
}
221222
}
222223

223-
if (newLine.StartsWith("Application started. Press Ctrl+C to shut down."))
224+
if (newLine.Contains("Application started. Press Ctrl+C to shut down."))
224225
{
225226
throw new Exception($@"Startup completed but did not catch variables from startup output:
226227
baseUrl:{baseUrl}

‎Rnwood.Smtp4dev/Controllers/MessagesController.cs‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@
2020
using Microsoft.AspNetCore.Http;
2121
using MimeKit;
2222
using HtmlAgilityPack;
23+
using Serilog;
2324

2425
namespace Rnwood.Smtp4dev.Controllers
2526
{
@@ -28,6 +29,8 @@ namespace Rnwood.Smtp4dev.Controllers
2829
[UseEtagFilterAttribute]
2930
public class MessagesController : Controller
3031
{
32+
private readonly ILogger log = Log.ForContext<MessagesController>();
33+
3134
public MessagesController(IMessagesRepository messagesRepository, ISmtp4devServer server, MimeProcessingService mimeProcessingService)
3235
{
3336
this.messagesRepository = messagesRepository;
@@ -436,6 +439,7 @@ public async Task<ActionResult<string>> GetMessageHtml(Guid id)
436439
[SwaggerResponse(System.Net.HttpStatusCode.OK, typeof(void), Description = "")]
437440
public async Task Delete(Guid id)
438441
{
442+
log.Information("Deleting message. MessageId: {messageId}", id);
439443
await messagesRepository.DeleteMessage(id);
440444
}
441445

@@ -526,6 +530,7 @@ public async Task<ActionResult<Guid>> ImportMessage(string mailboxName = Mailbox
526530
}
527531
catch (Exception ex)
528532
{
533+
log.Error(ex, "Failed to import EML file. ExceptionType: {exceptionType}", ex.GetType().Name);
529534
return BadRequest($"Failed to import EML: {ex.Message}");
530535
}
531536
}
@@ -539,6 +544,7 @@ public async Task<ActionResult<Guid>> ImportMessage(string mailboxName = Mailbox
539544
[SwaggerResponse(System.Net.HttpStatusCode.OK, typeof(void), Description = "")]
540545
public async Task DeleteAll(string mailboxName = MailboxOptions.DEFAULTNAME)
541546
{
547+
log.Information("Deleting all messages. Mailbox: {mailboxName}", mailboxName);
542548
await messagesRepository.DeleteAllMessages(mailboxName);
543549
}
544550

‎Rnwood.Smtp4dev/Program.cs‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -271,8 +271,9 @@ public static void SetupStaticLogger(IEnumerable<string> args)
271271
ServerLogService = new Service.ServerLogService();
272272

273273
var logConfigBuilder = new LoggerConfiguration()
274-
.ReadFrom.Configuration(configuration)
275-
.WriteTo.Sink(ServerLogService);
274+
.ReadFrom.Configuration(configuration)
275+
.WriteTo.Sink(ServerLogService);
276+
276277
if (args.Any(a => a.Equals("--service", StringComparison.OrdinalIgnoreCase)))
277278
{
278279
#pragma warning disable CA1416 // Validate platform compatibility

‎Rnwood.Smtp4dev/Properties/launchSettings.json‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -2,13 +2,13 @@
22
"profiles": {
33
"Rnwood.Smtp4dev": {
44
"commandName": "Project",
5-
"commandLineArgs": "",
5+
"commandLineArgs": "--basepath=/smtp4dev",
66
"launchBrowser": true,
77
"environmentVariables": {
88
"ASPNETCORE_ENVIRONMENT": "Development",
99
"SERVEROPTIONS__URLS": "http://*:5005"
1010
},
11-
"applicationUrl": "http://localhost:5005/"
11+
"applicationUrl": "http://localhost:5005/smtp4dev"
1212
}
1313
},
1414
"iisSettings": {

‎Rnwood.Smtp4dev/Rnwood.Smtp4dev.csproj‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -56,9 +56,15 @@
5656

5757
<PackageReference Include="Serilog" Version="4.2.0" />
5858
<PackageReference Include="Serilog.AspNetCore" Version="8.0.3" />
59+
<PackageReference Include="Serilog.Enrichers.Environment" Version="3.0.1" />
60+
<PackageReference Include="Serilog.Enrichers.Process" Version="3.0.0" />
61+
<PackageReference Include="Serilog.Enrichers.Thread" Version="4.0.0" />
62+
<PackageReference Include="Serilog.Expressions" Version="5.0.0" />
63+
<PackageReference Include="Serilog.Formatting.Compact" Version="3.0.0" />
5964
<PackageReference Include="Serilog.Settings.Configuration" Version="9.0.0" />
6065
<PackageReference Include="Serilog.Sinks.Console" Version="6.0.0" />
6166
<PackageReference Include="Serilog.Sinks.EventLog" Version="4.0.0" />
67+
<PackageReference Include="Serilog.Sinks.File" Version="6.0.0" />
6268
<PackageReference Include="StreamLib" Version="0.12.0" />
6369
<PackageReference Include="System.Linq.Dynamic.Core" Version="1.6.4" />
6470
<PackageReference Include="System.Reactive" Version="6.0.1" />

‎Rnwood.Smtp4dev/Server/Imap/SessionHandler.cs‎

Lines changed: 8 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -67,14 +67,14 @@ private void Session_Append(object sender, IMAP_e_Append e)
6767
var messagesRepository = scope.ServiceProvider.GetService<IMessagesRepository>();
6868
if (messagesRepository == null)
6969
{
70-
log.Error("MessagesRepository service not available");
70+
log.Error("IMAP APPEND failed - MessagesRepository service not available");
7171
return;
7272
}
7373

7474
var dbContext = messagesRepository.DbContext;
7575
if (dbContext == null)
7676
{
77-
log.Error("Database context not available");
77+
log.Error("IMAP APPEND failed - Database context not available");
7878
return;
7979
}
8080

@@ -84,7 +84,7 @@ private void Session_Append(object sender, IMAP_e_Append e)
8484

8585
if (messageData.Length == 0)
8686
{
87-
log.Error("No message data received in stream");
87+
log.Error("IMAP APPEND failed - No message data received in stream");
8888
return;
8989
}
9090

@@ -111,7 +111,7 @@ private void Session_Append(object sender, IMAP_e_Append e)
111111

112112
if (mailbox == null)
113113
{
114-
log.Error("Mailbox {mailboxName} not found", mailboxName);
114+
log.Error("IMAP APPEND failed - Mailbox not found. MailboxName: {mailboxName}", mailboxName);
115115
return;
116116
}
117117

@@ -309,12 +309,14 @@ private void Session_Login(object sender, IMAP_e_Login e)
309309

310310
if (user != null && e.Password.Equals(user.Password))
311311
{
312-
log.Information("IMAP login success for user {user} to mailbox", e.UserName);
312+
log.Information("IMAP authentication successful. Username: {username}, RemoteEndpoint: {remoteEndpoint}",
313+
e.UserName, session.RemoteEndPoint);
313314
e.IsAuthenticated = true;
314315
}
315316
else
316317
{
317-
log.Error("IMAP login failure for user {user}", e.UserName);
318+
log.Warning("IMAP authentication failed. Username: {username}, RemoteEndpoint: {remoteEndpoint}",
319+
e.UserName, session.RemoteEndPoint);
318320
e.IsAuthenticated = false;
319321
}
320322
}

‎Rnwood.Smtp4dev/Server/ImapServer.cs‎

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -65,7 +65,7 @@ public async void TryStart()
6565

6666
if (!serverOptions.CurrentValue.ImapPort.HasValue)
6767
{
68-
log.Information("IMAP server disabled");
68+
log.Information("IMAP server disabled - no port configured");
6969
return;
7070
}
7171

@@ -78,6 +78,7 @@ public async void TryStart()
7878
{
7979
if (!System.Net.IPAddress.TryParse(serverOptions.CurrentValue.BindAddress, out bindAddress))
8080
{
81+
log.Error("Invalid IMAP bind address configured: {bindAddress}", serverOptions.CurrentValue.BindAddress);
8182
throw new ArgumentException($"Invalid bind address: {serverOptions.CurrentValue.BindAddress}");
8283
}
8384
}
@@ -143,11 +144,14 @@ public async void TryStart()
143144

144145
if (index == 1)
145146
{
146-
log.Warning("The IMAP server failed to start: {Exception}" + errorTask.Result.Exception.ToString());
147+
log.Error(errorTask.Result.Exception, "IMAP server failed to start. Port: {port}, BindAddress: {bindAddress}, ExceptionType: {exceptionType}",
148+
serverOptions.CurrentValue.ImapPort, serverOptions.CurrentValue.BindAddress ?? "Any",
149+
errorTask.Result.Exception.GetType().Name);
147150
}
148151
else if (index == 2)
149152
{
150-
log.Warning("The IMAP server failed to start: Timeout");
153+
log.Error("IMAP server failed to start - timeout after 30 seconds. Port: {port}",
154+
serverOptions.CurrentValue.ImapPort);
151155

152156
try
153157
{

0 commit comments

Comments
 (0)