SQL Command Logging Using MVC 4 and Entity Framework 5

Entity Framework 6 shipped with a Command Interceptor that makes logging the generated SQL to a file easy.  I recently wanted to add the same functionality to and existing project that was using Entity Framework 5.  I find that it is much easier to debug some problems with an application if you can see the SQL that Entity Framework produces from your queries, this helps you track down issues caused by the way your queries are written.

We have an older project in production that was created with Visual Studio 2010, MVC 4 and Entity Framework 5.  We have been using Entity Framework Profiler to profile our SQL Statements, the company wanted to do away with the cost of renewing a license on the profiler every year.  I decided the thing to do would be to build in our own profiler that would log the SQL to a text file, and allow us some way of just copying and pasting the generated SQL into SQL Manager and executing it.

We already had this capability built into our projects that use Entity Framework 6, and it has been working great for us, so I decided to try and replicate this logger into this older project using Entity Framework 5.  In this post I will take you through my Journey to accomplish this in hopes that it will save some one else some time and effort to accomplish this same task.

To test the logging I will create a sample project called LogSQLWithMVC4EF5 which I will commit to a Github repository that I will link to later in this post.

I will be using a NuGet package called Clutch, some information can be found Here, although there is a glaring lack of any documentation on how to really use this package, it took me using information from several google searches combined to decipher how to actually use this package, but it turns out that it is very simple to use.

After creating a new ASP.NET MVC 4 project in Visual Studio 2010 I used the Manage Nuget Packages interface and did a search for Clutch and installed the Clutch.Diagnostics.EntityFramework package.

ClutchNuGet

Next we want to create a Tracing Listener Class for simplicity in this sample project I just created a Logging Folder in my project and added a new Class and named it DbTracingListener.

using System;
using System.Data;
using System.IO;
using System.Web;
using Clutch.Diagnostics.EntityFramework;

namespace LogSQLWithMVC4EF5.Logging
{
    /// 
    /// Implementation of IDbTracingListener
    /// Class is used for tracing all SQL Queries to the entity framework database
    /// 
    public class DbTracingListener : IDbTracingListener
    {
        public void CommandExecuting(DbTracingContext context) {
            //implementation if needed here..
        }

        public void CommandFinished(DbTracingContext context) {
            //implementation if needed here..
        }

        public void ReaderFinished(DbTracingContext context) {
            //implementation if needed here..
        }

        public void CommandFailed(DbTracingContext context) {
            var commandText = ParseParameters(context);

            commandText = "Failed - Timespan: " + context.Duration + Environment.NewLine + Environment.NewLine + commandText;

            var result = context.Result ?? "None";

            LogSql(commandText, result.ToString());
        }

        public void CommandExecuted(DbTracingContext context) {
            var commandText = ParseParameters(context);

            commandText = "Command - Timespan: " + context.Duration + Environment.NewLine + Environment.NewLine + commandText;

            var result = context.Result ?? "None";

            LogSql(commandText, result.ToString());
        }

        private string ParseParameters(DbTracingContext context) {
            var commandText = context.Command.CommandText;

            if (context.Command.Parameters.Count > 0) {

                for (var index = 0; index < context.Command.Parameters.Count; index++) {
                    var parameter = context.Command.Parameters[index];
                    var parameterName = parameter.ParameterName.StartsWith("@") ? parameter.ParameterName : "@" + parameter.ParameterName;
                    var parameterValue = String.Empty;

                    switch (parameter.DbType) {
                        case DbType.Boolean:
                            parameterValue = parameter.Value.ToString() != "0" ? "true" : "false";
                            break;
                        case DbType.AnsiString:
                        case DbType.AnsiStringFixedLength:
                        case DbType.Date:
                        case DbType.DateTime2:
                        case DbType.DateTimeOffset:
                        case DbType.Guid:
                        case DbType.Object:
                        case DbType.DateTime:
                        case DbType.String:
                        case DbType.StringFixedLength:
                        case DbType.Time:
                        case DbType.Xml:
                            parameterValue = "'" + parameter.Value + "'";
                            break;
                        default:
                            parameterValue = parameter.Value.ToString();
                            break;
                    }
                    commandText = commandText.Replace(parameterName, parameterValue);
                }

            }

            return commandText;
        }

        public void LogSql(string commandText, string result) {
            if (HttpContext.Current == null) {
                return;
            }

            var user = HttpContext.Current.User.Identity.Name;

            if (user == String.Empty) {
                return;
            }

            var fileDirectory = HttpRuntime.AppDomainAppPath + "/Logs/"+ user.Trim();

            // Create Logs Directory If It Does Not Exist
            if (!Directory.Exists(fileDirectory))
                Directory.CreateDirectory(fileDirectory);

            using (var fileWriter = File.AppendText(fileDirectory + "/debuglog.txt")) {
                fileWriter.WriteLine(commandText + Environment.NewLine + Environment.NewLine + "With Result: " + result + Environment.NewLine);
            }

        }

    }
}

This class implements the IDbTracingListener interface from the Clutch Package.  This interface required us to implement the following methods.  CommandExecuting, CommandFinished, ReaderFinished, CommandFailed and CommandExecuted.

All I am really interested in at this time is the SQL produced by Entity Framework and any Command Errors, therefore I chose to only implement code in the CommandFailed and CommandExecuted methods.

The ParseParameters() method will go through the SQL returned from queries, and replace the @0, @1 parameters with the actual value that the query is looking for, this will make it easier to just copy and paste the query to the SQL Manager.

The LogSql() method will write the parsed query out to the text file.

I created a new Folder under the scripts folder named Logging to contain the Java Script file for my SQL Log Dialog.  I added a new Java Script file named debuglog.js to this folder.

$(function () {
    InitializeHiddenSqlLogDialog();
});

function InitializeHiddenSqlLogDialog() {
    $('#sql-log-dialog')
        .dialog({
            height: 500,
            width: 900,
            autoOpen: false,
            modal: true,
            title: "Entity Framework Log",
            buttons:
            {
                "Close": function () { CloseSqlLogDialog(); }
            }
        });
}

function ShowSqlLogDialog() {
    $('#sql-log-dialog').dialog('open');
}

function CloseSqlLogDialog() {
    $('#sql-log-dialog').dialog('close');
}

function LoadDebugLogFile() {
    var userName = "";

    $.when(GetLogInformation()).then(function (data) {
        userName = data.userName;
        
        $.ajax({
            type: "GET",
            url: "/Logs/" + userName + "/debuglog.txt",
            dataType: "text",
            success: function (data) {
                $("#logTextarea").text(data);
                ShowSqlLogDialog();
            }
        });
    });

};

function GetLogInformation() {
    return $.ajax({
        type: 'GET',
        url: '/Logging/GetDebugLogInformation',
        async: true,
        data: {}
    });
}

Next I added a view to display the log file in.  I named the view SqlLogDisplay and I added it to the Shared Folder under the Views Folder.

<table>
    <tr>
        <td>
            <textarea id="logTextarea" cols="118" rows="21" readonly="readonly"></textarea>
        </td>
    </tr>
</table>

The next step is to implement the Trace Listener in the Application_Start() method in Global.asax module.

using System;
using System.Collections.Generic;
using System.Linq;
using System.Web;
using System.Web.Http;
using System.Web.Mvc;
using System.Web.Optimization;
using System.Web.Routing;
using Clutch.Diagnostics.EntityFramework;
using DbTracingListener = LogSQLWithMVC4EF5.Logging.DbTracingListener;

namespace LogSQLWithMVC4EF5 {
    // Note: For instructions on enabling IIS6 or IIS7 classic mode, 
    // visit http://go.microsoft.com/?LinkId=9394801

    public class MvcApplication : System.Web.HttpApplication {
        protected void Application_Start() {
            AreaRegistration.RegisterAllAreas();

            WebApiConfig.Register(GlobalConfiguration.Configuration);
            FilterConfig.RegisterGlobalFilters(GlobalFilters.Filters);
            RouteConfig.RegisterRoutes(RouteTable.Routes);
            BundleConfig.RegisterBundles(BundleTable.Bundles);
            AuthConfig.RegisterAuth();

            // Enable Tracing queries
            DbTracing.Enable();
            // Adding the listener (implementation of IDbTracingListener)
            DbTracing.AddListener(new DbTracingListener());

        }
    }
}

The lines I added will enable the Tracing Listener we created.

We will need to load the JQuery UI Cascading Style Sheets in our _Layout.cshtml file so we will have some styling on our dialog view.

        @Styles.Render("~/Content/css")
        @Styles.Render("~/Content/themes/base/css")
        @Scripts.Render("~/bundles/modernizr")

The style bundle /Content/themes/base/css contains all the JQuery UI style sheets, therefore I added the highlighted line near the top of the _Layout.cshtml file.

Now in our _Layout.cshtml file we want to add a link so we can click on it to display our Debug Log File.

<nav>
  <ul id="menu">
      @if (User.Identity.IsAuthenticated)
      {
          <li><a onclick="javascript:LoadDebugLogFile()" href="#">SQL Log</a>
      }
      <li>@Html.ActionLink("Home", "Index", "Home")
      <li>@Html.ActionLink("About", "About", "Home")
      <li>@Html.ActionLink("Contact", "Contact", "Home")
    </li></ul>
</nav>

The highligted lines above are the ones I added to the _Layout.cshtml to add a link that when clicked will display our SQL Log dialog.

We will need a DIV for our dialog to display in, so I added a Div to the _Layout.cshtml.

<div id="body">
    @RenderSection("featured", required: false)
    <section class="content-wrapper main-content clear-fix">
        @RenderBody()
    </section>
</div>
<div id="sql-log-dialog">
    @{ Html.RenderAction("SqlLogDisplay", "Logging"); }
</div>

This Div that is highlighted above, will contain the SqlLogDisplay view that we created earlier.

We will need to load our debuglog.js Java Script file so it will be available all through out our web site.  So I added the highlighted lines below to our _Layout.cshtml file.

        @Scripts.Render("~/bundles/jquery")
        @Scripts.Render("~/bundles/jqueryui")
        @Scripts.Render("~/Scripts/logging/debuglog.js")
        @RenderSection("scripts", required: false)
    </body>
</html>

In order for us to use the dialog function in JQuery we need to include the JQuery UI libraries before we include our debuglog.js Java Script file.

We will now create a controller we can use to display our SqlLogDisplay view.

I added a controller to the Controllers Folder and named it LoggingController.

using System;
using System.Collections.Generic;
using System.Linq;
using System.Web;
using System.Web.Mvc;

namespace LogSQLWithMVC4EF5.Controllers
{
    public class LoggingController : Controller
    {
        public virtual ActionResult SqlLogDisplay() {
            return PartialView();
        }

        public virtual ActionResult GetDebugLogInformation() {
            var userName = User.Identity.Name;

            return Json(new { userName }, JsonRequestBehavior.AllowGet);
        }

    }
}

The first Action Method SqlLogDisplay in this controller is used to display our SqlLogDisplay.cshtml file by returning a Partial View.

The second Action Method GetDebugLogInformation is used to return the currently logged in Users name so we can use it in our file path to get to the debuglog.txt file for this user.

In the AccountsController I decided to place some code on the user login method to create the Logs directory if it does not already exist, then it Creates or empties out the debuglog.txt file for this user.  I did this so that the log file would not just keep growing bigger and bigger, it essentially deletes and recreates the file on each new login.

[HttpPost]
[AllowAnonymous]
[ValidateAntiForgeryToken]
public ActionResult Login(LoginModel model, string returnUrl) {
    if (ModelState.IsValid && WebSecurity.Login(model.UserName, model.Password, persistCookie: model.RememberMe)) {
                
        var fileDirectory = HttpRuntime.AppDomainAppPath + "/Logs/" + model.UserName.Trim();

        // Create Logs Directory If It Does Not Exist
        if (!Directory.Exists(fileDirectory))
            Directory.CreateDirectory(fileDirectory);

        System.IO.File.CreateText(fileDirectory + "/debuglog.txt");

        return RedirectToLocal(returnUrl);
    }

    // If we got this far, something failed, redisplay form
    ModelState.AddModelError("", "The user name or password provided is incorrect.");
    return View(model);
}

I was thinking I needed some thing in my Demo to generate some SQL, so I added some code to the Contact() Action Method on the HomeController

that would generate some SQL when the user clicked the Contact link.

using WebMatrix.WebData;

I added a using statement to the top of the controller to include the WebMatrix.WebData namespace.  Then I added a line to the Contact() method.

public ActionResult Contact() {
    ViewBag.Message = "Your contact page.";

    ViewBag.UserName = WebSecurity.UserExists(User.Identity.Name);

    return View();
}

The line I added will generate an SQL statement to check if the current user exists in the database.

Unless I forgot to mention something, the Demo project should now be ready to run.  When I run the application and register a new User, then login using that User there is now an SQL Log link on the navigation bar.

SQL Log

At the moment the log is empty, but if I click on the Contact link then click the SQL Log link I should see my dialog with the logged SQL in it.

EFLog1

Now if I close the dialog and click the Contact link again, then click the SQL Log link one more time I should see a second SQL statement appended to the log file.

EFLog2

If I copy and paste one of the SQL statements into SQL Manager I get the following results.

SQLQuery

So, every thing appears to be working as it should.  Just in case I forgot something I have committed the code to a Github repository located at

LogSQLWithMVC4EF5 on Github.

This was just a Demo situation to try and help some one implement SQL Logging using MVC 4 and Entity Framework 5.  The important thing to note is how to implement the IDbTracingListener as we did in the DbTracingListener.cs class and the entries in the Global.asax file to enable the logging.

The choice of displaying the log in a dialog and writing to a text file under specific user names was just for Demo purposes.  You may want to interface with your text file differently or choose a different place and manner to store the file in.  There is a possibility of running into Access Denied error using the text file in this manner as the user may have multiple simultaneous logins.  By changing the LogSql function you could write to the debug console or some thing rather than a text file.  The options are many and there are various ways to implement the actual logging part.

This Demo should be enough though to help point some one in the right direction to implement logging in MVC 4 with Entity Framework 5.

Implementing prism Syntax Highlighting on BlueHost

I use BlueHost to host this Blog, and one of the functions that I really wanted to implement on this Blog was to be able to use Syntax Highlighting on programming code that I wanted to post on here.  My first attempt would not work correctly using a plugin, I’m still learning how all this works.

I decided to narrow my search for instructions down a bit and include BlueHost in my query on Google.  I came across a post on a blog made by some one calling themselves The Crambler.  I followed the instructions in the post and in just a few minutes I had the Syntax Highlighting working using Prism.

The post on Crambler’s blog was entitled How To Implement Prism.js Syntax Highlighting Into Your WordPress Site.  I found the information in this Post to be very helpful and I hope it may help others facing the Syntax Highlighting Blues.

The Birth of This Blog

I subscribe to get emails from John Sonmez at http://simpleprogrammer.com Mr. Sonmez sent an offer for an email course on blogging.  I signed up to receive the course through emails, and started reading them when they came in.  The course is well worth the time and effort to take it, you can sign up for the course at http://devcareerboost.com/blog-course/.

The emails come in twice a week, and are usually pretty short and easy to follow.  I followed the course and was introduced to http://bluehost.com through a link in the course that offered me a nice discount for hosting.  Bluehost was easy to use and the course has a link to a video to show you step by step how to set up your blog.  The support team at Bluehost was also very customer friendly when I called and ask them a couple of questions.

There are some great tips and tricks included in the email blog course for getting started with blogging and the author John Somnez has also published some great tutorial videos that I have watched on https://www.pluralsight.com/ that contain some very important information for Software Developers.

I would gladly recommend the email blogging course to anyone interested in successfully starting their own blog.