Real-time server debug info using NodeJS, jQuery, Websockets and Logbox
Server-side debugging can be a painful process. Creating Rich Internet Applications - RIAs - ( or single-page apps by another name ) in particular can frustrate even the most experienced developers. Building a JavaScript interface that connects to a web services API often involves tedious debugging of back-end code that does not expose a UI for simple debugging techniques like dumping debug information to the screen. Browsing log files is time-consuming and tedious.
I have been working primarily on RIAs for the last several years, and after years of frustration with the lack of easy access to server-side debug information during client-side development, I have come up with a solution to the problem.
LogBox - CFML Logging Library
My particualr solution uses LogBox to capture server-side debugging information. My app uses ColdBox, so configuring LogBox is a simple matter of adding LobBox config information to /config/Coldbox.cfc.
logBox = {
// Appenders
appenders : {
coldboxTracer : { class:"coldbox.system.logging.appenders.ColdboxTracerAppender" },
webSocketAppender : { class:"model.logging.WebSocketAppender", levelMax:"INFO", levelMin:"FATAL", properties : {host:"myapplication.home",port:"8000"} }
},
// Root Logger
root : {levelMin:"FATAL", levelMax:"DEBUG", appenders:"*"},
// Granualr Categories
categories : {
"coldbox.system" : { levelMin:"FATAL", levelMax:"INFO", appenders:"*"},
"handlers" : { levelMin:"FATAL", levelMax:"INFO", appenders:"*"},
"handlers.rest" : { levelMin:"FATAL", levelMax:"INFO", appenders:"*"},
"model" : { levelMin:"FATAL", levelMax:"INFO", appenders:"*"}
};
Websockets
The first thing you will notice in this code is a custom LobBox appender, model.logging.WebSocketAppender, which is based on the built in ColdBox SocketAppender class but uses Websockets for communication.
<!-----------------------------------------------------------------------Author : Robert Munn Date : 03/15/2015 Description : A websocket appender that logs to a websocket connectionInspiration from SocketAppender by Luis Majano Inspiration from Tim Blair <tim@bla.ir> by the cflogger projectProperties: - host : the host to connect to - port : the port to connect to -----------------------------------------------------------------------> <cfcomponent extends="coldbox.system.logging.AbstractAppender" output="false" hint="A NIO websocket appender"><!--- Init ---> <cffunction name="init" access="public" returntype="WebSocketAppender" hint="Constructor" output="false" > <!--- ************************************************************* ---> <cfargument name="name" required="true" hint="The unique name for this appender."/> <cfargument name="properties" required="false" default="#structnew()#" hint="A map of configuration properties for the appender"/> <cfargument name="layout" required="false" default="" hint="The layout class to use in this appender for custom message rendering."/> <cfargument name="levelMin" required="false" default="0" hint="The default log level for this appender, by default it is 0. Optional. ex: LogBox.logLevels.WARN"/> <cfargument name="levelMax" required="false" default="4" hint="The default log level for this appender, by default it is 5. Optional. ex: LogBox.logLevels.WARN"/> <!--- ************************************************************* ---> <cfscript> // Init supertype super.init(argumentCollection=arguments);// Verify properties if( NOT propertyExists('host') ){ $throw(message="The host must be provided",type="WebSocketAppender.HostNotFound"); }if( NOT propertyExists('port') ){ $throw(message="The port must be provided",type="WebSocketAppender.PortNotFound"); }// Socket storage instance.ws = "";var paths = arraynew(1); paths[1]= expandpath("/includes/java/java_websocket.jar"); paths[2]= expandpath("/includes/java/com.bonnydoonmedia.io.jar"); var uri = createObject( "java", "java.net.URI" ).init( "ws://" & getProperty("host") & ":" & getProperty("port") ); instance.javaloader = createObject('component',"javaloader.JavaLoader").init(paths); instance.ws = instance.javaloader.create( "com.bonnydoonmedia.io.WSClient" ).init( uri );return this; </cfscript> </cffunction><!--- onRegistration ---> <cffunction name="onRegistration" output="false" access="public" returntype="void" hint="When registration occurs"> <cfset openConnection()> </cffunction><!--- onRegistration ---> <cffunction name="onUnRegistration" output="false" access="public" returntype="void" hint="When Unregistration occurs"> <cfset closeConnection()> </cffunction><!--- Log Message ---> <cffunction name="logMessage" access="public" output="true" returntype="void" hint="Write an entry into the appender."> <!--- ************************************************************* ---> <cfargument name="logEvent" type="any" required="true" hint="The logging event"/> <!--- ************************************************************* ---> <cfscript> var loge = arguments.logEvent; var entry = "";// Prepare entry to send. if( hasCustomLayout() ){ entry = getCustomLayout().format(loge); } else{ entry = "#severityToString(loge.getseverity())# #loge.getCategory()# #loge.getmessage()# ExtraInfo: #loge.getextraInfoAsString()#"; }// Send data to Socket try{ getSocket().send( entry ); } catch(Any e){ $log("ERROR","#getName()# - Error sending entry to socket #getProperties().toString()#. #e.message# #e.detail#"); }</cfscript> </cffunction><cffunction name="getSocket" access="public" returntype="any" output="false" hint="Get the socket object"> <cfreturn instance.ws> </cffunction><!------------------------------------------- PRIVATE ------------------------------------------><!--- Open a Connection ---> <cffunction name="openConnection" access="private" returntype="void" output="false" hint="Opens a socket connection"> <cfscript> try{ getSocket().connect(); } catch(Any e){ $throw(message="Error opening socket to #getProperty("host")#:#getProperty("port")#", detail=e.message & e.detail & e.stacktrace, type="WebSocketAppender.ConnectionException"); } </cfscript> </cffunction><!--- Close the socket connection ---> <cffunction name="closeConnection" access="public" returntype="void" output="no" hint="Closes the socket connection"> <cfscript> getSocket().close(); </cfscript> </cffunction> </cfcomponent>
Because I am developing this solution on the Lucee platform and I do not have the Websocket extension built in, I created a websocket client in Java from an example on GitHub:
package com.bonnydoonmedia.io;import org.java_websocket.client.WebSocketClient; import org.java_websocket.drafts.Draft_10; import org.java_websocket.handshake.ServerHandshake;import java.net.URI;/* * author: Robert Munn * date: 3/15/15 * * WSClient.java * * Simple extension of WebSocketClient by Too Tall Nate * * based on example client at * * https://github.com/TooTallNate/Java-WebSocket * * License: MIT License * */public class WSClient extends WebSocketClient{public WSClient( URI serverUri , Draft_10 draft ) { super( serverUri, draft ); }public WSClient( URI serverURI ) { super( serverURI ); }public void connect(){ super.connect(); }public void send( String message ){ super.send( message ); }@Override public void onOpen( ServerHandshake handshakedata ) { System.out.println( "opened connection" ); System.out.println( "ready state : " + super.getReadyState() ); // if you plan to refuse connection based on ip or httpfields overload: onWebsocketHandshakeReceivedAsClient }@Override public void onMessage( String message ) { System.out.println( "received: " + message ); }@Override public void onClose( int code, String reason, boolean remote ) { // The codecodes are documented in class org.java_websocket.framing.CloseFrame System.out.println( "Connection closed by " + ( remote ? "remote peer" : "us" ) ); }@Override public void onError( Exception ex ) { ex.printStackTrace(); // if the error is fatal then onClose will be called additionally } }
The other thing you might notice about the LogBox config is the URL where it is posting - myapplication.home:8000. How, you ask, is that going to get information to the client? The debug information isn't going to the client, not directly anyway.
Enter NodeJS
The debug information is going to a small NodeJS server process that acts as a chat server. This code is based on a tutorial by Martin Sikora on building a chat server with NodeJS. Why Node? It's small, lightweight, and easy to execute.
// relayserver.js // code based on tutorial by Martin Sikora // http://ahoj.io/nodejs-and-websocket-simple-chat-tutorial//based on: // http://ejohn.org/blog/ecmascript-5-strict-mode-json-and-more/ "use strict";// Optional. You will see this name in eg. 'ps' or 'top' command process.title = 'relay-server';// Port where we'll run the websocket server var webSocketsServerPort = 8000;// websocket and http servers var webSocketServer = require('websocket').server; var http = require('http');/** * Global variables */ // latest 100 messages var history = [ ]; // list of currently connected clients (users) var clients = [ ];/** * Helper function for escaping input strings */ function htmlEntities(str) { return String(str).replace(/&/g, '&').replace(/</g, '<') .replace(/>/g, '>').replace(/"/g, '"'); }/** * HTTP server */ var server = http.createServer(function(request, response) { // Not important for us. We're writing WebSocket server, not HTTP server }); server.listen(webSocketsServerPort, function() { console.log((new Date()) + " Server is listening on port " + webSocketsServerPort); });/** * WebSocket server */ var wsServer = new webSocketServer({ // WebSocket server is tied to a HTTP server. WebSocket request is just // an enhanced HTTP request. For more info http://tools.ietf.org/html/rfc6455#page-6 httpServer: server });// This callback function is called every time someone // tries to connect to the WebSocket server wsServer.on('request', function(request) { console.log((new Date()) + ' Connection from origin ' + request.origin + '.');// accept connection - you should check 'request.origin' to make sure that // client is connecting from your website // (http://en.wikipedia.org/wiki/Same_origin_policy) var connection = request.accept(null, request.origin ); // we need to know client index to remove them on 'close' event var index = clients.push(connection) - 1;console.log((new Date()) + ' Connection accepted.');// send back chat history if (history.length > 0) { connection.sendUTF(JSON.stringify( { type: 'history', data: history} )); }// user sent some message connection.on('message', function(message) { if (message.type === 'utf8') { // accept only text// we want to keep history of all sent messages var obj = { time: (new Date()).getTime(), text: htmlEntities(message.utf8Data) }; history.push(obj); history = history.slice(-100);// broadcast message to all connected clients var json = JSON.stringify({ type:'message', data: obj }); for (var i=0; i < clients.length; i++) { clients[i].sendUTF(json); }} });// user disconnected connection.on('close', function(connection) { console.log((new Date()) + " Peer " + connection.remoteAddress + " disconnected."); // remove user from the list of connected clients clients.splice(index, 1); // push back user's color to be reused by another user });});
Executing the NodeJS app is as simple as going to CLI in the directory where this file is located and typing:
$ node relayserver
Thu May 14 2015 16:06:26 GMT-0700 (PDT) Server is listening on port 8000
Thu May 14 2015 16:07:02 GMT-0700 (PDT) Connection from origin undefined.
Thu May 14 2015 16:07:02 GMT-0700 (PDT) Connection accepted.
Thu May 14 2015 16:09:52 GMT-0700 (PDT) Connection from origin http://myapplication.home.
Thu May 14 2015 16:09:52 GMT-0700 (PDT) Connection accepted.
myapplication.home has a host entry on my machine pointing to 127.0.0.1. The application itself and the NodeHS relay server are both running on localhost, just on different ports. Once I have my client code running and I open the app, I get the connection information shown above. And that's another piece of the puzzle - the debug client in my JavaScript application that will show the logging information in real time.
/* * Based on NodeJS simple chat tutorial * http://ahoj.io/nodejs-and-websocket-simple-chat-tutorial * */( function( $ ) { "use strict";// for better performance - to avoid searching in DOM var title = "Debug Window", width = "50%", position = '{ my: "right top", at: "right top", of: "window" }';//flag to notify the system to start debugging application.debug = { active: true};window.WebSocket = window.WebSocket || window.MozWebSocket;// if browser doesn't support WebSocket, just show some notification and exit if (!window.WebSocket) { $('#debugDiv').html($('<p>', { text: 'Sorry, but your browser doesn\'t ' + 'support WebSockets.'} )); return; }// open connection var connection = new WebSocket('ws://myapplication.home:8000');connection.onopen = function () { console.log( "Opened debug session..." ); $('#debugDiv').html( "Opened debug session..."); };connection.onerror = function (error) { // just in there were some problems with conenction... $('#debugDiv').html($('<p>', { text: 'Sorry, but there\'s some problem with your ' + 'connection or the server is down.' } )); };// most important part - incoming messages connection.onmessage = function (message) { // try to parse JSON message. Because we know that the server always returns // JSON this should work without any problem but we should make sure that // the massage is not chunked or otherwise damaged. try { var json = JSON.parse(message.data); } catch (e) { console.log('This doesn\'t look like a valid JSON: ', message.data); return; }if (json.type === 'history') { // entire message history // insert every single message to the chat window for (var i=0; i < json.data.length; i++) { addMessage(json.data[i].text, new Date(json.data[i].time)); } } else if (json.type === 'message') { // it's a single message console.log("message received"); addMessage( json.data.text, new Date(json.data.time)); } else { console.log('Hmm..., I\'ve never seen JSON like this: ', json); } };$( window ) .on("close", function(){ connection.close(); });var addMessage = function(message, dt) { $('#debugDiv').prepend('<div>' + + (dt.getHours() < 10 ? '0' + dt.getHours() : dt.getHours()) + ':' + (dt.getMinutes() < 10 ? '0' + dt.getMinutes() : dt.getMinutes()) + ': ' + message + '</div>'); };}( jQuery ) );
This code supplies a websocket client that subscribes to the chat server and posts any messages it receives from the chat server into a floating window inside my application. From there, all I need to do to get live debug information from my application is add LogBox logging commands to my app. To start, I will add a log.info() command to the preHandler function in my /handlers/rest event handler CFCs which act as the endpoints for the REST API for my application.
function preHandler(event,rc,prc,action){ // default REST response to JSON event.paramValue("format", "json"); log.info( ", Event : #event.getCurrentRoute()#, Method: #event.getHTTPMethod()#, personId : #request.user.personId#" );// Verify supporter formats, else advice if( NOT reFindnocase("^(xml|json)$", rc.format) ){ rc.invalidFormat = rc.format; rc.format = "json"; event.overrideEvent("rest.contacts.invalidFormat"); }// create response data packet prc.response = { error = false, messages = "", data = "" }; }
Now, whenever my application calls any of the endpoint methods in that CFC, LogBox will log a message to the chat server via Websockets, and my client code wll pick up the broadcast of the message and display it in the floating window in my client application.
From this point, I can add LogBox logging calls anywhere in my application and I will get that logging information on my client in real time. This is especially useful for debugging background processes like scheduled tasks that can be difficult to monitor in real time.
Do you like this solution? Would you like to use it for group-based development? Contact us for a free consultation.