In my previous post, I discussed a lot of the when of logging – when to log things in your application. So in this post I’d like to talk a little bit about what to log.

Having lots of logs is certainly better than having none, but if the logs don’t capture important information that allow you to make decisions about your application design, then they are not as valuable as they could be. So in this post I will discuss certain key pieces of information which can greatly enrich your logs:

• • Web Request Data
  • User Data
  • Caller Data
  • Environment Data
  • Error Data

Web Request Data

In a web application, it can be hugely useful to log certain information about the incoming request. The first things we want to take a look at are what was requested. See below for WebForms/MVC code snippets:

Protocol

If your web server serves both HTTP and HTTPS requests, you should log the protocol being used for the request. (You do use HTTPS, right?)

Hostname

By logging the hostname, we can see the actual domain that was requested, including ports (if the port was specified) and the subdomain.

Path

This represents the actual request path – the part after the hostname and before the query string. In MVC apps, this is used for routing to the appropriate controller/view, and in WebForms apps this will be the path to the .aspx page which is rendered.

Query String

Because query strings are used for passing in important information, the request information is not really completed without it. NOTE: if you are passing sensitive data via query strings, be sure not to log them! Additionally, see this StackExchange post for reasons why you should not do this.

IP Address

This one is a common pitfall, but it’s good information to have no matter what. Remember that the IP address is the request of the machine which sent the request to you, and not unique to a user. For instance, if multiple people in the same home visit your website on different computers, you will most likely see the same IP address for all of them.

To add to the complexity, if a proxy, CDN, or load balancer forwarded the request to you on behalf of a user, then this IP address may not be the user’s at all. But take heart: well-behaved proxies will usually include the original IP in a header which you can retrieve. A common way of doing this is with the X-Forwarded-For header. Some other services such as Cloudflare and Akamai instead use the True-Client-IP header. Depending on your network infrastructure will determine where the actual user’s IP address will be stored in the request.

User Agent

The User Agent is another important header to capture – it indicates the web browser and operating system that the user is using. This can be very useful when attempting to diagnose bugs that only occur on certain browsers, and can also give insight into the technologies in use by your users. At work we were shocked to find that an extremely small percentage of our users were viewing our website on Android TVs!

Code Example: WebForms and .NET Framework MVC

Below is an example of how to fetch all of these values in an MVC or WebForms app. In your Controller/Page, there is a Request property defined which contains lots of information about the request:

var hostname = Request.UserHostName;
var path = Request.Path;
var queryString = Request.QueryString;
var ip = Request.UserHostAddress;
var forwardedFor = Request.Headers["X-Forwarded-For"];
var trueClientIp = Request.Headers["True-Client-IP"];
var userAgent = Request.UserAgent;

Code Example: .NET Core MVC

The implementation of the MVC Controller’s Request property’s class is a little different in .NET Core, but the same principles still apply here:

var hostname = Request.Host;
var path = Request.Path;
var queryString = Request.QueryString;
var ip = Request.HttpContext.Connection.RemoteIpAddress;
var forwardedFor = Request.Headers["X-Forwarded-For"];
var trueClientIp = Request.Headers["True-Client-IP"];
var userAgent = Request.Headers["User-Agent"];

Code Example: ASP.NET Core Owin

If you need to retrieve the request data from the Owin context during the execution of your Owin pipeline (this is a great place for performance and error logging!) then it is very similar to the above example, except that we will get the request object from the Owin context instead of a property on our Controller:

app.Use(async (context, next) =>
{
  var hostname = context.Request.Host;
  var path = context.Request.Path;
  var queryString = context.Request.QueryString;
  var ip = context.Request.HttpContext.Connection.RemoteIpAddress;
  var forwardedFor = context.Request.Headers["X-Forwarded-For"];
  var trueClientIp = context.Request.Headers["True-Client-IP"];
  var userAgent = context.Request.Headers["User-Agent"];
  return await next();
}

User Data

It is very useful to have information about the user themselves when looking at logs. This lets you know who caused the log, but can also be a useful aid when troubleshooting bugs, since you can create a test account with similar data. It is also very useful for audit logging, if you need to answer a question about which user took an action and when.

To get data about the current user, you will need access to the user’s Principal. How you get access to this will vary by environment:

• In WebForms or .NET Framework MVC apps, the Page/Controller has a User property which will contain the current user’s Principal.
• In most .NET Framework apps, you can also access the current user’s Principal using Thread.CurrentPrincipal.
• In .NET Core apps, Thread.Current principal is not available, and you should instead use .NET Core’s dependency injection and the IHttpContextAccessor interface.
• In the Owin pipeline, you can access the User property of the HttpContext, which contains a ClaimsPrincipal.

Once you have access to the user’s principal, you can use it to check whether they are properly authenticated, and get their name:

var userPrincipal = Thread.CurrentPrincipal;
var isAuthenticated = userPrincipal.Identity.IsAuthenticated;
var userName = userPrincipal.Identity.Name;

Additionally, a very common implementation of the IPrincipal interface is the ClaimsPrincipal, which can contain all sorts of information about the current user – common and useful claims to look at are the user’s roles, email, and any application-specific claims you might generate during user login, such as a user ID or customer ID.

Caller Data

A very useful diagnostic tool that I’ve come to love is: including the file and method which actually wrote the log. While you can rely on stack traces in the case of exception logging, it can also be useful to find out where other types of logs, such as user behavior logs are being generated, in order to put them into context.

C# exposes a couple of really handy attributes for this purpose which can be applied to your method parameters. The first is the CallerMemberNameAttribute which contains the method name of the method which called yours. The second is the CallerFilePathAttribute, which contains the path on disk to the source file in which the calling class is defined (note that the path will usually correspond to the machine which compiled the code and not necessarily the one on which it is running!)

To use these attributes, you simply need to add them to nullable string parameters on your method which does the logging:

private void CallerExample([CallerMemberName] string memberName = null,
    [CallerFilePath] string filePath = null)
{
  var fileName = filePath.Substring(filePath.LastIndexOf(Path.DirectorySeparatorChar) + 1);
}

Bear in mind that the values at runtime will be the calling method – even if you use some private helper methods to do logging, in which case the method and file name may always point to your logging class. In this case, simply add the parameters with the Caller attributes to your public method and pass the values in to your private method – the values you pass in as arguments will be used instead of the actual caller values.

Environment Data

Capturing information about the environment your code is running in can be very useful when diagnosing environmental issues, such as when an error only occurs on one server for some reason.

Some of the most useful pieces of information here are:

• Machine Name (useful to know if something is only happening on one machine.)
• Thread ID (useful for diagnosing race conditions.)
• UserAccount under which the application is running (useful for diagnosing permissions issues.)

These values can be accessed on the Environment static class:

var machineName = Environment.MachineName;
var threadId = Environment.CurrentManagedThreadId;
var userAccount = Environment.UserName;

Error Data

This one is fairly easy, but is nonetheless very important. Whenever your application detects an error or exception, you should log the Exception message and stack trace for diagnostics.

Many programmers simply log the exception itself and think that they’re done, but remember – your exception logs will be the first place you look when diagnosing a bug! Think ahead and put yourself in your shoes and consider what additional information might help you get to the bottom of a tricky bug, and log it now! Good candidates for this are things like method parameters, collection sizes, or user roles if an authorization exception is possible.

Conclusion

I hope that this has given you some useful ideas and code examples to really up your logging game. As you enrich your logging story by adding additional data to logs, and a more thorough system of logging to your application, you will find yourself learning about all sorts of things that happen during your program’s execution that you may never have discovered through normal testing.

When setting out to design maintainable software, one of the most critical things to bear in mind is creating feedback loops that allow you to make code decisions based on the application’s actual use and performance under real-world circumstances. A crucial aspect of this is that your application needs to be able to tell you when something is wrong.

One of the main ways to achieve this is by application logging. There are many forms of logging, but in the scope of this article we will discuss a few categories of logging:

• Diagnostic Logging
• Performance Logging
• User Behavior Logging
• Code Behavior Logging
• Audit Logging

Diagnostic Logging

Diagnostic logging is, broadly logs that help you identify and troubleshoot failure scenarios in your application. Below we will discuss a variety of ways to employ diagnostic logging to help reduce your time spent tracking down tricky bugs to help you spend more time on the fun parts of programming.

Catchall Exception Logging

This is the most basic form of exception logging, but its great benefit is that if any code is written in your application that does not correctly handle exceptions, you are guaranteed to have a log about it! Depending on the structure of your application this may take many forms.

In ASP.NET applications, you can define a method in your Global.asax file to handle all errors that occur during processing of an HTTP request:

void Application_Error(object sender, EventArgs e)

In an application using the Owin pipeline, you can write a simple middleware which wraps all subsequent middleware executions in a try/catch, something like this:

app.Use((context, next) =>
{
  try
  {
    return next();
  }catch(Exception ex)
  {
    // Log the exception here.
  }
}

In .NET desktop applications, you can use the AppDomain class’ UnhandledException and FirstChanceException lifecycle events to log either all exceptions or only unhandled exceptions, whichever you prefer (note that in recent versions of .NET Core console apps this works as well!):

AppDomain.CurrentDomain.UnhandledException += (sender, args) =>
{
  var ex = args.ExceptionObject;
  // TODO: test the exception object type and log it
};

Downstream Dependency Error Logging

Any time your application interacts with a downstream dependency, such as a database or another API, you should wrap the interaction in a try/catch and log any exceptions that get thrown. This is incredibly useful for determining when failures in your application are caused by bugs or outages in other people’s code!

try
{
  myDownstreamDependency.SendRequest()
}catch(Exception ex)
{
  // Log the exception here.
}

Note that when doing this, you should also include as many specifics about what you were doing in your log. Things like: which API call you were making, what URL you were accessing, what arguments you passed in, which user was taking the action, etc.

Soft Failure Logging

As we are adding logging to our application, it is important to remember that not all failures in our code result in exceptions being thrown. There are other code failures which can result in bad/missing data without ever throwing an exception. One good example of this is when you know an operation should always return a non-empty list, but the resulting list is empty. While this may not cause an exception that causes your application to be unusable, it is still a logical error which will have some known or unknown impact on your users and should be logged.

Performance Logging

Another thing we want to know about in our application is when something causes it to run slowly. In many cases, problems or changes in our code can cause the code to begin running more slowly, which from the user’s perspective is a bug!

So any operation which a user initiates which could cause a bad user experience if it were to take too long should be wrapped in some form of performance logging. A great tool for this is the .NET Stopwatch class.

var stopwatch = new Stopwatch();
stopwatch.Start();
// Do something
stopwatch.Stop();

After calling the Stop method on our Stopwatch, then we can check its ElapsedMilliseconds or ElapsedTicks properties to check how much time has passed, and include this information in our logs.

HTTP Request Performance Logging

Logging the performance of all HTTP Requests is a great way to get a high-level overview of the performance of a web application. Depending on your architecture there are a few ways of doing this, but in ASP.NET applications with a Global.asax file, you can define methods to handle the ASP.NET lifecycle events for the beginning and end of handling a request:

private Stopwatch _stopwatch;
protected void Application_BeginRequest()
{
  _stopwatch = new Stopwatch();
  _stopwatch.Start();
}
protected void Application_EndRequest()
{
  _stopwatch.Stop();
  // TODO: log the performance here
}

In an Owin application (such as ASP.NET Core apps), it’s even easier, you can just define a middleware near the beginning of your Owin pipeline that calls the rest of your middleware, and log the performance there:

app.Use((context, next) =>
{
  var stopwatch = new Stopwatch();
  stopwatch.Start();
  var result = next(); // We run all of our other middleware
  stopwatch.Stop();
  // Log the performance here.
  return result;
}

Downstream Dependency Performance Logging

Once again it is very important to keep track of your downstream dependencies. Not all problems in your application originate in your code, so being able to tell when slowness in your application originates in an API or database you depend on is very important to point your troubleshooting in the right direction (and point blame in the right direction, if you have the misfortune to work for an organization which does not have blameless postmortems…)

As with our downstream dependency error logging, we should capture as many specifics as possible about our API call/DB query in order to facilitate rapid troubleshooting of the problem.

User Behavior Logging

It can be very useful to know how your users are actually using your application. The scope of this extends beyond just troubleshooting bugs and problems, to informing your technical priorities and even feature grooming. Below are some suggestions about useful types of user actions to log:

Log In/Out

Whenever a user begins or ends using your application, you should log that behavior. This provides very insightful usage statistics. Additionally, when a user attempts to log in, you should record whether their login attempt succeeded or failed – this is useful for detecting brute force and DDoS attacks, or even informing your product decisions around things like password recovery or failed password lockout thresholds/durations.

New Features

When you release a new feature, it can be very useful to log how many users are using the feature and how they are using it. This is important feedback for an Agile development process – you can’t always talk to your users about how they are using your application, but you can log what they do! Combining this with error and performance logs can give you a lot of insight into whether users are having a positive experience with a new feature.

High-Impact Features

If a particular feature in your application is known to have a significant performance impact, it can be very good to log the frequency with which users use that feature. This might be operations such as provisioning a new virtual machine, or clearing all of the cached data for their customer.

Code Behavior Logging

Just as User Behavior Logging is useful for finding out what your users are doing, Code Behavior Logging is useful for finding out what your code is doing.

Application Lifecycle

Logging key events in your application lifecycle can be really useful for diagnosing startup problems and crashes. In particular, one of the first things you do when your app starts is create a log with the current machine name! This not only gives you a history of when your app was started or restarted, but also lets you make sure that your logging is working!

In a .NET Core application, the easiest place to do this is right in the beginning of the Main method:

public static void Main(string[] args)
{
  // Write your log here!
  CreateWebHostBuilder(args).Build().Run();
}

For older .NET Framework WebApps (MVC/WebForms), you will instead need to do this during the Application_Start HttpApplication lifecycle event in your Global.asax file:

protected void Application_Start()
{
  // Write your log here!
  // Usually startup things like dependency injection etc. go here.
}

 

For WPF desktop applications, the App.xaml.cs constructor or the MainWindow’s constructor are good places.

Other useful lifecycle events to capture are: application shutdown, and the execution of any recurring background worker threads which may run in the background during normal operations.

Branch Execution

This is particularly useful in legacy codebases. Sometimes you will find yourself staring at some old code and wondering “does this code even ever get hit any more?” Branch execution logs can answer this question for you – simply add a log statement in that code branch and release it to users. It won’t take long before you’ll have an answer to that question.

Data Logging

When it is not clear what the actual data in your application looks like at runtime, it can be useful to log the data itself or key attributes about it. For instance, if you are doing lots of string operations in your application, it might be useful to log the length of those strings so that you know how important optimizing your string operations is. If the strings are always small, the optimization work may not be valuable enough to do. But for long strings it might warrant a higher priority.

Audit Logging

Audit Logging is designed to give you a record of sensitive user behaviors. There are many concerns involved in audit logging – audit logs are often customer-facing and can sometimes play a role in compliance and legal matters. So it’s really important to get these ones right.

User-Facing Data Changes

Any time a user modifies data that users have access to, and that change is persisted anywhere (such as a database or filesystem) you should generate an audit log for this behavior. Be sure to log not only the data that was modified, but the user doing it, and if possible, some details about what was changed.

Viewing Sensitive Data

While we are normally worried about auditing when users change data, some data is so sensitive that even viewing it warrants an audit log entry. What data falls into this category will vary depending on your application, but good candidates are financial information, or when one user views personal data about other users.

Conclusion

I hope that this blog has given you some good heuristics to think about when adding logging to your application. Logs are an absolutely amazing tool when it comes time to troubleshoot a bug, diagnose an outage, or provide customers with really specific and useful data about a data loss scenario. When things go wrong (and they will) logs are what helps you put on your Sherlock Holmes hat and make sure it doesn’t go wrong twice!

In my experience, as DJs gain more experience, they go through several phases. I’d like to discuss them today, to help my friends who are just starting out DJing dances think about how to level up their DJ game as quickly as possible:

Phase 1: The “Music I Like” DJ

This is where most DJs begin their journey: they have created a nice little collection of music they love to dance to, and they create playlists from that. It’s all of their favorite songs, and they’re able to put together 1-3 hours sets containing only songs they enjoy.

This is a great start, and the community can always use eager people willing to volunteer their time to DJ for us! But the fundamental problem with this style of DJing is that it fails to account for other people’s tastes. By creating playlists that appeal perfectly to one person’s preferences, you may accidentally also be creating playlists that don’t appeal at all to other dancers who come to your dance!

Eventually most DJs notice this and begin to move into Phase 2.

Phase 2: The “Music the Dancers Like” DJ

These DJs have expanded their collection to include the most popular songs for their dance style – even the ones they personally don’t like. Their playlists still contain some of their absolute favorites and some guilty pleasures, of course – but the majority of their set is designed to appeal to their audience rather than their personal tastes.

This is a huge improvement from the first phase of DJ’ing because by taking other people’s tastes into account, you will rarely have your dancers going home thinking “man, that DJ didn’t play a song I liked all night!” But DJs in this phase often give little thought to the progression of their music throughout the night – whether their transitions between songs makes sense, and whether they are playing so many similar songs in a row that their dancers who would prefer something different are getting bored.

As DJs endeavor to bump their game up to the next level, they move on to Phase 3.

Phase 3: The “Perfect Playlist” DJ

These DJs invest a lot of time, love, and energy into their playlists. They pick the first song carefully, making sure that their first song is a popular one that kicks off their set with a bang and gets everyone on the floor. They pay close attention to transitions between songs, making sure not to have too many songs of the same tempo/style in a row, to give their dancers a breather between fast songs, and making sure that the vibe doesn’t become sleepy with too many slow songs in a row.

They also make sure that their dancers with particular tastes don’t have to go too long between songs that they really love – trying to mix in various styles at regular intervals. This gives their dancers a nice rhythm for the evening, taking social breaks on the songs they like less, but knowing it will only be 5-10 minutes until a song they will love is played. Everyone needs to take breaks sometimes, that’s expected. But we’ve all had the disappointing experience of going 15-20 minutes without hearing a song that really makes us want to jump up and dance.

But crowds change, tastes change, popular songs become played out, and we all know that the difference in vibe between late night dancing and early evening dancing is like night and day. So a great playlist, while it is a great start, still isn’t the top tier of DJing.

Phase 4: The “Handcrafted Playlist” DJ

These DJs create a playlist as a starting point, but know the old saying that “no playlist ever survives contact with the dancers.”

Because every crowd, every event, every evening is different, these DJs update their playlists on the fly based on who showed up and what the energy level of the room is like. If they see a large group of people sitting down for a while, they keep changing songs until they manage to play something that gets them on the floor. As they do this, they learn the tastes of the various cliques of dancers while still feeling out and shaping the vibe of the evening. As the evening gets late, they play more slower songs, but also know that songs with a slow tempo (BPM) can nonetheless have very high energy.

They also know their community and play songs appropriate for the hour. We all know that as the evening goes on, the dance (and the crowd of dancers) evolves in predictable ways. Many West Coast Swing events accommodate junior dancers – this is great, but it means that songs with profane lyrics are better played at 2am than at 10pm. Likewise, they know that their older dancers will love to hear hit songs from decades past, and will plan to play those earlier in the evening when the crowd will best enjoy it.

Conclusion

As I’ve worked on my own DJing, I’ve managed to journey through the first 3 phases of DJing, and am now challenging myself to become a true Phase 4 DJ. If you are a DJ or an aspiring DJ, I hope that this article gives you some things to think about to find ways to up your own DJ game!

There’s nothing better than playing music for an energetic crowd all night, and then having people with varying tastes in music come up to you afterward and tell you they loved your set – that’s how we know we’ve really done our job well and created something special!

If you’re like me, you like to be able to write unit tests for logic in your code. Unfortunately, Unity has historically not had great support for unit testing in the form that most programmers are used to – however recently, they are adding more and more support tor automated test.

Tonight I spent a fair bit of time figuring out how to write simple NUnit tests for my code in Unity, and now that I’ve figured it out, I wanted to share my findings!

Step 1: Create a Test Assembly

First, in your Scripts folder, right-click and add a Tests Assembly Folder:

You can name it anything you like. Under the covers, Unity manages C# projects for you, rather than using traditional .csproj files that most .NET developers are used to. These assemblies are managed using Assembly Definition (.asmdef) files – when we created our Tests Assembly Folder, Unity created an assembly definition for us.

Step 2: Configure our test assembly for Editor mode

Let’s navigate to the new folder and check out the assembly definition by clicking on it:

Now what we want to do is configure this assembly to use the Editor platform. For programmers used to old fashioned coded unit tests, this will be the most similar to what you’re used to. The other platforms allow you to design Play Mode tests which won’t be covered here. To change this, we can just select the Editor platform, then hit Apply:

Step 3: Create your test script

In the new Test folder, right-click and create a new C# Test Script:

This will create a test script for you with a couple of test methods using Unity’s UnityEngine.TestTools assembly, which is based on NUnit.

Step 4: Run our tests

Open the Test Runner (Window > General > Test Runner) and then select EditMode. here we will see the DLL generated from our Test Assembly definition, along with the tests inside of it:

Simply right-click and Run anywhere in the assembly hierarchy to run the tests:

Step 5: Create an Assembly Definition for your regular game code

Okay, so now we have tests, and we can run them. Awesome! But there’s a big gotcha – our test assembly is generated by Unity dynamically, meaning we can’t add an assembly reference to our code! If we try, then we will just get console errors when we try to run them in the Test Runner saying that our namespaces are not found.

To get around this, we can create another Assembly Definition for our main game code, then reference it in our test Assembly Definition. Let’s do this in our Scripts folder:

We can name this anything we want. Once we do this, if you reload your solution in Visual Studio, you will notice that your Assembly-CSharp project has been renamed to match our new Assembly Definition:

Before…

After.

Step 6: Reference our main game code Assembly from the test Assembly

Now let’s go back to our test assembly definition, and add a reference to it:

Select your Assembly from the list, then click Apply.

Step 7: reference your game code in your tests!

Now the test Assembly generated by Unity will have a reference to the Assembly containing our main game code. So now we can simply reference our code normally. To demonstrate this, we can define a really simple class in our game code assembly:

Then let’s go and edit our test to reference it:

Once we add a using statement to import our namespace, we can reference our game code directly in tests. Now simply run your test again in the unity Test Runner!

Next Steps:

Now that we have some unit tests in Unity, there’s a few new things to know. First, when the Test Runner builds your solution in the background, it will not display errors directly in the Test Runner. You’ll have to look for these errors in the Unity Console:

Second, it can often be useful to debug through our test code while it’s running – to do so, simply attach to Unity, then run your test(s) via the Unity Test Runner, and you will be able to hit breakpoints and step through your code.

And that’s it! For those of you like me who have a background in using coded tests to make sure your code keeps working long after it’s written, I hope this helps you adapt your testing habits to the Unity world! Happy coding!

I’ve had a self-hosted WordPress site for many years. But have decided that keeping it up to date and managing the Vm it ran on were not worth it. So I’m moving my blog content to a new home on wordpress.com to make things easier on myself.