Browse Source

Reduce allocations in logger.

pull/344/head
Sebastian Stehle 7 years ago
parent
commit
d02a2b6b3c
  1. 5
      Directory.build.props
  2. 4
      src/Squidex.Domain.Apps.Entities/Backup/BackupGrain.cs
  3. 12
      src/Squidex.Domain.Apps.Entities/Backup/Helpers/Safe.cs
  4. 20
      src/Squidex.Domain.Apps.Entities/Backup/RestoreGrain.cs
  5. 4
      src/Squidex.Domain.Apps.Entities/Contents/ContentSchedulerGrain.cs
  6. 12
      src/Squidex.Infrastructure.Redis/RedisSubscription.cs
  7. 32
      src/Squidex.Infrastructure/Commands/LogCommandMiddleware.cs
  8. 36
      src/Squidex.Infrastructure/EventSourcing/Grains/EventConsumerGrain.cs
  9. 22
      src/Squidex.Infrastructure/Log/Adapter/SemanticLogLogger.cs
  10. 2
      src/Squidex.Infrastructure/Log/IArrayWriter.cs
  11. 4
      src/Squidex.Infrastructure/Log/IObjectWriter.cs
  12. 2
      src/Squidex.Infrastructure/Log/ISemanticLog.cs
  13. 35
      src/Squidex.Infrastructure/Log/JsonLogWriter.cs
  14. 8
      src/Squidex.Infrastructure/Log/ProfilerSession.cs
  15. 13
      src/Squidex.Infrastructure/Log/SemanticLog.cs
  16. 110
      src/Squidex.Infrastructure/Log/SemanticLogExtensions.cs
  17. 2
      src/Squidex/Areas/Api/Controllers/Contents/ContentsController.cs
  18. 12
      src/Squidex/Areas/IdentityServer/Controllers/Account/AccountController.cs
  19. 3
      src/Squidex/Config/Authentication/GithubHandler.cs
  20. 6
      src/Squidex/Config/Domain/LoggingExtensions.cs
  21. 20
      src/Squidex/Pipeline/ActionContextLogAppender.cs
  22. 30
      src/Squidex/Pipeline/RequestLogPerformanceMiddleware.cs
  23. 2
      tests/Squidex.Infrastructure.Tests/Commands/LogCommandMiddlewareTests.cs
  24. 26
      tests/Squidex.Infrastructure.Tests/Log/JsonLogWriterTests.cs
  25. 174
      tests/Squidex.Infrastructure.Tests/Log/SemanticLogTests.cs

5
Directory.build.props

@ -0,0 +1,5 @@
<Project>
<PropertyGroup>
<LangVersion>7.3</LangVersion>
</PropertyGroup>
</Project>

4
src/Squidex.Domain.Apps.Entities/Backup/BackupGrain.cs

@ -171,10 +171,10 @@ namespace Squidex.Domain.Apps.Entities.Backup
}
catch (Exception ex)
{
log.LogError(ex, w => w
log.LogError(ex, job.Id.ToString(), (ctx, w) => w
.WriteProperty("action", "makeBackup")
.WriteProperty("status", "failed")
.WriteProperty("backupId", job.Id.ToString()));
.WriteProperty("backupId", ctx));
job.Status = JobStatus.Failed;
}

12
src/Squidex.Domain.Apps.Entities/Backup/Helpers/Safe.cs

@ -22,10 +22,10 @@ namespace Squidex.Domain.Apps.Entities.Backup.Helpers
}
catch (Exception ex)
{
log.LogError(ex, w => w
log.LogError(ex, id.ToString(), (logOperationId, w) => w
.WriteProperty("action", "deleteArchive")
.WriteProperty("status", "failed")
.WriteProperty("operationId", id.ToString()));
.WriteProperty("operationId", logOperationId));
}
}
@ -37,10 +37,10 @@ namespace Squidex.Domain.Apps.Entities.Backup.Helpers
}
catch (Exception ex)
{
log.LogError(ex, w => w
log.LogError(ex, id.ToString(), (logOperationId, w) => w
.WriteProperty("action", "deleteBackup")
.WriteProperty("status", "failed")
.WriteProperty("operationId", id.ToString()));
.WriteProperty("operationId", logOperationId));
}
}
@ -52,10 +52,10 @@ namespace Squidex.Domain.Apps.Entities.Backup.Helpers
}
catch (Exception ex)
{
log.LogError(ex, w => w
log.LogError(ex, id.ToString(), (logOperationId, w) => w
.WriteProperty("action", "cleanupRestore")
.WriteProperty("status", "failed")
.WriteProperty("operationId", id.ToString()));
.WriteProperty("operationId", logOperationId));
}
}
}

20
src/Squidex.Domain.Apps.Entities/Backup/RestoreGrain.cs

@ -135,6 +135,8 @@ namespace Squidex.Domain.Apps.Entities.Backup
private async Task ProcessAsync()
{
var logContext = (jobId: CurrentJob.Id.ToString(), jobUrl: CurrentJob.Url.ToString());
using (Profiler.StartSession())
{
try
@ -145,11 +147,11 @@ namespace Squidex.Domain.Apps.Entities.Backup
Log(" * Restore all objects like app, schemas and contents");
Log(" * Complete the restore operation for all objects");
log.LogInformation(w => w
log.LogInformation(logContext, (ctx, w) => w
.WriteProperty("action", "restore")
.WriteProperty("status", "started")
.WriteProperty("operationId", CurrentJob.Id.ToString())
.WriteProperty("url", CurrentJob.Url.ToString()));
.WriteProperty("operationId", ctx.jobId)
.WriteProperty("url", ctx.jobUrl));
using (Profiler.Trace("Download"))
{
@ -190,12 +192,12 @@ namespace Squidex.Domain.Apps.Entities.Backup
Log("Completed, Yeah!");
log.LogInformation(w =>
log.LogInformation(logContext, (ctx, w) =>
{
w.WriteProperty("action", "restore");
w.WriteProperty("status", "completed");
w.WriteProperty("operationId", CurrentJob.Id.ToString());
w.WriteProperty("url", CurrentJob.Url.ToString());
w.WriteProperty("operationId", ctx.jobId);
w.WriteProperty("url", ctx.jobUrl);
Profiler.Session?.Write(w);
});
@ -215,12 +217,12 @@ namespace Squidex.Domain.Apps.Entities.Backup
CurrentJob.Status = JobStatus.Failed;
log.LogError(ex, w =>
log.LogError(ex, logContext, (ctx, w) =>
{
w.WriteProperty("action", "retore");
w.WriteProperty("status", "failed");
w.WriteProperty("operationId", CurrentJob.Id.ToString());
w.WriteProperty("url", CurrentJob.Url.ToString());
w.WriteProperty("operationId", ctx.jobId);
w.WriteProperty("url", ctx.jobUrl);
Profiler.Session?.Write(w);
});

4
src/Squidex.Domain.Apps.Entities/Contents/ContentSchedulerGrain.cs

@ -83,10 +83,10 @@ namespace Squidex.Domain.Apps.Entities.Contents
}
catch (Exception ex)
{
log.LogError(ex, w => w
log.LogError(ex, content.Id.ToString(), (logContentId, w) => w
.WriteProperty("action", "ChangeStatusScheduled")
.WriteProperty("status", "Failed")
.WriteProperty("contentId", content.Id.ToString()));
.WriteProperty("contentId", logContentId));
}
});
});

12
src/Squidex.Infrastructure.Redis/RedisSubscription.cs

@ -54,10 +54,10 @@ namespace Squidex.Infrastructure
}
catch (Exception ex)
{
log.LogError(ex, w => w
log.LogError(ex, channelName, (logChannel, w) => w
.WriteProperty("action", "PublishRedisMessage")
.WriteProperty("status", "Failed")
.WriteProperty("channel", channelName));
.WriteProperty("channel", logChannel));
}
}
@ -76,17 +76,17 @@ namespace Squidex.Infrastructure
{
subject.OnNext(envelope.Payload);
log.LogDebug(w => w
log.LogDebug(channelName, (logChannel, w) => w
.WriteProperty("action", "ReceiveRedisMessage")
.WriteProperty("channel", channelName)
.WriteProperty("channel", logChannel)
.WriteProperty("status", "Received"));
}
}
catch (Exception ex)
{
log.LogError(ex, w => w
log.LogError(ex, channelName, (logChannel, w) => w
.WriteProperty("action", "ReceiveRedisMessage")
.WriteProperty("channel", channelName)
.WriteProperty("channel", logChannel)
.WriteProperty("status", "Failed"));
}
}

32
src/Squidex.Infrastructure/Commands/LogCommandMiddleware.cs

@ -24,47 +24,49 @@ namespace Squidex.Infrastructure.Commands
public async Task HandleAsync(CommandContext context, Func<Task> next)
{
var logContext = (id: context.ContextId.ToString(), command: context.Command.GetType().Name);
try
{
log.LogInformation(w => w
log.LogInformation(logContext, (ctx, w) => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", context.ContextId.ToString())
.WriteProperty("actionId", ctx.id)
.WriteProperty("status", "Started")
.WriteProperty("commandType", context.Command.GetType().Name));
.WriteProperty("commandType", ctx.command));
using (log.MeasureInformation(w => w
using (log.MeasureInformation(logContext, (ctx, w) => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", context.ContextId.ToString())
.WriteProperty("actionId", ctx.id)
.WriteProperty("status", "Completed")
.WriteProperty("commandType", context.Command.GetType().Name)))
.WriteProperty("commandType", ctx.command)))
{
await next();
}
log.LogInformation(w => w
log.LogInformation(logContext, (ctx, w) => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", context.ContextId.ToString())
.WriteProperty("actionId", ctx.id)
.WriteProperty("status", "Succeeded")
.WriteProperty("commandType", context.Command.GetType().Name));
.WriteProperty("commandType", ctx.command));
}
catch (Exception ex)
{
log.LogError(ex, w => w
log.LogError(ex, logContext, (ctx, w) => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", context.ContextId.ToString())
.WriteProperty("actionId", ctx.id)
.WriteProperty("status", "Failed")
.WriteProperty("commandType", context.Command.GetType().Name));
.WriteProperty("commandType", ctx.command));
throw;
}
if (!context.IsCompleted)
{
log.LogFatal(w => w
log.LogFatal(logContext, (ctx, w) => w
.WriteProperty("action", "HandleCommand.")
.WriteProperty("actionId", context.ContextId.ToString())
.WriteProperty("actionId", ctx.id)
.WriteProperty("status", "Unhandled")
.WriteProperty("commandType", context.Command.GetType().Name));
.WriteProperty("commandType", ctx.command));
}
}
}

36
src/Squidex.Infrastructure/EventSourcing/Grains/EventConsumerGrain.cs

@ -185,19 +185,19 @@ namespace Squidex.Infrastructure.EventSourcing.Grains
private async Task ClearAsync()
{
var actionId = Guid.NewGuid().ToString();
var logContext = (actionId: Guid.NewGuid().ToString(), consumer: eventConsumer.Name);
log.LogInformation(w => w
log.LogInformation(logContext, (ctx, w) => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", actionId)
.WriteProperty("actionId", ctx.actionId)
.WriteProperty("status", "Started")
.WriteProperty("eventConsumer", eventConsumer.Name));
.WriteProperty("eventConsumer", ctx.consumer));
using (log.MeasureTrace(w => w
using (log.MeasureTrace(logContext, (ctx, w) => w
.WriteProperty("action", "EventConsumerReset")
.WriteProperty("actionId", actionId)
.WriteProperty("actionId", ctx.actionId)
.WriteProperty("status", "Completed")
.WriteProperty("eventConsumer", eventConsumer.Name)))
.WriteProperty("eventConsumer", ctx.consumer)))
{
await eventConsumer.ClearAsync();
}
@ -208,21 +208,23 @@ namespace Squidex.Infrastructure.EventSourcing.Grains
var eventId = @event.Headers.EventId().ToString();
var eventType = @event.Payload.GetType().Name;
log.LogInformation(w => w
var logContext = (eventId, eventType, consumer: eventConsumer.Name);
log.LogInformation(logContext, (ctx, w) => w
.WriteProperty("action", "HandleEvent")
.WriteProperty("actionId", eventId)
.WriteProperty("actionId", ctx.eventId)
.WriteProperty("status", "Started")
.WriteProperty("eventId", eventId)
.WriteProperty("eventType", eventType)
.WriteProperty("eventConsumer", eventConsumer.Name));
.WriteProperty("eventId", ctx.eventId)
.WriteProperty("eventType", ctx.eventType)
.WriteProperty("eventConsumer", ctx.consumer));
using (log.MeasureTrace(w => w
using (log.MeasureTrace(logContext, (ctx, w) => w
.WriteProperty("action", "HandleEvent")
.WriteProperty("actionId", eventId)
.WriteProperty("actionId", ctx.eventId)
.WriteProperty("status", "Completed")
.WriteProperty("eventId", eventId)
.WriteProperty("eventType", eventType)
.WriteProperty("eventConsumer", eventConsumer.Name)))
.WriteProperty("eventId", ctx.eventId)
.WriteProperty("eventType", ctx.eventType)
.WriteProperty("eventConsumer", ctx.consumer)))
{
await eventConsumer.On(@event);
}

22
src/Squidex.Infrastructure/Log/Adapter/SemanticLogLogger.cs

@ -49,29 +49,31 @@ namespace Squidex.Infrastructure.Log.Adapter
break;
}
semanticLog.Log(semanticLogLevel, writer =>
var context = (eventId, state, exception, formatter);
semanticLog.Log(semanticLogLevel, context, (ctx, writer) =>
{
var message = formatter(state, exception);
var message = ctx.formatter(ctx.state, ctx.exception);
if (!string.IsNullOrWhiteSpace(message))
{
writer.WriteProperty(nameof(message), message);
}
if (eventId.Id > 0)
if (ctx.eventId.Id > 0)
{
writer.WriteObject(nameof(eventId), eventIdWriter =>
writer.WriteObject("eventId", ctx.eventId, (innerEventId, eventIdWriter) =>
{
eventIdWriter.WriteProperty("id", eventId.Id);
eventIdWriter.WriteProperty("id", innerEventId.Id);
if (!string.IsNullOrWhiteSpace(eventId.Name))
if (!string.IsNullOrWhiteSpace(innerEventId.Name))
{
eventIdWriter.WriteProperty("name", eventId.Name);
eventIdWriter.WriteProperty("name", innerEventId.Name);
}
});
}
if (state is IReadOnlyList<KeyValuePair<string, object>> parameters)
if (ctx.state is IReadOnlyList<KeyValuePair<string, object>> parameters)
{
foreach (var kvp in parameters)
{
@ -87,9 +89,9 @@ namespace Squidex.Infrastructure.Log.Adapter
}
}
if (exception != null)
if (ctx.exception != null)
{
writer.WriteException(exception);
writer.WriteException(ctx.exception);
}
});
}

2
src/Squidex.Infrastructure/Log/IArrayWriter.cs

@ -25,5 +25,7 @@ namespace Squidex.Infrastructure.Log
IArrayWriter WriteValue(Instant value);
IArrayWriter WriteObject(Action<IObjectWriter> objectWriter);
IArrayWriter WriteObject<T>(T context, Action<T, IObjectWriter> objectWriter);
}
}

4
src/Squidex.Infrastructure/Log/IObjectWriter.cs

@ -26,6 +26,10 @@ namespace Squidex.Infrastructure.Log
IObjectWriter WriteObject(string property, Action<IObjectWriter> objectWriter);
IObjectWriter WriteObject<T>(string property, T context, Action<T, IObjectWriter> objectWriter);
IObjectWriter WriteArray(string property, Action<IArrayWriter> arrayWriter);
IObjectWriter WriteArray<T>(string property, T context, Action<T, IArrayWriter> arrayWriter);
}
}

2
src/Squidex.Infrastructure/Log/ISemanticLog.cs

@ -11,7 +11,7 @@ namespace Squidex.Infrastructure.Log
{
public interface ISemanticLog
{
void Log(SemanticLogLevel logLevel, Action<IObjectWriter> action);
void Log<T>(SemanticLogLevel logLevel, T context, Action<T, IObjectWriter> action);
ISemanticLog CreateScope(Action<IObjectWriter> objectWriter);
}

35
src/Squidex.Infrastructure/Log/JsonLogWriter.cs

@ -147,6 +147,18 @@ namespace Squidex.Infrastructure.Log
return this;
}
IObjectWriter IObjectWriter.WriteObject<T>(string property, T context, Action<T, IObjectWriter> objectWriter)
{
jsonWriter.WritePropertyName(Format(property));
jsonWriter.WriteStartObject();
objectWriter?.Invoke(context, this);
jsonWriter.WriteEndObject();
return this;
}
IObjectWriter IObjectWriter.WriteArray(string property, Action<IArrayWriter> arrayWriter)
{
jsonWriter.WritePropertyName(Format(property));
@ -159,6 +171,18 @@ namespace Squidex.Infrastructure.Log
return this;
}
IObjectWriter IObjectWriter.WriteArray<T>(string property, T context, Action<T, IArrayWriter> arrayWriter)
{
jsonWriter.WritePropertyName(Format(property));
jsonWriter.WriteStartArray();
arrayWriter?.Invoke(context, this);
jsonWriter.WriteEndArray();
return this;
}
IArrayWriter IArrayWriter.WriteObject(Action<IObjectWriter> objectWriter)
{
jsonWriter.WriteStartObject();
@ -170,6 +194,17 @@ namespace Squidex.Infrastructure.Log
return this;
}
IArrayWriter IArrayWriter.WriteObject<T>(T context, Action<T, IObjectWriter> objectWriter)
{
jsonWriter.WriteStartObject();
objectWriter?.Invoke(context, this);
jsonWriter.WriteEndObject();
return this;
}
private static string Format(string property)
{
if (ReferenceEquals(string.IsInterned(property), property))

8
src/Squidex.Infrastructure/Log/ProfilerSession.cs

@ -46,10 +46,10 @@ namespace Squidex.Infrastructure.Log
{
foreach (var kvp in traces)
{
p.WriteObject(kvp.Key, k => k
.WriteProperty("elapsedMsTotal", kvp.Value.Total)
.WriteProperty("elapsedMsAvg", kvp.Value.Total / kvp.Value.Count)
.WriteProperty("count", kvp.Value.Count));
p.WriteObject(kvp.Key, kvp.Value, (value, k) => k
.WriteProperty("elapsedMsTotal", value.Total)
.WriteProperty("elapsedMsAvg", value.Total / value.Count)
.WriteProperty("count", value.Count));
}
});
}

13
src/Squidex.Infrastructure/Log/SemanticLog.cs

@ -31,12 +31,17 @@ namespace Squidex.Infrastructure.Log
this.writerFactory = writerFactory;
}
public void Log(SemanticLogLevel logLevel, Action<IObjectWriter> action)
public void Log<T>(SemanticLogLevel logLevel, T context, Action<T, IObjectWriter> action)
{
Guard.NotNull(action, nameof(action));
var formattedText = FormatText(logLevel, action);
var formattedText = FormatText(logLevel, context, action);
LogFormattedText(logLevel, formattedText);
}
private void LogFormattedText(SemanticLogLevel logLevel, string formattedText)
{
List<Exception> exceptions = null;
for (var i = 0; i < channels.Length; i++)
@ -62,7 +67,7 @@ namespace Squidex.Infrastructure.Log
}
}
private string FormatText(SemanticLogLevel logLevel, Action<IObjectWriter> objectWriter)
private string FormatText<T>(SemanticLogLevel logLevel, T context, Action<T, IObjectWriter> objectWriter)
{
var writer = writerFactory.Create();
@ -70,7 +75,7 @@ namespace Squidex.Infrastructure.Log
{
writer.WriteProperty(nameof(logLevel), logLevel.ToString());
objectWriter(writer);
objectWriter(context, writer);
for (var i = 0; i < appenders.Length; i++)
{

110
src/Squidex.Infrastructure/Log/SemanticLogExtensions.cs

@ -13,47 +13,92 @@ namespace Squidex.Infrastructure.Log
{
public static void LogTrace(this ISemanticLog log, Action<IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Trace, objectWriter);
log.Log<None>(SemanticLogLevel.Trace, null, (_, w) => objectWriter(w));
}
public static void LogTrace<T>(this ISemanticLog log, T context, Action<T, IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Trace, context, objectWriter);
}
public static void LogDebug(this ISemanticLog log, Action<IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Debug, objectWriter);
log.Log<None>(SemanticLogLevel.Debug, null, (_, w) => objectWriter(w));
}
public static void LogDebug<T>(this ISemanticLog log, T context, Action<T, IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Debug, context, objectWriter);
}
public static void LogInformation(this ISemanticLog log, Action<IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Information, objectWriter);
log.Log<None>(SemanticLogLevel.Information, null, (_, w) => objectWriter(w));
}
public static void LogInformation<T>(this ISemanticLog log, T context, Action<T, IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Information, context, objectWriter);
}
public static void LogWarning(this ISemanticLog log, Action<IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Warning, objectWriter);
log.Log<None>(SemanticLogLevel.Warning, null, (_, w) => objectWriter(w));
}
public static void LogWarning<T>(this ISemanticLog log, T context, Action<T, IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Warning, context, objectWriter);
}
public static void LogWarning(this ISemanticLog log, Exception exception, Action<IObjectWriter> objectWriter = null)
{
log.Log(SemanticLogLevel.Warning, writer => writer.WriteException(exception, objectWriter));
log.Log<None>(SemanticLogLevel.Warning, null, (_, w) => w.WriteException(exception, objectWriter));
}
public static void LogWarning<T>(this ISemanticLog log, Exception exception, T context, Action<T, IObjectWriter> objectWriter = null)
{
log.Log(SemanticLogLevel.Warning, context, (ctx, w) => w.WriteException(exception, ctx, objectWriter));
}
public static void LogError(this ISemanticLog log, Action<IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Error, objectWriter);
log.Log<None>(SemanticLogLevel.Error, null, (_, w) => objectWriter(w));
}
public static void LogError<T>(this ISemanticLog log, T context, Action<T, IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Error, context, objectWriter);
}
public static void LogError(this ISemanticLog log, Exception exception, Action<IObjectWriter> objectWriter = null)
{
log.Log(SemanticLogLevel.Error, writer => writer.WriteException(exception, objectWriter));
log.Log<None>(SemanticLogLevel.Error, null, (_, w) => w.WriteException(exception, objectWriter));
}
public static void LogError<T>(this ISemanticLog log, Exception exception, T context, Action<T, IObjectWriter> objectWriter = null)
{
log.Log(SemanticLogLevel.Error, context, (ctx, w) => w.WriteException(exception, ctx, objectWriter));
}
public static void LogFatal(this ISemanticLog log, Action<IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Fatal, objectWriter);
log.Log<None>(SemanticLogLevel.Fatal, null, (_, w) => objectWriter(w));
}
public static void LogFatal<T>(this ISemanticLog log, T context, Action<T, IObjectWriter> objectWriter)
{
log.Log(SemanticLogLevel.Fatal, context, objectWriter);
}
public static void LogFatal(this ISemanticLog log, Exception exception, Action<IObjectWriter> objectWriter = null)
{
log.Log(SemanticLogLevel.Fatal, writer => writer.WriteException(exception, objectWriter));
log.Log<None>(SemanticLogLevel.Fatal, null, (_, w) => w.WriteException(exception, objectWriter));
}
public static void LogFatal<T>(this ISemanticLog log, Exception exception, T context, Action<T, IObjectWriter> objectWriter = null)
{
log.Log(SemanticLogLevel.Fatal, context, (ctx, w) => w.WriteException(exception, ctx, objectWriter));
}
private static void WriteException(this IObjectWriter writer, Exception exception, Action<IObjectWriter> objectWriter)
@ -66,32 +111,57 @@ namespace Squidex.Infrastructure.Log
}
}
private static void WriteException<T>(this IObjectWriter writer, Exception exception, T context, Action<T, IObjectWriter> objectWriter)
{
objectWriter?.Invoke(context, writer);
if (exception != null)
{
writer.WriteException(exception);
}
}
public static IObjectWriter WriteException(this IObjectWriter writer, Exception exception)
{
return writer.WriteObject(nameof(exception), inner =>
return writer.WriteObject(nameof(exception), exception, (ctx, w) =>
{
inner.WriteProperty("type", exception.GetType().FullName);
inner.WriteProperty("message", exception.Message);
inner.WriteProperty("stackTrace", exception.StackTrace);
w.WriteProperty("type", ctx.GetType().FullName);
w.WriteProperty("message", ctx.Message);
w.WriteProperty("stackTrace", ctx.StackTrace);
});
}
public static IDisposable MeasureTrace(this ISemanticLog log, Action<IObjectWriter> objectWriter)
{
return log.Measure(SemanticLogLevel.Trace, objectWriter);
return log.Measure<None>(SemanticLogLevel.Trace, null, (_, w) => objectWriter(w));
}
public static IDisposable MeasureTrace<T>(this ISemanticLog log, T context, Action<T, IObjectWriter> objectWriter)
{
return log.Measure(SemanticLogLevel.Trace, context, objectWriter);
}
public static IDisposable MeasureDebug(this ISemanticLog log, Action<IObjectWriter> objectWriter)
{
return log.Measure(SemanticLogLevel.Debug, objectWriter);
return log.Measure<None>(SemanticLogLevel.Debug, null, (_, w) => objectWriter(w));
}
public static IDisposable MeasureDebug<T>(this ISemanticLog log, T context, Action<T, IObjectWriter> objectWriter)
{
return log.Measure(SemanticLogLevel.Debug, context, objectWriter);
}
public static IDisposable MeasureInformation(this ISemanticLog log, Action<IObjectWriter> objectWriter)
{
return log.Measure(SemanticLogLevel.Information, objectWriter);
return log.Measure<None>(SemanticLogLevel.Information, null, (_, w) => objectWriter(w));
}
public static IDisposable MeasureInformation<T>(this ISemanticLog log, T context, Action<T, IObjectWriter> objectWriter)
{
return log.Measure(SemanticLogLevel.Information, context, objectWriter);
}
private static IDisposable Measure(this ISemanticLog log, SemanticLogLevel logLevel, Action<IObjectWriter> objectWriter)
private static IDisposable Measure<T>(this ISemanticLog log, SemanticLogLevel logLevel, T context, Action<T, IObjectWriter> objectWriter)
{
var watch = ValueStopwatch.StartNew();
@ -99,11 +169,11 @@ namespace Squidex.Infrastructure.Log
{
var elapsedMs = watch.Stop();
log.Log(logLevel, writer =>
log.Log(logLevel, (Context: context, elapsedMs), (ctx, w) =>
{
objectWriter?.Invoke(writer);
objectWriter?.Invoke(ctx.Context, w);
writer.WriteProperty("elapsedMs", elapsedMs);
w.WriteProperty("elapsedMs", elapsedMs);
});
});
}

2
src/Squidex/Areas/Api/Controllers/Contents/ContentsController.cs

@ -123,7 +123,7 @@ namespace Squidex.Areas.Api.Controllers.Contents
[HttpGet]
[Route("content/{app}/{name}/")]
[ApiPermission]
[ApiCosts(2)]
[ApiCosts(1)]
public async Task<IActionResult> GetContents(string app, string name, [FromQuery] bool archived = false, [FromQuery] string ids = null)
{
var context = Context().WithArchived(archived);

12
src/Squidex/Areas/IdentityServer/Controllers/Account/AccountController.cs

@ -386,18 +386,20 @@ namespace Squidex.Areas.IdentityServer.Controllers.Account
errorMessageBuilder.AppendLine(error.Description);
}
log.LogError(w => w
.WriteProperty("action", operationName)
var errorMessage = errorMessageBuilder.ToString();
log.LogError((operationName, errorMessage), (ctx, w) => w
.WriteProperty("action", ctx.operationName)
.WriteProperty("status", "Failed")
.WriteProperty("message", errorMessageBuilder.ToString()));
.WriteProperty("message", ctx.errorMessage));
}
return result.Succeeded;
}
catch (Exception ex)
{
log.LogError(ex, w => w
.WriteProperty("action", operationName)
log.LogError(ex, operationName, (logOperationName, w) => w
.WriteProperty("action", logOperationName)
.WriteProperty("status", "Failed"));
return false;

3
src/Squidex/Config/Authentication/GithubHandler.cs

@ -6,11 +6,8 @@
// ==========================================================================
using System.Security.Claims;
using System.Text.Encodings.Web;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Authentication;
using Microsoft.AspNetCore.Authentication.OAuth;
using Microsoft.Extensions.Options;
using Squidex.Infrastructure;
using Squidex.Shared.Identity;

6
src/Squidex/Config/Domain/LoggingExtensions.cs

@ -30,11 +30,11 @@ namespace Squidex.Config.Domain
var orderedConfigs = config.AsEnumerable().Where(kvp => kvp.Value != null).OrderBy(x => x.Key, StringComparer.OrdinalIgnoreCase);
foreach (var kvp in orderedConfigs)
foreach (var (key, val) in orderedConfigs)
{
if (logged.Add(kvp.Key))
if (logged.Add(key))
{
c.WriteProperty(kvp.Key.ToLowerInvariant(), kvp.Value);
c.WriteProperty(key.ToLowerInvariant(), val);
}
}
}));

20
src/Squidex/Pipeline/ActionContextLogAppender.cs

@ -34,7 +34,7 @@ namespace Squidex.Pipeline
Guid requestId;
if (httpContext.Items.TryGetValue(nameof(requestId), out var value) && value is Guid requestIdValue)
if (httpContext.Items.TryGetValue(nameof(requestId), out var requestIdvalue) && requestIdvalue is Guid requestIdValue)
{
requestId = requestIdValue;
}
@ -43,21 +43,23 @@ namespace Squidex.Pipeline
httpContext.Items[nameof(requestId)] = requestId = Guid.NewGuid();
}
writer.WriteObject("web", w =>
var logContext = (requestId, context: httpContext, actionContextAccessor);
writer.WriteObject("web", logContext, (ctx, w) =>
{
w.WriteProperty("requestId", requestId.ToString());
w.WriteProperty("requestPath", httpContext.Request.Path);
w.WriteProperty("requestMethod", httpContext.Request.Method);
w.WriteProperty("requestId", ctx.requestId.ToString());
w.WriteProperty("requestPath", ctx.context.Request.Path);
w.WriteProperty("requestMethod", ctx.context.Request.Method);
var actionContext = actionContextAccessor.ActionContext;
var actionContext = ctx.actionContextAccessor.ActionContext;
if (actionContext != null)
{
w.WriteObject("routeValues", r =>
w.WriteObject("routeValues", actionContext.ActionDescriptor.RouteValues, (routeValues, r) =>
{
foreach (var kvp in actionContext.ActionDescriptor.RouteValues)
foreach (var (key, val) in routeValues)
{
r.WriteProperty(kvp.Key, kvp.Value);
r.WriteProperty(key, val);
}
});
}

30
src/Squidex/Pipeline/RequestLogPerformanceMiddleware.cs

@ -9,6 +9,7 @@ using System.Threading.Tasks;
using Microsoft.AspNetCore.Http;
using Squidex.Infrastructure;
using Squidex.Infrastructure.Log;
using Squidex.Infrastructure.Security;
namespace Squidex.Pipeline
{
@ -35,11 +36,36 @@ namespace Squidex.Pipeline
{
var elapsedMs = watch.Stop();
log.LogInformation(w =>
log.LogInformation((elapsedMs, context), (ctx, w) =>
{
Profiler.Session?.Write(w);
w.WriteProperty("elapsedRequestMs", elapsedMs);
w.WriteObject("ctx", ctx.context, (innerHttpContext, c) =>
{
var app = innerHttpContext.Features.Get<IAppFeature>()?.App;
if (app != null)
{
c.WriteProperty("appId", app.Id.ToString());
c.WriteProperty("appName", app.Name);
}
var subjectId = innerHttpContext.User.OpenIdSubject();
if (!string.IsNullOrWhiteSpace(subjectId))
{
c.WriteProperty("userId", subjectId);
}
var clientId = innerHttpContext.User.OpenIdClientId();
if (!string.IsNullOrWhiteSpace(subjectId))
{
c.WriteProperty("clientId", subjectId);
}
});
w.WriteProperty("elapsedRequestMs", ctx.elapsedMs);
});
}
}

2
tests/Squidex.Infrastructure.Tests/Commands/LogCommandMiddlewareTests.cs

@ -28,7 +28,7 @@ namespace Squidex.Infrastructure.Commands
public Dictionary<SemanticLogLevel, int> LogLevels { get; } = new Dictionary<SemanticLogLevel, int>();
public void Log(SemanticLogLevel logLevel, Action<IObjectWriter> action)
public void Log<T>(SemanticLogLevel logLevel, T context, Action<T, IObjectWriter> action)
{
LogCount++;
LogLevels[logLevel] = LogLevels.GetOrDefault(logLevel) + 1;

26
tests/Squidex.Infrastructure.Tests/Log/JsonLogWriterTests.cs

@ -114,6 +114,22 @@ namespace Squidex.Infrastructure.Log
Assert.Equal(@"{""property1"":[{""property2"":120}]}", result);
}
[Fact]
public void Should_write_object_in_array_with_context()
{
var result = sut.WriteArray("property1", a => a.WriteObject(13, (ctx, b) => b.WriteProperty("property2", 13))).ToString();
Assert.Equal(@"{""property1"":[{""property2"":13}]}", result);
}
[Fact]
public void Should_write_array_value_with_context()
{
var result = sut.WriteArray("property", 13, (ctx, a) => a.WriteValue(ctx)).ToString();
Assert.Equal(@"{""property"":[13]}", result);
}
[Fact]
public void Should_write_date_value()
{
@ -127,11 +143,19 @@ namespace Squidex.Infrastructure.Log
[Fact]
public void Should_write_nested_object()
{
var result = sut.WriteObject("property", a => a.WriteProperty("nested", "my-string")).ToString();
var result = sut.WriteObject("property", o => o.WriteProperty("nested", "my-string")).ToString();
Assert.Equal(@"{""property"":{""nested"":""my-string""}}", result);
}
[Fact]
public void Should_write_nested_object_with_context()
{
var result = sut.WriteObject("property", 13, (ctx, o) => o.WriteProperty("nested", ctx)).ToString();
Assert.Equal(@"{""property"":{""nested"":13}}", result);
}
[Fact]
public void Should_write_pretty_json()
{

174
tests/Squidex.Infrastructure.Tests/Log/SemanticLogTests.cs

@ -45,8 +45,8 @@ namespace Squidex.Infrastructure.Log
[Fact]
public void Should_log_multiple_lines()
{
Log.Log(SemanticLogLevel.Error, w => w.WriteProperty("logMessage", "Msg1"));
Log.Log(SemanticLogLevel.Error, w => w.WriteProperty("logMessage", "Msg2"));
Log.Log<None>(SemanticLogLevel.Error, null, (_, w) => w.WriteProperty("logMessage", "Msg1"));
Log.Log<None>(SemanticLogLevel.Error, null, (_, w) => w.WriteProperty("logMessage", "Msg2"));
var expected1 =
LogTest(w => w
@ -129,6 +129,19 @@ namespace Squidex.Infrastructure.Log
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_trace_and_context()
{
Log.LogTrace(1500, (ctx, w) => w.WriteProperty("logValue", ctx));
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Trace")
.WriteProperty("logValue", 1500));
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_debug()
{
@ -142,6 +155,19 @@ namespace Squidex.Infrastructure.Log
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_debug_and_context()
{
Log.LogDebug(1500, (ctx, w) => w.WriteProperty("logValue", ctx));
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Debug")
.WriteProperty("logValue", 1500));
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_information()
{
@ -155,6 +181,19 @@ namespace Squidex.Infrastructure.Log
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_information_and_context()
{
Log.LogInformation(1500, (ctx, w) => w.WriteProperty("logValue", ctx));
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Information")
.WriteProperty("logValue", 1500));
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_warning()
{
@ -168,6 +207,19 @@ namespace Squidex.Infrastructure.Log
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_warning_and_context()
{
Log.LogWarning(1500, (ctx, w) => w.WriteProperty("logValue", ctx));
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Warning")
.WriteProperty("logValue", 1500));
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_warning_exception()
{
@ -183,6 +235,22 @@ namespace Squidex.Infrastructure.Log
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_warning_exception_and_context()
{
var exception = new InvalidOperationException();
Log.LogWarning(exception, 1500, (ctx, w) => w.WriteProperty("logValue", ctx));
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Warning")
.WriteProperty("logValue", 1500)
.WriteException(exception));
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_error()
{
@ -196,6 +264,19 @@ namespace Squidex.Infrastructure.Log
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_error_and_context()
{
Log.LogError(1500, (ctx, w) => w.WriteProperty("logValue", ctx));
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Error")
.WriteProperty("logValue", 1500));
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_error_exception()
{
@ -211,6 +292,22 @@ namespace Squidex.Infrastructure.Log
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_error_exception_and_context()
{
var exception = new InvalidOperationException();
Log.LogError(exception, 1500, (ctx, w) => w.WriteProperty("logValue", ctx));
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Error")
.WriteProperty("logValue", 1500)
.WriteException(exception));
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_fatal()
{
@ -224,6 +321,19 @@ namespace Squidex.Infrastructure.Log
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_fatal_and_context()
{
Log.LogFatal(1500, (ctx, w) => w.WriteProperty("logValue", ctx));
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Fatal")
.WriteProperty("logValue", 1500));
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_fatal_exception()
{
@ -239,6 +349,22 @@ namespace Squidex.Infrastructure.Log
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_with_fatal_exception_and_context()
{
var exception = new InvalidOperationException();
Log.LogFatal(exception, 1500, (ctx, w) => w.WriteProperty("logValue", ctx));
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Fatal")
.WriteProperty("logValue", 1500)
.WriteException(exception));
Assert.Equal(expected, output);
}
[Fact]
public void Should_log_nothing_when_exception_is_null()
{
@ -265,6 +391,20 @@ namespace Squidex.Infrastructure.Log
Assert.StartsWith(expected.Substring(0, 55), output, StringComparison.Ordinal);
}
[Fact]
public void Should_measure_trace_with_contex()
{
Log.MeasureTrace("My Message", (ctx, w) => w.WriteProperty("message", ctx)).Dispose();
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Trace")
.WriteProperty("message", "My Message")
.WriteProperty("elapsedMs", 0));
Assert.StartsWith(expected.Substring(0, 55), output, StringComparison.Ordinal);
}
[Fact]
public void Should_measure_debug()
{
@ -279,6 +419,20 @@ namespace Squidex.Infrastructure.Log
Assert.StartsWith(expected.Substring(0, 55), output, StringComparison.Ordinal);
}
[Fact]
public void Should_measure_debug_with_contex()
{
Log.MeasureDebug("My Message", (ctx, w) => w.WriteProperty("message", ctx)).Dispose();
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Debug")
.WriteProperty("message", "My Message")
.WriteProperty("elapsedMs", 0));
Assert.StartsWith(expected.Substring(0, 55), output, StringComparison.Ordinal);
}
[Fact]
public void Should_measure_information()
{
@ -293,6 +447,20 @@ namespace Squidex.Infrastructure.Log
Assert.StartsWith(expected.Substring(0, 55), output, StringComparison.Ordinal);
}
[Fact]
public void Should_measure_information_with_contex()
{
Log.MeasureInformation("My Message", (ctx, w) => w.WriteProperty("message", ctx)).Dispose();
var expected =
LogTest(w => w
.WriteProperty("logLevel", "Information")
.WriteProperty("message", "My Message")
.WriteProperty("elapsedMs", 0));
Assert.StartsWith(expected.Substring(0, 55), output, StringComparison.Ordinal);
}
[Fact]
public void Should_log_with_extensions_logger()
{
@ -334,7 +502,7 @@ namespace Squidex.Infrastructure.Log
try
{
sut.Log(SemanticLogLevel.Debug, w => w.WriteProperty("should", "throw"));
sut.Log<None>(SemanticLogLevel.Debug, null, (_, w) => w.WriteProperty("should", "throw"));
Assert.False(true);
}

Loading…
Cancel
Save