Re: bluez-4.11 + 2.6.27-rc8 + SCO headset -> Invalid read of size 4

Stuart Pook
2008-10-06T18:38:55Z

hi Johan

> I think I managed to fix the segfault issue. The valgrind backtrace was
> actually misleading/incorrect but I managed to get a proper one with
> gdb.

I ran bluetoothd 4.11 from the source directory and the error message is
in fact different. Do you know why?

> Could you try the latest git and see if the segfault is gone?

next step!

> Unfortunately this still leaves you with the original issue of your
> player bailing out too early.

yes :-(

bluetoothd[15350]: connect(): Connection timed out (110)
==15350== Invalid read of size 4
==15350== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x1361D: error_common_reply (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x4ED9D2C: error_connection_attempt_failed (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x4EDA117: sco_connect_cb (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x2165E: connect_cb (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0xA410: main (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== Address 0x464c45b3 is not stack'd, malloc'd or (recently) free'd

:; while sleep 15; do aplay -D JX10 lib/alarm.wav ; done
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
^CAborted by signal Interrupt...
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
bt_audio_service_open: connect() failed: Connection refused (111)
aplay: main:564: audio open error: Connection refused

: root@kooka; valgrind bluez-4.11/src/.libs/bluetoothd -dn
==15350== Memcheck, a memory error detector.
==15350== Copyright (C) 2002-2007, and GNU GPL'd, by Julian Seward et al.
==15350== Using LibVEX rev 1854, a library for dynamic binary translation.
==15350== Copyright (C) 2004-2007, and GNU GPL'd, by OpenWorks LLP.
==15350== Using valgrind-3.3.1-Debian, a dynamic binary instrumentation framework.
==15350== Copyright (C) 2000-2007, and GNU GPL'd, by Julian Seward et al.
==15350== For more details, rerun with: -v
==15350==
bluetoothd[15350]: Bluetooth daemon
bluetoothd[15350]: Enabling debug information
bluetoothd[15350]: parsing main.conf
bluetoothd[15350]: offmode=NoScan
bluetoothd[15350]: discovto=0
bluetoothd[15350]: pageto=8192
bluetoothd[15350]: name=%h-%d
bluetoothd[15350]: class=0x000100
bluetoothd[15350]: inqmode=0
bluetoothd[15350]: Starting SDP server
bluetoothd[15350]: Loading plugins /usr/local/lib/bluetooth/plugins
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/audio.so
bluetoothd[15350]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
bluetoothd[15350]: Unix socket created: 11
bluetoothd[15350]: Telephony plugin initialized
bluetoothd[15350]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/serial.so
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/hal.so
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/service.so
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/network.so
bluetoothd[15350]: Parsing /etc/bluetooth/network.conf failed: No such file or directory
bluetoothd[15350]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true
==15350== Warning: noted but unhandled ioctl 0x89a0 with no size/direction hints
==15350== This could cause spurious value errors to appear.
==15350== See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
bluetoothd[15350]: bridge pan0 created
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/input.so
bluetoothd[15350]: input.conf: Key file does not have key 'IdleTimeout'
bluetoothd[15350]: HCI dev 0 registered
bluetoothd[15350]: child 15359 forked
bluetoothd[15350]: HCI dev 0 already up
==15359==
==15359== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 84 from 2)
==15359== malloc/free: in use at exit: 30,100 bytes in 352 blocks.
==15359== malloc/free: 751 allocs, 399 frees, 290,809 bytes allocated.
==15359== For counts of detected errors, rerun with: -v
==15359== searching for pointers to 352 not-freed blocks.
bluetoothd[15350]: headset_server_probe: path /org/bluez/hci0
==15359== checked 146,028 bytes.
==15359==
==15359== LEAK SUMMARY:
==15359== definitely lost: 0 bytes in 0 blocks.
==15359== possibly lost: 744 bytes in 3 blocks.
==15359== still reachable: 29,356 bytes in 349 blocks.
==15359== suppressed: 0 bytes in 0 blocks.
==15359== Rerun with --leak-check=full to see details of leaked memory.
bluetoothd[15350]: Adding record with handle 0x10000
bluetoothd[15350]: Adding record with handle 0x10001
bluetoothd[15350]: a2dp_server_probe: path /org/bluez/hci0
bluetoothd[15350]: SEP 0x4b31198 registered: type:0 codec:0 seid:1
bluetoothd[15350]: Adding record with handle 0x10002
bluetoothd[15350]: avrcp_server_probe: path /org/bluez/hci0
bluetoothd[15350]: Adding record with handle 0x10003
bluetoothd[15350]: Adding record with handle 0x10004
bluetoothd[15350]: proxy_probe: path /org/bluez/hci0
bluetoothd[15350]: Registered interface org.bluez.SerialProxyManager on path /org/bluez/hci0
bluetoothd[15350]: service_probe: path /org/bluez/hci0
bluetoothd[15350]: Registered interface org.bluez.Service on path /org/bluez/hci0
bluetoothd[15350]: network_server_probe: path /org/bluez/hci0
bluetoothd[15350]: Adding record with handle 0x10005
bluetoothd[15350]: register_server_record: got record id 0x10005
bluetoothd[15350]: Registered interface org.bluez.NetworkPeer on path /org/bluez/hci0
bluetoothd[15350]: network_server_probe: path /org/bluez/hci0
bluetoothd[15350]: Adding record with handle 0x10006
bluetoothd[15350]: register_server_record: got record id 0x10006
bluetoothd[15350]: Registered interface org.bluez.NetworkHub on path /org/bluez/hci0
bluetoothd[15350]: network_server_probe: path /org/bluez/hci0
bluetoothd[15350]: Adding record with handle 0x10007
bluetoothd[15350]: register_server_record: got record id 0x10007
bluetoothd[15350]: Registered interface org.bluez.NetworkRouter on path /org/bluez/hci0
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15350]: Probe drivers for /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15350]: Found Headset record
bluetoothd[15350]: Discovered Headset service on RFCOMM channel 2
bluetoothd[15350]: Registered interface org.bluez.Headset on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15350]: Found Hansfree record
bluetoothd[15350]: Discovered Handsfree service on RFCOMM channel 1
bluetoothd[15350]: headset_probe: path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15350]: Registered interface org.bluez.Input on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_14_A7_74_D3_AF
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_03_89_B7_F8_D3
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_0A_94_94_4F_B3
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_03_89_DC_5C_9F
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_03_89_DC_FC_EC
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_03_89_FE_E6_19
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_0E_6D_8F_91_6A
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_17_E5_E6_25_AB
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_17_E5_16_88_6C
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_17_E5_0C_EA_70
bluetoothd[15350]: Adapter /org/bluez/hci0 has been enabled
bluetoothd[15350]: Starting security manager 0
bluetoothd[15350]: child 15359 exited
bluetoothd[15350]: Computer is classified as desktop
bluetoothd[15350]: Current device class is 0x4a0104
bluetoothd[15350]: Setting 0x000104 for major/minor device class
bluetoothd[15350]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15350]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15350]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15350]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15350]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15350]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15350]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[15350]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[15350]: kernel auth requirements = 0x04
bluetoothd[15350]: stored link key type = 0x00
bluetoothd[15350]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[15350]: Received AT+BRSF=27
bluetoothd[15350]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[15350]: Received AT+CIND=?
bluetoothd[15350]: Received AT+CIND?
bluetoothd[15350]: Received AT+CMER=3, 0, 0, 1
bluetoothd[15350]: Event reporting (CMER): mode=3, ind=1
bluetoothd[15350]: HFP Service Level Connection established
bluetoothd[15350]: telephony-dummy: device 0x4b70708 connected
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[15350]: Received AT+VGS=15
bluetoothd[15350]: connect(): Connection timed out (110)
bluetoothd[15350]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[15350]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[15350]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[15350]: Audio API: sending BT_STREAMFD_IND
bluetoothd[15350]: unix_sendmsg_fd: Bad file descriptor(9)
bluetoothd[15350]: resume failed
bluetoothd[15350]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[15350]: Unix client disconnected (fd=23)
bluetoothd[15350]: No matching connection for handle 45
bluetoothd[15350]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15350]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15350]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15350]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15350]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[15350]: Unix client disconnected (fd=23)
bluetoothd[15350]: telephony-dummy: device 0x4b70708 disconnected
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[15350]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15350]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15350]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15350]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15350]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15350]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15350]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[15350]: Received AT+BRSF=27
bluetoothd[15350]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[15350]: Received AT+CIND=?
bluetoothd[15350]: Received AT+CIND?
bluetoothd[15350]: Received AT+CMER=3, 0, 0, 1
bluetoothd[15350]: Event reporting (CMER): mode=3, ind=1
bluetoothd[15350]: HFP Service Level Connection established
bluetoothd[15350]: telephony-dummy: device 0x4b70708 connected
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[15350]: connect: Operation not permitted (1)
bluetoothd[15350]: config failed
bluetoothd[15350]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[15350]: Unix client disconnected (fd=23)
bluetoothd[15350]: Received AT+VGS=15
bluetoothd[15350]: connect(): Connection timed out (110)
==15350== Invalid read of size 4
==15350== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x1361D: error_common_reply (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x4ED9D2C: error_connection_attempt_failed (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x4EDA117: sco_connect_cb (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x2165E: connect_cb (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0xA410: main (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== Address 0x464c45b3 is not stack'd, malloc'd or (recently) free'd
==15350==
==15350== Process terminating with default action of signal 11 (SIGSEGV)
==15350== Access not within mapped region at address 0x464C45B3
==15350== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x1361D: error_common_reply (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x4ED9D2C: error_connection_attempt_failed (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x4EDA117: sco_connect_cb (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x2165E: connect_cb (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0xA410: main (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350==
==15350== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 84 from 2)
==15350== malloc/free: in use at exit: 46,531 bytes in 869 blocks.
==15350== malloc/free: 2,715 allocs, 1,846 frees, 1,361,168 bytes allocated.
==15350== For counts of detected errors, rerun with: -v
==15350== searching for pointers to 869 not-freed blocks.
==15350== checked 162,032 bytes.
==15350==
==15350== LEAK SUMMARY:
==15350== definitely lost: 204 bytes in 3 blocks.
==15350== possibly lost: 864 bytes in 4 blocks.
==15350== still reachable: 45,463 bytes in 862 blocks.
==15350== suppressed: 0 bytes in 0 blocks.
==15350== Rerun with --leak-check=full to see details of leaked memory.
Segmentation fault