Logging an Item

MSBuild items seem like the should be almost the same as properties, but they are different in some odd ways. Time to add support for them.

Most of the time was just spent iterating with MSBuild, trying to understand what it expected, and how it would respond to different inputs. I'm glad I'm encapsulating that here in this class, so the rest of my Task code doesn't have to worry about it.

	private void LogProperty(PropertyInfo propertyInfo)
	{
	string name = propertyInfo.Name;
	var value = propertyInfo.GetValue(this);
	if (value is ITaskItem[])
	{
	LogTaskItems(value as ITaskItem[], name);
	}
	else
	{
	Log.LogMessage(MessageImportance.High, " {0} = {1}", name, value);
	}
	}
	private void LogTaskItems(ITaskItem[] taskItems, string itemGroup)
	{
	Log.LogMessage(MessageImportance.High, " {0} =", itemGroup);
	foreach (var item in taskItems)
	{
	LogTaskItem(item);
	}
	}
	private void LogTaskItem(ITaskItem item)
	{
	Log.LogMessage(MessageImportance.High, " {0}", item.ItemSpec);
	}

view raw LogTaskItems.cs hosted with ❤ by GitHub

	[TestMethod]
	public void TaskItemsGetLogged()
	{
	var buildTarget = CreateBuildTarget();
	var itemGroup = buildTarget.AddItemGroup();
	itemGroup.AddItem("Foo", "a");
	itemGroup.AddItem("Foo", "b");
	buildTarget.AddTask<TaskWithItems>().SetParameter("Foo", "@(Foo)");
	const string expected = @"Inputs:
	Foo =
	a
	b
	";
	AssertTargetOutput(expected, buildTarget);
	}

view raw TaskItemsGetLogged.cs hosted with ❤ by GitHub

EDIT: After posting this, I noticed a bug. I had hard-coded the name on line 7 of LogProperty. Some TDD gurus insist that you write more than one test before removing hard-coded results. If I had done that, I would have caught that bug before committing my code. I'm tired, so I'm looking for shortcuts; if I had a pair, I bet we wouldn't have let that happen.

Refactoring the test

All the TDD gurus admonish us to keep our test code well-factored.* I know I'll want to write more tests soon, so now is a good time to clean up the test I have. Let's refresh ourselves with starting code:

	var projectRootElement = ProjectRootElement.Create();
	projectRootElement
	.AddTarget("Build")
	.AddTask<MyTask>()
	.SetParameter("Foo", "hi");
	var highImportanceStringLogger = new HighImportanceStringLogger();
	var success = new ProjectInstance(projectRootElement).Build(new[] { highImportanceStringLogger });
	Assert.IsTrue(success);
	const string expected = @"Inputs:
	Foo = hi
	";
	Assert.AreEqual(expected, highImportanceStringLogger.ToString());

view raw gistfile1.cs hosted with ❤ by GitHub

This is a job for Extract Method. Most of the effort goes in to picking the right places to slice the method in to bits.

It's easier to know where to slice when you have a second (or 3rd!) example - it's easier to see the duplication. On the other hand, refactoring 3 is more work than refactoring 1. I took a quick stab at writing a new test, saw the duplication, deleted it, and then refactored. Call this an educated guess.

Here's what I ended up with:

	[TestMethod]
	public void RequiredInputGetsLogged()
	{
	var buildTarget = CreateBuildTarget();
	buildTarget.AddTask<TaskWithRequiredInput>().SetParameter("Foo", "hi");
	const string expected = @"Inputs:
	Foo = hi
	";
	AssertTargettOutput(expected, buildTarget);
	}
	private ProjectTargetElement CreateBuildTarget()
	{
	var buildTarget = ProjectRootElement.Create().AddTarget("Build");
	return buildTarget;
	}
	private static void AssertTargettOutput(string expected, ProjectTargetElement projectTargetElement)
	{
	var highImportanceStringLogger = new HighImportanceStringLogger();
	var success = new ProjectInstance(projectTargetElement.ContainingProject).Build(new[] { highImportanceStringLogger });
	Assert.IsTrue(success);
	Assert.AreEqual(expected, highImportanceStringLogger.ToString());
	}

view raw MSBuildParameterLoggingTests.cs hosted with ❤ by GitHub

I'm curious about this new assert. Some TDD gurus mention custom asserts as one element of advanced TDD, so I am going to pay attention here and see if anything interesting happens.

Next up, a new feature, with a new test. Let's see if my refactoring works out.

*Arlo Belshee goes a step further: don't worry about duplication between tests as much as making the rests read cleanly. They should say exactly what you want to test, no more, no less. He says tests should be "WET" - Write Explicit Tests, while product code should be "DRY" - Don't Repeat Yourself.

Refactoring the logging

Now that the tests are working OK, I want to turn my attention back to the other goal: cleaner code for task parameter logging. Here's the current implementation:

	public class MyTask : Task
	{
	[Required]
	public string Foo { get; set; }
	public override bool Execute()
	{
	Log.LogMessage(MessageImportance.Low, "Inputs:");
	Log.LogMessage(MessageImportance.Low, " Foo = {0}", this.Foo);
	return true;
	}
	}

view raw MyTask.cs hosted with ❤ by GitHub

I want to refactor this to generalize. I'm not going to add additional tests just yet, even though maybe I should. At least I have enough test coverage that I don't have to spend time manually testing as I go.

I used very small steps, but the outline is:

1. Extract Method LogInputs, push it up to base class LoggingTask
   
2. Replace the hard-coded "Foo" and this.Foo with reflection via this.GetType().GetProperty("Foo").Name and .GetValue(this).
   
3. Extract method LogInput, taking a PropertyInfo
   
4. Replace GetProperty() with a loop over GetProperties(), filtering by the [Required] attribute.
   
5. Extract Method GetPropertyInfos and HasAttribute.

Here's the result:

	public abstract class LoggingTask : Task
	{
	protected void LogInputs()
	{
	Log.LogMessage(MessageImportance.High, "Inputs:");
	foreach (var propertyInfo in GetInputProperties())
	{
	LogProperty(propertyInfo);
	}
	}
	private IEnumerable<PropertyInfo> GetInputProperties()
	{
	var propertyInfos = from propertyInfo in this.GetType().GetProperties()
	where propertyInfo.HasAttribute<RequiredAttribute>()
	select propertyInfo;
	return propertyInfos;
	}
	private void LogProperty(PropertyInfo propertyInfo)
	{
	string name = propertyInfo.Name;
	var value = propertyInfo.GetValue(this);
	Log.LogMessage(MessageImportance.High, " {0} = {1}", name, value);
	}
	}

view raw LoggingTask.cs hosted with ❤ by GitHub

As an indication that I'm on the right track, see how small the test task is:

	public class TaskWithRequiredInput : LoggingTask
	{
	[Required]
	public string Foo { get; set; }
	public override bool Execute()
	{
	LogInputs();
	return true;
	}
	}

view raw gistfile1.txt hosted with ❤ by GitHub

You will also need this extension:

	public static class PropertyInfoExtensions
	{
	public static bool HasAttribute<TAttribute>(this PropertyInfo propertyInfo)
	where TAttribute : Attribute
	{
	return propertyInfo.GetCustomAttribute<TAttribute>() != null;
	}
	}

view raw PropertyInfoExtensions.cs hosted with ❤ by GitHub

I don't really like that he [Required] attribute is used to find parameters; that's not quite the right rule. But I'll come back to that later.

Creating the MSBuild project in-memory

Now that we're no longer running the MSBuild command line, the next isolating refactoring is to create the project file in memory, too. To do that, I used ProjectRootElement:

	var projectRootElement = ProjectRootElement.Create();
	projectRootElement.AddUsingTask(typeof (MyTask));
	projectRootElement
	.AddTarget("Build")
	.AddTask(typeof(MyTask).Name)
	.SetParameter("Foo", "hi");
	var highImportanceStringLogger = new HighImportanceStringLogger();
	var success = new ProjectInstance(projectRootElement).Build(new[] { highImportanceStringLogger });
	Assert.IsTrue(success);
	const string expected = @"Inputs:
	Foo = hi
	";
	Assert.AreEqual(expected, highImportanceStringLogger.ToString());

view raw gistfile1.cs hosted with ❤ by GitHub

Note this depends on the following extension method, which I introduced to reduce duplication:

	using System;
	using Microsoft.Build.Construction;
	public static class ProjectRootElementExtensions
	{
	public static void AddUsingTask(this ProjectRootElement projectRootElement, Type type)
	{
	projectRootElement
	.AddUsingTask(type.Name, type.Assembly.Location, null);
	}
	}

view raw ProjectRootElementExtensions.cs hosted with ❤ by GitHub

I have an urge to write an extension method to replace AddTask which will ensure that the project has a UsingTask already. In fact, I'll go ahead and do that, so you can see the transformation.

	using System.Linq;
	using Microsoft.Build.Construction;
	static class ProjectTargetElementExtensions
	{
	public static ProjectTaskElement AddTask<TTask>(this ProjectTargetElement projectTargetElement)
	{
	string taskName = typeof (TTask).Name;
	ProjectRootElement projectRootElement = projectTargetElement.ContainingProject;
	if (!projectRootElement.UsingTasks.Any(ut => ut.TaskName == taskName))
	{
	projectRootElement.AddUsingTask<TTask>();
	}
	return projectTargetElement.AddTask(taskName);
	}
	}

view raw ProjectTargetElementExtensions.cs hosted with ❤ by GitHub

I also made AddUsingTask generic:

	using System;
	using Microsoft.Build.Construction;
	public static class ProjectRootElementExtensions
	{
	public static void AddUsingTask<TTask>(this ProjectRootElement projectRootElement)
	{
	Type taskType = typeof(TTask);
	projectRootElement
	.AddUsingTask(taskType.Name, taskType.Assembly.Location, null);
	}
	}

view raw ProjectRootElementExtensions.cs hosted with ❤ by GitHub

Which allows the following simpler test:

	var projectRootElement = ProjectRootElement.Create();
	projectRootElement
	.AddTarget("Build")
	.AddTask<MyTask>()
	.SetParameter("Foo", "hi");
	var highImportanceStringLogger = new HighImportanceStringLogger();
	var success = new ProjectInstance(projectRootElement).Build(new[] { highImportanceStringLogger });
	Assert.IsTrue(success);
	const string expected = @"Inputs:
	Foo = hi
	";
	Assert.AreEqual(expected, highImportanceStringLogger.ToString());

view raw gistfile1.cs hosted with ❤ by GitHub

Running MSBuild in-proc in a unit test

In the previous step, I executed my code under test (a custom MSBuild task) by running MSBuild as a separate process, with a hard-coded path to the EXE, passing a project file on the command line, and capturing standard output. An ideal unit test runs the system-under-test (SUT) in isolation, and this is far from isolated. That's fine in spike mode, but over time I want to refactor my tests to improve isolation.

To take a step in that direction, I'm am switching from Process.Start to using the MSBuild APIs directly. It took a while to figure out a way that works, but now I've got one:

	var myProject = new ProjectInstance(@"..\..\my.proj");
	var logger = new HighImportanceStringLogger();
	var success = myProject.Build(new[] { logger });
	Assert.IsTrue(success);
	const string expected = @"Inputs:
	Foo = hi
	";
	Assert.AreEqual(expected, logger.ToString());

view raw gistfile1.cs hosted with ❤ by GitHub

This requires a custom logger to gather the output, which I wrote like this:

	class HighImportanceStringLogger : ILogger
	{
	readonly private StringBuilder stringBuilder = new StringBuilder();
	public void Initialize(IEventSource eventSource)
	{
	eventSource.MessageRaised += eventSource_MessageRaised;
	}
	void eventSource_MessageRaised(object sender, BuildMessageEventArgs e)
	{
	if (e.Importance <= MessageImportance.High)
	{
	stringBuilder.AppendLine(e.Message);
	}
	}
	public string Parameters { get; set; }
	public void Shutdown() { }
	public LoggerVerbosity Verbosity { get; set; }
	public override string ToString()
	{
	return this.stringBuilder.ToString();
	}
	}

view raw HighImportanceStringLogger.cs hosted with ❤ by GitHub

This new logger  is pretty specialized - high importance messages only. I have an urge to generalize it to let the importance be a parameter, but for now, I'm applying YAGNI and leaving it as simple as I can.

Running MSBuild in a unit test

My aim now is to write a simple, fast, reliable test that will execute my custom MSBuild task. Currently, I can run it with the command line:

PS> msbuild .\My.proj /v:d

One challenge with testing it this way is that the output has a lot of non-repeatable test, including timestamps. Just to make things easier, I'll elevate the logging importance to "high".

Log.LogMessage(MessageImportance.High, "  Foo = {0}", this.Foo);

Then I'll run with minimal verbosity, and nologo to clean up the output:

PS> msbuild .\My.proj /v:m /nologo
  Inputs:
    Foo = hi

Now I need to actually write a test. The simplest test I can think of:

	[TestMethod]
	public void TestMethod1()
	{
	var process = new Process
	{
	StartInfo =
	{
	FileName = @"C:\Program Files (x86)\MSBuild\12.0\bin\MSBuild.exe",
	Arguments = @"..\..\my.proj /v:m /nologo",
	UseShellExecute = false,
	RedirectStandardOutput = true,
	}
	};
	process.Start();
	var result = process.StandardOutput.ReadToEnd();
	process.WaitForExit();
	const string expected = "";
	Assert.AreEqual(expected, result);
	}

view raw MyTaskTest.cs hosted with ❤ by GitHub

Note that I wrote the expected output as empty, to see the exact actual output (which is already known good, since I'm writing the test after the fact). I'll grab that actual output, make it the expected value, and the test will pass. That way of working is the basis of Llewellyn Falco's ApprovalTests, which I may switch to in a future step. But for now, make the test pass & check in:

            const string expected = @"  Inputs:
    Foo = hi
";

spiking a custom MSBuild Task

My team has a bunch of MSBuild tasks. Most of them write their input parameters to the log, like this:

	public class MyTask : Task
	{
	[Required]
	public string Foo { get; set; }
	public override bool Execute()
	{
	Log.LogMessage(MessageImportance.Low, "Inputs:");
	Log.LogMessage(MessageImportance.Low, " Foo = {0}", this.Foo);
	return true;
	}
	}

view raw MyTask.cs hosted with ❤ by GitHub

As of recent versions of MSBuild, this logging already happens automatically, but only in diagnostic logs. Those logs are so big as to be unusable for us, so we want this information to appear in the detailed (or perhaps normal) logs.

Today, I want to explore two ideas:

1. Using TDD on MSBuild tasks, and
2. Removing duplication of this logging code.

I'll start with a spike, to confirm that I do indeed know how to write & run a custom MSBuild task. The task implementation is presented above. Next, I write a small MSBuild project:

	<?xml version="1.0" encoding="utf-8"?>
	<Project ToolsVersion="4.0" xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
	<UsingTask TaskName="MyTask" AssemblyFile=".\bin\Debug\ClassLibrary2.dll" />
	<Target Name="Build">
	<MyTask Foo = "hi" />
	</Target>
	</Project>

view raw My.proj hosted with ❤ by GitHub

And then run it on the command line (the 2nd run is with diagnostic verbosity, so you can see what the built-in logging looks like)

	PS> msbuild .\My.proj /v:d
	...
	Task "MyTask"
	Inputs:
	Foo = hi
	Done executing task "MyTask".
	PS> msbuild .\My.proj /v:diag
	...
	Task "MyTask" (TaskId:2)
	Task Parameter:Foo=hi (TaskId:2)
	Inputs: (TaskId:2)
	Foo = hi (TaskId:2)
	Done executing task "MyTask". (TaskId:2)

view raw gistfile1.txt hosted with ❤ by GitHub

Great, I know how to do something. :-)

Next up, turn this in to a test.