Blog.Amit Apple

Blog by Amit Apple

Azure Website Logging - Tips and Tools

Using Azure Websites includes many benefits that come just out of the box, you just need to know that they're there and how to use them properly. Logging is one of those benefits that integrate seamlessly to your Azure website.

Reference to the official Azure Websites Logging Document

In this post I'll show ways on maximizing the Azure Websites logging experience.

Log Types

These are the different log types you can get for your Azure website:

  • Web Server Logging - Also known as http logs or iis logs, this will log all requests to your website in W3C Extended Log File Format.

  • Detailed Error Messages - Detailed version of the html files produced when your website responds with an error message. This is good to enable for debugging some error responses in your website. It is stored in the website's file system.

  • Failed Request Tracing - Also known as FREB, here you can get lots of information from IIS through its different stacks for each failing request. Note that these log files are also stored in the website's file system.

    You can get some more information about FREB here.

  • Eventlog.xml - You may see this file sometimes under your LogFiles directory of your website (d:\home\LogFiles). This file contains ETW designated events, usually it is generated and populated with errors of some crash that occurred.

  • Kudu Traces - In your website's file system under d:\home\LogFiles\Git\trace (The "Git" part is a misnomer for historic reasons) you can find the traces file for Kudu which drives some of the developer experience features of Azure Websites like: git deployment and WebJobs.

  • Application Logs - See detailed information on application logs in the next section.

Log files stored in the website's file system will show up under d:\home\LogFiles.


Setting different logs in the Azure portal

Setting different logs in the Azure portal


Application Logs

These are the logs coming from your Application/Service/Website/WebJob.

Application Logs for Websites

If you're using ASP.NET it's simple to write application logs, just use the Trace class, for example:

        Trace.WriteLine("Message"); // Write a verbose message
        Trace.TraceInformation("Message"); // Write an information message
        Trace.TraceWarning("Message");
        Trace.TraceError("Message");

In the Azure portal you can direct different verbosity levels to different targets (at the same time). The targets are: file system, Azure table storage and Azure blob storage.

For example you can have all Information level (and up including Warning and Error) logs go to Azure table storage and all logs (including Verbose and up) go to blob storage.


Setting application logs in the Azure portal

Setting application logs in the Azure portal


For node.js websites the way to write application logs is by writing to the console using console.log('message') and console.error('message') which goes to Information/Error level log entries. Currently the only supported target for the log files for node.js is the file system.

Other web site types like php and python are not supported for the application logs feature.

Application Logs for WebJobs

Triggered (Scheduled/On Demand)

Whatever is written to console output and console error will go to a log file for the specific triggered webjob run. You can see it on the WebJobs dashboard but the file itself is located under d:\home\data\jobs\triggered\{jobname}\{jobrunid}.

Continuous

Whatever is written to console output and console error will go to the application logs as log entries with log level Information/Error. The first 100 log entries when the continuous WebJob starts will also show up in the continuous WebJob log file that is available on the WebJobs dashboard.

The file itself is under d:\home\data\jobs\continuous\{jobname}.

.NET WebJobs

If you're using .NET console application as your WebJob, you can follow the same guideline as for an ASP.NET website. Once you use the Trace class, your traces are handled as application logs (including triggered WebJobs).

Application Logs Fields

Here is the list of fields each application log entry consists of:

  • Application Name - The website name.
  • Date Time
  • Level - Log level.
  • Event Id
  • Instance Id - A unique id for the VM running the website where the log entry came from.
  • Process Id
  • Thread Id
  • Activity Id - The current (at the time of the log) activity id.
  • Message

There are a couple a differences between logs stored in file system, table storage and blob storage:

Blob storage - Stored as a csv file with the following structure: Timestamp(DateTime), Level, ApplicationName, InstanceID, Timestamp(Ticks), EventID, ProcessID, ThreadID, Message, ActivityId

Table storage - Each log entry is stored as a table entity, with a Partition Key that is the log's date (formatted as "YYYYMMDDHH") and a Row Key which is an ordered GUID to help get the logs in the same order as they happened.

File system - Has a subset of the fields mentioned in the following format: {Date} PID[{Process ID}] {Event Type} {Message}

Using the Activity Id

The activity id field can be very powerful. It can help you correlate all log entries which came from a single request.

The easiest way to use it is to enable Failed Request Tracing on the Azure portal. This will have a side-effect of setting an activity id for each request your website receives where the activity id will propagate to all your application logs.

The actual proper way to set the activity id would have been using this code in the global.asax.cs file:

public class MvcApplication : System.Web.HttpApplication
{
    protected void Application_BeginRequest()
    {
        System.Diagnostics.Trace.CorrelationManager.ActivityId = Guid.NewGuid();
    }
}

But since ASP.NET is doing some funky things, the activity id may get lost (become empty) when using async operations.

Note that the same activity id concept would work for .NET WebJobs. For that you should use: System.Diagnostics.Trace.CorrelationManager.ActivityId = Guid.NewGuid(); before an operation that requires an activity id.

Retention Policies

File system

Log files will have some retention policy for each type:

  • Web server logs have a maximum size per log file and per sum of all log files (which is configurable in the Azure portal).
  • Similar for application logs, each log file can get up to 128 KB and the total size of all log files will go up to 1 MB after that old files are removed.
  • Detailed error messages and FREB have a maximum amount of files (each file consists of a single error).

Blob storage

Web server logs and application logs stored in blob storage can be configured with a retention policy for deleting log files older than X days.

Log Browser Site Extension

One more cool feature that Azure Websites release recently is the Azure Site Extensions.

Azure site extensions is basically a gallery of extensions to your Azure website that can originate from Microsoft or from the community. These site extensions can be useful utilities for your website administration.

One of those site extensions is called Azure Website Log Browser.

The Log Browser makes it super easy for you to access all of your Azure website logs described here.

Features

  • Provides first-class links to the different log directories that you have if you have them.
  • Show logs stored in your website's file system.
  • Show logs stored in your blob storage (based on the current configuration for http logs or application logs).
  • View the log files in the browser (with word highlighting capability) or download them for offline viewing.
  • For application logs stored in Azure table storage it has a nice UI for showing those too.

The tool itself should be self-explanatory, just install and start using it.

Here are some screen-shots:


Install the Log Browser from the new Azure Portal

Install the Log Browser from the new Azure Portal


Main page


View a log file


View log entries from table storage


The Log Browser site extension is open source and is hosted on GitHub. You can use this repository to help you get started on your own site extension idea or to contribute to the Log Browser site extension.

Final Thoughts

Azure Websites has a very nice and powerful logging experience, together with the Log Browser you get an online dashboard and log viewing experience for free and with minimal effort.

Read more...

WebJobs Graceful Shutdown

Azure WebJobs are doing work and running some process you expect not to be interrupted but as in life not everything is as expected and sometimes there are interruptions which can stop your WebJob abruptly without notice aborting your process and maybe leaving your work in some bad state.

These interruptions could be due to: stopping your site, restarting your site, some configuration change to your site which causes your site to restart, Azure maintenance (version update for example) or even the VM simply crashing for some reason.

For these kind of interruptions (minus VM crash) there is a concept of a more "graceful" shutdown process for a WebJob which can help you cleanup before your WebJob is forcefully stopped.

As usual with WebJobs this concept is a bit different for continuous and triggered WebJobs, let's discuss on both.

Graceful Shutdown for Continuous WebJobs

For continuous WebJobs Azure will notify the WebJob running process when it is about to stop it, then it'll wait a configurable amount of time (which is 5 seconds by default) after which if the process did not exit quietly it will close it.

The way Azure notifies the process it's about to be stopped is by placing (creating) a file at a path that is passed as an environment variable called WEBJOBS_SHUTDOWN_FILE.

Any WebJob that wants to listen on the shutdown notification will actually have to check for the presence of the file (using simple File.Exists function or using a FileSystemWatcher in whatever script language you use), when it shows up the WebJob will need to start cleaning up and break it's current loop where preferably it'll exit properly and Azure will continue the shutdown (of the site) process.

Here's an example using C#:

public class Program
{
    private static bool _running = true;
    private static string _shutdownFile;

    private static void Main(string[] args)
    {
        // Get the shutdown file path from the environment
        _shutdownFile = Environment.GetEnvironmentVariable("WEBJOBS_SHUTDOWN_FILE");

        // Setup a file system watcher on that file's directory to know when the file is created
        var fileSystemWatcher = new FileSystemWatcher(Path.GetDirectoryName(_shutdownFile));
        fileSystemWatcher.Created += OnChanged;
        fileSystemWatcher.Changed += OnChanged;
        fileSystemWatcher.NotifyFilter = NotifyFilters.CreationTime | NotifyFilters.FileName | NotifyFilters.LastWrite;
        fileSystemWatcher.IncludeSubdirectories = false;
        fileSystemWatcher.EnableRaisingEvents = true;

        // Run as long as we didn't get a shutdown notification
        while (_running)
        {
            // Here is my actual work
            Console.WriteLine("Running and waiting " + DateTime.UtcNow);
            Thread.Sleep(1000);
        }

        Console.WriteLine("Stopped " + DateTime.UtcNow);
    }

    private static void OnChanged(object sender, FileSystemEventArgs e)
    {
        if (e.FullPath.IndexOf(Path.GetFileName(_shutdownFile), StringComparison.OrdinalIgnoreCase) >= 0)
        {
            // Found the file mark this WebJob as finished
            _running = false;
        }
    }
}

Graceful Shutdown for Triggered WebJobs

For triggered WebJobs there is no shutdown notification but there is a graceful period (30 seconds by default) where the WebJob will not be forcefully shutdown immediately, the graceful period is configurable.

Updating the graceful period

The graceful period can be updated for any WebJob, the way to do it is to create a file called settings.job with the following content: { "stopping_wait_time": 60 }

The time is specified in seconds

This file is representing a json object of your WebJob's setting, for now the only meaningful settings are stopping_wait_time and is_singleton (for continuous WebJobs to set them to run only on a single instance).

If you have any questions on this topic feel free to leave comments.

Read more...

Getting notified when your Azure triggered WebJobs completes

Microsoft Azure WebJobs are awesome, and now a little bit more... I'm going to show you how you can setup a notification whenever your triggered (on-demand or scheduled) WebJobs completes.

The notification part is done by integration between Azure and Zapier which provides many different notification types such as: email, phone call, SMS, Facebook post and more, for this post I'll use a phone call but it is very easy to use any of them.

NOTE: In a previous post I explained about Zapier and how you can have a notification when your Azure Website deployment completes, this is very similar only with a triggered WebJob.

Let's do it:

Prerequisites

  • An Azure Website with at least 1 triggered (on-demand or scheduled) WebJob (although you can add it later).

  • Sign up to Zapier

  • Have both the Zapier and Azure portal open

Steps

  • Go to Zapier and create a new zap (Make a Zap!).

  • For the trigger service select Azure Web Sites.

  • For the trigger select New Triggered WebJob Run.

  • For the action, we'll select Phone and Call Phone for this sample but any can be selected.

  • Click Continue

  • We need to connect to our Azure Web Site hosting our triggered WebJob, for this we need one piece of information from the Azure portal.

This is the tricky part:

  • If your website has continuous deployment setup --> in the Azure portal go to your website, click on the CONFIGURE tab and under the git section copy the url which is under the DEPLOYMENT TRIGGER URL.

  • If you don't have continuous deployment, you can author this url yourself, it is: https://{userName}:{password}@{siteName}.scm.azurewebsites.net/deploy where you get the {userName} and {password} from your site's publishing profile.

  • Go back to the Zapier site and paste this url to the Deployment URL textbox, enter a name for this website account and click continue.

  • Now create your phone account by providing the phone number and verifying it.

  • At this point you can filter when you actually want to initiate the action, for example only when the WebJob run fails or only for a specific WebJob (by name), for now we keep this empty as we want to be notified on all WebJobs runs, click continue.

  • Next you specify the content of the message, it can be static and dynamic using the WebJob run result.

  • For example we'll use: Hello the WebJob named {{job_name}} has completed with status {{status}} and took {{duration}}, on the right you can use the "Insert fields" button to add other interesting dynamic fields.

  • You can even choose the voice of the caller (Man/Woman), I'll let you pick this one.

  • Continue

  • Test this Zap lets you test your zap by getting previous WebJob runs and doing the selected action on them, click the button and then you can skip the step or test your Zap.

  • Name and turn this Zap on

  • Now go to your Azure portal, run your WebJob, wait for it to complete and wait for the call :)

Get more help about Windows Azure Web Sites on Zapier.

Read more...