Upload failures after v2.8

[misaochan]

It seems that we are still encountering upload failures after 2.8, albeit with much lower frequency. I had them today when testing #1968 (however, I created this issue because I don't think it is relevant to that PR, which doesn't alter the auth flow), and had them once on my real device recently.

Logs below from API 27 Nexus S emulator. Interestingly, after seeing this failure, I checked Achievements to see if I was indeed not logged in. However, Achievements works perfectly fine! So my conclusion is that it is the edit tokens that are the issue, not the actual login. @maskaravivek

11-19 18:40:27.026 30937-30980/fr.free.nrw.commons D/UploadService: Before execution!
11-19 18:40:27.044 30937-30980/fr.free.nrw.commons D/UploadService: making sure of uniqueness of name: Michio Kaku .jpg
11-19 18:40:27.362 30937-31499/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api batchcomplete=""><query><pages><page _idx="-1" ns="0" title="Michio Kaku .jpg" missing=""/></pages></query></api>
11-19 18:40:27.947 30937-31499/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api batchcomplete=""><query><pages><page _idx="-1" ns="0" title="Michio Kaku.jpg" missing=""/></pages></query></api>
11-19 18:40:28.068 30937-30980/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api batchcomplete=""><query><pages><page _idx="-1" ns="6" title="File:Michio Kaku .jpg" missing="" imagerepository=""/></pages></query></api>
11-19 18:40:28.558 30937-30980/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api batchcomplete=""><query><userinfo id="0" name="[IP address]" anon=""/></query></api>
11-19 18:40:28.583 30937-30980/fr.free.nrw.commons D/CustomMwApi: User id is 0 and user name is [IP address]
11-19 18:40:28.584 30937-30980/fr.free.nrw.commons D/ApacheHttpClientMediaWi: Validate login response is false
11-19 18:40:28.585 30937-30980/fr.free.nrw.commons D/UploadService: Successfully revalidated token!
11-19 18:40:29.292 30937-30980/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api servedby="mw1345"><error code="notloggedin" info="Anonymous users cannot obtain a centralauthtoken." xml:space="preserve">See https://commons.wikimedia.org/w/api.php for API usage. Subscribe to the mediawiki-api-announce mailing list at &amp;lt;https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce&amp;gt; for notice of API deprecations and breaking changes.</error></api>
11-19 18:40:29.306 30937-30980/fr.free.nrw.commons D/ApacheHttpClientMediaWi: MediaWiki Central auth token is 
11-19 18:40:29.321 30937-30980/fr.free.nrw.commons E/ApacheHttpClientMediaWi: Error occurred while fetching auth token. Error code is notloggedin and message is Anonymous users cannot obtain a centralauthtoken.
11-19 18:40:29.796 30937-30980/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api servedby="mw1343"><error code="notloggedin" info="Anonymous users cannot obtain a centralauthtoken." xml:space="preserve">See https://commons.wikimedia.org/w/api.php for API usage. Subscribe to the mediawiki-api-announce mailing list at &amp;lt;https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce&amp;gt; for notice of API deprecations and breaking changes.</error></api>
11-19 18:40:29.802 30937-30980/fr.free.nrw.commons D/ApacheHttpClientMediaWi: MediaWiki Central auth token is 
11-19 18:40:29.816 30937-30980/fr.free.nrw.commons E/ApacheHttpClientMediaWi: Error occurred while fetching auth token. Error code is notloggedin and message is Anonymous users cannot obtain a centralauthtoken.
11-19 18:40:30.305 30937-30980/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api servedby="mw1317"><error code="badtoken" info="The centralauthtoken is not valid." xml:space="preserve">See https://commons.wikimedia.org/w/api.php for API usage. Subscribe to the mediawiki-api-announce mailing list at &amp;lt;https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce&amp;gt; for notice of API deprecations and breaking changes.</error></api>
11-19 18:40:30.335 30937-30980/fr.free.nrw.commons D/ApacheHttpClientMediaWi: MediaWiki edit token is 
11-19 18:40:30.499 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 26531 of 794431
11-19 18:40:30.539 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 51107 of 794431
11-19 18:40:30.575 26161-26161/system_process E/NotificationService: Muting recently noisy 0|fr.free.nrw.commons|1|null|10090
11-19 18:40:30.628 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 75683 of 794431
11-19 18:40:30.717 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 100259 of 794431
11-19 18:40:30.906 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 124835 of 794431
11-19 18:40:31.253 30937-30969/fr.free.nrw.commons I/zygote: Waiting for a blocking GC Explicit
11-19 18:40:31.296 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 149411 of 794431
11-19 18:40:31.435 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 173987 of 794431
11-19 18:40:31.580 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 198563 of 794431
11-19 18:40:31.599 30937-30949/fr.free.nrw.commons I/zygote: Background concurrent copying GC freed 117135(5MB) AllocSpace objects, 38(760KB) LOS objects, 43% free, 7MB/13MB, paused 681us total 1.005s
11-19 18:40:31.599 30937-30969/fr.free.nrw.commons I/zygote: WaitForGcToComplete blocked Explicit on HeapTrim for 346.940ms
11-19 18:40:31.695 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 223139 of 794431
11-19 18:40:31.783 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 247715 of 794431
11-19 18:40:31.884 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 272291 of 794431
11-19 18:40:32.072 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 296867 of 794431
11-19 18:40:32.300 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 321443 of 794431
11-19 18:40:32.337 30937-30969/fr.free.nrw.commons I/zygote: Explicit concurrent copying GC freed 28046(1214KB) AllocSpace objects, 0(0B) LOS objects, 45% free, 7MB/13MB, paused 3.833ms total 736.588ms
11-19 18:40:32.399 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 346019 of 794431
11-19 18:40:32.485 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 370595 of 794431
11-19 18:40:32.746 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 395171 of 794431
11-19 18:40:32.761 30937-31500/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api batchcomplete=""><query><pages><page _idx="-1" ns="0" title="Michio Kaku .jpg" missing=""/></pages></query></api>
11-19 18:40:32.876 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 419747 of 794431
11-19 18:40:33.017 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 444323 of 794431
11-19 18:40:33.260 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 468899 of 794431
11-19 18:40:33.557 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 493475 of 794431
11-19 18:40:33.885 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 518051 of 794431
11-19 18:40:34.065 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 542627 of 794431
11-19 18:40:34.120 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 567203 of 794431
11-19 18:40:34.305 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 591779 of 794431
11-19 18:40:34.437 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 616355 of 794431
11-19 18:40:34.500 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 640931 of 794431
11-19 18:40:34.573 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 665507 of 794431
11-19 18:40:34.794 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 690083 of 794431
11-19 18:40:35.181 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 714659 of 794431
11-19 18:40:35.327 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 739235 of 794431
11-19 18:40:35.516 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 763811 of 794431
11-19 18:40:35.649 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 788387 of 794431
11-19 18:40:35.652 30937-31499/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api batchcomplete=""><query><pages><page _idx="-1" ns="0" title="Michio Kaku .jpg" missing=""/></pages></query></api>
11-19 18:40:35.746 30937-30980/fr.free.nrw.commons D/UploadService$Notificat: Uploaded 794431 of 794431
11-19 18:40:36.822 30937-31499/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api batchcomplete=""><query><pages><page _idx="-1" ns="0" title="Michio Kaku.jpg" missing=""/></pages></query></api>
11-19 18:40:37.338 30937-31499/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api batchcomplete=""><query><pages><page _idx="-1" ns="0" title="Michio Kaku .jpg" missing=""/></pages></query></api>
11-19 18:40:37.876 30937-31499/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api batchcomplete=""><query><pages><page _idx="-1" ns="0" title="Michio Kaku .jpg" missing=""/></pages></query></api>
11-19 18:40:38.070 30937-30980/fr.free.nrw.commons D/CustomApiResult: API response is
     <?xml version="1.0" encoding="UTF-8"?><api servedby="mw1223"><error code="badtoken" info="The centralauthtoken is not valid." xml:space="preserve">See https://commons.wikimedia.org/w/api.php for API usage. Subscribe to the mediawiki-api-announce mailing list at &amp;lt;https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce&amp;gt; for notice of API deprecations and breaking changes.</error></api>
11-19 18:40:38.072 30937-30980/fr.free.nrw.commons E/ApacheHttpClientMediaWi: Result: fr.free.nrw.commons.mwapi.CustomApiResult@6dbe234
11-19 18:40:35.821 26161-26161/system_process E/NotificationService: Muting recently noisy 0|fr.free.nrw.commons|1|null|10090
11-19 18:40:38.164 30937-30980/fr.free.nrw.commons E/ApacheHttpClientMediaWi: badtoken

[VojtechDostal]

Yep I had some upload failures yesterday.

[misaochan]

@VojtechDostal Logging in and out again works for you, right? As a short-term measure we could add that suggestion to a "Failed upload" toast via #1556 so that other users aren't stuck not knowing what to do.

We will do an overhaul of the authentication flow in the next PG if approved.

[cascafico]

Logout and login doesn't solve upload failure, which happen say 2 out of 3 attempts.

[misaochan]

@cascafico Hmm, interesting, so the failures are not constant for you? Are you in beta testing? If you are, could you please go to Settings > Send Logs > enable the permissions. Then restart app > try to upload > tap Send Logs again after you experience a failure? This will help us debug the cause of the failure for you.

Thanks!

[misaochan]

Thanks for the logs. This is very strange, it is a badtoken error as well, but this is the first one I have seen that relogging does not fix.

@maskaravivek Could you please take a look at the logs as well? Thanks.

[misaochan]

Btw, @cascafico , do you have 2FA enabled on your account by any chance?

[cascafico]

No, I don't

[ashishkumar468]

@misaochan @maskaravivek @nicolas-raoul I was working on the upload issue, refactored the LoginActivity and UploadService, but none of it could actually solve the bad token issue. After debugging a lot, I could produce it and found that, even after fetching fresh c-auth token, we get a bad token error as if we are not logged in. I was hoping that some one who has more experience with the api's could suggest me a better approach to this. I would also recommend that we pick up a task of refactoring the network layer as it the code base it to coupled and prone to bugs.