RDAirPlay and "Wait up to" Grace Time Misbehavior

[dklann]

When an event scheduled near the end of the day is configured with a Hard Start and a Wait up to (aka grace) time, under specific conditions (see below), RDAirPlay stops playing the cart and jumps exactly 90 positions down the log and picks up at the start of the cart at that line.

I have observed and can reliably reproduce this behavior with Rivendell version 3.6.7 and 4.0.0rc3.

Steps to Reproduce

• build some logs with RDLogManager or RDLogEdit

• ensure your first log includes a LOG CHN event at the end. Set this event to have a Start at time of 23:59:45, and a "Wait up to" time of two minutes (02:00), with a STOP transition. The intention of this is to load the specified log no earlier than 23:59:45 and no later than one minute and 45 seconds past midnight

• set the Linux system time-of-day clock to 23:59:00 with sudo date MMDD2359

• launch RDAirPlay and load the first log: rdairplay --log1=YOUR_FIRST_LOG_NAME

• manually start an event before the LOG CHN event in the log, and start it so that the LOG CHN occurs after midnight

• watch as the next log is loaded and starts playing

• at the number of seconds after the hard start time of the LOG CHN event (120 in this case), observe the currently-playing cart stop, and RDAirPlay jump to line (or Count) 90 in that log and continue playback

What I Expected To Happen

I expect the event that starts after midnight will play to the end of the cart and continue processing each of the log's events as normal.

What Happened

It is often the case that the Hard Start event runs before the expiration of the grace timer, but after midnight. When the new day's log starts after midnight, RDAirPlay "cuts off" (immediately stops) the cart that is playing. This "cutoff" takes place at the number of seconds past the time at which the timed LOG CHN event would have started had the grace timer been needed. Most unexpectedly, RDAirPlay jumps to a line in the log that has so far predictably been the ninety-first event in the log (Count == 90). It does this only when the LOG CHN event fires and the new day's log is loaded and started after midnight.

I have observed the above behavior using shorter logs (just 5 lines in the log) and the "jump" behavior does not happen. The cart that is playing when the grace timer expires simply stops and the next event begins.

In any case, if the grace timer were canceled, nothing unexpected would happen and the log would simply run as normal.

How I Worked Around The Issue

Avoid using a "Wait up to" grace timer on events that take place near the end of a day. Or ensure that events with grace times start before the end of the day on which they are supposed to run.

Additional Thoughts

It seems to me that something is being missed when an event's grace time starts before the end of a day and expires the next day, and when that event runs after midnight. It seems like that timer is not being canceled.

As another troubleshooting test, I have assigned a "Hard Start", "Wait up to" to an event prior to the LOG CHN event and am able to reproduce the "log jump" behavior. In this case (as before), the errant behavior is induced when the event with the grace time runs after midnight and before the expiration of the grace timer.

The bigger puzzle for me is, "Why jump 90 lines down the log?" Why not simply continue the log with the next event?

[ElvishArtisan]

Partially confirmed here. I'm not seeing the 90 line offset, but rather a 2 line one. Definitely bonkers though.

[dklann]

Thanks for confirming Fred! I expect the 90-line "jump" is pretty situation-specific. I was able to make it jump different number of lines with different length logs... I know it's kind of an "edge case", so I'm eager to see what the fix might be!

[ElvishArtisan]

Certainly a convoluted set of circumstances to goose it, but the fix appears to be a simple one-liner. Basically, stop the grace timer before doing a chain-to!

Fixed in e19301d. Please test.

[dklann]

Awesome! Compiling now ... What do you think about applying this to the 3.6.x version?

[dklann]

Confirmed working here. I ran several logs that crossed midnight and several that ended before midnight. Worked as expected in both scenarios; no unwanted "log jumps". Thanks again!