Reactive-Extensions/Rx.NET — pull request #70 by jamesdoran (2014-12-09 06:02:29+00:00)
Title: Fixed race condition in Buffer where timer could stop ticking

# Overview
We're using the following Rx subscription in our system:

_subscription = _subject.Buffer(timeSpan: TimeSpan.FromMilliseconds(250), count: 1500)
.ObserveOn(TaskPoolScheduler.Default)
.Subscribe(list => Handler(list),
ex => /* OnError Logging */,
() => /* OnComplete Logging */);

Recently, we noticed that under certain conditions the OnNext action would stop being called every timeSpan (250ms in this case). This meant that anywhere up to 1499 items could be buffered but not passed to the observer until the 1500 count was reached. This caused a *very serious* bug in one of our use cases because only 4000 items were passed through the Buffer during its lifetime, so the last 500 items would never come out of the other side!

I can reproduce the issue within 3-4 runs and have tried using different schedulers and also including a scheduler on the Buffer call itself.

# Cause
I've tried to write a minimal test harness that would reproduce this issue, but have been unable to do so. As it's a race condition, it only seems to occur under very specific circumstances in our QA environment. This environment has a single CPU (constraint due to using VMWare fault tolerance) and at the time items are passed through the observable, the CPU is under high load. This obviously then affects OS thread scheduling.

## Tracing
To find the cause of the issue, I added some Trace.WriteLine() calls in the Buffer.cs Impl class, particularly in the CreateTimer and Tick methods. I then ran the system until the problem occurred. The output is shown below including annotations:

I had to include the hash code in order to correlate the logs, as there are multiple buffers in use in our system.

[10] 2014-12-08 11:10:38.146 Impl.CreateTimer: Hash 15645912: id: 0

// Handles the first tick and releases the _gate lock
[9] 2014-12-08 11:10:38.505 Impl.Tick: Hash 15645912: id 0. newId 1

// These calls were queued from the OnNext method, waiting for the lock
[10] 2014-12-08 11:10:38.848 Impl.CreateTimer: Hash 15645912: id: 2
[10] 2014-12-08 11:10:38.879 Impl.CreateTimer: Hash 15645912: id: 3

// The first thread is scheduled back in and creates a timer with a lower window ID
[9] 2014-12-08 11:10:39.176 Impl.CreateTimer: Hash 15645912: id: 1

// There's a mismatch, so Tick returns without scheduling another Tick call
[6] 2014-12-08 11:10:39.784 Impl.Tick: Hash 15645912: id 1 != _windowId 3. NOT CREATING NEW TIMER

# Changes made
All I've done is to move the CreateTimer call into the _gate lock in both OnNext and Tick. This ensures that the timers are created in the correct order with the correct IDs.

Since the change, I've run through my tests 50 times and been unable to reproduce the issue.

## Unit tests
I was unable to find any unit tests for the Buffer class, but would be happy to update these too if you have any.