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 ��.n��������+%������w��{.n�����{��� �^n�r������&��z�ޗ�zf���h���~����������_��+v���)ߣ�
