Jan Heggernes

. . . systematic randomness . . .

Mijan.Core - Service Overview

One of the more "common" tasks in computing in general is to have some sort of service running in the background doing all kinds of different things, and as a developer, I feel it's quite nice to just have a very basic framework I can plug into whenever I need something run as a service.

In Mijan.Core I have a Service namespace which contains the basics for your own windows service, complete with installer and the potential to debug as well. This is a very simplistic concept which enables people to make complex services and just quickly plug it into a windows service.

I've defined IService as the base interface for any service, a service needs to be able to start, stop and have a name for identification purposes. The Start method also takes an IServiceHandler as a parameter, if the service for some reason needs to interact with other services running in the same application, in general this parameter can be ignored though.

For the basic executable service, all you have to do is create a console application (not a service!) and have the following in the main entry point.


You can also add another optional parameter after args to specify the name of the service as it would appear in services, otherwise it'll default to MijanService.

I've made a basic TimerService implementation that resides in Mijan.Core.Service, this performs a given task every X minutes during a specified time interval, or simply every X minutes all the time. For a very simple implementation of this, look at the following.


This is essentially all that's needed for a service to execute something every minute, in this instance TimerTick() will write the current time to the Console.

For the service to pick up on this, however, it needs to be plugged in to the app.configuration file. MijanService needs its own little configurationSection, and that's handled as such.


The HelloService line is the timer just implemented above, with its name and namespace as well as the assembly where it's located. The second example is how to specify custom values in the configuration xml. In this case I've added a few properties in another service, and need to add a separate class for the XmlConfiguration, as well as a Service to handle this. As long as I have a service constructor with an XmlElement as its parameter, it will pass its service element into the constructor to handle. For this example, the classes look like

It's important to note the [XmlRoot("service")] attribute, as that's the XmlElement being passed into the constructor.

The service executable takes 3 different parameters when you launch it, either install, uninstall or debug. If you use install, it will be added to the computer's list of services, and will function as any other service in terms of start/stop/recovery. Uninstall obviously uninstalls it, while debug will launch the service in the console window, so you can essentially have it running in a controlled environment before throwing it into fully automated service-mode.

The result and output from running this service in debug mode will be ...


Both services specified in the configuration get to run in their own threads and have their fun!

Mijan.Core.DataLayer - Quick Cache Samples

One of the things I've done quite frequently over the years to improve performance against databases is to cache items which I consider relatively static. When I was writing the DataLayer wrapper I wanted to incorporate this in a very quick and easy way to ensure people could actually use this without the amount of hassle normally involved in setting up caching.

With Entity Framework, you'll often use the lazy-loading without thinking that you're actually lazy-loading any items due to the easy relations defined by the generated classes, or the code-first classes, I wanted an easy way to sort out easy caching options for these as well, but the problem here is that the model shouldn't really have access to data-retrieval options in a standard tiered setup, so I've added some reflecting magic that gets the job done.

The Quick Cache classes, (Qc and Qsc, for Quick-Cache and Quick-Single-Cache respectively) are accessible in the Mijan.Core.DataLayer. What they do is look up an implementation of IDbCache and uses this implementation to access the database - if you've already defined a DalCache class like mentioned in the previous post, it's already done! You can start using Qc and Qsc as much as you want for all your caching needs!

A practical example of this would be in a blog-model, where you rarely add authors, or any model with enum/type foreign keys, consider the following Code-First example in a Blog entity class.


Here you can simply use blog.AuthorCached to access a cached variant, where the blog.Author would actually load the row from the database.

What happens behind the scenes here is that the Quick Cache will load the entire Author table, and maintain it in-memory. The Qc class will return the List of those objects, while the Qsc will return a single entry there through a Dictionary approach, making it a lot more efficient for single-entry lookups. A note here is that Qsc will not work unless there's a single Primary Key on the table, due to the need for the initial reflection and dictionary approach becoming excessively complex with composite keys and potentially needing tuples to maintain key values. Simply use Qc instead for these scenarios.

Example of how to use Qc as follows, in this case, we want to cache all the posts for a given blog, as accessed through the code-first entity.


It's important to note that by default everything grabbed through this approach will be detached from its context, if you for some reason need the context attached, there is a GetWithContext for that as well, but I'd strongly recommend that you really know what you're doing in that case, and that you know how to handle potential errors coming from objects attached to "different contexts".

If you need to refresh data for whatever reason, Qc.Clear<T>(); and Qsc.Clear<T>(); will do the trick. Also, due to the nature of reflection and potential errors, there will be an exception thrown if you try to use this and there's anything but *one* instance of IDbcContext defined.

Mijan.Core.DataLayer NuGet Package - Overview

I've worked on a fair few projects lately, and I always use my own little custom wrapper of the Entity Framework for these projects. It abstracts the storage of the context away by defaulting to have it as a per-httpcontext storage, or a per-thread storage in case of non-web projects.

Other people have expressed interest in using the same approach, and as I'm constantly refining and upgrading what I'm using I've decided to take the step and actually create a NuGet package for this little tool.

This is the initial overview of the DataLayer package, and how to quickly get started using it.

The DataLayer package is named Mijan.Core.DataLayer, and can be installed through the NuGet Package Manager, or console by doing Install-Package Mijan.Core.DataLayer

There's technically support for both the legacy ObjectContext and the new DbContext, but I'm primarily focusing on developing the DbContext part as that's the "surviving" way forward.

Quickstart on how to get up and running with this wrapper is to go about creating your DbContext either through Code First or Db/Model first, then wrap the generated context with your own class-name as an example here.


There are other variants which offer non-static options, but this is the quickest and easiest way to manage your data. Once this is done, you can easily retrieve and manipulate data through the Dal classes you've "created".


In addition to this, the DalCache provides built-in MemoryCache wrapping.


This is just a very quick introduction to what the primary features are in the DataLayer NuGet package. Feel free to comment, I'll most likely add some more information about this package and the Mijan.Core package soon.

Common Entity Framework Errors and Performance Tips

I wanted to write a quick entry about Entity Framework and just point out some of the errors I’ve been asked to resolve, and some of the worst uses of EF I’ve seen performance-wise. All of these are done with the default EF4.0 settings and default entities with foreign keys exposed.

 

I should note that there are probably a ton of errors more frequent than these in the world, but this is based on my personal experience supervising and helping others use Entity Framework. If you have an error which keeps happening with your EF-application, add it to the comments below and I’ll try to write something about it in a future post.

 

Entity Framework Errors

System.InvalidOperationException: The relationship between the two objects cannot be defined because they are attached to different ObjectContext objects.

This error appears when you use entity objects from different contexts when specifying relations and attempt to persist the changes to the database, seeing how the state of the two objects are maintained by two different context instances, they can’t really know the exact state of the other object, and as such, refuse to go along with it. Typically this happens in real situations when you cache an entity or simply have a project which is designed to use more than one ObjectContext.

 

The best way to resolve this is to be consistent in terms of assigning related entities. For the most part I would recommend exposing the foreign key column and setting the id of the related entity directly rather than specifying the entire entity. When this isn’t an option, you either have to refresh the entity in the same context as the entity you want to add relations to, or explicitly detach the entity from its old context and attach it to the new one. The latter of these could be dangerous if it’s also referenced by its old context, so make sure you know what you’re doing if you go with that approach.

 

System.ObjectDisposedException: The ObjectContext instance has been disposed and can no longer be used for operations that require a connection.

This appears most often when you try to lazy-load entities related to an ObjectContext instance which has been disposed one way or another. I’ve seen quite a few instances of code which is similar to this approach:

 

 

which will subsequently die horribly due to the disposed context as a result of the using block. The typical real case scenario here is that you have a function which will return a list of products, then that list will be databound to a listview in a web application, and ProductModel.Name is evaluated there, resulting in much anger directed towards Entity Framework in general and a lot of creative workarounds as the deadline approaches.

 

To resolve this peacefully, a few different approaches should be considered. First off, if you maintain your ObjectContext in a way which lets the garbage collection deal with the entities, you shouldn’t have this problem at all unless you explicitly detach objects, resulting in you getting a nullreference exception instead of this exception.

 

If you explicitly dispose the context like it’s done here, you should always ensure that you have all the information you need by the time the context is disposed. If you work with more complex relations, you might want to consider creating some wrapper classes and populate them with all information needed, or simply specify include hints in the retrieval of the original object.

 

Entity Framework Common Performance Tips

First off, I would like to just mention that you really should run SQL Profiler or something to that extent while developing your EF-applications, especially if you’re new at this and not entirely sure what happens behind the scenes when you design your elegant LINQ queries. The ease of developing using Entity Framework as your data-layer comes with a certain responsibility to at least try to make efficient code. I also know some DBA types who really want to avoid the use of any O/RM due to the SQL it generates, so please think of the overall reputation of EF and try to keep things optimized. Again, these issues and suggestions I post here are based on my personal experiences with Entity Framework and optimizing actual code.

 

Do not ToList() before filtered iteration

Even though this one is a simple one, I’ve seen it slip through quite a few times. The standard way of messing up this way is to specify a query, add .ToList() to perform the query, and then filter it as we’d only want to see the first 500 entries regardless. When you’re developing on your own PC with a local SQL-server, you don’t really notice anything unless you’re profiling at the same time. In reality, you’re retrieving the entire table before you’re applying the filter, resulting in a lot more data transferred than what’s needed. Simply put, make sure you filter/select before you .ToList() a collection for re-use.

 

Related collections are *not* IQueryables

Something which is easy to forget, even if you laughed at the above point, is that the related collections when you have a one to many relationship are not IQueryables, but DataCollections. As a result of this, if you have a customer object and want to display his order number 123, doing customer.Order.Where(o=>o.OrderId == 123) is the same as retrieving all the orders for that customer from the database, then looking through the collection to find the right one. Rewrite this to retrieve the order based on both customerId and orderId to ensure you don’t end up with a lot more data than you need.

 

Be *very* careful when putting entities in ViewState

Avoid this as best you can, if you have to maintain objects in this fashion, try to make wrapper classes. Having the full entities in viewstate tend to be fairly huge compared to the relevant information that you want to keep track of, not to mention that if you have relations included, this will grow even bigger.

 

Avoid instantiating unnecessary ObjectContext-instances.

This is more of a CPU-performance issue, as the cost of creating the context is fairly high, so try to limit these and re-use a context as best you can, please do not put these things inside loops or loop-like scenarios such as partial class properties.

 

Includes

As EF4 rolled in and people could lazy-load without worrying about what was actually in the current context, it seemed to have the added effect of making developers a bit more lazy as well. The typical scenario where you really notice the improvement of a well placed include or two comes when you load up a decent set of data and databind it in an application, evaluating left and right across relations in the database, and EF simply serves up the data without any question at all.

 

It’s also very hard to give specific and definitive suggestions regarding when to use includes and when not to, as every situation tends to be different. Also, you need to consider whether or not this is for general use, or if it’s very specific for your one little area of code.

 

 

Here’s an example of 3 different ways to do the same thing, only difference is the amount of data being transferred and the amount of queries/stress being put on the SQL Server. For this example I want a report of 1000 sales from the AdventureWorks database, and I simulate requiring information from two related tables similar to how I’d do it with a report displayed nicely in a listview.

 

Now, the first method is slightly hard on my database with the amount of queries it’s performing, while the second one is the kindest, as it only requests the exact data it needs and returns it in an anonymous class, and the last one returns the same as the first one, only it does it in one query behind the scenes.

 

The obvious downside of the second option is that it’s an anonymous class and not very flexible. Creating a wrapper class to contain the specific information is okay to transfer it to other tiers of the application, but going down this road will most likely result in an insane amount of wrapperclasses for a ton of different data-subsets.

 

The third option provides the best option for flexibility when you need a lot of different data from all of these tables, but if you then re-use that method elsewhere and only want the specific information in the sales table, you’re all of a sudden getting a lot of extra information you’re not going to use.

 

So, as I’m unable to give one definitive answer here in terms of what to do, I can’t put enough emphasis on the importance of profiling your application while you’re developing. Go through the different database calls being done by your application on each page, and make sure each of them can be justified. You should also note that if you specify multiple includes, you really should ensure that it looks sane enough in a profiler and has a decent execution plan. Also, if you’re retrieving insane amounts of data, you really should avoid includes due to the sheer amount of data it will generate. If you’re loading a lot of metadata for caching, you should have a look at how the lazy loading works in this post, and keep messing around with SQL profiler to get the quickest loading time possible.

 

An additional note here on includes. I’ve seen a few of the generic data-layer/extensions which works with EF, but I haven’t seen one which enables you to specify include paths – as that’s not something that fits very well with the generic pattern in general, but something which must be done directly on the ObjectContext-table. Keep this in mind when you decide on such patterns and practices.

Entity Framework, Context and Lazy-Loading

I wanted to write up a short little entry about how the ObjectContext and Lazy-Loading works in situations where you typically lazy-load entities. In particular this is important to keep in mind when you maintain the context for longer period of times, or cache the context/entities in one way or another.

 

First off, the EF object context maintains the information about the entities it has loaded as long as the tracking option is enabled – by default this is enabled for EF4 with standard settings. Now, the only time these entities are accessed from the context rather than querying the database directly is when they are referred to from another related entity.

 

As an example of this, we can do (using the AdventureWorks DB)

 

This will result in 3 database queries as noted in the comments. It’s important to note that even though we already have the product with ID 680 stored in the context as a result of the first query, it still performs an additional query to retrieve the same object, as opposed to the lazy loaded entity which EF will be content to retrieve from the context once it’s in there.

 

This holds true regardless of where the information has been loaded from. Take the following example

 

Here we simply select all the ProductModel entites up front, which results in them being added to the object context even if they’re not “used” for anything.

 

This is all good when lazy-loading relatively static data. However, if the entities being lazy-loaded are changed through another context or in the database directly, this will potentially result in out-of-date data being used. In this case, if someone were to change the ProductModel relevant for our product, it wouldn’t refresh in our application as long as the object context lived, even if you “refresh” the main product. This can result in some unpredictable results and weird errors if you’re not aware of how it works.

 

If you find yourself in a scenario where you maintain the object context for a longer period of time, and think this could be a problem, there are a few ways to work around this. One way is to explicitly include the related entities in the query, another is to turn off entity tracking for the related objects altogether and you can also explicitly refresh the data if you’re using something similar to the .ToList() approach in the second picture.

 

 

This adds a bit of complexity to the SQL generated, as you tell EF to add a join clause to it, but will ensure that the ProductModule entity will be retrieved fresh from the database. If you have performance in mind for static and cached data, the option of simply loading all the relevant tables with .ToList() should be added as a contender if your includes are getting too complex.

 

 

Finally, the example of how the MergeOption can be used to ensure that we don’t get old data. It’s important to note that the option here is set on a table level, and it’s the table doing the queries which needs to have it set. If we set it on the ProductModel table, the Product table will still track its related ProductModel entities.

 

To summarize, make sure you know how the lazy loading works when you’re using it! Especially when using it in non-disposed contexts. If you rely on lazy-loading in such a context, make sure that you know that only explicit calls to the database will be fresh by default.

C# Coding Conventions

I’ve actually had a few people who are just getting into “the business” of programming ask me for advice recently, and after looking through some code samples, I really think that people who are just starting are underestimating the level of importance we place on correct casing and naming.

 

Sure, the code might still work, but for others who have grown accustomed to the “right” way of defining things in the C# world, it just feels wrong, and there’s really no reason to not use accepted conventions from day #1.

 

I found one of my old links related to coding standards, it’s definitely worth a look for any C# developer. I was looking through it earlier before passing it on, and I have to admit to completely forgetting about the string compare issue listed in point 4.32! :)

 

http://weblogs.asp.net/lhunt/pages/CSharp-Coding-Standards-document.aspx

Entity Framework with Caching and ViewState

I’ve been doing quite a few projects now using Entity Framework with .NET 4.0 and wanted to post a few hints and tips based on my experiences dealing with entities and caching.

 

First off I’d like to mention that my experience with Entity Framework has been very positive in general. I’ve been using it since its .NET 3.5 version both for commercial and private projects and found it to be very useful and easy to use. I also intend to keep using it as my DAL for future projects.

 

As far as performance goes, and to prevent relatively static data from being retrieved from the database, it’s usually preferred to cache or somehow temporarily store the data to minimize the load on the database as much as possible. For Entity Framework this usually means storing the individual entities or a collection of them.

 

A very quick and  simple generic way to cache results in the memory here is used regardless of entities could be as follows, using the System.Runtime.Caching implemented in .NET 4.0. (Previously found in System.Web)

 

 

This will simply store the results from GetStuffFromDatabase for 24 hours in a sane matter, the double cache check with lock is to prevent multiple simultaneous requests from accessing the database at the same time.

 

The important thing to note here when using this with the regular entities from Entity Framework – is that by default, this will include the DataContext which the objects are attached to. Meaning that, for instance, the entities will be able to access linked related objects through this specific context – which also means it will perform additional queries against the database later as long as you don’t explicitly dispose of the specific context.

 

It’s also important to note that if you intend to use the cached objects as references for other entities later on, you will most likely use a separate context and can’t use the objects directly. The simplest workaround for this is either to use exposed foreign key ids on the entities, or re-load the entity in the other context. An example to demonstrate this using the GetStuff method above is as follows, assuming that the AddAndSave will add the object to a fresh context and the GetStuff data has already been cached. Also, if you don’t expose foreign key id columns (4.0 feature), you won’t be able to do this, but need to reload the object instead.

 

When it comes to ViewState in ASP.NET applications, you want to be very careful when it comes to storing entities there. As with entities cached in memory, the ones you store in viewstate will also include the context, which might seem fine when you’re doing simple testing. However, a worse scenario could be if you for some reason retrieve 1000 entities and decide that you want to store one of them in the viewstate for a given page, the entire context will still be included, so the actual size will end up being that of all 1000 entities in the context.

 

There are a few relatively simple workarounds to this, the quickest one is to detach the entity from the context before you put it into the viewstate, meaning that only the actual entity will be stored there. It should be noted that you wouldn’t be able to access any foreign key related entity properties once you decided to do this unless you explicitly re-attach it to a context – which typically is not something you want to explicitly keep track of in an ASP.NET application.

 

The other, and slightly smarter way, includes creating a custom simple wrapper class including only the properties you deem relevant for the page being presented. This will effectively minimize the size of the viewstate and provide a much more defined way of saying to developers that it’s *not* an actual entity which can use its relations to access more data like a detached entity might say – but an object which already should have the data needed for the specific page. For anyone using entities and really wanting to optimize the page presented to the user and still need to use viewstate, this is the way to go. It’s really as lightweight as possible, and you weed out any extra properties and general overhead that you would still have in a POCO-entity/detached state. For more static data, you could combine this with the memory cache to store wrapped entities for the best performance.

 

In short, I’m quite happy with Entity Framework! It’s all incorporated nicely into the core of the .NET framework now, and it has in my opinion improved quite a bit in its 4.0 version. Getting it set up and working with the performance improvements you get from cached entities is also very simple and effective once you see the pitfalls related to how the contexts actually behave.

 

Setting up the data layer of any application in the most optimal way obviously depends on the nature of the different applications, but I hope this post has given a few pointers regarding how you can use Entity Framework with the standard .NET memory-caching.

ASP.NET Web Performance Trace Debugging with Log4net

I’ve recently worked a fair bit with checking out performance and pinpointing errors within web applications where performance is a priority, which, to be fair, really should be all web applications out there. Over the course of my performance adventures, I’ve returned to messing around with something I don’t really see a lot of people use to the extent which they could/should, the ASP.NET Trace.

 

For those not familiar with this, it’s information about the current page request, including specifics regarding everything conceivable about the current request plus server information, and in particular when it comes to performance, it provides specific load times and a view of the control hierarchy – including render size and viewstate size.

 

I’ve made a quick and very simple sample to illustrate what you can do with this, and in my little sample, the load time trace information on my default page looks a little something like this.

  

This table shows the load times for each of the steps, and by the looks of things, there are things happening in the Page Load which takes an unusually high amount of time to load!

 

To get detailed information about which specific portions of the web page which spends the most time delaying my page from rendering, I’m starting by adding a simple log4net entry to the trace appender in my web.config file, and configuring it on application start.

 

My Page Load consists of 3 simple calls, I want to figure out which calls are being the most painful ones, and I wrap each of them with debug messages for testing, like this.

  

Keep in mind, this is just for a quick sample, in reality with complex systems you’d most likely want to place such messages inside the functions, and probably give them slightly more relevant information. Even better is if you already have a decent debug scenario set up across your solution, in which case you get a lot of free debugging here!

 

I recompile my solution now, and check the trace again, and find that the log4net messages have now decided to join in with the other trace messages, which adds a few more lines in-between the page load, as shown here. It’s important to note that the log4net messages now “break up” the step between begin and end load, as the trace counter simply counts from the last event, which log4net is now hooked up to.

 

This gives me an overview to work with stating that QuickStuff takes roughly 0.1 seconds to finish, SomeStuff roughly 2 seconds and LotsOfStuff is the winner with 5 seconds. Using these debug messages I can drill further down with more detailed debug messages to find the exact source of the "problem" and thus know exactly where I need to optimize code and/or queries to make the page load quicker.

 

By default, the ASP.NET Trace is disabled, and a lot of people tend to keep it that way, either by choice or by accident. To turn on this feature, you can add Trace=”true” to the page declaration of each individual page, but this does create some issues as you really don’t want to accidently put the trace out on a production site! I’ve found that a generic and more “on demand” way to enable trace on demand is to add a check for it through a querystring check in global.asax. Although, don’t put this in production either! :)

 

Doing something like this in global.asax will make the trace appear when you append ?trace=1 to whichever url you are working on, provided that it’s not overridden in the page declaration. It’s worth to note that working with ajax will sometimes mess up your trace, I tend to disable that temporarily if that’s the case – however, if I can’t work around this, I will add a fileappender to the log4net configuration, and check the delays between the entries there manually.

 

The last part I’d like to mention is the “page size” problem when it comes to performance. An issue which is more or less specific to ASP.NET WebForms is the added overhead with the viewstate. Using the Control Tree Information in the trace lets you detect how much of the page is viewstate, and how much is actual rendering.

 

I’ve adjusted my sample webpage to now have two labels, one of which has EnableViewState=”false”, both have had their Text properties set to Hello World! looped 100.000 times for over the top emphasis.

 

Here you can see the exact control hierarchy of all the controls and text on the page, total render size is 4mb, with each of the labels having 1.2mb of text and the label with the viewstate having 1.6mb on top of that in added viewstate.

 

Although this is a very far out example, it’s important to note that the viewstate of the label here is about 33% larger than the size of the actual label, and the client will have to download both of these, increasing the total download from a non-viewstate label to a viewstate by 133%. Also keep in mind that on client postbacks, the client will have to post the amount of viewstate back to the server, so if you’re having huge amounts of data to post for relatively simple operations, you might want to refactor or restructure your page if you’re experiencing performance issues.

 

A few obvious things I feel is worth pointing out here as a result of this is that if you have WebForm pages which don’t use postbacks at all, keep viewstate off! You can disable viewstate on a page level in the page declaration with an EnableViewState=”false”, the same goes for any controls you might have.

 

Furthermore, when binding complex objects, it’s ideal for performance to make sure you only bind objects with the properties you really need. If you’re using O/RMs in particular, you want to try to make as simple wrapper classes of your objects as possible, to ensure that you don’t keep pushing data you don’t need at all to both the client when it’s being read, but also on a potential postback to your server.

Logging with log4net

I’ve decided to write up a small post regarding logging in C#/ASP.NET applications, as there’s a fair few people over the years who have had questions and trouble regarding how and when they should log information, and what they should include in their logs.

 

First off, the disclaimer! These are my internal rules and thoughts based on my experiences and my personal preferences when it comes to logging. There are most likely other (and hopefully better) ways of implementing and maintaining a healthy level of logging. In this post I’m just trying to write down some of my basic guidelines and the thoughts behind them.

 

The logging implementation of choice for all my applications has always been log4net by Apache Logging Services. The simplicity, power and flexibility of the framework has all the requirements I’d like from such a framework covered nicely without me having to put any significant effort into it.

 

Setup and Installation of log4net is documented thoroughly at the official homepage http://logging.apache.org/log4net/index.html – I’ll skip that part and head to how to actually use logging in various applications.

 

Logging Goals

The main objective of logging at a debug-level should be to ensure that you have enough information to troubleshoot virtually any problem happening in your production systems, even if there isn’t an exception present. Having enough information to accurately reproduce a bug or scenario which happened in a controlled test environment will drastically reduce the time it takes to fix things as opposed to having to look at the problem and guess what went wrong.

 

Logging at an exception-level should be aimed towards making sure that critical exceptions are distributed to the right people as soon as possible for a quick response in regards to whatever needs fixing. A pre-requisite for this to work is to have decent exception-handling present in the system.

 

What this logging should *not* be, is a tool to use for business-related tasks. If you need to use logs generated by log4net as the main source to report anything or solve any business-related queries that aren’t a result of bugs or flaws in the system, you’re much better off writing custom logic and storing the data some place accessible through your reporting or support systems.

 

log4net Thresholds

All the messages generated by log4net has its own threshold value. These are in order from lowest to highest, Debug, Info, Warn, Error, Fatal. A typical setup will route different levels of errors to different handlers – common usage tends to be logging everything to a text file locally, while sending off error and fatal messages per mail. Setting a threshold in the configuration will return all messages at that threshold and above.

 

Here’s a relatively short overview of how I use the various thresholds with examples. It’s important to note that the intended use of thresholds must reflect the appenders used. If you want developers to get notified immediately when the system dies horribly, you want to make sure that only those messages have the highest threshold, and the instant notification appender only catches the messages with the highest threshold.

 

DEBUG

The lowest value and primarily used for what it says, debug information. These should be the messages with diagnostic information used to recreate what is happening during a given operation. They will also be the messages you’ll most likely end up having the most of in your system. As such, it’s important to not go overboard with the amount of these messages, all of them should have a good reason for being included.

 

If I have a function which will add a customer to my system, I would start the function with a debug call saying which parameters I got passed into the function. If at a later stage in the function, there happens to be some complex logic related to which type of customer I’m going to add, with separate creation paths based on the result, I will add on another debug message here with the reasoning and result of the selection to show which code path was taken. At the end of the function where the customer will be saved to a database, another debug message should be fired off at the success of creating the customer, including the primary key of the Customer table to ensure that everything worked out.

 

In the event that there is something wrong with a Customer being entered here, a developer diagnosing the problem can bring up the logs and trace it easily by searching for the primary key of the Customer table and check backwards what was done during the creation, as well as getting the exact parameters used in the function. If the parameters passed or path choice listed can’t immediately explain what the problem here is, you can easily recreate the same customer being created in a testing environment by calling the same function with the same parameters.

 

If you manage to cover all relatively complex and vital functions in this manner you should be off to a great start in being able to track down problems.

 

A special mention here should go to external calls such as web services/MSMQ and so on – as you really want to log the source coming in there in addition to everything else to ensure that you can recreate anything that might be faulty outside of your code, always make sure you can prove that others are messing up!

 

For Data Access / External Interfaces there’s also the option of implementing very generic debug messages using object oriented approaches, you need to weigh the benefits of this compared to the amount of debug messages you will receive and plan accordingly.

 

INFO

I don’t really use this level a whole lot. Currently I only use it for saying when applications or services are starting and stopping, as the only other reason I see for this level is to use it for “important debug messages” – but I haven’t seen the need for this just yet, the debug messages are still debug messages!

 

WARN

The first of the thresholds more commonly used for exceptions. I’ve found myself using this more and more now for exceptions that happen without there being any decent business implications, but still something that might be looked at “at one point”™ or “when we have time”™. In addition to this, I also use this in cases where it’s something that probably isn’t dangerous, but if it happens a lot we should look at it.

 

An example of using this in an ASP.NET application could be if you handle a RequestValidation exception on a generic level, which typically comes from someone entering html/script accidentally in some form before submitting the page. This isn’t really something to be too worried about, but in the case of an actual attack, it’s worth mentioning in the logs if you skim through them on a Warn level.

 

It’s important to just add Warn messages when you actually might want to look at these messages, if you’re parsing some optional variable which might fail most of the time and using a try/catch to ensure that everything goes smooth regardless, you don’t want to log this at all.

 

A slight note here, the level is WARN not WARNING, if you happen to add WARNING as a threshold, log4net will be confused and revert to no threshold, giving you all Debug and Info messages as well.

 

ERROR

The Error level is the main way to handle exceptions. A rule of thumb here is that errors which will have some sort of business impact if ignored, or system errors which will need to be fixed should be put in this category.

 

A typical example of this for an ASP.NET application would be to add log4net calls to the Application_Error event in case the exception which has been thrown wasn’t handled better, and the user typically will be sent to a custom error page. This is typically behavior from the system which should be fixed, as such, an error message is warranted.

 

Make sure that you include the actual exception in the call to the error-logging here, along with an informative error message with as much information as you can get a hold of. Seeing how these messages usually are called from within catch blocks, be mindful that you code this information defensively, as you don’t want to accidently trigger a null-reference exception while doing a logging-call.

 

Keep in mind that as long as you include the exception, you will maintain a stack-trace in the message, so you don’t need to include detailed information which is already included in a standard stack-trace.

 

FATAL

The highest level is the one you ideally don’t want to see or use at all. I reserve this for critical errors resulting in the business or systems in general not being able to operate at all, or other errors requiring immediate attention.

 

I feel it’s extremely important to distinguish between the Fatal and Error levels at a business level, if you’re an e-commerce site and you get errors while trying to save a new customer it’s not quite at the same level as being completely unable to connect to the database containing all customer information. Receiving a “Shutdown in Progress” from the SQL Server would be quite Fatal, whereas “String or binary data would be truncated” is sad, but you probably won’t get too many developers cutting their lunch short to fix it.

 

In short, use this for exceptions where you get indications that the system is globally threatened, business-critical services stopping/not-starting or other situations where you would consider permanently relocating to Mexico if it’s not detected within 5mins and resolved within 30mins.

 

Threshold Summary

It’s very important to know the intended use of each level and follow the guidelines set by your company as best you can. When you’re writing code, keep in mind that debug messages will help immensely when you discover an issue in production. Even if you feel that it’s nice and safe code executing, you never know what the next person touching your code will do, and properly inserted debug messages across the application will help both of you when you try to figure out what “he” obviously did wrong.

 

When you do exception handling, think of all the various exceptions that could happen inside the catch block, catch them individually and log them according to the implications of that specific exception being unhandled. If you know you won’t need to worry about the exception, don’t log it as an Error!

 

log4net Appenders

The actual implementation of how to deal with the logging in your code will vary greatly depending on the applications, setup, infrastructure and other factors. It’s also important to point out that you can have multiple appenders set up with the same criteria so you can put the messages several places if you want to. It’s also very simple to create your own custom appenders with a bit of work if you want that SmsMessageAppender for the fatal errors for instance.

 

As a result of the differences in applications here I don’t really have an overall tip of how to do things here, just a few hints and tips on using the various common appenders.

 

A list of the default appenders provided by log4net is listed at http://logging.apache.org/log4net/release/sdk/log4net.Appender.html and examples of how to use them at http://logging.apache.org/log4net/release/config-examples.html – I recommend browsing through the latter and see which ones seem most reasonable.

 

The commonly used appenders would include FileAppender, RollingFileAppender, SmtpAppender, AdoNetAppender and in debug environments ColoredConsoleAppender/AspNetTraceAppender depending on the application.

 

FileAppenders

The FileAppender and RollingFileAppender are probably amongst the most common appenders used for Debug messages. They simply add messages to a file, with the option to roll over on a given size if you specify a RollingFileAppender.

 

When you use these, you need to make sure that the application running log4net has write access to the path/folder you specify as the log directory, or the IIS/ASPNET process if it’s a web application. It’s also important to make sure you don’t put the log file somewhere accessible from outside if you decide to use this on your web server.

 

It’s also common to add these appenders in test/development environments as they’re quite helpful alongside a tail-tool such as BareTail, adding color-coding to BareTail on a second monitor and pointing it to your logfile is an excellent way to see what’s happening behind the scenes when you’re doing things from the front-end.

 

It’s also nice to note that the RollingFileAppender has options which will let you roll over to new log files based on dates or hours, so you’re able to maintain a separate log-file per day/hour to simplify searches through the files.

 

SmtpAppender

This appender is probably the most used Error-threshold appender of them all. Sending an e-mail whenever something hits the threshold is quite useful and a decent way to notify developers that something is wrong.

 

A few notes on the BufferSize parameter here, BufferSize is used to specify how many messages *before* the actual error it should include. This means that if you get an error-message, it will also include a lot of debug-messages that happened before the error. This means that it’s even more important to include decent and descriptive debug messages if you intend to use the SmtpAppender.

 

AdoNetAppender

This appender is the one I’ve seen most people have problems using. It logs the messages over the given threshold to the database, nothing more, but it’s the most configuration-heavy appender out there.

 

There are two main causes for problems here,  the first is the specific configuration of every field you need to insert into. If the type or size is off, you won’t see anything enter the database at all – and you won’t get any sort of notification of this unless you have set the log4net debug options on and specified an output there. I recommend that you check out the “How do I enable log4net internal debugging?” in the http://logging.apache.org/log4net/release/faq.html document, and write the output to file, then check if there’s anything wrong with the setup in that log.

 

The second problem is mainly due to the fact that BufferSize doesn’t mean the same as with the SmtpAppender. For the AdoNetAppender, this specifies how many messages the buffer must have before it actually writes the batch to the database. If you’re testing that this actually works, you want to set this to 1 to write messages as they come.

 

There are some obvious drawbacks when it comes to using this appender, namely that you rely on a database being up to write entries, and it’s much too easy and tempting to also use the production database to store the logging data. Depending on the amount of logging data you expect, you should be very careful when deciding whether or not to use this logger, and extremely careful with the threshold you decide to set for it. Unless you really need the option to perform SQL-queries against the messages you have stored away, or need to further process them, there are most likely better options out there to cover your needs better with other appenders.

 

Other Appenders

There’s a variety of other appenders for the different scenarios you might encounter. When I’m debugging services as console applications, I always include the ColoredConsoleAppender to give me an overview of what’s happening on the fly.

 

For ASP.NET pages during development, you can simply enable trace and include the AspNetTraceAppender to add the log4net messages into the ASP.NET trace as well, all your debug messages will serve their purpose well when you double-check that the input values you provided resemble what’s being passed into the lower layers if you followed the debug pattern specified under thresholds.

 

The other appenders also have their uses, but are less common. The Remoting/UDP/network appenders have their use if you have a centralized logging server for instance, and you could most likely anger your administrator quite a bit by adding an EventLogAppender with a debug threshold to the web.config of your production web server!

 

Custom Appenders

If you have some specific  task you want done with the error messages that somehow isn’t covered here, you can easily specify your own appender by creating a class inheriting from the AppenderSkeleton class. This really isn’t as painful as it might sound, so if you have something fairly custom in mind, I recommend trying this out.

 

Uses here could be if you have your own task management system, and you receive errors coming in, you could add an appender which automatically transforms an error message to a task to be resolved.

 

Appender Summary

When deciding which logging approach and appenders to go for, you want to gather information regarding how/where the applications will be set up, what the infrastructure is like and how the overall logging is implemented in the applications.

 

As mentioned earlier, a simple web server application can go for a RollingFileAppender with threshold Debug + SmtpAppender at threshold Error. If things get a bit more complex and you have things like load balancing, multiple servers, multiple services and multiple applications, a good way to handle things could be to have a centralized application server receiving all the log messages and processing them further.

 

If you have an extremely business-critical service you need to have running at all times, you could go with a custom coded Appender which at the Fatal threshold will, not only send email to the developers, but also send SMSes to certain people at night, or if it’s during work hours – perform some custom task which will max out the volume on a PC in the office and start playing “Crazy Train” to ensure that everyone knows there’s tomfoolery afoot!

 

Summary

Having proper logging in place with a clearly defined logging strategy in your applications will help improve internal testing during development as well as being able to troubleshoot issues in production systems whenever bugs manage to sneak into the system.

 

Setting the right standards for when to use the available log-thresholds alongside the appenders and proper exception handling will ensure that any errors occurring in production environments can be found and diagnosed quickly with logs available.

 

In other news, I realize I wrote a bit more than I intended to, hope someone found it slightly useful at least!