.NET 5 BGW Never Finishes in Prod Only

[Shaggy Hiker]

The title sucks, but then again, the problem isn't simple.

Also, everything prior to post #22 that I wrote is essentially misleading. I narrowed down where the problem was. It manifests in weird ways depending on what code is along the way, but it comes down to one thing, which is in #22.

I have a program that downloads some data from a web service and checks it. This is written in .NET5. It works perfectly in debug or release versions while in VS, but does not work any other way, and the difference is quite telling and peculiar.

The way the program works is that the user can choose one or more items from a listbox. They then press a button. For each item selected, a BackGroundWorker is launched to get data from a service for that item. This data will cover a series of pages, so I have to download each page in turn. Each page is then passed to a Task for processing. Therefore, for each item there will be from 1 to 20 Tasks started, one per page.

All those tasks are started in the DoWork handler of the BGW, with one BGW per item selected. At the end of the DoWork, there's a WaitAll on the Tasks, such that when they all finish, the RunWorkerCompleted event for the BGW is called.

That's a fair amount of threading that could be happening. One or more BGW's, each starting 1 or more Tasks, then waiting for all the Tasks to complete before the BGW itself completes.

There is something that needs to be done when ALL the BGW's complete, so I create a form level integer variable to hold the number of tables, and in the RunWorkerCompleted event handler, I call Interlock.Decrement on the variable. When that gets to 0, then all BGW's have completed.

As I said, this is all working in Debug or Release version while in VS. One further point is that once all of this has completed, a DGV on the form shows the results of all the work. A datatable is being populated by the Tasks (in a thread safe fashion). That datatable is bound to the DGV. In VS, nothing shows up until all the BGW's and their Tasks have completed, at which point, the results appear in the form.

While results are being processed, a form is shown that changes information and color to show progress. This is updated in the ProgressChanged event of the BGWs. This looks a bit ugly, in practice, because all the different BGWs share the same ProgressChanged event handler, but nobody cares, cause all they care about is that progress is happening. This form is one of the telling points about the issue, though.

Once again, all of this is working as expected while in VS, whether Debug or Release.

I then took the program and tried to run it outside of VS. The program runs as expected at first. I can select one or more items, then press the button to start processing them. However, unlike in VS, results start showing up right away. They are being added to the result table, and that table is bound to the DGV, so I'm fine with them showing up right away, but this is different from the behavior in VS.

The real problem is that the BGW's, even if only one, never complete. The RunWorkerCompleted event appears to never be raised. The wait form shows that the progress has made it to the final page, which is where it might pause, but the RunWorkerCompleted should hide that form, and the form is never hidden.

I suspected that this might be because the table counter was not being decremented properly, so in the very first rows of the RunWorkerCompleted, I added this:

 lformcount.text = mTableCount.ToString
        lFormCount.Refresh()

I set the count into a label and force a refresh. I do that again after the decrement. In VS, it shows that the count is being properly decremented. It is not being properly decremented in production.

This does not prove that RunWorkerCompleted is not being fired, so I changed that code to set the label to something else (the word 'blue') in the RunWorkerCompleted event. The word Blue did not show up. That does prove that RunWorkerCompleted is not being raised.

So, I have different behavior:
1) The datatable is showing up in the DGV along the way, rather than only at the end. This is unimportant, but it IS a difference from the behavior in VS.
2) The RunWorkerCompleted event is never being called by any of the BGW when not running in VS, though it works fine in VS.

What is going on?

[dday9]

The way the program works is that the user can choose one or more items from a listbox. They then press a button. For each item selected, a BackGroundWorker is launched to get data from a service for that item.

This is a code smell. Why not start one background worker and loop over each item? If you want them to be processed simultaneously you would leverage a parallelism paradigm. What I suspect is happening is that one or more background workers are failing and so your form variable never reaches 0.

Reading your post a bit more, this plays into your suspicion as to what is happening.

With that being said, what are you doing in terms of error handling? Because if one of the workers fail, then I would suspect one of two things to happen:

1. The entire process is stopped and the user is notified
2. One "batch" doesn't stop the process, but it still decreases form variable value.

Update
So for example, if you were to setup your background worker to do the following:

Private Sub MyBackgroundWorker_DoWork(sender As Object, e As DoWorkEventArgs) Handles MyBackgroundWorker.DoWork
    For counter As Integer = 0 To SelectedItems.Length - 1
        Dim failedRequest As Object = Nothing
        Try
            ' do something with the item
        Catch ex As Exception
            failedRequest = SelectedItems(counter)
        Finally
            MyBackgroundWorker.ReportProgress(100 * counter / SelectedItems.Length, failedRequest)
        End Try
    Next
End Sub

Private Sub MyBackgroundWorker_ProgressChanged(sender As Object, e As ProgressChangedEventArgs) Handles MyBackgroundWorker.DoWork
    If (e.UserState IsNot Nothing) Then
        ' e.UserState failed, do something (or not)
    End If
End Sub

[jdc2000]

Another idea to check progress would be to add some code to create a log file for each background process. You could then check the log files to see the results for each process, and see which one(s) are missing log files.

[Shaggy Hiker]

Moved the project back to FW4.8, thinking this might have been a .NET5 issue, but the same thing is happening.

The RunWorkerCompleted event is never being raised for the BGW. It is while in VS, but not outside of VS.

[Shaggy Hiker]

Another idea to check progress would be to add some code to create a log file for each background process. You could then check the log files to see the results for each process, and see which one(s) are missing log files.

Perhaps, but the whole problem comes down to that RunWorkerComplete never being raised outside of VS. That's a bit difficult to log in any meaningful way, because I'm not quite sure what is not happening. One possibility is that the Task.WaitAll is never completing. I'll be testing that one next.

[Shaggy Hiker]

Okay, removing the Tasks solved the problem. Things are running slower, but they are at least completing, now.

So, the issue is that I created a bunch of tasks, adding them to a list of Task as I went with this:

tskList.Add(Task.Run(Sub() ParseOutThePage(tblName, outDict)))

Where tskList is just a List(of Task)

At the end of the DoWork method, I had this line:

Task.WaitAll(tskList.ToArray)

From the behavior that was seen, this line was never completing, which meant that the BGW were not completing. So, why is WaitAll, in fact, WaitFOREVER??

[Shaggy Hiker]

This is a code smell. Why not start one background worker and loop over each item? If you want them to be processed simultaneously you would leverage a parallelism paradigm. What I suspect is happening is that one or more background workers are failing and so your form variable never reaches 0.

Reading your post a bit more, this plays into your suspicion as to what is happening.

With that being said, what are you doing in terms of error handling? Because if one of the workers fail, then I would suspect one of two things to happen:

1. The entire process is stopped and the user is notified
2. One "batch" doesn't stop the process, but it still decreases form variable value.

Update
So for example, if you were to setup your background worker to do the following:

Private Sub MyBackgroundWorker_DoWork(sender As Object, e As DoWorkEventArgs) Handles MyBackgroundWorker.DoWork
    For counter As Integer = 0 To SelectedItems.Length - 1
        Dim failedRequest As Object = Nothing
        Try
            ' do something with the item
        Catch ex As Exception
            failedRequest = SelectedItems(counter)
        Finally
            MyBackgroundWorker.ReportProgress(100 * counter / SelectedItems.Length, failedRequest)
        End Try
    Next
End Sub

Private Sub MyBackgroundWorker_ProgressChanged(sender As Object, e As ProgressChangedEventArgs) Handles MyBackgroundWorker.DoWork
    If (e.UserState IsNot Nothing) Then
        ' e.UserState failed, do something (or not)
    End If
End Sub

I have it set up pretty much as you showed. Any exceptions in the BGW are being handled within the DoWork. That will end the BGW, at which point, it should complete. No exceptions were being raised, though. It was just that WaitAll was never returning, which meant that the BGW didn't complete.

I should mention that, while I would process multiple items in parallel, I wasn't. This was happening with just a single BGW. It was happening with two, as well, but the counter label showed that the counter never decremented. Neither BGW was completing, and I see no reason why they should, since one was never completing.

The issue comes down to that WaitAll. For some reason, that was blocking forever.

[jdc2000]

Some Russian novels that might have some useful information:

https://medium.com/@deep_blue_day/lo...t-1f39d7d84050

https://www.tugberkugurlu.com/archiv...sp-net-web-api

https://www.infoworld.com/article/31...ll-in-net.html

https://docs.microsoft.com/en-us/dot...l?view=net-6.0

https://docs.microsoft.com/en-us/dot...k?view=net-6.0

[dday9]

Ah, yeah that will do it. You probably want WhenAll instead of WaitAll. Per the documentation, the former will:

Create a task that will complete when all of the supplied tasks have completed.

[Shaggy Hiker]

As to why not to start just one BGW, it is because this is a reasonable place for threading. Each item can be processed in parallel, each item will take several seconds to process, and it is entirely possible to report progress while each is being processed. A BGW is nice in that it has that built-in mechanism for reporting progress. That's why I felt it was the easy way to go as far as running them in parallel while reporting progress.

For each item, the process is to go to a service and ask for a page. Each page can be processed in parallel, as well, which is what the Tasks were doing. Each Task processed one page. There could be hundreds of pages per item. A page is just a series of data rows of various sizes, each of which is being checked for validity. Therefore, the BGW could ask for each page in turn, but pass the pages off to be processed by individual Tasks.

When I removed the Tasks, the speed of processing one item dropped from 34 seconds to about 60 seconds, which shows the advantage that the Tasks were providing. Having two BGW working at the same time didn't increase the time taken to complete the whole process, so that was nice, as well.

[Shaggy Hiker]

Ah, yeah that will do it. You probably want WhenAll instead of WaitAll. Per the documentation, the former will:

No, I don't think I want that. I'm not looking to create a task, as far as I know. This is the documentation for WaitAll:

Waits for all of the provided Task objects to complete execution.

That is exactly what I wanted to do: Wait till they all completed, then continue in the current process.

EDIT: And do keep in mind that this works correctly when run in VS, whether with FW4.8 or .NET5. It just doesn't work when NOT in VS. That is particularly frustrating, as it makes it hard to study the problem.

[jdc2000]

Maybe time to report the issue to Microsoft?

[dbasnett]

Based on what I think you said I tried to reproduce your problem. I couldn't. Here is what I used to test,

    Private Async Sub Button1_Click(sender As Object, e As EventArgs) Handles Button1.Click
        RichTextBox1.Clear()
        Dim L_bgw As New List(Of System.ComponentModel.BackgroundWorker)
        Dim bgw As System.ComponentModel.BackgroundWorker
        Dim arg As Integer = 11
        For x As Integer = 1 To arg - 1
            bgw = New System.ComponentModel.BackgroundWorker
            bgw.WorkerReportsProgress = True
            bgw.WorkerSupportsCancellation = True

            L_bgw.Add(bgw)
            RemoveHandler bgw.DoWork, AddressOf bgw_DoWork
            RemoveHandler bgw.ProgressChanged, AddressOf bgw_ProgressChanged
            RemoveHandler bgw.RunWorkerCompleted, AddressOf bgw_RunWorkerCompleted
            RemoveHandler bgw.Disposed, AddressOf bgw_Disposed

            AddHandler bgw.DoWork, AddressOf bgw_DoWork
            AddHandler bgw.ProgressChanged, AddressOf bgw_ProgressChanged
            AddHandler bgw.RunWorkerCompleted, AddressOf bgw_RunWorkerCompleted
            AddHandler bgw.Disposed, AddressOf bgw_Disposed
        Next

        For Each bgw In L_bgw
            bgw.RunWorkerAsync(arg)
            arg -= 1
        Next
        Dim t As Task = Task.Run(Sub()
                                     Dim ct As Integer
                                     Do
                                         ct = L_bgw.Count
                                         For Each bgw In L_bgw
                                             If Not bgw.IsBusy Then
                                                 ct -= 1
                                             End If
                                         Next
                                         Threading.Thread.Sleep(100)
                                     Loop While ct > 0
                                     For Each bgw In L_bgw
                                         bgw.Dispose()
                                     Next
                                 End Sub)
        Await t
        RichTextBox1.AppendText("FINI")
        RichTextBox1.AppendText(ControlChars.Cr)
        RichTextBox1.ScrollToCaret()
    End Sub

    Private Sub bgw_DoWork(sender As Object,
                           e As System.ComponentModel.DoWorkEventArgs)

        Dim arg As Integer = DirectCast(e.Argument, Integer)
        Dim bgw As System.ComponentModel.BackgroundWorker = DirectCast(sender, System.ComponentModel.BackgroundWorker)
        bgw.ReportProgress(arg)

        Dim L_tsk As New List(Of Task)
        For x As Integer = 1 To arg
            Dim tsk As Task
            tsk = Task.Run(Sub()
                               FooTask()
                           End Sub)
            L_tsk.Add(tsk)
        Next
        Task.WaitAll(L_tsk.ToArray)
        Me.Invoke(Sub()
                      RichTextBox1.AppendText("End " & arg.ToString & "  Hash = " & bgw.GetHashCode.ToString)
                      RichTextBox1.AppendText(ControlChars.Cr)
                  End Sub)
    End Sub

    Private Sub bgw_ProgressChanged(sender As Object,
                                    e As System.ComponentModel.ProgressChangedEventArgs)
        Me.Invoke(Sub()
                      RichTextBox1.AppendText("Start " & e.ProgressPercentage.ToString)
                      RichTextBox1.AppendText(ControlChars.Cr)
                  End Sub)
    End Sub

    Private Sub bgw_RunWorkerCompleted(sender As Object,
                                       e As System.ComponentModel.RunWorkerCompletedEventArgs)
        Dim bgw As System.ComponentModel.BackgroundWorker = DirectCast(sender, System.ComponentModel.BackgroundWorker)
        Me.Invoke(Sub()
                      RichTextBox1.AppendText("Complete Hash = " & bgw.GetHashCode.ToString)
                      RichTextBox1.AppendText(ControlChars.Cr)
                      RichTextBox1.ScrollToCaret()
                  End Sub)
    End Sub

    Private Sub bgw_Disposed(sender As Object,
                             e As EventArgs)
        Me.Invoke(Sub()
                      RichTextBox1.AppendText("<<<<<<<<<<<<<<<<")
                      RichTextBox1.AppendText(ControlChars.Cr)
                      RichTextBox1.ScrollToCaret()
                  End Sub)
    End Sub

    Private Shared PRNG As New Random
    Private _Lock As New Threading.ManualResetEvent(True)
    Private ReadOnly _LOOP As Integer = 19654321
    Private Sub FooTask()
        Threading.Thread.Sleep(1)
        _Lock.WaitOne()
        Dim rnd As Integer = PRNG.Next(2, 11)
        _Lock.Set()

        Me.Invoke(Sub()
                      RichTextBox1.AppendText("rnd = " & rnd.ToString)
                      RichTextBox1.AppendText(ControlChars.Cr)
                      RichTextBox1.ScrollToCaret()
                  End Sub)
        Dim sb As New System.Text.StringBuilder
        Dim temp As Integer
        For x As Integer = 1 To rnd
            sb.Append(x.ToString)
            For y As Integer = 1 To _LOOP
                temp = y
            Next
            Threading.Thread.Sleep(50)
        Next
    End Sub

[Shaggy Hiker]

That's a bit inverted from what I was doing, as I have the DoWork method creating all the Tasks.

However, did you test this only in VS, or did you try it outside of VS? After all, it ran as expected while in VS.

[OptionBase1]

Is your project configured to do something extra, that isn't being done when simply launching the exe, like run with specific command line parameters?

[dbasnett]

That's a bit inverted from what I was doing, as I have the DoWork method creating all the Tasks.

However, did you test this only in VS, or did you try it outside of VS? After all, it ran as expected while in VS.

I did try it outside of VS. Don't I have several BGW's creating a bunch of tasks?

[Shaggy Hiker]

Well, forget all that, the situation has gotten weirder.

I removed the Tasks, as it looked like the WaitAll was causing the problem. In fact, that was probably a mistake. It was producing a symptom, but likely wasn't the cause.

With the tasks removed, and one single BGW running (as opposed to firing off a few of them), I found that the program runs to a point, then waits for 260 seconds, or so, and then completes. Once again, this doesn't happen in VS, where the program completes in 2 to 4 seconds for the same work. Also, it is pretty clear where that 260 seconds comes from, which is partway through the RunWorkerCompleted event handler.

I was thinking that the WaitAll might have been just delayed, the way the current process appears to be delayed, but that...well, hard to say.

So, here's what's happening:

1) Right off, before the BGW is launched, a form is shown non-modally. This will report progress. It mostly indicates progress by changing colors steadily and hypnotically.
2) The BGW reports progress, which changes the color on that WaitForm.
3) In the RunWorkCompleted event handler, I added this code:

        lFormCount.Text = "blue" 
        lFormCount.Refresh()

        If Interlocked.Decrement(mTableCount) = 0 Then
            m***orm.Close()
            m***orm.Dispose()
          
            lFormCount.Text = "green"
            lFormCount.Refresh()

What you see is a label being set and forcibly refreshed, then the Interlocked.Decrement, then the WaitForm is closed, then the label is forcibly changed. Basically, I wanted to see what the label would say during that long pause. It starts as a number, so if it was showing a number, then the RunWorkerCompleted hadn't even been called. If it showed 'Blue', and the WaitForm was still visible, then the delay was on the Interlocked.Decrement. If it showed 'green' then it got past the WaitForm. There were other indicators later on, but they don't matter.

When I have the Tasks in place, the label shows the number, which means that the RunWorkerCompleted was never even entered. When I removed the Tasks, the label showed 'blue' during the long delay, but the WaitForm was hidden. That means that the delay appears to have happened between the m***orm.Close() call and the next setting of the label.

Therefore, I decided to increase the information by changing the code to this:

        lFormCount.Text = "blue" 
        lFormCount.Refresh()

        If Interlocked.Decrement(mTableCount) = 0 Then
            lFormCount.Text = "puce"
            lFormCount.Refresh()
            m***orm.Close()
            lFormCount.Text = "cyan"
            lFormCount.Refresh()
            m***orm.Dispose()
          
            lFormCount.Text = "green"
            lFormCount.Refresh()

The label now shows 'puce', but the wait form is no longer visible. In other words, while the wait form does appear to have been closed, the code has not progressed past the WaitForm.Close method.

[Shaggy Hiker]

Oooookay. So that string of characters triggered the censor. How very strange is that? I guess not very. I abbreviated Wait to Wt, so Wt followed by Form put a string of three characters together that are censored. Whatever.

[dday9]

The acronym for: what the fudge

[Shaggy Hiker]

The next test was to comment out the wait form. The delay is still there, but the label now shows 'yellow'. That's just a bit further into the RunWorkerCompleted method, and just another nondescript place. From the color it shows when it hangs until it finishes, takes less than a millisecond. It just isn't always hanging in the same place. It hangs somewhere in the RunWorkerCompleted event handler, and the Wait Form doesn't appear to have anything to do with that. That's why I think the Tasks were also unrelated. The changes I make change where the delay happens, but doesn't change the fact that there is a delay. Also, the delay is always exactly 260 seconds on this computer (though I thought I saw 255 seconds on a different computer).

It feels like something is timing out, and it only completes when the timeout completes. Off to do more tests.

EDIT: Removed the ReportProgress entirely and it didn't change anything.

[OptionBase1]

Could a software firewall (Windows own or 3rd party) be in play here?

When executing from within VS, I'm assuming (admittedly blindly) that the running project has the "network permissions" of VS itself, which presumably are "anything goes". When executing as a stand-alone .exe file, perhaps some portion of the communication your program does is being blocked.

[Shaggy Hiker]

Okay, after a long series of tests, I'm pretty sure that it comes down to a single method. I expect that I'm using something wrong in it, and quite likely, everything I found prior to this was misleading.

I narrowed it down to a single call to a method called WriteOutput. The purpose of this method is to write a record to a datatable. Since this could be happening from a series of different threads, potentially, I wanted to lock the operation. Therefore, the body of the method looks like this:

       SyncLock mLockObject
            Dim nr = mDTResults.NewRow
            nr("TableName") = tableName
            nr("Field") = field
            nr("Issue") = issue
            nr("PK") = PK
            mDTResults.Rows.Add(nr)
        End SyncLock

In VS, this works fine. Outside of VS, it seems to work mostly fine. After all, the datatable is being populated, and what is in there certainly looks correct. However, if I comment out that code, then all is well (except that I don't get any data in the table). If I uncomment that code, then all the data looks great, but there's a 260 second delay that happens at some point after everything has been written, or perhaps on the last line.

So, am I misusing the Synclock? And for that matter, is it necessary? The new row is a local variable, so it seems like it might not be necessary, but I'm not sure.

[Shaggy Hiker]

Guess I spoke too soon. It's that function alright, but it isn't the SyncLock that's causing the problem.

In fact, after a bit more testing, it dawned on me that the program should have been crashing pretty early on, but it wasn't. One way or another, that was the ultimate issue.

I was populating a datatable, as can be seen in post #22. The default dataview of that DT was set as the datasource of the DGV on the form back in the constructor, before any of the work was done. In other words, I was updating a UI element from a background thread without turning off CheckForIllegalCrossThreadCalls (because that should NEVER be turned off). So...why was this NOT an illegal cross thread call? Why was I able to add rows to a datatable bound to a UI element? Those rows don't become visible in VS until after the thread has finished. When outside of VS, those rows became visible right away. I noticed that difference, and even mentioned it in the initial post, but didn't see the significance of that difference right away: I was updating a UI control from a background thread, which should have thrown an exception, or so I would have thought. Technically, I wasn't directly accessing the control, just directly accessing a datatable that happened to be bound to the control, but that's just a quibble, I would think. The control WAS being updated when not in VS, because I could see the data populating the control.

When I moved the databinding into the RunWorkerCompleted event, such that I am now populating the datatable, but it's not bound to the DGV until after the table has been fully populated, then the problem went away completely. So, the solution was to gather the data in the background thread, then display it.