ANT Forum

I have a workaround where I only request one scan at a time; letting it run for a few seconds before I cancel it and start a scan for the next device type.

Note: the ANT icon will flash on and off on a Sony device while this is happening, and the first few device searches won't actually start as the service is initialising (as seen by the fact that the ANT icon never turns on).

Note 2: Stopping the search and starting it again means that the searching ANT channel could be taken by someone while changing devices. This was happening to me when I automatically tried requesting access on a device (which had failed with NO_CHANNELS_AVAILABLE) when the (ANT API) AntChannelProvider.ACTION_CHANNEL_PROVIDER_STATE_CHANGED intent showed NEW_CHANNELS_AVAILABLE).

This works (although it can be very slow), however I consistently have these errors show up in LogCat:

06-05 11:37:20.231: E/AsyncScanController(7625): BBD20000: requestAccess failed
06-05 11:37:20.231: E/AsyncScanController(7625): BBD20000: Unexpected Event: ScanFailure on already null object, code: -4

It doesn't impact operation, and devices are still discovered, but what causes this error?

Thanks.
R      

This post

ShaneG - 09 May 2014 01:39 PM

Our new version of the ANT+ Plugins API being released within the next week will have a new feature that allows searching for multiple ANT+ devices concurrently on a single channel as you describe. We will be releasing a beta soon, if you are interested please subscribe as a watcher of our ANT+ Plugins GitHub repo to be kept up to date on changes: https://github.com/ant-wireless/Android_ANTPlusPlugins

mentions a beta API available from GitHub which allows scan for multiple device types, but I can't find it. There is a https://github.com/ant-wireless/Android_API_ANTPlus repository, but I only see the stable release. Do I need to register?      

Sorry we didn't get you involved in the limited beta arrgh, but as you are aware the release candidates are now out, http://www.thisisant.com/forum/viewthread/4357/      

My experience with the new API's is worse than before. Now every single time I stop/start an async scan I see the above errors and/or this:
W/MessageQueue(17402): Handler (android.os.Handler) {2be6dce8} sending message to a Handler on a dead thread
W/MessageQueue(17402): java.lang.RuntimeException: Handler (android.os.Handler) {2be6dce8} sending message to a Handler on a dead thread
W/MessageQueue(17402): at android.os.MessageQueue.enqueueMessage(MessageQueue.java:196)
W/MessageQueue(17402): at android.os.Handler.sendMessageAtTime(Handler.java:473)
W/MessageQueue(17402): at android.os.Handler.sendMessageDelayed(Handler.java:446)
W/MessageQueue(17402): at android.os.Handler.sendMessage(Handler.java:383)
W/MessageQueue(17402): at android.os.Handler$MessengerImpl.send(Handler.java:587)
W/MessageQueue(17402): at android.os.IMessenger$Stub.onTransact(IMessenger.java:56)
W/MessageQueue(17402): at android.os.Binder.execTransact(Binder.java:338)
W/MessageQueue(17402): at dalvik.system.NativeStart.run(Native Method)
Nothing has changed except moving to the new libraries.

Update: Switching to MultiDeviceSearch, this occurs when cancelling.      

2 parts to my workaround for the error log part:

1) To stop these logs but still allow turning on logging during development, add this at initialization:


2) To completely strip out the internal ANT+ library debug logs in a release, with ProGuard optimization enabled add this to the config:


The warning logs must not be due to requested log entries, so still occur (only in the latest release candidate library).      

We look into cleaning up extraneous logging when we can, but there is no negative side effect of allowing it to continue, apart from cluttering logs. There are many other things that clutter logs, so if that is the only issue, you should just use log filters.

Forcefully disabling logging may result in missing useful debugging messages and is not recommended.      

This has a more severe impact than you give it credit. Error and warning logs coming from an app makes it look buggy and unreliable (at least to the tech-savy people who view logcat), which has a negative impact on user opinion of the app and publisher. There is also the performance impact and the simple fact that part of the Android "preparing for release" steps is to turn off logging.

The "sending message to a Handler on a dead thread" is also an actual error occurring.

R      

I was trying to confirm if this warning also occurs on the ANT+ Sampler, or if it is just my app, however repeatedly entering Async Scan Demo then exiting, after a few attempts I see:

E/AntPluginService(32198): BBC30000: UnexpectedError, acquireChannel_helper called with null ArsComm
E/AsyncScanController(29444): BBD30000: requestAccess failed

Then I cleared the log and tried again (app still open), seeing:

07-14 13:14:56.003: E/AntChannelExecutor(32198): BBC30000: Executor Dying: RemoteException occured executing DoWork() in task: Scan Search Controller
07-14 13:14:56.013: E/AntPluginService(32198): BBC30000: Plugin async controller scan failed: executor died
07-14 13:14:56.073: E/AsyncScanController(29444): BBD30000: requestAccess failed
07-14 13:14:58.343: E/AntChannelExecutor(32198): BBC30000: Executor Dying: AntChannel fired OnChannelDeath()
07-14 13:14:58.343: E/AntChannelExecutor(32198): BBC30000: Executor Dying: RemoteException occured executing DoWork() in task: Scan Search Controller
07-14 13:14:59.163: E/ANTSocketManagerThread(25048): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-14 13:15:00.563: E/AntPluginService(32198): BBC30000: UnexpectedError, acquireChannel_helper called with null ArsComm
07-14 13:15:00.563: E/AsyncScanController(29444): BBD30000: requestAccess failed
07-14 13:15:01.363: E/AntPluginService(32198): BBC30000: Plugin async controller scan failed: executor died
07-14 13:15:01.363: E/AsyncScanController(29444): BBD30000: requestAccess failed

Interestingly, while I generally see a whole lot of:

07-14 13:14:57.366: I/bluedroid(282): bt_enable: ret: -1, errno: 19

before the "AntChannel fired OnChannelDeath()" I see:

07-14 13:14:58.103: I/bluedroid(282): bt_enable: ret: 0, errno: 19

Full log attached. This is again on a Sony Ericsson Ray.

Also, this is repeatedly logged during a scan:

E/ScanSearchControllerTask(32198): BBC30000: Search timeout occured
E/ScanSearchControllerTask(32198): BBC30000: Channel closed

     

Okay, first of all the Ray firmware has known issues that can cause bluetooth and ANT errors which we do not have very much control over. 'bt_enable' messages are common and are part of normal operation on this phone.

We are already looking into the other error you reported of the channel dying, it seems an error at the hardware level is causing ANT to fail. We have only seen this on the Ray. How often does this occur for you?

Finally the search timeout log is not an error and has the wrong logging level, we are already cleaning that up in next version.

     

On Channel Death: I have only seen this once during development of our app, and I am not sure if it was caused by the ANT+ Plugin Sampler or not. It is easily reproducible with the ANT+ Sampler.

Edit: Actually it is the quickly starting and stopping that is the issue. I am now using the MultiDeviceSearch but repeatedly toggling a switch which starts/cancels the search gave these error logs:

First time running app

07-15 14:26:35.413: E/AntPluginService(29379): BBC30000: UnexpectedError, acquireChannel_helper called with null ArsComm
07-15 14:26:36.650: E/AntPluginService(29379): BBC30000: UnexpectedError, acquireChannel_helper called with null ArsComm
07-15 14:26:37.513: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:26:38.730: E/AntPluginService(29379): BBC30000: UnexpectedError, acquireChannel_helper called with null ArsComm
07-15 14:26:40.763: E/AntPluginService(29379): BBC30000: UnexpectedError, acquireChannel_helper called with null ArsComm
07-15 14:27:03.333: E/AntChannelExecutor(29379): BBC30000: Executor Dying: AntChannel fired OnChannelDeath()
07-15 14:27:03.333: E/AntChannelExecutor(29379): BBC30000: Executor Dying: RemoteException occured executing DoWork() in task: Scan Search Controller
07-15 14:27:08.283: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:27:13.683: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:27:15.705: E/AntPluginService(29379): BBC30000: UnexpectedError, acquireChannel_helper called with null ArsComm

Second try:

07-15 14:28:02.463: E/AntChannelExecutor(29379): BBC30000: Executor Dying: AntChannel fired OnChannelDeath()
07-15 14:28:02.523: E/AntChannelExecutor(29379): BBC30000: Executor Dying: RemoteException occured executing DoWork() in task: Scan Search Controller
07-15 14:28:14.943: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:28:15.403: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:28:15.733: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:28:17.003: E/AntPluginService(29379): BBC30000: Reqacc msg handler rcvd msg, but service is dead
07-15 14:28:17.463: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:28:21.793: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:28:28.943: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:28:29.793: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:28:31.693: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).
07-15 14:28:40.853: E/ANTSocketManagerThread(29394): rxThread: Socket connection closed unnexpectedly. Attempting reconnection (after 6 second pause).

     

arrgh - 03 July 2014 11:57 AM

My experience with the new API's is worse than before. Now every single time I stop/start an async scan I see the above errors and/or this:
W/MessageQueue(17402): Handler (android.os.Handler) {2be6dce8} sending message to a Handler on a dead thread
W/MessageQueue(17402): java.lang.RuntimeException: Handler (android.os.Handler) {2be6dce8} sending message to a Handler on a dead thread
W/MessageQueue(17402): at android.os.MessageQueue.enqueueMessage(MessageQueue.java:196)
W/MessageQueue(17402): at android.os.Handler.sendMessageAtTime(Handler.java:473)
W/MessageQueue(17402): at android.os.Handler.sendMessageDelayed(Handler.java:446)
W/MessageQueue(17402): at android.os.Handler.sendMessage(Handler.java:383)
W/MessageQueue(17402): at android.os.Handler$MessengerImpl.send(Handler.java:587)
W/MessageQueue(17402): at android.os.IMessenger$Stub.onTransact(IMessenger.java:56)
W/MessageQueue(17402): at android.os.Binder.execTransact(Binder.java:338)
W/MessageQueue(17402): at dalvik.system.NativeStart.run(Native Method)
Nothing has changed except moving to the new libraries.

Update: Switching to MultiDeviceSearch, this occurs when cancelling.

I have still not received any acknowledgement that this is an issue. Is it being looked at? When might we expect a fix?

This will be a road block for me, but I believe fixing it is out of my control. Any help would be greatly appreciated!

Thanks.
R      

As I stated before these logs do not indicate a failure that affects the correct operation of the plugins. The logs are caused by a race between the PCC shutting down its message handlers and the service processing the release request while live data is still being received. We have worked on it, and some of the causes of it will be removed in the next release. Until all the fixes are released, these logs can be safely ignored.      

Please let me know if there is anything I can do to help with this, especially reproducing the cases which are not covered by "some of the cases of it will be removed in the next release". My project will not pass customer acceptance tests while repeatedly triggering a warning in logcat, and trying to explain to the client that ShaneG says "these logs can be safely ignored" is going to be a hard sell.