Jack Freelander's Blog

Advanced Blogging about Advanced Logging

JackFree — Tue, 31 Mar 2009 07:59:00 GMT

Advanced Blogging about Advanced Logging

One of the many new IIS 7 modules announced at MIX about 2 weeks ago is the IIS Advanced Logging Module, developed by the IIS Media Team. Why is it called "Advanced" Logging? Well, to make a short story long, the new logging feature went through a lot of names, including IIS Media Logging, Custom Logging, and more contentious & quirky names proposed by various team members to varying degrees of frivolity and political correctness, like "Brack" Logging (a combination of Brian/Jack, the primary developers who have been working on it), "Super Fly Logging", "Cupcake Logging" (based on an affectionate, well-meaning yet silly nickname for a certain coworker), and countless others that would have been instantly (and understandably) rejected by Marketing had they even made it that far. In the end we settled on "Advanced Logging", which, while somewhat sterile, is certainly more professional and marketable, and does convey the notion of a richer feature set, and one that is not exclusive to media.

A quick assessment of the typical logging functionality in most web servers today reveals a modest but respectable offering that includes per-website logging, with a choice of log policy (when to roll a log file) and a reasonable (but fixed) set of fields to choose from. This has served the web well for some time now, but there has also been a growing need to accommodate more complex web and media scenarios that demand a lot of flexibility and control. These scenarios may require custom log fields, real-time access to data, greater control over what gets logged and when, extensibility for new and different sources of data, the ability to consolidate log data coming from clients and correlating it to server data, the option of sharing data from various sources to store in multiple logs, capturing system-state information, inclusion in logs of canceled/aborted requests, and even logging multiple times per request. That's a big feature-set to tackle - let's go into detail into how the IIS Advanced Logging module (hereafter referred to as ALM) meets these demands, and others.

Custom Log Fields

One of the first things we tackled and one of the most common requests has been to allow custom log fields to be included in standard logs. Consider a standard W3C style log today:

#Version: 1.0
#Date: 20-Mar-2008 12:34:56
#Fields: time cs-method cs-uri
12:53:23 GET /abc.html
12:55:16 GET /subfolder/oprah.html
12:55:34 GET /subfolder/AtTheBuffet.jpg
12:57:11 GET /dietPlan.xml

There’s not a lot of flexibility in the fields you can log. What if you wanted to include the last-modified time of the file that was downloaded? Or a custom request header set by your client application? Previously you’d have to try to lump this information into the uri query string (cs-uri-query), which can work, but isn’t very clean and doesn’t scale too well. With the ALM you can define as many custom log fields as you want. We support retrieving values from request and response headers, from server variables (an IIS construct), in addition to standard built-in types like time-taken, bytes-sent, etc. Furthermore, the name used to identify origin of the data (the request-header name, or the event item name coming from another IIS module [more on this later], etc) does not have to be the same as the log header name that is stored in the final file. This level of abstraction allows you to use human-readable, friendly names for what gets stored in the file. So even if the source of your data is a cryptic name like “CModPlylstSessionStateGuid” [totally made up] you can log it as “Playlist Session” or whatever you like. Have as many log fields as you want, name them how you choose, and thanks to IIS’s powerful configuration system, the custom fields you define are available at lower configuration path nodes (so a custom log field that you define on a site is available at that site’s virtual directories, subfolders, etc, and a field defined at the server level is visible everywhere).

Here’s a short example from applicationHost.config that defines a custom log field called “ManifestUrl”. (Note that you don’t have to edit appHost manually, we’ve got a nice UI to use too ;)

<field id="ManifestURL" logHeaderName="ManifestURL" sourceName="clientManifestUrl" sourceType="module" category="Client Fields" description="The URL to the manifest for the content played" />

The id attribute uniquely identifies this log field so that many log definitions can reference the same field.
The logHeaderName attribute defines the actual text that will be included in the file as the log header.
The sourceName tells ALM how to identify the incoming data.
The sourceType tells ALM where the data is coming from. (A source type of “module”, for example, tells ALM that another IIS module will be providing this data).

Category and description are used by the ALM Server UI to help administrators easily indentify and categorize log fields to make them easier to find.

The various options in defining custom logs will become clearer as (and if) you read on – the main point I reemphasize is that you are free to define as many custom log fields as you want that will be treated as first class citizens in the log files produced!

Real-time access to data

Logging data is typically not available instantly – you may have to wait some time for cached (in-memory) log data to be flushed to disk, and long-running requests for large files will (today) not offer you access to the log data until the entire response has been sent. Further, you are typically tied to the file as the one and only output of the data. Not anymore! ALM publishes an event (based on IIS’s core tracing subsystem which is in turn based on ETW) that allows any IIS module to hook into ALM to receive notifications just before a log entry is enqueued (saved in memory but not yet written to disk). This means that we do all the heavy-lifting of aggregating log data from different sources throughout the lifetime of a request/response, ordering and validating that data against the log definition, and then providing a consolidated complete view in real-time. What does all this fancy verbiage mean? It means you can easily write a custom module that listens to these events and offers real-time access to log data, such as an analytics application. You could also publish the log data to another website or archive it in a database the instant it is available.

Greater control over what gets logged

Presently log data is a pretty simple entity – it’s either there or it’s not. You get a dash if the data is not there, and that’s about it. Not very exciting.

ALM might not be so exciting that your jaw drops in shock while reading this (no small feat for a blog article about logging), but it does offer more control. Specifically, you can mark individual fields as “required” so that a log entry will never be written unless it contains a value for that field. For example, if you have a client session Id that is sent as a cookie or a request header, you can mark it as a required field in your log definition so that requests that are missing this data will not be included. This is very useful in minimizing the data logged by verifying early on that fields critical to log parsing are always present.

Additionally, ALM allows you to specify a default value for a log field if it is absent, offering you a little more flexibility than just “-“. We also expose control over the text that is used for delimiting log fields, for new-lines and you can even shut off writing log headers to disk. This allows you to produce a simple flat-file (comma-separated or whatever you choose) to easily import into Excel, for example. The maximum size of a log field can also be customized, providing greater control of overall log growth, allowing certain fields to be quite large and restricting others to be quite small. It’s all configurable on a per-log basis!

Extensibility for new and different sources of data

IIS’s Advanced Logging Module has built-in support for retrieving log field values from a number of sources. It inherently understands request and response headers. These values can be included in any log, and, just like any other log field, can be marked required or given a max size. In addition to request/response headers, you can also log any server variable, whether populated by IIS or by a custom module. Have your own custom module for IIS 7? It’s a cinch to make your own fields available to be logged. It’s as simple as a call to RaiseTraceEvent .

Built-in support for client-provided log data

One of the most common sources of log data is (of course) not the server itself, but in fact the clients who connect to it. The Advanced Logging Module comes with a client handler that is used to accept client POST data in an XML format and publish it to any logs that wish to log the fields provided. The client handler is actually a relatively simple, straightforward and small piece of code. It would be very easy to write your own client handler to accept binary POST data, or to parse values which are part of a query string, and then publish those values for use by any custom log definition. Hopefully we’ll get some sample code online soon that shows just how easy it is to pass along data from any incoming format to the Advanced Logging Module.

Sharing data from various sources to store in multiple logs

Another very handy feature of our Advanced Logging Module is that it is naturally integrated with IIS’s hierarchical configuration system. Instead of logging every request that reaches a site, you can configure a log on an application, a virtual directory, a folder or even a file. This allows almost unlimited flexibility in logging just the requests of interest. It allows you to exclude uninteresting logs, say for “.jpg” files, and just log requests for HTML or ASPX pages.

You may be wondering how this all works – what is the logic behind getting data from its source to its destination? The answer is both simple and complex (of course). What makes Advanced Logging so useful is that it employs a very generic and extensible model for aggregating log data. There is a deliberately loose coupling of the source of log data and its destination. This means that the providers of log data need only give their fields a unique name, and don’t need to know anything about how many logs are configured, or for which sites, or even whether logging is enabled at all. The Advanced Logging Module does the work of determining which logs are eligible to receive data, all based on the configuration path of the request and the configuration path of the log definitions.

An example is in order. Let’s say you issue a request to your server for http://www.myserver.com/subfolder/a/b/test.html. Logs defined at the following configuration levels would have an opportunity to create a log entry for this request:

/               (site level)
/a              (the “a” subfolder, or virtual directory)
/a/b            (the “b” subfolder)
/a/b/test.html  (just the ‘test.html’ file)

However, a request to http://www.myserver.com/a would just reach the logs defined at the site level (“/”) and the “/a” subfolder (or virtual directory).

You’re not limited to one log at any particular configuration level, so it’s easy and useful to partition log data based on its final destination or purpose. There’s no restriction on which fields can go in which logs, so you can configure separate logs with no overlapping data, or share the same fields between logs at any level.

Capturing system-state information

Another interesting option that IIS Advanced Logging offers is the ability to include system state information in the logs themselves. We offer built in support for performance counters, allowing administrators to capture network load or CPU utilization at the time a request is logged. This can be very handy in diagnosing server issues such as increased latency, excessive memory consumption, or heavy disk I/O, by correlating system state with the requests that influence it.

Inclusion in logs of canceled/aborted requests

Previously it was not possible to capture log data for requests that were aborted or canceled. No so anymore – IIS Advanced Logging is implemented in such a way as to ensure that log entries can be generated for all requests, whether canceled, aborted, timed-out, etc.

Logging multiple times per request

The current paradigm for web server logging is that one line in a log file corresponds directly to one HTTP request. That’s fine most of the time, but it doesn’t offer any information about long-running requests which may take minutes or hours to complete. With IIS Advanced Logging you can configure a log so that each relevant trace event (that occurs within the lifetime of a request/response) generates a new line in the log file. These trace events can be raised by other IIS modules, such as IIS’s Bit Rate Throttling Module, or by any custom module. This can be very useful in debugging problems with long-running requests or for providing real-time data about the progress of a response. Because IIS Advanced Logging allows you to define any number of logs at a given configuration level, you can easily create a separate log for interim data that utilizes this behavior while maintaining another log that just stores per-request data.

Fine tuning of archive behavior

Another area of customizability that IIS Advanced Logging offers is control over how data is archived. Each log can specify its own archive-to-disk interval so that time-sensitive crucial data can be written very frequently, while other logs may choose to leverage the improved performance achieved by caching more data in memory between disk writes. Alternatively, for each log you could specify a maximum size (in KB) of log data to keep in memory before flushing to disk. Both of these settings (archiveToDiskInterval and inMemoryQueueSizeKB respectively) have reasonable defaults and need not be modified in order for archiving to happen regularly and reliably.

A rather low-level setting that can also be controlled on a per-log basis is the blocking queue size. By nature the Advanced Logging Module does the absolute minimum amount of processing on the thread that is servicing a request – it just saves off a copy of the relevant data. The actual disk I/O occurs asynchronously on another thread. If you have mission-critical log data that mustn’t be lost then you can optionally set a “blocking queue size” which specifies the maximum amount of log data to be stored in memory before requests will actually block and wait for the data to be archived.

If you have your own destination for the log data, or are just using the eventing feature of Advanced Logging, you may wish to turn off disk-writing entirely – a valid and supported scenario. Just set writeLogDataToDisk=false in the configuration for your log.

IIS Advanced Logging also offers a number of options for how to manage your log files – basic log roll options include schedule-based (hourly/daily/weekly/monthly/never), file-size based, or by duration of the entries contained within the log. The files themselves are created with names that you control, and we currently support using environment variables in the file names.

Just as with IIS’s existing logging functionality you can choose to log as UTF-8, or the default codepage of the system (CP_ACP). Since there’s no way to know whether all log servers will be configured with the same codepage, it is recommended to log in UTF-8.

I realize that this is a lot of information, but hopefully some will find it useful and applicable. We've put a lot of time and effort into making IIS Advanced Logging a feature-rich, robust and reliable logging solution that goes above and beyond expectations. We're always glad to hear your suggestions and feedback!

Cool things are still to come - as IIS Advanced Logging continues to develop and mature keep an eye out for even greater filtering and formatting features, and a few other surprises!

Happy logging,

-Jack

Bit Rate Throttling for IIS7 & Connection Limit Groups

JackFree — Tue, 18 Mar 2008 21:58:00 GMT

The recent release of the Bit Rate Throttling Module for IIS provides some useful and compelling features for managing response rates for data and media files. One of the interesting features that is included is the notion of a connection limit group. While IIS (via HTTP.SYS) provides a mechanism for limiting the concurrent connections for an entire site (see Advanced Settings in the UI), our Bit Rate Throttling module goes a step further, allowing admins to define and configure their own connection limits, grouped according to file type (based on file extension) or mime-type (based on the content-type response header).

Connection limit groups take some explaining, and are more of an advanced feature, and as such are not exposed via the UI (at least not yet!). Taking a peek at applicationHost.config after installing BRT, you’ll see the following settings (note that I have pruned these to fit nicely in a painfully narrow blog window):

</fileExtensionRules>

</throttleSettings>

</connectionLimitGroups>

You'll notice that each file extension rule associates, by name, a connection limit group with it (e.g. connectionLimitGroup="VideoFiles"). Later on in applicationHost.config we see the definitions for a connection limit group, each of which has simply a unique name and a connection limit defined (zero implies no limit). This allows administrators to have very custom and granular control over which responses should have limits associated with them. A likely scenario would be when you don't want simultaneous downloads for large video files to monopolize your available throughput. By limiting the number of connections available for video files (be they .wmv or .flv or whatever) you can effect control over how much bandwidth is allocated for that particular group of connections. A connection limit as defined above specifies the maximum number of concurrent connections allowed. If the connectionLimit for a particular group were set to "10" and 10 clients were each downloading a file whose type belonged to the same group, the 11th client (requesting the same type of file) would receive a 503 Response from the server.

There is a deliberate separation / independence between a throttling rule and a connection limit group. Both file extension rules and mime type rules (not seen in the above config) can specify this attribute. In all likelihood you'd need only a few connection limit groups, but their number, naming and limits are completely configurable – in theory each throttling rule could have its own. The example included with the default install illustrates a scenario where you wish to manage the # of connections based on whether a response originates from an audio or video file. The concept applies equally well to data rules, where you might want to limit the # of simultaneous downloads of large files. Presently there is no way to group and to limit responses which don't fall into one of the rules specified in the configuration (how would we know which connection limit group to add it to?).

The connectionLimitGroup attribute is optional, as is the connectionLimitGroups collection, so removing them from your config file won't cause an error. However, the UI does not yet support creating or modifying these rules. It may be handy to leave them in, so that should they become appealing in the future you won't have to dig through the schema to recall the exact syntax.

Also interesting is that a connection limit group may specify not only a "connectionLimit" but also a "targetThroughputRateKbps"! This means that responses belonging to a certain connection limit group can be throttled dynamically to stay at a target transfer rate (cumulative value). The idea here is to throttle only when necessary, and to maintain as best as possible a target throughput (hence the name ;). Note that by using a targetThroughputRateKbps (also referred to as "dynamic throttling") the Bit Rate Throttling module will never reduce a response's throttle rate below the value determined by the configuration settings. The targetThroughputRateKbps attribute is only ever used to *increase* throttle rates to take advantage of surplus bandwidth, to serve responses more quickly when conditions allow. It is a best-effort on-the-fly calculation that can and will fluctuate with load (remember too that the inital burts [specified by initialBufferTimeSeconds for media rules or initialSendSizeKBytes for data rules] are sent unthrottled!). It is not a hard-limit or maximum.

What happens if you specify a targetThroughputRateKbps for both the site and for a connection limit group? In this case the BRT module will respect the lower of the two limits.

Happy Throttling!

/jack

For more information on this release of Bit Rate Throttling for IIS 7.0, see:

http://blogs.iis.net/vsood/archive/2008/03/15/bit-rate-throttling-is-now-released.aspx

http://weblogs.asp.net/scottgu/archive/2008/03/18/iis-7-0-bit-rate-throttling-module-released.aspx

GET /jackfree.bio HTTP/1.1

JackFree — Tue, 18 Mar 2008 21:40:00 GMT

I couldn't think of a geekier title, so this one will have to do! I'm Jack Freelander, a relatively new developer on the IIS Media team, having joined IIS in the fall of last year. In the past I have worked in Exchange (Outlook Web Access and HTTP-DAV) and later Microsoft TV. So far the people and the work here in IIS are a blast, though I have to wonder about my location at the opposite end of the hallway from most of the devs, just a few doors down from BillS. At first I figured that Bill must also be a rabid Tori Amos fan, but I've yet to find him rocking out to any Tori songs when I walk by. So I do my part to contribute to the noise and racket down here, which at the moment I seem to be the sole source of!

Presently I am working on the Bit Rate Throttling module for IIS7 that we just shipped, and will be working in other media-related areas in the near future. When not at work I divide my time between playing with my golden retrieviers, cleaning up after my golden retrievers, cooking, baking, getting speeding tickets, going to concerts, movies, etc. Currently I am trying to grow tomatoes, basil, cilantro and strawberries in my office, though I'm not sure how well my office redecorating plans will be received when the grow light & sprinkler system are finally installed, and the crickets move in.

I'm beginning to understand why I'm at this end of the hall. ;)

/jack