Log Insert and Update Command sql query in Entity Framework

Question

I'm trying to log all Database operations in my webapplication.

I have a LOGS class that writes on Database

public partial class LOGS
{
    public static int AddLogs(LOGS log)
    {
        int ret = 0;
        try
        {
            using (var context = new Entities())
            {
                log.Data = DateTime.Now;
                context.LOGS.Add(log);
                ret += context.SaveChanges();
            }
            return ret;
        }
        catch (Exception ex)
        {
            string w = ex.Message;
            return -1;
        }
    }

    public static void WriteDetailed(string query)
    {
        if (u == null || u.LOGLevel == 0)
            return;
        else
        {
            StackTrace st = new StackTrace();
            StackFrame sf = st.GetFrame(1);
            if (sf != null)
            {
                MethodBase currentMethodName = sf.GetMethod();
                String metodo = currentMethodName.ReflectedType.FullName + " " + currentMethodName.Name;

                LOGS newLog = new LOGS();
                newLog.Tipo = "Q";
                newLog.TipoLog = metodo;
                newLog.Testo = query;

                AddLogs(newLog);
            }
        }
    }
}

To log the select operations I the method in this way:

 public static List<Agent> GetAgents()
    {
        try
        {
            using (var context = new Entities())
            {
                var entities = (from a in context.Agent
                                select a);
                LOGS.WriteDetailed(entities.ToString());
                return entities.ToList();
            }
        }
        catch (Exception ex)
        {
            LOGS.WriteExceptionLog(ex);
            return null;
        }
    }

but for me it's impossible to log the insert,updates end delete statements

I read that I could use this method

context.Database.Log = msg => LOGS.WriteDetailed(msg);

and I've tryied to use it in this way:

 public static bool AddAgent(Agent newAgent)
    {
        bool ret = true;

        using (var context = new Entities())
        {
            using (var dbContextTransaction = context.Database.BeginTransaction())
            {
                try
                {
                    newAgent.DateLM = DateTime.Now;
                    context.Agent.Add(newAgent);

                    context.Database.Log = msg => LOGS.WriteDetailed(msg);
                    ret = ret && context.SaveChanges() > 0;
                    if (ret)
                        dbContextTransaction.Commit();
                    else
                        dbContextTransaction.Rollback();

                    return ret;

                }
                catch (Exception ex)
                {
                    LOGS.WriteExceptionLog(ex);
                    return false;
                }
            }
        }

    }

this works but in a strange way: in a single INSERT operation it will pass in the method WriteDetailed 8 times...

1. INSERT [dbo].[Agent]([Name], [Active], [UserLM], [DateLM]) VALUES (@0, @1, @2, @3) SELECT [ID_Agent] FROM [dbo].[Agent] WHERE @@ROWCOUNT > 0 AND [ID_Agent] = scope_identity()
2. (empty) 3.-- @0: 'a' (Type = AnsiString, Size = 100)
3. -- @1: 'True' (Type = Boolean)
4. -- @2: '1' (Type = Int32)
5. -- @3: '25/08/2017 13:34:16' (Type = DateTime2)
6. -- Executing at 25/08/2017 13:46:17 +02:00

7. -- Completed in 8 ms with result: SqlDataReader

   Isn't possible having the complete INSERT Statement at once?

Answer 1

You would have to use more sophisticated mechanisms than just context.Database.Log : https://msdn.microsoft.com/en-us/library/dn469464(v=vs.113).aspx

Apart from mentioned context.Database.Log there is also DatabaseLogFormatter and IDbCommandInterceptor. Here is an example from the link:

public class NLogCommandInterceptor : IDbCommandInterceptor 
{ 
    private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); 

    public void NonQueryExecuting( 
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext) 
    { 
        LogIfNonAsync(command, interceptionContext); 
    } 

    public void NonQueryExecuted( 
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext) 
    { 
        LogIfError(command, interceptionContext); 
    } 

    public void ReaderExecuting( 
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) 
    { 
        LogIfNonAsync(command, interceptionContext); 
    } 

    public void ReaderExecuted( 
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) 
    { 
        LogIfError(command, interceptionContext); 
    } 

    public void ScalarExecuting( 
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext) 
    { 
        LogIfNonAsync(command, interceptionContext); 
    } 

    public void ScalarExecuted( 
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext) 
    { 
        LogIfError(command, interceptionContext); 
    } 

    private void LogIfNonAsync<TResult>( 
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext) 
    { 
        if (!interceptionContext.IsAsync) 
        { 
            Logger.Warn("Non-async command used: {0}", command.CommandText); 
        } 
    } 

    private void LogIfError<TResult>( 
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext) 
    { 
        if (interceptionContext.Exception != null) 
        { 
            Logger.Error("Command {0} failed with exception {1}", 
                command.CommandText, interceptionContext.Exception); 
        } 
    } 
}

Easiest way to set this up is by using static method:

DbInterception.Add(new NLogCommandInterceptor());

Answer 2

You gonna need to accumulate lines and detect SQL statement end. E.g. when the line begins with -- it is obviously past the end of the SQL statement. If you like to capture the comments (and parameters) you can trap the -- Completed line. So instead calling WriteDetailed directly, you call a method to aggregate and analyze the EF generated SQL text and call WriteDetailed yourself as appropriate.

In your LOGS class, add the following:

private static StringBuilder sb = new StringBuilder();

public static void SqlLineGenerated(string line)
{
    sb.Append(line);

    if (line.StartsWith("-- Completed", StringComparison.OrdinalIgnoreCase))
    {
        WriteDetailed(sb.ToString());
        sb = new StringBuilder();
    }
}

Next, setup logging like this:

context.Database.Log = msg => LOGS.SqlLineGenerated(msg);

And you're good to go.

Answer 3

You can aggregate all lines till you get the Executing line, but it wouldn't genetate a plane SQL without parameters.

Alternatively you can try to use ChangeTracker to collect data before SaveChanges call. You can iterate through results of context.ChangeTracker.Entries() and you'll see the state of the object and object data.