Log.Error shouldn't be printing "unhandled" message

[bclothier]

Given the following minimal repro:

Public Sub Test()
    
    DoCmd.OpenForm "frmVCSMain", , , , , acHidden
    Form_frmVCSMain.StartBuild False
    Log.Clear
    Log.Active = True
    
    On Error GoTo Derp
    
    Debug.Print 1 / 0
    
Dying:
    Log.Flush
    Stop ' check output
    Form_frmVCSMain.FinishBuild False
    Exit Sub
    
Derp:
    Log.Error eelError, "Derp", "Bonk"
    Resume Dying
End Sub

We get:

This is because within the Log.Error, there are calls that eventually reaches LogUnhandledError, particularly modDatabase.VerifyFocus, possibly others.

I'm not 100% sure what is the best resolution. Within the Log.Error routine, it reads from the Err object though I think it should be using a cached copy and then clearing it but there might be other ramifications I'm not considering.

[hecon5]

In the refactored log PR #654 some of this is worked on; though caching the entire Err object might be preferable as that would allow us to cache other information as well.

I ended up originaly caching the error number because it was causing race conditions and Log.AddEntry would never actually save the error number.

I think any entry into the log routine should immediately cache the "current" Err; the issue then becomes ensuring that Err object is the one that makes it to the Log.AddEntry vs another intermediate one that's picked up between the time you do something like Log.Prompt or Log.Whatever, it could call other functions which toss errors (like getting a timestamp). Log.Prompt also calls a specialized formatting tools so that you don't accidentally get a message box that's unclosable due to line count or width.

Thoughts on how to deal with this race condition (because I think that's actually what this is):

1. All Public Log functions that put data into the log (Log.Prompt, Log.AddEntry, Log.Add, etc.) will cache the current Err object with either a GUID, TimeStamp, or some other unique Id that's fast. This unique ID will be used to ensure the err object stays with the prompt until it's loaded into the log and the error number in the log matches the correct function.
2. Minimize external functions in Log which recursively call Log to reduce circular loops, or ensure that there's a way to detect a loop and break it.
3. Set LogUnhandledErrors to a lower eErrorLevel to hide it from the console. The refactored log sets different eErrorLevel for the Log vs the Console vs Message Box Prompts.

Thoughts?

[bclothier]

FWIW, I don't see it as a race condition. As the minimal repo above shows, we only had one error which was already handled by the procedure's error routine which then called Log.Error but because the Err was still initialized, by the time we reach VerifyFocus and hit the LogUnhandledError, it looks like someone forgot to handle the error when that is not the case.

Thinking about it, I suspect the cleanest way would be to take a variant of what you suggested with 1st item -- have all public log routine cache err into either an UDT or an object then pass that as a new argument into the internal functions as necessary.

This has the advantage of not having to maintain a cache and allows for reentry because it's just a variable/parameter which are independent in each call. That also encourage us to tighten up the Log API surface so it's consistent and will correctly handle any errors that it itself may generate without spewing spurious output as shown in the repro above.

[hecon5]

As the minimal repo above shows, we only had one error which was already handled by the procedure's error routine which then called Log.Error but because the Err was still initialized, by the time we reach VerifyFocus and hit the LogUnhandledError, it looks like someone forgot to handle the error when that is not the case.

Aha! I misunderstood the context; after the coffee has fully seeped into my bloodstream I now see that the only error was self-generated. Initially I thought that LogUnhandledErrors was actually picking up a new error.

Right now, we already cache the error number in my new PR; I'll adjust that to pick it up upon entry instead of where it's cached now. If you have some ideas, please feel free to comment / PR on my PR (how meta!). I do something similar in one of my applications for database queries (which might return numerous errors that need to be parsed separately), I'll see if I can carve out some time this week to put that together.