I’ve been using MVVM as a pattern for UI work for a while now, mostly because of WPF. Its a solid pattern and while I’ve not really delved into the publicly available frameworks (Prism, Caliburn.Micro, etc) I have put together a few reusable bits and pieces to make the journey easier.

One of those bits and pieces is the ability to perform work in the background, so that the UI remains responsive and usable while other important things are happening. This usually manifests as some sort of refresh or busy indicator on the screen after the user elects to do something complicated, but the important part is that the screen itself does not become unresponsive.

People get antsy when software “stops responding” and tend to murder it with extreme prejudice.

Now, the reusable components are by no means perfect, but they do get the job done.

Except when they don’t.

Right On Schedule

The framework itself is pretty bare bones stuff, with a few simple ICommand implementations and some view model base classes giving easy access to commonly desired functions.

The most complex part is the build in support to easily do background work in a view model while leaving the user experience responsive and communicative. The core idea is to segregate the stuff happening in the background from the stuff happening in the foreground (which is where all the WPF rendering and user interaction lives) using Tasks and TaskSchedulers from the TPL (Task Parallel Library), while also helping to manage some state to communicate what was happening to the user (like busy indicators).

Each view model is be responsible for executing some long running operation (probably started from a command), and then deciding what should happen when that operation succeeds, fails or is cancelled.

In order to support this segregation, the software takes a dependency on three separate task schedulers; one for the background (which is just a normal ThreadPoolTaskScheduler), one for the foreground (which is a DispatcherTaskScheduler or something similar) and one for tasks that needed to be scheduled on a regular basis (another ThreadPoolTaskScheduler).

This dependency injection allows for those schedulers to be overridden for testing purposes, so that they executed completely synchronously or could be pumped at will as necessary in tests.

It all worked pretty great until we started really pushing it hard.

Schedule Conflict

Our newest component to use the framework did a huge amount of work in the background. Not only that, because of the way the interface was structured, it pretty much did all of the work at the same time (i.e. as soon as the screen was loaded), in order to give the user a better experience and minimise the total amount of time spent waiting.

From a technical standpoint, the component needed to hit both a local database (not a real problem) and a remote API (much much slower), both of which are prime candidates for background work due to their naturally slow nature. Not a lot of CPU intensive work though, mostly just DB and API calls.

With 6-10 different view models all doing work in the background, it quickly became apparent that we were getting some amount of contention for resources, as not all Tasks were being completed in a reasonable amount of time. Surprisingly hard to measure, but it looked like The Tasks manually scheduled via the TaskSchedulers were quite expensive to run, and the ThreadPoolTaskSchedulers could only run so much at the same time due to the limits on parallelization and the number of threads that they could have running at once.

So that sucked.

As a bonus annoyance, the framework did not lend itself to usage of async/await at all. It expected everything to be synchronous, where the “background” nature of the work was decided by virtue of where it was executed. Even the addition of one async function threw the whole thing into disarray, as it became harder to reason about where the work was actually being executed.

In the grand scheme of things, async/await is still relatively new (but not that new, it was made available in 2013 after all), but its generally considered a better and less resource intensive way to ensure that blocking calls (like HTTP requests, database IO, file IO and so on) are not causing both the system and the user to wait unnecessarily. As a result, more and more libraries are being built with async functions, sometimes not even exposing a synchronous version at all. Its somewhat difficult to make an async function synchronous to, especially if you want to avoid potential deadlocks.

With those limitations noted, we had to do something.

Why Not Both?

What we ended up doing was allowing for async functions to be used as part of the background work wrappers inside the base view models. This retained the managed “busy” indicator functionality and the general programming model that had been put into place (i.e. do work, do this on success, this on failure, etc).

Unfortunately what it also did was increase the overall complexity of the framework.

It was now much harder to reason about which context things were executing on, and while the usage of async functions was accounted for in the background work part of the framework, it was not accounted for in either the success or error paths.

This meant that is was all too easy to use an async function in the wrong context, causing a mixture of race conditions (where the overarching call wasn’t aware that part of itself was asynchronous) or bad error handling (where a developer had marked a function as async void to get around the compiler errors/warnings).

Don’t get me wrong, it all worked perfectly fine, assuming you knew to avoid all of the things that would make it break.

The tests got a lot more flaky though, because while its relatively easy to override TaskSchedulers with synchronous versions, its damn near impossible to force async functions to execute synchronously.

Sole Survivor

Here’s where it all gets pretty hypothetical, because the solution we actually have right now is the one that I just wrote about (the dual natured, overly complex abomination) and its causing problems on and off in a variety of ways.

A far better model is to incorporate async/await into the fabric of the framework, allowing for its direct usage and doing away entirely with the segmentation logic that I originally put together (with the TaskSchedulers and whatnot).

Stephen Cleary has some really good articles in MSDN magazine about this sort of stuff (being async ViewModels and supporting constructs), so I recommend reading them all if you’re interested.

At a high level, if we expose the fact that the background work is occurring asynchronously (view async commands and whatnot), then not only do we make it far easier to do work in the background (literally just use the standard async/await constructs), but it becomes far easier to handler errors in a reliable way, and the tests become easier too, because they can simply be async themselves (which all major unit testing frameworks support).

It does represent a significant refactor though, which is always a bit painful.

Conclusion

I’m honestly still not sure what the better approach is for this sort of thing

Async/await is so easy to use at first glance, but has a bunch of complexity and tripwires for the unwary. Its also something of an infection, where once you use it even a little bit, you kind of have to push it through everything in order for it to work properly end-to-end. This can be problematic for an existing system, where you want to introduce it a bit at a time.

On the other side, the raw TPL stuff that I put together is much more complex to use, but is relatively shallow. It much easier to reason about where work is actually happening and relatively trivial tocompletely change the nature of the application for testing purposes. Ironically enough, the ability to easily change from asynchronous background workers to a purely synchronous execution is actually detrimental in a way, because it means your tests aren’t really doing the same thing as your application will, which can mask issues.

My gut feel is to go with the newer thing, even though it feels a bit painful.

I think the pain is a natural response to something new though, so its likely to be a temporary thing.

Change is hard, you just have to push through it.

A very long time ago I wrote a post on this blog about interceptors.

The idea behind an interceptor is pretty straight forward; dynamically create a wrapper around some interface or class to either augment or alter its behaviour when used by the rest of the system, without actually having to implement the interface or override the class. For example, my original post was for an interceptor that slowed down requests heading to an API, simulating how that particular application would feel for a user with terrible internet.

I honestly haven’t touched the concept since, until recently that is.

I wanted to add some logging around usage of a third party API from our legacy application and conceptually the problem seemed like a perfect application for another interceptor. A quick implementation of a logging interceptor injected via Ninject and I’d have all the logging I could ever want, without having to mess around too much.

Reality had other ideas though.

Here’s Why I Came Here Tonight

Our legacy software is at that time in its life where it mostly just gets integrations. Its pretty feature complete as far as core functionality goes, so until the day we finally grant it Finis Rerum and it can rest, we look to add value to our users by integrating with third party services.

The most recent foray in this space integrated a payment provider into the software, which is quite useful considering its core value proposition is trust account management. From a technical point of view, the payment provider has an API and we wrote a client to access that API, with structured request and response objects. Pretty standard stuff.

As part of our development, we included various log events that allowed us to track the behaviour of parts of the system, mostly so that we could more easily support the application and get accurate metrics and feedback from users in the wild relating to performance. This is all well and good, but those events generally cover off combined parts of the application logic; for example, an operation that queries the local DB and then augments that information by calling into the third party API to display a screen to the user.

This makes it relatively easy to see when any users are experiencing performance issues, but it makes it hard to see whether or not the local DB, the actual programming logic or the internet call was the root cause.

An improvement to this would be to also log any outgoing API requests and their responses, along with the execution time. With that information we would be able to either blame or absolve the clients internet connection when it comes to performance questions.

Now, I’m an extremely lazy developer, so while we have a nice interface that I could implement to accomplish this (i.e. some sort of LoggingPaymentProviderClient), its got like twenty methods and I really don’t have the time, patience or motivation for that. Also, while its unlikely that the interface would change all that much over time, its still something of a maintenance nightmare.

Interceptors to the rescue!

But I Got The Feeling That Something Ain’t Right

As I explained in my original post all those years ago, the IInterceptor interface supplied by the Castle library allows you to implement logic via a proxy and slot it seamlessly into a call stack. Its usage is made easier by the presence of good dependency injection, but its definitely not required at all.

Thus enters the logging interceptor.

public class PaymentProviderClientMethodExecutionLoggingInterceptor : IInterceptor
{
    public PaymentProviderClientMethodExecutionLoggingInterceptor(ILogger logger)
    {
        _logger = logger;
    }

    private readonly ILogger _logger;

    public void Intercept(IInvocation invocation)
    {
        var stopwatch = Stopwatch.StartNew();
        try
        {
            invocation.Proceed();
            stopwatch.Stop();

            var log = new PaymentProviderMethodCallCompleted(invocation, stopwatch.Elapsed);
            _logger.Information(log);
        }
        catch (Exception ex)
        {
            stopwatch.Stop();

            var log = new PaymentProviderMethodCallFailed(invocation, stopwatch.Elapsed, ex);
            _logger.Warning(log);

            throw;
        }
    }
}

Its not an overly complicated class, and while its written to be specific, its actually quite generic.

Given a proxied class, all methods called on that class will be logged via Serilog, with the method name, its parameters and its return value (the structured logging being provided by the dedicated event classes).

Nothing ever works the first time though, and while I’m constantly being reminded of that, I’m always hopeful all the same. Denial is a powerful motivator.

The problem was that the IInterceptor interface is old enough that it doesn’t consider the existence of asynchronous methods. It does exactly what it says on the tin, starts a timer, proceeds with the method invocation and then because the method is asynchronous, immediately logs an event with the wrong execution time and no return value.

It has no idea that it has to wait for the invocation to complete because it thinks everything is synchronous.

Clowns To The Left Of Me, Jokers To The Right

This is where everything is going to get a little bit fuzzier than I would like, because I wrote this blog post before I had a working solution.

From what I can tell, the situation is quite complex.

The simplest solution appears to be to leverage the existing interface and simply check for the presence of a Task (or Task<T>) return value. If detected, append a continuation to that Task to perform the desired functionality. For me this would be a continuation on both faulted and success (and maybe cancelled?) that would log the completion of the method. It seems like it would work, but I do have some concerns about the scheduling of the continuation and how that makes the code harder to reason about.

Luckily, someone has already written a reusable library together that allows for asynchronous interceptors via a slightly different interface.

This is attractive because its code that I don’t have to write (remember, I’m lazy), but it not being built into the core Castle library does make me question its legitimacy. Surely if it was that critical the maintainers would have updated Castle.Core?

Regardless, I explored using the library first, but in order to use it I had to go on an adventure to upgrade a bunch of our Nuget dependencies (because it relied on the latest version of Castle.Core), which meant updates to Castle, Ninject and Ninject’s extension libraries. This caused knock on effects because the Ninject.MockingKernel.NSubstitute library was not available for .NET 4.5 (even though all the others were), so I had to temporarily copy that particular implementation into our codebase.

Once everything was compiling, a full test run showed some failing tests that weren’t failing before the library upgrades, so I kind of stopped there.

For now.

Conclusion

Unfortunately this is one of those blog posts that comes off feeling a little hollow. I didn’t actually get to my objective (seamless per method logging for a third-party dependency), but I did learn a lot on the way, so I think it was still useful to write about.

Probably should have waited a little longer though, I jumped the gun a bit.

Its not the only time in recent memory that asynchronous behaviour has made things more difficult than they would have been otherwise. In an unrelated matter, some of our automated tests have been flakey recently, and the core of the issue seems to be asynchronous behaviour that is either a.) not being correctly overridden to be synchronous for testing purposes or b.) not correctly being waited for before tests proceed.

Its not hard to write tests that are purely async of course (NUnit supports tests marked with the async keyword), but when you’re testing a view model and the commands are “synchronous” it gets a bit more challenging.

That’s probably a topic for another day though.

Software Development as a discipline puts a bunch of effort into trying to minimise the existence and creation of bugs, but the reality is that its an investment/return curve that flattens off pretty quickly.

Early discovery of issues is critical. Remember, the cost to the business for a bug existing is never lower than it is at development time. The longer it has to fester, the worse its going to get.

Of course, when a bug is discovered, there are decisions to make around whether or not to fix it. For me, every bug that exists in a piece of software that might cause an issue for a user is a mark against its good name, so my default policy is to fix. Maybe not in the same piece of work that it was found in, but in general, bugs should be fixed.

That is, unless you hit that awkward conjunction of high cost/low incidence.

Why waste a bunch of money fixing a bug that might never happen?

Split Personality

I’m sure you can guess from the mere existence of this blog post that this is exactly the situation we found ourselves in recently.

While evaluating a new component in our legacy application, we noticed that it was technically possible to break what was intended to be an entirely atomic operation consisting of multiple database writes.

Normally this wouldn’t even be worth talking about, as its basically the reason that database transactions exist. When used correctly its a guarantee of an all or nothing situation.

Unfortunately, one of the writes was in Visual Basic 6 code, and the other was in .NET.

I don’t know if you’ve ever tried to span a database transaction across a technology boundary like that, but its not exactly the easiest thing in the world.

When we looked into the actual likelihood of the issue occurring, we discovered that if the VB6 part failed, we could easily just rollback the .NET part. If the write failed in .NET though, we had no way to go back and undo the work that had already been done in VB6. Keep in mind, this entire section was essentially creating transactions in trust accounting application, so non-atomic operations can get users into all sorts of terrible situations.

On deeper inspection, the only way we thought the .NET stuff could fail would be transitory database issues. That is, connection or command timeouts or disconnects.

We implemented a relatively straightforward retry strategy to deal with those sorts of failures and then moved on. Sure, it wasn’t perfect, but it seemed like we’d covered our bases pretty well and mitigated the potential issue as best we could.

I Did Not See That One Coming

Of course, the code failed in a way completely unrelated to temporary connectivity issues.

In our case, we were stupid and attempted to write an Entity Framework entity to the database whose string values exceeded the column size limits. Long story short, we were concatenating an information field from some other fields and didn’t take into account that maybe the sum of those other fields would exceed the maximum.

The write failure triggered exactly the situation that we were worried about; the actual trust account record had been created (VB6) but our record if it happening was missing (.NET).

I still don’t actually know why we bothered implementing column size limits. As far as I know, there is no difference between a column of VARCHAR(60) and VARCHAR(MAX) when it comes to performance. Sure, you could conceivably store a ridiculous amount of data in the MAX column at some point, but I feel like that is a lot less destructive than the write failures (and its knock-on effects) that we got.

Even worse, from the users point of view, the operation looked like it had worked. There were no error notifications visible to them, because we couldn’t write to the table that we used to indicate errors! When they returned to their original action list though, the item that failed was still present. They then processed it again and the same thing happened (it looked like it worked but it was still in the list afterwards) at which point they twigged that something was unusual and contacted our support team (thank god).

Once we found out about the issue, we figured out pretty quickly what the root cause was thanks to our logging and cursed our hubris.

Off With Their Head!

The fix for this particular problem was easy enough and involved two extension methods; one for truncating a string and another for scanning an object and automatically truncating string lengths as per data annotation attributes.

public static string Truncate(this string value, int maxLength, ILogger logger = null)
{
    if (string.IsNullOrEmpty(value))
    {
        return value;
    }

    if (maxLength < 0) throw new ArgumentException($"Truncate cannot be used with a negative max length (supplied {nameof(maxLength)} was [{maxLength}]). That doesn't even make sense, what would it even do?", nameof(maxLength));

    if (value.Length <= maxLength)
    {
        return value;
    }

    string truncated = null;
    truncated = maxLength <= 3 ? value.Substring(0, maxLength) : value.Substring(0, maxLength - 3) + "...";

    
    logger?.Debug("The string [{original}] was truncated because it was longer than the allowed length of [{length}]. The truncated value is [{truncated}]", value, maxLength, truncated);

    return truncated;
}

public static void TruncateAllStringPropertiesByTheirMaxLengthAttribute(this object target, ILogger logger = null)
{
    var props = target.GetType().GetProperties().Where(prop => Attribute.IsDefined(prop, typeof(MaxLengthAttribute)) && prop.CanWrite && prop.PropertyType == typeof(string));

    foreach (var prop in props)
    {
        var maxLength = prop.GetCustomAttribute(typeof(MaxLengthAttribute)) as MaxLengthAttribute;
        if (maxLength != null)
        {
            prop.SetValue(target, ((string)prop.GetValue(target)).Truncate(maxLength.Length, logger));
        }
    }
}

Basically, before we write the entity in question, just call the TruncateAllStringPropertiesByTheirMaxLengthAttribute method on it.

With the immediate problem solved, we were still left with two outstanding issues though:

• A failure occurred in the code and the user was not notified
• An atomic operation was still being split across two completely different programming contexts

In this particular case we didn’t have time to alleviate the first issue, so we pushed forward with the fix for the issue that we knew could occur.

We still have absolutely no idea how to deal with the second issue though, and honestly, probably never will.

Conclusion

In retrospect, I don’t think we actually made the wrong decision. We identified an issue, analysed the potential occurrences, costed a fix and then implemented a smaller fix that should have covered out bases.

The retry strategy would likely have dealt with transitory failures handily, we just didn’t identify the other cases in which that section could fail.

As much as I would like to, its just not cost-effective to account for every single edge case when you’re developing software.

Well, unless you’re building like pacemaker software or something.

Then you probably should.

Sometimes when maintaining legacy software, you come across a piece of code and you just wonder;

But….why?

If you’re lucky the reasoning might end up being sound (i.e. this code is structured this way because of the great {insert-weird-issue-here} of 1979), but its probably more likely that it was just a plain old lack of knowledge or experience.

Its always a journey of discovery though, so enjoy the following post, sponsored by some legacy VB6 code that interacts with a database.

Building On Shaky Foundations

As is typically the precursor to finding weird stuff, it all started with a bug.

During the execution of a user workflow, the presence of a ‘ character in a name caused an error, which in turn caused the workflow to fail, which in turn led to some nasty recovery steps. I’m not going to get into the recovery steps in this post, but suffice to say, this workflow was not correctly wrapped in a transaction scope and we’ll just leave it at that.

Now, the keen-eyed among you might already be able to guess what the issue was. Maybe because you’ve already fought this battle before.

Deep in the bowels of that particular piece of code, an SQL statement was being manually constructed using string concatenation.

Private Function Owner_LetPrepFees_CreateTransaction(ByVal psTransAudit As String, ByVal plTransLink As Long, ByVal plTransPropertyID As Long, _
                                                     ByVal plTransOwnerID As Long, ByVal psTransFromRef As String, ByVal psTransFromText As String, _
                                                     ByVal plTransCreditorID As Long, ByVal psTransToRef As String, ByVal psTransToText As String, _
                                                     ByVal psTransReference As String, ByVal psTransType As String, ByVal psTransDetails As String, _
                                                     ByVal pbGSTActive As Boolean, ByVal pnTransAmount As Currency, ByVal psTransLedgerType As String, _
                                                     ByVal pbLetFee As Boolean, ByVal pbPrepFee As Boolean, ByVal plCount As Long) As Long
    Dim sInsertFields           As String
    Dim sInsertValues           As String
    Dim lCursorLocation         As Long

    ' replaces single "'" with "''" to avoid the "'" issue in insert statement
    psTransFromRef = SQL_ValidateString(psTransFromRef)
    psTransFromText = SQL_ValidateString(psTransFromText)
    psTransToRef = SQL_ValidateString(psTransToRef)
    psTransToText = SQL_ValidateString(psTransToText)
    psTransReference = SQL_ValidateString(psTransReference)
    psTransDetails = SQL_ValidateString(psTransDetails)

    sInsertFields = "AccountID,Created,UserId,Audit,Date"
    sInsertValues = "" & GetAccountID() & ",GetDate()," & User.ID & ",'" & psTransAudit & "','" & Format(UsingDate, "yyyyMMdd") & "'"
    If plTransLink <> 0& Then
        sInsertFields = sInsertFields & ",Link"
        sInsertValues = sInsertValues & "," & plTransLink
    End If
    If plTransPropertyID <> 0 Then
        sInsertFields = sInsertFields & ",PropertyId"
        sInsertValues = sInsertValues & "," & plTransPropertyID
    End If
    If plCount = 1& Then
        sInsertFields = sInsertFields & ",OwnerID,FromRef,FromText"
        sInsertValues = sInsertValues & "," & plTransOwnerID & ",'" & Left$(psTransFromRef, 8&) & "','" & Left$(psTransFromText, 50&) & "'"
    Else
        sInsertFields = sInsertFields & ",CreditorId,ToRef,ToText"
        sInsertValues = sInsertValues & "," & plTransCreditorID & ",'" & Left$(psTransToRef, 8&) & "','" & Left$(psTransToText, 50&) & "'"
    End If
    sInsertFields = sInsertFields & ",Reference,TransType,Details,Amount,LedgerType"
    sInsertValues = sInsertValues & ",'" & psTransReference & "','" & psTransType & "','" & IIf(pbGSTActive, Left$(Trim$(psTransDetails), 50&), Left$(psTransDetails, 50&)) & "'," & pnTransAmount & ",'" & psTransLedgerType & "'"
    If pbLetFee And psTransType = "CR" And psTransLedgerType = "JC" Then
        sInsertFields = sInsertFields & ",DisburseType"
        sInsertValues = sInsertValues & "," & dtLetFeePayment
    ElseIf pbPrepFee And psTransType = "CR" And psTransLedgerType = "JC" Then
        sInsertFields = sInsertFields & ",DisburseType"
        sInsertValues = sInsertValues & "," & dtPrepFeePayment
    End If
    If pbGSTActive Then
        sInsertFields = sInsertFields & ",GST"
        sInsertValues = sInsertValues & "," & 1&
    End If
    
    lCursorLocation = g_cnUser.CursorLocation
    g_cnUser.CursorLocation = adUseClient
    Owner_LetPrepFees_CreateTransaction = RSQueryFN(g_cnUser, "SET NOCOUNT ON; INSERT INTO Transactions (" & sInsertFields & ") VALUES (" & sInsertValues & "); SET NOCOUNT OFF; SELECT SCOPE_IDENTITY() ID")
    g_cnUser.CursorLocation = lCursorLocation

End Function

Hilariously enough, I don’t even have a VB6 Syntax Highlighter available on this blog, so enjoy the glory of formatter:none.

Clearly we had run into the same problem at some point in the past, because the code was attempting to sanitize the input (looking for special characters and whatnot) before concatenating the strings together to make the SQL statement. Unfortunately, input sanitization can be a hairy beast at the best of times, and this particular sanitization function was not quite doing the job.

Leave It Up To The Professionals

Now, most sane people don’t go about constructing SQL Statements by concatenating strings, especially when it comes to values that are coming from other parts of the system.

Ignoring SQL injection attacks for a second (its an on-premises application, you would already have to be inside the system to do any damage in that way), you are still taking on a bunch of unnecessary complexity in handling all of the user input sanitization yourself. You might not even get it right, as you can see in the example above.

Even in VB6 there exists libraries that do exactly that sort of thing for you, allowing you to use parameterized queries.

No muss, no fuss, just construct the text of the query (which is still built, but is built from controlled strings representing column names and parameter placeholders), jam some parameter values in and then execute. It doesn’t matter what’s in the parameters at that point, the library takes care of the rest.

Private Function Owner_LetPrepFees_CreateTransaction(ByVal psTransAudit As String, _
            ByVal plTransLink As Long, ByVal plTransPropertyID As Long, _
            ByVal plTransOwnerID As Long, ByVal psTransFromRef As String, ByVal psTransFromText As String, _
            ByVal plTransCreditorID As Long, ByVal psTransToRef As String, ByVal psTransToText As String, _
            ByVal plTransReference As Long, ByVal psTransType As String, ByVal psTransDetails As String, _
            ByVal pbGSTActive As Boolean, ByVal pnTransAmount As Currency, ByVal psTransLedgerType As String, _
            ByVal pbLetFee As Boolean, ByVal pbPrepFee As Boolean, ByVal plCount As Long) As Long            


    'Trims the parameters to fit inside the sql tables columns'
    psTransFromRef = Left$(Trim$(psTransFromRef), 8&)
    psTransFromText = Left$(Trim$(psTransFromText), 50&)
    psTransToRef = Left$(Trim$(psTransToRef), 8&)
    psTransToText = Left$(Trim$(psTransToText), 50&)
    psTransDetails = Left$(Trim$(psTransDetails), 50&)

    Dim sCommand    As String
    Dim sFieldList  As String
    Dim sValueList  As String
    Dim oCommand    As ADODB.Command
    Dim oParameter  As ADODB.Parameter

    Set oCommand = New Command
    oCommand.ActiveConnection = g_cnUser
    oCommand.CommandType = adCmdText
    oCommand.CommandTimeout = Val(GetRegistry("Settings", "SQL Command Timeout Override", "3600"))

    sFieldList = "AccountID, Created, UserId, Audit, Date"
    sValueList = "?" & ", GetDate()" & ", ?" & ", ?" & ", ?"
    oCommand.Parameters.Append oCommand.CreateParameter(, adInteger, adParamInput, , GetAccountID())
    oCommand.Parameters.Append oCommand.CreateParameter(, adInteger, adParamInput, , User.ID)
    oCommand.Parameters.Append oCommand.CreateParameter(, adVarChar, adParamInput, 10, psTransAudit)
    oCommand.Parameters.Append oCommand.CreateParameter(, adDate, adParamInput, , UsingDate)

    If plTransLink <> 0& Then
        sFieldList = sFieldList & ", Link"
        sValueList = sValueList & ", ?"
        oCommand.Parameters.Append oCommand.CreateParameter(, adInteger, adParamInput, , plTransLink)
    End If

    If plTransPropertyID <> 0 Then
        sFieldList = sFieldList & ", PropertyId"
        sValueList = sValueList & ", ?"
        oCommand.Parameters.Append oCommand.CreateParameter(, adInteger, adParamInput, , plTransPropertyID)
    End If

    If plCount = 1& Then
        sFieldList = sFieldList & ", OwnerID" & ", FromRef" & ", FromText"
        sValueList = sValueList & ", ?" & ", ?" & ", ?"
        oCommand.Parameters.Append oCommand.CreateParameter(, adInteger, adParamInput, , plTransOwnerID)
        oCommand.Parameters.Append oCommand.CreateParameter(, adVarChar, adParamInput, 8, psTransFromRef)
        oCommand.Parameters.Append oCommand.CreateParameter(, adVarChar, adParamInput, 50, psTransFromText)
    Else
        sFieldList = sFieldList & ", CreditorId" & ", ToRef" & ", ToText"
        sValueList = sValueList & ", ?" & ", ?" & ", ?"
        oCommand.Parameters.Append oCommand.CreateParameter(, adInteger, adParamInput, , plTransCreditorID)
        oCommand.Parameters.Append oCommand.CreateParameter(, adVarChar, adParamInput, 8, psTransToRef)
        oCommand.Parameters.Append oCommand.CreateParameter(, adVarChar, adParamInput, 50, psTransToText)
    End If

    sFieldList = sFieldList & ", Reference" & ", TransType" & ", Details" & ", Amount" & ", LedgerType"
    sValueList = sValueList & ", ?" & ", ?" & ", ?" & ", ?" & ", ?"
    oCommand.Parameters.Append oCommand.CreateParameter(, adInteger, adParamInput, 8, plTransReference)
    oCommand.Parameters.Append oCommand.CreateParameter(, adVarChar, adParamInput, 2, psTransType)
    oCommand.Parameters.Append oCommand.CreateParameter(, adVarChar, adParamInput, 100, psTransDetails)
    oCommand.Parameters.Append oCommand.CreateParameter(, adCurrency, adParamInput, , pnTransAmount)
    oCommand.Parameters.Append oCommand.CreateParameter(, adVarChar, adParamInput, 2, psTransLedgerType)

    If pbLetFee And psTransType = "CR" And psTransLedgerType = "JC" Then
        sFieldList = sFieldList & ", DisburseType"
        sValueList = sValueList & ", ?"
        oCommand.Parameters.Append oCommand.CreateParameter(, adInteger, adParamInput, , dtLetFeePayment)
    ElseIf pbPrepFee And psTransType = "CR" And psTransLedgerType = "JC" Then
        sFieldList = sFieldList & ", DisburseType"
        sValueList = sValueList & ",?"
        oCommand.Parameters.Append oCommand.CreateParameter(, adInteger, adParamInput, , dtPrepFeePayment)
    End If

    If pbGSTActive Then
        sFieldList = sFieldList & ", GST"
        sValueList = sValueList & ", ?"
        oCommand.Parameters.Append oCommand.CreateParameter(, adBoolean, adParamInput, , pbGSTActive)
    End If

    Set oParameter = oCommand.CreateParameter(, adInteger, adParamReturnValue)
    oCommand.Parameters.Append oParameter
    sCommand = "INSERT INTO Transactions (" & sFieldList & ") VALUES (" & sValueList & "); SELECT ?=SCOPE_IDENTITY()"
    oCommand.CommandText = sCommand
    oCommand.Execute , , adExecuteNoRecords
    Exit Function    
    
    Owner_LetPrepFees_CreateTransaction = oParameter.Value
    Set oCommand = Nothing
    
End Function

Of course, because VB6 is a positively ancient language, its not quite as easy as all that.

Normally, in .NET or something similar, if you are constructing a parameterized query yourself, you’d probably use a query builder of some sort, and you would name your parameters so that the resulting query was easy to read as it goes through profilers and logs and whatnot.

No such luck here, the only parameter placeholder that seems to be supported is the classic ?, which means the parameters are positional. This can be dangerous when the code is edited in the future, but if we’re lucky, maybe that won’t happen.

Its still better than jamming some strings together though.

Conclusion

I think of this as a textbook case for never just “fixing the bug” as its stated. Sure, we could have just edited the SQL_ValidateString function to be more robust in the face of a particular arrangement of special characters, but that’s just putting a bandaid on a bad solution.

Instead we spent the time to work with the language and the constructs available to put a solution in place that is a lot more robust in the face of unexpected input.

And lets be honest, at this point, the only input we get is the unexpected kind.

I expect accounting software to make some pretty convincing guarantees about the integrity of its data over time.

From my experience, such software generally restricts the users capability to change something once it has been entered. Somewhat unforgiving of innocent mistakes (move money to X, whoops, now you’ve got to move to back and there is a full audit trail of your mistake), but it makes for a secure system in the long run.

Our legacy software is very strict about maintaining the integrity of its transactional history, and it has been for a very long time.

Except when you introduce the concept of database restores, but that’s not a topic for this blog post.

Nothing is perfect though, and a long history of development by a variety of parties (some highly competent, some….not) has lead to a complicated system that doesn’t play by its own rules every now and then.

Its like a reverse Butterfly Effect, changing the present can unfortunately change the past.

Its All Wrong

A natural and correct assumption about any reports that come out of a piece of accounting software, especially one that focuses on transactions, is that it shouldn’t matter when you look at the report (today, tomorrow, six months from now), if you’re looking at data in the past, it shouldn’t be changing.

When it comes to the core transactional items (i.e. “Transferred $200 to Bob”) we’re good. Those sorts of things are immutable at the time when they occur and it doesn’t matter when you view the data, its always the same.

Being that this is a blog post, suspiciously titled “Protecting the Timeline”, I think you can probably guess that something is rotten in the state of Denmark.

While the core transactional information is unimpeachable, sometimes there is meta information attached to a transaction with less moral integrity. For example, if the transaction is an EFT payment exiting the system, it needs to record bank account details to be compliant with legislation (i.e. “Transferred $200 to Bob (EFT: 123-456, 12346785)”).

Looking at the system, its obvious that the requirement to capture this additional information came after the original implementation, and instead of capturing the entire payload when the operation is executed, the immutable transaction is dynamically linked to the entities involved and the bank account details (or equivalent) are loaded from the current state of the entity whenever a report is created.

So we know unequivocally that the transaction was an EFT transaction, but we don’t technically know which account the transfer targeted. If the current details change, then a re-printed report will technically lie.

Freeze Frame

The solution is obvious.

Capture all of the data at the time the operation is executed, not just some of it.

This isn’t overly difficult from a technical point of view, just hook into the appropriate places, capture a copy of the current data and store it somewhere safe.

Whenever the transactions are queried (i.e. in the report), simply load the the same captured data and present it to the user.

Of course, if the requirements change again in the future (and we need to show additional information like Bank Name or something), then we will have to capture that as well, and all previous reports will continue to show the data as it was before the new requirement. That’s the tradeoff, you can’t capture everything, and whatever you don’t capture is never there later.

But what about the literal mountain of data that already exists with no captured meta information?

Timecop!

There were two obvious options that we could see to deal with the existing data:

1. Augment the reporting/viewing logic such that it would use the captured data if if existed, but would revert back to the old approach if not.
2. Rewrite history using current information and “capture” the current data, then just use the captured data consistently (i.e. in reports and whatnot).

The benefit of option one is that we’re just extending the logic that has existed for years. When we have better data we can use that, but if not, we just fall back to old faithful. The problem here is one of complication, as any usages now need to do two things, with alternate code paths. We want to make the system simpler over time (and more reliable), not harder to grok. Also, doing two operations instead of one, combined with the terrible frameworks in use (a positively ancient version of Crystal Reports) led to all sorts of terrible performance problems.

Option two basically replicates the logic in option one, but executes it only once when we distribute the upgrade to our users, essentially capturing data at that point in time, which then becomes immutable. From that point forward everything is simple, just use the new approach, and all of the old data is the same as it would have been if the reports had of been printed out normally.

If you couldn’t guess, we went with option two.

Conclusion

What we were left with was a more reliable reporting system, specifically focused around the chronological security of data.

Also, I’m pretty sure I made up the term “chronological security”, but it sounds cool, so I’m pretty happy.

I honestly don’t know what led to the original decision to not capture key parts of the transaction in an immutable fashion, and with hindsight its easy for me to complain about it. I’m going to assume the group (or maybe even individual) that developed the feature simply did not think through the ramifications of the implementation over time. Making good software requires a certain level of care and I know for a fact that that level of care was not always present for our long-suffering legacy software.

We’re better now, but that’s still a small slice of the overall history pie, and sometimes we build on some very shaky foundations.