Re: Permission denied (13) on Samsung WEP475 headset?

[Colin Beckingham <colbec@start.ca>]

On 08/08/2011 09:53 AM, Peter Hurley wrote:
> On Mon, 2011-08-08 at 09:31 -0400, Colin Beckingham wrote:
>>
>> On 08/08/2011 08:38 AM, Peter Hurley wrote:
>>> On Sat, 2011-08-06 at 13:22 -0400, Colin Beckingham wrote:
>>>> On 08/06/2011 12:50 PM, Peter Hurley wrote:
>>>>> On Sat, 2011-08-06 at 11:33 -0400, Colin Beckingham wrote:
>>>>>> Hi Peter:
>>>>>>
>>>>> ...<snip>...
>>>>>> I ran # hciconfig hci0 sspmode 1 to force the adapter into a secure attempt.
>>>>>>
>>>>>> I downloaded and installed the latest hcidump which identifies itself
>>>>>> (hcidump -v) as 2.0 even though it is marked as 2.1 version on the webpage.
>>>>>>
>>>>>> Made another attempt to connect, here is the syslog
>>>>>>
>>>>>> # tail -n 100 /var/log/messages | grep bluetoothd
>>>>>> Aug  6 05:15:39 linux-c96h bluetoothd[1246]: Audio connection got
>>>>>> disconnected
>>>>>> Aug  6 11:23:29 linux-c96h bluetoothd[1246]: Rejecting request: remote
>>>>>> device can't provide MITM
>>>>>> Aug  6 11:23:56 linux-c96h bluetoothd[1246]: Discovery session
>>>>>> 0x7f801d0a6ca0 with :1.4178 activated
>>>>>> Aug  6 11:24:01 linux-c96h bluetoothd[1246]: Stopping discovery
>>>>>> Aug  6 11:24:13 linux-c96h bluetoothd[1246]: Permission denied (13)
>>>>>>
>>>>>> and a binary hcidump is attached.
>>>>>
>>>>> Hi Colin,
>>>>>
>>>>> That makes a lot more sense!
>>>>>
>>>>> Would you please repeat the experiment with bluetoothd in debug mode,
>>>>> though? That would give me a lot more information to work with about how
>>>>> bluetoothd got to that point.
>>>>>
>>>>> As before, please capture hcidump binary at the same time. Also please
>>>>> include every bluetoothd syslog message starting from the start of the
>>>>> experiment.
>>>>>
>>>>> I appreciate your patience helping me to track down this bug.
>>>>>
>>>>> Regards,
>>>>> Peter Hurley
>>>>
>>>> Sorry, forgot to set bluetoothd in debug mode.
>>>>
>>>> Attached are my latest logs, 2 files, wep475a.*. Note in the syslog that
>>>> the first entry is timestamped way before the experiment was launched,
>>>> so the log should have everything that bluetoothd wrote for the current
>>>> experiment.
>>>
>>> Hi Colin,
>>>
>>> Well, the new logs did not recreate the "Rejecting request: remote
>>> device can't provide MITM". However, they did show 2 things:
>>>
>>> 1. The host controller has a race condition bug which has been seen
>>> before (see this thread
>>> http://comments.gmane.org/gmane.linux.bluez.kernel/14286 for the really
>>> technical discussion)
>>>
>>> That's why the initial attempt by the device at connecting an RFCOMM
>>> channel is rejected (@ 13:13:02.533713).
>>>
>>> Nevertheless, the headset is found anyway and Bluez connects to the
>>> headset. After establishing an insecure SDP link, Bluez attempts to open
>>> an RFCOMM channel to the device, and
>>>
>>> 2. the kernel attempts to connect the RFCOMM channel prior to the link
>>> being encrypted, so the device rejects the connection.
>>>
>>> There were some last minute changes to 3.0 final that directly impacts
>>> how this is supposed to work. However, even with those changes it's
>>> unclear to me how #2 is happening.
>>>
>>> Would you be willing to run the same experiment as before but with the
>>> kernel bluetooth module enabled for debug output?  If your kernel is
>>> configured for dynamic debug (Kernel hacking/Enable dynamic printk()
>>> support =>   Y), doing this is trivial:
>>> # sudo su
>>> # echo -n "module bluetooth +p"
>>>                       >   /sys/kernel/debug/dynamic_debug/control
>>> <   perform experiment>
>>> # echo -n "module bluetooth -p"
>>>                       >   /sys/kernel/debug/dynamic_debug/control
>>>
>>> Regards,
>>> Peter Hurley
>>
>> Peter, before I do this, let me just verify that my kernel is set up
>> right. I checked for dynamic printk and I am not clear that I have the
>> setting needed. Here is what my .config tells me for dynamic and printk
>> separately.
>>
>>   >  cat .config | grep DYNAMIC
>> CONFIG_NETCONSOLE_DYNAMIC=y
>> CONFIG_DVB_DYNAMIC_MINORS=y
>> CONFIG_SND_DYNAMIC_MINORS=y
>> # CONFIG_USB_DYNAMIC_MINORS is not set
>> CONFIG_HAVE_DYNAMIC_FTRACE=y
>> CONFIG_DYNAMIC_DEBUG=y
>    ^^^^^^^^
>
> This is the one and it's set correctly.
>
>>   >  cat .config | grep PRINTK
>> CONFIG_PRINTK=y
>> CONFIG_SND_VERBOSE_PRINTK=y
>> CONFIG_PRINTK_TIME=y
>> # CONFIG_BOOT_PRINTK_DELAY is not set
>> CONFIG_EARLY_PRINTK=y
>> CONFIG_EARLY_PRINTK_DBGP=y
>>
>> Could you confirm that I am ok to go?
>
> BTW, I just figured out how the kernel does the wrong thing now. If you
> want to wait on running this experiment, that's fine with me. I can
> contact you if someone wants proof that this happens.
>
> ~Peter

OK, Peter, I will put a hold on this. Let me know if you need further input.
-- 
---
Colin Beckingham