.NET Logging with log4mongo-net

mongodbIntroduction

In this post we will describe how to use MongoDB as a log store from your .NET application with very little work or code. We are going to be using log4mongo, a log4net appender to MongoDB. The sample application that we create in this post is available on GitHub.

Motivation

MongoDB is well suited for logging and can be preferred over logging to text files or to a relational database due to some of the following reasons:

  1. Simple asynchronous inserts a.k.a fire-and-forget.
  2. Use of MongoDB capped collections means old logs don’t need to be deleted manually. Logs can quickly fill up disk.
  3. Log schema doesn’t have to be defined, new information can be added adhoc.
  4. Off-site access easier than files.
  5. Query logs using MapReduce or Aggregation Framework.
  6. Logging to your relational database, assuming you are using one, increases load and disk space usage.
  7. If some logs are written in transactions and these transactions rolled back, you lose the logs.

Let’s get started.

First we need to install and run a MongoDB instance, if you are familiar with how to do this, continue to the next step, Preparing our .NET Application, where we install log4mongo-net with NuGet.

Setting up MongoDB

Download MongoDB for your platform. If you are on windows, the installer will install MongoDB to C:\Program Files\MongoDB 2.6 Standard\bin by default assuming you are using the 64 bit version and have installed version 2.6. If you are installing it on another platform, please consult the MongoDB docs.

Once you are installed, open up a command prompt and cd to your MongoDB install path. The MongoDB server is called mongod. If you run mongod without any arguments you will probably receive a message saying that you need to define the dbpath

If you receive a Windows Security Alert go ahead and Allow access.

If you see “waiting for connections on port 27017” you are good to go. You have an empty MongoDB server up and running, let’s fire up Visual Studio.

visual_studio_2012Preparing our .NET application

Create a new Visual Studio application or open an existing solution you wish to add logging to. We need to install log4mongo and its dependencies; log4net and mongocsharpdriver. log4net is a popular logging framework for .NET and mongocsharpdriver is the C# driver we need to talk to MongoDB.

There are a number of ways to use your logger from your application such as injecting a shared instance using your favourite IoC Container, use a Singleton logger, a static logger, a base class logger. My preferred method is to inject a shared instance via constructor injection and an IoC Container. We will not describe how to do this in this post as we are focusing on log4mongo. You can find more information on logging and the various ways to do it in this StackOverflow question.

Configuration

We are going to setup the log4net configuration file as well as log4mongo’s configuration file. If you are not familiar with log4net, see this CodeProject article. In a nutshell, log4net needs 3 things before it can work; a configuration file, a call to its static factory LogManager.GetLogger() method and a call to XmlConfigurator.Configure().

The log4net configuration is to be included in your app.config or web.config file. We are going to put the log4net appender in its separate configuration file, you don’t have to do this but I think it’s cleaner as app.config and web.config files can grow large and harder to read the more you add.

You need to add two lines to your configuration file:

The first line tells the configuration file that we are creating a log4net section called “log4net” and the second line is the log4net section itself. This line just refers to our other log4mongo appender configuration file (that we will create next). If you don’t wish to create a separate log4mongo configuration file, the contents would go here instead.

Now create a new application configuration file in the root of your Visual Studio project and replace with:

Here we have a log4net appender named “MongoDBAppender”. You can name it whatever you like but remember to reference it in the root appender-ref element. We define a connection string that points to the mongod instance we started. If you started mongod with the default port you can use mongodb://localhost. Next, the name of the collection that is going to hold our logs. The field elements define what properties each log document will contain, here we have the timestamp, the log level, the thread, the logger and the message. You can create your own custom fields, see the log4mongo-net GitHub documentation for more information. Finally, the root element where we define our log level and reference our MongoDBAppender.

If Visual Studio 2013 tells you that “The ‘log4net’ element is not declared.”, just ignore it. It’s defined in our configuration file that references this one!

That’s it for configuration files. Just make sure your application can find them at run time. If you moved them, take the necessary steps to tell log4net where to find them.

Code

We need to create our logger. You can choose to wrap the log4net logger in your own logger interface or not. The log4net ILog interface is a facade to it’s own implementation so it’s a nice interface to use, however you might want to wrap it so you can stub it or mock it in tests or even replace log4net with another logger in the future. I like to be able to able to inject fake implementations of my dependencies so I will wrap it even though we have to write a bit more code and can potentially loose some of log4net’s features if we do not expose them in our wrapper. I chose the following simple wrapper that exposes each log level with an overload that takes in an Exception.

Let’s implement our ILog wrapper:

We have an instance of log4net’s ILog and we are setting it using log4net’s static factory method, LogManager.GetLogger(). We are passing in the type of the class that is calling the logger as a string. This string can be set by your IoC Container.

That’s it for setup. Let’s instantiate our logger and log a message. I am logging in an ASP.NET MVC application so I am injecting an instance of my logger wrapper into my HomeController constructor:

I am calling our Info() log method three times, once in my index action, again in my about action and again in my contact action. If you are logging in a Console application, a WPF or Win Forms app just make sure you get an instance of ILogger and call some log methods on it.

Putting it all together

Let’s see if we are able to log to our mongod instance. Make sure your mongod instance is still running, if it’s not start it up again using the mongod –dbpath C:\data command. Start a mongo shell, this is the binary that’s simply named mongo. By default this will connect to your mongod running on the default port. If you did not start your mongod on the default port you need to run mongo –port 27017 to specify the port.

When our Visual Studio application launches and logs our info message it will try to find a database called log4net as we defined in the MongoDBAppender. If that database does not exist it will create it. We don’t have to worry about creating it manually. Inside the log4net database will be a collection called logs.

Run your application and go to your mongo shell. You can use the command show databases from the mongo shell. With a bit of luck you will see a database listed as log4net. Next, type use log4net. This switches the mongo shell to that database. Type show collections, you should see a collections called logs. Finally type:

The mongo shell will show you the message that your application logged. Notice that the documents are in the same form as we defined in our log4mongo configuration file; timestamp, level, thread, logger and message.

In the mongo shell query, db is the database we have set (in our case the log4net database), logs is the collection in that database that we want to query, find() gets all the documents in the collection and pretty() formats the Json in the shell so it is easier to read.

Finally, we should make our logs collection a MongoDB capped collection. A capped collection is a fixed size collection that when full makes room at the start of the collection for new inserts. This is ideal for logging as we don’t have to manually remember to delete old logs. Given that we already let our application create our non-capped collection, we need to change it to be capped:

To check that the collection is capped, run db.logs.isCapped() from the mongo shell.

If you are not seeing a log4net database go back and double check that your log4net and log4mongo configuration files are correct, that you are calling XmlConfigurator.Configure() in your wrapper and that your MongoDb connection string is correct. The default should be mongodb://localhost.

FInal Thoughts

That’s it! You have a simple and easy way to log from your application. The calls to the log methods are asynchronous on mongo’s end, we don’t need to wait for a response. Once mongod receives our log document our application can continue without blocking. If you are using C# 5 you could make the calls to log4net asynchronous at the application level, I will leave that as an exercise for the reader.

If you would like to learn more about MongoDB I suggest you head on over to MongoDB University. MongoDB University offers free online Developer and DBA classes and certificates. I would also like to recommend Kristina Chodorow’s book MongoDB: The Definitive Guide.

If you liked this article, please follow me on twitter. @sammleach

What to install on a new dev machine

While I am waiting for Visual Studio to install I will document what other tools I have installed on a new dev laptop. In no particular order:

  • FoxitReader
  • FileZilla
  • Putty
  • WinMerge
  • Wireshark
  • Evernote
  • Vlc
  • OzCode
  • uTorrent
  • Code Digger
  • StyleCop
  • ImgBurn
  • CodeMaid
  • ProPowerTools
  • WinDirStat
  • dotPeek
  • Fiddler4
  • Web Essentials
  • GitHub for Windows
  • LINQPad
  • Google Drive
  • DropBox
  • 7z
  • Paint.NET
  • TeraCopy
  • AgentRansack
  • Sublime Text 2
  • Visual Studio 2013 Ultimate
  • Instapaper Chrome extension
  • AdBlock
  • AngularJS Batarang
  • Feedly
  • Knockoutjs context debugger

I will add to this list as I install things.

Scott Hanselman’s Ultimate Developer Tools list and Calum Tomeny’s Developer Resources are a good resource.

Natural Language ambiguity

As developers we take ideas expressed in natural language and translate them into concrete programs.

Confusion over the stackoverflow gold electorate badge highlights the difference between natural language and programming language and the challenges developers face on a daily basis.

electorate_badge

The definition of the stackoverflow electorate badge is

Voted on 600 questions and 25% or more of total votes are on questions.

Reading this, one determines that

a) A user has to vote on 600 questions.
b) A user’s total number of votes needs to be composed of between 25% and 100% of votes on questions.

meta.stackoverflow.com shows the interpretations of the badge definition. Let’s look at the following three posts.

1. Where is my electorate badge?

I have cast 606 votes in which 227 are on question and else are on answers

Awais Qarni interpreted the word question to represent the complete stackoverflow post or thread. This interpretation is correct, threads on stackoverflow are questions. However the use of the word question in the badge description refers to only the question part of a stackoverflow thread (not the answers or comments). Awais was expecting to receive his gold badge because he had voted on 606 threads, 227 of which question posts.

2. Electorate Badge rules. Rich Seller did not understand b). In the comments, he states that he finds the wording unclear.

From your answer it seems the badge is awarded if you’ve voted for questions 3x as much as you’ve answered them? But I initially read it as “answer/question ratio”, and on rereading as “ratio of answer votes to question votes”.

He still is not understanding b).

3. Electorate badge, is it working, the badge definition is interpreted again.

Clarify electorate badge wording changed the wording of the badge description in an attempt of clarify it’s meaning. As we saw with Awais Qarni, it is still open to interpretation.

Natural language is not able to concretely communicate meaning. We interpret it, this is why literature and the arts can be so stimulating to our brains.

From a 14 word sentence, expressing a simple rule, we’ve seen how it can be interpreted. Now, take your average software project specification. It will likely contain more than 14 words in 1 sentence. Usually hundreds of sentences. As developers we need to continuously ask questions about the software we are writing because given more than one developer there will be parts of the specification that are interpreted differently.

One could write the following program to communicate the 14 word sentence explicitly.

The program communicates the definition of the electorate badge. Nothing is left open to interpretation. We run the program to prove that the definition it communicates is correct. This is impossible with natural language, our brains interpret the sentence and reach some decision about its meaning. The notion of question is impossible to define concretely as it can be correctly interpreted as both the full stackoverflow post or the question part of the stackoverflow post.

When writing, discussing and thinking about software requirements and specifications its imperative that we ask ourselves lots of questions. If we don’t have answers to one of our questions, we take care in defining the ideas that are open to interpretation. In a nutshell, be completely explicit. If an idea is not defined, define it.

Further reading:

Using Natural Language in Software Development

meta.stackoverflow.com

Visual Studio keyboard shortcut to collapse and expand code

Sometimes in Visual Studio you need to collapse all code to give your mind a quick clean and refresh, at least I feel it helps.

The Visual Studio keyboard shortcut to do this is as follows:

Ctrl + M + O for collapse

Ctrl + M + L for expand.

StackOverflow has a very popular question and answer with the shortcuts which leads me to believe that I cannot be alone in my need to occasionally collapse all to preserve my sanity.

Testing on the Toilet – Google Testing Blog

Google employees maintain a blog about testing.

They have a series titled ‘Testing on the Toilet’. Each short article teaches something short about testing. They are short enough to be read while on the toilet, hence the title of the series. Apparently, at Google, they print them out and leave them in toilets so their employees have something to read.

The explanation or introduction of Testing on the Toilet.

Although I don’t plan on reading them while on the toilet they are really short and informative to read every now and again, or one each day, for example.

I suggest every developer should read some.

If for example, you are still not sure what the difference between mocks, stubs, fakes, dummies, test doubles and test spies are, the answers are all in ‘Testing on the Toilet’.

AnkhSVN – Subversion Support for Visual Studio

Introduction

In this post I will explain how to install and setup AnkhSVN, subversion support for Visual Studio.

Steps

Download AnkhSVN

Run the installer to install AnkhSVN.

Before you can interact with Subversion directly and comfortably through Visual Studio, you must tell Visual Studio to use AnkhSVN.

To do this, go to:

Tools > Options > Source Control

and select ‘AnkhSVN – Subversion Support for Visual Studio’.

ankhSvn_1

The following Visual Studio window is now visible:

ankhSvn_2

allowing one to see non-commited changes, commit changes, update to receive the most recent changes, etc.

Benefits

Having Subversion integrated into Visual Studio is a productivity boost as opposed to using TortoiseSVN from windows explorer:

ankhSvn_3

NuGet 2.7 Release Candidate

NuGet is a package manager for .NET. It provides an easy way to download and include packages directly from Visual Studio. You can create your own NuGet repository containing any package you may have developed.

Before version 2.7 integrating NuGet with source control was not seamless, you had to jump through some hoops. Namely, you had to enable ‘NuGet Package Restore’ by right-clicking your solution. So when you checked out and built NuGet would automatically download any missing dependencies.

nuget 2.7

If you google ‘nuget auto restore not working’ you will see that many people have trouble setting this up properly. In summary, it takes up valuable time.

NuGet 2.7 enables Package Restore by Default which is great. No more remembering to manually enable it on your Visual Studio solution. This change is very welcome.

vs2013_0

Visual Studio 2013 Preview

Visual Studio 2012 was released Q4 of last year and already we have a replacement; Visual Studio 2013.

Download and Installation

Download

On the page, select ‘Visual Studio Ultimate 2013 Preview’ ‘Install Now’. You download a small 1MB file which downloads and installs the whole IDE. I installed it in a VM of Windows 8.1. It took a while, around 30 minutes.

vs2013_0

When installation is complete you are required to sign into your Microsoft account (or ‘Visual Studio’ account), apparently Visual Studio syncs with other devices (awesome)!

vs2013_1

Next, you choose the theme. I like the new grey Visual Studio 2012 theme but if you prefer you can choose the old Visual Studio 2010 blue theme.

Choose your development environment (C# for me) and click start. The welcome screen looks very familiar:

vs2013_2

There is an update to install as soon as you install the ide.

Reference couting

Let’s start a new Console app. The first change you notice is the reference counting. Each class and method has a little indicator above it telling you how many times it is being referenced.

vs2013_3

When you hover over the reference indicator it shows you where it is being referenced. In the following screenshot, it’s the constructor.

vs2013_4

I now reference the Play class from my main method:

vs2013_5

It’s kinda cool. You can now see, at a glance, which of your classes are heavily referenced and which are not. One could use this tool to focus your unit testing efforts on classes that are relatively heavily referenced.

Return Values Debugging

Return values in the Visual Studio debugger. The Autos window displays return types and values for methods.

(You must start the debugger and hit a breakpoint to be able to see the Auto window.)

vs2013_6

I honestly don’t use the auto window, I probably should. I didn’t know Visual Studio 2012 lacked this feature but it’s nice to now have it. My auto window is now open and I’ll use it when I am debugging.

Edit and Continue for 64-bit apps

Have you ever received the ‘Changed cannot be made to 64-bit applications’ message? I know I have. Apparently Visual Studio 2013 supports this.

Async debugging

Peak Definition and Scrollbar enhancements

I love these two features of Productivity Power Tools. It’s now in Visual Studio natively.

See what else is new or different in Visual Studio 2013

See what else is new in .NET 4.5.1