Friday, February 25, 2011

Jounce Part 11: Debugging MEF

The Jounce framework specifically relies on the Managed Extensibility Framework to help solve MVVM concerns. I recently presented an introduction to MEF and explained what I believe are the four core problems it solves:

  1. Discovery — it's good to decouple, but at some point you need to provide an implementation, and MEF does a great job of discovering implementations, wiring their dependencies, and providing them to you
  2. Lifetime management — instead of mangling classes to follow the singleton pattern, MEF provides you with a way to manage the lifetime of those classes through attributes. You can define whether or not an instance is shared or generated both where you define the class and when you require it, giving you plenty of flexibility over how the class is managed without having to change it
  3. Extensibility — this often throws people off because they believe it is just for plug-ins. The fact is MEF has a very easy, built-in means for dynamically loading XAP files and integrating them into your main application, making modularity and extensibility easy to implement
  4. Metadata — Jounce uses this extensively: the ability to tag an implementation with additional data and filter that data to route implementations and only create them on demand when needed. This is how Jounce manages views, view models, and regions

The one drawback to using MEF is troubleshooting. Sometimes the composition step — when MEF scans all of the requirements and contracts in a project and maps in the implementations that satisfy them — can fail and it's not immediately clear why. MEF uses stable composition, so if any part of a hierarchy fails to import the correct references, the entire composition step will fail. This is intentional so you don't get unexpected behavior when you are asking for a dependency and it can't be provided.

Fortunately, MEF provides plenty of hooks to debug what is going on when composition occurs. Jounce uses a special debug container that can actually be used independently of Jounce for your MEF projects. It is in a class called MEFDebugger and you can browse the source at CodePlex here.

The class constructor takes in a container and a logging mechanism. The logger is what messages are written to. The default logger supplied by Jounce simply emits debug statements, but it can be replaced by any implementation of your own and wired into any third-party logger available for Silverlight. The container is the main MEF container. Jounce configures this container when the application is started and passes it into the MEF debugging container. The debug container is closed — there are no additional methods or properties — so you simply maintain a reference to keep it alive for the duration of the application.

The first thing the debugger does is hook into an ExportsChanged event. This fires any time a new XAP file is loaded or the catalog is modified in any way that results in a change of exports. This is when recomposition comes into play and typically happens the first time the container is composed and subsequently whenever a dynamic XAP file is loaded.

Whenever the exports change, the debugger simply walks through the added parts, the removed parts, and the contract changes and emits those. It also examines the metadata in the exports and writes those out as well. Using the ToString override on your classes helps provide more friendly/readable information when the values of attributes or exports themselves are written out.

The call to debug the catalog simply walks through all import and export definitions and does the same thing. The end result is that you receive a stream of debug information explaining exactly what catalogs are included, what parts are found, the imports, exports, and metadata found in the parts, and any new information when recomposition occurs.

The easiest way to see this in action is to run the quick start. Set the DynamicXAPCalculatorTestPage.aspx page in the web project as the start page to launch this example. Jounce will parse the init params for the debug level to use in the logger. Add this init parameter to ensure you receive verbose debug information:

<param name="initParams" value="Jounce.LogLevel=Verbose" />

When you run the application in the debugger, you'll see very explicit container information sent to the debug window. For example, here is the part that represents the view shell. Notice it requires an import for the event aggregator, and exports a user control and a binding. You can also see the associated metadata, which in this case is the flag marking this as IsShell=true.

2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger :: MEF: Found part: DynamicXapCalculator.Views.Shell
2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger ::    With import: DynamicXapCalculator.Views.Shell.EventAggregator (ContractName="Jounce.Core.Event.IEventAggregator")
2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger ::    With export: DynamicXapCalculator.Views.Shell (ContractName="System.Windows.Controls.UserControl")
2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger ::       With key: ExportedViewType = Shell
2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger ::       With key: IsShell = True
2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger ::       With key: Category = 
2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger ::       With key: MenuName = 
2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger ::       With key: ToolTip = 
2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger ::       With key: ExportTypeIdentity = System.Windows.Controls.UserControl
2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger ::    With export: DynamicXapCalculator.Views.Shell.Binding (ContractName="Jounce.Core.ViewModel.ViewModelRoute")
2/25/2011 6:44:47 AM Verbose Jounce.Core.MefDebugger ::       With key: ExportTypeIdentity = Jounce.Core.ViewModel.ViewModelRoute

The calculator provides some basic functions for addition and subtraction. Multiplication and division are loaded in a dynamic XAP file. Click the link to load the advanced functions, and watch the debug window. You'll notice that additional exports are added to the container:

2/25/2011 6:48:16 AM Verbose Jounce.Core.MefDebugger :: Added Export: DyanmicXapCalculatorAdvanced.AdvancedFunctions.AddCommand (ContractName="System.Tuple(System.String,System.Windows.Input.ICommand)")
2/25/2011 6:48:16 AM Verbose Jounce.Core.MefDebugger ::       With key: ExportTypeIdentity = System.Tuple(System.String,System.Windows.Input.ICommand)

You'll also find that the contract for the commands that drive the calculator has changed (because it now has additional exports to use):

2/25/2011 6:48:16 AM Verbose Jounce.Core.MefDebugger :: Changed contracts:
2/25/2011 6:48:16 AM Verbose Jounce.Core.MefDebugger ::  ==>System.Tuple(System.String,System.Windows.Input.ICommand)
2/25/2011 6:48:16 AM Verbose Jounce.Core.MefDebugger ::  ==>System.ComponentModel.Composition.Contracts.ExportFactory

As you can see, a lot of detailed information is provided that most of the time will help you track down exactly where the imports, exports, and metadata that make up parts is coming from. By examining what is generated and what your code is expecting, you can quickly track down where composition errors may be coming from. With your own logger implementation you can easily route these messages to the server, a text file, or even store them in isolated storage for later inspection.

Jeremy Likness