Android Bluetooth logging filling up logcat

Question

I used the Bluetooth Chat example as a starting point to implement a BT connection from my phone to an embedded device. I am able to successfully connect to the device but once the connection is made the logcat is getting overrun by a massive amount of logging. I did not see this type of logging when first doing the BT chat app phone to phone.

Here is what is repeated over and over. It basically makes the logcat unusable. So far I haven't found a way to configure the logging or why it's logging so much. Any insights would be appreciated.

03-08 14:29:04.941: DEBUG/BluetoothSocket.cpp(11422): availableNative
03-08 14:29:04.957: DEBUG/BluetoothSocket(11422): available
03-08 14:29:04.957: DEBUG/BluetoothSocket.cpp(11422): availableNative
03-08 14:29:04.971: DEBUG/BluetoothSocket(11422): available
03-08 14:29:04.976: DEBUG/BluetoothSocket.cpp(11422): availableNative
03-08 14:29:04.989: DEBUG/BluetoothSocket(11422): available
03-08 14:29:04.991: DEBUG/BluetoothSocket.cpp(11422): availableNative
03-08 14:29:05.016: DEBUG/BluetoothSocket(11422): available
03-08 14:29:05.016: DEBUG/BluetoothSocket.cpp(11422): availableNative
03-08 14:29:05.034: DEBUG/BluetoothSocket(11422): available
03-08 14:29:05.036: DEBUG/BluetoothSocket.cpp(11422): availableNative
03-08 14:29:05.050: DEBUG/BluetoothSocket(11422): available
03-08 14:29:05.051: DEBUG/BluetoothSocket.cpp(11422): availableNative
03-08 14:29:05.066: DEBUG/BluetoothSocket(11422): available
03-08 14:29:05.066: DEBUG/BluetoothSocket.cpp(11422): availableNative
03-08 14:29:05.081: DEBUG/BluetoothSocket(11422): available
03-08 14:29:05.081: DEBUG/BluetoothSocket.cpp(11422): availableNative
03-08 14:29:05.086: DEBUG/(2419): jw_if_rfcomm_cl_cback: jw_if_rfcomm_cl_cback event=BTA_JV_RFCOMM_READ_EVT
03-08 14:29:05.086: DEBUG/(2419): jv_forward_data_to_jni: BTA_JV_RFCOMM_DATA_IND_EVT bta hdl 2
03-08 14:29:05.086: DEBUG/(2419): bts_log_tstamps_us: [update stats] ts    1263504, bta hdl 2, diff 01263504, tx_q 1 (1), rx_q 0 (0)
03-08 14:29:05.086: DEBUG/BLZ20_WRAPPER(11422): blz20_wrp_poll: transp poll : (fd 41) returned r_ev [POLLIN ] (0x1)
03-08 14:29:05.086: DEBUG/BLZ20_WRAPPER(11422): blz20_wrp_poll: return 1
03-08 14:29:05.086: DEBUG/BLZ20_WRAPPER(11422): blz20_wrp_read: read 122 bytes out of 1024 on fd 41
03-08 14:29:05.101: DEBUG/BluetoothSocket(11422): read
03-08 14:29:05.101: DEBUG/BluetoothSocket.cpp(11422): readNative
03-08 14:29:05.101: DEBUG/ASOCKWRP(11422): asocket_read
03-08 14:29:05.106: INFO/BLZ20_WRAPPER(11422): blz20_wrp_poll: nfds 2, timeout -1 ms
03-08 14:29:05.117: DEBUG/BluetoothSocket(11422): available
03-08 14:29:05.121: DEBUG/BluetoothSocket.cpp(11422): availableNative

Answer 1

After playing with my Arduino Board + Bluetooth-Adapter I tryed to implement the Bluetooth-Code from MATT BELL'S BLOG. The Problem is the following Code:

//final Handler handler = new Handler();
workerThread = new Thread(new Runnable()
{
    public void run()
    {
        while(!Thread.currentThread().isInterrupted() && !stopWorker)
        {
            try {
                int bytesAvailable = mmInputStream.available();
                if(bytesAvailable > 0)
                {
                    //Log.d(TAG,"bytesAvailable: "+bytesAvailable + " readBufferPosition: "+readBufferPosition);
                    byte[] packetBytes = new byte[bytesAvailable];
                    mmInputStream.read(packetBytes);

                    for(int i=0;i<bytesAvailable;i++)
                    {
                        byte delimiter = 0x0A;     // /n bzw. LF
                        byte b = packetBytes[i];
                        if(b == delimiter)
                        {
                            byte[] encodedBytes = new byte[readBufferPosition];
                            System.arraycopy(readBuffer, 0, encodedBytes, 0, encodedBytes.length);
                            final String data = new String(encodedBytes, "US-ASCII");
                            //final String data = new String(readBuffer);
                            readBufferPosition = 0;

                            Log.d(TAG,""+data);

//                                            //The variable data now contains our full command
//                                            handler.post(new Runnable()
//                                            {
//                                                public void run()
//                                                {
//                                                    //myLabel.setText(data);
//                                                    Log.d(TAG,""+data);
//                                                }
//                                            });
                        }
                        else
                        {
                            readBuffer[readBufferPosition++] = b;
                        }
                    }
                }
            } catch (Exception e) {
                Log.d(TAG,"Exeption 2: "+e.getMessage());
                stopWorker = true;
            }
        }
    }
});
workerThread.start();

Calling the following function results in huge Spam in logCat

int bytesAvailable = mmInputStream.available();

LogCat:

PS: The timestamps are in fact of the fixed version. Not using the fix will will result in a spam every 5ms effectivly blocking my whole Log

03-17 18:43:06.615: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:06.715: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:06.820: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:06.920: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:07.020: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:07.120: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:07.220: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:07.320: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:07.420: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:07.520: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:07.620: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:07.725: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:07.825: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:07.925: VERBOSE/BluetoothSocket.cpp(8871): availableNative
03-17 18:43:08.025: VERBOSE/BluetoothSocket.cpp(8871): availableNative

My current fix is adding the following code at the end of the while loop resulting in reduction of the spam.

try {
Thread.sleep(100);
} catch (Exception e) {
Log.d(TAG,"Exception Thread.sleep()");
}

I hope this will help some people with similar issues.

Edit: Currently I had to reduce the sleep-timer to 10ms bam .. SPAM

03-18 15:50:18.470: VERBOSE/BluetoothSocket.cpp(3482): availableNative
03-18 15:50:18.470: VERBOSE/BluetoothSocket.cpp(3482): availableNative
03-18 15:50:18.470: VERBOSE/BluetoothSocket.cpp(3482): availableNative
03-18 15:50:18.470: VERBOSE/BluetoothSocket.cpp(3482): availableNative
03-18 15:50:18.470: VERBOSE/BluetoothSocket.cpp(3482): availableNative
03-18 15:50:18.470: VERBOSE/BluetoothSocket.cpp(3482): availableNative
03-18 15:50:18.470: VERBOSE/BluetoothSocket.cpp(3482): availableNative
03-18 15:50:18.470: VERBOSE/BluetoothSocket.cpp(3482): availableNative
03-18 15:50:18.470: VERBOSE/BluetoothSocket.cpp(3482): availableNative
03-18 15:50:18.470: VERBOSE/BluetoothSocket.cpp(3482): availableNative

Answer 2

This must be an error, and a serious one:

• either Logcat only shows this debug print sometimes - although my code always comes across it

• or the Bluetooth chip runs loose sometimes...(more likely).

Just turning the log level to debug from verbose won't change the fact there is an enormous amount of data transferred to Logcat, blocking all normal logs...