SocketTimeoutException from fetching number of images deleted

[misaochan]

Summary:

I logged in to Misaochan, went to Nearby, and the app crashed for me while I was searching for an image to upload to Nearby. Stack trace seems to point to getRevertRespObjectSingle() in ApacheHttpClientMediaWikiApi

Steps to reproduce:

Unsure of how to reproduce, it is not consistent. However, we should handle this exception more gracefully. I think catching it and outputting an error message is sufficient since that method is not essential (it's just used to get user revert rate). [Edit: After looking into it further, this is NOT true - this function is called whenever the user loads ContributionsActivity, and it is nonNull.]

Add System logs:

09-03 19:16:22.913 27648-27648/fr.free.nrw.commons W/System.err: Caused by: java.net.SocketTimeoutException: timeout
        at okhttp3.internal.http2.Http2Stream$StreamTimeout.newTimeoutException(Http2Stream.java:593)
        at okhttp3.internal.http2.Http2Stream$StreamTimeout.exitAndThrowIfTimedOut(Http2Stream.java:601)
09-03 19:16:22.914 27648-27648/fr.free.nrw.commons W/System.err:     at okhttp3.internal.http2.Http2Stream.takeResponseHeaders(Http2Stream.java:146)
        at okhttp3.internal.http2.Http2Codec.readResponseHeaders(Http2Codec.java:125)
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:88)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
09-03 19:16:22.915 27648-27648/fr.free.nrw.commons W/System.err:     at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
09-03 19:16:22.916 27648-27648/fr.free.nrw.commons W/System.err:     at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
09-03 19:16:22.917 27648-27648/fr.free.nrw.commons W/System.err:     at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126)
09-03 19:16:22.918 27648-27648/fr.free.nrw.commons W/System.err:     at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
        at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:200)
        at okhttp3.RealCall.execute(RealCall.java:77)
09-03 19:16:22.919 27648-27648/fr.free.nrw.commons W/System.err:     at fr.free.nrw.commons.mwapi.ApacheHttpClientMediaWikiApi.lambda$getRevertRespObjectSingle$5$ApacheHttpClientMediaWikiApi(ApacheHttpClientMediaWikiApi.java:1018)
        at fr.free.nrw.commons.mwapi.ApacheHttpClientMediaWikiApi$$Lambda$9.call(Unknown Source:4)
        at io.reactivex.internal.operators.single.SingleFromCallable.subscribeActual(SingleFromCallable.java:35)
09-03 19:16:22.920 27648-27648/fr.free.nrw.commons W/System.err:     at io.reactivex.Single.subscribe(Single.java:2700)
        at com.tspoon.traceur.SingleOnAssembly.subscribeActual(SingleOnAssembly.java:43)
        at io.reactivex.Single.subscribe(Single.java:2700)
        at io.reactivex.internal.operators.single.SingleSubscribeOn$SubscribeOnObserver.run(SingleSubscribeOn.java:89)
09-03 19:16:22.921 27648-27648/fr.free.nrw.commons W/System.err:     at io.reactivex.Scheduler$DisposeTask.run(Scheduler.java:452)
        at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:61)
09-03 19:16:22.922 27648-27648/fr.free.nrw.commons W/System.err:     at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:52)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
09-03 19:16:22.923 27648-27648/fr.free.nrw.commons W/System.err:     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
        at java.lang.Thread.run(Thread.java:764)
09-03 19:16:22.924 27648-27648/fr.free.nrw.commons W/System.err: Caused by: com.tspoon.traceur.TraceurException: Debug Exception generated at call site
        at dalvik.system.VMStack.getThreadStackTrace(Native Method)
        at java.lang.Thread.getStackTrace(Thread.java:1536)
        at io.reactivex.Single.fromCallable(Single.java:448)
09-03 19:16:22.925 27648-27648/fr.free.nrw.commons W/System.err:     at fr.free.nrw.commons.mwapi.ApacheHttpClientMediaWikiApi.getRevertRespObjectSingle(ApacheHttpClientMediaWikiApi.java:1005)
        at fr.free.nrw.commons.quiz.QuizChecker.setRevertCount(QuizChecker.java:92)
        at fr.free.nrw.commons.quiz.QuizChecker.<init>(QuizChecker.java:55)
09-03 19:16:22.926 27648-27648/fr.free.nrw.commons W/System.err:     at fr.free.nrw.commons.contributions.ContributionsActivity.onCreate(ContributionsActivity.java:152)
        at android.app.Activity.performCreate(Activity.java:7174)
        at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1220)
09-03 19:16:22.927 27648-27648/fr.free.nrw.commons W/System.err:     at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2910)
        at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:3032)
        at android.app.ActivityThread.-wrap11(Unknown Source:0)
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1696)
09-03 19:16:22.928 27648-27648/fr.free.nrw.commons W/System.err:     at android.os.Handler.dispatchMessage(Handler.java:105)
        at android.os.Looper.loop(Looper.java:164)
        at android.app.ActivityThread.main(ActivityThread.java:6944)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327)
09-03 19:16:22.929 27648-27648/fr.free.nrw.commons W/System.err:     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)
09-03 19:16:22.930 27648-27648/fr.free.nrw.commons W/System.err: Caused by: com.tspoon.traceur.TraceurException: Debug Exception generated at call site
        at dalvik.system.VMStack.getThreadStackTrace(Native Method)
        at java.lang.Thread.getStackTrace(Thread.java:1536)
09-03 19:16:22.931 27648-27648/fr.free.nrw.commons W/System.err:     at io.reactivex.Single.subscribeOn(Single.java:2768)
        at fr.free.nrw.commons.quiz.QuizChecker.setRevertCount(QuizChecker.java:93)
09-03 19:16:22.932 27648-27648/fr.free.nrw.commons W/System.err: 	... 14 more
    Caused by: com.tspoon.traceur.TraceurException: Debug Exception generated at call site
09-03 19:16:22.933 27648-27648/fr.free.nrw.commons W/System.err:     at dalvik.system.VMStack.getThreadStackTrace(Native Method)
        at java.lang.Thread.getStackTrace(Thread.java:1536)
        at io.reactivex.Single.observeOn(Single.java:2296)
        at fr.free.nrw.commons.quiz.QuizChecker.setRevertCount(QuizChecker.java:94)
09-03 19:16:22.934 27648-27648/fr.free.nrw.commons W/System.err: 	... 14 more
09-03 19:16:22.946 3646-8649/? W/ActivityManager: crash : fr.free.nrw.commons,0
09-03 19:16:22.948 3646-8649/? W/ActivityManager:   Force finishing activity fr.free.nrw.commons/.nearby.NearbyActivity

Device and Android version:

Android 8.0 Samsung Galaxy s7

Commons app version:

#1875 which is based on 2.8-release, but the error does not appear to be relevant to that PR at all, just coincidence

Would you like to work on the issue?

Pref not

[misaochan]

Ugh, I just checked our Google Play stats and this appears to be a major cause of crashes - 60+ reports in the last 7 days. Unfortunately it seems that if we don't have time to find an ideal solution, we will have to remove the quiz checker in 2.8.3 and reinstate it once an ideal solution is found.

Full stacktrace:

Report 1

io.reactivex.exceptions.OnErrorNotImplementedException: 
  at io.reactivex.internal.functions.Functions$OnErrorMissingConsumer.accept (Functions.java:704)
  at io.reactivex.internal.functions.Functions$OnErrorMissingConsumer.accept (Functions.java:701)
  at io.reactivex.internal.observers.ConsumerSingleObserver.onError (ConsumerSingleObserver.java:45)
  at com.tspoon.traceur.SingleOnAssembly$OnAssemblySingleObserver.onError (SingleOnAssembly.java:75)
  at io.reactivex.internal.operators.single.SingleObserveOn$ObserveOnSingleObserver.run (SingleObserveOn.java:79)
  at io.reactivex.android.schedulers.HandlerScheduler$ScheduledRunnable.run (HandlerScheduler.java:109)
  at android.os.Handler.handleCallback (Handler.java:754)
  at android.os.Handler.dispatchMessage (Handler.java:95)
  at android.os.Looper.loop (Looper.java:163)
  at android.app.ActivityThread.main (ActivityThread.java:6228)
  at java.lang.reflect.Method.invoke (Native Method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run (ZygoteInit.java:904)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:794)
Caused by: java.net.UnknownHostException: 
  at java.net.Inet6AddressImpl.lookupHostByName (Inet6AddressImpl.java:95)
  at java.net.Inet6AddressImpl.lookupAllHostAddr (Inet6AddressImpl.java:74)
  at java.net.InetAddress.getAllByName (InetAddress.java:752)
  at okhttp3.Dns$1.lookup (Dns.java:40)
  at okhttp3.internal.connection.RouteSelector.resetNextInetSocketAddress (RouteSelector.java:185)
  at okhttp3.internal.connection.RouteSelector.nextProxy (RouteSelector.java:149)
  at okhttp3.internal.connection.RouteSelector.next (RouteSelector.java:84)
  at okhttp3.internal.connection.StreamAllocation.findConnection (StreamAllocation.java:214)
  at okhttp3.internal.connection.StreamAllocation.findHealthyConnection (StreamAllocation.java:135)
  at okhttp3.internal.connection.StreamAllocation.newStream (StreamAllocation.java:114)
  at okhttp3.internal.connection.ConnectInterceptor.intercept (ConnectInterceptor.java:42)
  at okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.java:147)
  at okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.java:121)
  at okhttp3.internal.cache.CacheInterceptor.intercept (CacheInterceptor.java:93)
  at okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.java:147)
  at okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.java:121)
  at okhttp3.internal.http.BridgeInterceptor.intercept (BridgeInterceptor.java:93)
  at okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.java:147)
  at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept (RetryAndFollowUpInterceptor.java:126)
  at okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.java:147)
  at okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.java:121)
  at okhttp3.RealCall.getResponseWithInterceptorChain (RealCall.java:200)
  at okhttp3.RealCall.execute (RealCall.java:77)
  at fr.free.nrw.commons.mwapi.ApacheHttpClientMediaWikiApi.lambda$getRevertRespObjectSingle$5$ApacheHttpClientMediaWikiApi (ApacheHttpClientMediaWikiApi.java:1009)
  at fr.free.nrw.commons.mwapi.ApacheHttpClientMediaWikiApi$$Lambda$9.call (Unknown Source)
  at io.reactivex.internal.operators.single.SingleFromCallable.subscribeActual (SingleFromCallable.java:35)
  at io.reactivex.Single.subscribe (Single.java:2700)
  at com.tspoon.traceur.SingleOnAssembly.subscribeActual (SingleOnAssembly.java:43)
  at io.reactivex.Single.subscribe (Single.java:2700)
  at io.reactivex.internal.operators.single.SingleSubscribeOn$SubscribeOnObserver.run (SingleSubscribeOn.java:89)
  at io.reactivex.Scheduler$DisposeTask.run (Scheduler.java:452)
  at io.reactivex.internal.schedulers.ScheduledRunnable.run (ScheduledRunnable.java:61)
  at io.reactivex.internal.schedulers.ScheduledRunnable.call (ScheduledRunnable.java:52)
  at java.util.concurrent.FutureTask.run (FutureTask.java:237)
  at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run (ScheduledThreadPoolExecutor.java:272)
  at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1133)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:607)
  at java.lang.Thread.run (Thread.java:760)
Caused by: com.tspoon.traceur.TraceurException: 
  at dalvik.system.VMStack.getThreadStackTrace (Native Method)
  at java.lang.Thread.getStackTrace (Thread.java:1565)
  at io.reactivex.Single.fromCallable (Single.java:448)
  at fr.free.nrw.commons.mwapi.ApacheHttpClientMediaWikiApi.getRevertRespObjectSingle (ApacheHttpClientMediaWikiApi.java:996)
  at fr.free.nrw.commons.quiz.QuizChecker.setRevertCount (QuizChecker.java:92)
  at fr.free.nrw.commons.quiz.QuizChecker.<init> (QuizChecker.java:55)
  at fr.free.nrw.commons.contributions.ContributionsActivity.onCreate (ContributionsActivity.java:152)
  at android.app.Activity.performCreate (Activity.java:6860)
  at android.app.Instrumentation.callActivityOnCreate (Instrumentation.java:1119)
  at android.app.ActivityThread.performLaunchActivity (ActivityThread.java:2674)
  at android.app.ActivityThread.handleLaunchActivity (ActivityThread.java:2782)
  at android.app.ActivityThread.-wrap12 (ActivityThread.java)
  at android.app.ActivityThread$H.handleMessage (ActivityThread.java:1521)
  at android.os.Handler.dispatchMessage (Handler.java:102)
  at android.os.Looper.loop (Looper.java:163)
  at android.app.ActivityThread.main (ActivityThread.java:6228)
  at java.lang.reflect.Method.invoke (Native Method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run (ZygoteInit.java:904)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:794)
Caused by: com.tspoon.traceur.TraceurException: 
  at dalvik.system.VMStack.getThreadStackTrace (Native Method)
  at java.lang.Thread.getStackTrace (Thread.java:1565)
  at io.reactivex.Single.subscribeOn (Single.java:2768)
  at fr.free.nrw.commons.quiz.QuizChecker.setRevertCount (QuizChecker.java:93)
Caused by: com.tspoon.traceur.TraceurException: 
  at dalvik.system.VMStack.getThreadStackTrace (Native Method)
  at java.lang.Thread.getStackTrace (Thread.java:1565)
  at io.reactivex.Single.observeOn (Single.java:2296)
  at fr.free.nrw.commons.quiz.QuizChecker.setRevertCount (QuizChecker.java:94)

[nicolas-raoul]

How catching the exception and such cases considering that the quiz is not needed (which is the less intrusive option)?

[misaochan]

@nicolas-raoul The main problem with doing that is, what do we return as the value of Single<JSONObject> getRevertRespObjectSingle() in the case of client.newCall(request).execute(); timing out? The function is @NonNull so it will not be as simple as returning null. Certainly still doable but would take more time and going through more of the code.

[misaochan]

I created a PR. If anyone wants to take this up and fix the crash properly (please bear in mind that you cannot just ignore the timeout or return null), please feel free. We can re-release the quiz as soon as it is fixed.

[neslihanturan]

@misaochan I have read the comments and your PR but, couldn't understand why we cannot just catch the exception and cancel quiz if caught. Can you please explain in more detail?

[ashishkumar468]

@misaochan I had the same doubt as @neslihanturan. Why cant we just handle the exception and delegate the flow accordingly, ie. log the exception for reference purposes and maybe set isRevertCountFetched=false [Just to stay safe] ensuring that callQuiz() is never called. Is there something I am missing ?

[maskaravivek]

I have added a PR refactoring some of the error-prone code pieces. Will take a final look at these modules tomorrow and makes any changes if necessary. The basic flow works well.

PS: Personally I was feeling bad about reverting some of @tanvidadu's changes so I decided to pitch in. :)