Old Routine - Totem Logic

[WiN]

When using the default Old Routine the totem is being recast multiple times per second. I added logging to the routine to see if the code was being called multiple times, and hard coded the delay to be 5000ms, made it look for <2 totems and for good measure added a reset to the timer almost as soon as the Totem logic runs (needless to say the default version has exactly the same problem - test by running quest bot to the Broken eggs quest - grab flame totem and press go):

// Handle totem logic.
if (_totemSlot != -1 &&
_totemStopwatch.ElapsedMilliseconds > 5000)
{
Log.InfoFormat("Totem Available");
var skill = LokiPoe.InGameState.SkillBarHud.Slot(_totemSlot);
if (skill.CanUse() &&
skill.DeployedObjects.Select(o => o as Monster).Count(t => !t.IsDead && t.Distance < 60) <
2)
{
Log.InfoFormat("Can Use Totem");
_totemStopwatch.Restart();
Log.InfoFormat("Reset Totem Counter");
await DisableAlwaysHiglight();
Log.InfoFormat("Highlight");
await Coroutines.FinishCurrentAction();
Log.InfoFormat("Finish Action");
var err1 = LokiPoe.InGameState.SkillBarHud.UseAt(_totemSlot, true,
myPos.GetPointAtDistanceAfterThis(cachedPosition,
cachedDistance/2));
Log.InfoFormat("Place Totem");


if (err1 == LokiPoe.InGameState.UseResult.None)
return true;
Log.InfoFormat("End Totem Bit");
Log.ErrorFormat("[Logic] UseAt returned {0} for {1}.", err1, skill.Name);
}
}

It isnt ...

2016-07-22 02:49:35,678 [9] INFO Logger - Totem Available
2016-07-22 02:49:35,680 [9] INFO Logger - Can Use Totem
2016-07-22 02:49:35,680 [9] INFO Logger - Reset Totem Counter
2016-07-22 02:49:35,680 [9] INFO Logger - Highlight
2016-07-22 02:49:35,681 [9] INFO Logger - Finish Action
2016-07-22 02:49:35,681 [9] INFO Logger - [UseAt] 5 True {547, 412}
2016-07-22 02:49:35,705 [9] INFO Logger - Place Totem
2016-07-22 02:49:35,733 [9] DEBUG Logger - [FinishCurrentAction] Waited 0 ms for the action to finish Flame Totem.
2016-07-22 02:49:35,838 [9] DEBUG Logger - [FinishCurrentAction] Waited 105 ms for the action to finish Flame Totem.
2016-07-22 02:49:35,962 [9] DEBUG Logger - [FinishCurrentAction] Waited 230 ms for the action to finish Flame Totem.
2016-07-22 02:49:36,072 [9] INFO Logger - [BeginUseAt] 5 False {546, 417}
2016-07-22 02:49:36,138 [9] INFO Logger - [InjectKeyEvent] 188 ms sleep for 87.
2016-07-22 02:49:37,380 [9] DEBUG Logger - [FinishCurrentAction] Waited 0 ms for the action to finish Flame Totem.
2016-07-22 02:49:37,488 [9] DEBUG Logger - [FinishCurrentAction] Waited 108 ms for the action to finish Flame Totem.
2016-07-22 02:49:37,605 [9] DEBUG Logger - [FinishCurrentAction] Waited 225 ms for the action to finish Flame Totem.
2016-07-22 02:49:37,722 [9] DEBUG Logger - [FinishCurrentAction] Waited 342 ms for the action to finish Flame Totem.
2016-07-22 02:49:37,857 [9] DEBUG Logger - [FinishCurrentAction] Waited 477 ms for the action to finish Flame Totem.
2016-07-22 02:49:37,955 [9] INFO Logger - [BeginUseAt] 3 False {546, 417}
2016-07-22 02:49:38,031 [9] INFO Logger - [BeginUseAt] 5 False {546, 417}
2016-07-22 02:49:38,780 [9] DEBUG Logger - [FinishCurrentAction] Waited 0 ms for the action to finish Flame Totem.
2016-07-22 02:49:38,906 [9] DEBUG Logger - [FinishCurrentAction] Waited 125 ms for the action to finish Flame Totem.
2016-07-22 02:49:39,006 [9] DEBUG Logger - [FinishCurrentAction] Waited 226 ms for the action to finish Flame Totem.
2016-07-22 02:49:39,122 [9] DEBUG Logger - [FinishCurrentAction] Waited 342 ms for the action to finish Flame Totem.
2016-07-22 02:49:39,239 [9] DEBUG Logger - [FinishCurrentAction] Waited 458 ms for the action to finish Flame Totem.
2016-07-22 02:49:39,364 [9] DEBUG Logger - [FinishCurrentAction] Waited 583 ms for the action to finish Flame Totem.
2016-07-22 02:49:39,393 [9] INFO Logger - [BeginUseAt] 3 False {546, 417}
2016-07-22 02:49:39,446 [9] INFO Logger - [BeginUseAt] 5 False {546, 417}
2016-07-22 02:49:39,833 [9] DEBUG Logger - [FinishCurrentAction] Waited 0 ms for the action to finish Fireball.
2016-07-22 02:49:39,956 [9] DEBUG Logger - [FinishCurrentAction] Waited 123 ms for the action to finish Fireball.
2016-07-22 02:49:40,065 [9] DEBUG Logger - [FinishCurrentAction] Waited 231 ms for the action to finish Fireball.
2016-07-22 02:49:40,174 [9] DEBUG Logger - [FinishCurrentAction] Waited 341 ms for the action to finish Fireball.
2016-07-22 02:49:40,205 [9] INFO Logger - [BeginUseAt] 3 False {533, 431}
2016-07-22 02:49:40,263 [9] INFO Logger - [BeginUseAt] 5 False {541, 413}
2016-07-22 02:49:40,397 [9] DEBUG Logger - [FinishCurrentAction] Waited 0 ms for the action to finish Fireball.
2016-07-22 02:49:40,522 [9] DEBUG Logger - [FinishCurrentAction] Waited 125 ms for the action to finish Fireball.
2016-07-22 02:49:40,623 [9] DEBUG Logger - [FinishCurrentAction] Waited 226 ms for the action to finish Fireball.
2016-07-22 02:49:40,740 [9] DEBUG Logger - [FinishCurrentAction] Waited 342 ms for the action to finish Fireball.
2016-07-22 02:49:40,858 [9] DEBUG Logger - [FinishCurrentAction] Waited 460 ms for the action to finish Fireball.
2016-07-22 02:49:40,974 [9] DEBUG Logger - [FinishCurrentAction] Waited 577 ms for the action to finish Fireball.
2016-07-22 02:49:41,022 [9] INFO Logger - [BeginUseAt] 3 False {533, 431}
2016-07-22 02:49:41,078 [9] INFO Logger - Totem Available
2016-07-22 02:49:41,080 [9] INFO Logger - Can Use Totem
2016-07-22 02:49:41,080 [9] INFO Logger - Reset Totem Counter
2016-07-22 02:49:41,080 [9] INFO Logger - Highlight
2016-07-22 02:49:41,081 [9] INFO Logger - Finish Action
2016-07-22 02:49:41,081 [9] INFO Logger - [UseAt] 5 True {537, 415}
2016-07-22 02:49:41,106 [9] INFO Logger - Place Totem

During the above log Totem was spam recast 10+ times, but doesn't show in the logs as repeating. So I was wondering how this is possible?