Page MenuHomePhabricator

Fatal exception of type "CannotCreateActorException" when trying to export file from zhwikibooks to commons
Closed, ResolvedPublic2 Estimated Story PointsPRODUCTION ERROR

Description

Error
normalized_message
[190d11a6-e4a3-46de-9770-ba6db85cbefc] 2022-05-18 17:03:23: Fatal exception of type "CannotCreateActorException"
exception.trace
from /srv/mediawiki/php-1.39.0-wmf.12/includes/user/ActorStore.php(631)
#0 /srv/mediawiki/php-1.39.0-wmf.12/includes/user/ActorStore.php(401): MediaWiki\User\ActorStore->validateActorForInsertion(MediaWiki\User\UserIdentityValue)
#1 /srv/mediawiki/php-1.39.0-wmf.12/includes/logging/ManualLogEntry.php(291): MediaWiki\User\ActorStore->acquireActorId(MediaWiki\User\UserIdentityValue, Wikimedia\Rdbms\DBConnRef)
#2 /srv/mediawiki/php-1.39.0-wmf.12/extensions/FileImporter/src/Operations/FileRevisionFromRemoteUrl.php(254): ManualLogEntry->insert()
#3 /srv/mediawiki/php-1.39.0-wmf.12/extensions/FileImporter/src/Operations/FileRevisionFromRemoteUrl.php(228): FileImporter\Operations\FileRevisionFromRemoteUrl->createUploadLog()
#4 /srv/mediawiki/php-1.39.0-wmf.12/extensions/FileImporter/src/Data/ImportOperations.php(133): FileImporter\Operations\FileRevisionFromRemoteUrl->commit()
#5 /srv/mediawiki/php-1.39.0-wmf.12/extensions/FileImporter/src/Data/ImportOperations.php(82): FileImporter\Data\ImportOperations::FileImporter\Data\{closure}(FileImporter\Operations\FileRevisionFromRemoteUrl)
#6 /srv/mediawiki/php-1.39.0-wmf.12/extensions/FileImporter/src/Data/ImportOperations.php(134): FileImporter\Data\ImportOperations->runOperations(integer, integer, boolean, Closure)
#7 /srv/mediawiki/php-1.39.0-wmf.12/extensions/FileImporter/src/Services/Importer.php(324): FileImporter\Data\ImportOperations->commit()
#8 /srv/mediawiki/php-1.39.0-wmf.12/extensions/FileImporter/src/Services/Importer.php(186): FileImporter\Services\Importer->commitImportOperations(FileImporter\Data\ImportOperations)
#9 /srv/mediawiki/php-1.39.0-wmf.12/extensions/FileImporter/src/SpecialImportFile.php(355): FileImporter\Services\Importer->import(User, FileImporter\Data\ImportPlan)
#10 /srv/mediawiki/php-1.39.0-wmf.12/extensions/FileImporter/src/SpecialImportFile.php(256): FileImporter\SpecialImportFile->doImport(FileImporter\Data\ImportPlan)
#11 /srv/mediawiki/php-1.39.0-wmf.12/extensions/FileImporter/src/SpecialImportFile.php(222): FileImporter\SpecialImportFile->handleAction(string, FileImporter\Data\ImportPlan)
#12 /srv/mediawiki/php-1.39.0-wmf.12/includes/specialpage/SpecialPage.php(688): FileImporter\SpecialImportFile->execute(NULL)
#13 /srv/mediawiki/php-1.39.0-wmf.12/includes/specialpage/SpecialPageFactory.php(1415): SpecialPage->run(NULL)
#14 /srv/mediawiki/php-1.39.0-wmf.12/includes/MediaWiki.php(316): MediaWiki\SpecialPage\SpecialPageFactory->executePath(string, RequestContext)
#15 /srv/mediawiki/php-1.39.0-wmf.12/includes/MediaWiki.php(912): MediaWiki->performRequest()
#16 /srv/mediawiki/php-1.39.0-wmf.12/includes/MediaWiki.php(566): MediaWiki->main()
#17 /srv/mediawiki/php-1.39.0-wmf.12/index.php(50): MediaWiki->run()
#18 /srv/mediawiki/php-1.39.0-wmf.12/index.php(46): wfIndexMain()
#19 /srv/mediawiki/w/index.php(3): require(string)
#20 {main}
Impact

Seen 32 times until 8:30 UTC on May 19, with the first one appearing 24 hours before at 9:23 UTC on May 18.
The exceptions are for various user names

Notes

Happened when trying to export File:Wiki.png on zhwikibooks to Wikimedia Commons (with new file name "Wikibooks-logo-zh-hans-old").

Event Timeline

Ladsgroup triaged this task as Unbreak Now! priority.May 18 2022, 7:39 PM
Ladsgroup subscribed.

Train blocker = UBN!

+ @thiemowmde who has proposed the change to FileImporter

Note there is also a MediaWiki core change which soft deprecate WikiRevision::getUserObj (https://gerrit.wikimedia.org/r/c/mediawiki/core/+/785800) and depends on that FileImporter change.

The message emitted by commons states:

Cannot create an actor for a usable name that is not an existing user: user_name="Gzdavidwong"

Which is the last user to have touched the file on Wikibooks: https://zh.wikibooks.org/wiki/File:Wiki.png . It is definitely existing based on https://meta.wikimedia.org/wiki/Special:CentralAuth/Gzdavidwong

Side track \MediaWiki\User\UserNameUtils::isUsable() has been changed by https://gerrit.wikimedia.org/r/c/mediawiki/core/+/786345 but that got deployed by wmf.10 and it merely replace a string by a constant.

My first suspicion was that this would happen for users that do not yet have a local account on Commons, or lacking an entry in the actor table. But that is not the case. For instance, Ivasykus has been contribution to commons since 2010, and both the user table and the actor table show comparitively low IDs associated with that name. So why does MW think that the user doesn't exist?

Change 793156 had a related patch set uploaded (by Thiemo Kreuz (WMDE); author: Thiemo Kreuz (WMDE)):

[mediawiki/extensions/FileImporter@master] Revert "Fix bogus user object creation in WikiRevisionFactory"

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

Change 793157 had a related patch set uploaded (by Thiemo Kreuz (WMDE); author: Thiemo Kreuz (WMDE)):

[mediawiki/extensions/FileImporter@wmf/1.39.0-wmf.12] Revert "Fix bogus user object creation in WikiRevisionFactory"

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

I found a patch that touches related code, though it's not immediately clear how it would cause the problem: https://gerrit.wikimedia.org/r/c/mediawiki/core/+/785800

There are a couple of lines inFileRevisionFromRemoteUrl::createUpdateLog that I find suspicious:

		$performer = $this->wikiRevision->getUserObj() ?:
			new UserIdentityValue( 0, $this->wikiRevision->getUser() );

This will create a UserIdentityValue with user ID 0 and a usable user name. Which is what the exception is complaining about. However, this code is not new. I don't understand how it is supposed to work, or why it did work, but it seems dubious.

The situation is conceptually dubious, though: the user name comes from a WikiRevision, which is a representation of a revision for import - the user name from a WikiRevision is not guaranted to be meaningful in the context of the local wiki. We could use User::newFromName to get a local user with the given name, but only if we know that we are importing from a wiki that is guaranteed to have the same user names we have locally (because it's using CentralAuth or shared tables).

There are a couple of lines inFileRevisionFromRemoteUrl::createUpdateLog that I find suspicious:

The old code (before rEFLI4737eb172002: Fix bogus user object creation in WikiRevisionFactory) created a User object via newFromName. When the getId was called on that object, it triggered auto-loading and returned the correct user ID. The new code, as you point out, creates a UserIdentityValue with ID 0 - in essence it tells ActorStore that this user doesn't exist.

I think the bug would still have been triggered by the old code when importing a revision where the user did not exist locally, that's just probably rare.

The situation is conceptually dubious, though: the user name comes from a WikiRevision, which is a representation of a revision for import - the user name from a WikiRevision is not guaranted to be meaningful in the context of the local wiki. We could use User::newFromName to get a local user with the given name, but only if we know that we are importing from a wiki that is guaranteed to have the same user names we have locally (because it's using CentralAuth or shared tables).

There are two conceptually correct options here, I think:

  • use a foreign user such as zhwiki>Gzdavidwong
  • assume that the authentication system matches usernames between wikis, so if the user exists locally and is attached, use it, if the user does not exist locally, autocreate it. If the user exists locally, but is not attached, fall back to the previous option.

Change 793415 had a related patch set uploaded (by Thiemo Kreuz (WMDE); author: Thiemo Kreuz (WMDE)):

[mediawiki/extensions/FileImporter@master] Fix incomplete user creation when importing archive log entries

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

Change 793156 abandoned by Thiemo Kreuz (WMDE):

[mediawiki/extensions/FileImporter@master] Revert "Fix bogus user object creation in WikiRevisionFactory"

Reason:

I684f28b is a better fix for master.

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

thiemowmde set the point value for this task to 2.

Sorry for the inconvenience. I suggest to fix the wmf.12 branch with a straight revert: https://gerrit.wikimedia.org/r/793157. For master I came up with a more appropriate fix, including a long explanation of what's going on: https://gerrit.wikimedia.org/r/793415.

This will create a UserIdentityValue with user ID 0 and a usable user name. Which is what the exception is complaining about. However, this code is not new.

Indeed. This is because that bogus new UserIdentityValue( 0, … ) was effectively dead code before https://gerrit.wikimedia.org/r/785812.

the user name from a WikiRevision is not guaranted to be meaningful in the context of the local wiki.

Usually yes, but because of the way things are wired here we have this guarantee. More details in https://gerrit.wikimedia.org/r/793415.

I think the bug would still have been triggered by the old code when importing a revision where the user did not exist locally

In that case the username is already prefixed with the wiki id the moment it reaches this code.

Thank you Tiemo! Given @Tgr looked at https://gerrit.wikimedia.org/r/c/mediawiki/extensions/FileImporter/+/793415 and that WMDE people are in a meeting this afternoon, I settle on deploying the change you have proposed. The worse case scenario is that FileImporter is as broken as it is currently.

We are going to deploy it.

Change 793157 merged by jenkins-bot:

[mediawiki/extensions/FileImporter@wmf/1.39.0-wmf.12] Revert "Fix bogus user object creation in WikiRevisionFactory"

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

Mentioned in SAL (#wikimedia-operations) [2022-05-19T13:21:51Z] <jnuche@deploy1002> Synchronized php-1.39.0-wmf.12/extensions/FileImporter/src/Services/WikiRevisionFactory.php: Backport: [[gerrit:793157|Revert "Fix bogus user object creation in WikiRevisionFactory" (T308691)]] (duration: 00m 53s)

jnuche claimed this task.

hi @Stang, we believe we have fixed the issue. Please let us know in case you can still see it

Apologize but there seems still exist some issue when importing file mentioned in description...

image.png (306×708 px, 18 KB)

Maybe this is a cache issue that file already imported to commons, but Fileimporter failed to find this...? Anyway I could not reproduce that now, should we delete that file on commons and import again for testing (ideally all revisions should be imported)

Looking at log for channel:FileImporter i see message:

Getting ImportPlan for URL: https://zh.wikibooks.org/wiki/File:Wiki.png
Calculated two-hop interwiki prefix b:zh to zh.wikibooks.org
ImportException: This page has been protected to prevent editing or other actions.

And

Getting ImportPlan for URL: https://zh.wikibooks.org/wiki/File:Wiki.png
Calculated two-hop interwiki prefix b:zh to zh.wikibooks.org
ImportException: File already on wiki

Why does it generates two different errors, I have no idea. Looks like the error message shown back to the user should be a bit more detailed than "Failed to commit operations".

And for the failed to commit message I believe it is:

| May 19, 2022 @ 13:26:58.182 | FileImporter | mw1369 | commonswiki | FileImporter\Services\Importer::commitImportOperationsFailed to commit operations.
| May 19, 2022 @ 13:26:58.168 | FileImporter | mw1369 | commonswiki | FileImporter\Operations\FileRevisionFromRemoteUrl::commit failed to commit.
| May 19, 2022 @ 13:26:53.640 | FileImporter | mw1369 | commonswiki | Performing submit on ImportPlan for URL: https://zh.wikibooks.org/wiki/File:Wiki.png
| May 19, 2022 @ 13:26:53.640 | FileImporter | mw1369 | commonswiki | FileImporter\Services\Importer::import started
| May 19, 2022 @ 13:26:53.122 | FileImporter | mw1369 | commonswiki | Calculated two-hop interwiki prefix b:zh to zh.wikibooks.org
| May 19, 2022 @ 13:26:52.780 | FileImporter | mw1369 | commonswiki | Getting ImportPlan for URL: https://zh.wikibooks.org/wiki/File:Wiki.png

With reqId edf2492d-d0f3-4ea9-8d12-d776b05b9dde

I can't see any specific detail though

As far as I can tell these error situations are all handled as they should and are unrelated to this ticket.

Thank you so much @thiemowmde for your assistance and to have taken some extra time to explain the last log messages I have posted. Follow up T308753 is an excellent idea to improve the user reporting, it kind of confused us since there is no message logged on the backend at error level so I was a bit clueless as to where the error was. Turns out it is "normal" behavior and does not deserve a backend error log ;)

Change 793785 had a related patch set uploaded (by Thiemo Kreuz (WMDE); author: Thiemo Kreuz (WMDE)):

[mediawiki/extensions/FileImporter@master] Inject UserIdentityLookup as a dependency

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

thiemowmde claimed this task.
thiemowmde lowered the priority of this task from Unbreak Now! to High.

Change 793415 merged by jenkins-bot:

[mediawiki/extensions/FileImporter@master] Fix incomplete user creation when importing archive log entries

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

Change 793785 merged by jenkins-bot:

[mediawiki/extensions/FileImporter@master] Inject UserIdentityLookup as a dependency

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

Is this now Resolved, or should it block the train deployment to group0 in a few hours' time?