search

square / okhttp

Square’s meticulous HTTP client for the JVM, Android, and GraalVM.
https://square.github.io/okhttp/
Apache License 2.0
45.69k stars 9.14k forks source link

5.0.0-alpha.5 regression #7129

Closed slavonnet closed 2 years ago

slavonnet commented 2 years ago

Android 6.0

In log exception

  java.net.SocketException: recvfrom failed: ETIMEDOUT (Connection timed out)
        at libcore.io.IoBridge.maybeThrowAfterRecvfrom(IoBridge.java:625)
        at libcore.io.IoBridge.recvfrom(IoBridge.java:587)
        at java.net.PlainSocketImpl.read(PlainSocketImpl.java:488)
        at java.net.PlainSocketImpl.-wrap0(PlainSocketImpl.java)
        at java.net.PlainSocketImpl$PlainSocketInputStream.read(PlainSocketImpl.java:242)
        at okio.InputStreamSource.read(JvmOkio.kt:94)
        at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:125)
        at okio.RealBufferedSource.indexOf(RealBufferedSource.kt:427)
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:320)
        at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29)
        at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:178)
        at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:111)
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:93)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:96)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:75)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.cisystems.ssmp.arm_vmb2.okhttp.CacheSaveInterceptor.intercept(CacheSaveInterceptor.kt:81)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.cisystems.ssmp.arm_vmb2.okhttp.GZIPResponseInterceptor.intercept(GZIPResponseInterceptor.kt:14)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.cisystems.ssmp.arm_vmb2.okhttp.OnlineOfflineInterceptor.intercept(OnlineOfflineInterceptor.kt:29)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.cisystems.ssmp.arm_vmb2.okhttp.OnlineOfflineInterceptorAfterGzip.intercept(OnlineOfflineInterceptorAfterGzip.kt:28)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.cisystems.ssmp.arm_vmb2.okhttp.MyHttpInterceptorResponse.intercept(MyHttpInterceptorResponse.kt:113)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.cisystems.ssmp.arm_vmb2.okhttp.MyHttpInterceptorRequest.intercept(MyHttpInterceptorRequest.kt:156)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.cisystems.ssmp.arm_vmb2.okhttp.GZIPRequestInterceptor.intercept(GZIPRequestInterceptor.kt:9)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.cisystems.ssmp.arm_vmb2.okhttp.UserAgentInterceptor.intercept(UserAgentInterceptor.kt:21)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.cisystems.ssmp.arm_vmb2.okhttp.CacheSaveInterceptor.intercept(CacheSaveInterceptor.kt:81)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:205)
        at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:533)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
        at java.lang.Thread.run(Thread.java:818)
     Caused by: android.system.ErrnoException: recvfrom failed: ETIMEDOUT (Connection timed out)
        at libcore.io.Posix.recvfromBytes(Native Method)
        at libcore.io.Posix.recvfrom(Posix.java:189)
        at libcore.io.Bl
2022-02-28 09:27:59.375 26711-26711/com.cisystems.ssmp.arm_vmb2 W/CacheSave: Unable to resolve host "ssmpdev.regeora.ru": No address associated with hostname

but GZIPResponseInterceptor.kt:141 have try/catch that is ignored

yschimke commented 2 years ago

Not sure we can help with GZIPResponseInterceptor since it's your class. But is this a regression you've observed from 4.9.3 to 5.0.0-alpha05?

Will assume it's an issue on your end if we don't hear back, but love to find out early about any observable problems after 5 upgrade.

slavonnet commented 2 years ago

bug in dns resolver. Any restart app one random connect not resolve host. And its specific to 6.0 android abi

swankjesse commented 2 years ago

I wonder if we can reproduce a behavior change? There's a lot that's moved around on recovery after connections fail, though I would have guessed this wouldn't have retried in 4.9.3 either

Lets try to create a test that reproduces this crash in 5.x but not in 4.x.

slavonnet commented 2 years ago

Looks like device issue or Android studio debugger

slavonnet commented 2 years ago 

2022-02-28 17:05:52.650 12629-12731/com.cisystems.ssmp.arm_vmb2 I/System.out: [CDS][DNS] getAllByNameImpl netId = 0
2022-02-28 17:05:52.650 12629-12731/com.cisystems.ssmp.arm_vmb2 D/libc-netbsd: [getaddrinfo]: hostname=ssmpdev.regeora.ru; servname=(null); netid=0; mark=0
2022-02-28 17:05:52.650 12629-12731/com.cisystems.ssmp.arm_vmb2 D/libc-netbsd: [getaddrinfo]: ai_addrlen=0; ai_canonname=(null); ai_flags=4; ai_family=0
2022-02-28 17:05:52.651 12629-12731/com.cisystems.ssmp.arm_vmb2 D/libc-netbsd: [getaddrinfo]: hostname=ssmpdev.regeora.ru; servname=(null); netid=0; mark=0
2022-02-28 17:05:52.651 12629-12731/com.cisystems.ssmp.arm_vmb2 D/libc-netbsd: [getaddrinfo]: ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0
2022-02-28 17:05:53.393 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 36, 0, 236, 512
2022-02-28 17:05:53.402 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 216, 228, 19, 23
2022-02-28 17:05:54.131 12629-12629/com.cisystems.ssmp.arm_vmb2 D/SettingsInterface:  from settings cache , name = sound_effects_enabled , value = 0
2022-02-28 17:05:54.205 12629-12640/com.cisystems.ssmp.arm_vmb2 I/art: Background sticky concurrent mark sweep GC freed 37641(1821KB) AllocSpace objects, 0(0B) LOS objects, 5% free, 27MB/29MB, paused 7.864ms total 51.332ms
2022-02-28 17:05:54.302 12629-12681/com.cisystems.ssmp.arm_vmb2 I/art: Note: end time exceeds epoch: 
2022-02-28 17:05:54.309 12629-12629/com.cisystems.ssmp.arm_vmb2 V/InputMethodManager: START INPUT: com.google.android.material.internal.NavigationMenuView{eb8c659 VFED.V... .F...... 0,0-704,1208 #7f08017f app:id/design_navigation_view} ic=null tba=android.view.inputmethod.EditorInfo@ad36aea controlFlags=#100
2022-02-28 17:05:54.313 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 36, 23, 237, 381
2022-02-28 17:05:54.356 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 36, 31, 201, 345
2022-02-28 17:05:54.451 12629-12629/com.cisystems.ssmp.arm_vmb2 I/art: Note: end time exceeds epoch: 
2022-02-28 17:05:54.603 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 36, 0, 260, 508
2022-02-28 17:05:54.613 12629-12629/com.cisystems.ssmp.arm_vmb2 V/InputMethodManager: START INPUT: androidx.viewpager2.widget.ViewPager2$RecyclerViewImpl{381cae7 VFED..... .F...... 0,0-800,908 #1} ic=null tba=android.view.inputmethod.EditorInfo@8809966 controlFlags=#100
2022-02-28 17:05:55.471 12629-12629/com.cisystems.ssmp.arm_vmb2 D/SettingsInterface:  from settings cache , name = sound_effects_enabled , value = 0
2022-02-28 17:05:55.630 12629-12629/com.cisystems.ssmp.arm_vmb2 V/InputMethodManager: START INPUT: androidx.drawerlayout.widget.DrawerLayout{edb0d3d VFED..... .F...... 0,0-800,1208 #7f0801bc app:id/drawer_layout} ic=null tba=android.view.inputmethod.EditorInfo@6dc0052 controlFlags=#100
2022-02-28 17:05:55.634 12629-12629/com.cisystems.ssmp.arm_vmb2 D/ActivityThread: SVC-UNBIND_SERVICE handled : 0 / BindServiceData{token=android.os.BinderProxy@95ce0a intent=Intent { act=com.google.android.gms.measurement.START cmp=com.cisystems.ssmp.arm_vmb2/com.google.android.gms.measurement.AppMeasurementService }}
2022-02-28 17:05:55.634 12629-12629/com.cisystems.ssmp.arm_vmb2 D/ActivityThread: SVC-Destroying service: com.google.android.gms.measurement.AppMeasurementService@5939c98
2022-02-28 17:05:55.634 12629-12629/com.cisystems.ssmp.arm_vmb2 V/FA: Local AppMeasurementService is shutting down
2022-02-28 17:05:55.634 12629-12629/com.cisystems.ssmp.arm_vmb2 D/ActivityThread: SVC-STOP_SERVICE handled : 0 / android.os.BinderProxy@95ce0a
2022-02-28 17:05:55.642 12629-12629/com.cisystems.ssmp.arm_vmb2 V/getNow: Get time from getNow!
2022-02-28 17:05:55.703 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: ~CanvasContext() 0x7f8e469800
2022-02-28 17:05:55.825 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.006817325537522
2022-02-28 17:05:55.838 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.012830620078855
2022-02-28 17:05:55.838 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.012830620078855
2022-02-28 17:05:55.838 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.000004924673617
2022-02-28 17:05:55.838 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.000004924673617
2022-02-28 17:05:55.838 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.0000025596289195
2022-02-28 17:05:55.838 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.000000764162132
2022-02-28 17:05:55.838 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.000000764162132
2022-02-28 17:05:55.838 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.000003332001458
2022-02-28 17:05:55.838 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.000000764162132
2022-02-28 17:05:55.839 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.006416183379478
2022-02-28 17:05:55.839 12629-12629/com.cisystems.ssmp.arm_vmb2 W/PathParser: Points are too far apart 4.000000764162132
2022-02-28 17:05:55.848 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 36, 0, 277, 501
2022-02-28 17:05:55.911 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 216, 117, 97, 367
2022-02-28 17:05:57.529 12629-12629/com.cisystems.ssmp.arm_vmb2 D/SettingsInterface:  from settings cache , name = sound_effects_enabled , value = 0
2022-02-28 17:05:57.833 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 216, 0, 133, 503
2022-02-28 17:05:57.939 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 36, 0, 328, 504
2022-02-28 17:05:57.961 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 72, 0, 315, 424
2022-02-28 17:05:57.969 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 328, 290, 36, 131
2022-02-28 17:05:57.980 12629-12687/com.cisystems.ssmp.arm_vmb2 D/OpenGLRenderer: CacheTexture 4 upload: x, y, width height = 348, 420, 14, 18
2022-02-28 17:06:02.102 12629-12670/com.cisystems.ssmp.arm_vmb2 D/SQLiteDatabase: beginTransaction()
2022-02-28 17:06:02.470 12629-12638/com.cisystems.ssmp.arm_vmb2 I/System: FinalizerDaemon: finalize objects = 9644
2022-02-28 17:06:02.662 12629-12731/com.cisystems.ssmp.arm_vmb2 D/libc-netbsd: getaddrinfo: ssmpdev.regeora.ru get result from proxy gai_error = 7
2022-02-28 17:06:02.662 12629-12731/com.cisystems.ssmp.arm_vmb2 I/System.out: [CDS][DNS]Unable to resolve host "ssmpdev.regeora.ru": No address associated with hostname

normal connect is same


2022-02-28 17:05:52.650 12629-12731/com.cisystems.ssmp.arm_vmb2 I/System.out: [CDS][DNS] getAllByNameImpl netId = 0
2022-02-28 17:05:52.650 12629-12731/com.cisystems.ssmp.arm_vmb2 D/libc-netbsd: [getaddrinfo]: hostname=ssmpdev.regeora.ru; servname=(null); netid=0; mark=0
2022-02-28 17:05:52.650 12629-12731/com.cisystems.ssmp.arm_vmb2 D/libc-netbsd: [getaddrinfo]: ai_addrlen=0; ai_canonname=(null); ai_flags=4; ai_family=0
2022-02-28 17:05:52.651 12629-12731/com.cisystems.ssmp.arm_vmb2 D/libc-netbsd: [getaddrinfo]: hostname=ssmpdev.regeora.ru; servname=(null); netid=0; mark=0
2022-02-28 17:05:52.651 12629-12731/com.cisystems.ssmp.arm_vmb2 D/libc-netbsd: [getaddrinfo]: ai_addrlen=0; ai_canonname=(null); ai_flags=1024; ai_family=0
yschimke commented 2 years ago

Looking into this, there are similar reports for Android 6. Not sure how OkHttp can recover from this, it should throw this exception in this case when Dns fails. So I'm struggling to see how the regression is because of 5.0.0-alpha5.

Does this exception not get thrown in that case? Or is it a different exception type?

but GZIPResponseInterceptor.kt:141 have try/catch that is ignored

slavonnet commented 2 years ago

I think this becouse Android 6.0 block network request in lockscreen and after install ADB and run debug have few seconds "no internet". "have try/catch that is ignored" look like debug mode line number pointer bug in AS. Look like this all not "5.0.0-alpha5 regression", sorry for that.

yschimke commented 2 years ago

Thanks for the update, that makes sense.