Page MenuHomePhabricator
Create Task
Maniphest T214471

wdio browser tests fail locally due to session not being persisted before 2nd stage of login starts
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

Randomly yesterday (2019-01-19) after having successfully run the browser tests locally (using a mediawiki-docker-dev setup).

I'm running it like this: DISPLAY="" MEDIAWIKI_USER="Admin" MEDIAWIKI_PASSWORD="adminpass" MW_SERVER="http://default.web.mw.localhost:8080" MW_SCRIPT_PATH="/mediawiki" npm run selenium-test

Those that required login started failing sometimes with errors from MWBot reporting Could not login: NeedToken

The following is an example of the output.

There are also debug statements I added manually to the request part of mwbot (src/index.js#264).

DISPLAY="" MEDIAWIKI_USER="Admin" MEDIAWIKI_PASSWORD="adminpass" MW_SERVER="http://default.web.mw.localhost:8080" MW_SCRIPT_PATH="/mediawiki" npm run selenium-test

> @ selenium-test /home/tom/src/wikimedia/mediawiki
> wdio ./tests/selenium/wdio.conf.js

pattern /home/tom/src/wikimedia/mediawiki/extensions/VisualEditor/modules/ve-mw/tests/selenium/specs/**/*.js did not match any file
pattern /home/tom/src/wikimedia/mediawiki/skins/*/tests/selenium/specs/**/*.js did not match any file
------------------------------------------------------------------
[chrome #0-0] Session ID: 099310085b914d7f18fd46cbb6303545
[chrome #0-0] Spec: /home/tom/src/wikimedia/mediawiki/tests/selenium/wdio-mediawiki/specs/BlankPage.js
[chrome #0-0] Running: chrome
[chrome #0-0]
[chrome #0-0]   BlankPage
[chrome #0-0]
[chrome #0-0]   BlankPage
[chrome #0-0]       ✓ should have its title @daily
[chrome #0-0]
[chrome #0-0]
[chrome #0-0] 1 passing (2s)
[chrome #0-0]

[10:13:53]      Saved screenshot: ERROR_chrome_2019-01-23T10-13-53.283Z.png

        Screenshot location: /home/tom/src/wikimedia/mediawiki/tests/selenium/log/Page-should-be-previewable.png 

[10:13:53]      Saved screenshot: ERROR_chrome_2019-01-23T10-13-53.772Z.png

        Screenshot location: /home/tom/src/wikimedia/mediawiki/tests/selenium/log/Page-should-be-creatable.png 

[10:13:54] PARAMS: {"action":"login","lgname":"Admin","lgpassword":"adminpass"}
[10:13:54] RESPONSE: {"warnings":{"main":{"*":"Subscribe to the mediawiki-api-announce mailing list at <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> for notice of API deprecations and breaking changes."},"login":{"*":"Fetching a token via \"action=login\" is deprecated. Use \"action=query&meta=tokens&type=login\" instead."}},"login":{"result":"NeedToken","token":"2944d635f7a0eb6a7e424d5ff0f4bcf55c483e62+\\"}}
[10:13:54] PARAMS: {"action":"login","lgname":"Admin","lgpassword":"adminpass","lgtoken":"2944d635f7a0eb6a7e424d5ff0f4bcf55c483e62+\\"}
[10:13:54] RESPONSE: {"warnings":{"main":{"*":"Subscribe to the mediawiki-api-announce mailing list at <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> for notice of API deprecations and breaking changes."},"login":{"*":"Fetching a token via \"action=login\" is deprecated. Use \"action=query&meta=tokens&type=login\" instead."}},"login":{"result":"NeedToken","token":"1ceadfa2c4a1ced8f4bb87ec7781ae3d5c483e62+\\"}}
[10:13:54] [E] [MWBOT] Login failed: Admin@http://default.web.mw.localhost:8080/mediawiki

        Screenshot location: /home/tom/src/wikimedia/mediawiki/tests/selenium/log/Page-should-be-re-creatable.png 


        Screenshot location: /home/tom/src/wikimedia/mediawiki/tests/selenium/log/Page-should-be-re-creatable.png 

[10:13:54] PARAMS: {"action":"login","lgname":"Admin","lgpassword":"adminpass"}
[10:13:54] RESPONSE: {"warnings":{"main":{"*":"Subscribe to the mediawiki-api-announce mailing list at <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> for notice of API deprecations and breaking changes."},"login":{"*":"Fetching a token via \"action=login\" is deprecated. Use \"action=query&meta=tokens&type=login\" instead."}},"login":{"result":"NeedToken","token":"2944d635f7a0eb6a7e424d5ff0f4bcf55c483e62+\\"}}
[10:13:55] PARAMS: {"action":"login","lgname":"Admin","lgpassword":"adminpass"}
[10:13:55] RESPONSE: {"warnings":{"main":{"*":"Subscribe to the mediawiki-api-announce mailing list at <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> for notice of API deprecations and breaking changes."},"login":{"*":"Fetching a token via \"action=login\" is deprecated. Use \"action=query&meta=tokens&type=login\" instead."}},"login":{"result":"NeedToken","token":"f3c9da68a3efe560aa8c8fe5cf57259d5c483e63+\\"}}
[10:13:56] PARAMS: {"action":"login","lgname":"Admin","lgpassword":"adminpass","lgtoken":"2944d635f7a0eb6a7e424d5ff0f4bcf55c483e62+\\"}
[10:13:56] RESPONSE: {"login":{"result":"WrongToken"}}
[10:13:56] [E] [MWBOT] Login failed: Admin@http://default.web.mw.localhost:8080/mediawiki

        Screenshot location: /home/tom/src/wikimedia/mediawiki/tests/selenium/log/Page-should-have-history-%40daily.png 


        Screenshot location: /home/tom/src/wikimedia/mediawiki/tests/selenium/log/Page-should-have-history-%40daily.png 

[10:13:56] PARAMS: {"action":"login","lgname":"Admin","lgpassword":"adminpass","lgtoken":"f3c9da68a3efe560aa8c8fe5cf57259d5c483e63+\\"}
[10:13:56] RESPONSE: {"warnings":{"main":{"*":"Subscribe to the mediawiki-api-announce mailing list at <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> for notice of API deprecations and breaking changes."},"login":{"*":"Main-account login via \"action=login\" is deprecated and may stop working without warning. To continue login with \"action=login\", see [[Special:BotPasswords]]. To safely continue using main-account login, see \"action=clientlogin\"."}},"login":{"result":"Success","lguserid":1,"lgusername":"Admin"}}
[10:13:56] [S] [MWBOT] Login successful: Admin@http://default.web.mw.localhost:8080/mediawiki
[10:13:57] PARAMS: {"action":"query","meta":"tokens","type":"csrf"}
[10:13:57] RESPONSE: {"batchcomplete":"","query":{"tokens":{"csrftoken":"221fcb32beda263ea3264d8b48bd16755c483e65+\\"}}}
[10:13:58] PARAMS: {"action":"login","lgname":"Admin","lgpassword":"adminpass"}
[10:13:58] RESPONSE: {"warnings":{"main":{"*":"Subscribe to the mediawiki-api-announce mailing list at <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> for notice of API deprecations and breaking changes."},"login":{"*":"Fetching a token via \"action=login\" is deprecated. Use \"action=query&meta=tokens&type=login\" instead."}},"login":{"result":"NeedToken","token":"6c0ae9168d670aa81192cac03b23fa475c483e66+\\"}}
[10:13:59] PARAMS: {"action":"login","lgname":"Admin","lgpassword":"adminpass"}
[10:13:59] RESPONSE: {"warnings":{"main":{"*":"Subscribe to the mediawiki-api-announce mailing list at <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> for notice of API deprecations and breaking changes."},"login":{"*":"Fetching a token via \"action=login\" is deprecated. Use \"action=query&meta=tokens&type=login\" instead."}},"login":{"result":"NeedToken","token":"b8f590c17eb69aabf514b3330a4a5ad45c483e67+\\"}}
[10:13:59] PARAMS: {"action":"login","lgname":"Admin","lgpassword":"adminpass","lgtoken":"6c0ae9168d670aa81192cac03b23fa475c483e66+\\"}
[10:13:59] RESPONSE: {"warnings":{"main":{"*":"Subscribe to the mediawiki-api-announce mailing list at <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> for notice of API deprecations and breaking changes."},"login":{"*":"Main-account login via \"action=login\" is deprecated and may stop working without warning. To continue login with \"action=login\", see [[Special:BotPasswords]]. To safely continue using main-account login, see \"action=clientlogin\"."}},"login":{"result":"Success","lguserid":1,"lgusername":"Admin"}}
[10:13:59] [S] [MWBOT] Login successful: Admin@http://default.web.mw.localhost:8080/mediawiki
[10:14:00] PARAMS: {"action":"login","lgname":"Admin","lgpassword":"adminpass","lgtoken":"b8f590c17eb69aabf514b3330a4a5ad45c483e67+\\"}
[10:14:00] RESPONSE: {"warnings":{"main":{"*":"Subscribe to the mediawiki-api-announce mailing list at <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> for notice of API deprecations and breaking changes."},"login":{"*":"Fetching a token via \"action=login\" is deprecated. Use \"action=query&meta=tokens&type=login\" instead."}},"login":{"result":"NeedToken","token":"2b67887c3f8a30d885066ff79d758f0a5c483e68+\\"}}
[10:14:00] [E] [MWBOT] Login failed: Admin@http://default.web.mw.localhost:8080/mediawiki

        Screenshot location: /home/tom/src/wikimedia/mediawiki/tests/selenium/log/Page-should-be-restorable.png 


        Screenshot location: /home/tom/src/wikimedia/mediawiki/tests/selenium/log/Page-should-be-restorable.png 

(node:4381) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'isPending' of undefined
    at /home/tom/src/wikimedia/mediawiki/node_modules/mocha/lib/runner.js:558:16
    at next (/home/tom/src/wikimedia/mediawiki/node_modules/mocha/lib/runner.js:369:14)
    at /home/tom/src/wikimedia/mediawiki/node_modules/mocha/lib/runner.js:379:7
    at next (/home/tom/src/wikimedia/mediawiki/node_modules/mocha/lib/runner.js:303:14)
    at /home/tom/src/wikimedia/mediawiki/node_modules/mocha/lib/runner.js:342:7
    at done (/home/tom/src/wikimedia/mediawiki/node_modules/mocha/lib/runnable.js:319:5)
    at /home/tom/src/wikimedia/mediawiki/node_modules/mocha/lib/runnable.js:377:11
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:182:7)
(node:4381) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 6)
(node:4381) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
[10:14:00] PARAMS: {"action":"query","meta":"tokens","type":"csrf"}
[10:14:00] RESPONSE: {"batchcomplete":"","query":{"tokens":{"csrftoken":"cf91c27d8bd421ef408d45fc57d436ae5c483e68+\\"}}}
------------------------------------------------------------------
[chrome #0-1] Session ID: 1441d6f2dd6a2ec9649706482a8cfd26
[chrome #0-1] Spec: /home/tom/src/wikimedia/mediawiki/tests/selenium/specs/page.js
[chrome #0-1] Running: chrome
[chrome #0-1]
[chrome #0-1]   Page
[chrome #0-1]
[chrome #0-1]   Page
[chrome #0-1]       1) should be previewable
[chrome #0-1]       2) should be creatable
[chrome #0-1]       3) should be re-creatable
[chrome #0-1]       4) should have history @daily
[chrome #0-1]       5) should be restorable
[chrome #0-1]
[chrome #0-1]
[chrome #0-1] 8 failing (10s)
[chrome #0-1]
[chrome #0-1] 1) Page should be previewable:
[chrome #0-1] An element could not be located on the page using the given search parameters ("#wpTextbox1").
[chrome #0-1] Error: An element could not be located on the page using the given search parameters ("#wpTextbox1").
[chrome #0-1]     at setValue("beforeEach-content-0.5141183036378307-Iñtërnâtiônàlizætiøn") - index.js:312:3
[chrome #0-1]
[chrome #0-1] 2) Page should be creatable:
[chrome #0-1] An element could not be located on the page using the given search parameters ("#wpTextbox1").
[chrome #0-1] Error: An element could not be located on the page using the given search parameters ("#wpTextbox1").
[chrome #0-1]     at setValue("beforeEach-content-0.46360455855645166-Iñtërnâtiônàlizætiøn") - index.js:312:3
[chrome #0-1]
[chrome #0-1] 3) Page should be re-creatable:
[chrome #0-1] Could not login: NeedToken
[chrome #0-1] Error: Could not login: NeedToken
[chrome #0-1]     at request.then.then (/home/tom/src/wikimedia/mediawiki/node_modules/mwbot/src/index.js:334:31)
[chrome #0-1]     at tryCatcher (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/util.js:16:23)
[chrome #0-1]     at Promise._settlePromiseFromHandler (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:512:31)
[chrome #0-1]     at Promise._settlePromise (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:569:18)
[chrome #0-1]     at Promise._settlePromise0 (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:614:10)
[chrome #0-1]     at Promise._settlePromises (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:694:18)
[chrome #0-1]     at _drainQueueStep (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:138:12)
[chrome #0-1]     at _drainQueue (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:131:9)
[chrome #0-1]     at Async._drainQueues (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:147:5)
[chrome #0-1]     at Immediate.Async.drainQueues [as _onImmediate] (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:17:14)
[chrome #0-1]     at runCallback (timers.js:763:18)
[chrome #0-1]     at tryOnImmediate (timers.js:734:5)
[chrome #0-1]     at processImmediate (timers.js:716:5)
[chrome #0-1]     at process.topLevelDomainCallback (domain.js:102:23)
[chrome #0-1]
[chrome #0-1] 4) Page should have history @daily:
[chrome #0-1] Could not login: WrongToken
[chrome #0-1] Error: Could not login: WrongToken
[chrome #0-1]     at request.then.then (/home/tom/src/wikimedia/mediawiki/node_modules/mwbot/src/index.js:334:31)
[chrome #0-1]     at tryCatcher (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/util.js:16:23)
[chrome #0-1]     at Promise._settlePromiseFromHandler (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:512:31)
[chrome #0-1]     at Promise._settlePromise (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:569:18)
[chrome #0-1]     at Promise._settlePromise0 (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:614:10)
[chrome #0-1]     at Promise._settlePromises (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:694:18)
[chrome #0-1]     at _drainQueueStep (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:138:12)
[chrome #0-1]     at _drainQueue (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:131:9)
[chrome #0-1]     at Async._drainQueues (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:147:5)
[chrome #0-1]     at Immediate.Async.drainQueues [as _onImmediate] (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:17:14)
[chrome #0-1]     at runCallback (timers.js:763:18)
[chrome #0-1]     at tryOnImmediate (timers.js:734:5)
[chrome #0-1]     at processImmediate (timers.js:716:5)
[chrome #0-1]     at process.topLevelDomainCallback (domain.js:102:23)
[chrome #0-1]
[chrome #0-1] 5) Page should be restorable:
[chrome #0-1] Could not login: NeedToken
[chrome #0-1] Error: Could not login: NeedToken
[chrome #0-1]     at request.then.then (/home/tom/src/wikimedia/mediawiki/node_modules/mwbot/src/index.js:334:31)
[chrome #0-1]     at tryCatcher (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/util.js:16:23)
[chrome #0-1]     at Promise._settlePromiseFromHandler (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:512:31)
[chrome #0-1]     at Promise._settlePromise (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:569:18)
[chrome #0-1]     at Promise._settlePromise0 (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:614:10)
[chrome #0-1]     at Promise._settlePromises (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/promise.js:694:18)
[chrome #0-1]     at _drainQueueStep (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:138:12)
[chrome #0-1]     at _drainQueue (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:131:9)
[chrome #0-1]     at Async._drainQueues (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:147:5)
[chrome #0-1]     at Immediate.Async.drainQueues [as _onImmediate] (/home/tom/src/wikimedia/mediawiki/node_modules/bluebird/js/release/async.js:17:14)
[chrome #0-1]     at runCallback (timers.js:763:18)
[chrome #0-1]     at tryOnImmediate (timers.js:734:5)
[chrome #0-1]     at processImmediate (timers.js:716:5)
[chrome #0-1]     at process.topLevelDomainCallback (domain.js:102:23)
[chrome #0-1]

Note that it does not fail everytime.

npm ls output: https://phabricator.wikimedia.org/P8022

Details

ProjectBranchLines +/-Subject
mediawiki/coremaster+7 -2Persist sessions pre-send instead of post-send
Customize query in gerrit

Related Objects

Event Timeline

Tarrow created this task.Jan 23 2019, 10:16 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJan 23 2019, 10:16 AM
Tarrow updated the task description. (Show Details)Jan 23 2019, 10:21 AM
Tarrow added a project: Browser-Tests.
zeljkofilipin added projects: User-zeljkofilipin, MediaWiki-Core-Tests.Jan 23 2019, 10:43 AM
zeljkofilipin moved this task from Inbox to Selenium on the MediaWiki-Core-Tests board.
zeljkofilipin moved this task from Backlog ⏪ to Next ⏭ on the User-zeljkofilipin board.
zeljkofilipin added a project: Release-Engineering-Team (Kanban).Jan 23 2019, 10:48 AM
Tarrow added a subscriber: • Addshore.Jan 25 2019, 12:51 PM

@Addshore and I dug into this today.

We believe that there is a race condition where the browser tests are going fast enough that they are making the second request of the login process before the mediawiki teardown has saved the session it just started.

We hackily solved this by adding something like this to ApiMain.php#1650:

/** @var SessionManager $sm */
$sm = \MediaWiki\Session\SessionManager::singleton();
$sm->shutdown();
Tarrow added a comment.Jan 25 2019, 12:58 PM

Alternatively this is solvable by adding a delay to the requests made by mwbot with something similar to:

return new Promise( (resolve) => { setTimeout(  () => {
                resolve()
            }, 1000 ) } ).then( () => {
                return this.rawRequest(requestOptions)
            } ).then.........

node_modules/mwbot/src/index.js:248

Tarrow added a comment.Jan 25 2019, 1:11 PM

Or finally you can turn of MW session handling with

define('MW_NO_SESSION_HANDLER', true);

in LocalSettings.php

• Addshore added subscribers: aaron, Anomie.Jan 25 2019, 1:15 PM

It feel like Chronology protector should be protecting something here?
But I guess as the db write to persist the session hasn't happened by time the whole page and headers are sent to the user there is no position to send / wait for in the following request?

Adding @Anomie for the session related stuff for some comments and @aaron for the cache & thoughts about chronology protector.

• Addshore added a project: MediaWiki-Authentication-and-authorization.Jan 25 2019, 1:16 PM
• Addshore added a project: User-Addshore.
• Addshore moved this task from Unsorted 💣 to Watching 👀 on the User-Addshore board.
• Addshore renamed this task from wdio browser tests fail locally with Could not login: WrongToken and NeedToken to wdio browser tests fail locally due to session not being persisted before 2nd stage of login starts.Jan 25 2019, 1:42 PM
Anomie added a comment.Jan 25 2019, 3:58 PM

Calling SessionManager::shutdown() would not be appropriate, that's not intended to be a public method (it's only public at the PHP level because it needs to be registered as a callback). Nor would ApiMain be a good place to do it.

What might make sense would be to call $request->getSession()->save() from MediaWiki::preOutputCommit(), maybe somewhere around line 601.

aaron added a comment.Jan 25 2019, 8:15 PM

I don't think ChronologyProtector is involved.

If the current shutdown only happens via register_shutdown_function (SessionManager::__construct()), then something like Brad's suggestion above makes sense to me.

• alaa_wmde added a subscriber: • alaa_wmde.Feb 4 2019, 2:06 PM
• alaa_wmde removed a subscriber: • alaa_wmde.
gerritbot added a subscriber: gerritbot.Feb 6 2019, 10:37 PM

Change 488598 had a related patch set uploaded (by Aaron Schulz; owner: Aaron Schulz):
[mediawiki/core@master] Persist sessions pre-send instead of post-send

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

gerritbot added a project: Patch-For-Review.Feb 6 2019, 10:37 PM
Krinkle edited projects, added Wikimedia-production-error (ARCHIVED -- Shared Build Failure); removed Browser-Tests.Feb 7 2019, 1:31 AM
Krinkle moved this task from Untriaged to In progress on the Wikimedia-production-error (ARCHIVED -- Shared Build Failure) board.
gerritbot added a comment.Feb 9 2019, 2:21 AM

Change 488598 merged by jenkins-bot:
[mediawiki/core@master] Persist sessions pre-send instead of post-send

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

ReleaseTaggerBot added a project: MW-1.33-notes (1.33.0-wmf.17; 2019-02-12).Feb 9 2019, 3:01 AM
• alaa_wmde claimed this task.Feb 18 2019, 5:30 PM

I'm looking into a permanent fix for this. One thing I tried is upgrade wdio and adjust tests accordingly. But I want to find a solution without the upgrade.

Anomie added a comment.Feb 19 2019, 10:09 PM

Did you test it with rMW276d065d1620: Persist sessions pre-send instead of post-send?

sarhan.alaa added a subscriber: sarhan.alaa.EditedFeb 20 2019, 7:16 AM

yes I did. I should add that the only teats failing for me now are WikibaseLexeme ones, specifically mwbot logins. There is an invalid edit token (+\\ feels truncated or smth) being stored and reused by the test sometimes, causing Invalid CSRF Token error.

This happens only when more than one test is executed.

So far I'm checking this possibility:

  • wikibaselexeme usage of mwbot is storing the invalid edit token when it shouldn't.

Sorry for the incomplete info in this comment.. juat adding from my memory. will add more info ane code references when I get back on it.

Anomie added a comment.Feb 20 2019, 5:18 PM

If the token is really +\\ with two backslashes, then your code is broken somewhere.

If it's actually +\ and the two backslashes are because whatever is printing it out is escaping the backslash (e.g. you're looking at dumped JSON), that's a valid edit token returned to non-logged-in users. Are you fetching the token before logging in, and then not re-fetching it after logging in?

• alaa_wmde added a comment.Feb 20 2019, 5:24 PM

Yes it is +\ the anonymous user token.

This morning I tried to log something closer to where it happens, I get this by logging the rejection of WikibaseApi.createItem() calls inside LexemeApi.create() method (... WikibaseApi.createItem().catch(console.log) ... at lines 43 and 46):

{ Error: badtoken: Invalid CSRF token.
    at rawRequest.then (/home/alaasarhan/src/mediawiki/extensions/WikibaseLexeme/node_modules/mwbot/src/index.js:257:31)
    at tryCatcher (/home/alaasarhan/src/mediawiki/extensions/WikibaseLexeme/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/home/alaasarhan/src/mediawiki/extensions/WikibaseLexeme/node_modules/bluebird/js/release/promise.js:512:31)
    at Promise._settlePromise (/home/alaasarhan/src/mediawiki/extensions/WikibaseLexeme/node_modules/bluebird/js/release/promise.js:569:18)
    at Promise._settlePromise0 (/home/alaasarhan/src/mediawiki/extensions/WikibaseLexeme/node_modules/bluebird/js/release/promise.js:614:10)
    at Promise._settlePromises (/home/alaasarhan/src/mediawiki/extensions/WikibaseLexeme/node_modules/bluebird/js/release/promise.js:694:18)
    at _drainQueueStep (/home/alaasarhan/src/mediawiki/extensions/WikibaseLexeme/node_modules/bluebird/js/release/async.js:138:12)
    at _drainQueue (/home/alaasarhan/src/mediawiki/extensions/WikibaseLexeme/node_modules/bluebird/js/release/async.js:131:9)
    at Async._drainQueues (/home/alaasarhan/src/mediawiki/extensions/WikibaseLexeme/node_modules/bluebird/js/release/async.js:147:5)
    at Immediate.Async.drainQueues (/home/alaasarhan/src/mediawiki/extensions/WikibaseLexeme/node_modules/bluebird/js/release/async.js:17:14)
    at runCallback (timers.js:810:20)
    at tryOnImmediate (timers.js:768:5)
    at processImmediate [as _immediateCallback] (timers.js:745:5)
  errorResponse: true,
  code: 'badtoken',
  info: 'Invalid CSRF token.',
  response: 
   { error: 
      { code: 'badtoken',
        info: 'Invalid CSRF token.',
        '*': 'See http://default.web.mw.localhost:8080/mediawiki/api.php for API usage. Subscribe to the mediawiki-api-announce mailing list at &lt;https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce&gt; for notice of API deprecations and breaking changes.' },
     servedby: '802a7111447b' },
  request: 
   { method: 'POST',
     headers: { 'User-Agent': 'mwbot/1.0.10' },
     qs: { format: 'json' },
     form: 
      { action: 'wbeditentity',
        new: 'item',
        data: '{"labels":{}}',
        token: '24a5a0e6af49141dd46dbb3c3f1e12475c6d2ecd+\\' },
     timeout: 120000,
     jar: true,
     time: true,
     json: true,
     uri: 'http://default.web.mw.localhost:8080/mediawiki/api.php' } }
Anomie added a comment.Feb 20 2019, 5:55 PM
In T214471#4969111, @alaa_wmde wrote:
token: '24a5a0e6af49141dd46dbb3c3f1e12475c6d2ecd+\\' },

That's not the +\ token. And also it doesn't seem to be related to this task, as to get that token you've managed to log in successfully.

If logins are reliably working now (no more NeedToken errors), let's resolve this task. You can open another one to track the new issue.

• alaa_wmde added a comment.Feb 20 2019, 6:15 PM

@Anomie Yes it seems unrelated indeed by now. I'll create a separate ticket in Wikibase board and continue there. Thanks for the support so far!

Anomie closed this task as Resolved.Feb 20 2019, 6:44 PM
Anomie reassigned this task from • alaa_wmde to aaron.
Anomie added a subscriber: • alaa_wmde.

Ok, I'm closing this task since the login issue seems to be resolved. Looks like the followup is in T216641: WikibaseLexeme browser tests failing with Invalid CSRF Token error.

mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:07 PM
Restricted Application added a subscriber: Liuxinyu970226. · View Herald TranscriptAug 28 2019, 11:07 PM
Maintenance_bot removed a project: Patch-For-Review.Aug 28 2019, 11:14 PM
Aklapper removed a subscriber: Anomie.Oct 16 2020, 5:38 PM
Krinkle mentioned this in T270225: Finish session storage to actually meet multi-DC requirements.Mar 19 2021, 2:26 AM
Content licensed under Creative Commons Attribution-ShareAlike 3.0 (CC-BY-SA) unless otherwise noted; code licensed under GNU General Public License (GPL) or other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL