Tag Archives: bug

Protobuf-net Is Broken Around DateTime

Protocol Buffers by Google are a great mechanism for serializing (and deserializing) structured data in a very fast and efficient way. Protobuf-net is Marc Gravell‘s port of Protocol Buffers for the .Net ecosystem.

While being very efficient, protobuf-net has a big issue when deserializing .Net’s DateTimes. Behind the scenes DateTimes are converted into Unix-Time which is a count (of ticks in this case) starting from the Unix Epoch (1970/01/01 UTC). When deserializing back to .Net protobuf-net adds that count to a DateTime representing the Epoch-Time resulting in the correct DateTime value. The issue with this process is that it loses the DateTime‘s original DateTimeKind.

DateTimeKind is an enum telling whether the DateTime‘s value represents a local time, UTC time or unspecified. That value isn’t serialized by protobuf-net so all DateTimes, be they local time or UTC, are deserialized as DateTimeKind.Unspecified.

DateTimeKind.Unspecified values have a behavior that I initially found surprising but later realized is the best possible option. Let’s assume you’re in Hawaii (because where else would you want to be?) and your time zone is UTC-10:00. If you have a DateTime value with DateTimeKind.Unspecified and you call ToLocalTime the method assumes the value is in UTC and “corrects” it, so 11:00 becomes 01:00. If however you call ToUniversalTime on that value the method now assumes it’s in local time and “corrects” it so 11:00 becomes 21:00. So the same value is treated as local while adjusting to universal and universal when adjusting to local. Let’s see that in code:

static void Main()
{
    var dolly = new Sheep {DateOfBirth = new DateTime(1966, 07, 05, 11, 0, 0, DateTimeKind.Utc)};
    Console.WriteLine(dolly.DateOfBirth.ToString("HH:mm:ss K")); // "11:00:00 Z" (Z means UTC)

    dolly = Serializer.DeepClone(dolly); // Serialize and deserialize using protobuf-net
    Console.WriteLine(dolly.DateOfBirth.ToString("HH:mm:ss K")); // "11:00:00" (no Z means unspecified)
    Console.WriteLine(dolly.DateOfBirth.ToLocalTime().ToString("HH:mm:ss K")); // "01:00:00 -10:00" (Hawaii timezone)
    Console.WriteLine(dolly.DateOfBirth.ToUniversalTime().ToString("HH:mm:ss K")); // "21:00:00 Z"
}

[ProtoContract(ImplicitFields = ImplicitFields.AllPublic)]
class Sheep
{
    public DateTime DateOfBirth { get; set; }
}

This can get extremely problematic especially if you, like me, depend upon some library that uses ToUniversalTime or ToLocalTime. For me that library was the .Net’s MongoDB Driver that stores all DateTimes in MongoDB in UTC. Using these 2 libraries together is impossible as DateTime values would keep changing value infinitely.

I have posted on the protobuf-net repository on github explaining this and managed to convince him to fix this problem (which he did with this commit). However, this fix was made 5 months prior to me writing this post and there’s still isn’t a new release including the fix (the latest stable release is from 2013/09/30).

But don’t fear… I do have a workaround you can use for the meantime. Protobuf-net uses a DateTime value representing the Unix Epoch (1970/01/01) to create all the DateTimes by adding the relevant delta to the epoch value. Since creating a new DateTime from an existing DateTime preserves the DateTimeKind, replacing the single epoch value with a UTC one will result with all protobuf-net DateTime values having DateTimeKind.UTC. We can do that by using reflection and replacing the epoch value with a UTC one:

typeof (BclHelpers).
    GetField("EpochOrigin", BindingFlags.NonPublic | BindingFlags.Static).
    SetValue(null, new DateTime(1970, 1, 1, 0, 0, 0, 0, DateTimeKind.Utc));

var dolly = new Sheep {DateOfBirth = new DateTime(1966, 07, 05, 11, 0, 0, DateTimeKind.Utc)};
Console.WriteLine(dolly.DateOfBirth.ToString("HH:mm:ss K")); // "11:00:00 Z" (Z means UTC)

dolly = Serializer.DeepClone(dolly); // Serialize and deserialize using protobuf-net
Console.WriteLine(dolly.DateOfBirth.ToString("HH:mm:ss K")); // "11:00:00 Z"

I admit it’s not pretty, but until Marc releases a new version, it’s preferable to building your own protobuf-net.

LogicalOperationStack Is Broken With async-await

Trace.CorrelationManager.LogicalOperationStack enables having nested logical operation identifiers where the most common case is logging (NDC). Evidently it doesn’t work with async-await.

The Issue

Here’s a simple example using LogicalFlow, my simple wrapper over the LogicalOperationStack:

static void Main()
{
    OuterOperationAsync().Wait();
}

static async Task OuterOperationAsync()
{
    Console.WriteLine(LogicalFlow.CurrentOperationId);
    using (LogicalFlow.StartScope())
    {
        Console.WriteLine("\t" + LogicalFlow.CurrentOperationId);
        await InnerOperationAsync();
        Console.WriteLine("\t" + LogicalFlow.CurrentOperationId);
        await InnerOperationAsync();
        Console.WriteLine("\t" + LogicalFlow.CurrentOperationId);
    }
    Console.WriteLine(LogicalFlow.CurrentOperationId);
}

static async Task InnerOperationAsync()
{
    using (LogicalFlow.StartScope())
    {
        await Task.Yield();
    }
}

LogicalFlow:

public static class LogicalFlow
{
    public static Guid CurrentOperationId
    {
        get
        {
            return Trace.CorrelationManager.LogicalOperationStack.Count > 0
                ? (Guid) Trace.CorrelationManager.LogicalOperationStack.Peek()
                : Guid.Empty;
        }
    }

    public static IDisposable StartScope()
    {
        Trace.CorrelationManager.StartLogicalOperation();
        return new Stopper();
    }

    private static void StopScope()
    {
        Trace.CorrelationManager.StopLogicalOperation();
    }

    private class Stopper : IDisposable
    {
        private bool _isDisposed;
        public void Dispose()
        {
            if (!_isDisposed)
            {
                StopScope();
                _isDisposed = true;
            }
        }
    }
}

And the output is:

00000000-0000-0000-0000-000000000000
    49985135-1e39-404c-834a-9f12026d9b65
    54674452-e1c5-4b1b-91ed-6bd6ea725b98
    c6ec00fd-bff8-4bde-bf70-e073b6714ae5
54674452-e1c5-4b1b-91ed-6bd6ea725b98

The specific Guid values don’t really matter. Both the outer lines should show Guid.Empty (i.e. 00000000-0000-0000-0000-000000000000) and the inner lines should show the same Guid value.

Multithreading

You might say that LogicalOperationStack is using a Stack which is not thread-safe and that’s why the output is wrong. But while that’s true in general, in this case there’s never more than a single thread accessing the LogicalOperationStack at the same time because every async operation is awaited when called and there’s no use of combinators such as Task.WhenAll.

The Root Cause

The root cause is that LogicalOperationStack is stored in the CallContext which has a copy-on-write behavior. That means that as long as you don’t explicitly set something into the CallContext (and you don’t with StartLogicalOperation as you just add to an existing stack) you’re using the parent context and not your own.

This can be shown by simply setting anything into the CallContext before adding to the existing stack. For example if we changed StartScope to this:

public static IDisposable StartScope()
{
    CallContext.LogicalSetData("Bar", "Arnon");
    Trace.CorrelationManager.StartLogicalOperation();
    return new Stopper();
}

The output is correct:

00000000-0000-0000-0000-000000000000
    fdc22318-53ef-4ae5-83ff-6c3e3864e37a
    fdc22318-53ef-4ae5-83ff-6c3e3864e37a
    fdc22318-53ef-4ae5-83ff-6c3e3864e37a
00000000-0000-0000-0000-000000000000

I’ve contacted the relevant developer at Microsoft and his response was this:

I wasn’t aware of this, but it does seem broken. The copy-on-write logic is supposed to behave exactly as if we’d really created a copy of the ExecutionContext on entry into the method. However, copying the ExecutionContext would have created a deep copy of the CorrelationManager context, as it’s special-cased in CallContext.Clone(). We don’t take that into account in the copy-on-write logic.”

Solution

Use an ImmutableStack stored in the CallContext instead of the LogicalOperationStack as it’s both thread-safe and immutable so when you call Pop you get back a new ImmutableStack that you then must set back into the CallContext.

public static class LogicalFlow
{
    private static ImmutableStack<Guid> LogicalStack
    {
        get
        {
            return CallContext.LogicalGetData("LogicalFlow") as ImmutableStack<Guid> ?? ImmutableStack.Create<Guid>();
        }
        set
        {
            CallContext.LogicalSetData("LogicalFlow", value);
        }
    }

    public static Guid CurrentId
    {
        get
        {
            var logicalStack = LogicalStack;
            return logicalStack.IsEmpty ? Guid.Empty : logicalStack.Peek();
        }
    }
    
    public static IDisposable StartScope()
    {
        LogicalStack = LogicalStack.Push(Guid.NewGuid()); // Here's where the CallContext is copied using copy-on-write
        return new Stopper();
    }
    
    private static void StopScope()
    {
        LogicalStack = LogicalStack.Pop();
    }
}

Another options is to to store the stack in the new System.Threading.AsyncLocal class added in .Net 4.6 (or Stephen Cleary‘s AsyncLocal) instead which should handle that issue correctly.

Note: This came after I asked (and answered) a question on Stack Overflow: Is LogicalOperationStack incompatible with async in .Net 4.5 which contains further discussion.