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.

__________________

What people don't get is that I am, ultimately, an artist at heart. My brush has two colors, 1 and 0, and my canvas is made of silicon.

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.

__________________

What people don't get is that I am, ultimately, an artist at heart. My brush has two colors, 1 and 0, and my canvas is made of silicon.

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.

__________________

What people don't get is that I am, ultimately, an artist at heart. My brush has two colors, 1 and 0, and my canvas is made of silicon.

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.

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.

__________________

What people don't get is that I am, ultimately, an artist at heart. My brush has two colors, 1 and 0, and my canvas is made of silicon.

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.

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.

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)