Log RestServiceBase request and response

Question

I'm using an old project that still references RestServiceBase<TRequest> and I know need to log all calls request and response for this API.

I can easily go through each service implementation and add something like:

// get reponse from request
object response = this.OnGetSpecificAccount(request);

// log
Logs.LogRequestWithResponse(
                this.RequestContext, this.Request.HttpMethod, response.ToJson());

and after some extraction and inserting into the database I would get a log looking like:

see larger image

But I was wondering if there's already some Logging implementation that I could take advantage and can easily hook up to the base class and log this automatically, as I would want to log the Auth call as well (in order to get the username that is being authenticated and match the username with the session.

Answer 1

While there is built in logging using the RequestLogsFeature, this is aimed at debugging your project.

However ServiceStack does make it easy to get at all the relevant information you need by using a request filter that will be run for each request.

The code below demonstrates how you would record how long a request takes, and the other values you were looking for, such as SessionId, IP address, Verb, URI, etc.

public override void Configure(Funq.Container container)
{
    // Record the time the request started.
    this.GlobalRequestFilters.Add((req, res, requestDto) => req.SetItem("StartTime", DateTime.Now));

    // The request has been processed, ready to send response
    this.GlobalResponseFilters.Add((req, res, responseDto) => {

        var startTime = req.GetItem("StartTime") as DateTime?;
        var endTime = DateTime.Now;

        var log = new {

            // Request URL
            Url = req.AbsoluteUri,

            // Verb
            Verb = req.Verb,

            // Session Id
            SessionId = req.GetSessionId(),

            // IP Address
            Ip = req.RemoteIp,

            // Record the Request DTO
            Request = req.Dto.ToJson(),

            // Record the Response DTO
            Response = responseDto.ToJson(),

            // Get the start time that was recorded when the request started
            StartTime = startTime.Value,

            // Time request finished
            EndTime = endTime,

            // Determine the duration of the request
            Duration = endTime - startTime.Value,

        };

        // Save the log to the database
        // Resolve the database connection
        var db = TryResolve<IDbConnectionFactory>().OpenDbConnection();
        // ...

    });
}

I hope this helps.

Answer 2

You can log all the request/responses using the RequestLogsFeature. At my company a co-worker implemented the ability to save this information to a database. We however don't log the responses.

Update Someone asked for our implementation. We originally used NewtonSoft.Json for json but I could never see the request data in the UI as it was deserialized. So I switched to Servicestack json and it worked as expected. Here it is:

DatabaseLoggingFeature.cs

   public class DatabaseLoggingFeature : IPlugin
{
    public DatabaseLoggingFeature(string connectionStringKey, int? capacity = null)
    {
        AtRestPath = "/requestlogs";
        ConnectionStringKey = connectionStringKey;
        Capacity = capacity;
        RequiredRoles = new[] {RoleNames.Admin};
        EnableErrorTracking = true;
        EnableRequestBodyTracking = false;
        ExcludeRequestDtoTypes = new[] {typeof (RequestLogs), typeof (ResourceRequest), typeof (Resources)};
        HideRequestBodyForRequestDtoTypes = new[]
        {
            typeof (Auth), typeof (Registration)
        };
    }

    /// <summary>
    ///     Gets or sets connection string
    /// </summary>
    public string ConnectionStringKey { get; set; }

    /// <summary>
    ///     RequestLogs service Route, default is /requestlogs
    /// </summary>
    public string AtRestPath { get; set; }

    /// <summary>
    ///     Turn On/Off Session Tracking
    /// </summary>
    public bool EnableSessionTracking { get; set; }

    /// <summary>
    ///     Turn On/Off Logging of Raw Request Body, default is Off
    /// </summary>
    public bool EnableRequestBodyTracking { get; set; }

    /// <summary>
    ///     Turn On/Off Tracking of Responses
    /// </summary>
    public bool EnableResponseTracking { get; set; }

    /// <summary>
    ///     Turn On/Off Tracking of Exceptions
    /// </summary>
    public bool EnableErrorTracking { get; set; }

    /// <summary>
    ///     Size of InMemoryRollingRequestLogger circular buffer
    /// </summary>
    public int? Capacity { get; set; }

    /// <summary>
    ///     Limit access to /requestlogs service to these roles
    /// </summary>
    public string[] RequiredRoles { get; set; }

    /// <summary>
    ///     Change the RequestLogger provider. Default is InMemoryRollingRequestLogger
    /// </summary>
    public IRequestLogger RequestLogger { get; set; }

    /// <summary>
    ///     Don't log requests of these types. By default RequestLog's are excluded
    /// </summary>
    public Type[] ExcludeRequestDtoTypes { get; set; }

    /// <summary>
    ///     Don't log request body's for services with sensitive information.
    ///     By default Auth and Registration requests are hidden.
    /// </summary>
    public Type[] HideRequestBodyForRequestDtoTypes { get; set; }

    /// <summary>
    ///     Registers plugin with service stack
    /// </summary>
    /// <param name="appHost">Application Host configuration object.</param>
    public void Register(IAppHost appHost)
    {
        appHost.RegisterService<RequestLogsService>(AtRestPath);

        IRequestLogger requestLogger = RequestLogger ?? new DatabaseRequestLogger(ConnectionStringKey);
        requestLogger.EnableSessionTracking = EnableSessionTracking;
        requestLogger.EnableResponseTracking = EnableResponseTracking;
        requestLogger.EnableRequestBodyTracking = EnableRequestBodyTracking;
        requestLogger.EnableErrorTracking = EnableErrorTracking;
        requestLogger.RequiredRoles = RequiredRoles;
        requestLogger.ExcludeRequestDtoTypes = ExcludeRequestDtoTypes;
        requestLogger.HideRequestBodyForRequestDtoTypes = HideRequestBodyForRequestDtoTypes;

        appHost.Register(requestLogger);

        if (EnableRequestBodyTracking)
        {
            appHost.PreRequestFilters.Insert(0,
                (httpReq, httpRes) => { httpReq.UseBufferedStream = EnableRequestBodyTracking; });
        }
    }
}

DatabaseRequestLogger.cs

public class DatabaseRequestLogger : IRequestLogger
{
    /// <summary>
    ///     Instance of the current database connection;
    /// </summary>
    private readonly DbConnection _connection;

    public DatabaseRequestLogger(string connectionStringKey)
    {
        if (string.IsNullOrEmpty(connectionStringKey))
        {
            throw new ArgumentNullException("connectionStringKey");
        }

        if (_connection != null || string.IsNullOrEmpty(connectionStringKey)) return;
        ConnectionStringSettingsCollection connectionStrings = ConfigurationManager.ConnectionStrings;

        if (connectionStrings == null) return;
        foreach (ConnectionStringSettings setting in connectionStrings.Cast<ConnectionStringSettings>()
            .Where(setting => setting.Name == connectionStringKey))
        {
            ConnectionString = setting.ConnectionString;
            ProviderName = setting.ProviderName;
            _connection = GetConnection(ProviderName, ConnectionString);
        }
    }

    public ILog log { get; set; }

    /// <summary>
    ///     Gets connection string
    /// </summary>
    public string ConnectionString { get; private set; }

    /// <summary>
    ///     Gets provider name
    /// </summary>
    public string ProviderName { get; private set; }

    /// <summary>
    /// </summary>
    public bool EnableErrorTracking { get; set; }

    /// <summary>
    /// </summary>
    public bool EnableRequestBodyTracking { get; set; }

    /// <summary>
    /// </summary>
    public bool EnableResponseTracking { get; set; }

    /// <summary>
    /// </summary>
    public bool EnableSessionTracking { get; set; }

    /// <summary>
    /// </summary>
    public Type[] ExcludeRequestDtoTypes { get; set; }

    /// <summary>
    ///     Returns latest log entries.
    /// </summary>
    /// <param name="take">number of records to retrieve.</param>
    /// <returns>List of RequestLogEntry</returns>
    public List<RequestLogEntry> GetLatestLogs(int? take)
    {
        var entries = new List<RequestLogEntry>();

        if (_connection != null)
        {
            if (_connection.State == ConnectionState.Closed)
            {
                _connection.Open();
            }

            using (DbCommand cmd = _connection.CreateCommand())
            {
                string query = "SELECT {0} FROM [dbo].[RequestLog] ORDER BY LoggedDate DESC";

                query = take.HasValue
                    ? string.Format(query, "TOP " + take.Value.ToString(CultureInfo.InvariantCulture) + " * ")
                    : string.Format(query, "*");

                cmd.Connection = _connection;
                cmd.CommandType = CommandType.Text;
                cmd.CommandText = query;

                try
                {
                    DbDataReader dr = cmd.ExecuteReader(CommandBehavior.CloseConnection);

                    while (dr.Read())
                    {
                        var serializer = new JsonSerializer<RequestLogEntry>();

                        RequestLogEntry entry = serializer.DeserializeFromString(dr["LogEntry"].ToString());

                        entries.Add(entry);
                    }
                }
                catch (Exception)
                {
                    cmd.Parameters.Clear();

                    if (cmd.Connection.State == ConnectionState.Open)
                    {
                        cmd.Connection.Close();
                    }
                }
            }
        }

        return entries;
    }

    /// <summary>
    /// </summary>
    public Type[] HideRequestBodyForRequestDtoTypes { get; set; }

    /// <summary>
    /// </summary>
    public string[] RequiredRoles { get; set; }

    /// <summary>
    ///     Logs request/response data.
    /// </summary>
    /// <param name="requestDto"></param>
    /// <param name="response">instance of <see cref="IHttpResponse" /> object.</param>
    /// <param name="requestContext"></param>
    /// <param name="duration"></param>
    public void Log(IRequestContext requestContext, object requestDto, object response, TimeSpan duration)
    {
        Type requestType = requestDto != null ? requestDto.GetType() : null;

        // if we don't want to track the request simply bail out.
        if (ExcludeRequestDtoTypes != null
            && requestType != null
            && ExcludeRequestDtoTypes.Contains(requestType))
        {
            return;
        }

        //Move this code to another class and create an interface

        if (_connection != null)
        {
            if (_connection.State == ConnectionState.Closed)
            {
                _connection.Open();
            }

            using (DbCommand cmd = _connection.CreateCommand())
            {
                cmd.Connection = _connection;
                cmd.CommandType = CommandType.StoredProcedure;
                cmd.CommandText = "spLogRequest";

                var entry = new RequestLogEntry
                {
                    DateTime = DateTime.UtcNow,
                    RequestDuration = duration
                };

                IHttpRequest httpRequest = requestContext != null ? requestContext.Get<IHttpRequest>() : null;

                if (httpRequest != null)
                {
                    entry.HttpMethod = httpRequest.HttpMethod;
                    entry.AbsoluteUri = httpRequest.AbsoluteUri;
                    entry.PathInfo = httpRequest.PathInfo;
                    entry.IpAddress = requestContext.IpAddress;
                    entry.Headers = httpRequest.Headers.ToDictionary();
                    entry.Referer = httpRequest.Headers[HttpHeaders.Referer];
                    entry.ForwardedFor = httpRequest.Headers[HttpHeaders.XForwardedFor];
                    entry.RequestDto = requestDto;
                    entry.Items = httpRequest.Items;
                    entry.UserAuthId = httpRequest.GetItemOrCookie(HttpHeaders.XUserAuthId);
                    entry.SessionId = httpRequest.GetSessionId();
                    entry.Session = EnableSessionTracking ? httpRequest.GetSession() : null;

                    if (HideRequestBodyForRequestDtoTypes != null
                        && requestType != null
                        && !HideRequestBodyForRequestDtoTypes.Contains(requestType))
                    {
                        entry.RequestDto = requestDto;

                        entry.FormData = httpRequest.FormData.ToDictionary();

                        if (EnableRequestBodyTracking)
                        {
                            entry.RequestBody = httpRequest.GetRawBody();
                        }
                    }

                    if (!response.IsErrorResponse())
                    {
                        if (EnableResponseTracking)
                        {
                            entry.ResponseDto = response;
                        }
                    }
                }

                DbParameter requestParam = cmd.CreateParameter();
                requestParam.ParameterName = "@LogEntry";
                requestParam.Direction = ParameterDirection.Input;
                requestParam.DbType = DbType.String;
                //JsConfig.IncludeTypeInfo = true;
                requestParam.Value = new JsonSerializer<RequestLogEntry>().SerializeToString(entry);

                DbParameter requestDurationParam = cmd.CreateParameter();
                requestDurationParam.ParameterName = "@RequestDuration";
                requestDurationParam.Direction = ParameterDirection.Input;
                requestDurationParam.DbType = DbType.Int64;
                requestDurationParam.Value = entry.RequestDuration.Ticks;

                cmd.Parameters.Add(requestParam);
                cmd.Parameters.Add(requestDurationParam);

                try
                {
                    cmd.ExecuteNonQuery();
                    cmd.Connection.Close();
                }
                catch (Exception ex)
                {
                    log.Error("Error occurred saving request log entry to the database in Log.", ex);
                }
                finally
                {
                    cmd.Parameters.Clear();

                    if (cmd.Connection.State == ConnectionState.Open)
                    {
                        cmd.Connection.Close();
                    }
                }
            }
        }
    }