Viewing assembly binding logs using fuslogvw.exe

Sometimes it’s very useful analyze how an application binds to referenced assemblies but this process is fairly hidden from us. However, Microsoft has given us a way to look into this process via the fuslogvw tool. This tool is not overly documented so this post describes how to install it on a computer that has neither Visual Studio nor the Windows SDK installed, such as a server.

Follow these steps:

Copy the following files from a computer with Visual Studio or the Windows SDK installed:

  • "C:\Program Files (x86)\Microsoft SDKs\Windows\v7.0A\Bin\FUSLOGVW.exe"
  • "C:\Program Files (x86)\Microsoft SDKs\Windows\v7.0A\Bin\NETFX 4.0 Tools\1033\flogvwrc.dll"

Put them into a folder on the target computer.

Create logging folder, e.g. c:\fuslog

Start FUSLOGVW.exe. Update the following settings:

  • Log all binds to disk
  • Enable Custom log path
  • Custom log path = c:\fuslog\

Finally, enable assembly binding logging in the registry by setting the HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Fusion\ForceLog value to 1.

Click Refresh in FUSLOGVW.exe and behold! A list of assembly binding events are displayed:

The individual events contain useful details:

/Emil

2014-11-10 Update: Removed the mention of editing the registry. I added that a little too quickly, fuslogvw.exe is supposed to do that stuff for us…

Retrieving the message count for MSMQ queues

Sometimes it can be useful to retrieve the number of messages in an MSMQ queue, for example for monitoring. However, it’s not immediately apparent how to do it if you google it, so here are my thoughts on the subject.

Other blog posts suggest iterating over messages (e.g. Counting Messages in an MSMQ MessageQueue from C#) or doing it using WMI. WMI is the best alternative in my opinion and if you want a quick way of doing it then PowerShell is the easiest:

$queues = Get-WmiObject Win32_PerfFormattedData_msmq_MSMQQueue
$queues | ft -property Name,MessagesInQueue

The result will be something similar to this:

Name                                                         MessagesInQueue
----                                                         ---------------
active714\private$\notify_queue$                                           0
active714\private$\deltagarloggservice\deltagarloggservi...                0
active714\private$\order_queue$                                            0
active714\private$\admin_queue$                                            0
Computer Queues                                                           27

This can also be done on remote machines:

$host = ...
$cred = get-credential
$queues = Get-WmiObject Win32_PerfFormattedData_msmq_MSMQQueue -computer $host -credential $cred
$queues | ft -property Name,MessagesInQueue

The Get-Credential Cmdlet will display a login dialog which is fine in interactive sessions but if you need to set the credentials in a non-interactive script, then the tip in this blog post might help: PowerShell – How to create a PSCredential object.

Retrieving message counts from code takes a little more coding but here’s an example in C# that searches for a given queue and returns its message count:

private static int GetMsmqMessageCount(string queuePath, string machine,
  string username, string password)
{
  var options = new ConnectionOptions
    {Username = username, Password = password};
  var path = string.Format(@"\\{0}\root\CIMv2", machine);
  var scope = new ManagementScope(path, options);
  scope.Connect();

  string queryString = 
    String.Format("SELECT * FROM Win32_PerfFormattedData_msmq_MSMQQueue WHERE Name = '{0}'",
	  queuePath);
  var query = new ObjectQuery(queryString);

  var searcher = new ManagementObjectSearcher(scope, query);

  IEnumerable<int> messageCountEnumerable = 
    from ManagementObject queue in searcher.Get()
    select (int) (UInt64) queue.GetPropertyValue("MessagesInQueue");

  return messageCountEnumerable.First();
}

This code also uses WMI but this time we do a query rather than enumerate all queues.

The above snippets has worked well for us so I felt it would be useful to post them here. Please leave a comment if you have issues with them or suggestions for improvement!

/Emil

Detecting unhandled errors in ASP.Net applications

For my own reference, here’s how to detect unhandled exceptions in Global.asax:

protected void Application_Error(object sender, EventArgs e)
{
  // Log error
  Exception ex = Server.GetLastError().GetBaseException();
  string msg = String.Format("Ohanterat fel!\r\nAdress: {0}\r\nFelmeddelande: {1}", Request.Url, ex.Message);
  LogHelper.Error(msg, ex);

  Server.ClearError();

  // Display simple error page
  Response.Write("Ett oväntat fel har inträffat...\r\n");
  Response.Write("<br/>\r\n<pre>\r\n");
  Response.Write(ex.ToString());
  Response.Write("<br/>\r\n</pre>\r\n");
  Response.End();
}

We mostly do it like this, if you have a better suggestion, please post a comment 🙂

/Emil

log4net configuration examples

Almost every application requires, or at least benefits greatly from, some kind of logging of events and errors. I suspect all of us have written custom code for logging to text files, database tables, the event log and other formats. We all know that we shouldn’t do this since there are several frameworks out there to help us, such as Microsoft’s own Tracing functionality, NLog and log4net. The obstacle to using them is often that it can be difficult to know how to configure them to work properly which is why this post will describe a set of configuration examples for log4net to make that framework do it’s magic.

For those of you new to log4net it’s a really useful package but somewhat difficult to configure, which is what I will try to help with in this post. I will not try to write a tutorial for it since others have already done so. Instead I will show a set of confiuration examples I personally find useful.

To use log4net, you need to add a reference to log4net.dll. Then a new section in the application’s config file must be added:

<section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />

Log4net logging is based on a provider-like design where each type of logging is done in a so called appender. There are appenders for file system files, databases, etc. and it’s in these appenders that log4net’s power lies.

To configure which appenders to use it easiest to use the root configuration element like this:

<log4net>
  ...
  <root>
    <level value="Debug"/>
    <appender-ref ref="ColoredConsoleAppender"/>
    <appender-ref ref="RollingFileAppender"/>
  </root>
</log4net>

We haven’t configured the referenced appenders yet, so that is the next step. The remainder of the post will be about some of the appenders that comes with log4net.

APPENDERS

Colored console appender
This appender is very useful for console applications and enables different types of events (debug, info, error, etc) to be displayed in different colors.

Here’s how to configure it:

    <appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
      <mapping>
        <level value="ERROR"/>
        <foreColor value="Red, HighIntensity"/>
      </mapping>
      <mapping>
        <level value="INFO"/>
        <foreColor value="White"/>
      </mapping>
      <mapping>
        <level value="DEBUG"/>
        <foreColor value="Green"/>
      </mapping>
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%-5level - %message%newline"/>
      </layout>
    </appender>

RollingFileAppender
This appender is used to write to a file while limiting the file size. When the maximum file size is reached then a new file is created which means that no log file will be unmanagably large.

    <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="d:\Logs\WorkflowAborter.log"/>
      <rollingStyle value="Size" />
      <appendToFile value="true"/>
      <maximumFileSize value="2000KB"/>
      <maxSizeRollBackups value="5"/>
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %identity %property{log4net:HostName}: %message%newline%exception"/>
      </layout>
    </appender>

The maxSizeRollBackups setting controls how many files will be created before the first one is deleted.

You can control when log4net creates a new file (rolls the file) by setting the rollingStyle attribute. It’s default setting is Composite which combines date and size limitations, whichever occurs first, to decide when a new file is created. The other possible values are Size and Date which are self-explanatory, and Once which creates a new log file for every time the application is executed.

Note however that, for some reason, the maxSizeRollBackups setting does not work when using Composite or Date so the number of files cannot be limited in when using those settings.

NetOutputDebugStringAppender

Logs events using the OutputDebugString Win32 API call whose output is shown in the Visual Studio output window. The appender is also useful in deployed applications since the output is captured by Mark Russinovich’s DebugView tool. (Just remember to enable “Capture Global Win32” setting of DebugView first, or else nothing will be displayed!)

    <appender name="NetOutputDebugStringAppender" type="log4net.Appender.OutputDebugStringAppender" >
      <layout type="log4net.Layout.PatternLayout">
        <param name="ConversionPattern" value="Butler: [%t] %-5p - %m%n" />
        <!--<conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />-->
      </layout>
    </appender>

NetTraceAppender

This appender logs to the Microsofts standard tracing framework in .Net. In Visual Studio, output is shown in the output window by default and for deployed applications it’s possible to configure the tracing to store events in different destinations. The appender could be useful if parts of an application is using the tracing framework and other parts are using log4net since it makes it possible to channel all events through the same framework (trace) but this is probably not used very often.

A more useful side effect is that many test runners (e.g. nUnit and ReSharper’s built-in test runner) captures trace calls and stores them with the test result making test failure analysis much easier.

Screen shot of ReSharper with log4net trace output

Configuration:

    <!-- Logga till .Net trace-listeners, t.ex- Outputfönstret i Visual Studio...-->
    <!-- Hamnar i output-fönstret om körs i VS, kan annars visas i DebugView -->
    <appender name="NetTraceAppender" type="log4net.Appender.TraceAppender, log4net">
      <layout type="log4net.Layout.PatternLayout,log4net">
        <param name="ConversionPattern" value="%d [%t] %-5p - %m%n" />
      </layout>
    </appender>

SmtpAppender
This appender is often overlooked, I have at least not seen many references to using it. It’s very useful for sending mail when an error occurs:

<appender name="SmtpAppender" type="log4net.Appender.SmtpAppender">
  <to value="foo@foobar.se, bar@foobar.se" />
  <from value="helpdesk@foobar.se" />
  <subject value="Error occured in MyApp" />
  <smtpHost value="smtp.foobar.se" />
  <bufferSize value="512" />
  <lossy value="true" />
  <evaluator type="log4net.Core.LevelEvaluator">
  	<threshold value="WARN"/>
  </evaluator>
  <layout type="log4net.Layout.PatternLayout">
  	<conversionPattern value="%n%d %-5level [%t] - %m" />
  </layout>
</appender>

Using configuration similar to the above, a mail such as the following is sent when a WARN or ERROR log occurs:

2011-02-04 03:00:06,958 INFO  [1] - ###############################################
2011-02-04 03:00:07,328 INFO  [1] - Startar...
2011-02-04 03:00:07,362 INFO  [1] - ###############################################
2011-02-04 03:00:07,429 INFO  [1] - Läser upp kursdeltagare 
2011-02-04 03:00:31,265 INFO  [1] - 6437 ska bearbetas.
2011-02-04 03:21:17,153 INFO  [1] - Timmar per vecka omräknade
2011-02-04 03:21:17,263 INFO  [1] - Tidsåtgång timmar per vecka: 00:21:09
2011-02-04 03:21:17,278 INFO  [1] - ----------------------------------------------------------------------------
2011-02-04 03:21:17,479 INFO  [1] - Läser upp kursdeltagare 
2011-02-04 03:22:08,793 INFO  [1] - 26532 ska bearbetas.
2011-02-04 04:10:28,050 ERROR [1] - Kunde inte ändra preliminärt slutdatum för timpott för sfi kd 24085 (Butler kd 83237)

Note that the 10 events prior to the ERROR event that triggered the mail is also included which makes error analysis very much easier.

MemoryAppender
This appender is useful for automated tests.

<appender name="unitTestMemoryAppender" type="log4net.Appender.MemoryAppender">
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date [%thread] %-5level %identity %property{log4net:HostName} %logger: %message%newline%exception"/>
  </layout>
</appender>

To create unit tests that checks whether logging is performed correctly, code such as this can be used:


using ActiveSolution.Lernia.Utils.Logging;
using log4net;
using log4net.Appender;
using log4net.Core;
using log4net.Repository.Hierarchy;
using NUnit.Framework;

namespace UtilsTests
{
    [TestFixture]
    public class LoggingTests
    {
        [SetUp]
        public void SetUp()
        {
            var appender = GetAppender();
            if (appender != null)   // Appender kommer vara null om inet loggats ännu.
            {
                appender.Clear();
            }
        }

        [Test]
        public void Logger_ErrorFormat_WithException_ShouldLogMessage()
        {
            // Arrange -----------------------------
            var ex = new ArgumentNullException("foo");

            // Act ---------------------------------
            LogHelper.ErrorFormat(ex, "Oväntat fel för id = {0}", 42);    // Call custom wrapper function for log4net

            // Assert ------------------------------
            var loggedEvents = GetLoggedEvents();
            Assert.That(loggedEvents.Length, Is.EqualTo(1));
            Assert.That(loggedEvents[0].RenderedMessage, Contains.Substring("Oväntat fel för id = 42"));
            Assert.That(loggedEvents[0].RenderedMessage, Contains.Substring("Value cannot be null"));
            Assert.That(loggedEvents[0].RenderedMessage, Contains.Substring("Parameter name: foo"));
        }

        private static LoggingEvent[] GetLoggedEvents()
        {
            MemoryAppender ma = GetAppender();
            return ma.GetEvents();
        }

        private static MemoryAppender GetAppender()
        {
            var h = LogManager.GetRepository() as Hierarchy;
            return h.Root.GetAppender("unitTestMemoryAppender") as MemoryAppender;
        }
    }
}

AdoAppender

The AdoAppender is used to store events in a database. Here’s a configuration example for using a stored procedure to store the events:

<appender name="ErrorHandlerAppender" type="log4net.Appender.AdoNetAppender">
  <filter type="log4net.Filter.LevelRangeFilter">
    <param name="LevelMin" value="WARN" />
  </filter>

  <bufferSize value="1" />
  <connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
  <connectionString value="Data Source=XXXXXXXXX;Initial Catalog=Errorhand;User ID=XXX;Password=XXX" />
  <commandType value="StoredProcedure" />
  <commandText value="ap_errorhandler_ins" />

  <parameter>
    <parameterName value="@APPLICATIONID" />
    <dbType value="String" />
    <size value="16"/>
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="Butler.EducationSI" />
    </layout>
  </parameter>

  <parameter>
    <parameterName value="@USERID" />
    <dbType value="String" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%identity" />
    </layout>
  </parameter>

  <parameter>
    <parameterName value="@SEVERITY" />
    <dbType value="String" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%level" />
    </layout>
  </parameter>

  <parameter>
    <parameterName value="@DESCRIPTION" />
    <dbType value="String" />
    <size value="4000"/>
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%message%newline%exception" />
    </layout>
  </parameter>

  <parameter>
    <parameterName value="@LOCAL_ADDR" />
    <dbType value="String" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%property{log4net:HostName}" />
    </layout>
  </parameter>
  <parameter>
    <parameterName value="@REMOTE_ADDR" />
    <dbType value="String" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%property{log4net:HostName}" />
    </layout>
  </parameter>
</appender>

The configuration segment for AdoAppenders tend to be rather long but the example is fairly self explaining. For more so called “conversionPattern fields” to use in parameters, look here. These are the same fields used in the other appenders to format the log strings. There’s quite a lot of interesting data that can be retrieved so make sure to have a look at the list.

FILTERING

Another powerful feature of log4net is the possibility of filtering. For example, if you’re referencing a 3rd party assembly such as NHibernate.dll that logs its events using log4net then those events can be configured separately like this:

<logger name="NHibernate">
  <level value="Error" />
</logger>

This tells log4net that DEBUG and INFO events from NHibernate should be ignored. The logger name is a string with the start of the logger names the filter should match. Other loggers can be configured in the same way and loggers that aren’t configured fall back to the root logger we defined in the beginning of this post.

TROUBLESHOOTING

Q: What do you do when having trouble with log4net logging?
A: You enable internal logging!

<appSettings>
  <add key="log4net.Internal.Debug" value="true"/>
</appSettings>

Note that these events are logged using the System.Diagnostics.Trace system so that may have to be configured as well. For more info about internal logging, see here.

That’s all for now. I’ll keep updating this post when I find more interesting settings.

/Emil

Assembly version redirection

Here’s how to redirect an assembly reference from one version (or version interval) to another:

  <runtime>
    <assemblyBinding xmlns="urn:schemas-microsoft-com:asm.v1">
      <dependentAssembly>
        <assemblyIdentity name="log4net" publicKeyToken="b32731d11ce58905" culture="neutral" />
        <bindingRedirect oldVersion="0.0.0.0-65535.65535.65535.65535" newVersion="1.2.10.0"/>
      </dependentAssembly>
    </assemblyBinding>
  </runtime>

Note that for this to work, put it as early in your config file as possible since it must occur before the assemblies are referenced. Also note that both the new and old version of the assembly must have the same public key token, if they don’t you’ll get a System.IO.FileNotFoundException during binding.

/Emil

Retrieving domain information in Powershell

Here’s how to retrieve the current domain:

[reflection.assembly]::loadwithpartialname("System.DirectoryServices")
[System.DirectoryServices.ActiveDirectory.Domain]::GetComputerDomain()

The result is a System.DirectoryServices.ActiveDirectory.Domain object:

Forest                  : i.activesolution.se
DomainControllers       : {ACTIVESERVER101.i.activesolution.se, ACTIVESERVER102.i.activesolution.se}
Children                : {}
DomainMode              : Windows2008R2Domain
Parent                  :
PdcRoleOwner            : ACTIVESERVER102.i.activesolution.se
RidRoleOwner            : ACTIVESERVER102.i.activesolution.se
InfrastructureRoleOwner : ACTIVESERVER102.i.activesolution.se
Name                    : i.activesolution.se

/Emil

Deciding whether an NHibernate object reference is a proxy

Have you ever had a need to decide whether an object reference to an NHibernate-mapped object is the real instantiated object or an NHibernate-generated proxy used for lazy loading? Here’s how to do it:

if (entityObject is NHibernate.Proxy.INHibernateProxy)
{
  ...
}

You don’t often need to make a distinction between proxies and the real objects but it may be useful when traversing object structures without triggering lazy-loading.

A related method is NHibernateUtil.IsInitialized which may come in handy in similar use cases as the above. It tells whether a proxy or persistent collection is initialized (i.e. loaded from the database) or not.

if (NHibernateUtil.IsInitialized(entityObject))
{
  ...
}

/Emil

Listing and resuming workflow instances

We recently had a need to list suspended Workflow Foundation 4 instances hosted in Windows Server AppFabric from code, and here’s how to do it:

SqlInstanceQueryProvider provider = new SqlInstanceQueryProvider();
var providerArgs = new NameValueCollection { { "connectionString", _instanceStoreConnectionString } };
provider.Initialize("WfInstanceProviderA", providerArgs);

InstanceQuery query = provider.CreateInstanceQuery();
var args = new InstanceQueryExecuteArgs { InstanceStatus = InstanceStatus.Suspended };

IAsyncResult asyncResult = query.BeginExecuteQuery(args, new TimeSpan(0, 0, 0, 30), null, null);
IEnumerable instances = query.EndExecuteQuery(asyncResult);

By the way, this requires a reference to Microsoft.ApplicationServer.StoreManagement.dll which is installed with AppFabric.

Resuming the workflow instances can be done like this:

SqlInstanceControlProvider provider = new SqlInstanceControlProvider();
var providerArgs = new NameValueCollection { { "connectionString", _instanceStoreConnectionString } };
provider.Initialize("WfInstanceProviderA", providerArgs);

InstanceControl control = provider.CreateInstanceControl();

foreach (InstanceInfo instanceInfo in instances)
{
    InstanceCommand cmd = new InstanceCommand
    {
        CommandType = CommandType.Resume,
        InstanceId = instanceInfo.InstanceId,
        ServiceIdentifier = instanceInfo.HostInfo.HostMetadata
    };

    // Not included in instanceInfo.HostInfo.HostMetadata...
    cmd.ServiceIdentifier["VirtualPath"] = 
         "/EducationWorkflowServices/AktivitetService.xamlx";

    IAsyncResult asyncResult = control.CommandSend.BeginSend(cmd,
        new TimeSpan(0, 0, 0, 30), null, null);
    control.CommandSend.EndSend(asyncResult);
}

AppFabric also has some great PowerShell cmdlets for administration that can be used for the same thing. Here are a few examples:

Import-Module ApplicationServer
Get-ASAppServiceInstance -status 'suspended'
Get-ASAppServiceInstance -status 'suspended' | Resume-ASAppServiceInstance
Get-ASAppServiceInstance -status 'suspended' | Stop-ASAppServiceInstance -Terminate
Get-ASAppServiceInstance -status 'suspended' | Remove-ASAppServiceInstance
Get-ASAppServiceInstance -InstanceId 95a25419-0d71-42c4-ab70-aa523ba603fc
Get-ASAppServiceInstance -InstanceId 95a25419-0d71-42c4-ab70-aa523ba603fc | Suspend-ASAppServiceInstance

Yet another alternative is to query the AppFabric persistance store database directly using SQL:

SELECT *
FROM [AppFabric_Application_Extensions].[System.Activities.DurableInstancing].[InstancesTable]
WHERE IsSuspended=1

Choose the alternative most to your liking 🙂

/Emil

The case of the slow for-loop

We recently had a problem with a page in an MVC application that was very slow, it took minutes before the server finished creating it. It turned out that it was this for-loop that caused the problem:

for (int i = 0; i < Model.Deltagare.Count(); i++)
{
  var deltagare = Model.Deltagare.ElementAt(i);
  ...
}

where Model.Deltagare is an IEnumerable. This is a common construct when you need to track the loop index for some reason but it turns out that its use really should be discouraged. The problem is that ElementAt(i) can take a really long time depending on the underlying list type of the enumerable. If it’s an array, it’s really quick, but in our case it was a System.Linq.Enumerable.WhereSelectListIterator and apparently ElementAt(i) had to traverse the enumerator from the start each time it was called. That’s not what you want to use an iterator for…

We changed the above loop to a foreach-loop instead, so that the iterator can be used more naturally:

int i;
foreach (var deltagare in Model.Deltagare)
{
  ...
  i++;
}

The duration of our loop went from about 10 minutes to 1 second for a list of about 6000 items.

Lesson learned.

/Emil

NDepend 3

In case you missed it, there’s a very powerful tool called NDepend that helps you analyze your code structure and detect potential problems very easily. A new version, NDepend 3, was released earlier this year and the biggest new feature is probably Visual Studio integration:

It still has all the code metrics you’ll probably ever need, a custom made code query language, diagrams (some of which are still a little difficult to read) and graphs to help with analysis. See my post about the previous version for some examples.

Here are a few live examples of using NDepend: http://www.ndepend.com/Features.aspx#Tour

If you’re into code analysis you should give NDepend a try. With this new version it’s more usable than before and it still has the same very powerful analysis engine under the hood. Check out http://www.ndepend.com for more info.

/Emil