Failure to cancel buffer restart timer

[aza547]

Describe the bug
See title. User did a M+. Following is in logs:

[2022-09-19 23:41:36.663] [info]  [OBS] obsRecorder: start
[2022-09-19 23:41:36.802] [debug] [OBS] Asserted OBS signal: recording start
[2022-09-19 23:41:43.633] [debug] [ChallengeMode] Starting Challenge Mode instance
[2022-09-19 23:41:43.634] [info]  [Recorder] Start recording by cancelling buffer restart
[2022-09-19 23:41:43.635] [info]  [Logutils] Handling zone change:  {
  timestamp: '9/19 23:41:26.922',
  args: [ 'ZONE_CHANGE', '2441', 'Tazavesh, the Veiled Market', '8' ]
}
[2022-09-19 23:42:12.780] [info]  [Logutils] Handling zone change:  {
  timestamp: '9/19 23:42:11.196',
  args: [ 'ZONE_CHANGE', '2441', 'Tazavesh, the Veiled Market', '8' ]
}
[2022-09-19 23:44:38.427] [debug] [ChallengeMode] Starting new boss encounter: Zo'phex the Sentinel
[2022-09-19 23:45:33.115] [debug] [ChallengeMode] Ending boss encounter: Zo'phex the Sentinel
[2022-09-19 23:46:33.390] [info]  [Recorder] Restart recording buffer
[2022-09-19 23:46:33.390] [info]  [OBS] obsRecorder: stop
[2022-09-19 23:46:33.404] [debug] [OBS] Asserted OBS signal: recording stopping
[2022-09-19 23:46:34.595] [debug] [OBS] Asserted OBS signal: recording stop

Notice the ordering:
23:41:33 - Buffer restarts as expected.
23:41:43 - Cancel buffer restart on M+ start.
23:46:33 - Buffer restarts exactly 5 mins later -- clearly it didn't get cancelled.

The restart proceeds to continue throughout the dungeon, obviously giving the wrong size of video at the end.

Expected behavior
Buffer is cancelled as expected. Video is expected size.

Screenshots
https://i.imgur.com/hYkRd39.png

[aza547]

2022-09-19_15-24-24.txt
WarcraftRecorder-2022-09-20 (1).log
WarcraftRecorder-2022-09-19 (6).log
2022-09-20_09-56-36.txt

[aza547]

Ahaa!

Right before we start recording:

[2022-09-19 23:26:33.373] [info]  [Recorder] Restart recording buffer
[2022-09-19 23:27:15.289] [info]  [Recorder] Restart recording buffer
[2022-09-19 23:31:33.377] [info]  [Recorder] Restart recording buffer
[2022-09-19 23:32:15.291] [info]  [Recorder] Restart recording buffer
[2022-09-19 23:36:33.379] [info]  [Recorder] Restart recording buffer
[2022-09-19 23:37:15.301] [info]  [Recorder] Restart recording buffer
[2022-09-19 23:41:33.390] [info]  [Recorder] Restart recording buffer
[2022-09-19 23:46:33.390] [info]  [Recorder] Restart recording buffer
[2022-09-19 23:51:33.400] [info]  [Recorder] Restart recording buffer

We have somehow ended up with more than 1 restart timer -- it's been leaked! Notice how timers are more frequent than each 5min.

[aza547]

Pretty sure the bug is in this series of events:

$ grep "Start recording buffer\|by cancelling\|App ready\|Wow.exe\|Stop recording buffer\|No buffer recording to" WarcraftRecorder-2022-09-19.6.log
[2022-09-19 15:24:23.148] [info]  [Main] App ready
[2022-09-19 15:24:27.318] [info]  [Logutils] Wow.exe has stopped
[2022-09-19 15:39:53.975] [info]  [Logutils] Wow.exe is running
[2022-09-19 15:39:53.976] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-19 16:44:15.332] [info]  [Logutils] Wow.exe has stopped
[2022-09-19 16:44:15.333] [info]  [Recorder] Stop recording buffer
[2022-09-19 19:38:33.734] [info]  [Logutils] Wow.exe is running
[2022-09-19 19:38:33.735] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-19 22:29:34.033] [info]  [Recorder] Start recording by cancelling buffer restart
[2022-09-19 22:30:54.412] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-19 22:35:25.153] [info]  [Recorder] Start recording by cancelling buffer restart
[2022-09-19 22:36:44.291] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-19 22:40:02.778] [info]  [Recorder] Start recording by cancelling buffer restart
[2022-09-19 22:41:11.215] [info]  [Recorder] Start recording by cancelling buffer restart
[2022-09-19 22:41:32.842] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-19 22:42:18.883] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-19 22:46:54.763] [info]  [Recorder] Start recording by cancelling buffer restart
[2022-09-19 22:48:24.574] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-19 22:52:32.045] [info]  [Recorder] Start recording by cancelling buffer restart
[2022-09-19 22:53:58.287] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-19 22:56:37.778] [info]  [Recorder] Start recording by cancelling buffer restart
[2022-09-19 22:58:27.030] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-19 22:59:38.092] [info]  [Recorder] Start recording by cancelling buffer restart
[2022-09-19 23:02:14.720] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-19 23:41:43.634] [info]  [Recorder] Start recording by cancelling buffer restart
[2022-09-20 00:01:42.522] [info]  [Recorder] Recorder: Start recording buffer
[2022-09-20 00:05:15.504] [info]  [Logutils] Wow.exe has stopped
[2022-09-20 00:05:15.504] [info]  [Recorder] Stop recording buffer

[aza547]

Propose we guard against ever having multiple buffers. That's a state we should never be in.

There is still an issue here that we called start recording buffer twice in succession. That's a logutils bug.