Page MenuHomePhabricator

Various browser tests failing with MediawikiApi::LoginError
Closed, ResolvedPublic

Description

Various browser tests are failing due to a login error.

Failing consistently (at least two times in a row, still failing):

Failing intermittently (at least once, but no longer):

selenium-Wikidata failed with MediawikiApi::LoginError in the last test run, but it takes more than 2 hours for the test run, so I am not rerunning it now, will wait until tomorrow.

Track stace looks like:

failed to log in with the returned token '6deec829078b4f823c8af5355cd5becf57aaa61e+\' (MediawikiApi::LoginError)
/mnt/home/jenkins-deploy/.gem/2.0.0/gems/mediawiki_api-0.7.0/lib/mediawiki_api/client.rb:135:in `log_in'
/mnt/home/jenkins-deploy/.gem/2.0.0/gems/mediawiki_api-0.7.0/lib/mediawiki_api/client.rb:136:in `log_in'
/mnt/home/jenkins-deploy/.gem/2.0.0/gems/mediawiki_selenium-1.7.2/lib/mediawiki_selenium/helpers/api_helper.rb:18:in `block in api'
/mnt/home/jenkins-deploy/.gem/2.0.0/gems/mediawiki_selenium-1.7.2/lib/mediawiki_selenium/helpers/api_helper.rb:17:in `tap'
/mnt/home/jenkins-deploy/.gem/2.0.0/gems/mediawiki_selenium-1.7.2/lib/mediawiki_selenium/helpers/api_helper.rb:17:in `api'
/mnt/jenkins-workspace/workspace/selenium-MultimediaViewer/BROWSER/firefox/MEDIAWIKI_ENVIRONMENT/beta/PLATFORM/Linux/label/contintLabsSlave && UbuntuTrusty/tests/browser/features/step_definitions/mmv_steps.rb:4:in `block in <top (required)>'
...

Event Timeline

I can replicate this.
x-analytics: "ns=-1;special=Badtitle;WMF-Last-Access=10-Aug-2016;https=1"
x-client-ip: "198.73.209.4"
MediawikiApi::LoginError: failed to log in with the returned token '3d64894be4a585ecf5d8c80dbf31ec8457ab937b+\'
from /Users/jrobson/.rvm/gems/ruby-2.1.1/gems/mediawiki_api-0.7.0/lib/mediawiki_api/client.rb:135:in `log_in'
from /Users/jrobson/.rvm/gems/ruby-2.1.1/gems/mediawiki_api-0.7.0/lib/mediawiki_api/client.rb:136:in `log_in'
from (irb):3
from /Users/jrobson/.rvm/rubies/ruby-2.1.1/bin/irb:11:in `<main>'

IT seems to happen when the user needs to change their password.
I tried for a user with a 6 character password and I got the above message.
When I login I see this screen:

Screen Shot 2016-08-10 at 1.50.47 PM.png (578×985 px, 72 KB)

I do not get the same issue with another account which doesn't have the password prompt.

2.1.1 :001 > require 'mediawiki_api'
 => true 
2.1.1 :002 > c = MediawikiApi::Client.new('https://en.wikipedia.beta.wmflabs.org/w/api.php', true)
 => #<MediawikiApi::Client:0x00000102bf5830 @cookies=#<HTTP::CookieJar:0x00000102bf5808 @store=#<HTTP::CookieJar::HashStore:0x00000102c1fae0 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x00000102c1fa90>, @logger=nil, @gc_threshold=150, @jar={}, @gc_index=0>>, @conn=#<Faraday::Connection:0x00000102c1f900 @parallel_manager=nil, @headers={"User-Agent"=>"Faraday v0.9.2"}, @params={}, @options=#<Faraday::RequestOptions (empty)>, @ssl=#<Faraday::SSLOptions (empty)>, @default_parallel_manager=nil, @builder=#<Faraday::RackBuilder:0x00000102c1f680 @handlers=[Faraday::Request::Multipart, Faraday::Request::UrlEncoded, Faraday::Response::Logger, Faraday::CookieJar, FaradayMiddleware::FollowRedirects, Faraday::Adapter::NetHttp]>, @url_prefix=#<URI::HTTPS:0x00000102c1f3b0 URL:https://en.wikipedia.beta.wmflabs.org/w/api.php>, @proxy=nil>, @logged_in=false, @tokens={}> 
2.1.1 :003 > c.log_in('ShortBadPassword', 'fake')
I, [2016-08-10T13:50:00.998792 #22282]  INFO -- : post https://en.wikipedia.beta.wmflabs.org/w/api.php
D, [2016-08-10T13:50:00.998904 #22282] DEBUG -- request: User-Agent: "Faraday v0.9.2"
Content-Type: "application/x-www-form-urlencoded"

I, [2016-08-10T13:50:04.447329 #22282]  INFO -- Status: 200
D, [2016-08-10T13:50:04.447494 #22282] DEBUG -- response: date: "Wed, 10 Aug 2016 20:50:04 GMT"
content-type: "application/json; charset=utf-8"
content-length: "229"
connection: "close"
server: "deployment-mediawiki01.deployment-prep.eqiad.wmflabs"
x-powered-by: "HHVM/3.12.1"
vary: "Accept-Encoding"
x-frame-options: "SAMEORIGIN"
p3p: "CP=\"This is not a P3P policy! See https://en.wikipedia.beta.wmflabs.org/wiki/Special:CentralAutoLogin/P3P for more info.\""
cache-control: "private, must-revalidate, max-age=0"
x-content-type-options: "nosniff"
set-cookie: "enwikiSession=kgnjibimrodauf63o82eo6idlc134lf6; path=/; secure; httponly, WMF-Last-Access=10-Aug-2016;Path=/;HttpOnly;secure;Expires=Sun, 11 Sep 2016 12:00:00 GMT, GeoIP=US:CA:San_Francisco:37.79:-122.39:v4; Path=/; secure; Domain=.beta.wmflabs.org"
backend-timing: "D=3080584 t=1470862201690582"
x-varnish: "684014097, 1212193766"
via: "1.1 varnish, 1.1 varnish"
accept-ranges: "bytes"
age: "0"
x-cache: "deployment-cache-text04 pass, deployment-cache-text04 pass"
x-cache-status: "pass"
x-analytics: "ns=-1;special=Badtitle;https=1;nocookies=1"
x-client-ip: "198.73.209.4"
I, [2016-08-10T13:50:04.448270 #22282]  INFO -- : post https://en.wikipedia.beta.wmflabs.org/w/api.php
D, [2016-08-10T13:50:04.448367 #22282] DEBUG -- request: User-Agent: "Faraday v0.9.2"
Content-Type: "application/x-www-form-urlencoded"
I, [2016-08-10T13:50:04.877614 #22282]  INFO -- Status: 200
D, [2016-08-10T13:50:04.877877 #22282] DEBUG -- response: date: "Wed, 10 Aug 2016 20:50:05 GMT"
content-type: "application/json; charset=utf-8"
content-length: "229"
connection: "close"
server: "deployment-mediawiki01.deployment-prep.eqiad.wmflabs"
x-powered-by: "HHVM/3.12.1"
vary: "Accept-Encoding"
x-frame-options: "SAMEORIGIN"
p3p: "CP=\"This is not a P3P policy! See https://en.wikipedia.beta.wmflabs.org/wiki/Special:CentralAutoLogin/P3P for more info.\""
cache-control: "private, must-revalidate, max-age=0"
x-content-type-options: "nosniff"
set-cookie: "enwikiSession=07hvh0ktek0fb9dfbgvbifaub7nlg5rj; path=/; secure; httponly"
backend-timing: "D=77570 t=1470862205139394"
x-varnish: "684014135, 1212193774"
via: "1.1 varnish, 1.1 varnish"
accept-ranges: "bytes"
age: "0"
x-cache: "deployment-cache-text04 pass, deployment-cache-text04 pass"
x-cache-status: "pass"
x-analytics: "ns=-1;special=Badtitle;WMF-Last-Access=10-Aug-2016;https=1"
x-client-ip: "198.73.209.4"
MediawikiApi::LoginError: failed to log in with the returned token '3d64894be4a585ecf5d8c80dbf31ec8457ab937b+\'
	from /Users/jrobson/.rvm/gems/ruby-2.1.1/gems/mediawiki_api-0.7.0/lib/mediawiki_api/client.rb:135:in `log_in'
	from /Users/jrobson/.rvm/gems/ruby-2.1.1/gems/mediawiki_api-0.7.0/lib/mediawiki_api/client.rb:136:in `log_in'
	from (irb):3
	from /Users/jrobson/.rvm/rubies/ruby-2.1.1/bin/irb:11:in `<main>'

Oh, right, I didn't think of that. The least painful way to fix it is just to change passwords. The old login API just submits the username and password and fails if that's not enough to log you in. Normally the way for bots to log in reliably is to use bot passwords, but that only gives you access to the API, so it's not useful for browser tests.

@greg is it possible for your team to rule out whether the user that runs the beta cluster tests simply needs a password change?

They can be changed in the jenkins credential store: https://integration.wikimedia.org/ci/credential-store/domain/selenium/

If it is changed there, please change it at https://office.wikimedia.org/wiki/Selenium_passwords as well

I presume it is User:Selenium_user on beta cluster, yes?

I don't see any warning about changing the password when I manually log in to this selenium user account

sure, not sure how that changes the test i just did where I can log in using the username/password without prompt for changing it

I presume it is User:Selenium_user on beta cluster, yes?

No, I tested that in T142141#2538427.

The general solution would be to make it easier to enable verbose logging in mediawiki_api; I'll take a shot at that.

Change 304331 had a related patch set uploaded (by Gergő Tisza):
0.7.1: Increase log verbosity

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

Change 304332 had a related patch set uploaded (by Gergő Tisza):
1.7.3: Add API log level to environment settings

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

@greg I'm not sure how to proceed. The above two patches add detailed logging to the test output which is good for manual testing, but it also includes the password and session cookie so it is only useful for debugging CI problems if we can selectively make the output nonpublic when the logging flag is set. Is that possible?

Also, while this would tell which user is failing, it still doesn't tell why it is falling as the API does not say (or even log) that. That needs to be fixed in MediaWiki core.

Change 305157 had a related patch set uploaded (by Gergő Tisza):
Log failure reasons in ApiLogin

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

Change 305157 merged by jenkins-bot:
Log failure reasons in ApiLogin

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

I re-ran the failing test but nothing was logged on beta (see authentication channel). Which in hindsight is not surprising, failed to log in with the returned token is reported when the API returns NeedToken, other error codes have a different message.

I can't reproduce the error in T142600#2541624 either; MediawikiApi::LoginError: Aborted as expected. Jon, can you retry that with https://gerrit.wikimedia.org/r/#/c/304332/ applied?

zeljkofilipin updated the task description. (Show Details)
zeljkofilipin renamed this task from Various browser tests failing due to login error to Various browser tests failing with MediawikiApi::LoginError.Aug 18 2016, 3:05 PM

Change 305515 had a related patch set uploaded (by Zfilipin):
WIP Fix MediawikiApi::LoginError

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

Jdlrobson raised the priority of this task from Medium to High.Aug 19 2016, 4:02 PM

I've personally started ignoring browser tests which is a bad sign so bumping priority. Does anyone have any theories on what broke this and how we might fix this??

I am working on this, I have tried a few things, no luck yet.

Stashbot added a subscriber: Stashbot.

Mentioned in SAL [2016-08-24T09:50:33Z] <hashar> deployment-redis02 fixed AOF file /srv/redis/deployment-redis02-6379.aof and restarted the redis instance should fix T143655 and might help T142600

As far as I can see, this is resolved when @hashar fixed redis. I will wait until tomorrow for all selenium jobs to run and then resolve the task if the error is gone.

The problem seems to be fixed. I have just checked all selenium jobs, and none of them have failed with MediawikiApi::LoginError.

Change 304331 abandoned by Zfilipin:
0.7.1: Increase log verbosity

Reason:
mediawiki/ruby/api is in maintenance-only mode

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

Change 304332 abandoned by Zfilipin:
1.7.3: Add API log level to environment settings

Reason:
mediawiki/selenium is in maintenance-only mode

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