Sitic created this task. Sitic added a subscriber: Sitic. Sitic added a project: pywikibot-core. Restricted Application added subscribers: Aklapper, pywikipedia-bugs.
TASK 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.
TASK DETAIL https://phabricator.wikimedia.org/T89702
REPLY HANDLER ACTIONS Reply to comment or attach files, or !close, !claim, !unsubscribe or !assign <username>.
EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/
To: Sitic Cc: pywikipedia-bugs, Aklapper, Sitic, jayvdb
XZise added a subscriber: XZise. XZise added a comment.
This is probably related to https://phabricator.wikimedia.org/T61678 I'd guess? 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?
TASK DETAIL https://phabricator.wikimedia.org/T89702
REPLY HANDLER ACTIONS Reply to comment or attach files, or !close, !claim, !unsubscribe or !assign <username>.
EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/
To: XZise Cc: XZise, Aklapper, Sitic, jayvdb, pywikipedia-bugs
Sitic added a comment.
Related to T61678: Implement badtoken detection and recovery https://phabricator.wikimedia.org/T61678.
TASK DETAIL https://phabricator.wikimedia.org/T89702
REPLY HANDLER ACTIONS Reply to comment or attach files, or !close, !claim, !unsubscribe or !assign <username>.
EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/
To: Sitic Cc: XZise, Aklapper, Sitic, jayvdb, pywikipedia-bugs
Sitic added a comment.
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.
TASK DETAIL https://phabricator.wikimedia.org/T89702
REPLY HANDLER ACTIONS Reply to comment or attach files, or !close, !claim, !unsubscribe or !assign <username>.
EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/
To: Sitic Cc: XZise, Aklapper, Sitic, jayvdb, pywikipedia-bugs
Mpaa added a subscriber: Mpaa. Mpaa added a comment.
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)
TASK DETAIL https://phabricator.wikimedia.org/T89702
REPLY HANDLER ACTIONS Reply to comment or attach files, or !close, !claim, !unsubscribe or !assign <username>.
EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/
To: Mpaa Cc: Mpaa, XZise, Aklapper, Sitic, jayvdb, pywikipedia-bugs
Sitic added a comment.
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 https://github.com/sitic/AsuraBot/blob/master/Rahu.py (it's a bit messy, was my first pywikibot script back then).
TASK DETAIL https://phabricator.wikimedia.org/T89702
REPLY HANDLER ACTIONS Reply to comment or attach files, or !close, !claim, !unsubscribe or !assign <username>.
EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/
To: Sitic Cc: Mpaa, XZise, Aklapper, Sitic, jayvdb, pywikipedia-bugs
Sitic closed this task as "Declined". Sitic claimed this task. Sitic added a comment.
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 https://phabricator.wikimedia.org/T61678.
TASK DETAIL https://phabricator.wikimedia.org/T89702
REPLY HANDLER ACTIONS Reply to comment or attach files, or !close, !claim, !unsubscribe or !assign <username>.
EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/
To: Sitic Cc: Mpaa, XZise, Aklapper, Sitic, jayvdb, pywikipedia-bugs
Sitic added a comment.
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? https://en.wikipedia.org/w/index.php?title=Wikipedia:Village_pump_(technical)&oldid=649751259#How_long_does_it_take_for_a_session_timeout.3F:
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)
TASK DETAIL https://phabricator.wikimedia.org/T89702
REPLY HANDLER ACTIONS Reply to comment or attach files, or !close, !claim, !unsubscribe or !assign <username>.
EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/
To: Sitic Cc: Mpaa, XZise, Aklapper, Sitic, jayvdb, pywikipedia-bugs
pywikipedia-bugs@lists.wikimedia.org