Logging with the .NET backend for Azure Mobile Services

Article
04/24/2014

On the node.js version of mobile services, logging was done mostly via the node’s console object. In any of the server scripts you could call console.[log|warn|error] and when that script was executed you could go to the “logs” tab in the portal to see them. In the .NET backend you still have the same capabilities, but there are some new features and quirks which one should be aware to get the best logging experience in that new backend. Let’s go over them here.

Logging when running locally

This is a very simple example of logging in the .NET backend. If we write this controller class, we can use the Log property in the Services member of the TableController<T> class to write to the Azure logs. Notice that the Info method in the Log property used below is an extension method and you need to add a ‘using System.Web.Http;’ statement to see it (same for the Debug / Warn / Error methods).

public class TodoItemController : TableController<TodoItem>
{
protected override void Initialize(HttpControllerContext controllerContext)
{
base.Initialize(controllerContext);
var context = new MyContext(this.Services.Settings.Schema);
this.DomainManager = new EntityDomainManager<TodoItem>(context, this.Request, this.Services);
}
public Task<TodoItem> PostItem(TodoItem item)
{
this.Services.Log.Info("[PostItem] Inserting new item: " + item.Id ?? "<<no id>>");
return base.InsertAsync(item);
}
}

When we publish the application to Azure and insert an item, we can see the log in the “logs” tab in the azure portal.

However, when we’re running the backend locally, there is no portal where we can see the logs, so where can we find them. As one user in Stack Overflow had this question, I imagine that others may have the same problem. And there’s nothing really fancy here – the logging is implemented (by default, see more advanced topics later) using the standard System.Diagnostics tracing system, so we can add a new listener in the web.config and send the log output to some file where you can read:

<system.diagnostics>
<trace autoflush="true">
<listeners>
<add name="default"
initializeData="c:\temp\mylog.txt"
type="System.Diagnostics.TextWriterTraceListener" />
</listeners>
</trace>
</system.diagnostics>

If we send the same request to the local service, we can now find it out the traces.

iisexpress.exe Information: 0 : Message='[PostItem] Inserting new item: 01234567-89ab-cdef-0123-456789abcdef-1', Id=00000000-0000-0000-0000-000000000000, Category='PostItem'

Another alternative, if you’re running the local .NET backend under the debugger, you can look at the “Output” window, selecting “Show output from: Debug”, and the traces will be shown in the window. If that’s the case you don’t even need to add a trace listener, as when running under the debugger VS will add one listener by default that writes to its output/debug window. There will be some noise on other information which is traced to the debug window, but that may be an acceptable solution as well.

The traces does not have the same format as we find in the portal, but that’s a quick way to get the information you want.

Customizing traces

But what if you really want a better formatted traces? Not a problem. The .NET backend uses the same system as its underlying framework, ASP.NET Web API. All traces are written via the ITraceWriter interface, and you can supply your own implementation of that interface, like in the code below, which uses a format very similar to the one displayed in the portal. The “category” parameter by default has the name of the member (typically method or property) where the log method was called, but it can be customized for anything that makes sense for your application.

public class MyTraceWriter : ITraceWriter
{
public void Trace(HttpRequestMessage request, string category, TraceLevel level, Action<TraceRecord> traceAction)
{
var record = new TraceRecord(request, category, level);
traceAction(record);
System.Diagnostics.Trace.WriteLine(string.Format("{0} - {1} - {2} - {3}",
record.Level, record.Message, record.Category, record.Timestamp.ToString("ddd MMM dd yyyy, HH:mm:ss tt")));
}
}

And to use it we can replace the trace writer service with our own implementation in the HttpConfiguration object returned by the ServiceConfig.Initialize method.

public static class WebApiConfig
{
public static void Register()
{
var configBuilder = new ConfigBuilder(configOptions);
var config = ServiceConfig.Initialize(new ConfigBuilder());
config.Services.Replace(typeof(ITraceWriter), new MyTraceWriter());
}
}

The document Tracing in ASP.NET Web API has a good introduction on the tracing system used by Web API (and the .NET backend of the mobile service). Now, everything works fine when we run locally, but if we publish the service to Azure and invoke the operations in the controller again, we won’t see the traces in the portal anymore. The problem is that while we’re tracing to the System.Diagnostic subsystem, that is not hooked up to the tracing in the service running in Azure. We can fix that by passing the original trace writer (which can trace within Azure) to our trace writer implementation:

public class MyTraceWriter : ITraceWriter
{
ITraceWriter original;
public MyTraceWriter(ITraceWriter original)
{
this.original = original;
}
public void Trace(HttpRequestMessage request, string category, TraceLevel level, Action<TraceRecord> traceAction)
{
if (this.original != null)
{
this.original.Trace(request, category, level, traceAction);
}
var record = new TraceRecord(request, category, level);
traceAction(record);
System.Diagnostics.Trace.WriteLine(string.Format("{0} - {1} - {2} - {3}",
record.Level, record.Message, record.Category, record.Timestamp.ToString("ddd MMM dd yyyy, HH:mm:ss tt")));
}
}

And when creating our trace writer we can pass the original writer if the service is running in Azure (which you can access via the extension method GetIsHosted – you’ll need to add a "using System.Web.Http" statement if you don’t have already to see that method).

public static class WebApiConfig
{
public static void Register()
{
var config = ServiceConfig.Initialize(new ConfigBuilder());
ITraceWriter originalTraceWriter = null;
if (config.GetIsHosted())
{
originalTraceWriter = (ITraceWriter)config.Services.GetService(typeof(ITraceWriter));
}
config.Services.Replace(typeof(ITraceWriter), new MyTraceWriter(originalTraceWriter));
}
}

Notice that for the case of a better local logging you could also only replace the trace writer if the service was running locally (i.e., if it was not hosted). But that organization will be useful in the next section.

Changing logs destination

Looking at the traces in the portal is fine during development, but as the service goes into production and if your mobile application is successful, you can expect thousands of traces being generated, and going through them via the portal isn’t the ideal way to analyze your logs. But since we can own completely the logging implementation, nothing prevents us from redirecting the logs to some external source – for example, table storage, where you can fetch and analyze them easier with several of the existing tools. Let’s change our trace listener implementation to send the logs to a table in Azure Storage if the service is running in the cloud.

public class MyTraceWriter : ITraceWriter
{
ITraceWriter original;
string mobileServiceName;
string storageConnectionString;
public MyTraceWriter(ITraceWriter original, string mobileServiceName, string storageConnectionString)
{
this.original = original;
this.mobileServiceName = mobileServiceName;
this.storageConnectionString = storageConnectionString;
}
public void Trace(HttpRequestMessage request, string category, TraceLevel level, Action<TraceRecord> traceAction)
{
var record = new TraceRecord(request, category, level);
traceAction(record);
if (this.original == null)
{
// Running locally
System.Diagnostics.Trace.WriteLine(string.Format("{0} - {1} - {2} - {3}",
record.Level, record.Message, record.Category, record.Timestamp.ToString("ddd MMM dd yyyy, HH:mm:ss tt")));
return;
}
this.original.Trace(request, category, level, traceAction);
TraceToTableStorage(record);
}
private void TraceToTableStorage(TraceRecord record)
{
CloudStorageAccount storageAccount = CloudStorageAccount.Parse(this.storageConnectionString);
CloudTableClient tableClient = storageAccount.CreateCloudTableClient();
CloudTable table = tableClient.GetTableReference("mylogs");
table.CreateIfNotExists();
TableOperation operation = TableOperation.Insert(new TableTraceRecord(mobileServiceName, record));
table.Execute(operation);
}
}

You’ll need to add a reference to the “Windows Azure Storage” package if you haven’t done it yet to be able to use the classes shown in the code above. The TableTraceRecord class is defined as a subclass of TableEntity, which is required to insert items into the tables. In this example I’m using the timestamp as the row key to make it easier to sort based on the trace order (and adding a random set of characters to disambiguate in case multiple trace requests come at the exact same instant).

public class TableTraceRecord : TableEntity
{
const string DateTimeFormat = "yyyy-MM-dd'T'HH:mm:ss.fffffff'Z'";
public string Message { get; set; }
public string Category { get; set; }
public string Level { get; set; }
public TableTraceRecord(string mobileServiceName, TraceRecord traceRecord)
: base(partitionKey: mobileServiceName, rowKey: CreateRowKey(traceRecord.Timestamp))
{
this.Category = traceRecord.Category;
this.Level = traceRecord.Level.ToString();
this.Message = traceRecord.Message;
}
private static string CreateRowKey(DateTime dateTime)
{
string disambiguator = Guid.NewGuid().ToString("N").Substring(0, 8); // in case two entries have same timestamp
return string.Format("{0}-{1}",
dateTime.ToUniversalTime().ToString(DateTimeFormat, CultureInfo.InvariantCulture),
disambiguator);
}
}

We now need to pass the connection string and mobile service name to the trace writer class. The recommended way to store the connection string is via the app settings, so I’ll add the connection string fro my account there:

And on the Register method we retrieve the values we need from the application settings.

public static class WebApiConfig
{
public static void Register()
{
var config = ServiceConfig.Initialize(new ConfigBuilder());
ITraceWriter originalTraceWriter = null;
if (config.GetIsHosted())
{
originalTraceWriter = (ITraceWriter)config.Services.GetService(typeof(ITraceWriter));
}
var mobileServiceName = ConfigurationManager.AppSettings[ServiceSettingsKeys.ServiceName];
var storageConnectionString = ConfigurationManager.AppSettings["MyTableStorageConnString"];
var myTraceWriter = new MyTraceWriter(originalTraceWriter, mobileServiceName, storageConnectionString);
config.Services.Replace(typeof(ITraceWriter), myTraceWriter);
config.SetIsHosted(true);
}
}

Now when the trace is executed, it will write to the table storage.

More logging please!

So far we’re looking at how to look at the logs which our application writes out. But the .NET backend also exposes other kinds of logs which you can see as well. When we’re initializing the service configuration, we can pass a set of configuration options. One of them is the list of trace categories which are excluded from the traces. By default, internal traces are excluded, but we can remove those by clearing the ExcludedTraceCategories list in the config options passed to the initializer, as shown below.

public static class WebApiConfig
{
public static void Register()
{
var configOptions = new ConfigOptions();
configOptions.ExcludedTraceCategories.Clear();
var configBuilder = new ConfigBuilder(configOptions);
var config = ServiceConfig.Initialize(configBuilder);
// ...
}
}

Try it out – you’ll see more information about the inner workings of the backend. Definitely some information that the majority of the users won’t need, but a good way to get a better view of what’s happening behind the scenes.

Another thing which we can do in the traces is change the log level. By default only traces with level of Info and higher are logged. If you use Services.Log.Debug in one of your controllers that log will not be written to the logs. You can use the MinimumTraceLevel property in the ConfigOptions object to change what will show up in the logs.

public static class WebApiConfig
{
public static void Register()
{
var configOptions = new ConfigOptions();
configOptions.MinimumTraceLevel = TraceLevel.Debug;
configOptions.ExcludedTraceCategories.Clear();
var configBuilder = new ConfigBuilder(configOptions);
var config = ServiceConfig.Initialize(configBuilder);
// ...
}
}

With this change, now all traces, from debug to error, are written out to the logs.

Wrapping up

I hope this post will help you understand how to better use the logging subsystems in the .NET backend for mobile services. As usual, feel free to submit questions or comments to this post, the MSDN forums or contact us via Twitter @AzureMobile.