Messages are being mixed up through Database.Log b

Question

In my case it's a web API project in Visual Studio. When I'm testing, the API is called multiple times concurrently.

I'm using the following to log the Raw SQL being sent to the SQL Server:

context.Database.Log = Console.WriteLine;

When SQL is logged, it's getting mixed up with queries on other threads. More specifically, it's most-often the parameters which get mixed up. This makes it next to impossible to correlate the right parameters with the right query. Sometimes the same API is called twice concurrently.

I am using async calls, but that wouldn't be causing the issue. It will be the fact there are multiple concurrent web requests on different completion threads.

I need accurate reliable logging so I can look back in the output window and review the SQL.

Answer 1

You need to buffer all log messages per-context, then write out that buffer upon disposal of your db context.

You need to be able to hook into your db context's dispose event

protected override void Dispose(bool disposing)
{
    base.Dispose(disposing);

    if (OnDisposed != null) OnDisposed(this, null);
}

public event EventHandler OnDisposed;

Then you need this class to manage the buffering per-context

class LogGroup
{
    static bool ReferenceActiveGroups = true; //I'm not sure if this is needed. It might work fine without.
    static HashSet<LogGroup> LogGroups = ReferenceActiveGroups ? new HashSet<LogGroup>() : null;

    /// <summary>
    /// For the currently being ran query, this outputs the Raw SQL and the length of time it was executed in the Output window (CTRL + ALT + O) when in Debug mode.
    /// </summary>
    /// <param name="db">The DbContext to be outputted in the Output Window.</param>
    public static void Log(ApiController context, AppContext db)
    {
        var o = new LogGroup(context, db);
        o.Initialise();
        if (ReferenceActiveGroups) o.Add();
    }

    public LogGroup(ApiController context, AppContext db)
    {
        this.context = context;
        this.db = db;
    }

    public void Initialise()
    {
        db.OnDisposed += (sender, e) => { this.Complete(); };
        db.Database.Log = this.Handler;

        sb.AppendLine("LOG GROUP START");
    }

    public void Add()
    {
        lock (LogGroups)
        {
            LogGroups.Add(this);
        }
    }

    public void Handler(string message)
    {
        sb.AppendLine(message);
    }

    public AppContext db = null;
    public ApiController context = null;
    public StringBuilder sb = new StringBuilder();

    public void Remove()
    {
        lock (LogGroups)
        {
            LogGroups.Remove(this);
        }
    }

    public void Complete()
    {
        if (ReferenceActiveGroups) Remove();

        sb.AppendLine("LOG GROUP END");
        System.Diagnostics.Debug.WriteLine(sb.ToString());
    }
}

It should work without saving a strong reference to the LogGroup object. But I haven't tested that yet. Also, you could include this kind of code directly on the context, so you definitely won't need to save a LogGroup reference object. But that wouldn't be as portable.

To use it in a controller action funtion:

var db = new MyDbContext();
LogGroup.Log(this, db);

Note, that I pass the controller reference, so the log can include some extra context information - the request URI.

Interpreting your log

Now that the log works, you'll find the commented parameters in the log output are a pain to work with. You would normally have to manually change them to proper SQL parameters, but even then it's difficult to run sub-sections of a larger SQL query with parameters.

I know there are one or two other ways to get EF to output the log. Those methods do provide better control over how parameters are output, but given the answer is about making Database.Log work I'll include this tool in WinForms, so it can rewrite your clipboard with a functional query.

public partial class Form1 : Form
{
    public Form1()
    {
        InitializeComponent();
    }

    class parameter
    {
        public string Name;
        public string Value;
        public string Type;

        public string FormattedValue
        {
            get
            {
                if (Type == "Boolean")
                {
                    if (Value == "True")
                        return "1";
                    else
                        return "0";
                }
                else if (Type == "Int32")
                {
                    return Value;
                }
                else
                    throw new Exception("Unsupported type - " + Type);
            }

        }

        public override string ToString()
        {
            return string.Format("{0} - {1} - {2} - {3}", Name, Value, Type, FormattedValue);

        }
    }

    private void button1_Click(object sender, EventArgs e)
    {


        var sb = new StringBuilder();
        var data = Clipboard.GetText(TextDataFormat.UnicodeText);
        var lines = data.Split(new string[] { "\r\n" }, StringSplitOptions.None);
        var parameters = GetParmeters(lines);
        parameters.Reverse();

        foreach (var item in lines)
        {
            if (item.Trim().Length == 0)
                continue;
            if (item.TrimStart().StartsWith("--"))
                continue;

            var SQLLine = item;
            foreach (var p in parameters)
            {
                SQLLine = SQLLine.Replace("@" + p.Name, p.FormattedValue);
            }
            sb.AppendLine(SQLLine);
        }

        Clipboard.SetText(sb.ToString());
    }

    private static List<parameter> GetParmeters(string[] lines)
    {
        var parameters = new List<parameter>();
        foreach (var item in lines)
        {
            var trimed = item.Trim();
            if (trimed.StartsWith("-- p__linq__") == false)
                continue;

            var colonInd = trimed.IndexOf(':');
            if (colonInd == -1)
                continue;

            var paramName = trimed.Substring(3, colonInd - 3);
            var valueStart = colonInd + 3;
            var valueEnd = trimed.IndexOf('\'', valueStart);
            if (valueEnd == -1)
                continue;

            var value = trimed.Substring(valueStart, valueEnd - valueStart);

            var typeStart = trimed.IndexOf("(Type = ");
            if (typeStart == -1)
                continue;
            typeStart += 8;

            var typeEnd = trimed.IndexOf(',', typeStart);
            if (typeEnd == -1)
                typeEnd = trimed.IndexOf(')', typeStart);
            if (typeEnd == -1)
                continue;

            var type = trimed.Substring(typeStart, typeEnd - typeStart);

            var param = new parameter();
            param.Name = paramName;
            param.Value = value;
            param.Type = type;

            parameters.Add(param);
        }

        return parameters;
    }
}