search

mooreatv / MoLib

MooreaTv addons common libs
5 stars 4 forks source link

AH issue with delayed/repeated scanning of results #16

Closed mooreatv closed 5 years ago

mooreatv commented 5 years ago

while looking with @odjur at some AH strangeness when you let time pass between the GetAll and the actual going over entries:

image

10x AuctionDB\MoLib/MoLibAH.lua:248: attempt to compare nil with number
AuctionDB\MoLib/MoLibAH.lua:248: in function `AHdump'
AuctionDB\MoLib/MoLibAH.lua:161: in function <AuctionDB\MoLib/MoLibAH.lua:156>
(tail call): ?
[C]: in function `GetAuctionItemTimeLeft'
AuctionDB\MoLib/MoLibAH.lua:239: in function `AHdump'
AuctionDB\MoLib/MoLibAH.lua:161: in function <AuctionDB\MoLib/MoLibAH.lua:156>
(tail call): ?
[C]: in function `GetAuctionItemTimeLeft'
AuctionDB\MoLib/MoLibAH.lua:239: in function `AHdump'
AuctionDB\MoLib/MoLibAH.lua:161: in function <AuctionDB\MoLib/MoLibAH.lua:156>
(tail call): ?
[C]: in function `GetAuctionItemTimeLeft'
...
AuctionDB\MoLib/MoLibAH.lua:161: in function <AuctionDB\MoLib/MoLibAH.lua:156>
(tail call): ?
[C]: in function `GetAuctionItemTimeLeft'
AuctionDB\MoLib/MoLibAH.lua:239: in function `AHdump'
AuctionDB\MoLib/MoLibAH.lua:161: in function <AuctionDB\MoLib/MoLibAH.lua:156>
(tail call): ?
[C]: in function `GetAuctionItemTimeLeft'
AuctionDB\MoLib/MoLibAH.lua:239: in function `AHdump'
AuctionDB\MoLib/MoLibAH.lua:278: in function <AuctionDB\MoLib/MoLibAH.lua:276>
SharedXML\C_TimerAugment.lua:16: in function <SharedXML\C_TimerAugment.lua:14>

Locals:
self = <table> {
 WatchedTable = <function> defined @AuctionDB\MoLib/MoLib.lua:791
 VerifySecureMessage = <function> defined @AuctionDB\MoLib/MoLib.lua:558
 RealmAbbrev = <function> defined @AuctionDB\MoLib/MoLib.lua:292
 autoScanDelay = 10
 debugPrint = <function> defined @AuctionDB\MoLib/MoLib.lua:147
 DisplayInfo = <function> defined @AuctionDB\MoLib/MoLibUI.lua:739
 EventHdlrs = <table> {
 }
 DebugEvCall = <function> defined @AuctionDB\MoLib/MoLib.lua:358
 bugReportMaxEntryLen = 400
 InitRealms = <function> defined @AuctionDB\MoLib/MoLib.lua:210
 PrintDefault = <function> defined @AuctionDB\MoLib/MoLib.lua:181
 Warning = <function> defined @AuctionDB\MoLib/MoLib.lua:163
 scaleUp = <function> defined @AuctionDB\MoLib/MoLibUI.lua:36
 securePastThreshold = 45
 SavePosition = <function> defined @AuctionDB\MoLib/MoLibUI.lua:1083
 HexDump = <function> defined @AuctionDB\MoLib/MoLib.lua:456
 myRid = 9
 ToHex = <function> defined @AuctionDB\MoLib/MoLib.lua:473
 ahPrefetch = 1000
 autoSave = false
 extractRealmID = <function> defined @AuctionDB\MoLib/MoLib.lua:281
 AHContext = <function> defined @AuctionDB\MoLib/MoLibAH.lua:73
 AddToItemDB = <function> defined @AuctionDB\MoLib/MoLibAH.lua:44
 EscNonPrintableAndPipe = <function> defined @AuctionDB\MoLib/MoLib.lua:91
 gold = <table> {
 }
 InitItemDB = <function> defined @AuctionDB\MoLib/MoLibAH.lua:92
 ahStartTS = 540287346.592800
 GetMyFQN = <function> defined @AuctionDB\MoLib/MoLib.lua:398
 optionsPanel = <unnamed> {
 }
 PixelPerfectScale = <function> defined @AuctionDB\MoLib/MoLibUI.lua:896
 MoLibInstallInto = <function> defined @AuctionDB\MoLib/MoLib.lua:61
 DebugStack = <function> defined @AuctionDB\MoLib/MoLib.lua:167
 measure = <function> defined @AuctionDB\MoLib/MoLib.lua:933
 ReplaceAll = <function> defined @AuctionDB\MoLib/MoLib.lua:601
 ahRetries = 0
 SetSaved = <function> defined @AuctionDB\MoLib/MoLib.lua:829
 NumToHex = <table> {
 }
 roundUp = <function> defined @AuctionDB\MoLib/MoLibUI.lua:21
 SetupMenu = <function> defined @AuctionDB\AuctionDB.lua:38
 RgbToHex = <function> defined @AuctionDB\MoLib/MoLib.lua:172
 minimapButtonAngle = 0
 DrawCross = <function> defined @AuctionDB\MoLib/MoLibUI.lua:794
 ShortHash = <function> defined @AuctionDB\MoLib/MoLib.lua:501
 round = <function> defined @AuctionDB\MoLib/MoLibUI.lua:13
 red = <table> {
 }
 testPerfGlobal = <function> defined @AuctionDB\MoLib/MoLib.lua:917
 first = <function> defined @AuctionDB\MoLib/MoLib.lua:365
 deepmerge = <function> defined @AuctionDB\MoLib/MoLib.lua:28
 GetLocalization = <function> defined @AuctionDB\MoLib/MoLib.lua:770
 Dump = <function> defined @AuctionDB\MoLib/MoLib.lua:345
 name = "AuctionDB"
 GsubEsc = <function> defined @AuctionDB\MoLib/MoLib.lua:591
 AHdump = <function> defined @AuctionDB\MoLib/MoLibAH.lua:184
 manifestVersion = "vX.YY.ZZ"
 ah = <table> {
 }
 EscNonPrintable = <function> defined @AuctionDB\MoLib/MoLib.lua:79
 GetCursorCoordinates = <function> defined @AuctionDB\MoLib/MoLibUI.lua:1126
 Print = <function> defined @AuctionDB\MoLib/MoLib.lua:73
 MoLibTexturesPreLoadFrame = <unnamed> {
 }
 AspectRatio = <function> defined @AuctionDB\MoLib/MoLibUI.lua:887
 ahEndTS = 540222957.858000
 SnapFrame = <function> defined @AuctionDB\MoLib/MoLibUI.lua:43
 L = <table> {
 }
 ScreenFrame = <function> defined @AuctionDB\MoLib/MoLibUI.lua:68
 Debug = <

The multiple GetAuctionItemTimeLeft in the stack are suspicious (corountine?)

Bug Report for AuctionDB vX.YY.ZZ
2019/08/22 22:36:03 -0700 @project-abbreviated-hash@

Bug report from slash command
Session messages log:
AuctionDB bug report open: Please submit on discord or https://bit.ly/ahbug or email
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
ni 1000 fi 18522 ahR nil
AuctionDB Error: Too many retries (11) without progress when trying to get to full AH of 60608 with page size 1000, stuck on item 18522
ni 1000 fi 18522 ahR 18522
ni 1000 fi 18522 ahR 18522
ni 1000 fi 18522 ahR 18522
ni 1000 fi 18522 ahR 18522
ni 1000 fi 18522 ahR 18522
ni 1000 fi 18522 ahR 18522
ni 1000 fi 18522 ahR 18522
ni 1000 fi 18522 ahR 18522
ni 1000 fi 18522 ahR 18522
ni 1000 fi 18522 ahR 18522
Expected incomplete ah 1000 results found at 18522 / 60598
ni 1000 fi 18522 ahR 16738
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60598 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60599 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60600 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60601 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60602 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60603 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60604 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60605 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60606 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60607 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60608 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60609 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60610 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60611 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60612 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60613 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60614 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60615 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60616 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60617 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60618 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60619 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60620 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60622 to 60621 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 16738 / 60622
ni 1000 fi 16738 ahR 15377
Expected incomplete ah 1000 results found at 15377 / 60622
ni 1000 fi 15377 ahR 13907
Expected incomplete ah 1000 results found at 13907 / 60622
ni 1000 fi 13907 ahR 12290
Expected incomplete ah 1000 results found at 12290 / 60622
ni 1000 fi 12290 ahR 10458
Expected incomplete ah 1000 results found at 10458 / 60622
ni 1000 fi 10458 ahR 9110
Expected incomplete ah 1000 results found at 9110 / 60622
ni 1000 fi 9110 ahR 7717
Expected incomplete ah 1000 results found at 7717 / 60622
ni 1000 fi 7717 ahR 6407
Expected incomplete ah 1000 results found at 6407 / 60622
ni 1000 fi 6407 ahR 4739
Expected incomplete ah 1000 results found at 4739 / 60622
ni 1000 fi 4739 ahR 3273
Expected incomplete ah 1000 results found at 3273 / 60622
ni 1000 fi 3273 ahR 1828
Expected incomplete ah 1000 results found at 1828 / 60622
ni 1000 fi 1828 ahR 308
Expected incomplete ah 1000 results found at 308 / 60622
ni 1000 fi 308 ahR 1
AuctionDB: Getting 60622 items from AH all dump. (initial list took 0.02 sec to get)
Scan started... please wait...
AuctionDB Warning: Running with existing last AH results instead of a real scan
AuctionDB: Auction scan complete and captured for 60622 listings in 3.94 s (15403.8 auctions/sec).
0 new items in DB, now 24566 entries. 
MoLib AH Scan data packed to 2.5 Mbytes
Scan context info: Neutral auction house on us / Kil'jaeden
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 628 results found at 58964 / 60622
ni 628 fi 58964 ahR 57001
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 57001 / 60622
ni 1000 fi 57001 ahR 55291
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 55291 / 60622
ni 1000 fi 55291 ahR 53233
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 53233 / 60622
ni 1000 fi 53233 ahR 50851
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 50851 / 60622
ni 1000 fi 50851 ahR 49117
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 49117 / 60622
ni 1000 fi 49117 ahR 47520
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 47520 / 60622
ni 1000 fi 47520 ahR 45385
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 45385 / 60622
ni 1000 fi 45385 ahR 43352
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 43352 / 60622
ni 1000 fi 43352 ahR 41265
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 41265 / 60622
ni 1000 fi 41265 ahR 39421
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 39421 / 60622
ni 1000 fi 39421 ahR 37807
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 37807 / 60622
ni 1000 fi 37807 ahR 35717
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 35717 / 60622
ni 1000 fi 35717 ahR 34109
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 34109 / 60622
ni 1000 fi 34109 ahR 32095
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 32095 / 60622
ni 1000 fi 32095 ahR 30481
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 30481 / 60622
ni 1000 fi 30481 ahR 28775
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 28775 / 60622
ni 1000 fi 28775 ahR 27381
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 27381 / 60622
ni 1000 fi 27381 ahR 25873
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 25873 / 60622
ni 1000 fi 25873 ahR 24555
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 24555 / 60622
ni 1000 fi 24555 ahR 23070
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 23070 / 60622
ni 1000 fi 23070 ahR 21530
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 21530 / 60622
ni 1000 fi 21530 ahR 20160
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 20160 / 60624 retry #3
ni 1000 fi 20160 ahR 20160
ni 1000 fi 20160 ahR 20160
Expected incomplete ah 1000 results found at 20160 / 60622
ni 1000 fi 20160 ahR 18462
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60622 (likely bad scan, please report)
AuctionDB Warning: Auction list count changed unexpectedly from 60624 to 60623 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 18462 / 60624
ni 1000 fi 18462 ahR 16674
Expected incomplete ah 1000 results found at 16674 / 60624
ni 1000 fi 16674 ahR 15327
Expected incomplete ah 1000 results found at 15327 / 60624
ni 1000 fi 15327 ahR 13818
Expected incomplete ah 1000 results found at 13818 / 60624
ni 1000 fi 13818 ahR 12119
Expected incomplete ah 1000 results found at 12119 / 60624
ni 1000 fi 12119 ahR 10247
Expected incomplete ah 1000 results found at 10247 / 60624
ni 1000 fi 10247 ahR 8988
Expected incomplete ah 1000 results found at 8988 / 60624
ni 1000 fi 8988 ahR 7588
Expected incomplete ah 1000 results found at 7588 / 60624
ni 1000 fi 7588 ahR 6273
Expected incomplete ah 1000 results found at 6273 / 60624
ni 1000 fi 6273 ahR 4560
Expected incomplete ah 1000 results found at 4560 / 60624
ni 1000 fi 4560 ahR 3037
Expected incomplete ah 1000 results found at 3037 / 60624
ni 1000 fi 3037 ahR 1642
Expected incomplete ah 1000 results found at 1642 / 60624
ni 1000 fi 1642 ahR 1
ni 1000 fi 1 ahR 1
AuctionDB: Getting 60624 items from AH all dump. (initial list took 0.02 sec to get)
Scan started... please wait...
AuctionDB Warning: Running with existing last AH results instead of a real scan
AuctionDB: Auction scan complete and captured for 60624 listings in 3.95 s (15352.2 auctions/sec).
0 new items in DB, now 24566 entries. 
MoLib AH Scan data packed to 2.5 Mbytes
Scan context info: Neutral auction house on us / Kil'jaeden
AuctionDB Warning: Auction list count changed unexpectedly from 60635 to 60624 (likely bad scan, please report)
Expected incomplete ah 661 results found at 58912 / 60624
ni 661 fi 58912 ahR 56945
AuctionDB Warning: Auction list count changed unexpectedly from 60635 to 60624 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 56945 / 60624
ni 1000 fi 56945 ahR 55249
AuctionDB Warning: Auction list count changed unexpectedly from 60635 to 60624 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 55249 / 60624
ni 1000 fi 55249 ahR 53188
AuctionDB Warning: Auction list count changed unexpectedly from 60635 to 60624 (likely bad scan, please report)
Expected incomplete ah 1000 results found at 53188 / 60624
ni 1000 fi 53188 ahR 50796
AuctionDB Warning: Auction list count changed unexpectedly from 60635 to 60624 (likely bad scan, please report)
[...skipped 2038 lines...]
ni 1000 fi 3845 ahR 3845
ni 1000 fi 3845 ahR 3845
ni 1000 fi 3845 ahR 3845
ni 1000 fi 3845 ahR 3845
ni 1000 fi 3845 ahR 3845
ni 1000 fi 3845 ahR 3845
ni 1000 fi 3845 ahR 3845
ni 1000 fi 3845 ahR 3845
ni 1000 fi 3845 ahR 3845
ni 1000 fi 3845 ahR 3845
ni 1000 fi 3845 ahR 3845
Expected incomplete ah 1000 results found at 3845 / 60653
ni 1000 fi 3845 ahR 3043
Expected incomplete ah 1000 results found at 3043 / 60653
ni 1000 fi 3043 ahR 1646
Expected incomplete ah 1000 results found at 1646 / 60653
ni 1000 fi 1646 ahR 2
Expected incomplete ah 1000 results found at 2 / 60653
ni 1000 fi 2 ahR 1
AuctionDB: Getting 60653 items from AH all dump. (initial list took 0.02 sec to get)
Scan started... please wait...
AuctionDB Warning: Running with existing last AH results instead of a real scan
AHDB: click the button, or hit space or enter to Start a full scan now! (/ahdb scan)
AHDB: click the button, or hit space or enter to Target the Auctioneer (/tar auctioneer)
AuctionDB vX.YY.ZZ by MooreaTv: type /ahdb for command list/help.

and the code

...
    if numIncomplete > 0 then
      self:PrintDefault("ni % fi % ahR %", numIncomplete, firstIncomplete, self.ahResumeAt)
      local progressMade = (firstIncomplete > self.ahResumeAt)
      if progressMade then
        self:Debug("We made progress from % to %, so resetting retries", self.ahResumeAt, firstIncomplete)
        self.ahRetries = 0
      end
      self.ahRetries = self.ahRetries + 1
      local retriesMsg = ""
      if self.ahRetries > 1 then
        retriesMsg = string.format(" retry #%d", self.ahRetries)
      end
      if not fromEvent or progressMade then
        self:PrintDefault("Expected incomplete ah % results found at % / %" .. retriesMsg, numIncomplete,
                          firstIncomplete, count, self.ahRetries)
      end
      if self.ahRetries > self.ahMaxRetries then
        self:Error(
          "Too many retries (%) without progress when trying to get to full AH of % with page size %, stuck on item %",
          self.ahRetries, count, self.ahPrefetch, firstIncomplete)
        self:AHrestoreNormal()
        return
      end
...

the return on error is after the arr check and calls AHrestoreNormal which clears the timer and flag that get AHdump() called... yet it errors

mooreatv commented 5 years ago

yup, that's the issue... when the list count changes (likely because of expiration), one of the calls block and further events are processed and the code can thus reenter (!) image

  if self.AHinDump then
    self:ErrorAndThrow("AHdump unexpected reentrance")
    return
  end

and I clear AHinDump when returning - see also that the checkpoint rewinds in time

mooreatv commented 5 years ago

fixed in https://github.com/mooreatv/MoLib/commit/a14b1f9451c8027b5dfa9b0a8b9c6df980d5467f and AuctionDB v0.06