Messages are mixed through Database.Log across multiple threads

Question

In my case, this is a web API project in Visual Studio. When I test, the API is called several times at the same time.

I use the following to register Raw SQL being submitted to SQL Server:

context.Database.Log = Console.WriteLine; 

When SQL is registered, it mixes with queries in other threads. In particular, these are most often parameters that are mixed. This makes it impossible to match the correct parameters with the correct query. Sometimes the same API is called twice at the same time.

I use asynchronous calls, but this will not cause a problem. It will be the fact that there are several concurrent web requests in different completion threads.

I need accurate reliable logging, so I can go back to the output window and view SQL.

Answer 1

You need to buffer all log messages in context, and then write out this buffer after deleting your db context.

You need to be able to connect to your db dispose event context

 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 control buffering for each 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 reference to the LogGroup object. But I have not tested this yet. In addition, you can include this type of code directly in the context, so you definitely will not need to save the LogGroup reference object. But that would not be as portable.

To use it in controller action functions:

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

Please note that I am passing a link to the controller, so the log may contain some additional contextual information - the request URI.

Interpretation of your journal

Now that the log is running, you will find that the commented parameters in the log output are a pain to work with. Usually you will have to manually change them to the correct SQL parameters, but even then it is difficult to run subsections of a larger SQL query with parameters.

I know that there are one or two other ways to get EF for log output. These methods provide better control over how the parameters are displayed, but given the answer about creating a Database.Log job, I will include this tool in WinForms so that it can rewrite your clipboard with a functional request.

 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; } }