App connection broken

[AlbertGRMN]

Bug Report

App sometimes fail to connect to HU due to other SDL app's incorrect SDL SDK connection implementation.

Reproduction Steps

1. Connect bad connection implementation SDL BT apps (MyTunerRadio, LINE MUSIC jpn ver.....) to HU.
2. Plugin SDL USB app.
3. If all apps connect successfully, unplug USB and repeat step 2 & 3.

Expected Behavior

All apps should connect successfully or just let the poor implemented apps break their own connection otherwise if a user installs a bad SDL app then the whole SDL related connection will get destroyed as well.

Observed Behavior

1. The incorrect SDL SDK connection implementation of other SDL apps will break the connection of correctly implemented apps as well.
2. Did some experiments and found those "incorrect" apps would create a new SdlManager every time they receive a BT or USB connection without correctly releasing the previous one. Therefore, they will constantly switching (sometimes will switch fail) their connection between BT & USB until the router service gets broken.

OS & Version Information

• Android Version: Android 10
• SDL Android Version: SDL SDK ver 5.1.1 (The SDK version containing the router service)
• Testing Against: Ford TDK, Samsung S9+

Test Case, Sample Code, and / or Example App

1. Install MyTunerRadio ver 8.0.33, Line Music Japan ver 5.4.0 and the "hello SDL" app in java_suite GitHub.
2. Modify the "hello SDL" app with setting the primary transport to USB.
3. Connect phone's BT with HU. MyTunerRadio and Line Music connceted.
4. Plugin USB and choose "hello SDL" app on AOA list.
5. Check the connection status of the three apps. Below are the logs of the fail case:

08-10 10:57:57.998 1470 3964 I ActivityManager: Start proc 4231:com.sdl.hellosdlandroid/u0a472 for broadcast com.sdl.hellosdlandroid/.SdlReceiver
08-10 10:57:59.057 1470 2580 I ActivityManager: Start proc 4273:jp.linecorp.linemusic.android/u0a468 for broadcast jp.linecorp.linemusic.android/com.naver.vibe.sdl.SdlReceiver
08-10 10:58:00.349 1470 3964 I ActivityManager: Start proc 4350:com.smartdevicelink.router/u0a472 for service com.sdl.hellosdlandroid/.SdlRouterService
08-10 10:58:00.719 1470 2874 I ActivityManager: Start proc 4413:com.smartdevicelink.router/u0a445 for service com.garmin.android.apps.linkboxapp/.sdl.SdlRouterService
08-10 10:59:22.176 1470 2240 I ActivityManager: Start proc 9552:com.sdl.hellosdlandroid/u0a472 for broadcast com.sdl.hellosdlandroid/.SdlReceiver
08-10 10:59:23.157 1470 3073 I ActivityManager: Start proc 9609:jp.linecorp.linemusic.android/u0a468 for broadcast jp.linecorp.linemusic.android/com.naver.vibe.sdl.SdlReceiver
08-10 10:59:38.569 3157 3157 E SDLReceiver: onSdlEnabled
08-10 10:59:38.571 3157 3157 E SdlManager: onStart()
08-10 10:59:38.593 9552 9552 I SdlBroadcastReceiver: 5.2.0: SDL Enabled
08-10 10:59:38.661 9552 9552 I RSVP : 5.2.0: Supplied service name of com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 10:59:38.675 9552 9552 I SdlTransportBroker: 5.2.0: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 10:59:38.701 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 10:59:38.709 9552 9552 I SdlTransportBroker: 5.2.0: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 10:59:38.728 9552 9552 I SdlListener: 5.2.0: : Saving connected status - F0:99:19:F6:00:C0 : true
08-10 10:59:38.733 9552 9552 I SdlProtocol: 5.2.0: onTransportConnected
08-10 10:59:38.737 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 10:59:38.747 9552 9552 I SdlSession: 5.2.0: Shutdown - No transports match requested primary transport
08-10 10:59:38.748 9552 9552 I SdlSession: 5.2.0: Shutdown - No transports match requested primary transport
08-10 10:59:38.748 9552 9552 I BaseSdlManager: 5.2.0: Proxy is closed.
08-10 10:59:38.764 9552 9552 I SdlTransportBroker: 5.2.0: Stopping transport broker for com.sdl.android.8678309.10590038
08-10 10:59:38.764 9552 9552 I SdlTransportBroker: 5.2.0: Attempting to unregister with Sdl Router Service
08-10 10:59:38.768 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 10:59:38.780 9609 9609 D SdlProtocol: onTransportConnected
08-10 10:59:38.786 9552 9552 I SdlProtocol: 5.2.0: Active transports ---
08-10 10:59:39.354 9609 10573 I SdlProxy: SDL Proxy Version: 4.11.1
08-10 10:59:39.362 9609 10573 D SdlProxy: notifyProxyClosed: Unable to register app interface. Review values passed to the SdlProxy constructor. RegisterAppInterface result code:
08-10 10:59:39.365 9609 10572 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 10:59:39.375 9609 10573 I SdlProxy: SDL Proxy Version: 4.11.1
08-10 10:59:39.385 9609 10573 D SdlProxy: notifyProxyClosed: Unable to register app interface. Review values passed to the SdlProxy constructor. RegisterAppInterface result code:
08-10 11:00:23.163 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:00:23.188 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:00:23.196 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:00:23.206 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:00:24.135 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:00:24.163 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:00:24.173 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:00:24.182 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:00:24.811 9609 11084 E SdlProxy: 4.11.1: RPCConverter was unable to process RPC
08-10 11:00:24.811 9609 11084 E SdlProxy: java.lang.ClassNotFoundException: com.smartdevicelink.proxy.rpc.OnSystemRequestResponse
08-10 11:00:24.811 9609 11084 E SdlProxy: at java.lang.Class.classForName(Native Method)
08-10 11:00:24.811 9609 11084 E SdlProxy: at java.lang.Class.forName(Class.java:453)
08-10 11:00:24.811 9609 11084 E SdlProxy: at java.lang.Class.forName(Class.java:378)
08-10 11:00:24.811 9609 11084 E SdlProxy: at com.smartdevicelink.managers.lifecycle.RpcConverter.convertTableToRpc(SourceFile:21)
08-10 11:00:24.811 9609 11084 E SdlProxy: at com.smartdevicelink.proxy.SdlProxyBase.handleRPCMessage(SourceFile:3)
08-10 11:00:24.811 9609 11084 E SdlProxy: at com.smartdevicelink.proxy.SdlProxyBase.dispatchIncomingMessage(SourceFile:28)
08-10 11:00:24.811 9609 11084 E SdlProxy: at com.smartdevicelink.proxy.SdlProxyBase.access$2800(SourceFile:1)
08-10 11:00:24.811 9609 11084 E SdlProxy: at com.smartdevicelink.proxy.SdlProxyBase$3.dispatch(SourceFile:2)
08-10 11:00:24.811 9609 11084 E SdlProxy: at com.smartdevicelink.proxy.SdlProxyBase$3.dispatch(SourceFile:1)
08-10 11:00:24.811 9609 11084 E SdlProxy: at com.smartdevicelink.Dispatcher.ProxyMessageDispatcher.handleMessages(SourceFile:3)
08-10 11:00:24.811 9609 11084 E SdlProxy: at com.smartdevicelink.Dispatcher.ProxyMessageDispatcher.access$000(SourceFile:1)
08-10 11:00:24.811 9609 11084 E SdlProxy: at com.smartdevicelink.Dispatcher.ProxyMessageDispatcher$1.run(SourceFile:1)
08-10 11:00:24.811 9609 11084 E SdlProxy: at java.lang.Thread.run(Thread.java:764)
08-10 11:00:24.811 9609 11084 E SdlProxy: Caused by: java.lang.ClassNotFoundException: Didn't find class "com.smartdevicelink.proxy.rpc.OnSystemRequestResponse" on path: DexPathList[[zip file "/data/app/jp.linecorp.linemusic.android-j8jSFksT1xBFpOXOQHqK2g==/base.apk"],nativeLibraryDirectories=[/data/app/jp.linecorp.linemusic.android-j8jSFksT1xBFpOXOQHqK2g==/lib/arm64, /data/app/jp.linecorp.linemusic.android-j8jSFksT1xBFpOXOQHqK2g==/base.apk!/lib/arm64-v8a, /system/lib64, /system/vendor/lib64]]
08-10 11:00:24.811 9609 11084 E SdlProxy: at dalvik.system.BaseDexClassLoader.findClass(BaseDexClassLoader.java:93)
08-10 11:00:24.811 9609 11084 E SdlProxy: at java.lang.ClassLoader.loadClass(ClassLoader.java:379)
08-10 11:00:24.811 9609 11084 E SdlProxy: at java.lang.ClassLoader.loadClass(ClassLoader.java:312)
08-10 11:00:24.811 9609 11084 E SdlProxy: ... 13 more
08-10 11:00:24.812 9609 11084 E SdlProxy: 4.11.1: handleRPCMessage: rpcMsg is null, returning.
08-10 11:00:24.975 9609 9609 E SdlProxy: 4.11.1: onServiceError, session Type: RPC, reason: End com.smartdevicelink.protocol.enums.SessionType@32a9cc4 Service NACK'ed
08-10 11:00:24.977 9609 9609 E SdlProxy: 4.11.1: onServiceError, session Type: RPC, reason: End com.smartdevicelink.protocol.enums.SessionType@32a9cc4 Service NACK'ed
08-10 11:00:25.053 9609 11084 I SdlProxy: SDL Proxy Version: 4.11.1
08-10 11:00:25.058 9609 11084 D SdlProxy: notifyProxyClosed: Unable to register app interface. Review values passed to the SdlProxy constructor. RegisterAppInterface result code:
08-10 11:00:25.062 9609 11083 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:00:25.131 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:00:25.149 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:00:25.154 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:00:25.157 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:00:26.144 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:00:26.156 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:00:26.161 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:00:26.166 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:00:27.134 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:00:27.153 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:00:27.159 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:00:27.163 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:00:28.123 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:00:28.137 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:00:28.141 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:00:28.145 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:00:29.135 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:00:29.150 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:00:29.156 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:00:29.161 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:00:30.298 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:00:30.311 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:00:30.315 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:00:30.317 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:00:31.115 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:00:31.120 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:00:31.123 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:00:31.124 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:00:32.115 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:00:32.123 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:00:32.125 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:00:32.127 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:00:38.797 1470 1525 W ActivityManager: Stopping service due to app idle: u0a472 -2m39s14ms com.sdl.hellosdlandroid/.SdlRouterService
08-10 11:01:51.534 9609 9609 D SdlTransportBroker: Hardware disconnected
08-10 11:01:51.535 9609 9609 D SdlProtocol: onTransportDisconnected - BLUETOOTH
08-10 11:01:51.536 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:51.548 9609 9609 D SdlProxy: notifyProxyClosed:
08-10 11:01:51.607 3157 3157 E ActivityThread: Service com.appgeneration.mytunerlib.sdl.SdlService has leaked IntentReceiver com.smartdevicelink.util.MediaStreamingStatus$1@ec964a that was originally registered here. Are you missing a call to unregisterReceiver()?
08-10 11:01:51.607 3157 3157 E ActivityThread: android.app.IntentReceiverLeaked: Service com.appgeneration.mytunerlib.sdl.SdlService has leaked IntentReceiver com.smartdevicelink.util.MediaStreamingStatus$1@ec964a that was originally registered here. Are you missing a call to unregisterReceiver()?
08-10 11:01:51.607 3157 3157 E ActivityThread: at com.smartdevicelink.session.SdlSession.isAudioRequirementMet(SdlSession.java:3)
08-10 11:01:51.607 3157 3157 E ActivityThread: at com.smartdevicelink.session.SdlSession.startSession(SdlSession.java:1)
08-10 11:01:51.607 3157 3157 E ActivityThread: at com.smartdevicelink.managers.SdlManager.start(SdlManager.java:10)
08-10 11:01:51.607 3157 3157 E ActivityThread: at com.appgeneration.mytunerlib.sdl.SdlService.onStartCommand(SdlService.kt:22)
08-10 11:01:51.610 3157 3157 E ActivityThread: Service com.appgeneration.mytunerlib.sdl.SdlService has leaked IntentReceiver com.smartdevicelink.util.MediaStreamingStatus$1@a9a48e3 that was originally registered here. Are you missing a call to unregisterReceiver()?
08-10 11:01:51.610 3157 3157 E ActivityThread: android.app.IntentReceiverLeaked: Service com.appgeneration.mytunerlib.sdl.SdlService has leaked IntentReceiver com.smartdevicelink.util.MediaStreamingStatus$1@a9a48e3 that was originally registered here. Are you missing a call to unregisterReceiver()?
08-10 11:01:51.610 3157 3157 E ActivityThread: at com.smartdevicelink.session.SdlSession.isAudioRequirementMet(SdlSession.java:3)
08-10 11:01:51.610 3157 3157 E ActivityThread: at com.smartdevicelink.session.SdlSession.startSession(SdlSession.java:1)
08-10 11:01:51.610 3157 3157 E ActivityThread: at com.smartdevicelink.managers.SdlManager.start(SdlManager.java:10)
08-10 11:01:51.610 3157 3157 E ActivityThread: at com.appgeneration.mytunerlib.sdl.SdlService.onStartCommand(SdlService.kt:22)
08-10 11:01:51.611 3157 3157 E ActivityThread: Service com.appgeneration.mytunerlib.sdl.SdlService has leaked ServiceConnection com.smartdevicelink.transport.TransportBroker$1@6223ed8 that was originally bound here
08-10 11:01:51.611 3157 3157 E ActivityThread: android.app.ServiceConnectionLeaked: Service com.appgeneration.mytunerlib.sdl.SdlService has leaked ServiceConnection com.smartdevicelink.transport.TransportBroker$1@6223ed8 that was originally bound here
08-10 11:01:51.611 3157 3157 E ActivityThread: at com.smartdevicelink.protocol.SdlProtocolBase.start(SdlProtocolBase.java:3)
08-10 11:01:51.611 3157 3157 E ActivityThread: at com.smartdevicelink.session.SdlSession.startSession(SdlSession.java:3)
08-10 11:01:51.611 3157 3157 E ActivityThread: at com.smartdevicelink.managers.SdlManager.start(SdlManager.java:10)
08-10 11:01:51.611 3157 3157 E ActivityThread: at com.appgeneration.mytunerlib.sdl.SdlService.onStartCommand(SdlService.kt:22)
08-10 11:01:51.745 9609 9609 W SdlTransportBroker: Unregister request denied from router service. Reason - 1
08-10 11:01:52.264 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.266 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.268 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.268 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.268 9609 9609 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.10590038 tried to send packet, but no where to send
08-10 11:01:52.269 9609 9609 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:52.269 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.269 9609 9609 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:52.269 9609 9609 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:01:52.269 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.270 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.270 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.271 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.273 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.275 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.275 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.275 9609 9913 W System.err: com.smartdevicelink.exception.SdlException: This object has been disposed, it is no long capable of executing methods.
08-10 11:01:52.276 9609 9913 W System.err: SdlExceptionCause: SDL_PROXY_DISPOSED
08-10 11:01:52.276 9609 9913 W System.err: at com.smartdevicelink.proxy.SdlProxyBase.sendRPC(SourceFile:25)
08-10 11:01:52.276 9609 9913 W System.err: at com.smartdevicelink.managers.SdlManager$7.sendRPC(SourceFile:1)
08-10 11:01:52.276 9609 9609 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.11000024 tried to send packet, but no where to send
08-10 11:01:52.276 9609 9609 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:52.276 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.276 9609 9609 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:52.276 9609 9609 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:01:52.276 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.278 9609 9869 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.10590026 tried to send packet, but no where to send
08-10 11:01:52.278 9609 11069 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.11000023 tried to send packet, but no where to send
08-10 11:01:52.279 9609 11069 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:52.279 9609 11069 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.279 9609 11069 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:52.279 9609 11069 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:01:52.283 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.284 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.284 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.285 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.286 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.286 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.286 9609 11086 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.11000025 tried to send packet, but no where to send
08-10 11:01:52.286 9609 11086 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:52.286 9609 11086 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.286 9609 11086 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:52.287 9609 11086 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:01:52.287 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.292 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.294 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.294 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.294 9609 11090 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.11000026 tried to send packet, but no where to send
08-10 11:01:52.294 9609 11090 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:52.294 9609 11090 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.294 9609 11090 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:52.294 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.295 9609 11090 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:01:52.295 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.296 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.296 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.297 9609 11099 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.11000027 tried to send packet, but no where to send
08-10 11:01:52.298 9609 11099 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:52.298 9609 11099 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.298 9609 11099 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:52.298 9609 11099 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:01:52.300 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.301 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.302 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.302 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.304 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.304 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.305 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.305 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.305 9609 11107 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.11000029 tried to send packet, but no where to send
08-10 11:01:52.305 9609 11107 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:52.305 9609 11107 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.305 9609 11107 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:52.305 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.305 9609 11107 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:01:52.306 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.307 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.307 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.308 9609 11104 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.11000028 tried to send packet, but no where to send
08-10 11:01:52.308 9609 11104 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:52.308 9609 11104 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.308 9609 11104 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:52.308 9609 11104 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:01:52.308 9609 11158 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.11000030 tried to send packet, but no where to send
08-10 11:01:52.309 9609 11158 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:52.309 9609 11158 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.309 9609 11158 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:52.309 9609 11158 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:01:52.310 9609 9609 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.312 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.312 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.312 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.313 9609 11177 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.11000031 tried to send packet, but no where to send
08-10 11:01:52.313 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:01:52.313 9609 11177 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:52.313 9609 11177 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:52.313 9609 11177 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:52.314 9609 11177 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:01:52.315 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:01:52.315 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:01:52.324 9609 9609 W SdlTransportBroker: Unregister request denied from router service. Reason - 1
08-10 11:01:52.324 9609 9609 W SdlTransportBroker: Unregister request denied from router service. Reason - 1
08-10 11:01:55.279 9609 9867 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.10590026 tried to send packet, but no where to send
08-10 11:01:55.280 9609 9867 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:01:55.280 9609 9867 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:01:55.280 9609 9867 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:01:55.282 9609 9867 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:03:03.712 1470 2580 I ActivityManager: Start proc 11603:com.sdl.hellosdlandroid/u0a472 for broadcast com.sdl.hellosdlandroid/.SdlReceiver
08-10 11:03:03.954 11603 11603 W System.err: at com.smartdevicelink.transport.SdlBroadcastReceiver.$jacocoInit(Unknown Source:13)
08-10 11:03:03.954 11603 11603 W System.err: at com.smartdevicelink.transport.SdlBroadcastReceiver.(Unknown Source:0)
08-10 11:03:03.993 9609 9609 D Sdl Broadcast Receiver: Check for local router
08-10 11:03:03.993 9609 9609 D Sdl Broadcast Receiver: attempting to wake up router service
08-10 11:03:04.010 9609 9609 D ServiceFinder: Received intent from package: com.garmin.android.apps.linkboxapp. Classname: com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:03:07.611 3157 3157 E SDLReceiver: onSdlEnabled
08-10 11:03:07.660 3157 3157 E SdlManager: onStart()
08-10 11:03:07.706 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:03:07.718 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:03:07.724 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:03:07.728 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:03:07.750 11603 11603 I RSVP : 5.2.0: Supplied service name of com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:03:07.761 11603 11603 I SdlTransportBroker: 5.2.0: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:03:07.777 11603 11603 I SdlTransportBroker: 5.2.0: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:03:07.792 11603 11603 I SdlListener: 5.2.0: : Saving connected status - F0:99:19:F6:00:C0 : true
08-10 11:03:07.802 11603 11603 I SdlProtocol: 5.2.0: onTransportConnected
08-10 11:03:07.805 11603 11603 I SdlSession: 5.2.0: Shutdown - No transports match requested primary transport
08-10 11:03:07.805 11603 11603 I SdlSession: 5.2.0: Shutdown - No transports match requested primary transport
08-10 11:03:07.806 11603 11603 I BaseSdlManager: 5.2.0: Proxy is closed.
08-10 11:03:07.809 11603 11603 I SdlTransportBroker: 5.2.0: Stopping transport broker for com.sdl.android.8678309.11030007
08-10 11:03:07.810 11603 11603 I SdlTransportBroker: 5.2.0: Attempting to unregister with Sdl Router Service
08-10 11:03:07.816 11603 11603 I SdlProtocol: 5.2.0: Active transports ---
08-10 11:03:15.809 9609 9609 D SdlSession2: Shutdown - Audio output no longer available
08-10 11:03:15.810 9609 9609 D SdlProxy: notifying proxy of closed
08-10 11:03:15.810 9609 9609 D SdlProxy: notifyProxyClosed: Audio output no longer available
08-10 11:03:15.811 9609 11675 D SdlTransportBroker: com.sdl.android.99063176-affa-4de8-a3c9-ca7cc058d9de.11030007 tried to send packet, but no where to send
08-10 11:03:15.811 9609 11675 E SdlTransportBroker: Unable to send message to router service. Not bound.
08-10 11:03:15.811 9609 11675 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:03:15.811 9609 11675 W SdlTransportBroker: Unable to unregister, not bound to router service
08-10 11:03:15.811 9609 11675 W SdlTransportBroker: Unable to unbind from router service. bound? false context? false router connection?true
08-10 11:03:22.571 11603 11603 I Sdl Broadcast Receiver: 5.2.0: Check for local router
08-10 11:03:22.571 11603 11603 I Sdl Broadcast Receiver: 5.2.0: attempting to wake up router service
08-10 11:03:22.581 9609 9609 D Sdl Broadcast Receiver: Check for local router
08-10 11:03:22.581 9609 9609 D Sdl Broadcast Receiver: attempting to wake up router service
08-10 11:03:24.736 11603 11603 I Sdl Broadcast Receiver: 5.2.0: Attempting to startForegroundService - 1628564604736
08-10 11:03:24.756 1470 2233 I ActivityManager: Start proc 11998:com.smartdevicelink.router/u0a472 for service com.sdl.hellosdlandroid/.SdlRouterService
08-10 11:03:24.972 11998 11998 W System.err: at com.smartdevicelink.transport.SdlRouterService.$jacocoInit(Unknown Source:13)
08-10 11:03:24.972 11998 11998 W System.err: at com.smartdevicelink.transport.SdlRouterService.(Unknown Source:0)
08-10 11:03:25.292 1470 2233 I ActivityManager: Start proc 12018:com.smartdevicelink.router/u0a445 for service com.garmin.android.apps.linkboxapp/.sdl.SdlRouterService
08-10 11:03:27.217 3157 3157 E SDLReceiver: onSdlEnabled
08-10 11:03:27.247 11603 11603 I SdlBroadcastReceiver: 5.2.0: SDL Enabled
08-10 11:03:27.263 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:03:27.266 3157 3157 E SdlManager: onStart()
08-10 11:03:27.272 11603 11603 I RSVP : 5.2.0: Supplied service name of com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:03:27.276 11603 11603 I SdlTransportBroker: 5.2.0: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:03:27.282 11603 11603 I SdlTransportBroker: 5.2.0: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:03:27.285 11603 11603 I SdlListener: 5.2.0: : Saving connected status - F0:99:19:F6:00:C0 : true
08-10 11:03:27.287 11603 11603 I SdlProtocol: 5.2.0: onTransportConnected
08-10 11:03:27.287 11603 11603 I SdlSession: 5.2.0: Shutdown - No transports match requested primary transport
08-10 11:03:27.288 11603 11603 I SdlSession: 5.2.0: Shutdown - No transports match requested primary transport
08-10 11:03:27.288 11603 11603 I BaseSdlManager: 5.2.0: Proxy is closed.
08-10 11:03:27.289 11603 11603 I SdlTransportBroker: 5.2.0: Stopping transport broker for com.sdl.android.8678309.11030027
08-10 11:03:27.289 11603 11603 I SdlTransportBroker: 5.2.0: Attempting to unregister with Sdl Router Service
08-10 11:03:27.292 11603 11603 I SdlProtocol: 5.2.0: Active transports ---
08-10 11:03:28.304 9609 9609 D SdlTransportBroker: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:03:28.310 9609 9609 D SdlTransportBroker: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:03:28.313 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:03:29.184 9609 12066 I SdlProxy: SDL Proxy Version: 4.11.1
08-10 11:03:46.811 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:03:46.824 3157 3157 E SDLReceiver: onSdlEnabled
08-10 11:03:46.827 3157 3157 E SdlManager: onStart()
08-10 11:03:46.841 11603 11603 I SdlBroadcastReceiver: 5.2.0: SDL Enabled
08-10 11:03:46.863 9609 9609 I SdlProxy: SDL_LIB_VERSION: 4.11.1
08-10 11:03:46.863 11603 11603 I RSVP : 5.2.0: Supplied service name of com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:03:46.872 11603 11603 I SdlTransportBroker: 5.2.0: Sending bind request to com.garmin.android.apps.linkboxapp - com.garmin.android.apps.linkboxapp.sdl.SdlRouterService
08-10 11:03:46.888 9609 9609 D SdlProtocol: onTransportConnected
08-10 11:03:46.913 11603 11603 I SdlTransportBroker: 5.2.0: Bound to service ComponentInfo{com.garmin.android.apps.linkboxapp/com.garmin.android.apps.linkboxapp.sdl.SdlRouterService}
08-10 11:03:46.919 11603 11603 I SdlListener: 5.2.0: : Saving connected status - F0:99:19:F6:00:C0 : true
08-10 11:03:46.920 11603 11603 I SdlProtocol: 5.2.0: onTransportConnected
08-10 11:03:46.934 11603 11603 I SdlProtocol: 5.2.0: Active transports ---
08-10 11:03:46.987 9609 12163 I SdlProxy: SDL Proxy Version: 4.11.1
08-10 11:03:46.988 9609 12163 D SdlProxy: notifyProxyClosed: Unable to register app interface. Review values passed to the SdlProxy constructor. RegisterAppInterface result code:
08-10 11:03:46.989 9609 12162 I SdlTransportBroker: Attempting to unregister with Sdl Router Service
08-10 11:03:46.990 9609 12163 I SdlProxy: SDL Proxy Version: 4.11.1
08-10 11:03:46.993 9609 12163 D SdlProxy: notifyProxyClosed: Unable to register app interface. Review values passed to the SdlProxy constructor. RegisterAppInterface result code:

[AlbertGRMN]

• Log (including router service) : issue_log.txt

• Result :
  

[AlbertGRMN]

Log (reproduced with Samsung S8) : issue_log_samsung_s8.txt

Reproduce step video : https://drive.google.com/file/d/16aSgIW1ghP00GBOhLLE_mdldPhARaUZC/view?usp=sharing

Line Music APK (JPN ver): https://drive.google.com/file/d/1Dh7WABfBvkjTSKTNBzdsmqokZl9m7SFL/view?usp=sharing

[joeygrover]

Updating the current status on this issue:

We've done investigation into this issue and the apps associated. The good news is that there is nothing within the library itself that causes applications to lose connections. The reason that the supplied apps disappear and the reappear is because of incorrect implementations on their part. When the router service makes a transport connection it will send out an intent to SDL apps to inform them of this connection. This happens regardless of first transport connected or subsequent ones. When these apps receive the intent they start up their SDL service. The SDL service's onStart method is then called and the apps create an SDLManager instance and register. However, since this intent can be sent multiple times the service attempts to create a new instance of the SDLManager for each intent received instead of checking if their instance is null or properly shutting it down. This causes the old SDLManager instance to be garbage collected, but the new instance does not register correctly, likely because a service can't have two bindings to the same component (router service) or they don't accept the new transport. Therefore, this issue is specifically an app integration issue and not an issue with the library itself. Unfortunately we do not have control over these applications, but we will try and work with them to get them to update their integrations. If you see any other apps having the same behavior please let us know so that we can reach out to them.

There is a second, unrelated issue to this one that is being observed. While the router service is connected over the bluetooth transport and then connects/disconnects the AOA(USB) transport several times it can get in a state where apps appear not to be able to register. We have traced the issue as far as seeing the initial StartService packet appear to be sent from the app through the USB transport, but we need to confirm if that packet is received on the Core side. This issue will continue to be investigated, though the AOA transport itself is known to be a bit unstable.

[AlbertGRMN]

Hi @joeygrover ,
Thanks for your help on this issue. We're wondering if it's possible to add a dummy check in SDL SDK to prevent the app from creating multiple SDLManager instances in case of careless developers.

[AlbertGRMN]

Hi @joeygrover , Is the above approach possible?

[joeygrover]

Hi, the app certification process is already in place to prevent careless mistakes like the ones observed with the applications listed. Line Music was certified a long time ago before the guidelines were approved by the SDLC so they are an outlier in this instance. MyTuner still needs to complete certification. The library itself is not a singleton/static instance so putting a check like that is not entirely safe. A developer can safely create two services that house their own SdlManager class and work just fine so checking for more than one instance of the SdlManager is not a guaranteed way around the issue. Also, any changes made to the library would still require the apps with poor implementations to update their app which they should simply update to a better implementation at that point. Some devs aren't up to the latest major version and may not have the resources to do so in order to obtain this potential check. However, if you believe you have an idea that is worth while you can take it through the SDL Evolution process with a submitted proposal https://github.com/smartdevicelink/sdl_evolution.

[RHenigan]

This GitHub issue covers 2 separate issues:

1. The incorrect implementation of certain apps causing those apps to lose connections
2. The RouterService reaching a state where apps appear to be unable to register over AOA.

For point 1, this issue is a result of improper implementation by app developers. As this is an app integration issue and not an issue with the library itself we will close this issue.
For point 2, we have created issue #1777