Real time logs with Chrome dev tools and signalr part 2


This is the second post in a series talking about creating real time logging using chrome dev tools and real time communication libraries such as signalr. The first post focused on the server-side portion of the setup. This post will focus on creating the chrome devtools plugin which will display the logging information from the server.

About chrome plugins
If you know html/javscript/css, creating a chrome extension is actually really easy. The only gripe I have is there seems to be no way to inspect dev tools extension panels.But, you can get around that by sending errors from window.onerror and try/catch to the inspected window or background page console. Another thing to keep in mind is certain features will not work if you don’t have the appropriate permissions in the plugin configuration. I strongly suggest reading the chrome developer documentation for a better understanding of how devtools plugins work.

Creating the Plugin
I will start off with a layout of the plugin files in the file system and explain each file in a logical order.
Plugin layout

Plugin Manifest
This file tells chrome about the plugin and the various files it needs to work correctly.

{
  "manifest_version": 2,
  "name": "Real Time Logger",
  "description": "This extension allows applications to send logs to client without embedded scripts",
  "version": "1.0",
  "background":{
  	"persistent": true,
    "scripts": ["lib/jquery-2.0.3.js","lib/jquery.signalR-2.0.1.js","background.js"]
  },
  "permissions": [
    "tabs", "http://*/*", "https://*/*"
  ],
  "devtools_page": "devtools.html"
}

The “background” directive will instruct chrome to load an html page and include the three js files as scripts. Alternatively, you can create your own background.html and include the scripts yourself. The permissions control access to otherwise limited capabilities of the chrome extensions api. The devtools_page is where the plugin will create the panel used by the plugin to display the log information.

Background.js
This is the workhorse of the plugin. It will maintain all the connections to the server, receive the log messages and pass them out to the respective panels to be displayed.

var connectionlib = {
	signalr: function(){
		var connection;
		return {
			init: function(settings, handler){
					 var url = settings['baseurl'] + settings['url'];
					 connection = $.hubConnection(url, { useDefaultPath: false });
					 var proxy = connection.createHubProxy(settings['hub']);
					 proxy.on('onSql', function(sql) {
						handler(sql);
					 });
	
					 connection.start();
			},
			stop: function(){
				connection.stop();
			}
		}
	}
}




chrome.runtime.onConnect.addListener(function (port) {

     chrome.tabs.executeScript(parseInt(port.name),{ file: 'autodiscover.js' },function(result){

     	var options = result[0].split(";");
     	var settings = {};
     	for(var o in options){
     		var s = options[o].split('=');
     		settings[s[0]] = s[1];
     	}
     	
     	var lib = connectionlib[settings['library']]();
     	lib.init(settings,function(sql){
     		port.postMessage(sql);
     	});
     	
     });

   	  
      port.onDisconnect.addListener(function(p) {
    		lib.stop();
      });
 
});

The connectionlib object is just a simple way to handle support for multiple libraries. The listener function is where all the magic happens. For every dev tools panel which connects to it, it will attempt to detect if the inspected page supports real time logging and connect to it.

autodiscover.js
The background page will inject this code into the inspected window and if the it finds a meta tag with realtime logging configuration, it will send that configuration back to the background page.

var autoDiscover = document.querySelector('meta[name="real-time-log"][content]');
if(autoDiscover){
		autoDiscover.content + ';baseurl=' + window.location.protocol + '//'+ window.location.host
}

When I thought of ways the dev tools plugin could discover logging capabilities the first thing that came to my mind was meta tags. However, this can be achieved using custom headers or some other content in the page. Another option is to not use automatic discovery at all and opt for entering the url in the panel.

devtools.js
This code is very simple. All it does is create our logging panel when devtools opens.

chrome.devtools.panels.create("Real Time Log",
    "icon.png",
    "Panel.html",
    function(panel) {
      // code invoked on panel creation
    }
);

panel.js
This code will connect to the background page and wait for any incoming logs to output.

var log = document.getElementById('log');
var clear = document.getElementById('clear');

clear.addEventListener("click", function(){
	log.innerHTML = '';
});

var backgroundConnection = chrome.runtime.connect({
    name: ''+ chrome.devtools.inspectedWindow.tabId + ''
});

backgroundConnection.onMessage.addListener(function(sql){
	var li = document.createElement('pre');
	li.innerHTML =  hljs.highlight('sql', sql).value;
	log.appendChild(li);
});

panel.html
This page contains the elements the user can see an interact with in the devtools panel. The log element will display all log messages. Highlight will be used for syntax highlighting in the messages.

<html>
<head>
<link rel="stylesheet" href="lib/highlight/styles/xcode.css" />
<link rel="stylesheet" href="panel.css" />
</head>
<body>
<button id="clear">Clear</button>
<div id="log"></div>
<script src="lib/highlight/highlight.pack.js"></script>
<script src="panel.js"></script>
</body>
</html>

panel.css
This is some basic css for presenting the logs

pre {
	border-bottom:#cccccc 1px solid;
	padding-bottom:3px;
}

panel.css
This is some basic css for presenting the logs

pre {
	border-bottom:#cccccc 1px solid;
	padding-bottom:3px;
}

devtools.html
All this file does is include the devtools.js

<script src="devtools.js"></script>

What I have described so far in my two posts is really all you need for a basic implementation of this real time logging concept. You can download highlight.js from http://highlightjs.org/. I was only able to get the signalR client files by creating a dummy project and adding it to the project via nuget.

General Overview of the entire solution:
Real time plugin

The code in this post is a really basic get your hands dirty example. I created a github project which I will use to take the idea further. You are free to download the plugin, try it out and send pull requests if you wish. The project readme explains how to install and use the plugin.

Real time logs with Chrome dev tools and signalr part 1


This post was created to document the process of creating a Google Chrome Dev Tools extension which will allow a web application or plugin developer to get real time log information in the browser while developing. This first post will cover creating the web application which will log information to the dev tools extension. The second post will talk about creating the dev tools extension and connecting to the application.

What is this really about?
If you visit a site like bugs.mysql.com you will notice it tells you how long it took to generate the page. In my case it said this “Page generated in 0.017 sec. using MySQL 5.6.15-enterprise-commercial-advanced-log”. There are basically two types of logs, the ones that are persisted somehow on the server and others that are sent back to the client somehow. The mysql bugs page is an example of the latter. In this post I will be talking about the sending relevant information back to the client independent of any specific requests.

Ajax has changed everything
When I did constant WordPress development, there were many times my blog/app did not behave the way it was supposed to and I had no way of seeing what was going on. I eventually created a plugin which not only outputted all the request data, it also allowed me to output arbitrary logs, warnings, errors and sql statements together with the generated page. Fast forward to today where the apps I work on are about 90% asynchronous and views are handled on the client side, it is no longer convenient to simply output some arbitrary html/javascript to the bottom of every page. To solve this problem we need two things:

  • A way to transport the debug/log information to the client
  • A way to display that debug/log information on the client side once it is received

The first can be satisfied by making use of real time protocols such as WebSockets. This will continue to report back to the client even when a request fails. The second can be satisfied by creating a dev tools extension which will receive and display the debug/log information. Again this log lives in the browser and therefore will be independent of individual page requests.

A real use case
For the past couple years I have worked with asp.net mvc and entity framework quite a bit. Two common task I have are to figure out why certain records aren’t showing up on a given screen and why a given feature is slow. Part of my process is opening up sql profiler and logging any relevant sql queries which come in from the app. With this I can see whether or not the correct filters were applied via where clauses and also how long each individual query took to run. This works ok except that it is yet another window I need to open on my already crowded screen and it isn’t always easy to target the queries I am interested in. So what if instead of opening sql profiler, my sql statements came back to a neat little console in the browser where I am working? All I would have to do is open up dev tools and I would see all the sql activity as it happened. So in effect what I am looking for is a sql profiler but in the browser. One that only shows me relevant information.

Technology options
Before I go on, please note that my chosen technologies are strictly based on the fact that I develop mostly in asp.net mvc on sql server. However, this sort of thing can be done using Node.js and Socket.io or even Mono and XSockets.NET. So although I am doing this using SignalR, my proof of concept was actually done with Node.js and Socket.io.

Implementing the server side
The real time part of this is very simple because SignalR is really easy to setup and use in an application. You won’t even break a sweat adding it after the fact. For logging the sql statements, we will make use of the new interceptor api introduced in entity framework 6.

We will start off by creating a new asp.net mvc 5 project in visual studio
new app

Once the project has been created use the package manager console or the Nuget GUI to add the latest SignalR (2.0+ id:Microsoft.AspNet.SignalR), EntityFramework (6.0+) and jQuery(2.0+) to the project. Next create a new class which will act as the SignalR bootstrapper

[assembly: OwinStartup(typeof(RealTimeLogging.SignalRStartup))]
namespace RealTimeLogging
{
   
    public class SignalRStartup
    {
        public void Configuration(IAppBuilder app)
        {
            app.MapSignalR();
        }
    }

}

Next create the SignalR hub by creating a new class which extends Microsoft.AspNet.SignalR.Hub

namespace RealTimeLogging
{
    public class LoggingHub : Hub
    {
    }
}

The next class will allow us to send messages via any SignalR hub from anywhere in the application. This class can actually be used for any hub.

namespace RealTimeLogging
{
    public static class HubCaller
    {
        public static void Invoke<THub>(Action<IHubContext> action) where THub : IHub
        {
            var context = GlobalHost.ConnectionManager.GetHubContext<THub>();

            action.Invoke(context);
        }
    }
}

Next create a class which implements the IDbCommandInterceptor interface. This class will be used to intercept entity framework DbCommands and results and send the sql statements down to the client via our SignalR hub.

namespace RealTimeLogging
{
    public class StatementLogger : IDbCommandInterceptor
    {

        void IDbCommandInterceptor.NonQueryExecuted(System.Data.Common.DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {
            SendToClient(command.CommandText);
        }

        void IDbCommandInterceptor.NonQueryExecuting(System.Data.Common.DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {
            SendToClient(command.CommandText);
        }

        void IDbCommandInterceptor.ReaderExecuted(System.Data.Common.DbCommand command, DbCommandInterceptionContext<System.Data.Common.DbDataReader> interceptionContext)
        {
            SendToClient(command.CommandText);
        }

        void IDbCommandInterceptor.ReaderExecuting(System.Data.Common.DbCommand command, DbCommandInterceptionContext<System.Data.Common.DbDataReader> interceptionContext)
        {
            SendToClient(command.CommandText);
        }

        void IDbCommandInterceptor.ScalarExecuted(System.Data.Common.DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            SendToClient(command.CommandText);
        }

        void IDbCommandInterceptor.ScalarExecuting(System.Data.Common.DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            SendToClient(command.CommandText);
        }

        void SendToClient(string sql)
        {
            HubCaller.Invoke<LoggingHub>(_c => _c.Clients.All.onSql(sql));
        }
    }
}

The above interface gives us access to more than than just sql statements so the possibilities for adding to this class are endless. However, let us just keep it simple for now. Once registered with entity framework, the above class will send the command text of all DbCommands it receives to the client. There are several issues with the current implementation which we can fix later. The first is we assume all CommandText is sql. Another is we are sending messages to everyone instead of just the current user.

Next we will create an Entity Framework Code-First database and a client page to initiate queries so we have something to log.

Entity:

namespace RealTimeLogging
{
    public class Person
    {
        [DatabaseGenerated(DatabaseGeneratedOption.Identity)] 
        public int PersonID { get; set; }

        [StringLength(50)]
        public string FirstName { get; set; }

        [StringLength(50)]
        public string LastName { get; set; }

        public int Age { get; set; }
    }
}

Context:

namespace RealTimeLogging
{
    public class PersonContext : DbContext
    {
        public DbSet<Person> People { get; set; }
    }
}

Initializer:

namespace RealTimeLogging
{
    public class DbInitializer : DropCreateDatabaseAlways<PersonContext>
    {
        protected override void Seed(PersonContext context)
        {
            context.People.Add(new Person
            {
                FirstName = "John",
                LastName = "Doe",
                Age = 55

            });

            context.People.Add(new Person
            {
                FirstName = "Jane",
                LastName = "Smith",
                Age = 90

            });

            context.SaveChanges();
        }
    }
}

Db config where initializer and interceptor is registered with entity framework.

namespace RealTimeLogging
{
    public class DbConfig : DbConfiguration
    {
        public DbConfig()
        {
            this.SetDatabaseInitializer<PersonContext>(new DbInitializer());
            this.AddInterceptor(new StatementLogger());
        }
    }
}

Finally, the DbContext:

namespace RealTimeLogging
{
    [DbConfigurationType(typeof(DbConfig))]
    public class PersonContext : DbContext
    {
        public DbSet<Person> People { get; set; }
    }
}

Next add an empty MVC 5 controller
new controller

Create a new view for the index action in the controller:
Add view

In RouteConfig.cs change the default controller action from “Home” to “Person”.

namespace RealTimeLogging
{
    public class RouteConfig
    {
        public static void RegisterRoutes(RouteCollection routes)
        {
            routes.IgnoreRoute("{resource}.axd/{*pathInfo}");

            routes.MapRoute(
                name: "Default",
                url: "{controller}/{action}/{id}",
                defaults: new { controller = "Person", action = "Index", id = UrlParameter.Optional }
            );
        }
    }
}

Next include the SingalR client script and a section for views to inject scripts at the bottom of _Layout.cshtml.

    <script src="~/Scripts/jquery-2.0.3.min.js"></script>
    <script src="~/Scripts/bootstrap.min.js"></script>
    <script src="~/Scripts/jquery.signalR-2.0.1.min.js"></script>
    @RenderSection("scripts",false)
</body>
</html>

At this point you should be able to run the mvc web application. You can find any missing “using” statements by right clicking classes and selecting the “Resolve” option. Once you have verified that the application can build we will create some controller actions and client side javascript which will interact with our database.

Replace the contents of Views/Person/Index.cshtml with the following:


@{
    ViewBag.Title = "Index";
}

<h2>Index</h2>
<button id="btnFirstPersonName">Name of First Person</button> <span id="FirstPersonName"></span><br /><br />
<button id="btnNumberOfPeople">Number of people</button> <span id="TotalPersons"></span>

@section scripts 
{
    <script type="text/javascript">
        $(function () {

            $('#btnFirstPersonName').click(function () {
                $.ajax({
                    url: '@Url.Action("FirstPersonName","Person")',
                    type: 'POST'
                }).done(function (data) {
                    $('#FirstPersonName').text(data);
                });
            });

            $('#btnNumberOfPeople').click(function () {
                $.ajax({
                    url: '@Url.Action("NumberOfPeople","Person")',
                    type: 'POST'
                }).done(function (data) {
                    $('#TotalPersons').text(data);
                });
           });

        });
    </script>

}

Change the PersonController class to look like the following:

    public class PersonController : Controller
    {
        PersonContext context = new PersonContext(); 
        //
        // GET: /Person/
        public ActionResult Index()
        {
            return View();
        }

        public JsonResult FirstPersonName()
        {
            var firstPerson = context.People.FirstOrDefault();
            return Json(firstPerson.FirstName + " " + firstPerson.LastName);
        }

        public JsonResult NumberOfPeople()
        {
            var numPeople = context.People.Count();
            return Json(numPeople);
        }
   }

At this point, if you run the app and press the two buttons your app should look like the following:
app working

Testing the Interceptor
Set a breakpoint inside the “SendToClient” method and click one of the buttons again. The app should stop at the breakpoint just like mine did. There will be several statements coming through here so you can keep going through to see the sort of commands Entity Framework sends to the database.

Logger debug

This concludes the first post which covered:

  • Creating a basic Asp.net MVC 5 application
  • Adding SignalR for transferring log data in real time
  • Entity Framework using Code First for our database
  • The new interceptor API for getting sql statements from Entity Framework
  • Setting up a basic page to call some controller actions which will query the database

The code used in this post can be found on Github. The next post will cover creating the dev tools extension which will display the log information.