What happened?:
As reported here, Liu1126 attempted to quit as a mentor, but they still have mentees and are still receiving questions.
What should have happened instead?:
Mentors who quit mentorship should have all their mentees reassigned.
Description
Description
Details
Details
Related Changes in Gerrit:
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Resolved | BUG REPORT | Urbanecm_WMF | T418194 Mentors still having mentees after removing themselves | ||
| Open | None | T439577 changeprop timeouts are not configured consistently | |||
| Open | None | T439580 reassignMenteeJob triggers fairly large transactions |
Event Timeline
There are a very large number of changes, so older changes are hidden. Show Older Changes
Comment Actions
Change #1280370 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[mediawiki/extensions/GrowthExperiments@wmf/1.46.0-wmf.24] ReassignMentees: Add logging information
Comment Actions
Change #1280368 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@wmf/1.46.0-wmf.26] ReassignMentees: Add logging information
Comment Actions
Change #1280370 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@wmf/1.46.0-wmf.24] ReassignMentees: Add logging information
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-04-30T12:19:15Z] <urbanecm@deploy1003> Started scap sync-world: Backport for [[gerrit:1280368|ReassignMentees: Add logging information (T418194)]], [[gerrit:1280370|ReassignMentees: Add logging information (T418194)]]
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-04-30T12:21:06Z] <urbanecm@deploy1003> urbanecm: Backport for [[gerrit:1280368|ReassignMentees: Add logging information (T418194)]], [[gerrit:1280370|ReassignMentees: Add logging information (T418194)]] synced to the testservers (see https://wikitech.wikimedia.org/wiki/Mwdebug). Changes can now be verified there.
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-04-30T14:30:46Z] <urbanecm@deploy1003> Finished scap sync-world: Backport for [[gerrit:1280368|ReassignMentees: Add logging information (T418194)]], [[gerrit:1280370|ReassignMentees: Add logging information (T418194)]] (duration: 131m 31s)
Comment Actions
The peroblem is we don't know what the smaller subtasks would be, as we don't know what this is caused by :). Hard to plan a bugfix for a bug with an unknown cause :/.
Comment Actions
Totally understand. If there isn’t a logical way to break the work into smaller subtasks, then I think the best next step is probably to agree on a clear timebox before we revisit the task again.
Fixing this bug is important, but since the work has now carried across several sprints, it may help to either set a clearer boundary on the investigation effort or have someone else take a fresh look at it for a different perspective.
Separately, given the mini sprint (during the offsite), I didn’t think this task was likely to be completed in that timeframe anyway, so moving it out of the sprint felt like the right call for now.
Comment Actions
I would say that this tasks purpose changed to add logging with the intention of surfacing information on where the real issue would be and could even be retitled to reflect that.
Right now it would be reasonable to call this an investigation that we've agreed to track outside the sprint.
Depending on how long the logs will be monitored for, a report on the logging results would be shared here and inform the creation of another ticket where the findings that suggest a fix could be addressed.
As Kirsten has mentioned, carrying this from sprint to sprint without a clear way to timebox only leads to more task completion ambiguity. This beats the purpose of adding tickets that have a clear timebox/estimation to a sprint that we intend to complete as a team.
Comment Actions
Timeboxed to look at logging and investigate further. After timebox, let's discuss further with engineers if there still isn't a clear solution.
Note from estimation: The job is running twice, it's unclear why. Complexity in that much of the scheduling code is less well known for Growth engineers, and it seems like there aren't any subject matter experts left at WMF with familiarity in this cosebase.
Comment Actions
Is the situation of this user marked 'away' in 2025 by @Pppery, and who continues to receive mentee questions also covered by this ticket? Or do we need to create a related task, "Mentors still having mentees after having been marked away by a third party"?
If the two situations are identical, or similar enough to be covered in this ticket, then please someone change the task title to something like, "Mentors still having mentees after removing themselves or being marked away". Thanks.
Comment Actions
That's unrelated to anything here. What happened there is that "away" marks have a maximum duration of a year and then this one expired. Marking someone as away isn't supposed to remove their mentees in case they return; it's supposed to dynamically redirect questions to other mentors and that part is working properly - the only problem here is 2025-Pppery's lack of foresight.
Comment Actions
@Mathglot - Pppery is correct. That said, Growth just realease a feature that should help with the issue you are mentioning:
https://www.mediawiki.org/wiki/Help:Growth/Mentorship#Automated_mentor_list_cleanup
We will be testing it on French Wikipedia next week, but an admin can already configure it on enwiki if there is interest:
https://en.wikipedia.org/wiki/Special:CommunityConfiguration/Mentorship
Comment Actions
I have configured enwiki to mark mentors as away after 1 month of inactivity, which matches roughly the standards people have asked to apply manually.
(Past-me made https://en.wikipedia.org/wiki/Wikipedia:Database_reports/Unanswered_mentor_questions and relied on it instead when marking people as away, and before that used two months, but people complained two months was too long and I'm trying to step back from the manual backlog-chasing I used to spend a huge amount of time doing due to loss of motivation)
Comment Actions
@Pppery Glad to hear this feature helps take something off your plate!
Just FYI, the change won't go into effect immediately. Eventually the Community Configuration change will be automatic, but since this change will start a new maintenance script @Urbanecm_WMF wisely suggested he should "flip the switch" the first time it runs on a production wiki so he's available to monitor and check logs.
We will be testing on frwiki next week, and if all goes as expected we will enable on enwiki next.
Comment Actions
For the record, this has happened some time ago, and it seems to be working: https://en.wikipedia.org/w/index.php?title=MediaWiki:GrowthMentors.json&action=history.
Comment Actions
So...GrowthExperiments:reassignMentees scheduled the same job _twice_, one version was delayed by 6 minutes, the other one started executing immediately? And then at 12:21:10.647Z, we scheduled a job delayed until 12:20:27Z? That...seems suspicious...
This has an explanation: It silently regressed in https://gerrit.wikimedia.org/r/c/mediawiki/extensions/GrowthExperiments/+/1077707, where we (among other things) switched to JobSpecification, which has a _different_ way to work with duplicates. This mean ignoreDuplicates() and getDeduplicationInfo() on the job are simply not consulted at all. Uploading a fix.
Comment Actions
Change #1344308 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[mediawiki/extensions/GrowthExperiments@master] ReassignMentees: Actually deduplicate reassignMenteesJob
Comment Actions
Change #1344323 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[mediawiki/extensions/GrowthExperiments@master] ReassignMentees: Make the jobReleaseTimestamp work
Comment Actions
Change #1344308 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@master] ReassignMentees: Actually deduplicate reassignMenteesJob
Comment Actions
Change #1344323 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@master] ReassignMentees: Make the jobReleaseTimestamp work
Comment Actions
Change #1344712 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[mediawiki/extensions/GrowthExperiments@wmf/1.47.0-wmf.21] ReassignMentees: Actually deduplicate reassignMenteesJob
Comment Actions
Change #1344713 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[mediawiki/extensions/GrowthExperiments@wmf/1.47.0-wmf.20] ReassignMentees: Actually deduplicate reassignMenteesJob
Comment Actions
Change #1344713 abandoned by Urbanecm:
[mediawiki/extensions/GrowthExperiments@wmf/1.47.0-wmf.20] ReassignMentees: Actually deduplicate reassignMenteesJob
Comment Actions
Change #1344712 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@wmf/1.47.0-wmf.21] ReassignMentees: Actually deduplicate reassignMenteesJob
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-09-29T08:48:35Z] <urbanecm@deploy1003> Started scap sync-world: Backport for [[gerrit:1344712|ReassignMentees: Actually deduplicate reassignMenteesJob (T418194)]]
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-09-29T08:52:47Z] <urbanecm@deploy1003> urbanecm: Backport for [[gerrit:1344712|ReassignMentees: Actually deduplicate reassignMenteesJob (T418194)]] synced to the testservers (see https://wikitech.wikimedia.org/wiki/Mwdebug). Changes can now be verified there.
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-09-29T08:59:43Z] <urbanecm@deploy1003> Finished scap sync-world: Backport for [[gerrit:1344712|ReassignMentees: Actually deduplicate reassignMenteesJob (T418194)]] (duration: 11m 07s)
Comment Actions
Preparing some users to tests this on:
[urbanecm@stat1008 ~]$ curl -s 'https://en.wikipedia.org/w/index.php?title=MediaWiki:GrowthMentors.json&action=raw' | jq -r '.Mentors | keys[]' | sed 's/$/, /g' | tr -d '\n'; echo # getting a list of current mentors 10006598, 1027855, 10806116, 11378440, 11555324, 12079125, 12652641, 128863, 12921690, 13006032, 13049451, 15748968, 1612380, 16294199, 16531723, 1659234, 16759563, 1686264, 169380, 17040, 17619453, 17692156, 17794675, 17859592, 18998846, 190064, 19502098, 19597010, 19637353, 1990013, 20284886, 20313678, 20319727, 20818275, 2158746, 21931029, 221, 22434203, 23085006, 23204849, 23257138, 2343159, 23530312, 2366721, 2386927, 24269494, 24484530, 2512606, 25242445, 2524922, 25261336, 2544398, 2559432, 25787236, 262675, 2639797, 26844029, 26928275, 27191399, 27191417, 27744084, 28103413, 28167610, 28941978, 29526596, 30052052, 30607451, 30842190, 31026899, 31091588, 31152058, 31259259, 3174456, 31812356, 31990484, 32308078, 32575524, 32806013, 32888185, 32975992, 329764, 33028965, 33145, 33234406, 33467233, 33608611, 33621746, 33842945, 33845031, 34192209, 34422962, 346308, 34669967, 34725219, 35098811, 35232820, 35395549, 35751661, 35839649, 35968872, 36043475, 36056848, 36148677, 36172507, 36269730, 36418353, 36869707, 36874176, 36878010, 37110517, 37755355, 37777109, 37896519, 38123398, 38788892, 39000530, 39042396, 39133416, 39177836, 39276444, 39368978, 39795743, 39915221, 39934507, 39999417, 40006740, 40234724, 40234806, 40244911, 40249159, 40275445, 40306036, 40387352, 4045206, 40509413, 40571816, 40581682, 40820929, 40862738, 40917049, 41091682, 41195652, 41248025, 41285927, 41354242, 41369960, 4150578, 41625374, 41670580, 41906421, 42207223, 42244930, 42297480, 42681389, 42788136, 43113873, 43475265, 43602427, 43687949, 43699801, 43768634, 43783383, 44230401, 44318843, 44402255, 44428614, 44433021, 44487672, 44753929, 44786610, 44846, 44882230, 44967271, 45029904, 45266726, 45416752, 45433808, 45462894, 45495555, 45521654, 45552802, 45572306, 4564448, 45739042, 45801052, 45929875, 45960494, 45981649, 45991369, 46067550, 46081742, 46115515, 46242311, 4626582, 46290774, 46488868, 46710697, 46717923, 46967642, 47012757, 47103691, 47285530, 47313424, 47397133, 47404959, 47519242, 47546009, 47641100, 47684007, 47733567, 47773670, 47776394, 47845483, 47851454, 47945897, 48144448, 48150152, 48153652, 48212644, 48254667, 48302818, 48325869, 48494857, 48618112, 48649018, 48675950, 4871659, 48747569, 48866919, 48902430, 48914397, 48984474, 49068582, 49124328, 49126888, 49174942, 49214, 49294195, 49386579, 49416358, 49554480, 49566734, 49592795, 49719784, 49850249, 49911012, 49979660, 50022150, 50075699, 50141202, 50197585, 50206322, 50239623, 502540, 50267773, 50301655, 50324240, 50329040, 50393845, 50404545, 50479220, 50575939, 50584560, 50599377, 50796328, 51142406, 51254819, 51812881, 51899051, 52195809, 52371925, 52706, 52750217, 52864486, 531277, 53147371, 54034842, 54513127, 5661201, 6196463, 643450, 6457542, 664832, 6959733, 7099464, 769695, 8240947, 86163, 910180, 9149531, 9203640, 9218543, 937895, 94080, [urbanecm@stat1008 ~]$ analytics-mysql --use-shard x1 enwiki mysql:research@dbstore1009.eqiad.wmnet [enwiki]> select gemm_mentor_id, count(*) from growthexperiments_mentor_mentee where gemm_mentor_role = 'primary' and gemm_mentor_id not in (10006598, 1027855, 10806116, 11378440, 11555324, 12079125, 12652641, 128863, 12921690, 13006032, 13049451, 15748968, 1612380, 16294199, 16531723, 1659234, 16759563, 1686264, 169380, 17040, 17619453, 17692156, 17794675, 17859592, 18998846, 190064, 19502098, 19597010, 19637353, 1990013, 20284886, 20313678, 20319727, 20818275, 2158746, 21931029, 221, 22434203, 23085006, 23204849, 23257138, 2343159, 23530312, 2366721, 2386927, 24269494, 24484530, 2512606, 25242445, 2524922, 25261336, 2544398, 2559432, 25787236, 262675, 2639797, 26844029, 26928275, 27191399, 27191417, 27744084, 28103413, 28167610, 28941978, 29526596, 30052052, 30607451, 30842190, 31026899, 31091588, 31152058, 31259259, 3174456, 31812356, 31990484, 32308078, 32575524, 32806013, 32888185, 32975992, 329764, 33028965, 33145, 33234406, 33467233, 33608611, 33621746, 33842945, 33845031, 34192209, 34422962, 346308, 34669967, 34725219, 35098811, 35232820, 35395549, 35751661, 35839649, 35968872, 36043475, 36056848, 36148677, 36172507, 36269730, 36418353, 36869707, 36874176, 36878010, 37110517, 37755355, 37777109, 37896519, 38123398, 38788892, 39000530, 39042396, 39133416, 39177836, 39276444, 39368978, 39795743, 39915221, 39934507, 39999417, 40006740, 40234724, 40234806, 40244911, 40249159, 40275445, 40306036, 40387352, 4045206, 40509413, 40571816, 40581682, 40820929, 40862738, 40917049, 41091682, 41195652, 41248025, 41285927, 41354242, 41369960, 4150578, 41625374, 41670580, 41906421, 42207223, 42244930, 42297480, 42681389, 42788136, 43113873, 43475265, 43602427, 43687949, 43699801, 43768634, 43783383, 44230401, 44318843, 44402255, 44428614, 44433021, 44487672, 44753929, 44786610, 44846, 44882230, 44967271, 45029904, 45266726, 45416752, 45433808, 45462894, 45495555, 45521654, 45552802, 45572306, 4564448, 45739042, 45801052, 45929875, 45960494, 45981649, 45991369, 46067550, 46081742, 46115515, 46242311, 4626582, 46290774, 46488868, 46710697, 46717923, 46967642, 47012757, 47103691, 47285530, 47313424, 47397133, 47404959, 47519242, 47546009, 47641100, 47684007, 47733567, 47773670, 47776394, 47845483, 47851454, 47945897, 48144448, 48150152, 48153652, 48212644, 48254667, 48302818, 48325869, 48494857, 48618112, 48649018, 48675950, 4871659, 48747569, 48866919, 48902430, 48914397, 48984474, 49068582, 49124328, 49126888, 49174942, 49214, 49294195, 49386579, 49416358, 49554480, 49566734, 49592795, 49719784, 49850249, 49911012, 49979660, 50022150, 50075699, 50141202, 50197585, 50206322, 50239623, 502540, 50267773, 50301655, 50324240, 50329040, 50393845, 50404545, 50479220, 50575939, 50584560, 50599377, 50796328, 51142406, 51254819, 51812881, 51899051, 52195809, 52371925, 52706, 52750217, 52864486, 531277, 53147371, 54034842, 54513127, 5661201, 6196463, 643450, 6457542, 664832, 6959733, 7099464, 769695, 8240947, 86163, 910180, 9149531, 9203640, 9218543, 937895, 94080) group by gemm_mentor_id order by count(*) desc limit 50; +----------------+----------+ | gemm_mentor_id | count(*) | +----------------+----------+ | 20842734 | 65500 | | 31015329 | 61088 | | 39166130 | 56048 | | 39886606 | 46425 | | 31984018 | 44983 | | 17340450 | 42234 | | 10044298 | 41024 | | 35040268 | 40077 | | 31051948 | 37137 | | 20355744 | 32290 | | 36979282 | 29622 | | 26021257 | 27447 | | 32 | 27186 | | 40205634 | 23577 | | 34677551 | 22551 | | 758130 | 22291 | | 29826975 | 21903 | | 35605780 | 19757 | | 43282988 | 19489 | | 37507540 | 17289 | | 23734011 | 15694 | | 35522111 | 15672 | | 30395827 | 15574 | | 37670553 | 15006 | | 44475625 | 14432 | | 27810432 | 14185 | | 35287515 | 12285 | | 32082182 | 11566 | | 34294366 | 10316 | | 35786750 | 9337 | | 30928816 | 9258 | | 35989210 | 8739 | | 42437146 | 8331 | | 33049997 | 8100 | | 43729757 | 7988 | | 34192994 | 7786 | | 42768779 | 7756 | | 31489042 | 7468 | | 40174072 | 7389 | | 41857613 | 7388 | | 29434718 | 6755 | | 44204299 | 6335 | | 45329123 | 6267 | | 39456488 | 6162 | | 44058392 | 6017 | | 44662595 | 5489 | | 28920063 | 5296 | | 34350642 | 5237 | | 30052055 | 4738 | | 22986354 | 4738 | +----------------+----------+ 50 rows in set (0.571 sec) mysql:research@dbstore1009.eqiad.wmnet [enwiki]> ^DBye [urbanecm@stat1008 ~]$
This one:
mysql:research@dbstore1008.eqiad.wmnet [enwiki]> select * from actor where actor_user=30052055; +----------+------------+------------+ | actor_id | actor_user | actor_name | +----------+------------+------------+ | 31150885 | 30052055 | Ikan | +----------+------------+------------+ 1 row in set (0.002 sec) mysql:research@dbstore1008.eqiad.wmnet [enwiki]>
sounds like a good trial candidate. I verified they were indeed removed, and their number of mentees is ~2 batches, so we should observe one lock exchange. Let's see what happens.
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-09-29T09:36:01Z] <urbanecm@deploy1003> mwscript-k8s job started: GrowthExperiments:reassignMentees --wiki=enwiki --mentor=Ikan --performer=Ikan --as-job # T418194
Comment Actions
It has finished:
[urbanecm@mwlog1003 ~]$ zgrep 30052055 /srv/mw-log/archive/JobExecutor.log-2026092909.gz > jobs-reassign-04.log
[urbanecm@mwlog1003 ~]$ grep reassignMenteesJob jobs-reassign-04.log
2026-09-29 09:37:02.018353 [bc91240f395027f1cc00c71b] mw-jobrunner.eqiad.main-669cbcd4c-l72hf enwiki 1.47.0-wmf.21 JobExecutor DEBUG: Beginning job execution {"job":"reassignMenteesJob Special: mentorId=30052055 performerId=30052055 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Ikan\"] jobReleaseTimestamp=1790674622 requestId=bc91240f395027f1cc00c71b","job_type":"reassignMenteesJob"}
2026-09-29 09:43:02.030138 [bc91240f395027f1cc00c71b] mw-jobrunner.eqiad.main-669cbcd4c-hjwgw enwiki 1.47.0-wmf.21 JobExecutor DEBUG: Beginning job execution {"job":"reassignMenteesJob Special: mentorId=30052055 performerId=30052055 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Ikan\"] jobReleaseTimestamp=1790674622 requestId=bc91240f395027f1cc00c71b","job_type":"reassignMenteesJob"}
2026-09-29 09:43:02.045330 [bc91240f395027f1cc00c71b] mw-jobrunner.eqiad.main-669cbcd4c-hjwgw enwiki 1.47.0-wmf.21 JobExecutor INFO: Finished job execution {"job":"reassignMenteesJob Special: mentorId=30052055 performerId=30052055 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Ikan\"] jobReleaseTimestamp=1790674622 requestId=bc91240f395027f1cc00c71b","job_type":"reassignMenteesJob","job_status":true,"job_duration":0.01826000213623047,"context.job_type":"reassignMenteesJob"}
2026-09-29 09:46:48.823232 [bc91240f395027f1cc00c71b] mw-jobrunner.eqiad.main-669cbcd4c-5h58m enwiki 1.47.0-wmf.21 JobExecutor DEBUG: Beginning job execution {"job":"reassignMenteesJob Special: mentorId=30052055 performerId=30052055 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Ikan\"] jobReleaseTimestamp=1790675140 requestId=bc91240f395027f1cc00c71b","job_type":"reassignMenteesJob"}
2026-09-29 09:46:49.196414 [bc91240f395027f1cc00c71b] mw-jobrunner.eqiad.main-669cbcd4c-l72hf enwiki 1.47.0-wmf.21 JobExecutor INFO: Finished job execution {"job":"reassignMenteesJob Special: mentorId=30052055 performerId=30052055 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Ikan\"] jobReleaseTimestamp=1790674622 requestId=bc91240f395027f1cc00c71b","job_type":"reassignMenteesJob","job_status":true,"job_duration":587.1801431179047,"context.job_type":"reassignMenteesJob"}
2026-09-29 09:52:48.828749 [bc91240f395027f1cc00c71b] mw-jobrunner.eqiad.main-669cbcd4c-hjwgw enwiki 1.47.0-wmf.21 JobExecutor DEBUG: Beginning job execution {"job":"reassignMenteesJob Special: mentorId=30052055 performerId=30052055 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Ikan\"] jobReleaseTimestamp=1790675140 requestId=bc91240f395027f1cc00c71b","job_type":"reassignMenteesJob"}
2026-09-29 09:52:48.838031 [bc91240f395027f1cc00c71b] mw-jobrunner.eqiad.main-669cbcd4c-hjwgw enwiki 1.47.0-wmf.21 JobExecutor INFO: Finished job execution {"job":"reassignMenteesJob Special: mentorId=30052055 performerId=30052055 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Ikan\"] jobReleaseTimestamp=1790675140 requestId=bc91240f395027f1cc00c71b","job_type":"reassignMenteesJob","job_status":true,"job_duration":0.011375904083251953,"context.job_type":"reassignMenteesJob"}
2026-09-29 09:56:31.129097 [bc91240f395027f1cc00c71b] mw-jobrunner.eqiad.main-669cbcd4c-md8q9 enwiki 1.47.0-wmf.21 JobExecutor DEBUG: Beginning job execution {"job":"reassignMenteesJob Special: mentorId=30052055 performerId=30052055 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Ikan\"] jobReleaseTimestamp=1790675695 requestId=bc91240f395027f1cc00c71b","job_type":"reassignMenteesJob"}
2026-09-29 09:56:31.364393 [bc91240f395027f1cc00c71b] mw-jobrunner.eqiad.main-669cbcd4c-5h58m enwiki 1.47.0-wmf.21 JobExecutor INFO: Finished job execution {"job":"reassignMenteesJob Special: mentorId=30052055 performerId=30052055 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Ikan\"] jobReleaseTimestamp=1790675140 requestId=bc91240f395027f1cc00c71b","job_type":"reassignMenteesJob","job_status":true,"job_duration":582.5436809062958,"context.job_type":"reassignMenteesJob"}
2026-09-29 10:00:00.300052 [bc91240f395027f1cc00c71b] mw-jobrunner.eqiad.main-669cbcd4c-md8q9 enwiki 1.47.0-wmf.21 JobExecutor INFO: Finished job execution {"job":"reassignMenteesJob Special: mentorId=30052055 performerId=30052055 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Ikan\"] jobReleaseTimestamp=1790675695 requestId=bc91240f395027f1cc00c71b","job_type":"reassignMenteesJob","job_status":true,"job_duration":209.1732840538025,"context.job_type":"reassignMenteesJob"}
[urbanecm@mwlog1003 ~]$But I still see empty jobs that I do not expect... Scheduling still shows two batches:
{P96537}
Weird.
Comment Actions
Change #1345986 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[mediawiki/extensions/GrowthExperiments@wmf/1.47.0-wmf.21] ReassignMentees: Make the jobReleaseTimestamp work
Comment Actions
Change #1345986 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@wmf/1.47.0-wmf.21] ReassignMentees: Make the jobReleaseTimestamp work
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-09-29T12:40:06Z] <urbanecm@deploy1003> Started scap sync-world: Backport for [[gerrit:1345986|ReassignMentees: Make the jobReleaseTimestamp work (T418194)]]
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-09-29T12:44:16Z] <urbanecm@deploy1003> urbanecm: Backport for [[gerrit:1345986|ReassignMentees: Make the jobReleaseTimestamp work (T418194)]] synced to the testservers (see https://wikitech.wikimedia.org/wiki/Mwdebug). Changes can now be verified there.
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-09-29T12:52:33Z] <urbanecm@deploy1003> Finished scap sync-world: Backport for [[gerrit:1345986|ReassignMentees: Make the jobReleaseTimestamp work (T418194)]] (duration: 12m 26s)
Comment Actions
For my own self, I converted the logs into a timeline:
The bolded strings represent the k8s worker this has run in. empty denotes a job that didn't actually do something (run into an already consumed lock and terminate immediately).
I'm really confused by the fact MediaWiki is executing the job more often than it is scheduled.
What I think is happening is this:
- MediaWiki schedules reassignMenteesJob, changeprop sends it to a job runner
- Job runner starts processing, giving MediaWiki up to 1200s to process it ($wgRequestTimeLimit is set to 1200 when on a job runner)
- Until MediaWiki finishes with the job, it keeps the HTTP request opened.
- At some point (by my measurements, 300 seconds), envoy loses patience with the request and returns a 504
- For some reason, MediaWiki continues running, so the job finishes
- Changeprop sees the 504, deems that to be a failure and schedules the job again
- MediaWiki jobrunner picks it up, sees a lock was claimed already and terminates nearly immediately. We treat "lock unavailable" as a success, so ChangeProp is satisfied and it doesn't try to schedule it again.
This seems to be supported by Changeprop's own logs (Logstash), which do have a stream timeout:
error_body_str: Original error: stream timeout "internalURI":"https://mw-jobrunner.discovery.wmnet:4448/rpc/RunSingleJob.php"
Comment Actions
This is several bugs combined into one:
- Changeprop is rescheduling a job that didn't error out: There seems to be inconsistent timeout (changeprop only waits 300 seconds to hear from MediaWiki, but jobs can run 1200 seconds; T418194#12374194 has details). Filled T439577: changeprop timeouts are not configured consistently for this problem.
- MediaWiki computes execution timestamp at wrong time: MediaWiki was computing the release timestamp for the job before it was actually scheduling the job, resulting in the two jobs (l72hf, 5h58m) to overlap each other (and 5h58m, md8q9 are touching each other nearly precisely). This should be fixed by https://gerrit.wikimedia.org/r/c/mediawiki/extensions/GrowthExperiments/+/1344323 (already backported, will test again).
- MediaWiki is scheduling notification jobs within a job: For some reason, Notifications (Echo) always schedules notifications in a job, even when a job itself runs Event::create() (this is the difference between "decision to schedule" and "actually sending the job to kafka", which is partly why point 2 is an actual problem). This should probably have a separate Notifications (Echo) task, and Notifications (Echo) should just send the notification straight away when possible.
- Transaction is suspiciously large: each job works within one transaction only, so we run transactions that affect ~2000 users at once; maybe we should have multiple smaller transactions instead? or just lower the batch size? Filled as T439580: reassignMenteeJob triggers fairly large transactions.
Comment Actions
Let's try another user:
mysql:research@dbstore1009.eqiad.wmnet [enwiki]> select count(*) from growthexperiments_mentor_mentee where gemm_mentor_role='primary' and gemm_mentor_id=34350642; +----------+ | count(*) | +----------+ | 5237 | +----------+ 1 row in set (0.009 sec) mysql:research@dbstore1009.eqiad.wmnet [enwiki]> mysql:research@dbstore1008.eqiad.wmnet [enwiki]> select * from actor where actor_user=34350642; +----------+------------+-------------+ | actor_id | actor_user | actor_name | +----------+------------+-------------+ | 259732 | 34350642 | Blacephalon | +----------+------------+-------------+ 1 row in set (0.002 sec) mysql:research@dbstore1008.eqiad.wmnet [enwiki]>
Expected behaviour: Jobs are scheduled with ~1 minute gap between them. There are going to be empty jobs 300 seconds after each one, because of T439577. With batch size of 2000, I expect 3 actual jobs and 3 "blank ones.
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2026-09-29T16:19:58Z] <urbanecm@deploy1003> mwscript-k8s job started: GrowthExperiments:reassignMentees --wiki=enwiki --mentor=Blacephalon --performer=Blacephalon --as-job # T418194
Comment Actions
Voilá:
2026-09-29 16:51:05.941012 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.main-58bb4854f5-2ld2c enwiki 1.47.0-wmf.21 GrowthExperiments INFO: ReassignMenteesJob finished reassignment for Blacephalon with true status {"status":"true","mentor":"Blacephalon","context.job_type":"reassignMenteesJob"}Job executor logs:
2026-09-29 16:20:59.022352 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.main-58bb4854f5-kn484 enwiki 1.47.0-wmf.21 JobExecutor DEBUG: Beginning job execution {"job":"reassignMenteesJob Special: mentorId=34350642 performerId=34350642 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Blacephalon\"] jobReleaseTimestamp=1790698859 requestId=47965e32cf7e7fecd58e355d","job_type":"reassignMenteesJob"}
2026-09-29 16:26:59.040965 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.main-58bb4854f5-p7rnj enwiki 1.47.0-wmf.21 JobExecutor DEBUG: Beginning job execution {"job":"reassignMenteesJob Special: mentorId=34350642 performerId=34350642 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Blacephalon\"] jobReleaseTimestamp=1790698859 requestId=47965e32cf7e7fecd58e355d","job_type":"reassignMenteesJob"}
2026-09-29 16:26:59.056356 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.main-58bb4854f5-p7rnj enwiki 1.47.0-wmf.21 JobExecutor INFO: Finished job execution {"job":"reassignMenteesJob Special: mentorId=34350642 performerId=34350642 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Blacephalon\"] jobReleaseTimestamp=1790698859 requestId=47965e32cf7e7fecd58e355d","job_type":"reassignMenteesJob","job_status":true,"job_duration":0.020840883255004883,"context.job_type":"reassignMenteesJob"}
2026-09-29 16:32:28.487170 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.main-58bb4854f5-kn484 enwiki 1.47.0-wmf.21 JobExecutor INFO: Finished job execution {"job":"reassignMenteesJob Special: mentorId=34350642 performerId=34350642 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Blacephalon\"] jobReleaseTimestamp=1790698859 requestId=47965e32cf7e7fecd58e355d","job_type":"reassignMenteesJob","job_status":true,"job_duration":689.4677200317383,"context.job_type":"reassignMenteesJob"}
2026-09-29 16:33:28.026749 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.canary-7947d69f4b-xq8fn enwiki 1.47.0-wmf.21 JobExecutor DEBUG: Beginning job execution {"job":"reassignMenteesJob Special: mentorId=34350642 performerId=34350642 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Blacephalon\"] jobReleaseTimestamp=1790699608 requestId=47965e32cf7e7fecd58e355d","job_type":"reassignMenteesJob"}
2026-09-29 16:39:28.022727 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.main-58bb4854f5-9bmjn enwiki 1.47.0-wmf.21 JobExecutor DEBUG: Beginning job execution {"job":"reassignMenteesJob Special: mentorId=34350642 performerId=34350642 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Blacephalon\"] jobReleaseTimestamp=1790699608 requestId=47965e32cf7e7fecd58e355d","job_type":"reassignMenteesJob"}
2026-09-29 16:39:28.028781 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.main-58bb4854f5-9bmjn enwiki 1.47.0-wmf.21 JobExecutor INFO: Finished job execution {"job":"reassignMenteesJob Special: mentorId=34350642 performerId=34350642 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Blacephalon\"] jobReleaseTimestamp=1790699608 requestId=47965e32cf7e7fecd58e355d","job_type":"reassignMenteesJob","job_status":true,"job_duration":0.008222103118896484,"context.job_type":"reassignMenteesJob"}
2026-09-29 16:46:20.911308 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.canary-7947d69f4b-xq8fn enwiki 1.47.0-wmf.21 JobExecutor INFO: Finished job execution {"job":"reassignMenteesJob Special: mentorId=34350642 performerId=34350642 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Blacephalon\"] jobReleaseTimestamp=1790699608 requestId=47965e32cf7e7fecd58e355d","job_type":"reassignMenteesJob","job_status":true,"job_duration":772.8888170719147,"context.job_type":"reassignMenteesJob"}
2026-09-29 16:47:20.018319 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.main-58bb4854f5-2ld2c enwiki 1.47.0-wmf.21 JobExecutor DEBUG: Beginning job execution {"job":"reassignMenteesJob Special: mentorId=34350642 performerId=34350642 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Blacephalon\"] jobReleaseTimestamp=1790700440 requestId=47965e32cf7e7fecd58e355d","job_type":"reassignMenteesJob"}
2026-09-29 16:52:04.371306 [47965e32cf7e7fecd58e355d] mw-jobrunner.eqiad.main-58bb4854f5-2ld2c enwiki 1.47.0-wmf.21 JobExecutor INFO: Finished job execution {"job":"reassignMenteesJob Special: mentorId=34350642 performerId=34350642 reassignMessageKey=growthexperiments-quit-mentorship-reassign-mentees-log-message reassignMessageAdditionalParams=[\"Blacephalon\"] jobReleaseTimestamp=1790700440 requestId=47965e32cf7e7fecd58e355d","job_type":"reassignMenteesJob","job_status":true,"job_duration":284.35536003112793,"context.job_type":"reassignMenteesJob"}3 workers (as expected), 2 blank jobs. I expected 3, but the last batch was <300 seconds, so it was not scheduled again.
Comment Actions
I call this fixed from an user facing perspective. The remaining few issues are tracked separately now.
Comment Actions
Pending mystery: Part of this issue is that enotifNotify jobs are getting scheduled for every single user, pushing our own follow up job further than a minute, thus breaking the lock handoff system we use.
But...EchoUseJobQueue seems to be false? Despite that:
{P96538}
Why does this happen?
Comment Actions
Why does this happen?
Because enotifNotify isn't related to Echo at all. It is related to MediaWiki's watchlist (it sends a notification to the user when a page on their watchlist is changed). Our actions are marked as bot already, but RecentChangeNotifier::shouldSendNotification is using User::isBot(), which requires the user to be in the bot group. I'm wondering why is it not checking for rc_bot instead...
Comment Actions
I take this back. There is one lingering danger. What happens now is this:
- reassignMenteesJob acquires a lock
- reassignMenteesJob does the actual reassignment
- reassignMenteesJob releases the lock
- reassignMenteesJob::run finishes; this triggers a COMMIT (T439580 might result in some changes there)
- reassignMenteesJob works on deferred stuff (currently takes ~100 seconds [and sometimes more]; T439626 should save some time here)
- as the very last thing, reassignMenteesJob schedules its successor
If reassignMenteesJob gets killed, changeprop should restart it (T439577 breaks that rn). However, if the kill happens in step 2, the lock would still be held (for 2400s, as far as I can see). So, even if the retry was working, it wouldn't come at an appropriate time. I filled T439651: LockManager-maintained locks that were not released are kept past job retry window for this particular trouble.
Comment Actions
Summary
The reported symptom — a mentor quits and keeps their mentees — is not one bug but a chain of them. reassignMenteesJob processes one batch and reschedules itself; anything that stops the chain leaves the remaining mentees behind silently, because the job reports success in every one of those cases.
What we found, in the order it bites:
- Deduplication was silently off. Since the switch to JobSpecification (change 1077707, Oct 2024), ignoreDuplicates() and getDeduplicationInfo() on the job were never consulted, so every hop could be produced more than once (T418194#12354607). Fixed as T438980 / change 1344308, backported to 1.47.0-wmf.21.
- jobReleaseTimestamp was computed before the job was actually pushed, so consecutive hops overlapped instead of being spaced a minute apart (T418194#12374545, point 2). Fixed by change 1344323, backported to 1.47.0-wmf.21.
- Jobs execute more often than they are scheduled. envoy's default 300s stream idle timeout cuts the RunSingleJob.php request; changeprop reads the 504 as a failure and retries. MediaWiki keeps going (ignore_user_abort( true ) in WebStart.php), so the batch still completes, and the retry finds the lock taken and exits in ~10 ms. Every batch longer than 300s gets exactly one such "empty" execution; a 209s batch got none (T418194#12374194, T418194#12375796). Tracked as T439577.
- A failed lock ends the chain permanently. ReassignMentees::doReassignMentees() takes scopedLock() with timeout = 0, returns false, and ReassignMenteesJob::run() then returns true without rescheduling — no error, no retry, and nothing anywhere reconciles mentee rows pointing at a non-mentor (T418194#11644161). Tracked as T439652, with T439651 for the lock outliving changeprop's retry window.
- Reassignment takes ~0.3–0.5s per mentee, because getRandomAutoAssignedMentor() walks the entire mentor list for every single mentee (T418194#11658435). Tracked as T439638.
- The post-run deferred drain costs ~100s per batch. Tracked as T439626 and T439580.
Verification
Two real quits on enwiki on 2026-09-29, with 1 and 2 deployed:
- Ikan (4738 mentees): 3 real hops (587s, 583s, 209s) plus 2 empty retries; all mentees reassigned.
- Blacephalon (5237 mentees): 3 real hops (689s, 773s, 284s) plus 2 empty retries, ending in finished reassignment for Blacephalon with true status (T418194#12375796).
In both runs the final batch was under 300s and got no retry, which is what the explanation in point 3 predicts.
From a user-facing perspective, quitting mentorship now reassigns all mentees. T439651: LockManager-maintained locks that were not released are kept past job retry window has a chance of bringing this issue again at a moment's notice.
Follow-ups
- T438980 — Resolved and deployed in 1.47.0-wmf.21; it restored job deduplication, without which every hop of the chain can be produced twice.
- T439577 (ServiceOps; already a subtask here) — Open; until envoy's idle timeout matches $wgRequestTimeLimit, long jobs are retried spuriously and, worse, a genuine failure after the first 300s is invisible to changeprop, so no retry happens at all.
- T439651 (JobQueue) — Open; a lock held by a killed job survives for 2× the wall-time limit (2400s on jobrunners), which is long past changeprop's last retry at +360s, so the retry can never succeed.
- T439652 (Growth) — Open; treating "lock unavailable" as success is only safe if the lock holder is really still alive, which T439651 shows is not guaranteed.
- T439638 (Growth; 4 patches in review) — Open; at ~0.5s/mentee a 2000-mentee batch runs ~600s, which is exactly what puts us over the 300s cut and forced the batch size down from 5000.
- T439626 (Echo; change 1346133) — Open; enqueueDeleteJob() uses push(), i.e. one blocking eventgate POST per notification, which is a large part of the ~100s drain that delays the next hop.
- T439580 (DBA) — Open; one transaction covering ~2000 ChangeMentor::execute() calls is large enough to deserve a DBA opinion, and smaller transactions would also make progress observable before the batch ends.
- T409171 (Growth) — Open, moved to the maintenance backlog; the away-status migration is only half done, which is the caveat blocking the cleanest version of T439638.
Comment Actions
@Sdkb This is basically done (as in, new resignations/removals should work as intended); more details are available in the summary above. If you see an issue in resignations/removals not being cleaned up fully, please do let me know.
However, we still have a lot of users formally assigned to non-mentors (more than a million of those on enwiki). In my opinion, this task shouldn't track the cleanup. This is tracked in T330071: Mentorship: ensure that all mentees are assigned to an active mentor, which is stalled on two remaining improvements. CC @KStoller-WMF for awareness.
With this, I'm moving to QA. It's been a very exploratory task (mostly because the root cause was hiding so well), and I believe all followup work is tracked in various other tasks.
Comment Actions
@Sdkb This is basically done (as in, new resignations/removals should work as intended); more details are available in the summary above. If you see an issue in resignations/removals not being cleaned up fully, please do let me know.
Nice report. On the strength of this, I'll propose that we mark this as resolved and let Samuel let us know if there's any regressions and will file a follow up based on any issues found.
Comment Actions
Checked on enwiki beta - works as expected
- a mentor (who has assigned mentees) quits
- immediately the following query returns 0 assigned mentees:
{
"batchcomplete": true,
"growthmentormentee": {
"mentor": "ET45",
"mentees": []
}
}- testing on testwiki wmf.22 was not possible due to T439782: [testwiki wmf.22] Special:QuitMentorship displays "Incorrect or missing CAPTCHA" preventing a mentor quit the issue seems unrelated to the scope of this task.