There seems to be a bug with the bluetooth daemon on the android phone
(in my case the Motorola Milestone), which prevents from enabling the
bluetooth. If you're trying to enable it in the option menu, it shows
you the message that it's getting enabled, but stays like that for \~1-2
minutes, whereas it's still disabled afterwards. Using the widget to
reenable it doesn't help as a stupid workaround, also the cold-reboot
(as recommended in several places) doesn't help any further.
So let's get into it a bit more in deep.... (skip the next chapter if
you only want to have it fixed, and don't care about the background)
Investigations
So since we're running a linux kernel (+some daemons), we're used to the verbose output/logfiles of them. So where can you get the 'dmesg' and the '--verbose' on an android phone? Like on an iPh.., there are also apps for everything on an android phone, so get your ass in the market and lookout for the 'Log Collector' and install it. So now that you've got it installed, just open it, and choose a method to send the log (mail, bluetooth, sms etc). My log looks like this (yep, the log is not from today, but it wouldn't differ even if.... ;-)):
Log Collector version: 1.1.0
Device model: Milestone
Firmware version: 2.0
Kernel version: 2.6.29-omap1
a21146@ca25rhe53 )
#1 PREEMPT Thu Nov 5 17:24:53 PST 2009
Build number: SHOLS_U2_01.03.1.1257641482
.....
05-18 00:28:43.066 E/BluetoothEventLoop.cpp( 1240): get_adapter_path: D-Bus error: org.freedesktop.DBus.Error.ServiceUnknown (The name org.bluez was not provided by any .service files)
05-18 00:28:43.355 I/DEBUG ( 1042): *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
05-18 00:28:43.355 I/DEBUG ( 1042): Build fingerprint: 'MOTO_O2DE/umts_sholes/umts_sholes/sholes:2.0/SHOLS_U2_01.03.1/1257641482:user/rel-keys'
05-18 00:28:43.355 I/DEBUG ( 1042): pid: 1931, tid: 1931 >>> /system/bin/bluetoothd <<<
05-18 00:28:43.355 I/DEBUG ( 1042): signal 11 (SIGSEGV), fault addr 4000d000
05-18 00:28:43.363 I/DEBUG ( 1042): r0 4000d000 r1 00000020 r2 afe3db8c r3 00000000
05-18 00:28:43.363 I/DEBUG ( 1042): r4 00016d18 r5 00012370 r6 4000ced7 r7 4000d000
05-18 00:28:43.363 I/DEBUG ( 1042): r8 00000128 r9 beaef938 10 aeb797ac fp 00000129
05-18 00:28:43.363 I/DEBUG ( 1042): ip aeb7e5b4 sp beaef880 lr aeb43711 pc afe1bec4 cpsr 20000030
05-18 00:28:43.371 I/DEBUG ( 1042): #00 pc 0001bec4 /system/lib/libc.so
05-18 00:28:43.371 I/DEBUG ( 1042): #01 lr aeb43711 /system/lib/libbluetoothd.so
05-18 00:28:43.371 I/DEBUG ( 1042):
05-18 00:28:43.371 I/DEBUG ( 1042): code around pc:
05-18 00:28:43.371 I/DEBUG ( 1042): afe1beb4 5cccd1fb 330154d4 d1fa2c00 bf00bd10
05-18 00:28:43.371 I/DEBUG ( 1042): afe1bec4 428b7803 b10bd003 e7f93001 47704618
05-18 00:28:43.371 I/DEBUG ( 1042): afe1bed4 e0032200 b90b3201 e0064618 f8115c83
05-18 00:28:43.371 I/DEBUG ( 1042):
05-18 00:28:43.371 I/DEBUG ( 1042): code around lr:
05-18 00:28:43.371 I/DEBUG ( 1042): aeb43700 4620ea04 ea00f7cc 21204638 ea14f7cc
05-18 00:28:43.371 I/DEBUG ( 1042): aeb43710 28004606 9c05d1be 98032654 f7cc9904
05-18 00:28:43.371 I/DEBUG ( 1042): aeb43720 e002e8bc e9d2f7cc 46206806 f7cc2108
05-18 00:28:43.371 I/DEBUG ( 1042):
05-18 00:28:43.371 I/DEBUG ( 1042): stack:
05-18 00:28:43.371 I/DEBUG ( 1042): beaef840 afe3d9d4
05-18 00:28:43.371 I/DEBUG ( 1042): beaef844 00000000
05-18 00:28:43.371 I/DEBUG ( 1042): beaef848 00016e40 [heap]
05-18 00:28:43.371 I/DEBUG ( 1042): beaef84c 0000a000 [heap]
05-18 00:28:43.371 I/DEBUG ( 1042): beaef850 00000128
05-18 00:28:43.371 I/DEBUG ( 1042): beaef854 afe0b34d /system/lib/libc.so
05-18 00:28:43.371 I/DEBUG ( 1042): beaef858 4000abdc /data/misc/bluetoothd/C0:E4:22:50:AD:1F/sdp
05-18 00:28:43.371 I/DEBUG ( 1042): beaef85c 00000009
05-18 00:28:43.371 I/DEBUG ( 1042): beaef860 00002bcc
05-18 00:28:43.371 I/DEBUG ( 1042): beaef864 00000000
05-18 00:28:43.371 I/DEBUG ( 1042): beaef868 beaef938 [stack]
05-18 00:28:43.371 I/DEBUG ( 1042): beaef86c 00016d18 [heap]
05-18 00:28:43.371 I/DEBUG ( 1042): beaef870 00012370 [heap]
05-18 00:28:43.371 I/DEBUG ( 1042): beaef874 4000ced7 /data/misc/bluetoothd/C0:E4:22:50:AD:1F/sdp
05-18 00:28:43.371 I/DEBUG ( 1042): beaef878 df002777
05-18 00:28:43.371 I/DEBUG ( 1042): beaef87c e3a070ad
05-18 00:28:43.371 I/DEBUG ( 1042): #00 beaef880 00000012
05-18 00:28:43.371 I/DEBUG ( 1042): beaef884 00000000
05-18 00:28:43.371 I/DEBUG ( 1042): beaef888 aeb1cff9 /system/lib/libbluetoothd.so
05-18 00:28:43.371 I/DEBUG ( 1042): beaef88c 4000a000 /data/misc/bluetoothd/C0:E4:22:50:AD:1F/sdp
05-18 00:28:43.371 I/DEBUG ( 1042): beaef890 00003000
05-18 00:28:43.371 I/DEBUG ( 1042): beaef894 00000012
05-18 00:28:43.371 I/DEBUG ( 1042): beaef898 00001f08
05-18 00:28:43.371 I/DEBUG ( 1042): beaef89c 00000000
05-18 00:28:43.371 I/DEBUG ( 1042): beaef8a0 00000000
05-18 00:28:43.371 I/DEBUG ( 1042): beaef8a4 000006d9
05-18 00:28:43.371 I/DEBUG ( 1042): beaef8a8 000081a4 /system/bin/bluetoothd
05-18 00:28:43.371 I/DEBUG ( 1042): beaef8ac 00000001
05-18 00:28:43.371 I/DEBUG ( 1042): beaef8b0 000003ea
05-18 00:28:43.371 I/DEBUG ( 1042): beaef8b4 000003ea
05-18 00:28:43.371 I/DEBUG ( 1042): beaef8b8 00000000
05-18 00:28:43.371 I/DEBUG ( 1042): beaef8bc 00000000
05-18 00:28:43.371 I/DEBUG ( 1042): beaef8c0 00000000
05-18 00:28:43.371 I/DEBUG ( 1042): beaef8c4 00000000
05-18 00:28:43.433 E/BluetoothEventLoop.cpp( 1240): get_adapter_path: D-Bus error: org.freedesktop.DBus.Error.NoReply (Message did not receive a reply (timeout by message bus))
05-18 00:28:43.433 E/BluetoothEventLoop.cpp( 1240): failure setting up Event Loop!
05-18 00:28:43.943 D/BluetoothService( 1240): bt EnableThread giving up
05-18 00:28:43.943 I/bluedroid( 1240): Stopping bluetoothd deamon
05-18 00:28:44.453 I/bluedroid( 1240): Stopping hciattach deamon
05-18 00:28:44.453 I/usbd ( 1059): process_usb_uevent_message(): buffer = change@/devices/platform/wl127x-rfkill.0/rfkill/rfkill0
05-18 00:28:44.453 I/usbd ( 1059): main(): call select(...)
05-18 00:28:44.457 I/usbd ( 1059): process_usb_uevent_message(): buffer = remove@/devices/virtual/bluetooth/hci0
05-18 00:28:44.457 I/usbd ( 1059): main(): call select(...)
05-18 00:28:44.472 V/BluetoothEventRedirector( 1895): Received android.bluetooth.adapter.action.STATE_CHANGED
05-18 00:28:44.512 W/Process ( 1240): Unable to open /proc/1933/status
05-18 00:28:47.285 I/wpa_supplicant( 1194): CTRL-EVENT-STATE-CHANGE id=0 state=6
05-18 00:28:47.285 V/WifiMonitor( 1240): Event [CTRL-EVENT-STATE-CHANGE id=0 state=6]
05-18 00:28:47.293 V/WifiStateTracker( 1240): Changing supplicant state: COMPLETED ==> GROUP_HANDSHAKE
05-18 00:28:47.293 I/wpa_supplicant( 1194): WPA: Group rekeying completed with 00:00:00:00:00:00 [GTK=CCMP]
05-18 00:28:47.293 V/WifiMonitor( 1240): Event [WPA: Group rekeying completed with 00:00:00:00:00:00 [GTK=CCMP]]
05-18 00:28:47.293 I/wpa_supplicant( 1194): CTRL-EVENT-STATE-CHANGE id=0 state=7
05-18 00:28:47.293 V/WifiMonitor( 1240): Event [CTRL-EVENT-STATE-CHANGE id=0 state=7]
05-18 00:28:47.293 V/WifiStateTracker( 1240): Changing supplicant state: GROUP_HANDSHAKE ==> COMPLETED
05-18 00:28:49.683 D/dalvikvm( 1895): GC freed 1509 objects / 98880 bytes in 86ms
05-18 00:28:49.910 W/BatteryStatsImpl( 1240): Couldn't get kernel wake lock stats
05-18 00:28:49.926 D/WifiService( 1240): ACTION_BATTERY_CHANGED pluggedType: 0
05-18 00:28:49.933 I/usbd ( 1059): process_usb_uevent_message(): buffer = change@/devices/platform/cpcap_battery/power_supply/battery
05-18 00:28:49.933 I/usbd ( 1059): main(): call select(...)
05-18 00:29:00.691 D/dalvikvm( 1618): GC freed 15736 objects / 521720 bytes in 361ms
05-18 00:29:03.394 I/power ( 1240): *** set_screen_state 0
05-18 00:29:03.394 D/SurfaceFlinger( 1240): About to give-up screen, flinger = 0x148e20
05-18 00:29:03.394 D/Sensors ( 1240): using accelerometer (name=accelerometer)
05-18 00:29:03.433 D/WifiService( 1240): ACTION_SCREEN_OFF
05-18 00:29:03.449 D/WifiService( 1240): setting ACTION_DEVICE_IDLE timer for 900000ms
05-18 00:29:03.457 W/SSM ( 1060): no ack
05-18 00:29:03.504 D/ThumbnailIntentReceiver( 1720): received Intent android.intent.action.SCREEN_OFF, mGalleryRunning is false
05-18 00:29:03.527 I/System.out( 1680): First Task is :::com.android.launcher
05-18 00:29:03.527 D/ActivityManager( 1240): Uninstalling process com.android.vending
05-18 00:29:03.527 D/ActivityManager( 1240): Force removing process ProcessRecord{44eef628 1853:com.android.vending/10011} (com.android.vending/10011)
05-18 00:29:03.535 I/Process ( 1240): Sending signal. PID: 1853 SIG: 9
05-18 00:29:03.535 D/ActivityManager( 1240): Force finishing activity com.android.vending/.SearchAssetListActivity
05-18 00:29:03.535 W/ActivityManager( 1240): Activity HistoryRecord{44eed108 com.android.vending/.SearchAssetListActivity} being finished, but not in LRU list
05-18 00:29:03.535 D/ActivityManager( 1240): Force finishing activity com.android.vending/.AssetBrowserActivity
05-18 00:29:03.535 W/ActivityManager( 1240): Activity HistoryRecord{44b65ac8 com.android.vending/.AssetBrowserActivity} being finished, but not in LRU list
05-18 00:29:03.535 D/GTalkService( 1379): [GTalkService.1] logoutAllSessions
05-18 00:29:03.668 W/ResourceType( 1240): Resources don't contain package for resource number 0x7f060001
05-18 00:29:03.676 I/WindowManager( 1240): WIN DEATH: Window{44cddbf0 com.android.vending/com.android.vending.AssetBrowserActivity paused=true}
05-18 00:29:03.676 D/ActivityManager( 1240): Received spurious death notification for thread android.os.BinderProxy@44c4d958
05-18 00:29:03.676 I/WindowManager( 1240): WIN DEATH: Window{44b30b80 com.android.vending/com.android.vending.SearchAssetListActivity paused=true}
05-18 00:29:03.683 D/ActivityManager( 1240): Uninstalling process com.google.code.appsorganizer
05-18 00:29:03.683 D/ActivityManager( 1240): Force removing process ProcessRecord{44f402a8 1846:com.google.code.appsorganizer/10069} (com.google.code.appsorganizer/10069)
05-18 00:29:03.683 I/Process ( 1240): Sending signal. PID: 1846 SIG: 9
05-18 00:29:03.683 D/ActivityManager( 1240): Force finishing activity com.google.code.appsorganizer/.shortcut.LabelShortcut
05-18 00:29:03.683 W/ActivityManager( 1240): Activity HistoryRecord{44b49878 com.google.code.appsorganizer/.shortcut.LabelShortcut} being finished, but not in LRU list
05-18 00:29:03.691 W/ResourceType( 1240): Resources don't contain package for resource number 0x7f060001
05-18 00:29:03.691 I/WindowManager( 1240): WIN DEATH: Window{44c5c5e0 com.google.code.appsorganizer/com.google.code.appsorganizer.shortcut.LabelShortcut paused=true}
05-18 00:29:03.699 D/ActivityManager( 1240): Received spurious death notification for thread android.os.BinderProxy@44d9ba08
05-18 00:29:03.699 I/System.out( 1680): size of runningProcess is 27
05-18 00:29:03.715 D/ActivityManager( 1240): Uninstalling process com.android.settings
05-18 00:29:03.715 D/ActivityManager( 1240): Force removing process ProcessRecord{44f5fd20 1895:com.android.settings/1000} (com.android.settings/1000)
05-18 00:29:03.715 I/Process ( 1240): Sending signal. PID: 1895 SIG: 9
05-18 00:29:03.730 W/ResourceType( 1240): Resources don't contain package for resource number 0x7f060001
05-18 00:29:03.730 D/ActivityManager( 1240): Received spurious death notification for thread android.os.BinderProxy@44c41ac8
05-18 00:29:03.730 D/ActivityManager( 1240): Uninstalling process it.medieval.blueftp
05-18 00:29:03.730 D/ActivityManager( 1240): Force removing process ProcessRecord{44ed7a28 1914:it.medieval.blueftp/10046} (it.medieval.blueftp/10046)
05-18 00:29:03.730 I/Process ( 1240): Sending signal. PID: 1914 SIG: 9
05-18 00:29:03.738 W/ResourceType( 1240): Resources don't contain package for resource number 0x7f060001
05-18 00:29:03.746 D/ActivityManager( 1240): Received spurious death notification for thread android.os.BinderProxy@44e01c30
05-18 00:29:03.746 D/ActivityManager( 1240): Uninstalling process de.anno.android.missedCallDroid
05-18 00:29:03.746 D/ActivityManager( 1240): Force removing process ProcessRecord{44dfd038 1919:de.anno.android.missedCallDroid/10079} (de.anno.android.missedCallDroid/10079)
05-18 00:29:03.746 I/Process ( 1240): Sending signal. PID: 1919 SIG: 9
05-18 00:29:03.754 W/ResourceType( 1240): Resources don't contain package for resource number 0x7f060001
05-18 00:29:03.754 D/ActivityManager( 1240): Received spurious death notification for thread android.os.BinderProxy@44e23b18
05-18 00:29:08.512 W/Process ( 1240): Unable to open /proc/1846/status
05-18 00:29:08.512 W/Process ( 1240): Unable to open /proc/1853/status
05-18 00:29:08.512 W/Process ( 1240): Unable to open /proc/1895/status
05-18 00:29:08.512 W/Process ( 1240): Unable to open /proc/1914/status
05-18 00:29:08.512 W/Process ( 1240): Unable to open /proc/1919/status
05-18 00:29:08.738 D/dalvikvm( 1240): GC freed 13581 objects / 933504 bytes in 154ms
05-18 00:29:08.871 I/ActivityManager( 1240): Start proc com.android.settings for broadcast com.android.settings/.widget.SettingsAppWidgetProvider: pid=1936 uid=1000 gids={3003, 3002, 3001}
05-18 00:29:21.530 I/usbd ( 1059): process_usb_uevent_message(): buffer = change@/devices/platform/wl127x-rfkill.0/rfkill/rfkill0
05-18 00:29:21.530 I/usbd ( 1059): main(): call select(...)
05-18 00:29:21.655 I/dalvikvm( 1936): Debugger thread not active, ignoring DDM send (t=0x41504e4d l=38)
05-18 00:29:50.530 I/usbd ( 1059): process_usb_uevent_message(): buffer = change@/devices/platform/wl127x-rfkill.0/rfkill/rfkill0
05-18 00:29:50.530 I/usbd ( 1059): main(): call select(...)
05-18 00:29:50.678 I/dalvikvm( 1936): Debugger thread not active, ignoring DDM send (t=0x41504e4d l=44)
05-18 00:30:19.530 I/usbd ( 1059): process_usb_uevent_message(): buffer = change@/devices/platform/wl127x-rfkill.0/rfkill/rfkill0
05-18 00:30:19.530 I/usbd ( 1059): main(): call select(...)
05-18 00:30:19.796 I/k9 ( 1454): Committing preference changes
05-18 00:30:20.678 I/k9 ( 1454): Preferences commit took 880ms
05-18 00:30:21.811 D/dalvikvm( 1454): GC freed 12272 objects / 495960 bytes in 98ms
05-18 00:30:23.936 I/k9 ( 1454): Committing preference changes
05-18 00:30:24.272 I/k9 ( 1454): Preferences commit took 333ms
05-18 00:30:24.288 I/k9 ( 1454): Committing preference changes
05-18 00:30:24.327 I/k9 ( 1454): Preferences commit took 38ms
05-18 00:30:26.530 I/usbd ( 1059): process_usb_uevent_message(): buffer = change@/devices/platform/wl127x-rfkill.0/rfkill/rfkill0
05-18 00:30:26.530 I/usbd ( 1059): main(): call select(...)
05-18 00:30:48.522 I/usbd ( 1059): process_usb_uevent_message(): buffer = change@/devices/platform/wl127x-rfkill.0/rfkill/rfkill0
05-18 00:30:48.522 I/usbd ( 1059): main(): call select(...)
05-18 00:30:48.905 I/usbd ( 1059): process_usb_uevent_message(): buffer = change@/devices/platform/wl127x-rfkill.0/rfkill/rfkill0
05-18 00:30:48.905 I/usbd ( 1059): main(): call select(...)
05-18 00:30:48.913 D/KeyguardViewMediator( 1240): wakeWhenReadyLocked(26)
05-18 00:30:48.913 D/KeyguardViewMediator( 1240): handleWakeWhenReady(26)
05-18 00:30:48.913 D/KeyguardViewMediator( 1240): pokeWakelock(5000)
05-18 00:30:48.921 I/power ( 1240): *** set_screen_state 1
05-18 00:30:48.928 D/Sensors ( 1240): using sensors (name=sensors)
05-18 00:30:48.999 D/WifiService( 1240): ACTION_SCREEN_ON
05-18 00:30:49.007 W/SSM ( 1060): no ack
05-18 00:30:49.233 D/SurfaceFlinger( 1240): Screen about to return, flinger = 0x148e20
05-18 00:30:49.303 I/NotificationService( 1240): enqueueToast pkg=biz.stachibana.TaskKiller callback=android.app.ITransientNotification$Stub$Proxy@44f01cb0 duration=1
05-18 00:30:49.374 D/ThumbnailIntentReceiver( 1720): received Intent android.intent.action.SCREEN_ON, mGalleryRunning is false
05-18 00:30:50.358 W/InputManagerService( 1240): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@44d011e0
05-18 00:30:55.655 I/ActivityManager( 1240): Starting activity: Intent { act=android.intent.action.MAIN flg=0x10100000 cmp=com.xtralogic.android.logcollector/.SendLogActivity }
05-18 00:30:55.702 W/InputManagerService( 1240): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@44bd44f8
05-18 00:30:55.858 I/ActivityManager( 1240): Displayed activity com.xtralogic.android.logcollector/.SendLogActivity: 184 ms (total 184 ms)
05-18 00:31:00.296 I/global ( 1902): Default buffer size used in BufferedReader constructor. It would be better to be explicit if an 8k-char buffer is required.
So what we're interested in, are the lines with *bluetooth*, like these:
05-18 00:28:43.355 I/DEBUG ( 1042): pid: 1931, tid: 1931 >>> /system/bin/bluetoothd <<<
05-18 00:28:43.355 I/DEBUG ( 1042): signal 11 (SIGSEGV), fault addr 4000d000
05-18 00:28:43.371 I/DEBUG ( 1042): beaef858 4000abdc /data/misc/bluetoothd/XX:XX:XX:XX:XX:XX/sdp
05-18 00:28:43.433 E/BluetoothEventLoop.cpp( 1240): get_adapter_path: D-Bus error: org.freedesktop.DBus.Error.NoReply (Message did not receive a reply (timeout by message bus))
05-18 00:28:43.433 E/BluetoothEventLoop.cpp( 1240): failure setting up Event Loop!
05-18 00:28:43.943 D/BluetoothService( 1240): bt EnableThread giving up
05-18 00:28:43.943 I/bluedroid( 1240): Stopping bluetoothd deamon
05-18 00:28:44.453 I/bluedroid( 1240): Stopping hciattach deamon
As you can see, the bluetooth daemon suddenly suffered from a SIGSEV
(line 2), ok, doesn't help further, let's continue.. line 3... looks
cool, not directly an errormessage, but seems like a fileaccess at the
moment the programm crashes. What happens if we move the file
/data/misc/bluetoothd/XX:XX:XX:XX:XX:XX/sdp to something called sdp.bak
(the XX:XX.. should be replaced with your bluetooth-interface MAC)?? It
works again!
So what was the real problem?? I'm not totally sure what was wrong with
the file, but if somebody has the same issue, please drop me that 'sdp'
file and i'll have a look at it.. removed my backup after it was working
again... :-D
Fix / Solution
In order for this procedure, you need to have a rooted phone, else you don't have access to the root of your filesystem! Tutorials about rooting can be found everywhere on the net, just google. Was easy on my Milestone, but seems to be tricky on a HTC desire as I've been told by a friend of mine.
From the app-side, there's only a shell 'connection' required to your phone, which 'Connectbox' does just fine. ..If you want to use tools like root-explorer, feel free to do so, haven't tested them, but they sound like filemanagers allowing root-access, so if you can do a file-move, it's already enough.
- Connect to your phone using Connectbox
- Get root, type 'su
' - move the file away, type 'mv
/data/misc/bluetoothd/XX:XX:XX:XX:XX:XX/sdp
/data/misc/bluetoothd/XX:XX:XX:XX:XX:XX/sdp.bak
' - exit Connectbot and turn on bluetooth in the settings dialog
Notes
As mentioned early in the article, you need to be root in order to alter
any files in the root-directory.
You might wonder what the sdp file contains.. Just check it out with a
texteditor, it's a simpleplain-text file. And just that you know, it's
safe to move the file away, since it doesn't contain valueable
information. SDP stands for 'Service Discovery Protocol' and is used by
bluetooth to determine which services a particular device offers. And as
simple as that, your phone can/will simply rerun the scan if it's
lacking these information.
Hope you enjoyed! If you have questions, don't hesitate to ask in the comments below.
Edit (28.06.2010): Seems like I'm not the only one having this issue: Android Bugtracker and Google support forums. I've asked a guy there to drop me the faulty SDP file, so I can investigate it, complete the bugreport and have it fixed in the next release ;-)
Cheers,
Raphi