Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

AbortFlowException crash on repeated connect/disconnect calls #47

Closed
twyatt opened this issue Dec 29, 2020 · 19 comments
Closed

AbortFlowException crash on repeated connect/disconnect calls #47

twyatt opened this issue Dec 29, 2020 · 19 comments
Assignees

Comments

@twyatt
Copy link
Member

twyatt commented Dec 29, 2020

@twyatt yes I could not reproduce this crash but I have found another crash when does connect/disconnect a lot of times in raw.
kotlinx.coroutines.flow.internal.AbortFlowException: Flow was aborted, no more elements needed
Unfortunately that there are not other lines of the stack trace.
It happens just after call method connect.

kotlinx.coroutines.flow.internal.AbortFlowException: Flow was aborted, no more elements needed 2020-12-29 12:39:45.027 6461-6511/com.xx D/BluetoothGatt: connect() - device: 43:95:9A:31:C7:6C, auto: false 2020-12-29 12:39:45.028 6461-6511/com.xx D/BluetoothAdapter: isSecureModeEnabled 2020-12-29 12:39:45.029 6461-6511/com.xx D/BluetoothGatt: registerApp() 2020-12-29 12:39:45.030 6461-6511/com.xx D/BluetoothGatt: registerApp() - UUID=1228b816-0f28-48f8-a49d-ef4c752b9027 2020-12-29 12:39:45.034 6461-6476/com.xx D/BluetoothGatt: onClientRegistered() - status=0 clientIf=10

Originally posted by @kostya29-strikersoft in #44 (comment)

@m31wayfarer
Copy link

I have attached simple android peripheral app. Name of this peripheral "SensorTag" :-)
peripheral.apk.zip

@twyatt
Copy link
Member Author

twyatt commented Dec 29, 2020

Without a stacktrace I'm not totally confident what the issue is, but looks closely related to Kotlin/kotlinx.coroutines#1454. Hopefully fixed in #48. 🤞

@kostya29-strikersoft can you test it out and see if it fixes the issue?

import java.net.URI

repositories {
    maven { url = URI("https://oss.sonatype.org/content/repositories/snapshots") }
}

dependencies {
    implementation("com.juul.kable:core:0.1.0-issue-47-SNAPSHOT")
}

Thanks so much!

@m31wayfarer
Copy link

m31wayfarer commented Dec 30, 2020

@twyatt Now the app does not get disconnected state from peripheral.state flow after BluetoothGatt: close() BluetoothGatt: unregisterApp() but don't see the crash with abortflowexception. Please fix propagating peripheral state

@twyatt
Copy link
Member Author

twyatt commented Dec 30, 2020

@twyatt Now the app does not get disconnected state from peripheral.state flow after BluetoothGatt: close() BluetoothGatt: unregisterApp() but don't see the crash with abortflowexception. Please fix propagating peripheral state

Good to know, thanks! I'll look into it.

@twyatt twyatt self-assigned this Dec 30, 2020
@twyatt twyatt modified the milestones: 0.1.1, 0.2.0 Dec 31, 2020
@twyatt twyatt modified the milestones: 0.2.0, 0.3.0 Jan 12, 2021
@twyatt twyatt removed this from the 0.3.0 milestone Feb 17, 2021
@mattbutlar
Copy link

@twyatt Just wanted to mention that I am seeing this issue and it is making it impossible to move forward on anything... sometime I get it to connect and the exception isn't thrown, but most of the time it throws the AbortFlowException right after registering the app, and no try/catch prevents it from crashing the app, and there is no stacktrace of any sort. It is pretty horrible.

@twyatt
Copy link
Member Author

twyatt commented Feb 26, 2021

@mattbutlar thanks for sharing. I'll get the associated PR merged and a version pushed out either today or tomorrow.

@mattbutlar
Copy link

@twyatt I did try that snapshot and saw no improvement just so you know

@twyatt
Copy link
Member Author

twyatt commented Feb 26, 2021

@twyatt I did try that snapshot and saw no improvement just so you know

Oh, yikes. Ok, I'll need to investigate further then. Super helpful to know that the SNAPSHOT didn't help.

@twyatt
Copy link
Member Author

twyatt commented Feb 26, 2021

@mattbutlar is your failure occurring on connect, or during scan? Or, more specifically, what method call is causing the crash?

I'm wondering if you're see #67 by chance? Can you try the snapshot mentioned in that ticket?

@mattbutlar
Copy link

@twyatt I hadn't see #67 but I just tried it's snapshot and it didn't crash, so it looks like it was the scan even though it happened well after connection had started

@twyatt
Copy link
Member Author

twyatt commented Feb 26, 2021

@twyatt I hadn't see #67 but I just tried it's snapshot and it didn't crash, so it looks like it was the scan even though it happened well after connection had started

Great, thanks for checking. I'll get a version (that has the #67 fix) released ASAP.

@twyatt
Copy link
Member Author

twyatt commented Feb 27, 2021

If anyone continues to see this issue in 0.3.0 (or newer) can you please comment on this issue?

I have a suspicion that #67 might have been the cause for the crash reported in this issue, and it was just observed after a short delay making it seem like it was due to quick reconnect (rather than from the scanner).

Based on #47 (comment) I'm hesitant to merge #48 until I've received confirmation that this is still an issue (and warrants further investigation).

@zhourenjun
Copy link

0.3.0 If the device is far away from the disconnection and close to the reconnection, the crash will reproduce after multiple operations

@twyatt
Copy link
Member Author

twyatt commented Mar 18, 2021

@zhourenjun thanks for reporting that the issue still exists.

Can you try the following SNAPSHOT and let me know if it fixes the issue?

import java.net.URI

repositories {
    maven { url = URI("https://oss.sonatype.org/content/repositories/snapshots") }
}

dependencies {
    implementation("com.juul.kable:core:0.3.0-issue-47-SNAPSHOT")
}

Thank you!

@zhourenjun
Copy link

Still not working, I crashed the second time I reconnected, and my log did not capture the specific reason

@twyatt
Copy link
Member Author

twyatt commented Mar 19, 2021

If at all possible to get the failure (and ideally a stacktrace) then it'd be super helpful. Otherwise it'll be a bit challenging to track down.

In the mean time, I'll try to find some time to reproduce.

@zhourenjun
Copy link

zhourenjun commented Mar 19, 2021

com.juul.kable.ConnectionLostException
    at com.juul.kable.PeripheralKt$suspendUntilConnected$2.invokeSuspend(Peripheral.kt:261)
    at com.juul.kable.PeripheralKt$suspendUntilConnected$2.invoke(Unknown Source:10)
    at kotlinx.coroutines.flow.FlowKt__TransformKt$onEach$$inlined$unsafeTransform$1$2.emit(Collect.kt:134)
    at kotlinx.coroutines.flow.StateFlowImpl.collect(StateFlow.kt:348)
    at kotlinx.coroutines.flow.StateFlowImpl$collect$1.invokeSuspend(Unknown Source:12)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
    at android.os.Handler.handleCallback(Handler.java:883)
    at android.os.Handler.dispatchMessage(Handler.java:100)
    at android.os.Looper.loop(Looper.java:214)
    at android.app.ActivityThread.main(ActivityThread.java:7417)
    at java.lang.reflect.Method.invoke(Native Method)
    at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:980)
Full logs
2021-03-19 11:43:14.967 20449-20449/? I/.juul.sensorta: Late-enabling -Xcheck:jni
2021-03-19 11:43:14.979 20449-20449/com.juul.sensortag E/.juul.sensorta: Unknown bits set in runtime_flags: 0x8000
2021-03-19 11:43:15.368 20449-20449/com.juul.sensortag W/.juul.sensorta: Accessing hidden method Landroid/view/View;->computeFitSystemWindows(Landroid/graphics/Rect;Landroid/graphics/Rect;)Z (greylist, reflection, allowed)
2021-03-19 11:43:15.368 20449-20449/com.juul.sensortag W/.juul.sensorta: Accessing hidden method Landroid/view/ViewGroup;->makeOptionalFitsSystemWindows()V (greylist, reflection, allowed)
2021-03-19 11:43:15.388 20449-20449/com.juul.sensortag D/SensorTag: Scan status: com.juul.sensortag.features.scan.ScanStatus$Stopped@46b4028
2021-03-19 11:43:15.393 20449-20449/com.juul.sensortag I/SurfaceFactory: [static] sSurfaceFactory = com.mediatek.view.impl.SurfaceFactoryImpl@d7de427
2021-03-19 11:43:15.398 20449-20449/com.juul.sensortag D/ViewRootImpl[ScanActivity]: hardware acceleration = true , fakeHwAccelerated = false, sRendererDisabled = false, forceHwAccelerated = false, sSystemRendererDisabled = false
2021-03-19 11:43:15.402 20449-20449/com.juul.sensortag V/PhoneWindow: DecorView setVisiblity: visibility = 0, Parent = android.view.ViewRootImpl@ada9bc3, this = DecorView@65bec40[ScanActivity]
2021-03-19 11:43:15.415 20449-20449/com.juul.sensortag E/GraphicExt: Can't load libboost_ext_fwk
2021-03-19 11:43:15.415 20449-20449/com.juul.sensortag E/GraphicExt: GraphicExtModuleLoader::CreateGraphicExtInstance false
2021-03-19 11:43:15.416 20449-20480/com.juul.sensortag I/GPUD: @gpudInitialize: successfully initialized with GL, dbg=0 mmdump_dbg=0 mmpath_dbg=0
2021-03-19 11:43:15.421 20449-20480/com.juul.sensortag I/GED: [GT]_get_procNameprocess pid(20449)
2021-03-19 11:43:15.421 20449-20480/com.juul.sensortag I/GED: [GT]_getprocess name(com.juul.sensortag)
2021-03-19 11:43:15.424 20449-20480/com.juul.sensortag D/Surface: Surface::connect(this=0x73b6392000,api=1)
2021-03-19 11:43:15.425 20449-20480/com.juul.sensortag D/mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, EGLBoolean) returns 0x3000
2021-03-19 11:43:15.425 20449-20480/com.juul.sensortag D/Surface: Surface::setBufferCount(this=0x73b6392000,bufferCount=3)
2021-03-19 11:43:15.425 20449-20480/com.juul.sensortag D/Surface: Surface::allocateBuffers(this=0x73b6392000)
2021-03-19 11:43:15.430 20449-20480/com.juul.sensortag W/Gralloc3: mapper 3.x is not supported
2021-03-19 11:43:15.431 20449-20480/com.juul.sensortag E/gralloc: Arm Module v1.0
2021-03-19 11:43:15.432 20449-20480/com.juul.sensortag E/ion: ioctl c0044901 failed with code -1: Invalid argument
2021-03-19 11:43:15.432 20449-20480/com.juul.sensortag W/gralloc: WARNING: internal format modifier bits not mutually exclusive. AFBC basic bit is always set, so extended AFBC support bits must always be checked.
2021-03-19 11:43:19.333 20449-20449/com.juul.sensortag D/SensorTag: Scan status: com.juul.sensortag.features.scan.ScanStatus$Started@a68e89c
2021-03-19 11:43:19.358 20449-20449/com.juul.sensortag D/BluetoothAdapter: isLeEnabled(): ON
2021-03-19 11:43:19.360 20449-20467/com.juul.sensortag D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=11 mScannerId=0
2021-03-19 11:43:22.411 20449-20449/com.juul.sensortag D/BluetoothAdapter: isLeEnabled(): ON
2021-03-19 11:43:22.463 20449-20449/com.juul.sensortag W/ActivityThread: handleWindowVisibility: no activity for token android.os.BinderProxy@8c30db8
2021-03-19 11:43:22.483 20449-20449/com.juul.sensortag W/SensorTag: State Disconnected(status=null)
2021-03-19 11:43:22.483 20449-20449/com.juul.sensortag I/SensorTag: Waiting 250 ms to reconnect...
2021-03-19 11:43:22.484 20449-20449/com.juul.sensortag I/SensorTag: connect
2021-03-19 11:43:22.487 20449-20449/com.juul.sensortag D/BluetoothGatt: connect() - device: D1:D3:2A:C5:C3:16, auto: false
2021-03-19 11:43:22.487 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp()
2021-03-19 11:43:22.487 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp() - UUID=73db7297-ac88-4018-a7bb-8c06758aabe6
2021-03-19 11:43:22.488 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2021-03-19 11:43:22.512 20449-20449/com.juul.sensortag V/PhoneWindow: DecorView setVisiblity: visibility = 4, Parent = null, this = DecorView@f414bf5[]
2021-03-19 11:43:22.514 20449-20449/com.juul.sensortag D/ViewRootImpl[SensorActivity]: hardware acceleration = true , fakeHwAccelerated = false, sRendererDisabled = false, forceHwAccelerated = false, sSystemRendererDisabled = false
2021-03-19 11:43:22.516 20449-20449/com.juul.sensortag V/PhoneWindow: DecorView setVisiblity: visibility = 0, Parent = android.view.ViewRootImpl@a97c818, this = DecorView@f414bf5[SensorActivity]
2021-03-19 11:43:22.527 20449-20449/com.juul.sensortag E/GraphicExt: GraphicExtModuleLoader::CreateGraphicExtInstance false
2021-03-19 11:43:22.528 20449-20480/com.juul.sensortag D/Surface: Surface::connect(this=0x73b7f0d000,api=1)
2021-03-19 11:43:22.529 20449-20480/com.juul.sensortag D/mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, EGLBoolean) returns 0x3000
2021-03-19 11:43:22.529 20449-20480/com.juul.sensortag D/Surface: Surface::setBufferCount(this=0x73b7f0d000,bufferCount=3)
2021-03-19 11:43:22.529 20449-20480/com.juul.sensortag D/Surface: Surface::allocateBuffers(this=0x73b7f0d000)
2021-03-19 11:43:22.735 20449-20480/com.juul.sensortag D/Surface: Surface::disconnect(this=0x73b6392000,api=1)
2021-03-19 11:43:22.752 20449-20449/com.juul.sensortag V/PhoneWindow: DecorView setVisiblity: visibility = 4, Parent = android.view.ViewRootImpl@ada9bc3, this = DecorView@65bec40[ScanActivity]
2021-03-19 11:43:22.754 20449-20449/com.juul.sensortag I/SensorTag: connect
2021-03-19 11:43:22.754 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connecting@e7c1373
2021-03-19 11:43:24.948 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:43:24.949 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connected@6b38230
2021-03-19 11:43:24.952 20449-20514/com.juul.sensortag D/BluetoothGatt: discoverServices() - device: D1:D3:2A:C5:C3:16
2021-03-19 11:43:25.583 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=6 latency=0 timeout=500 status=0
2021-03-19 11:43:25.783 20449-20467/com.juul.sensortag D/BluetoothGatt: onSearchComplete() = Device=D1:D3:2A:C5:C3:16 Status=0
2021-03-19 11:43:25.894 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=39 latency=0 timeout=500 status=0
2021-03-19 11:43:27.446 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=168 latency=0 timeout=600 status=0
2021-03-19 11:43:45.297 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:43:45.298 20449-20514/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:43:45.298 20449-20514/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=11
2021-03-19 11:43:45.300 20449-20514/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:43:45.300 20449-20514/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:43:45.304 20449-20449/com.juul.sensortag W/SensorTag: State Disconnected(status=com.juul.kable.State$Disconnected$Status$Timeout@22d5c2e)
2021-03-19 11:43:45.304 20449-20449/com.juul.sensortag I/SensorTag: Waiting 250 ms to reconnect...
2021-03-19 11:43:45.557 20449-20449/com.juul.sensortag I/SensorTag: connect
2021-03-19 11:43:45.562 20449-20449/com.juul.sensortag D/BluetoothGatt: connect() - device: D1:D3:2A:C5:C3:16, auto: false
2021-03-19 11:43:45.563 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp()
2021-03-19 11:43:45.563 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp() - UUID=ca006497-6ae8-4e7a-b6b5-0ec4657f0cf0
2021-03-19 11:43:45.567 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2021-03-19 11:43:45.577 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connecting@e7c1373
2021-03-19 11:43:56.680 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:43:56.681 20449-20547/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:43:56.681 20449-20547/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=11
2021-03-19 11:43:56.682 20449-20547/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:43:56.682 20449-20547/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:43:56.683 20449-20449/com.juul.sensortag W/SensorTag: State Disconnected(status=Unknown(status=133))
2021-03-19 11:43:56.684 20449-20449/com.juul.sensortag I/SensorTag: Waiting 1000 ms to reconnect...
2021-03-19 11:43:56.694 20449-20449/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:43:56.694 20449-20449/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:43:56.695 20449-20449/com.juul.sensortag W/System.err: com.juul.kable.ConnectionLostException
2021-03-19 11:43:56.697 20449-20449/com.juul.sensortag W/System.err:     at com.juul.kable.PeripheralKt$suspendUntilConnected$2.invokeSuspend(Peripheral.kt:261)
2021-03-19 11:43:56.697 20449-20449/com.juul.sensortag W/System.err:     at com.juul.kable.PeripheralKt$suspendUntilConnected$2.invoke(Unknown Source:10)
2021-03-19 11:43:56.697 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.flow.FlowKt__TransformKt$onEach$$inlined$unsafeTransform$1$2.emit(Collect.kt:134)
2021-03-19 11:43:56.697 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.flow.StateFlowImpl.collect(StateFlow.kt:348)
2021-03-19 11:43:56.698 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.flow.StateFlowImpl$collect$1.invokeSuspend(Unknown Source:12)
2021-03-19 11:43:56.698 20449-20449/com.juul.sensortag W/System.err:     at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
2021-03-19 11:43:56.698 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
2021-03-19 11:43:56.698 20449-20449/com.juul.sensortag W/System.err:     at android.os.Handler.handleCallback(Handler.java:883)
2021-03-19 11:43:56.699 20449-20449/com.juul.sensortag W/System.err:     at android.os.Handler.dispatchMessage(Handler.java:100)
2021-03-19 11:43:56.699 20449-20449/com.juul.sensortag W/System.err:     at android.os.Looper.loop(Looper.java:214)
2021-03-19 11:43:56.699 20449-20449/com.juul.sensortag W/System.err:     at android.app.ActivityThread.main(ActivityThread.java:7417)
2021-03-19 11:43:56.699 20449-20449/com.juul.sensortag W/System.err:     at java.lang.reflect.Method.invoke(Native Method)
2021-03-19 11:43:56.700 20449-20449/com.juul.sensortag W/System.err:     at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
2021-03-19 11:43:56.700 20449-20449/com.juul.sensortag W/System.err:     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:980)
2021-03-19 11:43:57.687 20449-20449/com.juul.sensortag I/SensorTag: connect
2021-03-19 11:43:57.692 20449-20449/com.juul.sensortag D/BluetoothGatt: connect() - device: D1:D3:2A:C5:C3:16, auto: false
2021-03-19 11:43:57.692 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp()
2021-03-19 11:43:57.692 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp() - UUID=f82a031a-fe1a-49c4-981e-a5ec1752453f
2021-03-19 11:43:57.697 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2021-03-19 11:43:57.708 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connecting@e7c1373
2021-03-19 11:43:58.439 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:43:58.440 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connected@6b38230
2021-03-19 11:43:58.441 20449-20562/com.juul.sensortag D/BluetoothGatt: discoverServices() - device: D1:D3:2A:C5:C3:16
2021-03-19 11:43:59.070 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=6 latency=0 timeout=500 status=0
2021-03-19 11:43:59.308 20449-20467/com.juul.sensortag D/BluetoothGatt: onSearchComplete() = Device=D1:D3:2A:C5:C3:16 Status=0
2021-03-19 11:43:59.419 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=39 latency=0 timeout=500 status=0
2021-03-19 11:44:00.922 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=168 latency=0 timeout=600 status=0
2021-03-19 11:45:04.973 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:45:04.973 20449-20562/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:45:04.973 20449-20562/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=11
2021-03-19 11:45:04.975 20449-20562/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:45:04.976 20449-20562/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:45:04.977 20449-20449/com.juul.sensortag W/SensorTag: State Disconnected(status=com.juul.kable.State$Disconnected$Status$Timeout@22d5c2e)
2021-03-19 11:45:04.978 20449-20449/com.juul.sensortag I/SensorTag: Waiting 250 ms to reconnect...
2021-03-19 11:45:05.230 20449-20449/com.juul.sensortag I/SensorTag: connect
2021-03-19 11:45:05.235 20449-20449/com.juul.sensortag D/BluetoothGatt: connect() - device: D1:D3:2A:C5:C3:16, auto: false
2021-03-19 11:45:05.235 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp()
2021-03-19 11:45:05.235 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp() - UUID=79c71a6d-910a-427f-ae11-5cfa5fc466ad
2021-03-19 11:45:05.239 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2021-03-19 11:45:05.250 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connecting@e7c1373
2021-03-19 11:45:13.024 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:45:13.026 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connected@6b38230
2021-03-19 11:45:13.037 20449-20629/com.juul.sensortag D/BluetoothGatt: discoverServices() - device: D1:D3:2A:C5:C3:16
2021-03-19 11:45:13.750 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=6 latency=0 timeout=500 status=0
2021-03-19 11:45:14.262 20449-20467/com.juul.sensortag D/BluetoothGatt: onSearchComplete() = Device=D1:D3:2A:C5:C3:16 Status=0
2021-03-19 11:45:14.340 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=39 latency=0 timeout=500 status=0
2021-03-19 11:45:15.572 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=168 latency=0 timeout=600 status=0
2021-03-19 11:45:24.812 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:45:24.813 20449-20629/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:45:24.813 20449-20629/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=11
2021-03-19 11:45:24.816 20449-20629/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:45:24.816 20449-20629/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:45:24.817 20449-20449/com.juul.sensortag W/SensorTag: State Disconnected(status=com.juul.kable.State$Disconnected$Status$Timeout@22d5c2e)
2021-03-19 11:45:24.818 20449-20449/com.juul.sensortag I/SensorTag: Waiting 250 ms to reconnect...
2021-03-19 11:45:25.069 20449-20449/com.juul.sensortag I/SensorTag: connect
2021-03-19 11:45:25.074 20449-20449/com.juul.sensortag D/BluetoothGatt: connect() - device: D1:D3:2A:C5:C3:16, auto: false
2021-03-19 11:45:25.074 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp()
2021-03-19 11:45:25.074 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp() - UUID=4fc11d2e-1629-4718-b1a0-4ee062c5982e
2021-03-19 11:45:25.078 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2021-03-19 11:45:25.089 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connecting@e7c1373
2021-03-19 11:45:34.810 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:45:34.811 20449-20651/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:45:34.811 20449-20651/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=11
2021-03-19 11:45:34.812 20449-20651/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:45:34.812 20449-20651/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:45:34.814 20449-20449/com.juul.sensortag W/SensorTag: State Disconnected(status=Unknown(status=133))
2021-03-19 11:45:34.814 20449-20449/com.juul.sensortag I/SensorTag: Waiting 1000 ms to reconnect...
2021-03-19 11:45:34.815 20449-20449/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:45:34.816 20449-20449/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:45:34.817 20449-20449/com.juul.sensortag W/System.err: com.juul.kable.ConnectionLostException
2021-03-19 11:45:34.817 20449-20449/com.juul.sensortag W/System.err:     at com.juul.kable.PeripheralKt$suspendUntilConnected$2.invokeSuspend(Peripheral.kt:261)
2021-03-19 11:45:34.818 20449-20449/com.juul.sensortag W/System.err:     at com.juul.kable.PeripheralKt$suspendUntilConnected$2.invoke(Unknown Source:10)
2021-03-19 11:45:34.818 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.flow.FlowKt__TransformKt$onEach$$inlined$unsafeTransform$1$2.emit(Collect.kt:134)
2021-03-19 11:45:34.818 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.flow.StateFlowImpl.collect(StateFlow.kt:348)
2021-03-19 11:45:34.818 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.flow.StateFlowImpl$collect$1.invokeSuspend(Unknown Source:12)
2021-03-19 11:45:34.818 20449-20449/com.juul.sensortag W/System.err:     at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
2021-03-19 11:45:34.819 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
2021-03-19 11:45:34.819 20449-20449/com.juul.sensortag W/System.err:     at android.os.Handler.handleCallback(Handler.java:883)
2021-03-19 11:45:34.819 20449-20449/com.juul.sensortag W/System.err:     at android.os.Handler.dispatchMessage(Handler.java:100)
2021-03-19 11:45:34.819 20449-20449/com.juul.sensortag W/System.err:     at android.os.Looper.loop(Looper.java:214)
2021-03-19 11:45:34.820 20449-20449/com.juul.sensortag W/System.err:     at android.app.ActivityThread.main(ActivityThread.java:7417)
2021-03-19 11:45:34.820 20449-20449/com.juul.sensortag W/System.err:     at java.lang.reflect.Method.invoke(Native Method)
2021-03-19 11:45:34.820 20449-20449/com.juul.sensortag W/System.err:     at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
2021-03-19 11:45:34.820 20449-20449/com.juul.sensortag W/System.err:     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:980)
2021-03-19 11:45:35.817 20449-20449/com.juul.sensortag I/SensorTag: connect
2021-03-19 11:45:35.822 20449-20449/com.juul.sensortag D/BluetoothGatt: connect() - device: D1:D3:2A:C5:C3:16, auto: false
2021-03-19 11:45:35.822 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp()
2021-03-19 11:45:35.823 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp() - UUID=68f25497-60d0-4035-96f5-4d32c7c63409
2021-03-19 11:45:35.827 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2021-03-19 11:45:35.837 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connecting@e7c1373
2021-03-19 11:45:37.593 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:45:37.594 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connected@6b38230
2021-03-19 11:45:37.598 20449-20655/com.juul.sensortag D/BluetoothGatt: discoverServices() - device: D1:D3:2A:C5:C3:16
2021-03-19 11:45:38.520 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=6 latency=0 timeout=500 status=0
2021-03-19 11:45:38.845 20449-20467/com.juul.sensortag D/BluetoothGatt: onSearchComplete() = Device=D1:D3:2A:C5:C3:16 Status=0
2021-03-19 11:45:38.942 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=39 latency=0 timeout=500 status=0
2021-03-19 11:45:40.097 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=168 latency=0 timeout=600 status=0
2021-03-19 11:46:02.777 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:46:02.777 20449-20655/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:46:02.777 20449-20655/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=11
2021-03-19 11:46:02.779 20449-20655/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:46:02.780 20449-20655/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:46:02.781 20449-20449/com.juul.sensortag W/SensorTag: State Disconnected(status=com.juul.kable.State$Disconnected$Status$Timeout@22d5c2e)
2021-03-19 11:46:02.781 20449-20449/com.juul.sensortag I/SensorTag: Waiting 250 ms to reconnect...
2021-03-19 11:46:03.033 20449-20449/com.juul.sensortag I/SensorTag: connect
2021-03-19 11:46:03.036 20449-20449/com.juul.sensortag D/BluetoothGatt: connect() - device: D1:D3:2A:C5:C3:16, auto: false
2021-03-19 11:46:03.036 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp()
2021-03-19 11:46:03.037 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp() - UUID=10b7b515-a55c-43f4-a623-262dc699f11f
2021-03-19 11:46:03.040 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2021-03-19 11:46:03.048 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connecting@e7c1373
2021-03-19 11:46:08.991 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:46:08.992 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connected@6b38230
2021-03-19 11:46:08.995 20449-20673/com.juul.sensortag D/BluetoothGatt: discoverServices() - device: D1:D3:2A:C5:C3:16
2021-03-19 11:46:10.545 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=6 latency=0 timeout=500 status=0
2021-03-19 11:46:10.801 20449-20467/com.juul.sensortag D/BluetoothGatt: onSearchComplete() = Device=D1:D3:2A:C5:C3:16 Status=0
2021-03-19 11:46:10.899 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=39 latency=0 timeout=500 status=0
2021-03-19 11:46:11.613 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=168 latency=0 timeout=600 status=0
2021-03-19 11:46:21.485 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:46:21.485 20449-20673/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:46:21.485 20449-20673/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=11
2021-03-19 11:46:21.488 20449-20673/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:46:21.488 20449-20673/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:46:21.489 20449-20449/com.juul.sensortag W/SensorTag: State Disconnected(status=com.juul.kable.State$Disconnected$Status$Timeout@22d5c2e)
2021-03-19 11:46:21.490 20449-20449/com.juul.sensortag I/SensorTag: Waiting 250 ms to reconnect...
2021-03-19 11:46:21.743 20449-20449/com.juul.sensortag I/SensorTag: connect
2021-03-19 11:46:21.748 20449-20449/com.juul.sensortag D/BluetoothGatt: connect() - device: D1:D3:2A:C5:C3:16, auto: false
2021-03-19 11:46:21.748 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp()
2021-03-19 11:46:21.748 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp() - UUID=1d376a5d-34e6-413c-ae7b-ac1e5b5198d9
2021-03-19 11:46:21.753 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2021-03-19 11:46:21.763 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connecting@e7c1373
2021-03-19 11:46:28.822 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:46:28.823 20449-20692/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:46:28.823 20449-20692/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=11
2021-03-19 11:46:28.825 20449-20692/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:46:28.825 20449-20692/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:46:28.826 20449-20449/com.juul.sensortag W/SensorTag: State Disconnected(status=Unknown(status=133))
2021-03-19 11:46:28.827 20449-20449/com.juul.sensortag I/SensorTag: Waiting 1000 ms to reconnect...
2021-03-19 11:46:28.836 20449-20449/com.juul.sensortag D/BluetoothGatt: close()
2021-03-19 11:46:28.836 20449-20449/com.juul.sensortag D/BluetoothGatt: unregisterApp() - mClientIf=0
2021-03-19 11:46:28.838 20449-20449/com.juul.sensortag W/System.err: com.juul.kable.ConnectionLostException
2021-03-19 11:46:28.839 20449-20449/com.juul.sensortag W/System.err:     at com.juul.kable.PeripheralKt$suspendUntilConnected$2.invokeSuspend(Peripheral.kt:261)
2021-03-19 11:46:28.839 20449-20449/com.juul.sensortag W/System.err:     at com.juul.kable.PeripheralKt$suspendUntilConnected$2.invoke(Unknown Source:10)
2021-03-19 11:46:28.839 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.flow.FlowKt__TransformKt$onEach$$inlined$unsafeTransform$1$2.emit(Collect.kt:134)
2021-03-19 11:46:28.839 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.flow.StateFlowImpl.collect(StateFlow.kt:348)
2021-03-19 11:46:28.840 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.flow.StateFlowImpl$collect$1.invokeSuspend(Unknown Source:12)
2021-03-19 11:46:28.840 20449-20449/com.juul.sensortag W/System.err:     at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
2021-03-19 11:46:28.840 20449-20449/com.juul.sensortag W/System.err:     at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
2021-03-19 11:46:28.840 20449-20449/com.juul.sensortag W/System.err:     at android.os.Handler.handleCallback(Handler.java:883)
2021-03-19 11:46:28.840 20449-20449/com.juul.sensortag W/System.err:     at android.os.Handler.dispatchMessage(Handler.java:100)
2021-03-19 11:46:28.841 20449-20449/com.juul.sensortag W/System.err:     at android.os.Looper.loop(Looper.java:214)
2021-03-19 11:46:28.841 20449-20449/com.juul.sensortag W/System.err:     at android.app.ActivityThread.main(ActivityThread.java:7417)
2021-03-19 11:46:28.841 20449-20449/com.juul.sensortag W/System.err:     at java.lang.reflect.Method.invoke(Native Method)
2021-03-19 11:46:28.842 20449-20449/com.juul.sensortag W/System.err:     at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
2021-03-19 11:46:28.842 20449-20449/com.juul.sensortag W/System.err:     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:980)
2021-03-19 11:46:29.829 20449-20449/com.juul.sensortag I/SensorTag: connect
2021-03-19 11:46:29.834 20449-20449/com.juul.sensortag D/BluetoothGatt: connect() - device: D1:D3:2A:C5:C3:16, auto: false
2021-03-19 11:46:29.835 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp()
2021-03-19 11:46:29.835 20449-20449/com.juul.sensortag D/BluetoothGatt: registerApp() - UUID=052719fb-ab42-4d21-ad43-78c68288ed2e
2021-03-19 11:46:29.839 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2021-03-19 11:46:29.850 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connecting@e7c1373
2021-03-19 11:46:33.656 20449-20467/com.juul.sensortag D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=11 device=D1:D3:2A:C5:C3:16
2021-03-19 11:46:33.657 20449-20449/com.juul.sensortag W/SensorTag: State com.juul.kable.State$Connected@6b38230
2021-03-19 11:46:33.659 20449-20696/com.juul.sensortag D/BluetoothGatt: discoverServices() - device: D1:D3:2A:C5:C3:16
2021-03-19 11:46:34.385 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=6 latency=0 timeout=500 status=0
2021-03-19 11:46:34.757 20449-20467/com.juul.sensortag D/BluetoothGatt: onSearchComplete() = Device=D1:D3:2A:C5:C3:16 Status=0
2021-03-19 11:46:34.853 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=39 latency=0 timeout=500 status=0
2021-03-19 11:46:36.250 20449-20467/com.juul.sensortag D/BluetoothGatt: onConnectionUpdated() - Device=D1:D3:2A:C5:C3:16 interval=168 latency=0 timeout=600 status=0
2021-03-19 11:46:41.016 20449-20480/com.juul.sensortag D/Surface: Surface::disconnect(this=0x73b7f0d000,api=1)
2021-03-19 11:46:41.030 20449-20480/com.juul.sensortag I/GED: ged_boost_gpu_freq, level 100, eOrigin 2, final_idx 27, oppidx_max 27, oppidx_min 0
2021-03-19 11:46:41.039 20449-20449/com.juul.sensortag V/PhoneWindow: DecorView setVisiblity: visibility = 4, Parent = android.view.ViewRootImpl@a97c818, this = DecorView@f414bf5[SensorActivity]

@twyatt
Copy link
Member Author

twyatt commented Mar 19, 2021

@zhourenjun I believe you're referring to the ConnectionLostException you're seeing?

I'm guessing you're seeing this propagate from a connect call (which aligns with your description of it happening when peripheral is nearly out-of-range and attempting to reconnect)?

This is by design, to propagate the fact that the connection was lost while attempting to connect.

I see that the logs are from the SensorTag example app...I should update that sample to demonstrate how to handle this failure from within sample.

How you handle it (within your app) really depends on what you want to do in the event that a connection attempt fails.

In the SensorTag sample, since we re-attempt (with exponential back-off) to connect by listening to the state Flow, we can generally ignore this failure, since the reconnect logic should kick in for us.

In the case of the SensorTag sample app, the code may look something like:

try {
    peripheral.connect()
    sensorTag.enableGyro()
    sensorTag.writeGyroPeriodProgress(periodProgress.get())
} catch (e: ConnectionLostException) {
    // Silently ignore connection lost as we'll reconnect automatically.
    // Would be best to log some warning message, so the logs show we ignored a failure purposely.
    return@launch
}

...but, for your app, it really depends on how you want to handle a connect failure.

@twyatt
Copy link
Member Author

twyatt commented Jun 24, 2021

I don't believe this issue still exists in the latest versions of Kable. Please comment on this issue if I am mistaken (and it is still an issue).

@twyatt twyatt closed this as completed Jun 24, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants