Investigate bug where block exemptions are being overridden for some users
Closed, ResolvedPublicSpike
Actions

Assigned To

Authored By

	• Samwalton9-WMF
	Dec 1 2021, 3:08 PM

Description

Some users have the ignore_wp_blocks status checked, which should exempt them from the 'no blocks' criterion for access. This has mostly been working as expected for the few dozen users we've granted it to.

For at least two users, however, the status keeps resetting to unchecked: User:Cinadon36 and User:BushelCandle.

In the case of BushelCandle, we granted the exemption in September 2021. It seemed, at the time, that each time they tried to login the status reset. We didn't change anything but the status has remained checked since after their last login attempt around then.

For Cinadon36 we've only - this week - granted the exemption, but it also seems to keep resetting.

Event Timeline

• Samwalton9-WMF created this task.Dec 1 2021, 3:08 PM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptDec 1 2021, 3:08 PM

I've asked both users to try logging in again. Their current status is:

Cinadon36

Last login: 2021-11-30
Ignore WP blocks: True (I just set this)
Wp editcount updated: 2021-12-01 14:46:20

BushelCandle

Last login: 2021-09-09
Ignore WP blocks: True
Wp editcount updated: 2021-12-01 14:58:17

BushelCandle logged in and their access is working today.

Last login: 2021-12-01
Ignore WP blocks: True
Wp editcount updated: 2021-12-01 15:45:53

I'll check back tomorrow to see if the cron changed anything.

BushelCandle still seems to have their exemption today:

Last login: 2021-12-01
Ignore WP blocks: True
Wp editcount updated: 2021-12-02 10:48:11

Cinadon logged in this morning and was not exempt anymore. I should have checked before they tried this morning to narrow this down to cron vs login, apologies for missing that.

Last login:2021-12-02
Ignore WP blocks: False
Wp editcount updated: 2021-12-02 12:47:03

• Samwalton9-WMF triaged this task as Medium priority.Dec 9 2021, 3:42 PM

• Samwalton9-WMF added a project: Spike.

Restricted Application changed the subtype of this task from "Task" to "Spike". · View Herald TranscriptDec 9 2021, 3:42 PM

I set Cinadon's block exemption just over an hour ago, and when checking again now (with no login having happened), it's off again.

Wp editcount updated: 2021-12-09 16:56:41 (10 minutes ago)

Just for completeness, when was last login?

7th December.

Excellent! This means that it is definitely our cron task that is creating the problem. Thanks!

User:Fuzzy has run into this problem today too. I set the flag, they logged in within 5 minutes of that, and the flag had reset.

User:Brezelpaul is another.

Doing some testing with my personal account:

Account isn't blocked, and I set the flag to true, then logged in. After login the flag is still true. Wp editcount updated is two weeks ago (1st February)*. Logged out and back in, still correct, updated edit count date is now right now, from this login. Further log outs/ins seem to retain the flag status.
Blocked myself. Logged out and back in. I'm still able to use the library; block exemption flag is intact. Logged out and back in, flag still intact.

TL;DR: I can't reproduce the flag turning off through logging in.

*Shouldn't that be updating on a regular basis through the cron?

Today, we examined the source code and verified that we are setting ignore_wp_blocks in any of our login or cron code. We read the value to check eligibility, but that's it. The only place the field is exposed for editing is in the user admin interface. We also checked production to verify that we were not stuck on the migration that set the initial field value, and it looked fine.

There are many places where editors get modified and saved, however, and possibly places where this happens indirectly via signals from other classes. We suspect that somewhere the editor is getting saved and that somehow the value is missing in some (unknown) cases. With the current model configuration, the default value is false. This makes it difficult to even identify impacted users, since false is expected to be the value for most users.

We talked about making the field nullable to test, but I just thought of a more expedient option:
On my local machine, I'm going to make ignore_wp_blocks true for all users and then test logging in, running cron tasks, etc to see when accounts flip over to false.

jsn.sherman claimed this task.Feb 16 2022, 3:35 PM

okay, I've verified that crons aren't causing the issue.
I did the following locally:

set ingore_blocks for everybody update users_editor set ignore_wp_blocks = 1;
verify ignore_blocks was set for everbody select count(wp_username) from users_editor where ignore_wp_blocks = 0 or ignore_wp_blocks IS NULL;
run crons python manage.py runcrons
verify all blocks were still set select count(wp_username) from users_editor where ignore_wp_blocks = 0 or ignore_wp_blocks IS NULL;

[...] After login the flag is still true. Wp editcount updated is two weeks ago (1st February)*. [...] *Shouldn't that be updating on a regular basis through the cron?

Yes, and I'm discovering that our visibility into how the cron tasks are doing is pretty limited.

@Samwalton9
it looks like the multiple bundle auths issue has been causing the update eligibility task to fail out without updating all users for a long time. The main impact of this is keeping people eligible for longer than they should be since the sample period for recent edit count can stretch out to however long it has been between logins.
I'm now working with a recent backup in staging and some extra exception handling and logging in this pr:
https://github.com/WikipediaLibrary/TWLight/pull/963
Which seems to resolve the big issue (the task now completes) and gives us an email alert when the task encounters editors with this problem.
This is a separate issue from the block exemption bug, but it needs to be fixed and was also getting in the way of this investigation.

In T296853#7716538, @jsn.sherman wrote:

okay, I've verified that crons aren't causing the issue.
I did the following locally:

set ingore_blocks for everybody update users_editor set ignore_wp_blocks = 1;

verify ignore_blocks was set for everbody select count(wp_username) from users_editor where ignore_wp_blocks = 0 or ignore_wp_blocks IS NULL;

run crons python manage.py runcrons

verify all blocks were still set select count(wp_username) from users_editor where ignore_wp_blocks = 0 or ignore_wp_blocks IS NULL;

I repeated this on staging before running the updated cron task yesterday, by the way.
All editors still have the flag set, which is what I'd expect.

Back to the main issue.
I'm looking through impacted editor accounts in django admin on production. I'll add comments for each editor as I pull them together
Cinadon36
last login: 2021-12-16
ignore_wp_blocks: true
change history:

Nov. 19, 2021, 1:31 p.m.	Changed Ignore wp blocks and Contributions for wikipedia editor “Cinadon36”.
Nov. 29, 2021, 2:50 p.m.	Changed Ignore wp blocks and Contributions for wikipedia editor “Cinadon36”.
Nov. 30, 2021, 10:02 a.m.	Changed Ignore wp blocks and Contributions for wikipedia editor “Cinadon36”.
Dec. 1, 2021, 12:25 p.m.	Changed Ignore wp blocks and Contributions for wikipedia editor “Cinadon36”.
Dec. 1, 2021, 3:09 p.m.		Changed Ignore wp blocks and Contributions for wikipedia editor “Cinadon36”.
Dec. 9, 2021, 3:43 p.m.		Changed Ignore wp blocks and Contributions for wikipedia editor “Cinadon36”.

I think this reflects us trying to get it to stick, and then it did.

BushelCandle
last login:2021-12-01
ignore_wp_blocks: true
change history:

Sept. 8, 2021, 3:32 p.m.		Changed Ignore wp blocks for wikipedia editor “BushelCandle”.
Sept. 9, 2021, 8:40 a.m.		Changed Ignore wp blocks for wikipedia editor “BushelCandle”.
Sept. 18, 2021, 12:29 a.m.		Changed Ignore wp blocks for wikipedia editor “BushelCandle”.
Sept. 18, 2021, 12:29 a.m.		No fields changed.

Brezelpaul
last login: 2022-02-15
ignore_wp_blocks: false
change history:

This object doesn’t have a change history. It probably wasn’t added via this admin site.

This points to some kind of issue with django admin, but I'll keep going to see if there is a pattern.

I went ahead and updated Brezelpaul with ignore_wp_blocks and then checked the history:

Feb. 18, 2022, 3:36 p.m.		Changed Ignore wp blocks for wikipedia editor “Brezelpaul”.

We'll see if it sticks.

Fuzzy
last login: 2022-01-19
ignore_wp_blocks: false
change history:

Jan. 19, 2022, 12:38 p.m.		Changed Ignore wp blocks for wikipedia editor “Fuzzy”.

Hmm, so here we have the ignore blocks set to false, but we do see the history of it being changed. I went ahead and set ignore blocks back to true, so now we have:

Jan. 19, 2022, 12:38 p.m.		Changed Ignore wp blocks for wikipedia editor “Fuzzy”.
Feb. 18, 2022, 4:08 p.m.		Changed Ignore wp blocks for wikipedia editor “Fuzzy”.

Fuzzy's flag got the reverted.

I have identified the issue, and it is in the user_update_eligibility command.
When the editors queryset gets evaluated in the command, the entire set gets loaded into memory and then looped through.
When the editor gets changed in admin (or anywhere else) while the command is looping through the editors, the updated value is not reflected in the Editor instance that is being updated in the command is stale.
It looks like this is a case where we want to be using the iterator method on the queryset instead of a for loop to avoid loading the whole thing in memory, but a refresh_from_db may be necessary as well.
In other words, this is a one or two line fix. I'll verify the correct path to take.

How I reproduced the issue

removed all ignore_blocks flags: update users_editor set ignore_wp_blocks = 0;
verified the count of users with the flag:

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;
+--------------------+
| count(wp_username) |
+--------------------+
|                  0 |
+--------------------+
1 row in set (0.013 sec)

started the command: python manage.py user_update_eligibility
added the flag back to all accounts while the command was running: update users_editor set ignore_wp_blocks = 1;
repeatedly queried for the accounts with the flag, and watched the number dropped as the command saved stale editor data:

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;                                                               
+--------------------+                                                                                                                                   
| count(wp_username) |                                                                                                                                   
+--------------------+                                                                                                                                   
|              21236 |                                                                                                                                   
+--------------------+                                                                                                                                   
1 row in set (0.020 sec)                                                                                                                                 
                                                                                                                                                         
MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;                                                               
+--------------------+                                                                                                                                   
| count(wp_username) |                                                                                                                                   
+--------------------+                                                                                                                                   
|              21235 |                                                                                                                                   
+--------------------+                                                                                                                                   
1 row in set (0.029 sec)                                                                                                                                 
                                                                                                                                                         
MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;                                                               
+--------------------+                                                                                                                                   
| count(wp_username) |                                                                                                                                   
+--------------------+                                                                                                                                   
|              21232 |                                                                                                                                   
+--------------------+                                                                                                                                   
1 row in set (0.017 sec)                                                                                                                                 
                                                                                                                                                         
MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;                                                               
+--------------------+                                                                                                                                   
| count(wp_username) |                                                                                                                                   
+--------------------+                                                                                                                                   
|              21232 |                                                                                                                                   
+--------------------+                                                                                                                                   
1 row in set (0.019 sec)                                                                                                                                 
                                                                                                                                                         
MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;                                                               
+--------------------+                                                                                                                                   
| count(wp_username) |                                                                                                                                   
+--------------------+                                                                                                                                   
|              21232 |                                                                                                                                   
+--------------------+                                                                                                                                   
1 row in set (0.018 sec)                                                                                                                                 
                                                                                                                                                         
MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;
+--------------------+
| count(wp_username) |
+--------------------+
|              21230 |
+--------------------+
1 row in set (0.019 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;
+--------------------+
| count(wp_username) |
+--------------------+
|              21228 |
+--------------------+
1 row in set (0.021 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;
+--------------------+
| count(wp_username) |
+--------------------+
|              21226 |
+--------------------+
1 row in set (0.020 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;
+--------------------+
| count(wp_username) |
+--------------------+
|              21224 |
+--------------------+
1 row in set (0.020 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;
+--------------------+
| count(wp_username) |
+--------------------+
|              21221 |
+--------------------+
1 row in set (0.020 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;
+--------------------+
| count(wp_username) |
+--------------------+
|              21217 |
+--------------------+
1 row in set (0.019 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;
+--------------------+
| count(wp_username) |
+--------------------+
|              21214 |
+--------------------+
1 row in set (0.021 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;
+--------------------+
| count(wp_username) |
+--------------------+
|              21212 |
+--------------------+
1 row in set (0.020 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 1;
+--------------------+
| count(wp_username) |
+--------------------+
|              21210 |
+--------------------+
1 row in set (0.013 sec)

That's great news! I'm glad it's an easy fix :)

Okay, I have hotfixed the issue:
https://github.com/WikipediaLibrary/TWLight/compare/1269e7d51503...7fffc0ce83ea
I verified that this resolves the issue.
Once this makes it onto prod, we shouldn't have any more editors get their flags unset.

How I verified
Now when I go through the steps I outlined to reproduce the issue, only the first editor has the flag unset, and even that one is just there because the object was loaded in the command before I set the flag for all users directly in the db.

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 0;                                                              
+--------------------+
| count(wp_username) |
+--------------------+
|                  1 |
+--------------------+
1 row in set (0.019 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 0;                                                              
+--------------------+
| count(wp_username) |
+--------------------+
|                  1 |
+--------------------+
1 row in set (0.019 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 0;                                                              
+--------------------+
| count(wp_username) |
+--------------------+
|                  1 |
+--------------------+
1 row in set (0.027 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 0;                                                              
+--------------------+
| count(wp_username) |
+--------------------+
|                  1 |
+--------------------+
1 row in set (0.019 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 0;                                                              
+--------------------+
| count(wp_username) |
+--------------------+
|                  1 |
+--------------------+
1 row in set (0.012 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 0;                                                              
+--------------------+
| count(wp_username) |
+--------------------+
|                  1 |
+--------------------+
1 row in set (0.018 sec)

MariaDB [twlight]> select count(wp_username) from users_editor where ignore_wp_blocks = 0;                                                              
+--------------------+
| count(wp_username) |
+--------------------+
|                  1 |
+--------------------+
1 row in set (0.026 sec)

When the editor gets changed in admin (or anywhere else) while the command is looping through the editors

Wow that's quite a surprising edge case and perfectly explains why the behaviour was so inconsistent - great work!

I've re-set the flag on all exempted users who didn't currently have it set (approx 20% of all exemptions).

• Samwalton9-WMF closed this task as Resolved.Feb 24 2022, 3:40 PM

Investigate bug where block exemptions are being overridden for some usersClosed, ResolvedPublicSpikeActions

Description

Event Timeline

Investigate bug where block exemptions are being overridden for some users
Closed, ResolvedPublicSpike
Actions