Geoff Hudik's Tech-E Blog

ASP.NET NLog Sql Server Logging and Error Handling Part 2

Geoff Hudik — Fri, 24 May 2013 19:00:00 +0000

Be sure to check out Part 1 as this post builds upon it and the two go hand in hand.

Series Overview

Part 1 - Setting up logging with ASP.NET MVC, NLog and SQL Server

Part 2 - Unhandled exception processing, building an error report, emailing errors, and custom error pages.

Custom Error Handling Attribute

Added in FilterConfig.RegisterGlobalFilters and bound in DiagnosticModule, AppErrorHandlerAttribute invokes reporting the unhandled exception and setting the error view to be displayed to the end user. An enableErrorPages appSetting controls whether any of this is done; for local debugging or a dev web server having this off might be desirable.

namespace NLogSql.Web.Infrastructure.ErrorHandling
{
    public class AppErrorHandlerAttribute : FilterAttribute, IExceptionFilter
    {
        [Inject]
        public IErrorReporter Reporter { get; set; }

        public void OnException(ExceptionContext exceptionContext)
        {
            if (exceptionContext.ExceptionHandled) return;

            if (ConfigurationManager.AppSettings["enableErrorPages"] == "false")
            {
                AppLogFactory.Create<AppErrorHandlerAttribute>().Error(
                    "Unexpected error. enableErrorPages is false, skipping detailed "
					+ "error gathering. Error was: {0}",
                    exceptionContext.Exception.ToString());
                return;
            }

            Ensure.That(Reporter, "Reporter").IsNotNull();
            Reporter.ReportException(exceptionContext);

            SetErrorViewResult(exceptionContext);
        }

        private static void SetErrorViewResult(ExceptionContext exceptionContext)
        {
            var statusCode = new HttpException(null, exceptionContext.Exception)
				.GetHttpCode();

            exceptionContext.Result = new ViewResult
            {
                ViewName = MVC.Shared.Views.ViewNames.Error,
                TempData = exceptionContext.Controller.TempData,
                //ViewData = new ViewDataDictionary<ErrorModel>(new ErrorModel())
            };

            exceptionContext.ExceptionHandled = true;
            exceptionContext.HttpContext.Response.Clear();
            exceptionContext.HttpContext.Response.StatusCode = statusCode;
            exceptionContext.HttpContext.Response.TrySkipIisCustomErrors = true;
        }
    }
}

Logging and Reporting the Error

In the same namespace the ErrorReporter class invokes generation of an error report and logs and emails the error report. The overload with customActivityMessage would generally be used with handled exceptions where it may still be desirable to report the exception in cases.

public class ErrorReporter : IErrorReporter
{
	private readonly ILog _log;

	public ErrorReporter(ILog log)
	{
		_log = Ensure.That(log, "log").IsNotNull().Value;
	}

	private string CustomActivityMessage { get; set; }

	public void ReportException(ControllerContext controllerContext, 
		Exception exception, string customActivityMessage = null)
	{
		this.CustomActivityMessage = customActivityMessage;
		ReportException(new ExceptionContext(controllerContext, exception));
	}

	public void ReportException(ExceptionContext exceptionContext)
	{
		var errorInfo = new ErrorReportInfo(exceptionContext, this.CustomActivityMessage);
		errorInfo.Generate();
		_log.Error("Unexpected error: {0}", errorInfo.ReportText);

		if (errorInfo.Errors.Any())
			_log.Error("Error generating error report. Original exception: {0}", 
				exceptionContext.Exception);

		// sending mail can be a little slow, don't delay end user seeing error page
		Task.Factory.StartNew(
		state =>
		{
			var errorReport = (ErrorReportInfo)state;
			DependencyResolver.Current.GetService<IErrorEmailer>()
				.SendErrorEmail(errorReport);
		},
		errorInfo).ContinueWith(t =>
		{
			if (null != t.Exception)
				_log.Error("Error sending email: " + t.Exception.ToString());    
		});
	}
}

Building the Error Report

Various diagnostic info classes are responsible for building different diagnostic "sub reports". Each inherits from DiagnosticInfoBase which is a glorified StringBuilder, with functionality to build both a plain text version of the report (logged to DB) as well as an HTML formatted version (used for emails).

The base class has safe appending and formatting functionality and ensures that any error in generating a part of the report doesn't stop the whole process.

A sample implementation:

public class FormInfo : DiagnosticInfoBase
{
	private readonly HttpRequestBase _request;

	public FormInfo(HttpRequestBase request)
	{
		_request = request;
	}

	protected override void GenerateReport()
	{
		StartTable();
		var keys = _request.Form.AllKeys.OrderBy(s => s).ToList();

		foreach (var name in keys)
		{
			var value = _request.Form[name];

			if (null != value && name.Contains("password", StringComparison.OrdinalIgnoreCase))
			{
				value = new string('*', value.Length);
			}

			AppendRow(name, value);
		}

		EndTable();
	}
}

The ErrorReportInfo class combines the output of each section for the full error report.

In the end this produces a sample HTML email report like this.

Sending the Email

Sending the email logs the result on failure or success,

public interface IErrorEmailer
{
	void SendErrorEmail(ErrorReportInfo errorInfo);
}

public class ErrorEmailer : IErrorEmailer
{
	private readonly IMailer _mailer;
	private readonly ILog _log;

	public ErrorEmailer(IMailer mailer, ILog log)
	{
		_mailer = Ensure.That(mailer, "mailer").IsNotNull().Value;
		_log = Ensure.That(log, "log").IsNotNull().Value;
	}

	public void SendErrorEmail(ErrorReportInfo errorInfo)
	{
		try
		{
			var subject = string.Format("{0} Error", 
				Assembly.GetExecutingAssembly().GetName().Name);

			if (null != errorInfo.Server && null != errorInfo.Location
				&& !string.IsNullOrWhiteSpace(errorInfo.Location.ControllerAction)
				&& !string.IsNullOrWhiteSpace(errorInfo.Server.HostName))
			{
				subject = string.Format("{0}: {1} - {2}", subject, 
					errorInfo.Server.HostName, errorInfo.Location.ControllerAction);
			}

			var to = AppSettings.Default.Email.ErrorMessageTo;
			_mailer.SendMail(to, subject, errorInfo.ReportHtml);

			_log.Info("Sent email: {0} to {1}", subject, to);
		}
		catch (Exception ex)
		{
			_log.Error("Error sending error report email: {0}", ex);
		}
	}
}

The Error View

At the end of AppErrorHandlerAttribute the SetErrorViewResult invoked the Views\Shared\Error.cshtml page. According to the HTTP status code, content such as text, images and styles differ. Separate error pages may have more advantages if there are a larger number of differences; a single page was less work here.

@section styles{
    <link rel="stylesheet" href="~/Content/Error.css"/>
}

@{
    var statusTitleMap = new Dictionary<int, string> {
             {404, "Something got lost in the shuffle"},
             {410, "Gone like yesterday"},
             {500, "Something go boom"}
         };
}

@section hero{
    <div id="error-body" class="container-fluid">
        <div class="row-fluid">
            <div class="span3">
                @{ var errorClass = (Response.StatusCode == 404 || Response.StatusCode == 410) ? "_" + Response.StatusCode : "_500";}
                <div id="errorImageBlock" class="@errorClass"></div>
            </div>
    
            <div class="span8 offset1">
                <div class="row-fluid">
                    <div class="span12 text-center" id="status-code">
                        @Response.StatusCode
                    </div>
                </div>
                <div class="row-fluid">
                    <div class="span12" id="well-this">
                        @statusTitleMap[Response.StatusCode]
                    </div>
                </div>
        
                <div class="row-fluid">
                    <div class="span11" id="message">
                    @switch (Response.StatusCode)
                    {
                        case 404:
                            @:We cannot find the page you are looking for. If you typed in the address, double check the spelling. If you got here by clicking a link, 
                            @: <a href="mailto:customerservice@domain.com?subject=Page%20Not%20Found">let us know</a>.
                            break;
                        case 410:
                            @:The page you are looking for is gone (permanently). If you feel you reached this page incorrectly, <a href="mailto:customerservice@domain.com?subject=Link%20Gone">let us know</a>.
                            break;
                        case 500:
                            @:Oh dear, something's gone wrong. Our team has already been alerted to the problem and will fix it as soon as possible! 
                            break;
                    }  
                    </div>
                </div>
            </div>
        </div>
    </div>
}

Testing Errors

At the bottom of the home page are some links to test out error functionality.

Handling Not Found and Gone Permanently

404s have some special handling in Global.asax.cs:

protected void Application_EndRequest()
{
	if (Context.Response.StatusCode == 404)
	{
		if (Request.RequestContext.RouteData.Values["fake404"] == null)
		{
			Response.Clear();

			var rd = new RouteData();
			rd.Values["controller"] = MVC.Error.Name;
			rd.Values["action"] = MVC.Error.ActionNames.NotFound;

			var c = (IController)DependencyResolver.Current.GetService<ErrorController>();
			Request.RequestContext.RouteData = rd;
			c.Execute(new RequestContext(new HttpContextWrapper(Context), rd));
		}
	}
}

That code makes me itch a bit and could be done better but there is a reason for it. If you're wondering why not just use custom error pages, the answer is that doing so for a 404 page ends up producing a 301 redirect to then 404 on the custom not found page. For SEO purposes that is usually considered a bad practice. If you don't have a public site or as much SEO concern, that may be acceptable but in this case it wasn't.

Error Controller

The error controller sets and logs the response status codes and returns the error view. For the Gone action, usually there'd be routes defined for legacy URLs that would direct to that action.

public partial class ErrorController : Controller
{
	private readonly ILog _log;

	public ErrorController(ILog log)
	{
		_log = Ensure.That(log, "log").IsNotNull().Value;
	}

	public virtual ActionResult NotFound()
	{
		Response.StatusCode = (int)HttpStatusCode.NotFound;
		RouteData.Values["fake404"] = true;
		_log.Write(LogType.Warn, new { Code = "404" }, 
			"404 Not Found for {0}", Request.Url);
		return View("Error");
	}

	public virtual ActionResult Gone()
	{
		Response.StatusCode = (int)HttpStatusCode.Gone;
		Response.Status = "410 Gone";
		Response.TrySkipIisCustomErrors = true;
		_log.Write(LogType.Warn, new {Code = "410"}, 
			"410 gone permanently for {0}", Request.Url);
		return View("Error");
	}
}

Future Enhancements

The diagnostic info report building classes are pretty quick and messy in spots and could use cleanup.
Error view work including better responsive design and user-acceptable images :)
Admin error view to inspect log data and errors
Use and integration of apps such as appfail.net and New Relic to monitor errors and performance. This app used those tools in conjunction with the custom error handling and logging functionality.

The Code

The code for this series is available at https://github.com/thnk2wn/NLogSql.Web

ASP.NET NLog Sql Server Logging and Error Handling Part 1

Geoff Hudik — Tue, 21 May 2013 05:51:00 +0000

It was the eleventh hour before a web app was to go live and there was nothing in place for error handling or logging. You're shocked I'm sure (that's my sarcastic voice). Normally with web apps in the past I've used ELMAH for unhandled error logging and NLog with text file targets for other logging.

ELMAH works great but in this case I was told it was pulled for some reason. With no time to find out the story there I threw together something to capture basic error details and send an email. Later that grew and was customized and ELMAH never returned though perhaps it should have. Still there are benefits of doing this yourself including more customization, less bloat, less hunting through perhaps lacking documentation etc.

On the logging front I still wanted to use NLog but text file logging was no longer a fit. This app had a few instances behind a load balancer and central logging was needed plus it needed a higher volume of logging in some troublesome workflows, more so than the occasional errors or warnings here and there. I had not used NLog with SQL Server before but this seemed like the perfect time to do so.

Series Overview

Part 1 - Setting up logging with ASP.NET MVC, NLog and SQL Server

Part 2 - Unhandled exception processing, building an error report, emailing errors, and custom error pages.

Setup and Configuration

I began by installing the NLog NuGet package and the NLog.Extended package for asp.net specific information into the ASP.NET MVC 4 project. The NLog.Config package is useful for a standalone NLog config file but for web apps with existing config transforms I find embedding the configuration in Web.config easier.

In web.config under configuration/configSections, the NLog section is defined:

	<section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog" />

Under <configuration> my initial NLog config looked like the below, using the async attribute on targets to make each target work asynchronously:

<nlog xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" throwExceptions="true" 
    internalLogLevel="Debug" internalLogFile="${basedir}/NlogInternal.log">
    <!-- go to http://nlog-project.org/wiki/Configuration_file for more information -->
    <extensions>
      <add assembly="NLog.Extended" />
    </extensions>
    <targets async="true">
      <target xsi:type="Database" name="dbTarget" connectionStringName="Logger" 
	  commandText="exec sLogEvent_Insert @time_stamp, @level, @logger, @userName, @url, 
	    @machineName, @sessionId, @threadId, @referrer, @userAgent, @code, @message">
        <parameter name="@time_stamp" layout="${date}" />
        <parameter name="@level" layout="${level}" />
        <parameter name="@logger" layout="${logger}" />
        <parameter name="@userName" layout="${identity}" />
        <parameter name="@url" layout="${aspnet-request:serverVariable=Url}" />
        <parameter name="@machineName" layout="${machinename}" />
        <parameter name="@sessionId" layout="${aspnet-sessionid}" />
        <parameter name="@threadId" layout="${threadid}" />
        <parameter name="@referrer" 
			layout="${aspnet-request:serverVariable=HTTP_REFERER}" />
        <parameter name="@userAgent" 
			layout="${aspnet-request:serverVariable=HTTP_USER_AGENT}" />
		<parameter name="@code" layout="${event-context:item=Code}" />
        <parameter name="@message" layout="${message}" />
      </target>
      <target name="debugTarget" xsi:type="Debugger" 
		layout="${time}|${level:uppercase=true}|${logger}|${message}" />
    </targets>
    <rules>
      <!-- Levels: Off, Trace, Debug, Info, Warn, Error, Fatal -->
      <logger name="*" minlevel="Trace" writeTo="debugTarget,dbTarget" />
    </rules>
</nlog>

Later I swapped to explicit use of AsyncWrapper targets as it allowed me to control the behavior more explicitly and mirrored the reality at runtime, at the cost of being more verbose.

<nlog xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" throwExceptions="true" 
    internalLogLevel="Debug" internalLogFile="${basedir}/NlogInternal.log">
    <!-- go to http://nlog-project.org/wiki/Configuration_file for more information -->
    <extensions>
      <add assembly="NLog.Extended" />
    </extensions>
    <targets>
      <target name="asyncDbWrapperTarget" xsi:type="AsyncWrapper" queueLimit="10000" 
	  timeToSleepBetweenBatches="50" batchSize="100" overflowAction="Block">
        <target xsi:type="Database" name="dbTarget" connectionStringName="Logger" 
		commandText="exec sLogEvent_Insert @time_stamp, @level, @logger, @userName, @url, 
		@machineName, @sessionId, @threadId, @referrer, @userAgent, @code, @message">
          <parameter name="@time_stamp" layout="${date}" />
          <parameter name="@level" layout="${level}" />
          <parameter name="@logger" layout="${logger}" />
          <parameter name="@userName" layout="${identity}" />
          <parameter name="@url" layout="${aspnet-request:serverVariable=Url}" />
          <parameter name="@machineName" layout="${machinename}" />
          <parameter name="@sessionId" layout="${aspnet-sessionid}" />
          <parameter name="@threadId" layout="${threadid}" />
          <parameter name="@referrer" 
			layout="${aspnet-request:serverVariable=HTTP_REFERER}" />
          <parameter name="@userAgent" 
			layout="${aspnet-request:serverVariable=HTTP_USER_AGENT}" />
          <parameter name="@code" layout="${event-context:item=Code}" />
          <parameter name="@message" layout="${message}" />
        </target>
      </target>
      <target name="asyncDebugWrapperTarget" xsi:type="AsyncWrapper" queueLimit="10000" 
	  timeToSleepBetweenBatches="50" batchSize="100" overflowAction="Block">
        <target name="debugTarget" xsi:type="Debugger" 
			layout="${time}|${level:uppercase=true}|${logger}|${message}" />
      </target>
    </targets>
    <rules>
      <!-- Levels: Off, Trace, Debug, Info, Warn, Error, Fatal -->
      <logger name="*" minlevel="Trace" 
		writeTo="asyncDebugWrapperTarget,asyncDbWrapperTarget" />
    </rules>
 </nlog>

The database target's connectionStringName value of Logger points to the DB connection string to use.

<connectionStrings>
<add name="Logger" providerName="System.Data.SqlClient" 
   connectionString="Data Source=(local);Initial Catalog=Chinook.Logs;Persist Security Info=True;User ID=ChinookLogger;Password=L0gger!" />
</connectionStrings>

The Database

Our DBA setup a separate database for logging data to set DB properties differently as log data and transactional app data are different beasts. The sample app for this post is written against the Chinook sample database so I named the log database Chinook.Logs. The primary table script follows, minus the indexes, SET statements and the like.

CREATE TABLE [dbo].[LogEvent](
	[LogId] [int] IDENTITY(1,1) NOT NULL,
	[LogDate] [datetime] NOT NULL,
	[EventLevel] [nvarchar](50) NOT NULL,
	[LoggerName] [nvarchar](500) NOT NULL,
	[UserName] [nvarchar](50) NULL,
	[Url] [nvarchar](1024) NULL,
	[MachineName] [nvarchar](100) NOT NULL,
	[SessionId] [nvarchar](100) NULL,
	[ThreadId] [int] NULL,
	[Referrer] [nvarchar](1024) NULL,
	[UserAgent] [nvarchar](500) NULL,
	[Code] [nvarchar](10) NULL,
	[LogMessage] [nvarchar](max) NOT NULL,
	[PartitionKey] [tinyint] NOT NULL,
PRIMARY KEY CLUSTERED 
(
	[LogId] ASC,
	[PartitionKey] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON)
)

The table is pretty straightforward with perhaps a couple of exceptions. The Code field was to be used for custom error codes (HTTP or otherwise) or "tagging" log statements. PartitionKey was added by our DBA mainly for archiving log data but also for efficient querying by day; more on this to come. Finally I originally had the string columns as varchar but we found that NLog used nvarchar and a conversion was happening with each insert that had a slight performance impact.

The insert sproc grabs the day of the week and inserts that as the partition key and the rest of the data just passes through.

CREATE PROCEDURE [dbo].[sLogEvent_Insert]
	@time_stamp datetime,
	@level nvarchar(50),
	@logger nvarchar(500),
	@userName nvarchar(50),
	@url nvarchar(1024),
	@machineName nvarchar(100),
	@sessionId nvarchar(100),
	@threadId int,
	@referrer nvarchar(1024),
	@userAgent nvarchar(500),
	@code nvarchar(10),
	@message nvarchar(max)
AS
BEGIN
	SET NOCOUNT ON;
	Declare @currentDate Datetime
	declare @partitionKey tinyint
	
	set		@currentDate = getdate()
	set		@partitionKey = DATEPART(weekday, @currentDate)

	INSERT INTO [dbo].[LogEvent]
           ([LogDate]
           ,[EventLevel]
           ,[LoggerName]
           ,[UserName]
           ,[Url]
           ,[MachineName]
           ,[SessionId]
           ,[ThreadId]
           ,[Referrer]
           ,[UserAgent]
		   ,[Code]
           ,[LogMessage]
		   ,[PartitionKey])
     VALUES
           (@time_stamp
           ,@level
           ,@logger
           ,@userName
           ,@url
           ,@machineName
           ,@sessionId
           ,@threadId
           ,@referrer
           ,@userAgent
		   ,@code
           ,@message
		   ,@partitionKey);
END

An identical log table was created but with the name LogEvent_Switched. The cleanup sproc was created by our DBA:

CREATE PROCEDURE [DBA].[WeekdayPartitionCleanup_PartitionSwitching] 
AS
BEGIN
	SET NOCOUNT ON;
	declare @partitionKey int
	declare @SQLCommand nvarchar(1024)
	truncate table [Chinook.Logs].dbo.LogEvent_Switched;

	set @partitionKey = datePart(weekday, getdate()) + 1
	if(@partitionkey >7)
		set @partitionKey = 1

	set @SQLCommand = 'alter table [Chinook.Logs].dbo.LogEvent switch partition  ' 
	  + cast(@partitionKey as varchar) + ' to [Chinook.Logs].dbo.LogEvent_Switched;'
	exec sp_executesql @SQLCommand
END

That was scheduled to run daily. So if today is Friday, datePart(weekday, getdate()) returns 6, +1 is Saturday so all of last Saturday's log records get automagically switched over to the LogEvent_Switched table. This leaves the last 6 days of log records in LogEvent and the 7th day in LogEvent_Switched. If you don't have the Enterprise edition and can't use partitioning, regular deletes may work but could be problematic when deleting a large number of rows during frequent inserts or selects.

Finally permission to execute the sproc was granted and then it was back to .net land.

GRANT EXECUTE on dbo.sLogEvent_Insert to ChinookLogger;

Wiring up the Logging Code

First an interface that mostly mirrors NLog's Logger class.

namespace NLogSql.Web.Infrastructure.Diagnostics.Logging
{
    public interface ILog
    {
        void Debug(string format, params object[] args);
        void Error(string format, params object[] args);
        void Fatal(string format, params object[] args);
        void Info(string format, params object[] args);
        void Trace(string format, params object[] args);
        void Warn(string format, params object[] args);

        // custom
        void Write(LogType type, object properties, string message, params object[] args);

        bool IsDebugEnabled { get; }
        bool IsErrorEnabled { get; }
        bool IsFatalEnabled { get; }
        bool IsInfoEnabled { get; }
        bool IsTraceEnabled { get; }
        bool IsWarnEnabled { get; }
    }
}

The functionality of the Log class is provided mostly by inheriting from NLog's Logger class. One custom method is defined to allow passing custom log properties much like you would in ASP.NET (new {code = "404"}).

using System.ComponentModel;
using System.Globalization;
using NLog;

namespace NLogSql.Web.Infrastructure.Diagnostics.Logging
{
    public class Log : Logger, ILog
    { 
        public void Write(LogType type, object properties, string message, 
			params object[] args)
        {
            var info = new LogEventInfo(LogLevel.FromOrdinal((int)type), Name, 
				CultureInfo.CurrentCulture, message, args);

            if (null != properties)
            {
                foreach (PropertyDescriptor propertyDescriptor 
					in TypeDescriptor.GetProperties(properties))
                {
                    var value = propertyDescriptor.GetValue(properties);
                    info.Properties[propertyDescriptor.Name] = value;
                }
            }

            Log(info);
        }
    }

    public enum LogType
    {
        Trace, Debug, Info, Warn, Error, Fatal
    }
}

A log instance is typically created via injecting ILog into the constructor of the class needing logging. Here I use Ninject to wire this up.

using System;
using System.Linq;
using System.Web.Mvc;
using NLog;
using NLogSql.Web.Infrastructure.Diagnostics.Logging;
using NLogSql.Web.Infrastructure.ErrorHandling;
using Ninject.Activation;
using Ninject.Modules;
using Ninject.Web.Mvc.FilterBindingSyntax;

namespace NLogSql.Web.DI
{
    public class DiagnosticsModule : NinjectModule
    {
        public override void Load()
        {
            Bind<ILog>().ToMethod(CreateLog);
            Bind<IErrorReporter>().To<ErrorReporter>();
            Bind<IEventLogWriter>().To<EventLogWriter>();
            Bind<IErrorEmailer>().To<ErrorEmailer>();

            Kernel.BindFilter<AppErrorHandlerAttribute>(FilterScope.Controller, 0);
        }

        private static ILog CreateLog(IContext ctx)
        {
            var p = ctx.Parameters.FirstOrDefault(x => 
				x.Name == LogConstants.LoggerNameParam);
            var loggerName = (null != p) ? p.GetValue(ctx, null).ToString() : null;

            if (string.IsNullOrWhiteSpace(loggerName))
            {
                if (null == ctx.Request.ParentRequest)
                {
                    throw new NullReferenceException(
                        "ParentRequest is null; unable to determine logger name; " 
						+ "if not injecting into a ctor a parameter for the "
						+ "logger name must be provided");
                }

                var service = ctx.Request.ParentRequest.Service;
                loggerName = service.FullName;
            }

            var log = (ILog)LogManager.GetLogger(loggerName, typeof(Log));
            return log;
        }
    }
}

In some cases we can't easily do ctor injection - for example in the application class of Global.asax.cs or in a filter attribute. For these exception cases AppLogFactory is used to create an instance of ILog.

using System;
using System.Diagnostics;
using System.Web.Mvc;
using Ninject;
using Ninject.Parameters;

namespace NLogSql.Web.Infrastructure.Diagnostics.Logging
{
    /// <summary>
    /// Creates a log object for those instances where one cannot be injected (i.e. app startup).
    /// Generally you should just ctor inject ILog
    /// </summary>
    public static class AppLogFactory
    {
        public static ILog Create()
        {
            var declaringType = new StackTrace(1, false).GetFrame(1)
				.GetMethod().DeclaringType;

            if (declaringType != null)
            {
                var loggerName = declaringType.FullName;
                return Create(loggerName);
            }

            throw new InvalidOperationException(
				"Could not determine declaring type; specify logger name explicitly");
        }

        public static ILog Create<T>()
        {
            return Create(typeof(T).FullName);
        }

        public static ILog Create(string loggerName)
        {
            var log = Kernel.Get<ILog>(
				new ConstructorArgument(LogConstants.LoggerNameParam, loggerName));
            return log;
        }

        private static IKernel Kernel
        {
            get
            {
                return DependencyResolver.Current.GetService<IKernel>();
            }
        }
    }

    public class LogConstants
    {
        public const string LoggerNameParam = "loggerName";
    }
}

Exercising the Log

First a simple test, injecting ILog into a controllor ctor, ensuring it isn't null using the Ensure.That NuGet package and logging a count around a database fetch.

public partial class HomeController : Controller
{
	private readonly IMappingService _mappingService;
	private readonly ILog _log;
	private readonly IMusicService _musicService;

	public HomeController(IMusicService musicService, ILog log, IMappingService mappingService)
	{
		_mappingService = Ensure.That(mappingService, "mappingService").IsNotNull().Value;
		_log = Ensure.That(log, "log").IsNotNull().Value;
		_musicService = Ensure.That(musicService, "musicService").IsNotNull().Value;
	}
	
	public virtual ActionResult Index()
	{
		_log.Debug("Retrieving genres");
		var genres = GetGenres().Result;
		_log.Info("Retrieved {0} music genres from the database", genres.Count);
		// ...
	}
}

To get a little more value, an action filter to log each controller action executed along with the execution time.

public class ActionTrackerAttribute : ActionFilterAttribute
{
	private Stopwatch Watch { get; set; }
	private ILog Log { get; set; }
	private ActionExecutingContext FilterContext { get; set; }

	private string ActionName
	{
		get { return FilterContext.ActionDescriptor.ActionName; }
	}

	private string ControllerName
	{
		get { return FilterContext.ActionDescriptor.ControllerDescriptor.ControllerName; }
	}

	private Uri Url
	{
		get { return FilterContext.RequestContext.HttpContext.Request.Url; }
	}

	public override void OnActionExecuting(ActionExecutingContext filterContext)
	{
		base.OnActionExecuting(filterContext);

		try
		{
			FilterContext = filterContext;
			Log = AppLogFactory.Create<ActionTrackerAttribute>();
			Log.Trace("Executing {0}.{1}", ControllerName, ActionName);
			Watch = Stopwatch.StartNew();
		}
		catch (Exception ex)
		{
			Trace.WriteLine(ex);
		}
	}

	public override void OnResultExecuted(ResultExecutedContext filterContext)
	{
		base.OnResultExecuted(filterContext);

		try
		{
			Watch.Stop();
			Log.Info("Executed {0}.{1} for {2} in {3:##0.000} second(s)", 
				ControllerName, ActionName, Url, Watch.Elapsed.TotalSeconds);
		}
		catch (Exception ex)
		{
			Trace.WriteLine(ex);
		}
	}
}

Troubleshooting Failed Logging

When setting up logging initially or making changes later, logging might not work. Usually I'd first fire up SQL Server Profiler and watch for calls to the log insert sproc. If I didn't see them then I'd know it's probably a configuration issue. In the nlog tag in the config file I set throwExceptions="true" internalLogLevel="Debug" internalLogFile="${basedir}/NlogInternal.log" but in practice that rarely seemed to do anything; turning off async temporarily may further help troubleshoot.

First I'd check when creating the log if the log levels were enabled as expected from the config.

Next I'd check the configuration in code with a small class, also useful for changing config at runtime.

public class LogManagement
{
	public static AsyncTargetWrapper GetAsyncDbWrapperTarget()
	{
		var target = (AsyncTargetWrapper)LogManager.Configuration
			.FindTargetByName("asyncDbWrapperTarget");
		return target;
	}
}

From there I'd further inspect the configuration to see if everything looks okay.

If I did see the insert sproc call in SQL Server Profiler then I'd check DB setup and permissions and grab the SQL from Profiler...

... and paste into a query window, then format the Sql (I use Poor Man's TSql Formatter) and execute to check for errors.

Evaluating Async Logging

Because I'm paranoid, OCD, detailed and curious I wanted to ensure the async behavior and compare to non-async. On the home page I added a link to generate batch log records, corresponding to this controller action.

public virtual ActionResult BatchTest()
{
	var sw = Stopwatch.StartNew();
	const int count = 10000;
	for (var i = 0; i < count; i++)
	{
		_log.Trace("Testing {0}", i);
	}
	sw.Stop();
	var msg = string.Format("{0} log invokes in {1:##0.000} seconds", count, 
		sw.Elapsed.TotalSeconds);
	_log.Info(msg);

	return new ContentResult { Content = msg };
}

The async result:

And the non-async result:

Evaluating Log Queries

Usually when inspecting log records I'd select just those columns I'm interested in and order by LogId DESC.

Once enough log data was there it was helpful to query on the columns that would typically be filtered on and evaluate the execution plan and response times. From there indexes were added as needed for columns such as EventLevel, URL, UserName, etc. and execution times compared afterwards.

Preparing for Deployment

In Web.Config.Release NLog config transformations are performed to change the log level from Trace to Info, to remove debugger output, and to tone down NLog internal issue reporting.

<nlog xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xdt:Transform="SetAttributes"
        throwExceptions="false" internalLogLevel="Warn" 
		internalLogFile="${basedir}/NlogInternal.log">
    <rules>
       <!-- Levels: Off, Trace, Debug, Info, Warn, Error, Fatal -->
       <logger name="*" minlevel="Info" writeTo="asyncDbWrapperTarget" 
	      xdt:Transform="SetAttributes" xdt:Locator="Match(name)" />
    </rules>
</nlog>

Slow Cheetah preview:
Note that removing the nlog xsd attribute in the root web.config (and all transforms) was needed for the transformation to work correctly. Also at one point I tried a replace transform to replace the entire nlog tag but found it didn't work correctly and it created too much duplicate content between configurations.

Some Queries

Everything today:

SELECT *
FROM LogEvent WITH (NOLOCK)
WHERE PartitionKey = (
		SELECT DATEPART(weekday, getdate())
		)
ORDER BY logid DESC;

Errors and warnings in the past 2 hours:

SELECT *
FROM LogEvent WITH (NOLOCK)
WHERE eventlevel IN (
		'Error'
		,'Warn'
		)
	AND DATEDIFF(hh, LogDate, GETDATE()) <= 2
ORDER BY logid DESC;

Errors by day and url:

SELECT cast(logdate AS DATE) [Day]
	,url
	,count(*) ErrorCount
FROM LogEvent WITH (NOLOCK)
WHERE eventlevel = 'Error'
	AND len(url) > 0
GROUP BY cast(logdate AS DATE)
	,url
ORDER BY Day DESC
	,Url;

Errors by logger name / class name / component area:

SELECT LoggerName
	,count(*) AS ErrorCount
FROM LogEvent WITH (NOLOCK)
WHERE EventLevel = 'Error'
GROUP BY LoggerName
ORDER BY count(*) DESC;

Unhandled exceptions today:

SELECT *
FROM LogEvent WITH (NOLOCK)
WHERE PartitionKey = (
		SELECT DATEPART(weekday, getdate())
		)
	AND eventlevel = 'Error'
	AND LoggerName IN ('NLogSql.Web.Infrastructure.ErrorHandling.IErrorReporter')
ORDER BY logid DESC;

Future Enhancements / Considerations

Web view to read, search, filter log maybe with some SignalR goodness
AppId type column if logging from multiple apps w/o desire for multiple log databases
Possibly a separate error table that the log table could link to for errors with the full error report split up

The Code

The code for this series is available at https://github.com/thnk2wn/NLogSql.Web

Using T4 to Generate Typesafe Enum Classes and Resource Files

Geoff Hudik — Tue, 02 Oct 2012 04:25:00 +0000

In working on the domain layer of an application, I wrote a couple of typesafe enumeration classes that mirrored data in a couple of reference tables in a database. If you are not familiar with the pattern, Jimmy Bogard's Enumeration classes post explains the pattern and rationale. The classes I wrote inherit from a modified version of the Enumeration class presented in Jimmy's post. The basic idea was to avoid switches and provide more functionality than an enum could offer. In our case the enum members mirrored a reference table and would be used for domain logic and for dropdown lists.

As the app progressed we had more of a need to do this for other reference tables, some of which had several records. At this point we decided to look into T4 to generate the typesafe enum classes. Since this application has a worldwide audience, the display names of the enum members needed globalization consideration since some of the enum values would end up in dropdown lists displayed to end users. I decided to create two T4 files, one to generate resource files with display name strings, and another to generate the enum classes that would use the resource strings.

Reference Datasource

This application uses XML files for various database definitions including reference data; these files get parsed to build the SQL Server database in automated fashion.

A sample of reference_data.xml looks something like:

<referenceData>
	<refTable name="CONTACT_TYPE" alias="ContactType" default="Person">
		<record CONTACT_TYPE_ID="1" CONTACT_TYPE_NAME="Company" RANK="2">
			<langs field="CONTACT_TYPE_NAME">
				<lang name="en">Company</lang>
				<lang name="de">Gesellschaft</lang>
				<lang name="es">Empresa</lang>
				<lang name="zh-CN">公司</lang>
				<lang name="fr">Société</lang>
			</langs>
		</record>
		<record CONTACT_TYPE_ID="2" CONTACT_TYPE_NAME="Person" RANK="1">
			<langs field="CONTACT_TYPE_NAME">
				<lang name="en">Person</lang>
				<lang name="de">Person</lang>
				<lang name="es">Persona</lang>
				<lang name="zh-CN">人</lang>
				<lang name="fr">Personne</lang>
			</langs>
		</record>
	</refTable>
</referenceData>

Schema Metadata and Parsing

Since multiple projects needed to perform T4 code generation off database schema information, I defined some T4 include files in a shared project to define the schema structure and XML parsing logic. This would make the T4 code easier and prevent duplicating XML parsing logic in multiple T4 files.

First SchemaMetadata.ttinclude defines the classes that hold the schema information in a T4-friendly manner:

Next SchemaReader.ttinclude would get consumed by T4 files to parse the XML data and return friendly objects defined in SchemaMetadata.ttinclude:

This shared T4 folder also included MultipleOutputHelper.ttinclude from this Damien Guard post to make splitting T4 output into multiple files a bit easier.

RefDataResources.tt

This T4 file generates one resource file per language and will setup the custom tool to produce the designer generated file to reference the resources in code:

Inside the function block of this file the schema data is loaded and the resource files are generated:

const string ReferenceData = "ReferenceData";

private SchemaMetadata LoadSchema()
{
	var loader = new SchemaReader(Host);
	var schema = loader.Load(SchemaReader.LoadOption.ReferenceData);
	return schema;
}

private void GenerateResourceFiles(SchemaMetadata schema, Manager manager, 
	DirectoryInfo t4DirInfo)
{
	var distinctLanguages = schema.ReferenceData.DistinctLanguages;
	foreach (var lang in distinctLanguages)
	{
		var resxNameNoExt = ("en" != lang) ? ReferenceData + "." + lang : ReferenceData;
		var resxName = resxNameNoExt + ".resx";
		manager.StartNewFile(resxName);

		var resxFilename = Path.Combine(t4DirInfo.FullName, resxName);
		// use .net's ResXResourceWriter so we don't have to worry about the XML format
		using (ResXResourceWriter  resx = new ResXResourceWriter(resxFilename))
		{
			var strings = schema.ReferenceData.StringsForLanguage(lang);

			foreach (var warn in schema.Warnings)
			{
				base.Warning(warn);
			}

			foreach (var de in strings)
			{
				try 
				{
					resx.AddResource(de.Key, de.Value);
				}
				catch (Exception ex)
				{
					base.Warning(ex.ToString());
				}
			}

			resx.Generate();
			resx.Close();
		}

		// we've written the file but outside the process of T4. 
		// In order to get the file to automatically added as a new output file 
		// underneath the t4 file, we must write the generated content to output stream
		Write(File.ReadAllText(resxFilename));

		manager.EndBlock();
		
	} // end for each lang loop
}

In the above code block there are a couple of things worth pointing out. First, the filename of the main / default language resource file will be ReferenceData.resx for English (en), otherwise ReferenceData.lang.resx for other languages. Second, the output from .NET's ResXResourceWriter gets read in with File.ReadAllText and written to T4 output with Write; otherwise the generated content would just exist on disk and would not get added into the project nested under the T4 file.

Finally, to get the designer generated class created, a function is created to set the custom tool property on the main ReferenceData.resx file that was generated. For the initial add that would be enough. However we also invoke execution of the custom tool with RunCustomTool() to handle the case where reference data is modified later on and the T4 transformation is performed again:

private void SetCustomToolOnMainResourceFile(DirectoryInfo t4DirInfo)
{
	// WARNING: You are entering the dark land of EnvDTE COM. You've been warned
	var hostServiceProvider = (IServiceProvider) Host;
	var dte = (EnvDTE.DTE) hostServiceProvider.GetService(typeof(EnvDTE.DTE));
	var filename = Path.Combine(t4DirInfo.FullName, "ReferenceData.resx");
	var projectItem = dte.Solution.FindProjectItem(filename);
	projectItem.Properties.Item("CustomTool").Value = "PublicResXFileCodeGenerator";
	projectItem.Properties.Item("CustomToolNamespace").Value = "App.Domain";
	var projItemObj = (VSProjectItem)projectItem.Object;
	projItemObj.RunCustomTool();
}

Running the T4 produces the following files:

The resource strings are created with a TableName_FieldNameValue format:

Enums.tt

Enums.tt reads the schema data just as in RefDataResources.tt and generates the C# typesafe enum class. The full source is available with the sample code for this post.

A small example of the generated output (ContactType.generated.cs):

//------------------------------------------------------------------------------
// <auto-generated>
//     This code was generated from a template.
//
//     Changes to this file may cause incorrect behavior and will be lost if
//     the code is regenerated.
// </auto-generated>
//------------------------------------------------------------------------------
using System;
using System.CodeDom.Compiler;
using System.Diagnostics;
using System.Diagnostics.CodeAnalysis;
using JetBrains.Annotations;

namespace App.Domain
{
	public partial class ContactType : Enumeration
	{		
		/// <summary>
		/// ContactType of Company (ID: 1, "Company")
		/// </summary>
		[GeneratedCode("TextTemplatingFileGenerator", "11")]
		public static readonly ContactType Company 
			= new ContactType( 1, ReferenceData.ContactType_Company );

		/// <summary>
		/// ContactType of Person (ID: 2, "Person")
		/// </summary>
		[GeneratedCode("TextTemplatingFileGenerator", "11")]
		public static readonly ContactType Person 
			= new ContactType( 2, ReferenceData.ContactType_Person );


		[ExcludeFromCodeCoverage, DebuggerNonUserCode, GeneratedCode("TextTemplatingFileGenerator", "11")]
		private ContactType( int value, string displayName ) : base( value, displayName ) { }

		[ExcludeFromCodeCoverage, DebuggerNonUserCode, GeneratedCode("TextTemplatingFileGenerator", "11")]
		public static ContactType Default()
		{
			return Person;
		}

		[UsedImplicitly, Obsolete("ORM runtime use only")]
		[ExcludeFromCodeCoverage, DebuggerNonUserCode, GeneratedCode("TextTemplatingFileGenerator", "11")]
		private ContactType() { }
	}
}

Of course there's more value in automatically generating all of the reference enums or at least those with more members:

Testing It Out

First some basic tests just to ensure the resource files and strongly typed resource class generated correctly:

using System.Globalization;
using NUnit.Framework;
using System.Threading;

namespace App.Domain.Tests
{
    [TestFixture, Category("Unit")]
    public class ReferenceDataI18NTests
    {
        [Test]
        public void English_To_French_Strings_Change()
        {
            var orig = Thread.CurrentThread.CurrentUICulture;
            Assert.AreEqual("Company", ReferenceData.ContactType_Company);
            Thread.CurrentThread.CurrentUICulture = new CultureInfo("fr-FR");
            Assert.AreEqual("Société", ReferenceData.ContactType_Company);
            Thread.CurrentThread.CurrentUICulture = orig;
        }

        [Test]
        public void English_To_Spanish_Strings_Change()
        {
            var orig = Thread.CurrentThread.CurrentUICulture;
            Assert.AreEqual("Company", ReferenceData.ContactType_Company);
            Thread.CurrentThread.CurrentUICulture = new CultureInfo("es");
            Assert.AreEqual("Empresa", ReferenceData.ContactType_Company);
            Thread.CurrentThread.CurrentUICulture = orig;
        }

        [Test]
        public void English_To_German_Strings_Change()
        {
            var orig = Thread.CurrentThread.CurrentUICulture;
            Assert.AreEqual("Company", ReferenceData.ContactType_Company);
            Thread.CurrentThread.CurrentUICulture = new CultureInfo("de");
            Assert.AreEqual("Gesellschaft", ReferenceData.ContactType_Company);
            Thread.CurrentThread.CurrentUICulture = orig;
        }

        [Test]
        public void English_To_Chinese_Taiwan_Strings_Change()
        {
            var orig = Thread.CurrentThread.CurrentUICulture;
            Assert.AreEqual("Company", ReferenceData.ContactType_Company);
            Thread.CurrentThread.CurrentUICulture = new CultureInfo("zh-CN");
            Assert.AreEqual("公司", ReferenceData.ContactType_Company);
            Thread.CurrentThread.CurrentUICulture = orig;
        }
    }
}

Just to make sure the Enumeration class works as expected, some tests to exercise it through one of the concrete classes:

using System.Linq;
using FluentAssertions;
using NUnit.Framework;

namespace App.Domain.Tests
{
    [TestFixture(
        Description = "Tests base Enumeration class via PhoneType concrete class")]
    [Category("Unit")]
    public class EnumerationTests
    {
        [Test]
        public void FromValue_Matches_Type_Value()
        {
            var fromValue = Enumeration.FromValue<PhoneType>(PhoneType.Cell.Value);
            Assert.AreEqual(PhoneType.Cell, fromValue);

            fromValue = Enumeration.FromValue<PhoneType>(PhoneType.Voice.Value);
            Assert.AreEqual(PhoneType.Voice, fromValue);
        }

        [Test]
        public void FromDisplayName_Matches_Type_Name()
        {
            var fromName = Enumeration.FromDisplayName<PhoneType>(PhoneType.Fax.DisplayName);
            Assert.AreEqual(PhoneType.Fax.DisplayName, fromName.DisplayName);

            fromName = Enumeration.FromDisplayName<PhoneType>(PhoneType.Pager.DisplayName);
            Assert.AreEqual(PhoneType.Pager.DisplayName, fromName.DisplayName);
        }

        [Test]
        public void ToString_Equals_DisplayName()
        {
            Assert.AreEqual(PhoneType.Cell.DisplayName, PhoneType.Cell.ToString());
        }

        [Test]
        public void Absolute_Difference_Math_Is_Correct()
        {
            var diff = Enumeration.AbsoluteDifference(PhoneType.Cell, PhoneType.Voice);
            Assert.AreEqual(3, diff);
            diff = Enumeration.AbsoluteDifference(PhoneType.Voice, PhoneType.Cell);
            Assert.AreEqual(3, diff);
        }

        [Test]
        public void GetAll_Contains_Expected_Members()
        {
            var all = Enumeration.GetAll<PhoneType>().ToList();
            Assert.AreEqual(4, all.Count);
            Assert.NotNull(all.FirstOrDefault(x => x == PhoneType.Cell));
            Assert.NotNull(all.FirstOrDefault(x => x == PhoneType.Fax));
            Assert.NotNull(all.FirstOrDefault(x => x == PhoneType.Pager));
            Assert.NotNull(all.FirstOrDefault(x => x == PhoneType.Voice));
            Assert.NotNull(all.FirstOrDefault(x => x == PhoneType.Default()));
        }

        [Test]
        public void Equality_Two_Are_Equal()
        {
            var one = PhoneType.Cell;
            var two = PhoneType.Cell;
            Assert.AreEqual(one, two);
            Assert.True(one == two);
        }

        [Test]
        public void Equality_Two_Different_Not_Equal()
        {
            var one = PhoneType.Cell;
            var two = PhoneType.Voice;
            Assert.AreNotEqual(one, two);
            Assert.True(one != two);
        }

        [Test]
        public void Equality_One_Null_Not_Equal()
        {
            PhoneType.Cell.Equals(null).Should().BeFalse();
        }

        [Test]
        public void Compare_To_Succeeds()
        {
            var diff = PhoneType.Cell.CompareTo(PhoneType.Fax);
            diff.Should().Be(1);

            diff = PhoneType.Fax.CompareTo(PhoneType.Cell);
            diff.Should().Be(-1);
        }

        [Test]
        public void Invalid_Parse_Number_Throws()
        {
            Assert.That(() => { Enumeration.FromValue<PhoneType>(999); }, Throws.Exception);
        }
    }
}

There's More

For simplicity some complexity was removed from the T4. This includes reference tables that have foreign keys to other reference tables (including strongly typed properties and ctor params) and resource strings for fields other than the primary display name.
One thing that bothered me initially with this was it felt a bit like introducing Data Driven Design into an otherwise Domain Driven Design paradigm. This was offset somewhat with aliases for table names (or a naming convention pattern) and reference tables could be selectively ignored in code generation through the use of attributes or other means. Another possible issue is class name conflicts with existing types in the domain project; this could be offset with a different namespace and/or naming convention.
Many apps load reference data from the database each time it's needed, or load it once and cache it until invalidated. Other apps may let users edit select sets of reference type data. If the data is likely to change during an app session or if users can edit some of it, chances are it isn't truly reference data to begin with. With a good deployment process, any compiled reference data info can be easily deployed and various reference data is likely to be tied to app business and presentation rules anyway.
Several of the enum classes would have corresponding partial classes for extended logic. For this reason, various code generation type attributes were places directly on generated members and not on the class itself, per various guidance.
An example use in the domain would be a ContactType enum property on a Contact object and requiring different fields when attempting to add contacts of different types. This app uses this component strategy in Fluent NHibernate to map the data from the database reference table into the domain class. For the UI side, Enumeration.GetAllMembers can be used along with AutoMapper to get the id and text values into simple ViewModel types for select lists.

Code

T4RefDataCode.zip

AutoMapper's ForMember

Geoff Hudik — Fri, 03 Aug 2012 21:24:17 +0000

Calling AutoMapper's ForMember has been bugging me lately with having to deal with its member configuration options like so:

Mapper.CreateMap<Contact, AddressBookDetailsModel>()
	.ForMember( d => d.PhoneNumbers, o => o.MapFrom( s => s.Phones ) );

The member configuration options provides much more than just MapFrom but 99 times out of 100 I'm only dealing with MapFrom. What I'd really like is something like this:

Mapper.CreateMap<Contact, AddressBookDetailsModel>()
	.ForMember( d => d.PhoneNumbers).MapFrom( s=> s.Phones );

In looking around I did find http://trycatchfail.com/blog/post/A-More-Fluent-API-For-AutoMapper.aspx. It looked promising but (a) the code was incomplete and (b) it broke down for more complex mappings.

I'd like the syntax above but for now I went with something quicker to implement that gave me a shorter syntax though it might not be as syntactically sweet:

public static class AutoMapperExtensions
{
	public static IMappingExpression<TSource, TDestination> MapItem<TSource, TDestination, TMember>(
		this IMappingExpression<TSource, TDestination> target,
		Expression<Func<TDestination, object>> destinationMember,
		Expression<Func<TSource, TMember>> sourceMember )
	{
		return target.ForMember( destinationMember, opt => opt.MapFrom( sourceMember ) );
	}
}

Now when creating maps I don't need to fuss with an extra lambda and method call:

				
Mapper.CreateMap<Contact, AddressBookDetailsModel>()
	.MapItem( d => d.PhoneNumbers, s=> s.Phones );

I can do something similar to simplify Ignore calls:

		
public static class AutoMapperExtensions
{
	public static IMappingExpression<TSource, TDestination> Ignore<TSource, TDestination>(
		this IMappingExpression<TSource, TDestination> target,
		Expression<Func<TDestination, object>> destinationMember)
	{
		return target.ForMember( destinationMember, opt => opt.Ignore() );
	}
	
	/* other code removed for brevity */
}

A Week With the New MacBook Air

Geoff Hudik — Mon, 16 Jul 2012 01:00:00 +0000

Time for a New Computer

My mid-2009 MacBook Pro has been good to me as my first Mac. However after 3+ years it was showing its age with slow performance, particularly with any heavy disk access and especially running Windows. It stopped resuming from sleep quite a bit and started locking up more. I had previously upgraded it from 4 to 8 GB of memory and considered switching it to use an SSD but wanted more. I usually end up replacing my computers every 2-4 years or so anyway with 3 being the average of late. So I decided to start backing everything up with CrashPlan and start shopping around.

To Stick with Apple or Not

I've always been a Windows guy and a Microsoft developer and have been happy there personally and professionally. I originally bought a Mac for iPhone development and because I thought it was wise to diversify and mix things up. I've certainly learned a lot and have enjoyed the Mac life for the most part. However I still prefer Windows 7 over Mac OS X in many ways; I'm more a fan of iOS than OS X. I still feel a Mac at home and Windows at work is a good arrangement, I like Apple's innovation and hardware, and I can run both operating systems well on a Mac but not the other way around. That's enough to keep me locked into the "dark side" for now.

Apple's New Lineup

I was really tempted to buy the new retina MackBook Pro after drooling a bit at the Apple Store. The display was beautiful to look at, especially text readability and any high-res images, and I liked the smaller form factor and extra power, among other things.

However there were a few things with the rMBP that gave me pause:

Price - A 256GB HD isn't large enough for me so that means the $2800 model; add in tax and AppleCare and it's up to nearly $3,500. Talk about $ticker $hock.
Portability - After using a MacBook Air for a bit, that light, super portable form factor is hard to give up. The retina MBP is quite lighter than my MBP but it still feels heavy and large next to the Air.
The Bleeding Edge - The icons in many third party apps look pretty bad with such an HD display. While major apps were/are updated quickly, others will take some time. I have more concerns about website images which aren't likely to be upgraded any time soon just to clean them up for HD displays at the cost of slower load times. I've also seen posts regarding plasma style image burn-in, overheating, and resolution issues in Windows to name a few.

Those things were enough for me to decide against a rMBP for now. I considered the standard MBP which was still refreshed enough and a decent middle ground between the extremes of the rMPB and the Air. Ultimately though it was still pricey and portability is more important to me these days. So I decided it was time to look seriously at the MBA.

Evaluating the Air

The initial Air model seemed more like a lightweight netbook for email and surfing by execs. Last year's model seemed beefed up enough for several developers to be happy with them as dev machines. With the 2012 model especially I felt like they had sufficient power and the benchmarks beat my MBP. I decided to go ahead and buy a fully loaded 13" Air with 512GB flash storage, 8GB RAM, and a 2.0GHz dual core i7. I figured I had 14 days to return it if it didn't work for me.

Initial Impressions

Connections

Connecting my Apple LED Cinema display (prior generation model) was a little awkward. First the power cord doesn't fit the Air; I knew this ahead of time but wasn't fond of another cord to run and leaving the monitor's laptop power cord hanging felt strange. The other minor annoyance was that the thunderbolt port was on the right side of the Air, instead of the left side where the Mini DisplayPort is on my MBP. This meant a further, tighter cord stretch with my desk setup. However those are minor complaints and at least Thunderbolt is backwards compatible with Mini DisplayPort connections and the monitor still works great.

I decided to bite the bullet and spring for a $99 super drive. While I rarely use optical discs, I did have some installs of large software packages that I preferred not to re-download, and some older software that can't easily be found online. Additionally I have data on some discs that I occasionally need to read and didn't want to connect a really old and bulky external disc drive I had.

Weight and Size

I got an idea of weight and size of the Air in the Apple store but it wasn't until using it at home that I really appreciated it. My MBP which never felt *that* heavy suddenly felt like a tank. Before I rarely unplugged it and removed it from my desk but with the Air I found myself taking it all over instead of reaching for my iPad as much or returning to my desk.

Speed

Cold boot time with the SSD (my first) was just over 20 seconds, including my fumbling around with the mouse and keyboard to type my password. Installs and app launches were very zippy and I was quite pleased. Going to and from sleep was nearly instantaneous.

Bootcamp Debacle

To Bootcamp or not to Bootcamp

Bootcamp bothered me in the past with subpar drivers from Apple and having to partition the hard disk and dual boot or pay a performance penalty using a VM like Parallels or Fusion against Bootcamp. However there were enough issues with going VM-only that brought me back to Bootcamp:

Phone emulators - Some mobile dev emulators such as Windows Phone wouldn't run under Parallels; the VM inside a VM Inception type problem. However I believe Fusion worked and maybe this has since been fixed in Parallels.
Silverlight - there was at least one Silverlight runtime issue that was specific to running inside a VM.
Compatibility, performance - some other select apps and games had problems running virtually either compatibility wise or performance wise.

To the best of my knowledge the situation with these types of issues hasn't changed much. Issues aside, if I'm going to be doing longer periods of Windows development on my Mac, it is convenient to just boot into Windows in ways (especially with the speedy SSD). So bootcamp it is.

Bootcamp Setup While Half Asleep

I made the mistake of setting up Bootcamp while half asleep and without coffee and I gave it no forethought whatsoever. I did this 3 years ago after all, who needs forethought? So have a laugh at my expense. Go on.

Fail 1

Attempted to get away with 4GB USB thumb drive. Win7 was a bit over 3GB but w/bootcamp drivers etc. it wasn't enough. 8GB thumb drive it is.

Fail 2

Tried creating an ISO from a Win7 DVD using Toast and my MBP. Somehow it produced a corrupt ISO.

Fail 3

Tried creating an ISO from a Win7 DVD using Disk Utility and my MBP:

Selected disc in Disk Utility
File->New Disc Image From
Chose the CD/DVD .cdr option
Saved .cdr to my public folder
Renamed .cdr to .iso (seriously Apple why not .iso)
Pointed Bootcamp assistant on my Air to Win7 iso on my MBP public folder
Copied 25% of Windows files and hung indefinitely

Fail 4

At this point I start to wake up and remembered I had the superdrive. Forget the dang thumbdrive. In Bootcamp Assistant I dedicated 200GB to the Windows partition, leaving some 230GB to the Mac side. However Bootcamp assistant did not give the option of using the external disc drive; only a thumb drive. I was able to uncheck that but when rebooting it tried to boot off the thumb drive and not the DVD. I tried holding down the Option key and selecting the disc drive but received a "CDBOOT: Couldn't find BOOTMGR" error.

Fail 5 / Win 1

Okay well that disc should have been bootable but maybe the Air doesn't allow booting off a Windows disc from an external disc drive. Fine, back to the thumb drive it is; I copied the iso from my Air to it and went back to Bootcamp Assistant. I chose the same partition size as before and I rebooted. Now I was in Windows setup and after formatting the bootcamp partition I was into Windows and all looked good for a moment. Then I noticed networking wasn't working along with about everything else. I realized the bootcamp drivers weren't installed and for some crazy reason I thought for a moment that they should have been automagically installed already. Coffee Geoff, coffee. I browsed to the bootcamp setup on the thumb drive and afterwards all was right with the world.

Setting Up For Development

After about a hundred Windows Updates, I installed Visual Studio 2010 w/SP1, VS2012 RC, ReSharper, various VS extensions, DropBox, SnagIt, SkyDrive, and other misc apps. I fired up Visual Studio 2012 and opened some projects and all felt good. However I was more curious of how it performed from the Mac side. I installed Parallels 7 and dedicated 3GB of RAM and 2 CPUs to the bootcamp VM.

Performance

Here is screencast I captured that gives an idea of performance.

So I could launch Windows and startup apps in a VM, open VS 2012 w/various addons, load a modest sized solution like SignalR, build and run it in ~2 minutes which is certainly acceptable to me.

Other Misc. Timings

Windows and VS 2012 fully loaded and ready via Parallels: ~45 seconds
git clone SignalR: < 8 seconds
Initial SignalR build.cmd run (includes executing unit tests): under 2 mins
Cold boot time into Mac including entering password and startup apps: < 22 seconds

MBP Comparision

The performance blows away my MBP. Getting Windows and VS 2012 fully loaded via Parallels for example could take as long as 13 minutes on my MBP, compared with 45 seconds on the Air. Although then again my MBP doesn't have an SSD and that's the majority of the difference along with 3 years of age. It would be more interesting to compare development related timings between the Air and the rMBP.

The Boot Selection Screen

When holding down the Option key at startup to boot Windows, it took longer than on my MBP to kick off Windows after selecting it and hitting Enter. My best guess was the addition of the WiFi dropdown on the Air that I do not get on my MBP. I have several wireless networks in my area and it appears the delay is trying to scan and list them all. I wonder if that feature can be turned off?

Putting it to Work

Heat and Fan

Over more extended Visual Studio development sessions (Parallels or straight boot camp) or during movie editing with Quicktime or iMovie, the laptop got a bit warm and the fan would kick on for a while and seemed rather noisy. Part of that is more noticeable because of the otherwise silent operation I think. In general the Air didn't get too hot or too loud for too long.

Battery Life

Battery life was excellent, coming close to the the advertised 7 hour mark, at least while staying in Mac land. Rebooting into Windows and staying there drained it a good deal quicker but still pretty good life.

Windows

It is a shame the bootcamp drivers dumb things down so Windows cannot take full advantage of the hardware like the Mac side can (graphics switching, CPU boost, smarter power mgt). I'm not sure whether to buy the conspiracy theories that Apple is trying to make Windows look bad or if it is more that there is not much incentive for them to take the kind of time to support that.

A Freak Dock Issue

One strange issue happened when I plugged in the Air to charge it and then accidentally deleted the Desktop background image. The fan kicked on hard and the CPU usage went up to almost 100%. When I checked things out it was the Dock process. Killing it and other apps didn't help. A reboot fixed the issue and it hasn't happened since. I did see others mentioning a similar issue online in reference to an older version of Parallels.

Summary

At the end of the day this is still a modestly powered portable laptop and not a power workstation. So far though I do not see any indication that it can't serve well as my primary personal development machine. I'm sure over time as I load it up more it'll slow down and it won't be ideal for heavy HD video editing or games. Worst case scenario I'll switch over to my work laptop or back to a desktop for heavy duty work should it get to that but I'm not sure it will. I would rather sacrifice some power for the portability, price and battery life and I cannot see myself giving this up yet. Time will be the ultimate test but so far, so good.

Trying Out Jobs in PowerShell

Geoff Hudik — Wed, 04 Jul 2012 20:51:51 +0000

An older app in our workplace stack is a webforms website project and it has a large enough directory structure to take a while to compile the site. I have to run the site a fair amount for a rewrite effort and it changes enough to make the initial build and run painfully slow.

Since I have been working on a build related PowerShell module lately, I thought precompiling the "legacy" site might be a good candidate for a background job. I have not used jobs in PowerShell before and for whatever reason I was having a hard time finding good, complete examples of using them. There were also some things that tripped me up, so here is an example for the future version of me to reference some day.

param (
	$TrunkPath = "D:\Projects\MyApp\trunk"
)	

function Start-WebsitePrecompile
{    
    $logFile = (join-path $TrunkPath "\build\output\logs\BackgroundCompile.log")
    "Build log file is $logFile"
        
    $msg = @"
Starting background compile of site. Use Get-Job to check progress. 
You may go on about your merry way but may want to leave the host open until complete.
"@
    
    Write-Output $msg
    $job = Start-Job -InputObject $TrunkPath -Name MyAppPageCompile -ScriptBlock {
        # doesn't appear transcription is supported here
        $trunk = $input

        Set-Alias aspnetcompile $env:windir\Microsoft.NET\Framework\v4.0.30319\aspnet_compiler.exe
        
        # see website solution file for these values
        $virtualPath = "/web"
        $physicalPath = (join-path $trunk "\web")
        $compilePath = $trunk + "\PrecompiledWeb\web"
        aspnetcompile -v $virtualPath -p $physicalPath -f -errorstack $compilePath        
    }
    
    # output details
    $job    
   
    Register-ObjectEvent $job -MessageData $logFile -EventName StateChanged `
        -SourceIdentifier Compile.JobStateChanged `
        -Action {            
            $logFile = $event.MessageData
            Set-Content -Force -Path $logFile `
            	-Value $(Receive-Job -Id $($Sender.Id) -Keep:$KeepJob | Out-String)
            #$eventSubscriber | UnregisterEvent
            Unregister-event -SourceIdentifier Compile.JobStateChanged
            $eventSubscriber.Action | Remove-Job
            Write-Host "Job # $($sender.Id) ($($sender.Name)) complete. Details at $logFile." 
        }
}

Some Notes

Everything inside the job's script block will be executed in another PowerShell process; anything from outside the script block that needs to be used inside must be passed into the script block with the InputObject parameter ($input). While this might be obvious it does mean potential refactoring considerations.
It didn't appear transcription was supported inside the script block which was disappointing.
I half expected that Start-Job would provide a parameter for a block to call when the job was complete. Register-ObjectEvent works but it's a bit verbose and isn't even mentioned in many posts talking about job management.
Like the job script block, the event handler action script block cannot refer to anything from the outside other than anything passed into the block with the MessageData parameter and automatic variables such as $event, $eventSubscriber, $sender, $sourceEventArgs, and $sourceArgs.
I went through some trial and error in getting the output from the job in the completed event. The code on line 36 and 37 worked fine but it was not the most obvious initial syntax.
There are a couple of ways to unregister events such as line 38, but I found that when I called the function again I received an error that the event was already subscribed to, so it was clear the unregistration was not working for some reason. The current code is working but similar code did not work previously. I dunno man, gremlins.
Event handler cleanup strikes me as a bit odd and this Register-TemporaryEvent script is worth a look.

I am tempted to refactor more of this developer build module process to use more background jobs to do more in parallel. However it is a bit tricky in that many of the functions are called both individually and chained together in driver functions and they need to work both in "foreground" and "background" modes. It would also mean a loss of rich progress reporting and things get more difficult in terms of debugging, output, code sharing, etc. Also, while multiple cores may help with parallel work, there's a law of diminishing returns to be considered as well as machine performance while attempting to do other work while PowerShell crunches away.

PowerShell Activity Progress with Time Estimates

Geoff Hudik — Mon, 25 Jun 2012 03:00:00 +0000

The Goal

Recently I worked on a PowerShell module to do various application build related functions on development machines. One side objective was multi-level activity progress reporting with time estimation so activity duration could be gauged over time. The desire was for this to be done generically and quickly as it was more of a nice-to-have.

In Action

While running this, progress reporting looked something like the below.

Calls to Record Activity Progress

Some low-level functions in this module might be called directly at times and other driver functions might get called to chain together several activities. Either way progress is recorded at each level. Each function simply invokes a call to record the start of an activity as the first step and stopping it as the last.

function New-Build() # params omitted, body simplified for brevity
{	
    Start-Activity "Performing a new build"
	$percentComplete = 0
	
	Log-Progress "Creating code" -PercentComplete $percentComplete		
	New-CodeGen
	$percentComplete += 33
	
	Log-Progress "Creating config" -PercentComplete $percentComplete		
	New-Config
	$percentComplete += 33
	
	Log-Progress "Creating DB" -PercentComplete $percentComplete
	New-DB -common
	
	Stop-Activity
}

function New-CodeGen ([bool]$buildStatusUpdate = $true)
{	
    Start-Activity "Running CodeGen with NAnt"
	# ... real work done here ...
	Stop-Activity
}

# ...

Starting an Activity

First a stack is created at the script level to store the activities. The Start-Activity function creates a new object to store the activity name, start time, total duration and estimated duration (more on that later). This information is pushed onto the stack and output is sent to Write-Progress and Write-Output.

$_activityStack = new-object Collections.Stack

function Start-Activity([string]$activity = $(throw "activity is required"))
{
    Write-Output "Activity starting: $activity"
    
    $act = new-object PSObject
    $act | add-member -membertype NoteProperty -name "StartTime" -value $(get-date)
	$act | add-member -membertype NoteProperty -name "Name" -value $activity    
	$act | add-member -membertype NoteProperty -name "TotalSeconds" -Value 0
    $act | add-member -membertype NoteProperty -name "EstimatedSeconds" `
		-Value (Get-ActivityEstimatedSeconds $activity)
    
    $_activityStack.Push($act)
    Log-Progress $activity
}

Stopping an Activity

Stop-Activity will pop the most recent activity off the stack and calculate the duration. It then writes the completion data to progress and output as well as to a stats file that stores the durations by activity name.

function Stop-Activity
{
    $id = $_activityStack.Count
    $act = $_activityStack.Pop()
    $ts = $(get-date) - $act.StartTime
	$act.TotalSeconds = $ts.TotalSeconds
    $time = ""
    
    if ($ts.TotalMinutes -ge 1) { $time = "{0:##.00} minute(s)" -f $ts.TotalMinutes }
    else { $time = "{0:##.00} second(s)" -f $ts.TotalSeconds }
    
	# TODO: add in $act.EstimatedSeconds if > 0
    $status = ("'{0}' complete in {1}" -f $act.Name, $time)
    Write-Progress -Activity $act.Name -Status $status -Completed -Id $id
    Write-Output $status
	
	Write-Stats $act 
}

Writing Activity Stats

Write-Stats takes in the activity object and adds it to an array. If the stats (CSV) filename exists it reads it in, sorts the data in descending time order, adds up to $maxKeep (50) existing records into the array, and removes the existing file. The stats filename is then written out with the most recent records.

function Write-Stats ($act = $(throw "activity is required"))
{	
	# initialize an array to hold recent stats for this activity
 	$recent=@()
	$recent += $act
	$statsFile = Get-StatsFilename
	$maxKeep = 50 # across all activities; several different, want a few of each
	
	if (Test-Path $statsFile)
	{
	 	# get a list of the $maxKeep-1 most recent stats and add each path to the $recent array
		# | Where-Object {$_.Name -eq $act.Name}
	 	Import-CSV $statsFile | Sort StartTime -Descending `
			| Select -Last ($maxKeep -1) | foreach {$recent+=$_}
		# remove the file as we have the data in memory and want to re-write w/top item # and desc time sort
		Remove-Item $statsFile -force
	}
	
	$recent | select StartTime, Name, TotalSeconds | Export-Csv $statsFile -NoTypeInformation
}

Getting Activity Estimated Time

Time estimation is done via reading in the CSV file, filtering on the activity name, adding the completion time for each to an array, and averaging those values.

function Get-ActivityEstimatedSeconds([string]$activityName)
{
    $statsFile = (Get-StatsFilename)
    $avg = -1
    
    if (Test-Path $statsFile) 
    {
        $totalSeconds=@()
        Import-CSV $statsFile | Where-Object {$_.Name -eq $activityName} `
			| foreach {$totalSeconds+=$_.TotalSeconds}
        $m = $totalSeconds | measure-object -ave
        $avg = $m.Average
    }	
	
    return $avg
}

Misc. Functions

Log-Progress writes both to standard out and to progress. It retrieves the current activity without removing it from the stack, formats the estimated completion time calculated earlier, and adds that to the progress information. The number of current activities is used as the progress bar id since there will be multiple levels; in my case everything is done serially. Initially I set the estimated seconds argument on Write-Progress but found it misleading; my script shells out to various other apps and that is blocking - it won't update via a timer or anything like that.

function Log-Progress([string]$msg, [int]$percentComplete = 0)
{
    Write-Output $msg
    $act = $_activityStack.Peek()
    $id = $_activityStack.Count
	# the problem with -SecondsRemaining is it won't auto update w/timer or anything 
	# so it will be helpful at first and then quickly misleading
	
	$actName = $act.Name
	
	if ($act.EstimatedSeconds -ge 0)
	{
		$estFinish = $act.StartTime.AddSeconds($act.EstimatedSeconds)
		$actName += " - Est. Finish @ " + $estFinish.ToString("hh:mm:ss tt")
	}
	
    Write-Progress -Activity $actName -Status $msg -PercentComplete $percentComplete `
        -Id $id #-SecondsRemaining $act.EstimatedSeconds
}

For simplicity all activity details are stored in the same file, up the max limit defined in Write-Stats.

function Get-StatsFilename
{
	# considered a separate file per activity but we can filter out of one file
	# too much clutter w/sep and would have to build a safe filename with activity name
	$file = (Join-Path (Get-StatsFilePath) "Stats.csv")
	return $file
}

function Get-StatsFilePath
{
	$path = (join-path $env:LOCALAPPDATA "MyCompany\MyApp\build_output\stats")
	if (!(Test-Path $path)) { New-Item $path -type directory | Out-Null }
	return $path
}

In Conclusion

Other options on timing activities include things like the Stopwatch class or PowerShell's Measure-Command. I'll use those more for ad-hoc measuring here or there. In the case of my module though, I found this "CSV stack" approach to work well as a simple, generic way to time everything across the board. If there are a large number of activity records being kept, deep function chaining, and/or threading work this approach might be a bit more problematic and slow.

CodeStock 2012 Windows Phone App

Geoff Hudik — Wed, 16 May 2012 18:50:37 +0000

The CodeStock conference is coming up soon on June 15th in downtown Knoxville. As such I have upgraded the CodeStock 2011 Windows Phone app for this year's conference and am pleased to announce it has been published to the marketplace.

Marketplace

Video

Source Code

Changes Over Last Year's Version

I have not had much time this year to enhance the application but below are highlights of what changed for the 2012 version. For more details see the commit history.

Mango upgrade - OS target upgrade from 7.0 to 7.1 and many fixes to address breaking changes
Map view - new map view with various points of interest and directions. Points of interest are externally configured so if you have suggestions, let me know.
Branding - logo, title, date, image and theme related changes
Source control and hosting - switch from HG and bitbucket to git and github
New app, not an upgrade - Due to various factors this year's version was submitted as a new app and last year's was hidden. If by chance you have last year's version installed, uninstall it first.

Potential Future Changes

There is a chance I might make additional updates before the conference and might consider pull requests if you are so inclined. Feel free to add an issue for any bugs or feature requests.

Some changes I'd like to see in the future:

Live tile - maybe showing next session via schedule and/or favorite
Better twitter integration - i.e. more of a native twitter client instead of mobile twitter links.
More graceful public WiFi handling - better error message when an HTML response (from a WiFi logon page) was received instead of expected JSON. (change pending Marketplace approval in v2.2)

On another Windows Phone project I started refactoring the Phone.Common assembly out into multiple NuGet packages that are a bit more generic. I have not had the time to finish that or incorporate it into the CodeStock app yet.

Overview Video

The below video gives an overview of most of the features minus a few miscellaneous ones.

This page can also be accessed via http://www.geoffhudik.com/codestock-wp7.

Build Automation Part 4: Database and Report Deployments

Geoff Hudik — Mon, 14 May 2012 19:16:24 +0000

Series Index

Build Automation Part 1: Overview and Pre-build Tasks
Build Automation Part 2: Building and Packaging
Build Automation Part 3: App Deployment Script
Build Automation Part 4: Database and Report Deployments

Unlike deploying the application itself in its entirety each time, database and report items have required incremental deployments due to their nature and sheer size. The question becomes how to manage these increments in coordination with the application bits to ensure everything is in sync.

I do not pretend to have all the answers here. I was hoping this part of the process could get overhauled more with our last release but there is only so much time in the day.

Some Challenges

Size, Dependencies, Impact Analysis

On the (Oracle) database side of our operational app we have around 800 tables, 500+ packages, 500+ views, 300+ functions and procedures, and a variety of other object types across 3 schemas. Running schema compares / diffs and doing sync scripts has been a time consuming pain in the past, regardless of various tools we have tried.

The situation is complicated by some 10 database environments, other app databases our app is dependent on, various apps depending on our database, and dynamic SQL embedded into report RDL files or coming from ORM's like Entity Framework. Dependency and impact analysis can be difficult, particularly across systems.

On the report side this app has over 600 SSRS reports scattered over 8 servers, several folders and different versions of SQL Server Reporting Services.

Source Control

Source control for reports has not been a problem so much with using SSRS, other than TFS generating a lot of unnecessary merge conflicts on those XML RDL files.

On the database side we have had some success using Team Coding in Toad with the TFS MSSCCI Provider. Quest came out with a native TFS provider but it did not support TFS work item association which ruled out our use of it.

The MSSCCI provider "works" with Toad for basic changes like packages, procedures, functions, triggers, views, etc. but boy it is not without a lot of quirks. So much so that for a while I saved any database object script changes to files on my desktop out of fear my changes would get overwritten, which used to happen quite a bit. The other problem is that not all changes are source controlled such as table schema changes, data changes etc. We offset that via some SQL file attachments to tasks tied to a project.

Pulling Report and Database Changes

I posted before about a custom TFS Artifact Manager (hereinafter "TAM") tool for pulling down report and database changeset files and task attachments either for a single work item or a large batch of related work items, such as all tasks linked through a series of scenarios, backlog items and bugs tied to a project. I won't repeat those details here but we currently still use the tool to gather up all the report and database changes for a given project release. It far from perfect but it beats manual guesswork and building sync scripts from database compares.

The TAM tool is also used to pull artifacts from various single task ad-hoc changes made outside of any official product release. Many reports can be added to the application dynamically through some dynamic report forms with common parameters; new records are added to the database and the reports are deployed outside of any app deployment. Likewise there are occasional database changes made independent of the application.

There are other tools mentioned in the TAM post that we may try using more in the future. Also, Troy Hunt has a good series of deployment posts including this one regarding Automated database releases with TeamCity and Red Gate. Doing exactly that with our schemas would make me a bit nervous but perhaps with tweaks and some experiments in the future.

Additionally I posted a review on Red Gate's Schema Compare for Oracle which can be quite a useful tool. We don't rely on it as heavily anymore with custom tools and processes but it is handy to use it to double-check things after deployments or for doing more one-off database syncs.

Deploying Reports

Ad hoc Report Deployments

When deploying from Development to Test, our CI process picks up any reports merged from $/MyApp/Reports/Dev/ to $/MyApp/Reports/Main/ and automatically deploys those via PowerShell and RS Utility. Any corresponding database changes are manually applied before that. Environments beyond Test currently require attaching report and database changes to a Help Desk ticket and routing to a DBA. The DBA runs any database changes and deploys the reports using the script mentioned in the next section.

App Report Deployments

For reports to be deployed with a given build of an application, the process is basically the same as the ad-hoc process in respect to going from Dev to Test. One difference is on timing of merging the report changes in source control to correspond with any dependent changes to the application code. When moving beyond the Test environment, all reports tied to a given project work item are pulled using the TAM tool. They are then deployed in mass using PowerShell and the SSRS web service (without RS Utility), in a manner similar to this post on Uploading SSRS Reports with PowerShell.

Deploying Database Changes

We currently do not have much automation around ad hoc database deployments but not much is needed there.

For app database changes we start by pulling the database changes using the TAM tool. In that tool a script "package" is built by choosing the scripts to include and specifying any needed order or execution. Previously someone (dev or DBA depending on environment) would either execute all those manually by hand in Toad, or build out an index/driver script and run that. It was not as bad as it might sound, given the tool produced combined SQL scripts for views, packages, procs, etc. Still it was tedious if there were a number of data or schema migration scripts to be run in order.

Executing Database Scripts With PowerShell

Our resident Oracle expert Jim Tilson ("The Optimizer") had the idea of creating a PowerShell script that used SQL*Plus to generically execute all database scripts in a given directory. I paired with him to get the basic interaction going but this is his brainchild and work. He should probably be the one explaining this but no telling when that slacker will get around to blogging :). If you have any interest in Oracle, SQL optimization, database tech in general, or Ruby, you should reach out to him on Twitter and ask him to blog more (and tweet more while he is at it). At any rate this might be useful for others so I will post the code and attempt to explain it.

Structure

The script expects all the database script files to be located in subfolders where the script resides, one folder per schema name, and no subfolders with each schema folder (not recursive).

Each file in a schema folder will be executed regardless of filename extension. Ordering is based on filename; our TAM tool prefixes a numeric wart on each file to ensure an obvious order. At the moment the script does not explicitly specify a name ordering but that's the default.

Executing Scripts for Each Schema

At the bottom of the script, the server TNS name is prompted for and a couple things are set before running the main run-scripts function.

set-location (Get-ScriptDirectory)
$dateWart = Get-DateWart
$server = read-host "Enter the server TNS name"
run-scripts
echo "Successfully ran all scripts."

Run-Scripts invokes a function to run the scripts for each schema, passing along the user and server info. This could be made more generic by assuming any subfolder where the PowerShell script resides represents a schema with database scripts to run.

function Run-Scripts
{
    foreach ($user in @("USER_SCHEMA_1", "USER_SCHEMA_2", "USER_SCHEMA_3")) 
	{ 
		run-scriptsforschema -server $server -user $user
	}
}

Running Scripts for a Schema

This function will temporarily set location to the schema subfolder corresponding to the user/schema name passed in. It prompts for a password for a later connection to that schema. Finally it enumerates all files in the schema folder, calls a Run-Script function to execute each, and writes progress as it goes.

Each successfully executed file is moved into a Completed subfolder. That file move is important as many migration scripts are written assuming they will only be run once and we have been bit by DBA's accidentally running scripts more than once.

function Run-ScriptsForSchema($user)
{
    echo "Running scripts for $user."
    push-location    
    set-location $user    
	$password = get-password($user)    
    ensure-directory(".\Completed")

    $files = @(get-childitem | where {!$_.PsIsContainer})
	$count = 0
	
    foreach ($fileInfo in $files)
    {        
        write-progress -activity "Running scripts for $user" `
			-currentoperation $fileinfo.name -status ("Executing") `
			-PercentComplete (100*$count/$files.count)
        Run-Script $user $password $fileInfo
        $count++
        write-progress -activity "Running scripts for $user" `
			-currentoperation $fileinfo.name -status ("Done") `
			-PercentComplete (100*$count/$files.count)
        move-item -path $fileInfo.fullname -destination ".\Completed" -Force
    }
    
    write-progress -activity "Running scripts for $user" -status ("Complete") -completed
    pop-location    
    echo "Completed scripts for $user"
}

Running a Script

The Run-Script function takes care of some logging and calls a normalize function to tack on additional SQL before and after the SQL contained in the file (error handling, commits, etc.); more on that in a moment. Function notes follow.

Path - the sqlplus location should be in the SYSTEM PATH environment variable so fully qualifying it should not be needed. In my case the location is C:\app\[username]\product\11.2.0\client_1\.
-L Parameter - instructs the app to only attempt to log on once; otherwise w/bad credentials it can get hung awaiting input.
-M Parameter - indicates HTML output is desired from sqlplus.
Credentials - The server name captured earlier is passed in along with the user/schema and password parameter values.
SQL - the normalize script function returns a SQL string and that is piped into sqlplus to be executed.
Output - the output is sent to $logFile and the 2>$1 sends standard error to standard output.
Error checking - Finally $LASTEXITCODE is checked to see what sqlplus.exe exited with; if 0 it was successful, otherwise it is the Oracle error number. The process stops on any error; manual changes might be needed to address any problems then the script can be run again.

function Run-Script($user, $password, $fileInfo)
{
    $logDir = ("..\Logs\{0}\{1}" -f $dateWart, $user)
    ensure-directory $logDir
    $logFile = join-path $logDir ($fileInfo.basename + ".html")
    
    (normalize-script $fileinfo.fullname) | sqlplus.exe -L -M "HTML ON SPOOL ON" `
		-S "$user/""$password""@$server" >> $logfile 2>$1

    $lec = $LASTEXITCODE
    
    if ($lec -ne 0)
    {
        write-error ("ERROR executing {0}!" -f $fileInfo.FullName)
        exit
    }
}

Adjusting the SQL

There are two critical adjustments made to the SQL read from the database script files to execute. The first is detecting a SQL error and exiting SQL*PLus with the error code. The other is issuing a commit at the end; most of our data related scripts do not include a commit as often they are ran and verified before issuing a commit. It is worth reading over the WHENEVER SQLERROR documentation as some types of errors will not trigger an exit; fully checking for all types of errors might require something more brittle like scanning the log files for certain error phrases.

function normalize-script($filename)
{
@"
    whenever sqlerror exit sql.sqlcode
    set echo off
    set termout off
    $([string]::join("`n", (get-content $fileinfo.fullname -readcount 0)))
    commit;
    exit
"@
}

Helper Functions

At the top of the script are some helper functions and an interop services dll is loaded for later use in translating the secure password to a plain text string to be passed along to SQL*Plus.

[Reflection.Assembly]::LoadWithPartialName("System.Runtime.InteropServices")

function Get-ScriptDirectory
{
    Split-Path ((Get-Variable MyInvocation -scope script).Value.MyCommand.Path)
}

function ensure-directory($dir)
{
    if (!(test-path $dir)) { new-item $dir -type directory }
}

function Get-DateWart()
{
    get-date -uformat "%Y %m %d %H %M %S"
}

function get-password($user)
{
    $enterpassword = read-host -AsSecureString "Password for $user@$server"
    [System.Runtime.InteropServices.Marshal]::PtrToStringAuto(`
		[System.Runtime.InteropServices.Marshal]::SecureStringToBSTR($enterpassword));
}

Analyzing the Results

The script stores logs under a Logs\[Timestamp]\Schema\ folder for troubleshooting and verification purposes.

SQL*Plus Alternatives

One alternative to SQL*Plus is using OracleCommand's ExecuteNonQuery method in Oracle.DataAccess.dll. I tried this approach back when I created an OracleScriptExecutor utility app that was designed to easily run SQL Scripts against multiple schemas. It was a bit of a nightmare that I do not recommend. For one you have to deal with annoyances like linefeed issues, semicolon and BEGIN/END block issues, and it is quite difficult to deal with multiple scripts combined in one SQL file (i.e. '/' delimited). It almost requires a full blown SQL parsing engine to handle it correctly so I'd rather delegate that pain to a tool like SQL*Plus that already handles such complexity.

In Conclusion

This really only scratches the surface of the problems and solutions in dealing with database and report deployments. With some time and TLC I am sure this beast could be further tamed. Thoughts, suggestions, tips, helpful tools, processes? Leave a comment!

I am running out of time in this series but hopefully I can touch on some CI details with TeamCity next.

Build Automation Part 3: App Deployment Script

Geoff Hudik — Wed, 09 May 2012 19:32:29 +0000

Series Index

Types of Deployment Scripts

We currently have different deployment scripts that are run independently though there is a desire to chain them together in automated fashion when time allows.

Application - Deploys the application bits
Database - Deploys the database script changes for a given project release
Reports - Deploys SSRS report changes for a given project release

The database and report artifact deployments are deserving of a dedicated post to this in the future. This post will focus on the application deployment script.

Deployment Script Skeleton

Looking at the script in a top-down fashion is best I think. Some of the helper functions being called will be listed later.

Top

param (
    [string]$DeployToServer = "",
    [switch]$SkipBackup = $false,
    [switch]$automated = $false
) 

$global:ErrorActionPreference = "Stop"

# error on uninitialized variables, non-existent properties, bad function calls
Set-StrictMode -version 2

At the top of the script some script preferences are set and the following parameters are defined:

DeployToServer - Name of the target server to deploy to. The idea is this would bypass a prompt where the user chose the server to deploy to. This would generally be set by a CI process. At the moment this isn't being used in the script as our build server went down in flames before I could make use of this.
SkipBackup - Allows turning off default behavior of backing up the existing app installation on the target deployment server.
Automated - This was meant to control whether the script ever paused for any user-interaction or not. It is used in a couple of places but not fully implemented. It could be replaced by use of DeployToServer but I wanted to be explicit. Typically this would just be set from a CI build.

Bottom

After all the functions in the deployment script, the following script level variables are defined. I went with an $_ naming convention for script level variables; $script:variableName may have been better but more verbose.

$_scriptPath = (get-scriptdirectory)

# import generic deployment script functions
. (join-path $_scriptPath "Deploy-Common.ps1")

$_packagePath = $_scriptPath # for now anyway, just being explicit here
$_transcriptFile = (join-path $_scriptPath "DeployTranscript.txt")

$_targetServer = ""
$_targetClickOnceDir = ""
$_targetSatelliteDir = ""
$_targetServicesDir = ""
$_targetRoot = ""
$_envName = ""

$_activity = "Initializing"
$_zipFileObject = $null

$_successfulDeploy = $false

$_scriptErrorMessage = ""
$_clickOnceUrl = ""
$_deployTS = $null

At the very bottom is the call to the main Publish-App function with error handling, invoking the product web page if successful, and transcript logging and emailing.

try 
{
    Init
    Publish-App
    
    if (!$script:automated)
    {
        $_clickOnceUrl = ("http://{0}.domain.com/MyApp/" -f $_targetServer)
        "Launching app landing page at $_clickOnceUrl"
        Invoke-InternetExplorer $_clickOnceUrl
    }
    
    $_successfulDeploy = $true
}
catch [System.Exception]
{
    $_scriptErrorMessage = ("Deployment failed with error: {0}{1}{1}Script: {2}  Line,Col: {3},{4}" `
		-f $_.Exception.ToString(), [System.Environment]::NewLine,  $_.InvocationInfo.ScriptName, `
		$_.InvocationInfo.ScriptLineNumber, $_.InvocationInfo.OffsetInLine)
    Write-Warning $_scriptErrorMessage    
}
finally
{
    Write-Progress "Done" "Done" -completed
    
    if (Get-CanTranscribe)
    {
        Stop-Transcript
        Send-Notification
    }
}

if (!$_successfulDeploy) { invoke-item  $_transcriptFile }

# if not an automated deploy then pause
if (!$script:automated)
{
    "`nPress enter to continue..."
    [void][System.Console]::ReadLine()
}

Initialization

The Init function kicks off transcription, reads in build version information from a file (See Initialization in Part 1), tacks on to the PATH environment variable, and sets up the PowerShell UI shell.

function Init
{
    #setting $ErrorActionPreference here doesn't appear to effect anything
    try { Stop-Transcript | out-null } catch { }    
    
    if (Get-CanTranscribe) { Start-Transcript -path $_transcriptFile }

    $buildInfo = Get-BuildInfo
    $env:path += ";$env:windir\Microsoft.NET\Framework\v4.0.30319;$env:windir\System32"
   
    # customize window shell
    if ($Host -and $Host.UI -and $Host.UI.RawUI)
    {
        try 
        {
            $ui = (Get-Host).UI.RawUI                
            $ui.WindowTitle = ("Deploy MyApp {0} ({1})" `
				-f $buildInfo.AppVersion, $buildInfo.FileVersion)
            
            if (!(Get-IsHostISE))
            {
                $ui.BackgroundColor = "DarkBlue"
                $ui.ForegroundColor = "White"
                $bufferSize = $ui.BufferSize
                $bufferSize.Width = 120
                $bufferSize.Height = 9000
                $ui.BufferSize = $bufferSize
                $winSize = $ui.WindowSize    
                $winSize.Width = 120
                $winSize.Height = 70
                $ui.WindowSize = $winSize
            }
        }
        catch [System.Exception]
        {
            ("Error configuring host UI: {0}" -f $_.Exception.Message)
        }
    }
}

Deployment Target Menu

This function is intended for user-interactive execution of the deployment; in our case this was mostly for production-level environments where another group performed the deployment. However it also came in handy in some other scenarios where we could not do completely automated continuous deployment, such as a period where our CI server was all hosed up. Additionally there are times where it is handy to push a custom build from anywhere to anywhere, outside of the normal process flow.

For automated CI deployments a target server name would be passed in and this user menu interaction would be skipped. This function displays a menu of valid target environments to deploy to, sets the target server accordingly, and invokes a deployment function with that target server name.

For the menu I originally tried just using $Host.ui.PromptForChoice as in this article by James O'Neill. However I did not like how that laid out; everything was rendered horizontally instead of vertically and some things ran together or were not spaced to my liking. That lead me to this post by Jeff Hicks which my menu is based on; the Show-Menu function in the switch statement below is his function which I did not modify.

function Publish-App
{
    $menu = " `
    1 Development `
    2 Iteration `
    3 Test `
    4 Pre-release Training `
    5 Production `
    6 Post-release Training `
    `    
    C Cancel `
`    
Your choice "
   
    $targetServer = ""
    $script:_envName = ""
    $buildInfo = Get-BuildInfo
	$title = ("Select Target Destination for MyApp {0} ({1})" `
		-f $buildInfo.AppVersion, $buildInfo.FileVersion)

    # Keep looping and running the menu until the user selects a valid item or cancels.
    Do
    {
        switch (Show-Menu $menu $title -clear)
        {
           "1" { $targetServer = "dev-server"; $script:_envName = "Development"; }
           "2" { $targetServer = "itr-server"; $script:_envName = "Iteration"; }
           "3" { $targetServer = "tst-server"; $script:_envName = "Test"; }
           "4" { $targetServer = "pre-server"; $script:_envName = "Pre-release"; }
           "5" { $targetServer = "prod-server"; $script:_envName = "Production"; }
           "6" { $targetServer = "post-server"; $script:_envName = "Post-release"; }
           "C" { Write-Output "Cancel"; return; }           
        }
    
    } While (!$script:_envName -and !$targetServer)
    
    if ($targetServer -and $script:_envName)
    {    
        $choiceYes = New-Object System.Management.Automation.Host.ChoiceDescription "&Yes", "Answer Yes."
    	$choiceNo = New-Object System.Management.Automation.Host.ChoiceDescription "&No", "Answer No."
    	$options = [System.Management.Automation.Host.ChoiceDescription[]]($choiceYes, $choiceNo)
    	$result = $host.ui.PromptForChoice("Confirm deployment target", `
			"Deploy My App to $_envName ($targetServer)?", $options, 0)
        
        if ($result -eq 0)
        {
            Publish-ToServer $targetServer -skipBackup:$script:skipBackup
        }
        else 
        {
            Write-Output "Deployment cancelled"
        }
    }
}

Server Deployment Driver Function

This function sets some script level variables such as common folder locations, and calls functions to perform cleanup, backup any existing installation (see this post), and deploy ClickOnce, satellite and service files.

function Publish-ToServer (
    [string] $targetServer = $(throw "targetServer is required"),
    [switch] $skipBackup = $false )
{
    $startTime = [DateTime]::Now
    Write-Output "`n"
    Set-Activity "Deploying to $targetServer"
    Write-Log "Beginning deploy to target server $targetServer"
    $script:_targetServer = $targetServer
    $script:_targetRoot = "\\$targetServer\Share$"
    $script:_targetClickOnceDir = "\\$targetServer\Share$\MyApp\ClickOnce"
    $script:_targetSatelliteDir = "\\$targetServer\Share$\MyApp\Satellite"
    $script:_targetServicesDir = "\\$targetServer\Share$\MyApp\Services"
    
    Clear-OldFiles
    if (!$skipBackup) { Backup-ExistingInstall }
    
    Publish-ClickOnceFiles
    Publish-SatelliteFiles
    Publish-Service
    
    $script:_deployTS = [DateTime]::Now - $startTime   
    Write-Log ("Published to $targetServer in {0:N0} minute(s) and {1} second(s)`n" `
		-f [math]::floor($_deployTS.TotalMinutes), $_deployTS.Seconds)
}

Cleanup Before Backup

Before backing up the existing target folders, the script does some cleanup to remove some files and folders that are not desirable for backup. Mostly this cleanup is around removing old ClickOnce folders; because of the version naming convention there will quickly be a large number of folders.

The below function will look for folders ordered by modified time descending and select the first one to determine the most recent ClickOnce folder (you could argue some holes with that logic). It will then keep only that one, getting rid of all the others. In this way it will only be backing up the last ClickOnce folder. If you are starting fresh this is not a problem per se but in my case there were many existing versions out there already.

function Clear-OldFiles
{
    Set-Activity "Cleaning up old ClickOnce versions"
	Clear-OldClickOnceAppFiles $_targetClickOnceDir	
	# additional cleanup here removed...
}

function Clear-OldClickOnceAppFiles ($rootDir)
{
    if (!(Test-Path $rootDir))
    {
        Write-Log "$rootDir doesn't exist; nothing to do"
        return;
    }

    # exclude on subdirectory names doesn't seem to work
	# so we'll just rename dir, grab most recent child, copy over    
    # http://tinyurl.com/copy-item-exclude
    $appFilesDir = (join-path $rootDir "\Application Files")
    
    if (!(Test-Path $appFilesDir))
    {
        Write-Log "Didn't find Application Files folder at $appFilesDir; nothing to do"
        return
    }
    
    Write-Log ("Removing old ClickOnce app files beyond one version back from {0}" `
		-f $appFilesDir)
    $folders = @(Get-ChildItem -Path $appFilesDir -recurse `
		| Where-Object {$_.PSIsContainer})
        
    if ($folders.Length -le 1)
    {
        Write-Log ("No old versions to remove (folder count was {0}); exiting" `
			-f ($folders.Length))
        return
    }
    else 
    {
        Write-Log ("Found {0} ClickOnce version folder(s)" -f ($folders.Length))
    }
    
    Write-Log "Renaming $appFilesDir to Application Files Temp"
    Rename-Item $appFilesDir "Application Files Temp"    
    
    Write-Log "Determining most recent ClickOnce app files subfolder"
    $appFilesTempDir = (join-path $rootDir "\Application Files Temp")    
    $mostRecentAppFilesDir = Get-ChildItem -Path $appFilesTempDir `
		| Where-Object {$_.PSIsContainer} `
		| Sort-Object LastWriteTime -Descending | Select-Object -First 1
    Write-Log "Most recent app files dir is $mostRecentAppFilesDir"        
    
    New-Item $appFilesDir -type directory
    Write-Log ("Copying {0} to $appFilesDir" -f ($mostRecentAppFilesDir.FullName))
    copy-item -recurse $mostRecentAppFilesDir.FullName $appFilesDir    
    
    $folderCount = ((Get-ChildItem -Path $appFilesTempDir `
		| Where-Object {$_.PSIsContainer})).Length
    Write-Log ("Removing {0} old version(s)" -f ($folderCount-1))
    Remove-Dir $appFilesTempDir
    
    Write-Log "Old ClickOnce app files removed"
}

Deploying Satellite Files

Because some of the client satellite files are loaded directly off the network by this app, some files will be locked if users are running the app. This function first calls a helper function that uses PowerShell remoting to disconnect file sessions to a remote server. I'm not a fan of loading assemblies directly off a network share; I think syncing the client files with the server and then loading on the client is better but it is what it is.

The function then deletes all the files in the target Satellite directory minus the config file. At the moment the deployment script is not updating configuration files though that was the plan in the beginning.

There is also a hackish sleep call between deleting files and copying as there were sporadic access denied errors of a locking / timing nature. Finally a call is made to a copy helper function that has support for additional attempts on error as well as outputting the results of what was copied.

function Publish-SatelliteFiles
{
    Set-Activity "Deploying Staging files"    
    Disconnect-FileSessions $_targetServer   
           
    # exclude deleting config - currently configured by hand until it can be automated
    Remove-RootFilesInDir $_targetSatelliteDir -exclude "MyApp.Client.exe.config"
    
    "Pausing between delete and copy"
    Start-Sleep -s 3
    
    Copy-Files -from "$_packagePath\Satellite\**" -dest $_targetSatelliteDir `
		-recurse -attempts 2
}

Deploying ClickOnce Files

The ClickOnce deployment is similiar.

function Publish-ClickOnceFiles
{
    Set-Activity "Deploying ClickOnce files"
    Disconnect-FileSessions $_targetServer
    
    Remove-Dir (join-path $_targetClickOnceDir "Application Files")    
    Remove-RootFilesInDir $_targetClickOnceDir
    
    "Pausing between delete and copy"
    Start-Sleep -s 3
    
    Copy-Files -from "$_packagePath\ClickOnce\**" -dest $_targetClickOnceDir `
		-recurse -attempts 2
    Copy-Files -from "$_packagePath\BuildInfo.csv" -dest $_targetClickOnceDir
}

Deploying Service Files

I posted Install a Windows Service Remotely with PowerShell a while back so refer to it for additional details such as the functions Uninstall-Service, Install-Service and Start-Service.

function Publish-Service
{
    Set-Activity "Deploying Service files"
    $serviceName = "MyAppDataService"
    
    Write-Log "Stopping, uninstalling service $serviceName on $_targetServer"
    Uninstall-Service $serviceName $_targetServer
    "Pausing to ensure files are not locked during delete..."
    Start-Sleep -s 5 # Yeah I know, don't beat me up over this
    
    Remove-RootFilesInDir $_targetServicesDir    
   
    Copy-Files "$_packagePath\Services\**" $_targetServicesDir -recurse
    New-RestartServiceCommand
    
    Install-Service `
    -ServiceName $serviceName `
    -TargetServer $_targetServer `
    -DisplayName "MyApp Data Service" `
    -PhysicalPath "D:\Apps\MyApp\Services\MyApp.DataService.exe" `
    -Username "NT AUTHORITY\NetworkService" `
    -Description "Provides remote TCP/IP communication between the MyApp client application and the database tier."
        
    Start-Service $serviceName $_targetServer
}

The New-RestartServiceCommand function creates a batch file that restarts the Windows service. On each target server there is a scheduled task that invokes this batch file daily late at night. Originally that was done to help ensure any memory and network resources were properly released in the event of unexpected issues. The scheduled task is currently a one-time manual setup process though creating it could certainly be automated as well.

function New-RestartServiceCommand
{    
    $file = (join-path $_targetServicesDir "MyAppServiceRestart.bat")
    "Creating $file for the nightly scheduled task to restart the service"
    if (Test-Path $file) { Remove-Item -Force $file }
    Add-Content $file "REM This is for automatically restarting the MyApp data service via a nightly scheduled task"
    Add-Content $file "net stop `"MyApp Data Service`""
    Add-Content $file "net start `"MyApp Data Service`""
}

Some Common Helper Functions

Some of the common helper functions used are below (functions detailed in other referenced posts are omitted).

File I/O

function Copy-Files([string]$from, [string]$dest, [switch]$recurse, [int]$attempts = 1)
{
    "Copying $from to $dest with recurse $recurse" 
    $result = $null
    for ($i=1; $i -le $attempts; $i++)
    {
        try 
        {
            $result = Copy-Item -Recurse:$recurse -Force -PassThru $from `
				-Destination $dest
            break
        }
        catch [System.Exception]
        {
            if ($i -lt $attempts)
            {
                ("Copy failed: '{0}'. Pausing. Max attempts: {1}, Attempts: {2}" `
					-f $_.Exception.Message, $attempts, $i)
                Start-Sleep -s 3
            }
            else { throw }
        }
    }
    
    if ($result) {foreach ($i in $result) {("Copied {0}" -f $i.FullName)}}
}

function Remove-Dir([string]$path)
{
    if (Test-Path $path)
    {
        Write-Output "Removing folder '$path'"
        Remove-Item -recurse -force $path
    }
}

function Remove-RootFilesInDir([string]$path, [string]$pattern = "*.*", `
	[string[]]$exclude)
{
    $deleteWhat = (join-path $path $pattern)
    "Removing $deleteWhat"
    remove-item -Force $deleteWhat -Exclude $exclude
}

PowerShell Host Related

function Get-CanTranscribe
{
    # probably not the best way to answer this question but will at least rule out ISE
    return (!(Get-IsHostISE))
}

function Get-IsHostISE
{
    return ((Get-Host).Name -eq "Windows PowerShell ISE Host")
}

function get-scriptdirectory 
{ 
    if (Test-Path variable:\hostinvocation) 
    {
        $FullPath=$hostinvocation.MyCommand.Path
    }
    else 
    {
        $FullPath=(get-variable myinvocation -scope script).value.Mycommand.Definition
    }
    if (Test-Path $FullPath)
    { 
        return (Split-Path $FullPath) 
    }
    else
    { 
        $FullPath=(Get-Location).path
        Write-Warning ("Get-ScriptDirectory: Powershell Host <" + $Host.name `
			+ "> may not be compatible with this function, the current directory <" `
			+ $FullPath + "> will be used.")
        return $FullPath
    }
}

Miscellaneous

# note that net session \\computername /delete won't work w/remote deployment
#     NET SESSION displays incoming connections only.
#     In other words it must be run on the machine that is acting as the server.
# Enabling PS Remoting: http://technet.microsoft.com/en-us/magazine/ff700227.aspx
# 1) On target server ensure that winrm service is running
#    In PowerShell: get-service winrm
#
# 2) Enable PS remoting on the target server
#    Enable-PSRemoting –force
function Disconnect-FileSessions ([string]$server = $(throw "server is required"))
{
    "Disconnecting file sessions to $server"    
    $S=NEW-PSSESSION –computername $server
    INVOKE-COMMAND –Session $s –scriptblock { (NET SESSION /delete /y) }
    REMOVE-PSSESSION $S
}

function Invoke-InternetExplorer([string]$url)
{
    $IE=new-object -com internetexplorer.application
    $IE.navigate2($url)
    $IE.visible=$true
}

function Send-Email($from, $to, $subject, $body, $smtpServer = "mail.domain.com", `
	$attachment = $null, $isHtmlBody = $true)
{
    $smtp = new-object Net.Mail.SmtpClient($smtpServer)    
    $msg = new-object Net.Mail.MailMessage
    $msg.From = $from
    $msg.To.Add($to)
    $msg.Subject = $subject
    $msg.IsBodyHtml = $isHtmlBody
    $msg.Body = $body
    
    if ($attachment)
    {
        $att = new-object Net.Mail.Attachment($attachment)
        $msg.Attachments.Add($att)
    }
    
    $smtp.Send($msg)
    $att.Dispose | out-null
}

Other Functions

Other functions that are not as generic/common in nature but are included in the main script follow.

Retrieving Build Information

The build info file discussed previously in this series is packaged in the same directory as the script and read for displaying in the PowerShell console and in sending a deployment notification.

function Get-BuildInfo
{    
	$buildInfoFile = (join-path (scriptdirectory) "BuildInfo.csv")
	return Import-Csv $buildInfoFile
}

A sample of this file:

"AppVersion","FileVersion","BuiltOn","ClickOnceRevision","ClickOncePublishVersion"
"3.3.0.17","2012.05.07.1008","5/7/2012 10:08:53 AM","117","3.3.0.117"

Logging, Diagnostics and Progress

function Set-Activity([string]$activity)
{
    $script:_activity = $activity
    Write-Log "Current Activity: $_activity"
}

function Write-Log ([string]$message)
{
    write-output $message
    write-progress -activity $_activity -status $message
}

Backup Functions

Functions such as Backup-ExistingInstall, Backup-Dir, and Compress-Files are included in Compression Experiments In the Build and Deployment Process.

Deployment Email

function Send-Notification
{
    $buildInfo = Get-BuildInfo
    $env = $script:_envName
    $appVer = $buildInfo.AppVersion
    $fileVer = $buildInfo.FileVersion
    $publishVer = $buildInfo.ClickOncePublishVersion
    $builtAt = $buildInfo.BuiltOn
    
    $deployText = "deployed"
    if (!$_successfulDeploy) {$deployText = "deployment failed"}
    
    $subject = "MyApp v {0} {1} to {2} ({3})" -f $buildInfo.AppVersion, `
		$deployText, $script:_envName, $_targetServer
    $deployedFrom = [Environment]::MachineName
    $deployedBy = [Environment]::UserName
    $deployedAt = [DateTime]::Now.ToString("G")
    
    $successOrFail = ""
    
    if ($_successfulDeploy) { $successOrFail = "Successful: True" }
    else 
    {
        $successOrFail = "Successful: False`n`n" + "Error: " + $_scriptErrorMessage + "`n"
    }
    
    $deployTime = ""
    if ($_deployTS)
    {
        $deployTime = ("Deployment completed in {0:N0} minute(s) and {1} second(s)`n" `
			-f [math]::floor($_deployTS.TotalMinutes), $_deployTS.Seconds)
    }
    
    $br = "
"
    $body = @"
MyApp deployment results follow.$br$br

$successOrFail$br$br

Environment: $env ($_targetServer)$br
Run Webpage: $_clickOnceUrl$br$br

App Version: $appVer$br
Publish Version: $publishVer$br
File Version: $fileVer$br$br

Built At: $builtAt$br$br

Deployed from $deployedFrom by $deployedBy. Deployment details are attached.$br
$deployTime$br$br
This message was sent by an automated process.
"@
    
    $to = "PRODUCT_SUPPORT@domain.com"
    Send-Email -from "$deployedBy@domain.com" -to $to `
        -subject $subject -body $body -attachment $_transcriptFile
}

In Conclusion

That wraps up the initial version of this deployment script. Potential changes going forward are:

Adjustments to re-integrate this with CI (build server is currently down)
Updating app config files from the script
Automating creation of a scheduled task to restart the service
Script refactoring and cleanup
Kicking off database and/or report script deployments from app script
"Down for maintenance" page for users
Dependent apps - another web app uses some business and data components of this app and it should be updated when this app is deployed

Potential future posts may be added soon on database and report deployment scripts and CI setup.