In T168736#3375331, @Legoktm wrote:

So the edit_delta variable is wrong?

edit_delta, added_lines, removed_lines, and several others appear to be wrong. But they are for the right page, and the timestamp shown in Special:AbuseLog/18775762 and Special:AbuseFilter/examine/955398370 are the same. Very odd.

I just ran another test with the same filter but removed added_lines rlike "^[\n\s]+$", and some 5-10 edits were tripped that all had the correct values for the variables. Then I added it back, and had a brief moment of relief when this edit was tripped (correct) but soon after I got this which is clearly not correct. Not sure what's going on!

I've checked a few more active filters and am not seeing the same issue. I'm starting to believe added_lines rlike "^[\n\s]+$" is somehow making it bug out.

So I again ran the filter with just:

user_age == 0 &
edit_delta < 5 &
edit_delta > -5

and got numerous hits that were all correct. So I'm a bit confident all is well there.

Then I tried just:

user_age == 0 &
added_lines rlike "^[\n\s]+$"

and I'm seeing more weirdness. This edit should not have been tripped. It removed the text "not at all", but I don't see that in old_wikitext at either Special:AbuseFilter/examine/log/18776773 or Special:AbuseLog/18776773. The variable added_lines is also mysteriously not shown.

Possibly related T156920, T143353

We haven't seen an influx of reports at Wikipedia:Edit filter/False positives, and as I said when I spot checked other filters they seem to be working as expected. So for now I'm not sure if this bug is worthy of "unbreak now" but it is certainly a nasty one!

@Legoktm: As this was set to "Unbreak Now" priority, do you have anybody in mind who plans to work on this task?

STRIKE THIS - it was a deletion/restoration

In T168736#3412966, @Xaosflux wrote:

[https://en.wikipedia.org/w/index.php?diff=789228399&oldid=789209302&title=User_talk:RugratsFan2003 This edit], made 04:57 on 6 July 2017, currently shows in the [https://en.wikipedia.org/w/index.php?title=User_talk:RugratsFan2003&action=history history] as an addition of +163 bytes, rather than a very large negative value that I would expect

Definitely looks like a bug to me, but I think this is probably unrelated to the issues with AbuseFilter. In those cases the sizes shown in the revision history were correct.

@MusikAnimal - forget that last one - there was a deletion action in the middle there.

This has been UBN! since June 23rd and hasn't seen any movement or comments for almost 2 weeks. What is the status?

Adding @hoo as maintainer of AbuseFilter per https://www.mediawiki.org/wiki/Developers/Maintainers

In T168736#3445144, @greg wrote:

This has been UBN! since June 23rd and hasn't seen any movement or comments for almost 2 weeks. What is the status?

Adding @hoo as maintainer of AbuseFilter per https://www.mediawiki.org/wiki/Developers/Maintainers

For what it's worth, as I said above I don't believe this issue is widespread. Filter authors who have run into this probably noticed the same weirdness and abandoned their filter just as I have. All the existing filters on enwiki appear to be working. In other words I don't think there was a bad deploy or regression that recently introduced this.

May be the same core issue as T173977: AbuseFilter tripping more times than it should, and for the wrong edit, and not tagging

I started looking into this. So, let's proceed with small steps.

1. First of, what triggered the filter is the regex on added_lines, which are wrong.
2. Added_lines and removed_lines are both extracted from the unidiff stored in edit_diff, which is wrong.
3. The diff is generated on the fly using the Diff class on old_wikitext and new_wikitext.
4. So, this problem is caused by old_wikitext and new_wikitext being wrong: in fact, they're almost identical (looking at the diff there should be a difference of a \n, but I'm not sure due to var dumping not being clean); those variables are generated upstream in the hook.

Now, comparing old/new_wikitext with the actual diff reveals that both variables are actually holding the new revision text (from now on I'll ignore that newline thingy). So, we can further restrict our attention to old_wikitext being computed wrongly. As for the very root of this problem, I still don't know. I replicated the edit on my local wiki and, as expected, everything went fine. Practically speaking, the interesting section of the code is this one. Whatever happened there at the moment remains cryptic to me, but if I'm right old_wikitext is what caused all these problems. I'll try to see if I can figure it out, but since this isn't reproducible, it won't be easy at all.

ADD: I looked at the other examples quite quickly, but I could see the same pattern, e.g. old_wikitext equal to new_wikitext (again, apart from that \n stuff) which in turn caused everything else to be wrong. However, what I'll do now is check around if we had some core change on June 23rd, since this might as well be caused by something unrelated to AF.

Curiously, the IPv6 address doesn't have any entry in the AbuseLog, although it's listed in filter hits. Maybe using fetchText.php to directly get variables may help? If so, old_id is 796324721. I really can't tell what's wrong with that edit, when doing getRevision it probably got the current revision instead of the old one, but I can't say why. I also couldn't find any related change happened in those days. Maybe someone else does?

Thanks so much for looking into this!

I re-enabled the same filter at en:Special:AbuseFilter/637, and I found this edit that seems to suffer from the same defect. If you look at the IP's contributions, there are no qualifying edits (one has an edit delta of -5 and one with 5, just outside the range). Again if you examine the edit with the above pattern it does not match. edit_delta is also missing from Special:AbuseLog/21144035 :(

I can try to look for other examples, if it helps.

@MusikAnimal Yes please! The more examples, the better it is. Unfortunately I still can't examine it due to the lack of abusefilter-modify right (although I can see the variables). If we find more examples of this, we may need to add some debugging lines to the code in order to have some info on live data. And BTW, missing variables are a separate problem for which we have a patch that should be carefully reviewed.

ADD: Interesting, I noticed that on enwiki lots of hits for that filter have the same problem with old_wikitext. I enabled a similar test filter on itwiki as well to see if I can catch some more examples, since to me it's completely impossible to replicate the behaviour on my local wiki.

Ohhh, the thing is getting tricky. I just found the problem on itwiki, see AbuseLog. But it's not over: if you go to filter hits and click on the diff link for the edit (the ony by 37.116.233.175), you actually get to the next revision. Looks like AbuseFilter is retrieving the wrong version to make its checks, and uses it in some points like old_wikitext and diff link. However I can't tell if it's due to the used regex. I also couldn't find any common point to all of those edits: some on enwiki are mobile edits, this on itwiki was made using VisualEditor, but it's too early to determine if those things are involved. Further investigation and brainstorming coming here.

I can't tell if it's due to the used regex

I can say the regex ^[\n\s]+$ doesn't seem to do what I think it does. It's supposed to look at added_lines, and match anything where the line contains only a new line or space. The majority of edits that were triggered with my test filter do not have any lines that are only a space or new line character. Anyway, I'm going to chalk that up as a separate issue.

The diff link points to a completely different revision

Indeed, it looks like the same is true for my examples. However even the diff it does link to shouldn't trip the filter. I had the edit_delta conditions edit_delta < 5 & edit_delta > -5 but all surrounding edits were outside this range. So even if the regex ^[\n\s]+$ is messing up, that doesn't explain why the edit_delta check malfunctioned.

Maybe we should pursue T176291 first, since that will help with debugging?

Yeah, it would definitely be good to give a look at mentioned task, although they're not necessary. This is what I can tell basing on hits bot on itwiki and enwiki.

• The core issue is with the revision/WikiPage gathered in the hook. AF gets a wrong revision for either old_wikitext, new_wikitext or both (all of these can be found within provided links if I'm correct)
• Other text variables have to be wrong because they all rely on new_wikitext and old_wikitext to compute diff, edit_delta etc. so they're not a problem
• Although it's not clear which revision object is being picked, the diff is always the same, i.e. there's an added newline at the end of the page (not sure if it's a linefeed or a carriage return, or both). This generates a blank added line, catched by the filter.
• Sometimes the filter does what it's meant to do, i.e. match edits which only add a new blank line

Now, looking to this entry as an example, this is the specifical situation:

• On Special:AbuseLog the action is logged as performed by User:Geoide. The "diff" link doesn't bring to the expected revision by her, but to the previous one by User:Kirk39 (which happened 15 minutes earlier).
• Clicking on /details (or /examine, it's the same), variables are as following: user_name, user_groups, summary and timestamp refer to Geoide's edit (weird fact: timestamp is 18.37.xx, but in history the edit is reported to be save at 18.38). old_wikitext and new_wikitext both contain a copy of Kirk39's edit (plus a newline in new_wikitext), which consequently makes edit_diff, old_size, new_size, edit_delta, added_lines and removed_lines refer to this ghost edit, thus breaking them.

There's some sort of mix where some variables are correct, while the others are completely wrong.

However, I have another doubt. We perform a contentToString on old_wikitext and new_wikitext to achieve a result similar to PST due to T22310 (patch). That function simply replaces "\r\n" with "\n". Some days ago I sent a patch to simplify it and use TextContent::normalizeLineEndings to achieve the same result + applying a rtrim. Right now, my concern is that the trailing \n in new_wikitext is sometimes added before invoking abusefilter; since right now we don't apply rtrim, the two revisions are considered different: what might happen is that the user makes some sort of null edit, AbuseFilter gets an rtrimmed old_wikitext and a raw new_wikitext. Then it performs these comparisons and finds that the edit isn't null (again, due to the \n).So the filters are run and a match is registered (since we're specifically looking to blank lines, which we get here). Then it gets to logging the action, but since the edit wasn't really saved AF gets confused and just links an unrelated revision with a medley of wrong variables.

-->I developed the above idea while writing, but the more I think about it the more it makes sense to me. Further investigation definitely coming tomorrow.

I tested a bit my theory, although I'm not still able to trigger the filter. Maybe it could help to know if the added character is a linefeed or a carriage return. Also, maybe it depends on whether we check equality on Content objects or strings. Further tests coming tomorrow, and even if I can't reproduce the issue I feel like we're getting closer and closer.

EUREKA! I was at least able to get a hit. Speaking with Geoide I learned that in her case there have been an edit conflict. So I tried various blends of conflicted edits with the help of my bot, and one of these triggered the filter. The used steps were:

1. Start editing a section from main account and add some text.
2. Edit the same section with another account, add the summary (so the edit is stashed) and save
3. Go back to the main account, add the summary (stashed again) and try to save
4. The conflict window will pop up. Just ignore it and press "save" again.

Result: the edit will trigger the filter. The diff link is correctly pointing to the last revision where the text from (1.) is added. /details, instead, has the new version in both new_wikitext and old_wikitext (apart from the usual \n) and variables are all wrong as expected.

A very important thing to note is that this probably isn't the only way this malfunctioning could happen. For instance, I can see filter hits from pages without any conflict (only one edit by same user), and the diff link being correct is also an exception. However, I strongly believe that the core issue is the same, and since now I'm able to replicate the problem I'll do more specific testing.

Further details
Stashing the edit is not necessary. I repeated the steps above adding a summary, but editing the text later (so no stash). The result is the same: the main edit wasn't be saved but the main account triggered the filter, with diff link pointing to the last page revision, which is from the alternative account.

ADD: Unfortunately I'm having some problems in testing it on my local wiki since it doesn't let me click the save button in the conflict window. Or, better, I can click it but I'd be sent to another conflict window with an empty diff, and clicking on "save" this process would repeat. Maybe some problems with my wiki config, although I re-installed the master core.

A few hours later
I could finally reproduce this on another private wiki with the above steps simplified as much as possible (no summary, no stash, just conflict and null-save). I could also see that the patch linked above actually works, since it makes the edit be treated as a null edit and thus ignored. Of course some more testing of the patch should be done, together with an assessment of potential regressions in rtrimming the text, but I'm quite confident.

However this opens a new philosophical question. In *_wikitext we don't have an exact copy of the page text, instead we provide something between the user input and the PST result. This means that it's possible to trigger a filter without actually saving the edit. For instance, if I put a signature and save, then re-edit the page adding the 4 tildes (in the same minute), the page won't be saved (identical PST content). However, AF will register a hit (if the edit was caught by any filter) and the diff in /details will show the removal of the signature and the addition of the tildes. A "diff" link will also be shown, pointing to the latest available revision. We should probably devise a clean way to deal with raw text and the PSTed one, behaving simlarly to how MW core does, while keeping *_wikitext and *_pst variables distinct and useful.

Change 432355 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Simplify contentToString function

https://gerrit.wikimedia.org/r/432355

Change 432355 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Simplify contentToString function

https://gerrit.wikimedia.org/r/432355

I forgot to re-enable the filter for final testing, so I did it now. @MusikAnimal could you please re-enable it on enwiki as well in order to be sure that the problem is solved?

ADD: Seems fixed with the edit conflict scenario reported above. Let's wait for a further confirmation.

Thanks for re-activating it. Looking at both it and enwiki hits, the problem didn't show up (entries which have a "diff" link are genuine). I'd say to keep filters in place another day or two, then this could be confirmed. I only found a weird hit, this one, however it was for "upload" action, which makes me think there may be another reason for it.

Yes, I think the issue has been fixed :) Before after only a few hours I would see some inaccurate hits. I've had it running for close to a day now and everything looks good :) Thank you again!

In T168736#4205843, @MusikAnimal wrote:

I can say the regex ^[\n\s]+$ doesn't seem to do what I think it does.

Even better, this apparently does work :)

In T168736#4268394, @Daimona wrote:

I only found a weird hit, this one, however it was for "upload" action, which makes me think there may be another reason for it.

Interesting. I was under the impression added_lines didn't apply to the upload action. I guess that's the description that it is picking up?

In T168736#4269241, @MusikAnimal wrote:

Before after only a few hours I would see some inaccurate hits.

Same on itwiki, I also rechecked filter hits on enwiki as well and everything seems fine, so yeah, confirmed fixed.

In T168736#4269241, @MusikAnimal wrote:

Interesting. I was under the impression added_lines didn't apply to the upload action. I guess that's the description that it is picking up?

Probably yes. In both cases there was no description, so it catched an empty page, but I see this isn't in the scope of this task.