Remote GUI (knewc) Slow After Deleting Recording

[BrettB]

sub: I've been working Martin on some slowness/timeout things with knewc recently. And I just captured a possibly good example with a theory of "why".

I watched a recording, stopped it, hit the Record button to delete it, confirmed, and then knewc timed out (the alpha test version I'm using times out after 10 seconds with no response from the server).

Code:

2020-09-28 12:24:43.677 [DEBUG][11] DeleteRecording(14757)
2020-09-28 12:24:43.677 [DEBUG][11] DeleteRecording@1
2020-09-28 12:24:43.677 [DEBUG][11] -removing: E:\NPVR Recordings2\Lights Out With David Spade\Lights Out with David Spade.S01E01.Dana Carvey, Al Madrigal, Sarah Tiana.ts
2020-09-28 12:24:44.130 [DEBUG][11] DeleteRecording@2
2020-09-28 12:24:44.130 [DEBUG][11] -removing: E:\NPVR Recordings2\Lights Out With David Spade\Lights Out with David Spade.S01E01.Dana Carvey, Al Madrigal, Sarah Tiana.log
2020-09-28 12:24:44.130 [DEBUG][11] -removing: E:\NPVR Recordings2\Lights Out With David Spade\Lights Out with David Spade.S01E01.Dana Carvey, Al Madrigal, Sarah Tiana.edl
2020-09-28 12:24:44.145 [DEBUG][11] PlaybackPositionHelper.DeletePlaybackPosition(E:\NPVR Recordings2\Lights Out With David Spade\Lights Out with David Spade.S01E01.Dana Carvey, Al Madrigal, Sarah Tiana.ts)
2020-09-28 12:24:44.145 [DEBUG][11] DeleteRecording@5
2020-09-28 12:24:44.145 [DEBUG][11] DeleteRecording@exit
2020-09-28 12:24:44.145 [DEBUG][11] ActivatePopup: null
2020-09-28 12:24:44.145 [DEBUG][11] deactivating old popup: Popup
2020-09-28 12:24:44.145 [DEBUG][11] Going to dispose popup at end of animation
2020-09-28 12:24:44.145 [DEBUG][11] Calling dispose on old popup: Popup
2020-09-28 12:24:44.145 [DEBUG][11] Recordings.RELOAD_RECORDINGS

But then the NextPVR GUI server seems to call RELOAD_RECORDINGS 20! times

Code:

2020-09-28 12:24:44.676 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:45.128 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:45.580 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:46.033 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:46.719 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:47.437 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:47.640 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:47.827 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:48.373 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:48.841 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:49.293 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:49.761 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:50.276 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:50.728 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:51.181 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:51.384 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:51.883 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:52.382 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:52.912 [DEBUG][11] Recordings.RELOAD_RECORDINGS
2020-09-28 12:24:53.443 [DEBUG][11] Recordings.RELOAD_RECORDINGS

before finally rendering a screen to send back to knewc

Code:

2020-09-28 12:24:54.067 [DEBUG][11] DoCompositeRendering() took 93.5994ms

Unfortunately, by that time, 11 seconds have elapsed and now knewc has timed-out!

What I realized looking at this example, was that the recording I had just deleted was the only one in that folder. So when NextPVR was going to go back to the recording list after the delete completed, the folder it would have normally gone back to was no longer there. I'm guessing that this is (part) of what trigger calling RELOAD_RECORDINGS so many times.

I'm hoping that you can take a look at the code and see what is happening!

[BrettB]

I guess the problem with multiple reloads isn't related to the delete. I just had the same thing happen when simply stopping playback (before I even got the chance to delete).

Code:

2020-09-28 14:43:51.162 [DEBUG][66] Got request [::ffff:192.168.143.26]: /control
2020-09-28 14:43:51.162 [DEBUG][66] PreventMonitorStandby() needs implementation
2020-09-28 14:43:51.162 [DEBUG][66] About to store playback position information
2020-09-28 14:43:51.162 [DEBUG][66] PlaybackPositionHelper.StorePlaybackPosition(The Great Indoors.S01E21.Rolands Secret.ts, 1855, 2161)
2020-09-28 14:43:51.162 [DEBUG][66] PlaybackPositionHelper.DeletePlaybackPosition(F:\NPVR Recordings3\The Great Indoors\The Great Indoors.S01E21.Rolands Secret.ts)
2020-09-28 14:43:51.193 [DEBUG][66] GetExtraInfo: ResumePointsChanged
2020-09-28 14:43:51.193 [DEBUG][66] Resume point has changed for playback of recording
2020-09-28 14:43:51.193 [DEBUG][66] GetExtraInfo@exit
2020-09-28 14:43:51.209 [DEBUG][66] Setting activity: stop
2020-09-28 14:43:51.209 [DEBUG][66] Recordings.RELOAD_RECORDINGS

This time there are 22 RELOAD_RECORDINGS!

Code:

2020-09-28 14:43:51.209 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:51.848 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:52.301 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:52.753 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:53.221 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:53.908 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:54.750 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:54.953 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:55.452 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:56.076 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:56.528 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:56.996 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:57.527 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:57.963 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:58.447 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:58.665 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:59.211 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:43:59.757 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:44:00.225 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:44:00.756 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:44:01.286 [DEBUG][66] Recordings.RELOAD_RECORDINGS
2020-09-28 14:44:01.707 [DEBUG][66] Recordings.RELOAD_RECORDINGS

finally rendering and returning the screen 11 seconds later:

Code:

2020-09-28 14:44:02.144 [DEBUG][66] Recordings.RELOAD_RECORDINGS@2
2020-09-28 14:44:02.144 [DEBUG][66] PlaybackPositionHelper.GetLastPlaybackDate(F:\NPVR Recordings3\The Great Indoors\The Great Indoors.S01E21.Rolands Secret.ts)
2020-09-28 14:44:02.160 [DEBUG][66] Recordings.RELOAD_RECORDINGS@exit
2020-09-28 14:44:02.425 [DEBUG][66] DoCompositeRendering() took 62.3996ms
2020-09-28 14:44:38.258 [DEBUG][33] Got request [::ffff:192.168.143.33]: /index.html

As a test, I also tried playing the same file from the NextPVR.exe client. It only has one RELOAD_RECORDINGS:

Code:

2020-09-28 14:49:13.999 [DEBUG][1] Stop@0
2020-09-28 14:49:13.999 [DEBUG][1] Stopping graph@1
2020-09-28 14:49:14.373 [DEBUG][1] Stopping graph@2
2020-09-28 14:49:14.373 [DEBUG][1] Stopping graph@3
2020-09-28 14:49:14.387 [DEBUG][1] Removing filter  AC3 Audio Renderer
2020-09-28 14:49:14.391 [DEBUG][1] Removing filter  NPVR CC Dump
2020-09-28 14:49:14.391 [DEBUG][1] Removing filter  EVR Renderer
2020-09-28 14:49:14.425 [DEBUG][1] Removing filter  LAV Audio Decoder
2020-09-28 14:49:14.426 [DEBUG][1] Removing filter  Line 21 Decoder
2020-09-28 14:49:14.426 [DEBUG][1] Removing filter  LAV Video Decoder
2020-09-28 14:49:14.429 [DEBUG][1] Removing filter  NPVR CC Extractor
2020-09-28 14:49:14.432 [DEBUG][1] Removing filter  NPVR TS Reader 5
2020-09-28 14:49:14.435 [DEBUG][1] Recordings.RELOAD_RECORDINGS
2020-09-28 14:49:14.435 [DEBUG][1] Recordings.RELOAD_RECORDINGS@1
2020-09-28 14:49:14.435 [DEBUG][1] LoadList@0
2020-09-28 14:49:14.437 [DEBUG][1] LoadList@1
2020-09-28 14:49:14.690 [DEBUG][1] LoadList@2
2020-09-28 14:49:14.690 [DEBUG][1] LoadList@3
2020-09-28 14:49:14.949 [DEBUG][1] LoadList@setobjects
2020-09-28 14:49:14.960 [DEBUG][1] LoadList@exit
2020-09-28 14:49:14.960 [DEBUG][1] Recordings.RELOAD_RECORDINGS@2
2020-09-28 14:49:14.961 [DEBUG][1] PlaybackPositionHelper.GetLastPlaybackDate(F:\NPVR Recordings3\The Great Indoors\The Great Indoors.S01E21.Rolands Secret.ts)
2020-09-28 14:49:14.974 [DEBUG][1] Recordings.RELOAD_RECORDINGS@exit
2020-09-28 14:49:14.992 [DEBUG][1] Calling dispose on old popup(2): ShowDetailsPopup
2020-09-28 14:49:14.992 [DEBUG][1] ShowDetailsPopup.Dispose()

And the corresponding nrecord.log only shows:

Code:

2020-09-28 14:49:12.929 [DEBUG][76] Got request [::ffff:192.168.143.26]: /activity
2020-09-28 14:49:13.995 [DEBUG][79] GetExtraInfo: ResumePointsChanged
2020-09-28 14:49:13.995 [DEBUG][79] Resume point has changed for playback of recording
2020-09-28 14:49:13.996 [DEBUG][79] GetExtraInfo@exit
2020-09-28 14:49:14.947 [DEBUG][82] Got request [::ffff:192.168.143.26]: /activity

[sub]

Can you try these patches. If it doesn't help, post the logs (I've added some additional logging).

[BrettB]

Can you try these patches. If it doesn't help, post the logs (I've added some additional logging).

Hey, sub.

I put in these patches a few days ago. They seem to have helped with the timeouts. However, looking at the logs, there are still a lot of RELOAD_RECORDINGS, but now they have stack dumps:

Code:

2020-10-03 17:26:01.579    [DEBUG][36]    Recordings.RELOAD_RECORDINGS
2020-10-03 17:26:01.579    [ERROR][36]       at System.Environment.get_StackTrace()
   at NextPVR.TV.Recordings2.Notify(String eventName, Object eventArg)
   at NUtility.EventBus.Notify(String eventName, Object eventArg)
   at NextPVR.TV.Recordings2.PluginCallback(Object source, String command, Object args)
   at NUtility.Base.SimplePopup.HandleCommand(String command)
   at NUtility.Base.SimpleMessageBox.OnKeyDown(KeyEventArgs e)
   at NUtility.UIController.OnKeyDown(KeyEventArgs e)
   at NextPVRServer.Controllers.WebClientHelper.GetImage(Dictionary`2 args)
   at NextPVRServer.Controllers.WebClientController.Get()
   at lambda_method(Closure , Object , Object[] )
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAwaitedAsync()
   at Microsoft.AspNetCore.Mvc.Controller.OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextResourceFilter()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeAsync()
   at Microsoft.AspNetCore.Builder.RouterMiddleware.Invoke(HttpContext httpContext)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at Microsoft.AspNetCore.Builder.RouterMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware.Invoke(HttpContext context)
   at NPVR5.Startup.<Configure>b__7_1(HttpContext context, Func`1 next)
   at NPVR5.Startup.<>c.<<Configure>b__7_0>d.MoveNext()
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at NPVR5.Startup.<>c.<Configure>b__7_0(HttpContext context, Func`1 next)
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.ResponseCompression.ResponseCompressionMiddleware.Invoke(HttpContext context)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at Microsoft.AspNetCore.ResponseCompression.ResponseCompressionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.StaticFiles.DefaultFilesMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
2020-10-03 17:26:01.579    [DEBUG][36]    Recordings.RELOAD_RECORDINGS@1

[BrettB]

sub: Have you had a chance to look at the cause of all these stack dumps in the RELOAD_RECORDINGS calls?

[BrettB]

sub: Have you had a chance to look at the cause of all these stack dumps in the RELOAD_RECORDINGS calls?

BUMP

[sub]

Sorry had meant to reply. I did take a look at these logs, but it still isn't clear to me why this is happening. I'll probably need to look at adding further logging.

[BrettB]

Sorry had meant to reply. I did take a look at these logs, but it still isn't clear to me why this is happening.  I'll probably need to look at adding further logging.

Just to update with current version (5.0.9.201018) logs, the stack dump is still happening:

Code:

2020-10-18 08:42:56.253    [DEBUG][7]    Recordings.RELOAD_RECORDINGS
2020-10-18 08:42:56.253    [ERROR][7]       at System.Environment.get_StackTrace()
   at NextPVR.TV.Recordings2.Notify(String eventName, Object eventArg)
   at NextPVR.TV.Recordings2.NeedsRendering()
   at NUtility.UIController.GetActivity(Dictionary`2 args)
   at NextPVRServer.Controllers.WebClientHelper.GetActivity(Dictionary`2 args)
   at NextPVRServer.Controllers.WebClientActivityController.Get()
   at lambda_method(Closure , Object , Object[] )
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAwaitedAsync()
   at Microsoft.AspNetCore.Mvc.Controller.OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextResourceFilter()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeAsync()
   at Microsoft.AspNetCore.Builder.RouterMiddleware.Invoke(HttpContext httpContext)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at Microsoft.AspNetCore.Builder.RouterMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware.Invoke(HttpContext context)
   at NPVR5.Startup.<Configure>b__7_1(HttpContext context, Func`1 next)
   at NPVR5.Startup.<>c.<<Configure>b__7_0>d.MoveNext()
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at NPVR5.Startup.<>c.<Configure>b__7_0(HttpContext context, Func`1 next)
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.ResponseCompression.ResponseCompressionMiddleware.Invoke(HttpContext context)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at Microsoft.AspNetCore.ResponseCompression.ResponseCompressionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.StaticFiles.DefaultFilesMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
2020-10-18 08:42:56.253    [DEBUG][7]    Recordings.RELOAD_RECORDINGS@1

[sub]

Sorry had meant to reply. I did take a look at these logs, but it still isn't clear to me why this is happening.  I'll probably need to look at adding further logging.

Just to update with current version (5.0.9.201018) logs, the stack dump is still happening:

Oops. I've disabled it for the next build.