Re: Kernel oops with bluetooth usb dongle

[Quel Qun]

 -------------- Original message ----------------------
From: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
> On Thu, 21 Feb 2008, Quel Qun wrote:
> > > >  > Not that I'm aware off, but this might as well be some old use after
> > > >  > free bug which got exposed by some unrelated change. The good news is
> > > >  > that it is reproducible. I'll hack up some nasty debug patch which
> > > >  > lets us - hopefully - decode where the timer was armed.
> > > >
> > > >  Quel, before I do that, is there any chance that you retest with the
> > > >  latest mainline git version ?
> > > >
> > > >  
> > > 
> http://www.kernel.org/pub/linux/kernel/v2.6/snapshots/patch-2.6.25-rc2-git4.bz2
> > > 
> > > And please test with this patch as well:
> > > 
> > > http://lkml.org/lkml/2008/2/20/121
> > > 
> > Same kind of result unfortunately with this last patch on top of git4:
> 
> At least it is fully reproducible. Please apply the patch below to
> your git4 tree and do not change your .config. The output should show,
> which code armed the timer.
> 
Thomas,

Thanks for the patch, but that did not work, I never got the trace.

I switched to git5 and applied the patch.

First crash (= attached kernlog.9) showed some hald process, so I decided to reduce the number of services and processes to a maximum. Attached are process list before starting sdptool browse and crashing, list of modules and list of services.

Second crash:

BUG: unable to handle kernel paging request at 6b6b6b6b
IP: [<c012d51d>] get_next_timer_interrupt+0x11f/0x234
*pde = 00000000
Oops: 0000 [#1] SMP
Modules linked in: hidp rfcomm l2cap nfsd exportfs nfs lockd nfs_acl sunrpc autofs4 af_packet binfmt_misc loop nls_iso8859_1 nls_cp437 vfat fat fuse snd_pcm_oss snd_mixer_oss snd_intel8x0 snd_ac97_codec hci_usb ac97_bus snd_pcm parport_pc snd_timer snd sr_mod i2c_i801 rtc_cmos iTCO_wdt i2c_core parport soundcore iTCO_vendor_support pcspkr snd_page_alloc bluetooth button thermal processor evdev dcdbas tg3 sg ide_disk piix ide_core ata_piix ahci libata sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd usbcore [last unloaded: scsi_wait_scan]

Pid: 0, comm: swapper Not tainted (2.6.25-rc2-git5kk1 #1)
EIP: 0060:[<c012d51d>] EFLAGS: 00010002 CPU: 0
EIP is at get_next_timer_interrupt+0x11f/0x234
EAX: 6b6b6b6b EBX: 3ffda6f6 ECX: c0432744 EDX: 6b6b6b6b
ESI: 00000027 EDI: c043260c EBP: c03b1ee8 ESP: c03b1eac
 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
Process swapper (pid: 0, ti=c03b0000 task=c03813a0 task.ti=c03b0000)
Stack: fffda6f6 c0431e00 00000000 fffda700 00000001 000000f7 00000027 00fffda7
       c043260c c043280c c0432a0c c0432c0c c18090c0 0643e180 fffda6f6 c03b1f2c
       c013fb78 00000001 c03a3b08 00000046 c03b1f20 0644b3c1 00000022 0643e180
Call Trace:
 [<c013fb78>] ? tick_nohz_stop_sched_tick+0x130/0x337
 [<c0129a54>] ? irq_exit+0x55/0x6e
 [<c01146e7>] ? smp_apic_timer_interrupt+0x59/0x92
 [<c010582c>] ? apic_timer_interrupt+0x28/0x30
 [<c013007b>] ? get_signal_to_deliver+0x2d8/0x332
 [<c011879f>] ? native_safe_halt+0x5/0x7
 [<c0103965>] ? default_idle+0x4d/0x7f
 [<c0103918>] ? default_idle+0x0/0x7f
 [<c01037c4>] ? cpu_idle+0x6f/0x100
 [<c02e2e89>] ? rest_init+0x49/0x50
 =======================
Code: 85 e0 8b 4d e0 83 e1 3f 89 4d dc 89 ce 8b 04 f7 8b 10 0f 18 02 90 8d 0c f7 39 c8 0f 84 8d 00 00 00 8b 40 08 39 d8 0f 48 d8 89 d0 <8b> 12 0f 18 02 90 39 c8 75 ec c7 45 cc 01 00 00 00 8b 7d dc 85
EIP: [<c012d51d>] get_next_timer_interrupt+0x11f/0x234

$ addr2line -e vmlinux c012d51d
/usr/src/linux-2.6.25-rc2-git5kk1/kernel/timer.c:770

Crap, that is on the next list_for_each_entry in timer.c :(

I tried to make a similar test loop as you did a few lines above:

@@ -718,6 +767,14 @@
 
 		index = slot = timer_jiffies & TVN_MASK;
 		do {
+			struct list_head *tmp;
+
+			__list_for_each(tmp, varp->vec + slot) {
+				nte = (struct timer_list *) tmp;
+				if (nte->entry.next == (void *)0x6b6b6b6b)
+					ttrace_find_timer(nte);
+			}
+
 			list_for_each_entry(nte, varp->vec + slot, entry) {
 				found = 1;
 				if (time_before(nte->expires, expires))

I thought I got it on the next crash, but the system locked too fast, and the only thing I saw was:

TTRACE timer f7b52858 fn f8e7c608 addr c012d776
TTRACE fn l2cap_info_timeout
TTRACE addr mod_timer
BUG: unable to handle kernel paging request at 6b6b6b6b
IP:

$ addr2line -e vmlinux.kk1 c012d776
/usr/src/linux-2.6.25-rc2-git5kk1/kernel/timer.c:533

int mod_timer(struct timer_list *timer, unsigned long expires)
{
        BUG_ON(!timer->function);

        timer_stats_timer_set_start_info(timer);
        /*
         * This is a common optimization triggered by the
         * networking code - if the timer is re-modified
         * to be the same thing then just return:
         */
        if (timer->expires == expires && timer_pending(timer))
                return 1;

        return __mod_timer(timer, expires);
}     <<<< line 533 is here

Unfortunately, I never got anything more. After that, the only thing I got, even without my changes, was:

list_add corruption. prev->next should be next (c0432764), but was 6b6b6b6b. (prev=f6d6e908).
------------[ cut here ]------------
kernel BUG at lib/list_debug.c:33!
invalid opcode: 0000 [#1] SMP
Modules linked in: hidp rfcomm l2cap binfmt_misc loop nls_iso8859_1 nls_cp437 vfat fat fuse snd_pcm_oss snd_mixer_oss snd_intel8x0 sr_mod snd_ac97_codec ac97_bus snd_pcm parport_pc snd_timer parport snd soundcore i2c_i801 i2c_core hci_usb snd_page_alloc bluetooth rtc_cmos pcspkr iTCO_wdt iTCO_vendor_support tg3 processor button evdev dcdbas sg ide_disk piix ide_core ata_piix ahci libata sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd usbcore [last unloaded: scsi_wait_scan]

Pid: 8, comm: events/0 Not tainted (2.6.25-rc2-git5kk1 #3)
EIP: 0060:[<c01f5703>] EFLAGS: 00010086 CPU: 0
EIP is at __list_add+0x5a/0x5e
EAX: 00000061 EBX: c18093d0 ECX: 00000001 EDX: 00000096
ESI: c18093d0 EDI: c0431e00 EBP: f788defc ESP: f788dee8
 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
Process events/0 (pid: 8, ti=f788c000 task=f785cc60 task.ti=f788c000)
Stack: c035609c c0432764 6b6b6b6b f6d6e908 fffd277d f788df0c c012cba2 c18093d0
       c0431e00 f788df2c c012d2cc fffd2b64 00000000 00000286 c18093c0 c18093d0
       f7811690 f788df44 c0133ee6 ffffffff c18093c0 000003e8 f7811690 f788df5c
Call Trace:
 [<c012cba2>] ? internal_add_timer+0x53/0xb4
 [<c012d2cc>] ? __mod_timer+0xe9/0x102
 [<c0133ee6>] ? queue_delayed_work_on+0x84/0xb7
 [<c0133f71>] ? queue_delayed_work+0x40/0x48
 [<c0169025>] ? vmstat_update+0x0/0x28
 [<c0133f9b>] ? schedule_delayed_work+0x22/0x26
 [<c016904b>] ? vmstat_update+0x26/0x28
 [<c01337d4>] ? run_workqueue+0xc1/0x150
 [<c0134022>] ? worker_thread+0x83/0xd9
 [<c013676e>] ? autoremove_wake_function+0x0/0x38
 [<c0133f9f>] ? worker_thread+0x0/0xd9
 [<c01364c4>] ? kthread+0x37/0x59
 [<c013648d>] ? kthread+0x0/0x59
 [<c01059bb>] ? kernel_thread_helper+0x7/0x1c
 =======================
Code: 54 24 04 c7 04 24 4c 60 35 c0 e8 f1 fe f2 ff 0f 0b eb fe 89 44 24 0c 89 54 24 08 89 4c 24 04 c7 04 24 9c 60 35 c0 e8 d5 fe f2 ff <0f> 0b eb fe 55 89 e5 8b 0a e8 98 ff ff ff 5d c3 90 55 89 e5 53
EIP: [<c01f5703>] __list_add+0x5a/0x5e SS:ESP 0068:f788dee8
---[ end trace bd4e31c9ceb47c4f ]---

I hope the tiny bit of trace can trigger some idea. At least l2cap has something to do with bluetooth. l2cap_info_timeout is line 360 of net/bluetooth/l2cap.c, apparently only called from l2cap_conn_add, line 391: setup_timer(&conn->info_timer, l2cap_info_timeout, (unsigned long)conn);

After four hours and ten crashes today, it is the little I got. Kernel stuff is tough...
--
kk1

Attachment: mod_list
Description: Binary data

Attachment: ps_list
Description: Binary data

Attachment: serv_list
Description: Binary data

Attachment: kernlog.9
Description: Binary data