As you know we published a story about the QBWin.log file just yesterday (5/3/2018) in response to some frequently asked questions I have received over the years about the log. In response to the story a reader contacted me asking a question I have never been asked before "What's up with all these new LVL_ERRORS in the QBWin.log?"
What the reader was asking about are the increasing number of errors in the log being reported in relationship to the 'timing' associated with all the sub-routines that make-up either the Verify or Rebuild functions. The log excerpt illustrates (in the yellow highlighted) portions the LVL_ERRORS the reader was asking about.
QBWin_New_Task-time_Errors
Historically, a LVL_ERROR level error was a serious enough error to result in the Verify utility failing, yet LVL_ERRORS like this not only don't trigger a Verify failure, they don't appear in the Verify or Rebuild reports (found within newer QuickBooks versions).
If you look closely, you will notice (highlighted in the purplish color in the above example) that the message 'Errorsfound: 0' appears at the end of the LVL_ERROR messages in yellow. Obviously this means that there really was 'no error', so why are these errors being reported when there are no errors found?
Elementary, My Dear Watson (as Sherlock would put it), the LVL_ERROR---Verify Rebuild error must have something to do with the 'remaining piece of information' recorded for each of these errors. Each of the sub-routines like Account Balances, Name Balances and Permissions (just to name a few) are undergoing verification. Then you will notice the amount of time it took for that verification to be completed.
In the case of Account Balances it took 1322.312035 milliseconds, Name Balances took 209.205472 milliseconds, and Permissions took 119.195152 milliseconds. In each case the time to verify is recorded even though the actual errors found are zero.
Now I have previously written about the various measures of time recorded in the QBWin.log including:
- CHECKPOINT (time) – the date/time recorded corresponds to your computer’s displayed time (not a measure of the actual internal system clock).
- PerformanceMeasure.cpp record of “wall time” – ‘Wall time’ is what programmers call “real world” time (what the clock on the wall shows), as opposed to the system clock's idea of time which is based upon the number of ticks required to execute an action.
- PerformanceMeasure.cpp record of ‘busy” – Busy or ‘waiting’ (sometimes called spinning) time is the time a process repeatedly checks to see if a condition is true; in software engineering this is a technique used to generate an arbitrary time delay for other critical functions to take place.
Sometime in the recent updates to I suspect the 2018 QuickBooks versions first, we have gotten this new time measure related to verification (duration). That feature is probably a good thing in terms of providing even more information to those who interpret the QBWin.log, but what concerns me is why these time measures are being recorded as a significant error level within the log.
Apparently QuickBooks (Desktop) programmers must have some algorithm that says 'if it takes longer than 'x' milliseconds per record verified, then generate a LVL_ERROR---Verify and log-it. To me it would seem that these should be recorded as a 'Message' if there are no actual 'errors' found...and obviously the same programmers agree with that even though they don't do that in the QBWin.log file, because they manage to prevent all these 'verification step duration errors' from posting to their Verify and Rebuild Reports.
Unfortunately, while informative, these new errors actually make it harder than ever to interpret the QBWin.log file for serious issues because we can no longer simply 'search' the log for LVL_ERROR errors without now finding a lot of meaningless information. If we want to identify or resolve problems within the Verify and/or Rebuild results we are now going to have to track them down 1 by 1.
If you want to learn more about the QBWin.log file and you can't attend my Scaling New Heights 2018 conference courses, you should attend Insightful Accountant's FREE QBTalks webinar on Wednesday May 9, 2018 at 1:00 PM EST under our new AccountingCred alliance with Surgent. See the related story here.