Android Bluetooth socket freeze application

I have a strange issue with bluetooth socket. If I create socket and later close application, android device freeze with very hight CPU load.

Here my sample code:

  // open socket
  public ConnectThread(final BluetoothDevice device) {
    Log.v(ConnectThread.class.getName(), "Try to get a socket");

    try {
      this.socket = device.createRfcommSocketToServiceRecord(UUID.fromString("00001101-0000-1000-8000-00805F9B34FB"));
    } catch (IOException e) {
      Log.e(ConnectThread.class.getName(), e.getMessage());
    }

    Log.v(ConnectThread.class.getName(), "Got a socket");
  }

  // close it
  public void cancel() {
    try {
      Log.v(ConnectThread.class.getName(), "cancel");
      this.socket.close();
    } catch (IOException e) {
      Log.e(ConnectThread.class.getName(), e.getMessage());
    }
  }

Dispite that I close socket with close() method, I don't understand why Android device freeze after my app close. Please note, that it only socket created, but not connected...

EDIT:

OK, there sample code:

package com.ss.test;

import java.io.IOException;
import java.util.UUID;

import android.app.Activity;
import android.bluetooth.BluetoothAdapter;
import android.bluetooth.BluetoothDevice;
import android.bluetooth.BluetoothSocket;
import android.os.Bundle;
import android.util.Log;

public class testBump extends Activity {
  @Override
  public void onCreate(Bundle savedInstanceState) {
    super.onCreate(savedInstanceState);
    setContentView(R.layout.main);

    BluetoothDevice device = this.bluetoothAdapter.getRemoteDevice("58:B0:35:6F:8E:C7");

    Log.e(testBump.class.getName(), "Try to get a socket");

    try {
      this.socket = device.createRfcommSocketToServiceRecord(UUID.fromString("00001101-0000-1000-8000-00805F9B34FB"));
    } catch (IOException e) {
      Log.e(testBump.class.getName(), e.getMessage());
    }

    Log.e(testBump.class.getName(), "Got a socket");

    Log.e(testBump.class.getName(), "DESTROY");

    try {
      this.socket.close();
    } catch (IOException e) {
      Log.e(testBump.class.getName(), e.getMessage());
    }

    Log.e(testBump.class.getName(), "DESTROYED");

  }

  @Override
  public void onDestroy() {
    super.onDestroy();
  }

  private BluetoothAdapter bluetoothAdapter = BluetoothAdapter.getDefaultAdapter();
  private BluetoothSocket socket = null;
}

and log:

12-16 11:42:40.558: ERROR/com.ss.test.testBump(3161): Try to get a socket
12-16 11:42:40.558: DEBUG/BluetoothSocket.cpp(3161): initSocketNative
12-16 11:42:40.558: INFO/BLZ20_WRAPPER(3161): blz20_wrp_socket: fam 31, type 1, prot BTPROTO_RFCOMM
12-16 11:42:40.558: DEBUG/BLZ20_WRAPPER(3161): blz20_init: initializing...
12-16 11:42:40.558: DEBUG/BTL_IFC_WRP(3161): wsactive_init: init active list
12-16 11:42:40.562: INFO/BTL_IFC(3161): main_client_thread: Client main thread starting
12-16 11:42:40.651: DEBUG/MediaProvider(2590): mMediaScannerReceiver - intent.getAction : android.intent.action.ACTION_MEDIA_SCANNER_PROGRESS
12-16 11:42:40.769: DEBUG/MediaScanner(2590): Normal  556 done (3600msec)
12-16 11:42:40.769: DEBUG/MediaScanner(2590): Sync..
12-16 11:42:40.851: DEBUG/MediaScanner(2590): Start Nazca /mnt/sdcard/external_sd
12-16 11:42:40.851: ERROR/MediaScanner(2590): Cannot get device path from mount info. Check SD Unmounted.
12-16 11:42:40.851: DEBUG/MediaScanner(2590): Normal Meta & DB Insert/Update Start
12-16 11:42:40.851: DEBUG/MediaScanner(2590): Normal    0 done (1msec)
12-16 11:42:40.855: DEBUG/MediaScanner(2590): postscan enter: directories - /mnt/sdcard
12-16 11:42:40.874: DEBUG/MediaScanner(2590): start checking FileCacheEntry
12-16 11:42:40.878: DEBUG/MediaScanner(2590): end checking FileCacheEntry
12-16 11:42:40.940: DEBUG/MediaScanner(2590): postscan return
12-16 11:42:40.940: DEBUG/MediaScanner(2590):  prescan time: 109ms
12-16 11:42:40.940: DEBUG/MediaScanner(2590):     scan time: 8327ms
12-16 11:42:40.940: DEBUG/MediaScanner(2590): postscan time: 86ms
12-16 11:42:40.940: DEBUG/MediaScanner(2590):    total time: 8522ms
12-16 11:42:40.956: DEBUG/MediaProvider(2590): mMediaScannerReceiver - intent.getAction : android.intent.action.MEDIA_SCANNER_FINISHED
12-16 11:42:40.960: ERROR/CscReceiver(2585): onReceive android.intent.action.MEDIA_SCANNER_FINISHED
12-16 11:42:40.960: DEBUG/CscReceiver(2585): isCSCimage
12-16 11:42:40.960: INFO/global(2585): Default buffer size used in BufferedReader constructor. It would be better to be explicit if an 8k-char buffer is required.
12-16 11:42:40.960: DEBUG/CscParser(2585): ID_path =/system/SW_Configuration.xml
12-16 11:42:40.960: DEBUG/CscParser(2585): return ok ID path /system/SW_Configuration.xml
12-16 11:42:40.960: DEBUG/CscReceiver(2585): Media DB Scanner finished.
12-16 11:42:40.960: ERROR/CscReceiver(2585): check_9
12-16 11:42:40.972: VERBOSE/MediaProvider(2590): Resuming ThumbWorker
12-16 11:42:40.972: INFO/MediaProvider(2590): MediaScanner stopped!!!
12-16 11:42:40.983: DEBUG/MediaScannerService(2590): done scanning volume external
12-16 11:42:40.983: INFO/MediaScannerService(2590): !@endofMediascannerservice
12-16 11:42:41.034: INFO/TEST(3050): Got intent with action Intent { act=android.intent.action.MEDIA_SCANNER_FINISHED dat=file:///mnt/sdcard cmp=com.cooliris.media/com.cooliris.cache.BootReceiver (has extras) }
12-16 11:42:41.034: DEBUG/BootReceiver(3050): ACTION_MEDIA_SCANNER_FINISHED: path = /mnt/sdcard
12-16 11:42:41.034: DEBUG/BootReceiver(3050): ImageManager.hasStorage()truetrue
12-16 11:42:41.190: INFO/CacheService(3050): Refreshing cache.
12-16 11:42:41.190: ERROR/DiskCache(3050): Delete All Cache Files!!!
12-16 11:42:41.210: ERROR/MTPRx(3059): In MtpReceiverandroid.intent.action.MEDIA_SCANNER_FINISHED
12-16 11:42:41.214: WARN/MTPRx(3059): Media scanning is finished
12-16 11:42:41.214: INFO/System.out(3059): setting Media scanner status0
12-16 11:42:41.214: INFO/System.out(3059): After setting Media scanner status0
12-16 11:42:41.245: WARN/BackupManagerService(2496): dataChanged but no participant pkg='com.android.providers.settings' uid=10035
12-16 11:42:41.249: DEBUG/MediaScannerReceiver(2590): onReceive : EXTERNAL scan FINISHED.
12-16 11:42:41.261: DEBUG/MediaReceiver(3065): MEDIA SCANNER FINISHED.
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_init: success
12-16 11:42:41.562: INFO/BTL_IFC(3161): BTL_IFC_RegisterSubSystem: Register subsystem [BTS]
12-16 11:42:41.562: INFO/BTL_IFC(3161): btl_ifc_ctrl_connect: Connect control channel for subsystem [BTS]
12-16 11:42:41.562: DEBUG/BTL_IFC_WRP(3161): wrp_sock_create: CTRL
12-16 11:42:41.562: DEBUG/BTL_IFC_WRP(3161): wrp_alloc_new_sock: wrp_alloc_new_sock sub 1
12-16 11:42:41.562: DEBUG/BTL_IFC_WRP(3161): wrp_sock_create: 32
12-16 11:42:41.562: DEBUG/BTL_IFC_WRP(3161): wrp_sock_connect: wrp_sock_connect brcm.bt.dtun:9000 (32)
12-16 11:42:41.562: DEBUG/BTL_IFC_WRP(3161): DTUN_MAKE_LOCAL_SERVER_NAME return name: brcm.bt.dtun.9000
12-16 11:42:41.562: INFO/BTL-IFS(2751): main_server_thread: [CTRL] Client connected (22)
12-16 11:42:41.562: INFO/BTL_IFC_WRP(3161): wrp_sock_connect: Connected. (32)
12-16 11:42:41.562: INFO/BTL_IFC(3161): send_ctrl_msg: [BTL_IFC CTRL] send BTLIF_REGISTER_SUBSYS_REQ (BTS) 0 pbytes (hdl 32)
12-16 11:42:41.562: INFO/BTL-IFS(2751): attach_client: multiclient index 1
12-16 11:42:41.562: INFO/BTL-IFS(2751): attach_client: ######## Attached client subsystem BTS (22) ######## 
12-16 11:42:41.562: INFO/BTL-IFS(2751): btl_if_notify_local_event: Notify local event BTLIF_SUBSYSTEM_ATTACHED
12-16 11:42:41.562: DEBUG/(2751): btlif_bts_api_ctrl_cb: btlif_bts_api_ctrl_cb : id BTLIF_SUBSYSTEM_ATTACHED (4112) on hdl 22
12-16 11:42:41.562: INFO/(2751): btlif_rfc_ctrl_chan_attached: client attached ctrl handle 22
12-16 11:42:41.562: DEBUG/BTL-IFS(2751): send_registration_rsp: send_registration_rsp [0]
12-16 11:42:41.562: INFO/BTL-IFS(2751): send_ctrl_msg: [BTL_IFS CTRL] send BTLIF_REGISTER_SUBSYS_RSP (CTRL) 2 pbytes (hdl 22)
12-16 11:42:41.562: DEBUG/BTL_IFC(3161): BTL_IFC_RegisterSubSystem: add new ctrl fd to active set
12-16 11:42:41.562: DEBUG/BTL_IFC_WRP(3161): wrp_wsock_create: BTS
12-16 11:42:41.562: DEBUG/BTL_IFC_WRP(3161): wrp_alloc_new_sock: wrp_alloc_new_sock sub 15
12-16 11:42:41.562: DEBUG/BTL_IFC_WRP(3161): wrp_wsock_create: 33
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): btsk_alloc_add: success
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_socket: return 33
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_setsockopt:  fd (-1:33), bta -1, rc 0, wflags 0x0, cflags 0x0, port 0
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_setsockopt: configure rfcomm lm mode 0x26, (master:0, auth 1, enc 1)
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_setsockopt: success
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_setsockopt:  fd (-1:33), bta -1, rc 0, wflags 0x0, cflags 0x0, port 0
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_setsockopt: configure rfcomm sndbuf len 71680 bytes
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_setsockopt: success
12-16 11:42:41.562: DEBUG/BluetoothSocket.cpp(3161): ...fd 33 created (RFCOMM, lm = 26)
12-16 11:42:41.562: DEBUG/BluetoothSocket.cpp(3161): initSocketFromFdNative
12-16 11:42:41.562: DEBUG/ASOCKWRP(3161): asocket_init
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_fcntl: s 33, cmd 3
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_fcntl:  fd (-1:33), bta -1, rc 0, wflags 0x0, cflags 0x0, port 0
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_fcntl: s 33, cmd 4
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_fcntl:  fd (-1:33), bta -1, rc 0, wflags 0x0, cflags 0x0, port 0
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_fcntl: transparant fcntl
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_fcntl: s 35, cmd 3
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_fcntl: wsock not found, pass through transparantly
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_fcntl: s 35, cmd 4
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_fcntl: wsock not found, pass through transparantly
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_set_asocket: success (33,34,35)
12-16 11:42:41.562: ERROR/com.ss.test.testBump(3161): Got a socket
12-16 11:42:41.562: ERROR/com.ss.test.testBump(3161): DESTROY
12-16 11:42:41.562: DEBUG/BluetoothSocket.cpp(3161): abortNative
12-16 11:42:41.562: DEBUG/ASOCKWRP(3161): asocket_abort [33,34,35]
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_shutdown: s 33, how 2
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_shutdown:  fd (-1:33), bta -1, rc 0, wflags 0x0, cflags 0x0, port 0
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_shutdown: shutdown socket
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_write: wrote 1 bytes out of 1 on fd 35
12-16 11:42:41.562: DEBUG/BluetoothSocket.cpp(3161): ...asocket_abort(33) complete
12-16 11:42:41.562: DEBUG/BluetoothSocket.cpp(3161): destroyNative
12-16 11:42:41.562: DEBUG/ASOCKWRP(3161): asocket_destroy
12-16 11:42:41.562: DEBUG/ASOCKWRP(3161): asocket_abort [33,34,35]
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_shutdown: s 33, how 2
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_shutdown:  fd (-1:33), bta -1, rc 0, wflags 0x0, cflags 0x0, port 0
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_shutdown: shutdown socket
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_write: wrote 1 bytes out of 1 on fd 35
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_close: s 35
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_close: std close (35)
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_close: s 34
12-16 11:42:41.562: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_close: std close (34)
12-16 11:42:41.562: INFO/BLZ20_WRAPPER(3161): blz20_wrp_close: s 33
12-16 11:42:41.569: DEBUG/BLZ20_WRAPPER(3161): blz20_wrp_close:  fd (-1:33), bta -1, rc 0, wflags 0x0, cflags 0x0, port 0
12-16 11:42:41.569: INFO/BLZ20_WRAPPER(3161): __close_prot_rfcomm: fd 33
12-16 11:42:41.569: DEBUG/BTL_IFC(3161): BTL_IFC_CtrlSend: BTL_IFC_CtrlSend
12-16 11:42:41.569: INFO/BTL_IFC(3161): send_ctrl_msg: [BTL_IFC CTRL] send BTLIF_BTS_RFC_CLOSE (BTS) 8 pbytes (hdl 32)
12-16 11:42:41.569: DEBUG/(2751): btlif_bts_api_ctrl_cb: btlif_bts_api_ctrl_cb : id BTLIF_BTS_RFC_CLOSE (4468) on hdl 22
12-16 11:42:41.569: DEBUG/(2751): btlif_rfc_close: scn 0, sock 33
12-16 11:42:41.569: INFO/(2751): btlif_rfc_close: channel not found scn 0, sock 33
12-16 11:42:41.569: DEBUG/BTL_IFC_WRP(3161): wrp_close_s_only: wrp_close_s_only [33] (33:-1) []
12-16 11:42:41.569: DEBUG/BTL_IFC_WRP(3161): wrp_close_s_only: data socket closed
12-16 11:42:41.569: DEBUG/BTL_IFC_WRP(3161): wsactive_del: delete wsock 33 from active list [ad3f5f70]
12-16 11:42:41.569: DEBUG/BTL_IFC_WRP(3161): wrp_close_s_only: wsock fully closed, return to pool
12-16 11:42:41.569: DEBUG/BLZ20_WRAPPER(3161): btsk_free: success
12-16 11:42:41.569: DEBUG/BluetoothSocket.cpp(3161): ...asocket_destroy(33) complete
12-16 11:42:41.569: ERROR/com.ss.test.testBump(3161): DESTROYED

As you can see from log, socket closed successfully. Now, exit from app (it'll run in background), run to Task Manager and kill app. In that moment android device will freeze with very high CPU load.

EDIT 2:

I found, that issue reproduce on Samsung GALAXY Tab device only. For example, I can't reproduce it with my HTC Desire.

回答1:

A solution I found working (for a samsung galaxy mini) - that is quite unfriendly to the user, and not good "design" (but the broadcom firmware bug is not good "design" anyway) - but it's better than letting the user's phone freeze - is to turn OFF the bluetooth after we're done:

In both my onDestroy() and onBackPressed() - I call my cleanup() function that has something like this:

if(mBluetoothAdapter != null)
{           
mBluetoothAdapter.disable();            
}    
mBluetoothAdapter = null;

回答2:

Did the socket get successfully created before calling the Close() method ? I would try initializing the socket to null before the call to createRfcommSocketToServiceRecord(UUID) The Bluetooth Chat example does this .. here is a snippet .

public ConnectThread(BluetoothDevice device) {
        mmDevice = device;
        BluetoothSocket tmp = null;

        // Get a BluetoothSocket for a connection with the
        // given BluetoothDevice
        try { 
            tmp = device.createRfcommSocketToServiceRecord(MY_UUID);
        } catch (IOException e) {
            Log.e(TAG, "create() failed", e);
        }
        mmSocket = tmp;
    }

    public void cancel() {
        try {
            mmSocket.close();
        } catch (IOException e) {
            Log.e(TAG, "close() of connect socket failed", e);
        }
    }

回答3:

Take a look at the code that calls cancel(). In particular, look at how it handles runtime exceptions thrown by cancel(). The code above will throw a NPE if cancel() is called after ConnectThread() catches an exception.

Also, check any loops where you perform an operation on socket. Once the close() is called, connect(), getInputStream(), and getOutputStream() will throw IOEs.

回答4:

Did you try looking into traceview ? which method is stalling the cpu ? That may give you some insights on this problem. Even if this happens only on a particular device, you should be able to find with traceview.

回答5:

I am facing the same issue but in server mode when I used BluetoothServerSocket. I was using system.exit(0) to quit the application which I read somewhere this is not recommended. I removed the system.exit(0) call and I don't have the freeze issue. (But if I kill the app then it does exhibit the freeze).

Does anybody has an issue in Server mode when sometimes the SDP record doesn't get deleted?

回答6:

OK, it's an Samsung GALAXY Tab bug, so waiting Android update...

UPDATE: fixed in new firmware!