Page MenuHomePhabricator

Edits fail with "badtoken: Invalid token" after script runs for a while
Closed, DeclinedPublic

Description

I'm maintaining a continuous running script, which resets the sandbox on dewiki (the sandbox on dewiki is a bit different to the ones on e.g. enwiki, it's a specialized script, not the reset_sandbox one).

It's been running without problems for several months, but suddenly since 12. February I only get "badtoken: Invalid token" exceptions when trying to save a page. When restarting it runs fine for a while, and then only gets "badtoken: Invalid token" on page.save.

Here is an example from the log

2015-02-17 10:43:39            Rahu.py,  182 in      reset_sandbox: INFO     {lightyellow}17. February 2015, 10:43:39: Reseting Sandbox ...{default}
2015-02-17 10:43:39           login.py,  205 in              login: INFO     Logging in to wikipedia:de as AsuraBot
2015-02-17 10:43:40           login.py,  223 in              login: VERBOSE  Should be logged in now
2015-02-17 10:43:40        throttle.py,  247 in               wait: INFO     Sleeping for 7.0 seconds, 2015-02-17 10:43:40
2015-02-17 10:43:48             api.py, 1314 in             submit: VERBOSE  API Error: query=
{'action': [u'edit'],
 'assert': [u'user'],
 'basetimestamp': [Timestamp(2015, 2, 17, 9, 22, 18)],
 'bot': [True],
 'createonly': [False],
 'format': ['json'],
 'maxlag': ['5'],
 'minor': [False],
 'nocreate': [False],
 'notminor': [False],
 'recreate': [True],
 'summary': [u'[[WP:Bots', u'Bot]]: Spielwiese gem\xe4ht (zur\xfcckgesetzt)'],
 'text': [u'{{Bitte erst NACH dieser Zeile schreiben! (Begr\xfc\xdfungskasten)}}\n{{subst:Vorlage:Bitte erst NACH dieser Zeile schreiben! (Begr\xfc\xdfungskasten)/Text}}'],
 'title': [u'Wikipedia:Spielwiese'],
 'token': [u'6c367b3d3ec08fed211b51859359f8d054e263f0+\\']}
2015-02-17 10:43:48             api.py, 1316 in             submit: VERBOSE             response=
{u'servedby': u'mw1190', u'error': {'help': u'See https://de.wikipedia.org/w/api.php for API usage'}}
2015-02-17 10:43:48            page.py, 1056 in              _save: VERBOSE  Error saving page [[Wikipedia:Spielwiese]] (badtoken: Invalid token)
Traceback (most recent call last):
  File "/shared/pywikipedia/core/pywikibot/page.py", line 1047, in _save
    watch=watchval, bot=botflag, **kwargs)
  File "/shared/pywikipedia/core/pywikibot/site.py", line 1041, in callee
    return fn(self, *args, **kwargs)
  File "/shared/pywikipedia/core/pywikibot/site.py", line 4048, in editpage
    result = req.submit()
  File "/shared/pywikipedia/core/pywikibot/data/api.py", line 1318, in submit
    raise APIError(code, info, **result["error"])
APIError: badtoken: Invalid token
2015-02-17 10:43:48            Rahu.py,  195 in      reset_sandbox: INFO     {lightyellow}Edit to page [[Wikipedia:Spielwiese]] failed:
badtoken: Invalid token while reseting!{default}
2015-02-17 10:43:49            Rahu.py,  182 in      reset_sandbox: INFO     {lightyellow}17. February 2015, 10:43:49: Reseting Sandbox ...{default}
2015-02-17 10:43:49           login.py,  205 in              login: INFO     Logging in to wikipedia:de as AsuraBot
2015-02-17 10:43:50           login.py,  223 in              login: VERBOSE  Should be logged in now
2015-02-17 10:43:50        throttle.py,  247 in               wait: INFO     Sleeping for 7.5 seconds, 2015-02-17 10:43:50
2015-02-17 10:43:58             api.py, 1314 in             submit: VERBOSE  API Error: query=
{'action': [u'edit'],
 'assert': [u'user'],
 'basetimestamp': [Timestamp(2015, 2, 17, 9, 22, 18)],
 'bot': [True],
 'createonly': [False],
 'format': ['json'],
 'maxlag': ['5'],
 'minor': [False],
 'nocreate': [False],
 'notminor': [False],
 'recreate': [True],
 'summary': [u'[[WP:Bots', u'Bot]]: Spielwiese gem\xe4ht (zur\xfcckgesetzt)'],
 'text': [u'{{Bitte erst NACH dieser Zeile schreiben! (Begr\xfc\xdfungskasten)}}\n{{subst:Vorlage:Bitte erst NACH dieser Zeile schreiben! (Begr\xfc\xdfungskasten)/Text}}'],
 'title': [u'Wikipedia:Spielwiese'],
 'token': [u'6c367b3d3ec08fed211b51859359f8d054e263f0+\\']}
2015-02-17 10:43:58             api.py, 1316 in             submit: VERBOSE             response=
{u'servedby': u'mw1139', u'error': {'help': u'See https://de.wikipedia.org/w/api.php for API usage'}}
2015-02-17 10:43:58            page.py, 1056 in              _save: VERBOSE  Error saving page [[Wikipedia:Spielwiese]] (badtoken: Invalid token)
Traceback (most recent call last):
  File "/shared/pywikipedia/core/pywikibot/page.py", line 1047, in _save
    watch=watchval, bot=botflag, **kwargs)
  File "/shared/pywikipedia/core/pywikibot/site.py", line 1041, in callee
    return fn(self, *args, **kwargs)
  File "/shared/pywikipedia/core/pywikibot/site.py", line 4048, in editpage
    result = req.submit()
  File "/shared/pywikipedia/core/pywikibot/data/api.py", line 1318, in submit
    raise APIError(code, info, **result["error"])
APIError: badtoken: Invalid token
2015-02-17 10:43:58            Rahu.py,  195 in      reset_sandbox: INFO     {lightyellow}Edit to page [[Wikipedia:Spielwiese]] failed:
badtoken: Invalid token while reseting!{default}
2015-02-17 10:44:01            Rahu.py,  182 in      reset_sandbox: INFO     {lightyellow}17. February 2015, 10:44:01: Reseting Sandbox ...{default}
2015-02-17 10:44:01           login.py,  205 in              login: INFO     Logging in to wikipedia:de as AsuraBot
2015-02-17 10:44:02           login.py,  223 in              login: VERBOSE  Should be logged in now
2015-02-17 10:44:03        throttle.py,  247 in               wait: INFO     Sleeping for 4.9 seconds, 2015-02-17 10:44:03
2015-02-17 10:44:08             api.py, 1314 in             submit: VERBOSE  API Error: query=
{'action': [u'edit'],
 'assert': [u'user'],
 'basetimestamp': [Timestamp(2015, 2, 17, 9, 22, 18)],
 'bot': [True],
 'createonly': [False],
 'format': ['json'],
 'maxlag': ['5'],
 'minor': [False],
 'nocreate': [False],
 'notminor': [False],
 'recreate': [True],
 'summary': [u'[[WP:Bots', u'Bot]]: Spielwiese gem\xe4ht (zur\xfcckgesetzt)'],
 'text': [u'{{Bitte erst NACH dieser Zeile schreiben! (Begr\xfc\xdfungskasten)}}\n{{subst:Vorlage:Bitte erst NACH dieser Zeile schreiben! (Begr\xfc\xdfungskasten)/Text}}'],
 'title': [u'Wikipedia:Spielwiese'],
 'token': [u'6c367b3d3ec08fed211b51859359f8d054e263f0+\\']}
2015-02-17 10:44:08             api.py, 1316 in             submit: VERBOSE             response=
{u'servedby': u'mw1228', u'error': {'help': u'See https://de.wikipedia.org/w/api.php for API usage'}}
2015-02-17 10:44:08            page.py, 1056 in              _save: VERBOSE  Error saving page [[Wikipedia:Spielwiese]] (badtoken: Invalid token)
Traceback (most recent call last):
  File "/shared/pywikipedia/core/pywikibot/page.py", line 1047, in _save
    watch=watchval, bot=botflag, **kwargs)
  File "/shared/pywikipedia/core/pywikibot/site.py", line 1041, in callee
    return fn(self, *args, **kwargs)
  File "/shared/pywikipedia/core/pywikibot/site.py", line 4048, in editpage
    result = req.submit()
  File "/shared/pywikipedia/core/pywikibot/data/api.py", line 1318, in submit
    raise APIError(code, info, **result["error"])
APIError: badtoken: Invalid token

Why is the token always the same? The relevant part of the script:

def reset_sandbox()
      site = pywikibot.Site()                                                  
      site.login()                                                             
      sandboxPage = pywikibot.Page(site, sandboxTitle)                         
      sandboxPage.get(force=True, get_redirect=True)                           
      sandboxPage.text = sandboxDefault                                        
      sandboxPage.save(comment=comment, botflag=botflag, minor=False)

I previously used a shared site object, which causes the same errors.

Event Timeline

Sitic created this task.Feb 17 2015, 10:44 AM
Sitic updated the task description. (Show Details)
Sitic raised the priority of this task from to Needs Triage.
Sitic added a project: Pywikibot.
Sitic added a subscriber: Sitic.
Restricted Application added subscribers: Aklapper, Unknown Object (MLST). · View Herald TranscriptFeb 17 2015, 10:44 AM
XZise added a subscriber: XZise.EditedFeb 17 2015, 10:47 AM

This seems to be related to T61678? We've changed that the tokens are now cached but that was a few months ago so do you know which version you was using when it was still working?

This comment was removed by Sitic.

It was last started when the server on tools were rebooted on Tools (beginning of February I think), and ran flawlessly nonstop till the bug showed on 12. February. Might be more MediaWiki related bug, but I haven't seen any other reports.

Mpaa added a subscriber: Mpaa.Feb 17 2015, 7:39 PM

Does it make any difference if you do once single login() (maybe this is what you meant with shared site?):

site = pywikibot.Site()                                                  
site.login()

and then repeatedly call

def reset_sandbox()                                                           
      sandboxPage = pywikibot.Page(site, sandboxTitle)                         
      sandboxPage.get(force=True, get_redirect=True)                           
      sandboxPage.text = sandboxDefault                                        
      sandboxPage.save(comment=comment, botflag=botflag, minor=False)
Sitic added a comment.Feb 17 2015, 7:51 PM

Sorry, that was exactly what I meant by shared site (terrible wording).

Previously, the script only used self.site (with login once) and self.sandboxPage for everything, which worked fine untill this bug showed. I've changed it to the style shown in this bug report to avoid any possible issues. The original script is shown here (it's a bit messy, was my first pywikibot script back then).

Sitic closed this task as Declined.Feb 23 2015, 5:05 PM
Sitic claimed this task.

The script now works again when omitting

sandboxPage.get(force=True, get_redirect=True)

from the example in the bug report. The original working script still gets badtoken errors after it runs for some hours.

I've just seen the badtoken error on save while working on a completely unrelated script using a ipython notebook on my laptop with a pywikibot version from 13. January 2015.. site.logout() and then site.login() or a new site = pywikibot.Site() didn't help, all new edits got the badtoken error always showing the same csrf-token. Only site.tokens._tokens[u'AsuraBot'] = {} fixed the problem.

I'm surprised that I'm the only one who seems to get these errors frequently. I'm closing this bug here, it doesn't seem like a regression bug and the main bug seems to be T61678: Implement badtoken detection and recovery.

Sitic added a comment.Mar 3 2015, 10:46 PM

This seems to be the recent change that causes the sudden badtoken errors Village pump (technical)#How long does it take for a session timeout?:

The test fetching the edit token at the beginning and end of the run should certainly have not given you the same token each time; even fetching two tokens one second apart should give you two different tokens (but both valid) since the end of October. Since you got the same token hours apart, whatever you're using to fetch the tokens is apparently caching them rather than fetching a new one the second time.
Ideally, your bot should be able to attempt the edit, and if it gets a badtoken error it should automatically fetch a fresh token and retry the edit.
As for the time it takes, the configuration is currently using the default of 1 hour for $wgObjectCacheSessionExpiry. I don't see any recent changes to the timeout, but I do see there was this recent change to session handling that probably made page views no longer reset the session timer. Anomie⚔ 13:05, 3 March 2015 (UTC)

FWIW, I think we're seeing this same issue in one of our integration tests on the Android app. I haven't been able to get much detail on it yet though. The test's intention is to use the anonymous +\ token but it's possible there's a race condition with a separate test causing it to use something else.

Restricted Application added a subscriber: StudiesWorld. · View Herald TranscriptJan 13 2016, 7:58 PM

I also have a problem that seems related. I save the cookies from a login request and use them in subsequent runs of a bot. Previously, it would work fine for months on end. But in recent weeks/months the bot is no longer able to edit pages after a few hours of inactivity. According to an assert=user query, it's still logged in. But fetching a new csrf token and attempting to edit a page always fails with the error: badtoken: Invalid token. It works again after a new login.

jayvdb added a subscriber: jayvdb.Mar 16 2016, 4:56 AM

@Ghouston, this task was before pywikibot understood the badtoken response. pywikibot 2.0 or 3.0-dev now have badtoken handling. There may be bugs in it, or it might be some other problem. Please create a new task describing your problem. Also, if possible, it would be very helpful to know when it has started behaving different, as that will help us identify what pywikibot or mediawiki changes are relevant.

OK, I created T130091. I'm not using pywikibot, so that's not the issue.