Who wants to drink from the firehose?

[spiel2001]

Just a heads up to addon authors about a new taint.log feature on the 5.2 PTR... '/console taintlog 11'

This feature is, and only ever will be, available on the public test realms and not the production servers. In essence, this new logging level will log *every* taint event that happens. And I do mean every. Expect *huge* taint.log files to be generated very quickly. In testing, I've seen 200meg+ files created before the world view is displayed.

I highly recommend the use of a regex tool such as grepWin if you're going to play with this option. That said, if you want to know what your addons are tainting when, and where, this new option will flat tell you.

The UI team also made some changes to how taint is reported in the hopes that there will be fewer instances of misreported taint (the wrong addon getting blamed, etc.). These changes should appear over on the production servers when 5.2 goes live.

Many thanks to T2 and company for making this happen... it's made my life as a UI author *way* easier when it comes to dealing with taint. I can state for a fact that taint issues I've spent months looking for I was able to resolve in under an hour with these taint.log changes.

[Talyrius]

Are you sure that this new verbose taint log will only be obtainable on the PTR? How are we to attain this invaluable information when the PTR isn't up?

[spiel2001]

It is, indeed, only on the PTR. Reason being that it could be exploited for nefarious purposes.

It's there to give addon authors an opportunity to work out bugs in the new patches, for which there's always ample time to access the PTR. Otherwise, on the production servers, you'll still be limited to '/console taintlog 1' and '/console taintlog 2' as has been the case for some time now.

And, yes... I am 100% certain. At least for the time being.

[spiel2001]

By way of follow-up, since I've gotten a few e-mails since posting this thread, I wanted to explain a little about what's going on in the new '/console taintlog 11'

In a nutshell, *EVERY* time an addon sets a variable, that variable is tainted. It does not matter if it is a top level global, such as "UIDROPDOWNMENU_MENU_LEVEL" or a member of a table such as 'MyAddonSavedVars.someValue' or, for that matter, even a function name. Anything and everything an addon does outside of the secure environment is by definition tainted.

Generally speaking, that's not an issue. The only time it becomes an issue is when the Blizzard code, or a secure code snippet, tries to read from a variable that's been tainted, or execute a tainted function, while in a secure execution path. As soon as that happens, the execution path becomes tainted and you can no longer execute secure calls... i.e. buttons don't work, spell casts fail, etc. Anything that is "secure" in Blizzard's point of view, will no longer work once the execution path becomes tainted.

So, as long as the execution path is not tainted, everything is sunshine and lollipops. However, Once the execution path is tainted, no secure functions or abilities will work until the path is terminated. So, then, the question becomes what tainted the execution path when, where and how.

In the simplest case, when this happens, you get a message to the effect of "Interface action failed because of an AddOn" and unless you have a bug tracker like BugSack or Swatter installed, and you have logging of warnings enabled, that's all you know about it. By default, the taint log is turned off (/console taintlog 0), so you have no information there, either. So, you turn the taint log on using the command '/console taintlog 1' and reload the user interface, reproduce the error and log out. When you do that, you'll find a file called 'taint.log' in the [ World of Warcraft > Logs ] folder. It will contain minimal information about the event, but often that is enough.

However, you do have the option of using the command '/console taintlog 2' to increase the logging level, as well. In this mode, the taint.log will contain more information, basically telling you who tainted the thing that caused the execution path to be tainted. But, even then, that's often not enough to track down subtle taint problems. Speaking for myself, I've had some taint issues in my code that have been there for years because I couldn't figure them out using the taint log as it existed up until the 5.2 patch.

Enter '/console taintlog 11' (turn it up to 11 dude!) and the modifications that were made to how taint is reported in 5.2

The key to understanding this expanded taint.log mode is to understand that it logs *every* taint event *every time* it happens. It does not just log the first time a variable is tainted, but every time. Nor does it log the first time the execution path is tainted, but every time. Quite literally, every single taint event is written to the log along with the offender and, quite often, a stack trace.

A quick caveat -- at present, the taint.log does not fully expand the variables names. I'm hoping that will change. It does not differentiate between a top level global variable name like 'UIDROPDOWNMENU_MENU_LEVEL' and 'MyAddonVars.UIDROPDOWNMENU_MENU_LEVEL' -- it will report *both* as 'Global variable UIDROPDOWNMENU_MENU_LEVEL tainted by MyAddon' -- that makes it a little problematic when you get a message like 'Global variable id has been tainted by MyAddon' -- okay... unitFrame.id, actionButton.id, mything.id or what? This probably will not get fixed in 5.2, but let's cross our fingers. It is being looked at.

If you've got a busy addon, lots of OnUpdate and OnEvent stuff going on, it can easily produce a couple hundred meg of taint.log in minutes or even seconds. Trying to read this file manually will make your head explode. Regex is your friend. I mucked about with grepWin for a while and it did okay... I just hated that I couldn't chain (pipe) rules, nor should I only show lines that didn't match the rule. I'm a linux guy, so I just copied the output to my Linux VM and had at it with grep. To be sure, the pathway to enlightenment passes through pattern searching.

For myself, nirvana was turning off every other addon I use, including bug catchers like BugSack and Swatter, and running with nothing but my own addon enabled. Logged in, used the '/console taintlog 11' command and logged back out. Then logged back in, immediately reproduced the taint error and immediately logged back out. Ten seconds logged in, maybe 15. My taint.log was close to 250 meg. I then used grep (regular expression search) to make a list of all of the times the execution path was tainted and all of the variables that caused it to be tainted. From there I worked backwards to build a list of every place in the code where I tainted that variable. It was fast and easy... far more so than it has even been for me in the nearly 5 years that nUI has been around. It took me about five minutes to fix a taint error that I haven't been able to find for months. In under an hour, I had fixed every taint error I had, even some I never knew were there.

It takes a bit to get your head around the scale of data in the new taint log, but I promise you once you do, you'll see how quickly it can help you resolve taint problems... even really hard to find ones.

[TSquared]

Actually the execution path is also "tainted" whenever an addon is called or a tainted variable is read. That in turn taints every variable written to. So on, and so on, and so on...

As you stated, It only becomes an issue when a "protected" function is called. The execution path is then tested, and if found tainted, will fail with the normal error.

[zork]

Thanks spiel.

I'm actually very interested in how you fixed your taints.

Could you post a snippet of code that tainted for you (A) and a working solution that fixed the issue (B)? What do you had to do to fix the errors in general. Just curious.

[spiel2001]

I'm at work at the moment, so I can't give you a full response. That said, the easiest example I can think of was the BattlefieldMinimap.... in my code I had something to the effect of...

BattlefieldMinimap:StartMoving();
BattlefieldMinimap:StartSizing();

-- blah blah blah stuff to manipulate the size and position of the map

BattlefieldMinimap:StopMovingOrSizing();

That looks innocent enough on the face of it. But, in my doing so, I tainted the battlefield minimap. Specifically, when you call BattlefieldMinimap:StopMovingOrSizing() that triggers a call, eventually, to BattlefieldMinimap_OnUpdate() [if memory serves me correctly] which, in turn, sets the value of BATTLEFIELD_MINIMAP_NUM_OVERLAYS [again. operating from memory] which is read during combat lockdown in battlegrounds and a host of other places.

Using the taintlog 11 mode, I was able to work out that I was tainting BATTLEFIELD_MINIMAP_NUM_OVERLAYS (which I never knew before) and working backwards in the taint.log I found that it was the call to StopMovingOrSizing() that did it -- something I never, in a million years, would have guessed just reading through my code. More surprising was the fact that is was this taint of the BATTLEFIELD_MINIMAP_NUM_OVERLAYS that was causing me to throw combat taint errors on my action bar buttons whenever the secure action button code tried to call ActionButton_Update() it would throw a combat taint on the ActionButton:Show() function.

Who would have guessed that my action buttons were failing because I called BattlefieldMinimap:StopMovingOrSizing() ??

As for how I fixed it... rather than use the StartMoving(), StartSizing() and StopMovingOrSizing() methods, I pulled the relevant bits I needed out of the BattlefieldMinimap.lua code and replicated them in my own code, while avoiding setting any globals within the Battlefield Minimap code base.

[Foxlit]

It's great that the taint log is now more verbose about tainted table fields. The next logical step would be to also include tainted local variables.

Setting taintlog to 11 outputs additional messages to taint.log whenever a table field is tainted, following the same format as taintlog 2 (and erroneously claiming that the variable was global):

1/29 15:40:00.002  Global variable foo tainted by FooAddon - Interface\AddOns\FooAddon\File.lua:30

and when a tainted table field is read:

1/29 15:40:00.004  Execution tainted by FooAddon while reading name - Interface\FrameXML\OptionsFrameTemplates.lua:80 OptionsList_DisplayButton()
      Interface\FrameXML\InterfaceOptionsFrame.lua:184 InterfaceAddonsList_Update()
      Interface\FrameXML\InterfaceOptionsFrame.lua:629 InterfaceAddonsList_AddCategory()
      Interface\AddOns\FooAddon\File.lua:42

While this is nice, any taint problem is 90% solved (or at the very least identified) once you have a found a concise and reliable way to reproduce it -- the rest is just about reading enough FrameXML code to understand what's going on. Ultimately, a huge log file (and one only available on the PTR) is less helpful in debugging occasional problems people encounter on live realms.

A better long-term fix would be to allow the client to (optionally) store taint history* alongside the taint flags, and backtrace through that history whenever a protected function is called from a tainted execution path. This would produce a taint trace that would be about as helpful as an ordinary stack trace is to diagnosing an ordinary error.


* More specifically, the execution should remember why it was tainted (which tainted variable was read, and why that variable was tainted), and all variables should remember why they were tainted (which variable tainted the execution when they were written, and why that variable was tainted).

Originally Posted by spiel2001 The UI team also made some changes to how taint is reported in the hopes that there will be fewer instances of misreported taint (the wrong addon getting blamed, etc.). These changes should appear over on the production servers when 5.2 goes live.

What exactly are those changes? I'm still under the impression that if your addon appeared in a taint error, it is as a consequence (albeit a potentially remote one) of code included in your addon.

[spiel2001]

Originally Posted by Foxlit I'm still under the impression that if your addon appeared in a taint error, it is as a consequence (albeit a potentially remote one) of code included in your addon.

Then you would be wrong. Until 5.2, the taint.log often blamed the wrong addon for having caused the taint.

With regard to the changes you're proposing, I don't work for Blizz, so I'm not in a position to answer for them. That said, the taint system is very lightweight. Adding a good bit of functionality (logic) to it would create a non-trivial impact on performance. Humans are quite good at that kind of work... dump the raw data to a linear file and allow the sentient being to apply its skills to working out what happened if/when they need to, versus, penalize everything because someone might want to have a look and is unwilling to work backwards through the output. Meh.

[Foxlit]

Originally Posted by spiel2001 Then you would be wrong. Until 5.2, the taint.log often blamed the wrong addon for having caused the taint.

Screenshots or it didn't happen

But seriously, the "taintlog is totally wrong, my addon is blameless!" sentiment is expressed frequently, but never with any amount of detail behind it. It'd be great to see an actual example of things being misattributed in 5.1, or get an actual description of the reporting change made in 5.2.

[spiel2001]

/sigh

And it's my job to defend this because?

I just reported it... if you don't like it, don't want to use it, fine. Not my problem.

It's there. It was added for a reason. It works.

Anything beyond that costs more than I'm getting paid to do this... which is nothing.

[zork]

I should have wrote this yesterday when I saw you guys beginning to fight.

Stop it.

It is an important topic (well the title is misleading but who cares).

If anyone else has some interesting stuff on fixing taints please let us know.

I have a question. Since I read spiel's explanation I'm now sure that this is causing my raid-invite issue (someone joins the party/raid while infight).

local crfm = _G["CompactRaidFrameManager"]
    CompactRaidFrameManagerToggleButton:HookScript("OnClick", function(m)
      if CompactRaidFrameManager.collapsed then
        CompactRaidFrameManager:SetAlpha(0.2)
      else
        CompactRaidFrameManager:SetAlpha(1)
      end
    end)
    CompactRaidFrameManager:SetAlpha(0.2)
    CompactRaidFrameManagerToggleButton:SetScript("OnEnter", function(self)
      GameTooltip:SetOwner(self, "ANCHOR_RIGHT")
      GameTooltip:AddLine("RaidFrameManger", 0, 1, 0.5, 1, 1, 1)
      if CompactRaidFrameManager.collapsed then
        GameTooltip:AddLine("Click to open.", 1, 1, 1, 1, 1, 1)
      else
        GameTooltip:AddLine("Click to close.", 1, 1, 1, 1, 1, 1)
      end
      GameTooltip:Show()
    end)
    CompactRaidFrameManagerToggleButton:SetScript("OnLeave", function(self)
      GameTooltip:Hide()
    end)

I do not harm the raidframe manager in any way. I just added a hover functionality on top.

Regarding what I read I'm not allowed to touch that frame at all because I'm running in unsecure environment and touching it in any way will make it fail later on.

Is that a correct guess?

If so...how would someone add a hover functionality to the RaidFrameManager in a secure environment? Is that even possible?

[spiel2001]

Yeah... that's why I posted what I did in the last post. No need to debate about it... that was silly.

As for your code, I don't see anything there that jumps out at me as something that going to cause a taint. Setting alpha, thankfully, does not normally cause a problem and is even one of the ways one gets around a taint problem... you can show/hide non-secure frames all day long (i.e. the GameTooltip frame), it's secure frames that give you heartburn. In which case, if you can't Hide() it, you can often SetAlpha( 0 ) it.

Odds are, if you've got something that's tainting in your code, it's not in this section.

Have you tried turning on the taintlog and do a raid-invite, then log out and find where the raid-invite execution borked and work backwards? If not, turn off everything except your mod and give it a go.

In my experience, taint almost never happens where you thought it did.

[Foxlit]

Originally Posted by zork I have a question. Since I read spiel's explanation I'm now sure that this is causing my raid-invite issue (someone joins the party/raid while infight). [...] Regarding what I read I'm not allowed to touch that frame at all because I'm running in unsecure environment and touching it in any way will make it fail later on. Is that a correct guess?

Your guess is not correct -- you are allowed to touch secure and protected frames, as long as you do so in a careful manner (i.e. do not insecurely modify variables that will later be accessed by FrameXML from secure execution paths that will eventually go on to call a protected function, or go on to write to variables that will be used in this fashion). I agree with spiel regarding the code you quoted -- it looks benign, and is probably not the source of any issues.

I'm not sure if you've described what exactly your raid/party invite issue is -- quoting the error or the negative consequences would be helpful, as well as posting a link to the addons involved. In any case, you can approach debugging this by finding the (presumably) FrameXML line of code calling a protected function you get taint errors about (taintlog 1 should be sufficient to get a stack trace when the error occurs), figuring out which variables are accessed before the execution gets to that line, checking which of these are tainted, and then figuring out how your addon is tainting those variables.

[semlar]

Zork, I don't think you can call SetScript on a secure frame without tainting it. You might try replacing them with HookScript, which will work even if they don't have that script set, but I don't know if it'll taint if it didn't have that script already.

[zork]

*edit* Made a log only with oUF_Diablo, oUF and rLib enabled.

While I was testing it sth strange happened. I was in combat at a puppy and tried to right-click a focus frame I set to another player. I got an error box saying "drop-down menu ran for too long"...

I never had that. Nontheless.

Here is my taintlog:
http://rothui.googlecode.com/svn/trunk/log/taint.log

What I'm currently looking for is the taint that I get from inviting someone into the party while in combat.

[Phanx]

Originally Posted by zork How can r g b be global if they are part of a table?

You should probably re-read spiel2001's post earlier in this thread, particularly the "caveat" section. The TLDR version is that your variables aren't global, but the taint system (or at least the logging part of the system) can't tell the difference.

[zork]

Thanks. Currently looking into whatever may cause the taint for me.

Here is what I got so far. Stuff that I may look into:

2/2 11:50:53.956  An action was blocked in combat because of taint from oUF - oUF_DiabloPartyHeaderUnitButton1:SetFrameStrata()
2/2 11:50:53.956  An action was blocked in combat because of taint from oUF - oUF_DiabloPartyHeaderUnitButton1:SetFrameLevel()
2/2 11:50:53.956  An action was blocked in combat because of taint from oUF - oUF_DiabloPartyHeaderUnitButton1:SetSize()
2/2 11:50:53.986  An action was blocked in combat because of taint from oUF - oUF_DiabloPartyHeaderUnitButton1:SetHitRectInsets()

That taintlog is pretty good actually. I forgot to remove the setsize string in party.lua which is not allowed for header units...(no clue why I forgot that because I set width/height in the spawn)

...

Result. I fixed those lines and the taint is gone.

Important notice. Forget about this error when you are running "console taintlog 11"
http://imgur.com/8qQzizm

It is gone once you disable logging.

[spiel2001]

Originally Posted by zork Important notice. Forget about this error when you are running "console taintlog 11" http://imgur.com/8qQzizm It is gone once you disable logging.

Yeah... that's one of the reasons that you won't see taintlog 11 on the production servers... too easy to use it for lag exploits.