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.

Loading Gist 7523672

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:

Loading Gist 7519763

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:

Loading Gist 7522819

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:

Loading Gist 7517928

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:

Loading Gist 7521986

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

Loading Gist 7521995

You will also need this extension:

Loading Gist 7522018

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:

Loading Gist 7519460

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

Loading Gist 7519477

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.

Loading Gist 7519648

I also made AddUsingTask generic:

Loading Gist 7519677

Which allows the following simpler test:

Loading Gist 7519763

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:

Loading Gist 7519022

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

Loading Gist 7519004

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:

Loading Gist 7518446

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:

Loading Gist 7517928

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:

Loading Gist 7518019

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)

Loading Gist 7518058

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

Next up, turn this in to a test.