Sql Logging With Parameters

ServiceStack.OrmLite SQL Server
1

Hi,

As suggested by:

[ServiceStack OrmLite Sql Query Logging][1]

var sql = connection.GetLastSql(); will give me the last executed sql.
However i get sth like

UPDATE "Batches" SET "BatchStatusID"=@1 WHERE ("ID" = @0)

The thing is that i need to log also the Parameters.

I do not want to use a Profiler for such a simple task and the purpose is to log the whole sql query in case of an exception.

I’ve hacked it using a

    public SpecializedProfiledDbCommand(DbCommand cmd, DbConnection conn, IDbProfiler profiler)
  : base(cmd, conn, profiler)
{
  ASTATICCLASS.DbParameters.Clear();
  ASTATICCLASS.DbParameters.Add(this.Parameters);
}

This way i hold the last parameters and accompanied with the lastSql i can have a proper log.
However this is far from elegant and no threadSafe/AsyncSafe!

I also tried to use a

      public class MyProfiler : IDbProfiler
  {
    public void ExecuteStart(DbCommand profiledDbCommand, ExecuteType executeType)
    {
    }

    public void ExecuteFinish(DbCommand profiledDbCommand, ExecuteType executeType, DbDataReader reader)
    {
    }

    public void ReaderFinish(DbDataReader reader)
    {
    }

    public void OnError(DbCommand profiledDbCommand, ExecuteType executeType, Exception exception)
    {
      var asd = profiledDbCommand;
    }

    public bool IsActive { get; }
  }

SpecializedProfiledDbConnection

      public class SpecializedProfiledDbConnection : ProfiledConnection
  {
    public SpecializedProfiledDbConnection(DbConnection connection, IDbProfiler profiler, bool autoDisposeConnection = true)
        : base(connection, profiler, autoDisposeConnection)
    { }

    public SpecializedProfiledDbConnection(IDbConnection connection, IDbProfiler profiler, bool autoDisposeConnection = true)
        : base(connection, profiler, autoDisposeConnection)
    { }

    protected override DbCommand CreateDbCommand()
    {
      return new SpecializedProfiledDbCommand(InnerConnection.CreateCommand(), InnerConnection, Profiler);
    }
  }

DbFactoryInitialization

    protected static readonly IDbConnectionFactory DbConnectionFactory =
  new OrmLiteConnectionFactory(GlobalConfig.ConnectionString, SqlServerDialect.Provider)
  {
    ConnectionFilter = connection => new SpecializedProfiledDbConnection(connection, new MyProfiler())
  };

However the OnError is never being hit

Thanks

2

If you just set a debug Logging Provider, e.g:

LogManager.LogFactory = new ConsoleLogFactory(debugEnabled:true)

It will log both SQL Statement + params.

If you just want to capture to see what SQL and params OrmLite generates you can use the CaptureSqlFilter which just captures the SQL without executing it.

3

I really appreciate your fast support.

I end up using CaptureSqlFilter which is exactly what i wanted.

Thanks a lot.

4

Unfortunately the CaptureSqlFilter does not let the commands getting executed…

I’m a little confused. The scenario is that in case of an exception i want to Log the Sql Command, accompanied with the parameters.

If i understand correctly

LogManager.LogFactory = new ConsoleLogFactory(debugEnabled:true)

is used for debugging.
EDIT: (Well after further investigation on the source i can see that the pattern of

if (Log.IsDebugEnabled)
            Log.DebugCommand(dbCmd);

is being used as the logging mechanic.

However this is something clearly for debugging since it logs everything.

Can i make the CaptureSqlFilter to only log the commands and not suppress them? I would be grateful for any suggestion.

Thanks in advance

5

Right it only captures the SQL without executing it (mentioned earlier). It takes over control over the execution of the command so can’t be made to also execute the query.

I’ve added support for a OrmLiteConfig.ExceptionFilter in this commit which should do what you need, i.e. you can use it to handle when an Exception occurs when executing a query which gets passed in the IDbCommand and Exception which you can use to extract the SQL that was executed as well as any db params, e.g:

OrmLiteConfig.ExceptionFilter = (dbCmd, ex) =>
{
    var lastSql = dbCmd.CommandText;
    var lastParam = (IDbDataParameter)dbCmd.Parameters[0];
};

This change is available from v4.0.61 that’s now available on MyGet.

6

Hi mythz,

I understood incorrectly that it was not required for the sql to be executed to be logged, and not that it wasn’t executed at all :smile:

Anyway, i saw your commit and i really appreciate your support. Haven’t yet implemented it, out of the office…

I also think that others will find usefull the new feature.

Thanks again

1 Like
7

Hello and sorry for bumping this up.

I was converting some code from sync to async.
The thing is that ExceptionFilter is static, and not a variable linked with the IdbConnection itself(instance).

Having that in mind i was thinking how in an async/await enviroment when multiple db connection are going to be spanned across different/multiple threads in case multiple exception are being thrown at the same time(on different threads) this is going to work properly.

Having something like this Inside evey db call:

 OrmLiteConfig.ExceptionFilter = (command, exception) =>
{
lastSql = command.CommandText;
lastParams = command.Parameters;
};

isn’t going to eventually mess things since we have multiple db accesses from multiple threads?

8

OrmLiteConfig.ExceptionFilter being static isn’t an issue as the arguments are passed in the callback, i.e. it’s not accessing static state. But you shouldn’t be reassigning the ExceptionFilter callback, if that’s what you’re thinking about doing.

9

Ok having one assignement for this is ok, however:

There is no easy way to demonstrate it here so copy paste to a console or test:
You can use Any table with a UID and an int column,just make sure it will throw (ex constraint)

    private static Random rnd = new Random();
static string lastSql = null;
static IDataParameterCollection lastParam = null;

static async Task Test()
{
  var ConnectionString = ConfigurationManager.ConnectionStrings["ConnectionStringLocal"].ConnectionString;
  OrmLiteConnectionFactory DbFactory = new OrmLiteConnectionFactory(ConnectionString, SqlServer2016Dialect.Provider);

  OrmLiteConfig.ExceptionFilter = (command, exception) =>
  {
    lastSql = command.CommandText;
    lastParam = command.Parameters;
  };

  for (int i = 0; i < 150; i++)
  {
    // No await to reproduce Server async enviroment
    /*await*/ NewMethod(DbFactory, i);
  }
}

private static async Task NewMethod(OrmLiteConnectionFactory DbFactory, int i)
{
  using (var db = DbFactory.OpenDbConnection())
  {
    try
    {
      // Random delay so at to mix server random requests
      await Task.Delay(rnd.Next(1, 1000));
      // Use a table with a Unique Id that's already there
      // Use an int column at this table to put the i
      var results = db.Insert<Batch>(new Batch() { Id = 2, CreatedDate = DateTime.Now, LockedBy = i });
    }
    catch (Exception)
    {
      Console.WriteLine($ "Exception:{i} {lastParam.GetParams()}");
    }
  }
}

static void Main(string[] args)
{
  Task.Run(async () => { await Test(); }).GetAwaiter().GetResult();
  Console.ReadKey();
}

public static string GetParams(this IDataParameterCollection parameters)
{
  string returnValue = string.Empty;
  if (parameters != null)
  {
    foreach (SqlParameter item in parameters)
    {
      var name = item.ParameterName;
      var sql = item.SqlValue.ToString();
      returnValue += name + ": " + sql + Environment.NewLine;
    }
  }
  return returnValue;
}

You will notice Exception:{i} and CreatedBy:{i} will be different

10

If you wrap try/catch block in Transaction with IsolationLevel.ReadCommitted you will get the same numbers in Exception:{i} and LockedBy:{i}

private static async Task NewMethod(OrmLiteConnectionFactory DbFactory, int i)
{
    using (var db = DbFactory.OpenDbConnection())
    {
        using (var trans = db.OpenTransaction(IsolationLevel.ReadCommitted))
        {
            try
            {
                // Random delay so at to mix server random requests
                await Task.Delay(rnd.Next(1, 1000));
                // Use a table with a Unique Id that's already there
                // Use an int column at this table to put the i
                var results = db.Insert<Batch>(new Batch() { Id = 2, CreatedDate = DateTime.Now, LockedBy = i });
            }
            catch (Exception)
            {
                Console.WriteLine($ "Exception:{i} {lastParam.GetParams()}");
            }
        }
    }
}
11

No you won’t and even if it did this has nothing to do with the Isolation level, but more of a side effect. The thing is that between async calls the IDbConnection (OrmLiteConnection should hold the ExceptionFilter and not a static class).

Exception:27 
@LockedBy: 6

This is why .Net 4.6.1 introduced AsyncLocal.

When you are on async and multiple requests arrive, let’s say you have a single point of DbAccess:

private T QueryInner<T>(Func<IDbConnection, T> query, IsolationLevel? isolationLevel)

Inside you have sth like this:

try
      {
		...
        returnValue = query(connection);
      }
      catch (Exception ex)
      {
        Logger.LogErrror("ServiceBase", "SQL: " + $ "{lastSql}, {lastParams.GetParams()}", null, ex);


        throw ex;
      }

Now the problem is that when something throws, you expect to catch it. However another exception might be thrown just before you catch it on another thread (or the same/async/) .The static Action will change the static variables for lastSql and lastParams

Hackish way for this is for me to check when lastSql is changed and to notify so as to handle this without interfering with OrmLite.

@mythz Of course i could always be using this wrongly or have missunderstood sth :smile: .

12

Oh, I missed that you saving intermediate results into static variable and then trying to access it. But why don’t you use AsyncLocal<> (or ExecutionContext in .NET 4.5) in this case?

13

Cause i’m thinking that i want to add this behavior to the OrmLiteConnection itself and not doing circles. The thing is that before i cut a branch or sth i wanted to discuss this with mythz and if he has sth better in mind :smile:

14

You shouldn’t be capturing it in static variables, I’d just be doing the logging from inside ExceptionFilter - if you want to capture the variables you’d need to use AsyncLocal storage as @xplicit suggested.

1 Like
15

Thank you both for this conversation.
You really killed me with this super simple solution which i haven’t thought from the beginning. :blush: