Why do you think this has something to do with OAuth? The log just shows pywikibot retrying after the API returns a 'badtoken' response, as it's supposed to. I'm not sure why it's continuously failing, but that might have something to do with the multithreaded nature of your bot (two threads get a token, one uses them, the other gets a badtoken response).

In T125779#1997112, @valhallasw wrote:

Why do you think this has something to do with OAuth? The log just shows pywikibot retrying after the API returns a 'badtoken' response, as it's supposed to. I'm not sure why it's continuously failing, but that might have something to do with the multithreaded nature of your bot (two threads get a token, one uses them, the other gets a badtoken response).

Well, you cannot get an valid crsf token from an invalid oauth token. And no, multiprocessing should be irrelevant, as none of the upload attempts succeeded (the token being consumed). Even when only one process working, the same issues happen as well:

All upload attempts after this failed. However, it used to work anyways:

[2016-01-28 18:50:27,038: WARNING/Worker-14] -1: Configuring Pywikibot...
[2016-01-28 18:50:27,061: VERBOSE/Worker-14] Found 1 commons:commons processes running, including this one.
[2016-01-28 18:50:27,120: INFO/Worker-14] Starting new HTTPS connection (1): commons.wikimedia.org
[2016-01-28 18:50:27,358: WARNING/Worker-14] -1: Uploading...
[2016-01-28 18:50:27,374: WARNING/Worker-14] -1: Uploading...
[2016-01-28 18:50:27,905: INFO/Worker-14] Sleeping for 9.2 seconds, 2016-01-28 18:50:27
[2016-01-28 18:51:11,702: INFO/Worker-14] Upload successful.
[2016-01-28 18:51:11,758: WARNING/Worker-14] 100: Upload success!
[2016-01-28 18:51:11,762: WARNING/Worker-14] -1: Cleaning up...
[2016-01-28 18:51:11,875: WARNING/Worker-14] 100: Done!

And two processes uploading at the same time had happened and succeeded, though I can't find the entries in these 200M log

In case it's confusing, this in not really multithreading, but multiprocessing via os.fork():

Well, you cannot get an valid crsf token from an invalid oauth token.

In that case, I would expect an error 'Can't retrieve CSRF token, API returned ...' rather than a badtoken error -- or more specifically: I would expect a mwoauth-invalid-authorization error response, which would

raise NoUsername('Failed OAuth authentication for %s: %s'
                   % (self.site, info))

Can you run your script with -debug? That should create a log file in logs/ that shows the exact API requests made, and their response.

In T125779#1997288, @valhallasw wrote:

Can you run your script with -debug? That should create a log file in logs/ that shows the exact API requests made, and their response.

Is it possible to set this flag at runtime?

Probably. Pywikibot uses the logging module, which you can reconfigure the logging using the standard features it provides (see the python documentation), so running

import logging
logging.basicConfig(level=logging.DEBUG)

Whether you can also easily turn it off again: I don't know.

Ok, I'll try next time this happens. @Yann has already refreshed his oauth tokens, so the old invalid tokens are no longer accessible, as the tool stores oauth tokens nowhere except in redis session storage (already invalidated), redis celery broker (task queue, already popped), and in worker memory when the task is running (already SIGINT-ed).

Hmm... MediaWiki seems to return csrf tokens correctly, yet they are reported invalid:
(before this is a gigantic upload request of 64MB chunk)

2016-02-08 17:26:37             api.py, 1977 in             submit: DEBUG    API response received from commons:commons:
{"servedby":"mw1137","error":{"code":"badtoken","info":"Invalid token","*":"See https://commons.wikimedia.org/w/api.php for API usage"}}
2016-02-08 17:26:37             api.py, 2084 in             submit: WARNING  API error badtoken: Invalid token
2016-02-08 17:26:37             api.py, 2145 in             submit: VERBOSE  Bad token error for Sporti. Tokens for "csrf" used in request; invalidated them.
2016-02-08 17:26:37             api.py, 1944 in             submit: DEBUG    API request to commons:commons (uses get: False):
Headers: {u'Content-Type': u'application/x-www-form-urlencoded'}
URI: u'/w/api.php'
Body: 'maxlag=5&format=json&rawcontinue=&meta=tokens%7Cuserinfo&action=query&type=csrf&uiprop=blockinfo%7Chasmsg'
2016-02-08 17:26:37             api.py, 1977 in             submit: DEBUG    API response received from commons:commons:
{"query":{"tokens":{"csrftoken":"338b076f59e12239a5d3e0e23289883456b8cfcd+\\"},"userinfo":{"id":234501,"name":"Sporti"}}}

(Ctrl-C happened right after this)

Perhaps this is blocked by a MediaWiki-extensions-OAuth bug?

Perhaps this is blocked by a MediaWiki-extensions-OAuth bug?

I don't know much about pywikibot, but this doesn't seem likely. If OAuth was not correctly see the authorization, the you would get an OAuth error, not a session error.

Does pywikibot use OAuth for every api call? OAuth uses a slightly different session than a normal, cookie-based session, so mixing the two could give you unpredictable results.

We've been dealing with numerous session issues in the last week related to session manager, so there's a change you were simply logged out between getting the csrf token and using it?

Sorry, I was discussing this on irc #pywikibot and didn't see this responce. T126257: The API should not require CSRF tokens for an OAuth request was created during the discussion as a potential workaround.

Does pywikibot use OAuth for every api call? OAuth uses a slightly different session than a normal, cookie-based session, so mixing the two could give you unpredictable results.

Yes. I'm not entirely sure about cookies, but from the logs it seems every Api calls are OAuth-signed. @valhallasw you can explain this :)

We've been dealing with numerous session issues in the last week related to session manager, so there's a change you were simply logged out between getting the csrf token and using it?

Um, there's only a few seconds between the requests, with no other api requests in between (from the logs).

This is probably a session handling bug that will be fixed by https://gerrit.wikimedia.org/r/#/c/268702/ (or by deploying SessionManager, whichever happens first).

Yes. I'm not entirely sure about cookies, but from the logs it seems every Api calls are OAuth-signed. @valhallasw you can explain this :)

Well, I don't know the specific oauth implementation, but we do handle cookies as one would expect in a browser. There's a requests.session shared between all requests; it uses a cookie jar (programmatically accessible via pywikibot.comms.http.session.cookies) which in the default configuration is backed by the file pywikibot.comms.http.session.cookies.filename.

It might be interesting to dump the contents of the cookie (to check if the username is as expected), or to clear it using pywikibot.comms.http.session.cookies.clear(), but I'm not sure how much introspection you can do.