Added optional debug output; Attempt to fix auto shot bugs

Config/MainMenu.lua

@@ -119,14 +119,34 @@ Quiver_Config_MainMenu_Create = function()
 	colorPickers:SetPoint("Right", f, "Right", -PADDING_FAR, 0)
 	f:SetWidth(PADDING_FAR + controls:GetWidth() + PADDING_FAR + colorPickers:GetWidth() + PADDING_FAR)
 
+	local selectDebugLevel = Quiver_Component_DropdownSelect(f,
+		"Debug Level", { "None", "Verbose" },
+		Quiver_Store.DebugLevel
+	)
+	local debugX = 0.5 * (PADDING_FAR + controls:GetWidth() + PADDING_FAR - selectDebugLevel:GetWidth())
+	local debugY = yOffset - colorPickers:GetHeight() + selectDebugLevel:GetHeight() + QUIVER.Size.Gap
+	selectDebugLevel:SetPoint("Left", f, "Left", debugX, 0)
+	selectDebugLevel:SetPoint("Top", f, "Top", 0, debugY)
+	-- Dropdown options
+	for _k,oLoop in selectDebugLevel.Menu.Options do
+		local option = oLoop
+		option:SetScript("OnClick", function()
+			local text = option.Text:GetText()
+			Quiver_Store.DebugLevel = text
+			selectDebugLevel.Selected:SetText(text)
+			selectDebugLevel.Menu:Hide()
+		end)
+	end
+
+	-- Dropdown tranq shot announce channel
 	local selectChannelHit = Quiver_Component_DropdownSelect(f,
 		"Tranq Speech", { "None", "/Say", "/Raid" },
 		Quiver_Store.ModuleStore[Quiver_Module_TranqAnnouncer.Id].TranqChannel)
 	local tranqX = 0.5 * (PADDING_FAR + controls:GetWidth() + PADDING_FAR - selectChannelHit:GetWidth())
-	local tranqY = yOffset - colorPickers:GetHeight() + selectChannelHit:GetHeight() + QUIVER.Size.Gap
+	local tranqY = debugY + QUIVER.Size.Gap + selectChannelHit:GetHeight()
 	selectChannelHit:SetPoint("Left", f, "Left", tranqX, 0)
 	selectChannelHit:SetPoint("Top", f, "Top", 0, tranqY)
-
+	-- Dropdown options
 	for _k,oLoop in selectChannelHit.Menu.Options do
 		local option = oLoop
 		option:SetScript("OnClick", function()

Lib/Spellbook.lua

@@ -44,15 +44,16 @@ end)()
 Quiver_Lib_Spellbook_CalcCastTime = function(spellName)
 	local baseTime = HUNTER_CASTABLE_SHOTS[spellName]
 	local _,_, msLatency = GetNetStats()
-	local start = GetTime() + msLatency / 1000
+	local startLocal = GetTime()
+	local startLatAdjusted = startLocal + msLatency / 1000
 
 	local speedCurrent = UnitRangedDamage("player")
 	local speedBase = calcRangedWeaponSpeedBase()
 	local speedMultiplier = speedCurrent / speedBase
 
 	-- https://www.mmo-champion.com/content/2188-Patch-4-0-6-Feb-22-Hotfixes-Blue-Posts-Artworks-Comic
 	local casttime = 0.5 + baseTime * speedMultiplier
-	return casttime, start
+	return casttime, startLatAdjusted, startLocal
 end
 
 local GetIsSpellLearned = function(spellName)

Modules/AutoShotTimer.lua

@@ -6,7 +6,8 @@ local BORDER = 1
 local castTime = 0
 local isCasting = false
 local isFiredInstant = false
-local timeStartCast = 0
+local timeStartCastLatAdjusted = 0
+local timeStartLocal = 0
 -- Auto Shot
 local AIMING_TIME = 0.65
 local isReloading = false
@@ -15,6 +16,12 @@ local maxBarWidth = 0
 local reloadTime = 0
 local timeStartShootOrReload = GetTime()
 
+local log = function(text)
+	if Quiver_Store.DebugLevel == "Verbose" then
+		DEFAULT_CHAT_FRAME:AddMessage(text)
+	end
+end
+
 local position = (function()
 	local x, y = 0, 0
 	local updateXY = function() x, y = GetPlayerMapPosition("player") end
@@ -106,7 +113,10 @@ local updateBarShooting = function()
 end
 
 local startReloading = function()
-	if not isReloading then timeStartShootOrReload = GetTime() end
+	if not isReloading then
+		timeStartShootOrReload = GetTime()
+		log("starting reload")
+	end
 	isReloading = true
 	reloadTime = UnitRangedDamage("player") - AIMING_TIME
 end
@@ -134,6 +144,7 @@ local updateBarReload = function()
 	if timePassed <= reloadTime then
 		frame.BarAutoShot:SetWidth(maxBarWidth - maxBarWidth * timePassed / reloadTime)
 	else
+		log("End reload")
 		isReloading = false
 		if isShooting then
 			startShooting()
@@ -191,7 +202,8 @@ local onSpellcast = function(spellName)
 	if isShooting and (not isReloading) then
 		timeStartShootOrReload = GetTime()
 	end
-	castTime, timeStartCast = Quiver_Lib_Spellbook_CalcCastTime(spellName)
+	castTime, timeStartCastLatAdjusted, timeStartLocal = Quiver_Lib_Spellbook_CalcCastTime(spellName)
+	log("Start Cast :" .. string.format(" %.3f to %.3f / %.3f", GetTime() - timeStartCastLatAdjusted, GetTime() - timeStartLocal, castTime))
 end
 
 local handleEvent = function()
@@ -212,17 +224,26 @@ local handleEvent = function()
 		-- If we fired an Auto Shot at the same time, then "ITEM_LOCK_CHANGED" will
 		-- trigger twice before "SPELLCAST_STOP", so we mark the first one as done.
 			isFiredInstant = false
+			log("Instant Shot")
 		elseif isCasting then
-			local elapsed = GetTime() - timeStartCast
-			if isShooting and elapsed < castTime then
+			-- This check is hard to make reliable.
+			-- The fastest possible cast (multi-shot) takes 0.5 seconds, so we can use any number between that and zero.
+			local elapsedMax = GetTime() - timeStartLocal
+			local elapsedMin = GetTime() - timeStartCastLatAdjusted
+			if isShooting and elapsedMax <= 0.25 then
 		-- Case 3 - We started casting immediately after firing an Auto Shot. We're casting and reloading.
+				log("Auto Fired - Starting Cast: " .. string.format(" %.3f to %.3f / %.3f", elapsedMin, elapsedMax, castTime))
 				startReloading()
 			else
 		-- Case 4 - We finished a cast. If we're done reloading, we can shoot again
+				log("Cast Fired")
 				if not isReloading then timeStartShootOrReload = GetTime() end
 				isCasting = false
 			end
+		-- TODO on rare occasions this doesn't trigger (less than once per 5 minutes shooting).
+		-- Need more debug logging and QA time.
 		elseif isShooting then
+			log("Auto Fired")
 		-- Case 5 - Fired Auto Shot
 		-- Works even if we cancelled Auto Shot as we fired because "STOP_AUTOREPEAT_SPELL" is lower priority.
 			startReloading()
@@ -232,8 +253,10 @@ local handleEvent = function()
 	elseif e == "SPELLCAST_STOP" or e == "SPELLCAST_FAILED" or e == "SPELLCAST_INTERRUPTED" then
 		isCasting = false
 	elseif e == "START_AUTOREPEAT_SPELL" then
+		log("Start shooting")
 		startShooting()
 	elseif e == "STOP_AUTOREPEAT_SPELL" then
+		log("Stop shooting")
 		isShooting = false
 	end
 end

Quiver.lua

@@ -13,6 +13,7 @@ local savedVariablesRestore = function()
 	Quiver_Store.IsLockedFrames = Quiver_Store.IsLockedFrames == true
 	Quiver_Store.ModuleEnabled = Quiver_Store.ModuleEnabled or {}
 	Quiver_Store.ModuleStore = Quiver_Store.ModuleStore or {}
+	Quiver_Store.DebugLevel = Quiver_Store.DebugLevel or "None"
 	for _k, v in _G.Quiver_Modules do
 		Quiver_Store.ModuleEnabled[v.Id] = Quiver_Store.ModuleEnabled[v.Id] ~= false
 		Quiver_Store.ModuleStore[v.Id] = Quiver_Store.ModuleStore[v.Id] or {}

Quiver.toc

@@ -2,7 +2,7 @@
 ## Title: Quiver - |cff00ff00Hunter
 ## Notes: A collection of hunter utilities.
 ## Author: SabineWren, 2022-2023
-## Version: 2.6.2
+## Version: 2.6.3
 ## SavedVariables: Quiver_Store
 
 Lib\F.lua