[Abp vNext source code analysis] - 8. Audit log

1, Brief description

The audit module in ABP vNext was mentioned in dependency injection and interceptor earlier, but it was not analyzed in detail.

The audit module is a basic component of ABP vNext framework. It can provide some practical logging. However, the log here does not mean the system log, but the execution status (execution time, incoming parameters, exception information, request IP) after each call of the interface.

In addition to the regular log functions, the audit field interfaces for entities and aggregates are also stored in the audit module. (creator, creation time, modifier, modification time, deleted by, deleted time)

2, Source code analysis

2.1. Audit log interceptor

2.1.1 registration of audit log interceptor

The module definition of Volo.Abp.Auditing is very simple. It mainly provides the registration function of audit log interceptor. The following code will call AuditingInterceptorRegistrar.RegisterIfNeeded method to determine whether to inject audit log interceptor for implementation type during component registration.

public class AbpAuditingModule : AbpModule
{
    public override void PreConfigureServices(ServiceConfigurationContext context)
    {
        context.Services.OnRegistred(AuditingInterceptorRegistrar.RegisterIfNeeded);
    }
}

Jump to the specific implementation, and you can see that the internal judgment will be combined with three types. They are AuditedAttribute, IAuditingEnabled and DisableAuditingAttribute.

The first two functions are that as long as the type is marked with the AuditedAttribute attribute or implements the IAuditingEnable interface, the audit log interceptor will be injected into the type.

On the contrary, the DisableAuditingAttribute type will not enable the audit log interceptor as long as the attribute is marked on the type. If the performance of some interfaces needs to be improved, you can try to use this feature to disable the audit log function.

public static class AuditingInterceptorRegistrar
{
    public static void RegisterIfNeeded(IOnServiceRegistredContext context)
    {
        // When the conditions are met, an audit log interceptor will be injected for this type.
        if (ShouldIntercept(context.ImplementationType))
        {
            context.Interceptors.TryAdd<AuditingInterceptor>();
        }
    }

    private static bool ShouldIntercept(Type type)
    {
        // First, judge whether auxiliary types are used above types.
        if (ShouldAuditTypeByDefault(type))
        {
            return true;
        }

        // If any method is marked with the AuditedAttribute attribute, an interceptor is still injected for that type.
        if (type.GetMethods().Any(m => m.IsDefined(typeof(AuditedAttribute), true)))
        {
            return true;
        }

        return false;
    }

    //TODO: Move to a better place
    public static bool ShouldAuditTypeByDefault(Type type)
    {
        // The following is to judge whether to inject the audit log interceptor for the current type according to three auxiliary types.
        if (type.IsDefined(typeof(AuditedAttribute), true))
        {
            return true;
        }

        if (type.IsDefined(typeof(DisableAuditingAttribute), true))
        {
            return false;
        }

        if (typeof(IAuditingEnabled).IsAssignableFrom(type))
        {
            return true;
        }

        return false;
    }
}

2.1.2 implementation of audit log interceptor

The internal implementation of audit log interceptor mainly uses three types to work together. They are the IAuditingManager responsible for managing audit log information, the IAuditingHelper responsible for creating audit log information, and the Stopwatch frequently executed by the statistical interface.

The general process of the whole audit log interceptor is as follows:

  1. The first is to determine whether the MVC audit log filter is processed.
  2. Again, verify whether the audit log information should be created according to the characteristics and types.
  3. Create AuditLogInfo and AuditLogActionInfo audit log information according to the call information.
  4. Call the StopWatch timing method. If an exception occurs, add the exception information to the AuditLogInfo object just built.
  5. Whether an exception occurs or not, it will enter the finally statement block. At this time, the stop method of StopWatch instance will be called and the completion execution time will be counted.
public override async Task InterceptAsync(IAbpMethodInvocation invocation)
{
    if (!ShouldIntercept(invocation, out var auditLog, out var auditLogAction))
    {
        await invocation.ProceedAsync();
        return;
    }

    // Start timing operation.
    var stopwatch = Stopwatch.StartNew();

    try
    {
        await invocation.ProceedAsync();
    }
    catch (Exception ex)
    {
        // If an exception occurs, the exception information is added to the audit log results in the same way.
        auditLog.Exceptions.Add(ex);
        throw;
    }
    finally
    {
        // The statistics are completed and the information is added to the audit log results.
        stopwatch.Stop();
        auditLogAction.ExecutionDuration = Convert.ToInt32(stopwatch.Elapsed.TotalMilliseconds);
        auditLog.Actions.Add(auditLogAction);
    }
}

You can see that the following statistics and other operations will be executed only when the ShouldIntercept() method returns true.

protected virtual bool ShouldIntercept(
    IAbpMethodInvocation invocation, 
    out AuditLogInfo auditLog, 
    out AuditLogActionInfo auditLogAction)
{
    auditLog = null;
    auditLogAction = null;

    if (AbpCrossCuttingConcerns.IsApplied(invocation.TargetObject, AbpCrossCuttingConcerns.Auditing))
    {
        return false;
    }

    // If no score is obtained, false is returned.
    var auditLogScope = _auditingManager.Current;
    if (auditLogScope == null)
    {
        return false;
    }

    // Make a secondary judgment on whether the audit log needs to be stored.
    if (!_auditingHelper.ShouldSaveAudit(invocation.Method))
    {
        return false;
    }

    // Build audit log information.
    auditLog = auditLogScope.Log;
    auditLogAction = _auditingHelper.CreateAuditLogAction(
        auditLog,
        invocation.TargetObject.GetType(),
        invocation.Method, 
        invocation.Arguments
    );

    return true;
}

2.2 persistence of audit logs

The general process is the same as what we said above, but it seems that an important step is missing, that is, persistence operation. You can find the definition of IAuditingStore interface in Volo.Abp.Auditing module, but its savesync () method is not called inside the interceptor. Similarly, in the implementation of MVC audit log filter, you will also find that the persistence method is not called.

When are our audit logs persisted? Find the place where savesync() is called, and find that ABP vNext implements an ASP.NET Core middleware for audit logs.

The internal implementation of this middleware is relatively simple. First, a determination method is used to determine whether to execute the IAuditingManager.BeginScope() method for this request. If the decision is passed, execute, otherwise not only do any operation.

public async Task InvokeAsync(HttpContext context, RequestDelegate next)
{
    if (!ShouldWriteAuditLog(context))
    {
        await next(context);
        return;
    }

    using (var scope = _auditingManager.BeginScope())
    {
        try
        {
            await next(context);
        }
        finally
        {
            await scope.SaveAsync();
        }
    }
}

As you can see, ABP vNext is built using IAuditingManager, calls its BeginScope() to build an IAuditLogSaveHandle object, and uses its provided savesync() method for persistence.

2.2.1 nested persistence operation

In the constructed IAuditLogSaveHandle object, the savesync () method provided by AuditingManager, the default implementation of IAuditingManager, is used for persistence.

After reading the source code, I found the following two problems:

  1. IAuditingManager does not expose the persistence method, but as a protected level method.
  2. Why call the persistence method of the manager indirectly with the help of IAuditLogSaveHandle.

This starts with the middleware code. You can see that it constructs an IAuditLogSaveHandle object that can be released. The purpose of ABP vNext is to nest multiple scopes, that is, the audit log is recorded only within a certain range. This feature is similar to the usage of unit of work, and its underlying implementation is the IAmbientScopeProvider object mentioned in the previous article.

For example, in an application service, I can write code as follows:

using (var scope = _auditingManager.BeginScope())
{
    await myAuditedObject1.DoItAsync(new InputObject { Value1 = "I'm internal nested test method 1.", Value2 = 5000 });
    using (var scope2 = _auditingManager.BeginScope())
    {
        await myAuditedObject1.DoItAsync(new InputObject {Value1 = "I'm internal nested test method 2.", Value2 = 10000});
        await scope2.SaveAsync();
    }
    await scope.SaveAsync();
}

Think about the previous code. Inside the interceptor, we get the currently available IAuditLogScope through IAuditingManager.Current, and this Scope is generated after calling IAuditingManager.BeginScope().

2.2.3 final persistence code

Through the above process, we know that the final audit log information will be persisted through iauditingstore. ABP vNext provides us with a default SimpleLogAuditingStore implementation, which internally calls ILogger to output information. If you need to persist the audit log to the database, you can implement the iauditingstore interface to overwrite the original implementation, or use the Volo.Abp.AuditLogging module provided by ABP vNext.

2.3 serialization of audit logs

The serialization of the audit log is used in the default implementation of IAuditingHelper. You can see the internal method of building the audit log. The Action parameters are serialized through a custom serializer to facilitate storage.

public virtual AuditLogActionInfo CreateAuditLogAction(
    AuditLogInfo auditLog,
    Type type, 
    MethodInfo method, 
    IDictionary<string, object> arguments)
{
    var actionInfo = new AuditLogActionInfo
    {
        ServiceName = type != null
            ? type.FullName
            : "",
        MethodName = method.Name,
        // Serialize parameter information.
        Parameters = SerializeConvertArguments(arguments),
        ExecutionTime = Clock.Now
    };

    //TODO Execute contributors

    return actionInfo;
}

protected virtual string SerializeConvertArguments(IDictionary<string, object> arguments)
{
    try
    {
        if (arguments.IsNullOrEmpty())
        {
            return "{}";
        }

        var dictionary = new Dictionary<string, object>();

        foreach (var argument in arguments)
        {
            // The main function of the ignored code is to build a parameter dictionary.
        }

        // Call the serializer to serialize the call parameters of the Action.
        return AuditSerializer.Serialize(dictionary);
    }
    catch (Exception ex)
    {
        Logger.LogException(ex, LogLevel.Warning);
        return "{}";
    }
}

The following is the code of the specific serializer:

public class JsonNetAuditSerializer : IAuditSerializer, ITransientDependency
{
    protected AbpAuditingOptions Options;

    public JsonNetAuditSerializer(IOptions<AbpAuditingOptions> options)
    {
        Options = options.Value;
    }

    public string Serialize(object obj)
    {
        // Use JSON.NET for serialization.
        return JsonConvert.SerializeObject(obj, GetSharedJsonSerializerSettings());
    }

    // ... omitted code.
}

2.4 configuration parameters of audit log

The definitions of configuration parameters related to audit logs are stored in AbpAuditingOptions. Next, I will give a detailed description of the purpose of each parameter.

public class AbpAuditingOptions
{
    //TODO: Consider to add an option to disable auditing for application service methods?

    // This parameter is not used in the current version and is reserved.
    public bool HideErrors { get; set; }

    // Whether to enable the audit log function. The default value is true.
    public bool IsEnabled { get; set; }

    // The application name of the audit log. The default value is null. It is mainly used when building AuditingInfo.
    public string ApplicationName { get; set; }

    // Whether to record audit logs for anonymous requests. The default value is true.
    public bool IsEnabledForAnonymousUsers { get; set; }

    // The collaborator collection of the audit log function. By default, the AspNetCoreAuditLogContributor implementation is added.
    public List<AuditLogContributor> Contributors { get; }

    // The default ignore type is mainly used in serialization.
    public List<Type> IgnoredTypes { get; }

    // Entity type selector.
    public IEntityHistorySelectorList EntityHistorySelectors { get; }

    //TODO: Move this to asp.net core layer or convert it to a more dynamic strategy?
    // Whether to record audit logs for Get requests. The default value is false.
    public bool IsEnabledForGetRequests { get; set; }

    public AbpAuditingOptions()
    {
        IsEnabled = true;
        IsEnabledForAnonymousUsers = true;
        HideErrors = true;

        Contributors = new List<AuditLogContributor>();

        IgnoredTypes = new List<Type>
        {
            typeof(Stream),
            typeof(Expression)
        };

        EntityHistorySelectors = new EntityHistorySelectorList();
    }
}

2.5 entity related audit information

At the beginning of the article, it is mentioned that in addition to the audit log recording of HTTP requests, ABP vNext also provides the function of recording entity audit information. The so-called entity audit information means that after the entity inherits the interface provided by ABP vNext, ABP vNext will automatically maintain the implemented interface fields, which does not need to be processed by the developers themselves.

These interfaces include the related information IHasCreationTime, IMayHaveCreator, ICreationAuditedObject for creating an entity, and the related information interfaces IHasDeletionTime, IDeletionAuditedObject that need to be recorded when deleting an entity. In addition to the types defined by the audit log module, there are also many default implementations of audit entities in the Auditing of Volo.Abp.Ddd.Domain module.

I won't list them one by one here. I'll just quickly explain how ABP vNext realizes the automatic maintenance of audit fields through these interfaces.

Inside the audit log module, we see an interface called IAuditPropertySetter, which provides three methods, namely:

public interface IAuditPropertySetter
{
    void SetCreationProperties(object targetObject);

    void SetModificationProperties(object targetObject);

    void SetDeletionProperties(object targetObject);
}

Therefore, these methods are used to set, create, modify and delete information. Now jump to the default implementation AuditPropertySetter and find any SetCreationTime() method. This method first determines whether the incoming object implements the IHasCreationTime interface. If it implements forced type conversion, then assign a value.

private void SetCreationTime(object targetObject)
{
    if (!(targetObject is IHasCreationTime objectWithCreationTime))
    {
        return;
    }

    if (objectWithCreationTime.CreationTime == default)
    {
        objectWithCreationTime.CreationTime = Clock.Now;
    }
}

The other Set methods are similar. Let's see where the above three methods are used.
You can see that users include EF Core module and MongoDB module. Here, I take EF Core module as an example and guess that entity objects should be passed in.
Sure enough... Check the call chain of this method and find that DbContext will automatically assign audit fields to the entity every time SaveChanges/SaveChangesAsync is performed.

3, Summary

Audit log is an optional component provided by ABP vNext. When the audit log function is enabled, we can quickly locate problems according to the audit log information. However, the opening of the audit log will also greatly affect the performance, because the audit log information will be created for each request and then persisted. Therefore, when using the audit log function, you can combine the DisableAuditingAttribute feature and IAuditingManager.BeginScope() to enable the audit log function on demand.

Posted by slipmatt2002 on Thu, 21 Oct 2021 11:54:11 -0700