Page MenuHomePhabricator

reviewer-bot sometimes not working
Closed, ResolvedPublic

Description

Event Timeline

https://www.mediawiki.org/wiki/Git/Reviewers says "Please send me a talk page message or e-mail if the bot is malfunctioning." and links to https://github.com/valhallasw/gerrit-reviewer-bot/issues instead of Wikimedia Phabricator...

I cannot find any reference to this changeset in the bot logs. This suggests the changeset never showed up on the mediawiki-commits mailing list (which is odd), the email was filtered out as spam (again, unclear why that would happen), or the email was ignored by the bot (but there's nothing in the log to suggest this -- skipped emails are also logged).

fwiw, this is from the logs:

Tue May 7 21:15:12 UTC 2019: Running as task 2914886 @ tools-sgeexec-0901.tools.eqiad.wmflabs
4 e-mails to process (154 kB)
[MediaWiki-commits] [Gerrit] mediawiki/core[master]: Mass
        conversion to NamespaceInfo "jenkins-bot (Code Review)" <gerrit@wikimedia.org> I2fef157ceec772f304c0923a1cd8c0eef2e82a0f
skipping message (merged)
[MediaWiki-commits] [Gerrit] mediawiki...Echo[master]: Remove usage
        of deprecated database access code from Echo "jenkins-bot (Code Review)" <gerrit@wikimedia.org> Ib7cfe384f4104dbaeed5ba6659e81555eb810f97
skipping message (merged)
[MediaWiki-commits] [Gerrit] mediawiki...TorBlock[master]: Update
        type hint to parent class AbstractBlock "jenkins-bot (Code Review)" <gerrit@wikimedia.org> Id7dac1595d0a250052034eab57fc680b3b9a8fcd
skipping message (merged)
[MediaWiki-commits] [Gerrit] pywikibot/core[master]: Drop support
        for script_wui.py "Xqt (Code Review)" <gerrit@wikimedia.org> I1c51f246d352c12e664c304f7203c869f81a652d
(getting  70133f3554c99dc94cebcefba1d4d44ebff603d8 )

Processing changeset  I1c51f246d352c12e664c304f7203c869f81a652d Drop support for script_wui.py by Xqt
u scripts/README.rst
u setup.py
u docs/scripts/scripts.archive.rst
u docs/scripts/scripts.rst
u requirements.txt
u scripts/archive/script_wui.py
u tox.ini
u tests/script_tests.py
u pwb.py
gerrit set-reviewers --add 'John Vandenberg' --add D3r1ck01 'pywikibot%2Fcore~master~I1c51f246d352c12e664c304f7203c869f81a652d'
Done.

Tue May 7 21:25:12 UTC 2019: Running as task 2915177 @ tools-sgeexec-0926.tools.eqiad.wmflabs
0 e-mails to process (0 kB)
Done.

Tue May 7 21:35:12 UTC 2019: Running as task 2915467 @ tools-sgeexec-0940.tools.eqiad.wmflabs
1 e-mails to process (69 kB)
[MediaWiki-commits] [Gerrit] wikidata...rdf[master]: Propagate
        Projection from SubqueryNode to where clause "Igor Kim (Code Review)" <gerrit@wikimedia.org> I5c3a3bb8b5616c8e6ee397977b733af559c08500
(getting  75fa14fc23405524e466a2715c864b7a0e8c49ee )

Processing changeset  I5c3a3bb8b5616c8e6ee397977b733af559c08500 Propagate Projection from SubqueryNode to where clause by Igor Kim
[...]
gerrit set-reviewers --add Smalyshev 'wikidata%2Fquery%2Frdf~master~I5c3a3bb8b5616c8e6ee397977b733af559c08500'
Done.

I1c51f246d352c12e664c304f7203c869f81a652d is r508717; I5c3a3bb8b5616c8e6ee397977b733af559c08500 is r508725. This actually means quite a few changes were not processed:

There's another odd thing here. If we look at changeset 508721, GRB adds the reviewer at 21:30 UTC.

The bot start logs show the following:

Tue May 7 21:20:12 UTC 2019: Running as task 2915083 @ tools-sgeexec-0933.tools.eqiad.wmflabs
Tue May 7 21:25:12 UTC 2019: Running as task 2915177 @ tools-sgeexec-0926.tools.eqiad.wmflabs
Tue May 7 21:30:27 UTC 2019: Running as task 2915354 @ tools-sgeexec-0907.tools.eqiad.wmflabs
Tue May 7 21:35:12 UTC 2019: Running as task 2915467 @ tools-sgeexec-0940.tools.eqiad.wmflabs
Tue May 7 21:40:12 UTC 2019: Running as task 2915624 @ tools-sgeexec-0942.tools.eqiad.wmflabs

yet the bot run logs show the following:

Tue May 7 21:15:12 UTC 2019: Running as task 2914886 @ tools-sgeexec-0901.tools.eqiad.wmflabs
[...]
Tue May 7 21:25:12 UTC 2019: Running as task 2915177 @ tools-sgeexec-0926.tools.eqiad.wmflabs
[...]
Tue May 7 21:35:12 UTC 2019: Running as task 2915467 @ tools-sgeexec-0940.tools.eqiad.wmflabs

In other words, half the runs are not logging to the output file, or are somehow overwritten. This might be due to the automatic pruning of the output; I will disable the pruning for now.

@AndyRussG: could you keep an eye out for this happening again? Hopefully the logs will then be more informative.

Aklapper changed the task status from Open to Stalled.Nov 1 2019, 10:36 AM
Tgr changed the task status from Stalled to Open.Nov 19 2019, 2:07 AM
Tgr added a subscriber: Tgr.

Seems to be defunct most of the time these days. E.g. notifications for GrowthExperiments pretty consistently don't work, none of the core patches I checked work...

Thanks for spotting that -- I think something has changed in the API response used to get the reviewers:

{'created': '2019-11-02 00:39:20.000000000', 'updated': '2019-11-04 18:43:33.000000000', 'status': 'NEW', 'change_id': 'If252e32163b6d75826437ab3b5078ee7aefd401e', 'mergeable': True, 'submit_type': 'REBASE_IF_NECESSARY', 'insertions': 3, 'has_review_started': True, 'owner': {'username': 'jforrester', 'name': 'Jforrester', 'status': '🙄', 'email': 'jforrester@wikimedia.org', '_account_id': 366}, 'revisions': {'22fd4c8b40eedc356fd99dac92c0439432b68266': {'created': '2019-11-02 00:39:20.000000000', 'fetch': {'anonymous http': {'url': 'https://gerrit.wikimedia.org/r/integration/quibble', 'ref': 'refs/changes/43/547843/1'}}, '_number': 1, 'ref': 'refs/changes/43/547843/1', 'files': {'quibble/commands.py': {'size_delta': -17, 'size': 24665, 'lines_deleted': 1, 'lines_inserted': 1}, 'tests/test_commands.py': {'size_delta': -34, 'size': 12624, 'lines_deleted': 2, 'lines_inserted': 2}}, 'kind': 'REWORK', 'uploader': {'username': 'jforrester', 'name': 'Jforrester', 'status': '🙄', 'email': 'jforrester@wikimedia.org', '_account_id': 366}}}, 'hashtags': [], 'unresolved_comment_count': 0, 'current_revision': '22fd4c8b40eedc356fd99dac92c0439432b68266', 'id': 'integration%2Fquibble~master~If252e32163b6d75826437ab3b5078ee7aefd401e', 'project': 'integration/quibble', 'subject': 'phpunit: Drop --debug-tests command, killed off in PHPUnit 8', 'branch': 'master', 'deletions': 3, '_number': 547843}
 caused exception:Traceback (most recent call last):
  File "pop3bot.py", line 130, in 
    main()
  File "pop3bot.py", line 118, in main
    add_reviewers(changeset['id'], reviewers)
  File "/mnt/nfs/labstore-secondary-tools-project/gerrit-reviewer-bot/src/gerrit-reviewer-bot-stretch/add_reviewer.py", line 133, in add_reviewers
    reviewers = list(reviewers)
  File "/mnt/nfs/labstore-secondary-tools-project/gerrit-reviewer-bot/src/gerrit-reviewer-bot-stretch/add_reviewer.py", line 90, in _filter_reviewers
    for (reviewer, modulo) in reviewers:
  File "/mnt/nfs/labstore-secondary-tools-project/gerrit-reviewer-bot/src/gerrit-reviewer-bot-stretch/add_reviewer.py", line 67, in _reviewer_generator
    filere = re.compile(part.value.text or part.value.ext.inner.text, flags=re.DOTALL | re.IGNORECASE)
  File "src/lxml/objectify.pyx", line 231, in lxml.objectify.ObjectifiedElement.__getattr__
  File "src/lxml/objectify.pyx", line 451, in lxml.objectify._lookupChildOrRaise
AttributeError: no such child: ext

I don't think I can look into it today yet, but hopefully can tomorrow.

The bot is running again -- the issue was an empty file_regexp on the configuration page and the bot crashing because of that. I'll add some extra monitoring as well as checks for the config page over the coming week, but for now at least the bot is running again.

It is going to take a little while to get through the backlog; it's being processed at approx 200 changesets every 5 minutes. The backlog is likely a few thousand emails, although I don't know exactly how many (the gmail pop interface just reports 'several hundreds' and 'several megabytes')

hashar assigned this task to valhallasw.