Escalated to Bugzilla from IssueTracker
Event posted on 07-31-2009 03:53pm EDT by myates They have a c program which reads and writes to tape drive from buffer, which caused kernel panic. They have tested this utility on other controllers on RHEL 5 and it does not cause a panic. They suspected the problem could be with kernel/cciss driver/P212 controller. Flavio (fbl) said in IRC that "something is messing with slab cache. any proprietary module? perhaps the controller driver is doing something bad. fw update might help in this case." All 4 cores are on megatron.gsslab.rdu.redhat.com: /cores/20090730173849 #vmcore1 /cores/20090731141752 #vmcore2 /cores/20090730133307 #vmcore3 /cores/20090730182813 #vcomre4 --------------------------------------------------- 1. Time and date of problem: reproduceable regularly on their site 2. System architecture(s): RHEL 5 x86_64 3. Provide a clear and concise problem description as it is understood at the time of escalation. Please be as specific as possible in your description. Do not use the generic term "hang", as that can mean many things. Observed behavior: Kernel panic when doing reads/writes to tape drive from buffer Desired behavior: no kernel panic 4. Specific action requested of SEG: assistance analyzing the cores and figuring out how to resolve it 5. Is a defect (bug) in the product suspected? it is possible there could be an issue with the driver Bugzilla number (if one already exists): 6. Does a proposed patch exist? not sure If yes, attach patch, making sure it is in unified diff format (diff -pruN) 7. What is the impact to the customer when they experience this problem? This is especially important for severity one and two issues: -They need to urgently isolate the problem, since they have this hardware build for 400+ plus servers [myates@megatron 20090730173849]$ crash 1928180_vmcore1 vmlinux KERNEL: vmlinux DUMPFILE: 1928180_vmcore1 CPUS: 16 DATE: Tue Jul 28 13:56:35 2009 UPTIME: 01:51:19 LOAD AVERAGE: 1.00, 1.00, 0.93 TASKS: 234 NODENAME: raptor-bk.imdlab.ao.dcn RELEASE: 2.6.18-128.2.1.el5debug VERSION: #1 SMP Wed Jul 8 12:29:22 EDT 2009 MACHINE: x86_64 (2666 Mhz) MEMORY: 11.7 GB PANIC: "" PID: 6340 COMMAND: "rwtape" TASK: ffff81031d7baec0 [THREAD_INFO: ffff81031fbfe000] CPU: 2 STATE: TASK_RUNNING (PANIC) crash> bt PID: 6340 TASK: ffff81031d7baec0 CPU: 2 COMMAND: "rwtape" #0 [ffff81031fbffae0] crash_kexec at ffffffff800b4ca2 #1 [ffff81031fbffba0] __die at ffffffff80069157 #2 [ffff81031fbffbe0] die at ffffffff8006fc1c #3 [ffff81031fbffc10] do_invalid_op at ffffffff80070216 #4 [ffff81031fbffcd0] error_exit at ffffffff80060e9d [exception RIP: list_del+33] RIP: ffffffff801597e6 RSP: ffff81031fbffd88 RFLAGS: 00010082 RAX: 0000000000000058 RBX: ffff81018203e000 RCX: 0000000000000058 RDX: ffff81031d7baec0 RSI: 0000000000000000 RDI: ffffffff8030e2e0 RBP: ffff81018203e000 R8: 0000000000000002 R9: ffffffff8001791b R10: ffffffff8001791b R11: 0000000000000000 R12: ffff810109d478b8 R13: ffff810109d22340 R14: ffff8101a0023d90 R15: 00000000ffffffff ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018 #5 [ffff81031fbffd80] list_del at ffffffff801597e6 #6 [ffff81031fbffd90] cache_alloc_refill at ffffffff8005e832 #7 [ffff81031fbffdd0] kmem_cache_alloc at ffffffff8000ad98 #8 [ffff81031fbffe00] __sigqueue_alloc at ffffffff8009a843 #9 [ffff81031fbffe20] send_signal at ffffffff8009a8b2 #10 [ffff81031fbffe50] __group_send_sig_info at ffffffff8009b0b6 #11 [ffff81031fbffe70] do_notify_parent at ffffffff8009b655 #12 [ffff81031fbfff20] do_exit at ffffffff800164f8 #13 [ffff81031fbfff80] system_call at ffffffff80060116 RIP: 000000000041493f RSP: 00007fffb68fe388 RFLAGS: 00010202 RAX: 00000000000000e7 RBX: ffffffff80060116 RCX: 000000000068d340 RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000 RBP: 0000000000000000 R8: 00000000000000e7 R9: ffffffffffffffd0 R10: 2020202020202020 R11: 0000000000000246 R12: 0000000000000000 R13: 0000000000481110 R14: ffffffff8004b410 R15: 0000000000000000 ORIG_RAX: 00000000000000e7 CS: 0033 SS: 002b crash> log ... list_del corruption. prev->next should be ffff81018203e000, but was 0000000000000400 ----------- [cut here ] --------- [please bite here ] --------- Kernel BUG at lib/list_debug.c:65 invalid opcode: 0000 [1] SMP last sysfs file: /devices/pci0000:00/0000:00:00.0/irq CPU 2 Modules linked in: autofs4 st sunrpc ip_conntrack_netbios_ns ipt_REJECT xt_state ip_conntrack nfnetlink iptable_filter ip_tables ip6t_REJECT xt_tcpudp ip6table_filter ip6_tables x_tables ipv6 xfrm_nalgo crypto_api dm_mirror dm_multipath scsi_dh video hwmon backlight sbs i2c_ec i2c_core button battery asus_acpi acpi_memhotplug ac parport_pc lp parport s r_mod cdrom sg bnx2 pcspkr serio_raw hpilo dm_raid45 dm_message dm_region_hash dm_log dm_mod dm_mem_cache usb_storage ata_piix libata mptsas mptscsih scsi_transport_sas mptbase shpchp cciss sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd Pid: 6340, comm: rwtape Not tainted 2.6.18-128.2.1.el5debug #1 RIP: 0010:[<ffffffff801597e6>] [<ffffffff801597e6>] list_del+0x21/0x71 RSP: 0018:ffff81031fbffd88 EFLAGS: 00010082 RAX: 0000000000000058 RBX: ffff81018203e000 RCX: 0000000000000058 RDX: ffff81031d7baec0 RSI: 0000000000000000 RDI: ffffffff8030e2e0 RBP: ffff81018203e000 R08: 0000000000000002 R09: ffffffff8001791b R10: ffffffff8001791b R11: 0000000000000000 R12: ffff810109d478b8 R13: ffff810109d22340 R14: ffff8101a0023d90 R15: 00000000ffffffff FS: 0000000000000000(0000) GS:ffff81031ff9e1d0(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b CR2: 0000000000465f30 CR3: 0000000000201000 CR4: 00000000000006e0 Process rwtape (pid: 6340, threadinfo ffff81031fbfe000, task ffff81031d7baec0) Stack: 0000000000000010 ffffffff8005e832 0000022000000000 ffff810109d22340 ffffffff80310f0c 0000000000000046 0000000000000220 ffffffff8009a843 0000000000401b80 ffffffff8000ad98 ffffffff80310f00 ffffffff80310f0c Call Trace: [<ffffffff8005e832>] cache_alloc_refill+0x166/0x201 [<ffffffff8009a843>] __sigqueue_alloc+0x3c/0x69 [<ffffffff8000ad98>] kmem_cache_alloc+0xb0/0xeb [<ffffffff8009a843>] __sigqueue_alloc+0x3c/0x69 [<ffffffff8009a8b2>] send_signal+0x42/0x122 [<ffffffff8009b0b6>] __group_send_sig_info+0x78/0x94 [<ffffffff8009b655>] do_notify_parent+0x14f/0x188 [<ffffffff8001625f>] do_exit+0x590/0x934 [<ffffffff800164f8>] do_exit+0x829/0x934 [<ffffffff8004b410>] debug_mutex_init+0x0/0x3b [<ffffffff80060116>] system_call+0x7e/0x83 Code: 0f 0b 68 02 98 2b 80 c2 41 00 48 8b 03 48 8b 50 08 48 39 da RIP [<ffffffff801597e6>] list_del+0x21/0x71 RSP <ffff81031fbffd88> ------------------CORE 2 ------------------------------- [myates@megatron 20090731141752]$ crash 1938180_vmcore2 vmlinux KERNEL: vmlinux DUMPFILE: 1938180_vmcore2 CPUS: 16 DATE: Tue Jul 28 07:53:53 2009 UPTIME: 00:08:29 LOAD AVERAGE: 0.98, 0.58, 0.25 TASKS: 234 NODENAME: raptor-bk.imdlab.ao.dcn RELEASE: 2.6.18-128.2.1.el5debug VERSION: #1 SMP Wed Jul 8 12:29:22 EDT 2009 MACHINE: x86_64 (2666 Mhz) MEMORY: 11.7 GB PANIC: "" PID: 54 COMMAND: "events/4" TASK: ffff81019f9de880 [THREAD_INFO: ffff81031fb5a000] CPU: 4 STATE: TASK_RUNNING (PANIC) crash> bt PID: 54 TASK: ffff81019f9de880 CPU: 4 COMMAND: "events/4" #0 [ffff81031fb5bab0] crash_kexec at ffffffff800b4ca2 #1 [ffff81031fb5bb70] __die at ffffffff80069157 #2 [ffff81031fb5bbb0] die at ffffffff8006fc1c #3 [ffff81031fb5bbe0] do_invalid_op at ffffffff80070216 #4 [ffff81031fb5bca0] error_exit at ffffffff80060e9d [exception RIP: __list_add+72] RIP: ffffffff8015987e RSP: ffff81031fb5bd50 RFLAGS: 00010086 RAX: 0000000000000058 RBX: ffff81019f195d90 RCX: 0000000000000058 RDX: ffff81019f9de880 RSI: 0000000000000000 RDI: ffffffff8030e2e0 RBP: ffff810194d6b000 R8: 0000000000000002 R9: ffffffff8001791b R10: ffffffff8001791b R11: ffffffff8016ebd9 R12: ffff8101988d3000 R13: ffff8101988d3034 R14: ffff8101988d31a8 R15: 0000000000000001 ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018 #5 [ffff81031fb5bd68] free_block at ffffffff800e2766 #6 [ffff81031fb5bdb8] drain_array at ffffffff800e2812 #7 [ffff81031fb5bdf8] cache_reap at ffffffff800e3648 #8 [ffff81031fb5be38] run_workqueue at ffffffff8004fa19 #9 [ffff81031fb5be78] worker_thread at ffffffff8004c31a #10 [ffff81031fb5bee8] kthread at ffffffff80034480 #11 [ffff81031fb5bf48] kernel_thread at ffffffff80061079 crash> log list_add corruption. prev->next should be ffff81019f195d90, but was 0000004608100000 ----------- [cut here ] --------- [please bite here ] --------- Kernel BUG at lib/list_debug.c:31 invalid opcode: 0000 [1] SMP last sysfs file: /devices/pci0000:00/0000:00:1c.2/0000:03:00.1/irq CPU 4 Modules linked in: autofs4 st sunrpc ip_conntrack_netbios_ns ipt_REJECT xt_state ip_conntrack nfnetlink iptable_filter ip_tables ip6t_REJECT xt_tcpudp ip6table_filter ip6_tables x_tables ipv6 xfrm_nalgo crypto_api dm_mirror dm_multipath scsi_dh video hwmon backlight sbs i2c_ec i2c_core button battery asus_acpi acpi_memhotplug ac parport_pc lp parport s r_mod cdrom sg bnx2 hpilo serio_raw pcspkr dm_raid45 dm_message dm_region_hash dm_log dm_mod dm_mem_cache usb_storage ata_piix libata mptsas mptscsih scsi_transport_sas mptbase shpchp cciss sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd Pid: 54, comm: events/4 Not tainted 2.6.18-128.2.1.el5debug #1 RIP: 0010:[<ffffffff8015987e>] [<ffffffff8015987e>] __list_add+0x48/0x68 RSP: 0018:ffff81031fb5bd50 EFLAGS: 00010086 RAX: 0000000000000058 RBX: ffff81019f195d90 RCX: 0000000000000058 RDX: ffff81019f9de880 RSI: 0000000000000000 RDI: ffffffff8030e2e0 RBP: ffff810194d6b000 R08: 0000000000000002 R09: ffffffff8001791b R10: ffffffff8001791b R11: ffffffff8016ebd9 R12: ffff8101988d3000 R13: ffff8101988d3034 R14: ffff8101988d31a8 R15: 0000000000000001 FS: 0000000000000000(0000) GS:ffff81031fe14898(0000) knlGS:0000000000000000 CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b CR2: 00002b5472f193a0 CR3: 000000031de58000 CR4: 00000000000006e0 Process events/4 (pid: 54, threadinfo ffff81031fb5a000, task ffff81019f9de880) Stack: ffff8101988d3000 ffff81019f195d90 ffff81019c6e44c0 ffffffff800e2766 0000000100000000 ffff81031e6bf728 00000000800e27d1 ffff81031e6bf728 0000000000000001 ffff81031e6bf6e0 ffff81019f195dd0 0000000000000000 Call Trace: [<ffffffff800e2766>] free_block+0x1c2/0x1e3 [<ffffffff800e2812>] drain_array+0x8b/0xca [<ffffffff800e35ab>] cache_reap+0x23/0x252 [<ffffffff800e3648>] cache_reap+0xc0/0x252 [<ffffffff800e3588>] cache_reap+0x0/0x252 [<ffffffff8004fa19>] run_workqueue+0x9a/0xf4 [<ffffffff8004c22a>] worker_thread+0x0/0x122 [<ffffffff8004c31a>] worker_thread+0xf0/0x122 [<ffffffff8008ebf6>] default_wake_function+0x0/0xe [<ffffffff80034480>] kthread+0xfe/0x132 [<ffffffff8006808c>] trace_hardirqs_on_thunk+0x35/0x37 [<ffffffff80061079>] child_rip+0xa/0x11 [<ffffffff8006898d>] _spin_unlock_irq+0x24/0x27 [<ffffffff800606a8>] restore_args+0x0/0x30 [<ffffffff80034382>] kthread+0x0/0x132 [<ffffffff8006106f>] child_rip+0x0/0x11 Code: 0f 0b 68 02 98 2b 80 c2 1f 00 4c 89 63 08 49 89 1c 24 4c 89 RIP [<ffffffff8015987e>] __list_add+0x48/0x68 RSP <ffff81031fb5bd50> ------------------CORE 3 ------------------------------- [myates@megatron 20090730133307]$ crash 1938180_vmcore3 vmlinux KERNEL: vmlinux DUMPFILE: 1938180_vmcore3 CPUS: 16 DATE: Wed Jul 29 14:06:07 2009 UPTIME: 01:18:47 LOAD AVERAGE: 1.00, 1.00, 0.93 TASKS: 234 NODENAME: raptor-bk.imdlab.ao.dcn RELEASE: 2.6.18-128.2.1.el5debug VERSION: #1 SMP Wed Jul 8 12:29:22 EDT 2009 MACHINE: x86_64 (2666 Mhz) MEMORY: 11.7 GB PANIC: "" PID: 5109 COMMAND: "rwtape" TASK: ffff810196014c00 [THREAD_INFO: ffff8101823aa000] CPU: 14 STATE: TASK_RUNNING (PANIC) crash> bt PID: 5109 TASK: ffff810196014c00 CPU: 14 COMMAND: "rwtape" #0 [ffff8101823ab850] crash_kexec at ffffffff800b4ca2 #1 [ffff8101823ab910] __die at ffffffff80069157 #2 [ffff8101823ab950] die at ffffffff8006fc1c #3 [ffff8101823ab980] do_invalid_op at ffffffff80070216 #4 [ffff8101823aba40] error_exit at ffffffff80060e9d [exception RIP: __list_add+36] RIP: ffffffff8015985a RSP: ffff8101823abaf8 RFLAGS: 00010086 RAX: 0000000000000058 RBX: ffff81018c4d3000 RCX: 0000000000000058 RDX: ffff810196014c00 RSI: 0000000000000000 RDI: ffffffff8030e2e0 RBP: ffff81019f6544e0 R8: 0000000000000002 R9: ffffffff8001791b R10: ffffffff8001791b R11: 0000000000000000 R12: ffff810183a07000 R13: ffff81031f1d0440 R14: ffff81019f6544d0 R15: 0000000000000002 ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018 #5 [ffff8101823abaf0] __list_add at ffffffff8015985a #6 [ffff8101823abb10] cache_alloc_refill at ffffffff8005e847 #7 [ffff8101823abb50] kmem_cache_alloc at ffffffff8000ad98 #8 [ffff8101823abb80] mempool_alloc at ffffffff800240be #9 [ffff8101823abbe0] scsi_prep_fn at ffffffff8807b5eb #10 [ffff8101823abc10] elv_next_request at ffffffff8014995f #11 [ffff8101823abc70] blk_execute_rq_nowait at ffffffff8014b6fd #12 [ffff8101823abc90] scsi_execute_async at ffffffff8807ab8b #13 [ffff8101823abd30] st_do_scsi at ffffffff884bde13 #14 [ffff8101823abda0] st_int_ioctl at ffffffff884be9e8 #15 [ffff8101823abe30] st_ioctl at ffffffff884c0a28 #16 [ffff8101823abee0] do_ioctl at ffffffff8004413f #17 [ffff8101823abf00] vfs_ioctl at ffffffff800319ba #18 [ffff8101823abf40] sys_ioctl at ffffffff8004e926 #19 [ffff8101823abf80] system_call at ffffffff80060116 RIP: 0000000000416077 RSP: 00007fff95d468b0 RFLAGS: 00010206 RAX: 0000000000000010 RBX: ffffffff80060116 RCX: 0000000000415dc0 RDX: 00007fff95d468e0 RSI: 0000000040086d01 RDI: 0000000000000003 RBP: 00007fff95d46930 R8: 0a2e29736b636f6c R9: 00007fff95d45f78 R10: 0000000000000000 R11: 0000000000000246 R12: 000000000dbaa000 R13: 0000000000000003 R14: 0000000000001000 R15: 0000000000010000 ORIG_RAX: 0000000000000010 CS: 0033 SS: 002b crash> log list_add corruption. next->prev should be ffff81019f6544e0, but was ffff810100000000 ----------- [cut here ] --------- [please bite here ] --------- Kernel BUG at lib/list_debug.c:26 invalid opcode: 0000 [1] SMP last sysfs file: /devices/pci0000:00/0000:00:00.0/irq CPU 14 Modules linked in: autofs4 st sunrpc ip_conntrack_netbios_ns ipt_REJECT xt_state ip_conntrack nfnetlink iptable_filter ip_tables ip6t_REJECT xt_tcpudp ip6table_filter ip6_tables x_tables ipv6 xfrm_nalgo crypto_api dm_mirror dm_multipath scsi_dh video hwmon backlight sbs i2c_ec i2c_core button battery asus_acpi acpi_memhotplug ac parport_pc lp parport s r_mod cdrom sg bnx2 hpilo serio_raw pcspkr dm_raid45 dm_message dm_region_hash dm_log dm_mod dm_mem_cache usb_storage ata_piix libata mptsas mptscsih scsi_transport_sas mptbase shpchp cciss sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd Pid: 5109, comm: rwtape Not tainted 2.6.18-128.2.1.el5debug #1 RIP: 0010:[<ffffffff8015985a>] [<ffffffff8015985a>] __list_add+0x24/0x68 RSP: 0018:ffff8101823abaf8 EFLAGS: 00010086 RAX: 0000000000000058 RBX: ffff81018c4d3000 RCX: 0000000000000058 RDX: ffff810196014c00 RSI: 0000000000000000 RDI: ffffffff8030e2e0 RBP: ffff81019f6544e0 R08: 0000000000000002 R09: ffffffff8001791b R10: ffffffff8001791b R11: 0000000000000000 R12: ffff810183a07000 R13: ffff81031f1d0440 R14: ffff81019f6544d0 R15: 0000000000000002 FS: 000000000dba8850(0063) GS:ffff81031fd678f0(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b CR2: 000000000fb669ec CR3: 000000031e031000 CR4: 00000000000006e0 Process rwtape (pid: 5109, threadinfo ffff8101823aa000, task ffff810196014c00) Stack: 000000000000000e ffff810183a07000 ffff810109f9a330 ffffffff8005e847 0001122000000001 ffff81031f1d0440 ffff81031f1c7818 0000000000000046 0000000000011220 ffffffff800240be ffff81018d60d928 ffffffff8000ad98 Call Trace: [<ffffffff8005e847>] cache_alloc_refill+0x17b/0x201 [<ffffffff800240be>] mempool_alloc+0x42/0xf8 [<ffffffff8000ad98>] kmem_cache_alloc+0xb0/0xeb [<ffffffff800240be>] mempool_alloc+0x42/0xf8 [<ffffffff88075e2e>] :scsi_mod:scsi_get_command+0xe1/0x102 [<ffffffff8807b5eb>] :scsi_mod:scsi_prep_fn+0x262/0x3fb [<ffffffff8014995f>] elv_next_request+0xe5/0x1a6 [<ffffffff8807b04f>] :scsi_mod:scsi_request_fn+0x6a/0x3a4 [<ffffffff8014b6fd>] blk_execute_rq_nowait+0x86/0x97 [<ffffffff8807ab8b>] :scsi_mod:scsi_execute_async+0x359/0x39c [<ffffffff884bde13>] :st:st_do_scsi+0x1e7/0x24c [<ffffffff884bd738>] :st:st_sleep_done+0x0/0x48 [<ffffffff884be9e8>] :st:st_int_ioctl+0x641/0x994 [<ffffffff884c0a28>] :st:st_ioctl+0xb03/0xe89 [<ffffffff8004413f>] do_ioctl+0x55/0x6b [<ffffffff800319ba>] vfs_ioctl+0x256/0x26f [<ffffffff800a7064>] trace_hardirqs_on+0x11b/0x13f [<ffffffff8004e926>] sys_ioctl+0x59/0x78 [<ffffffff80060116>] system_call+0x7e/0x83 Code: 0f 0b 68 02 98 2b 80 c2 1a 00 48 8b 55 00 48 39 da 74 1b 48 RIP [<ffffffff8015985a>] __list_add+0x24/0x68 RSP <ffff8101823abaf8> ----------------------- CORE 4---------------------------- [myates@megatron 20090730182813]$ crash 1928180_vmcore4 vmlinux KERNEL: vmlinux DUMPFILE: 1928180_vmcore4 CPUS: 16 DATE: Wed Jul 29 12:42:06 2009 UPTIME: 22:40:20 LOAD AVERAGE: 0.99, 0.96, 0.92 TASKS: 234 NODENAME: raptor-bk.imdlab.ao.dcn RELEASE: 2.6.18-128.2.1.el5debug VERSION: #1 SMP Wed Jul 8 12:29:22 EDT 2009 MACHINE: x86_64 (2666 Mhz) MEMORY: 11.7 GB PANIC: "" PID: 0 COMMAND: "swapper" TASK: ffff810109fb6740 (1 of 16) [THREAD_INFO: ffff81031fdb8000] CPU: 14 STATE: TASK_RUNNING (PANIC) crash> bt PID: 0 TASK: ffff810109fb6740 CPU: 14 COMMAND: "swapper" #0 [ffff81031fdbf8c0] crash_kexec at ffffffff800b4ca2 #1 [ffff81031fdbf980] __die at ffffffff80069157 #2 [ffff81031fdbf9c0] die at ffffffff8006fc1c #3 [ffff81031fdbf9f0] do_invalid_op at ffffffff80070216 #4 [ffff81031fdbfab0] error_exit at ffffffff80060e9d [exception RIP: list_del+33] RIP: ffffffff801597e6 RSP: ffff81031fdbfb60 RFLAGS: 00010082 RAX: 0000000000000058 RBX: ffff81018087e000 RCX: 0000000000000058 RDX: ffff810109fb6740 RSI: 0000000000000000 RDI: ffffffff8030e2e0 RBP: ffff81018087e000 R8: 0000000000000002 R9: ffffffff8001791b R10: ffffffff8001791b R11: ffffffff8016ebd9 R12: ffff81019fef3720 R13: ffff81019fafc200 R14: ffff81019fafb930 R15: 0000000000000006 ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018 #5 [ffff81031fdbfb68] cache_alloc_refill at ffffffff8005e832 #6 [ffff81031fdbfba8] kmem_cache_alloc at ffffffff8000ad98 #7 [ffff81031fdbfbd8] dst_alloc at ffffffff8022e71e #8 [ffff81031fdbfbe8] ip_route_input at ffffffff80039415 #9 [ffff81031fdbfce8] ip_rcv at ffffffff800372a4 #10 [ffff81031fdbfd18] netif_receive_skb at ffffffff80021750 #11 [ffff81031fdbfd58] bnx2_poll_work at ffffffff8821a52e #12 [ffff81031fdbfec8] bnx2_poll_msix at ffffffff8821dc8a #13 [ffff81031fdbfef8] net_rx_action at ffffffff8000ce73 #14 [ffff81031fdbff38] __do_softirq at ffffffff80012ac8 #15 [ffff81031fdbff68] call_softirq at ffffffff800613d0 #16 [ffff81031fdbff80] do_softirq at ffffffff80070b63 #17 [ffff81031fdbff90] do_IRQ at ffffffff80070b25 --- <IRQ stack> --- #18 [ffff81031fdb9e38] ret_from_intr at ffffffff80060652 [exception RIP: mwait_idle+63] RIP: ffffffff800596ad RSP: ffff81031fdb9ee8 RFLAGS: 00000246 RAX: 0000000000000000 RBX: 000000000000000e RCX: 0000000000000000 RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffffffff80306218 RBP: 0000000000000e00 R8: 0000000000000000 R9: 0000000000000001 R10: 00000000000000ff R11: ffff810109fb6740 R12: 000000000000000a R13: ffff810109fb6740 R14: ffff81031fdb8000 R15: 0000000000000046 ORIG_RAX: ffffffffffffffac CS: 0010 SS: 0018 #19 [ffff81031fdb9ee0] mwait_idle at ffffffff80059677 #20 [ffff81031fdb9ef0] cpu_idle at ffffffff8004b553 crash> log ... list_del corruption. prev->next should be ffff81018087e000, but was 0000000000000400 ----------- [cut here ] --------- [please bite here ] --------- Kernel BUG at lib/list_debug.c:65 invalid opcode: 0000 [1] SMP last sysfs file: /devices/pci0000:00/0000:00:00.0/irq CPU 14 Modules linked in: autofs4 st sunrpc ip_conntrack_netbios_ns ipt_REJECT xt_state ip_conntrack nfnetlink iptable_filter ip_tables ip6t_REJECT xt_tcpudp ip6table_filter ip6_tables x_tables ipv6 xfrm_nalgo crypto_api dm_mirror dm_multipath scsi_dh video hwmon backlight sbs i2c_ec i2c_core button battery asus_acpi acpi_memhotplug ac parport_pc lp parport s r_mod cdrom hpilo sg bnx2 serio_raw pcspkr dm_raid45 dm_message dm_region_hash dm_log dm_mod dm_mem_cache usb_storage ata_piix libata mptsas mptscsih scsi_transport_sas mptbase shpchp cciss sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd Pid: 0, comm: swapper Not tainted 2.6.18-128.2.1.el5debug #1 RIP: 0010:[<ffffffff801597e6>] [<ffffffff801597e6>] list_del+0x21/0x71 RSP: 0018:ffff81031fdbfb60 EFLAGS: 00010082 RAX: 0000000000000058 RBX: ffff81018087e000 RCX: 0000000000000058 RDX: ffff810109fb6740 RSI: 0000000000000000 RDI: ffffffff8030e2e0 RBP: ffff81018087e000 R08: 0000000000000002 R09: ffffffff8001791b R10: ffffffff8001791b R11: ffffffff8016ebd9 R12: ffff81019fef3720 R13: ffff81019fafc200 R14: ffff81019fafb930 R15: 0000000000000006 FS: 0000000000000000(0000) GS:ffff81031fd678f0(0000) knlGS:0000000000000000 CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b CR2: 00002b05dc0499d8 CR3: 000000031e51e000 CR4: 00000000000006e0 Process swapper (pid: 0, threadinfo ffff81031fdb8000, task ffff810109fb6740) Stack: 000000000000000a ffffffff8005e832 0000022000000000 ffff81019fafc200 0000000000000000 0000000000000246 0000000000000220 ffffffff8022e71e 0000000000000000 ffffffff8000ad98 ffffffff8035f4c0 0000000000000001 Call Trace: <IRQ> [<ffffffff8005e832>] cache_alloc_refill+0x166/0x201 [<ffffffff8022e71e>] dst_alloc+0x29/0x80 [<ffffffff8000ad98>] kmem_cache_alloc+0xb0/0xeb [<ffffffff8022e71e>] dst_alloc+0x29/0x80 [<ffffffff80039415>] ip_route_input+0x9e1/0xceb [<ffffffff80228f4d>] __netdev_alloc_skb+0x12/0x2d [<ffffffff800372a4>] ip_rcv+0x28d/0x57d [<ffffffff80021750>] netif_receive_skb+0x384/0x3bd [<ffffffff8821a52e>] :bnx2:bnx2_poll_work+0xfab/0x10e3 [<ffffffff800a5338>] lock_release_holdtime+0x27/0x48 [<ffffffff80155bc2>] __next_cpu+0x19/0x28 [<ffffffff8006898d>] _spin_unlock_irq+0x24/0x27 [<ffffffff8821dc8a>] :bnx2:bnx2_poll_msix+0x2e/0xdb [<ffffffff8000ce73>] net_rx_action+0xa9/0x1bb [<ffffffff80012a88>] __do_softirq+0x54/0x152 [<ffffffff80012ac8>] __do_softirq+0x94/0x152 [<ffffffff800613d0>] call_softirq+0x1c/0x28 [<ffffffff80070b63>] do_softirq+0x35/0xa0 [<ffffffff80070b25>] do_IRQ+0xfb/0x104 [<ffffffff8005966e>] mwait_idle+0x0/0x54 [<ffffffff80060652>] ret_from_intr+0x0/0xf <EOI> [<ffffffff800596ad>] mwait_idle+0x3f/0x54 [<ffffffff80059677>] mwait_idle+0x9/0x54 [<ffffffff8004b553>] cpu_idle+0x9a/0xbd [<ffffffff8007ae21>] start_secondary+0x45a/0x469 Code: 0f 0b 68 02 98 2b 80 c2 41 00 48 8b 03 48 8b 50 08 48 39 da RIP [<ffffffff801597e6>] list_del+0x21/0x71 RSP <ffff81031fdbfb60> This event sent from IssueTracker by djeffery [SEG - Storage] issue 325087
Event posted on 08-06-2009 10:36am EDT by myates Customer updated so I think we know where to focus now: ------ So did you run the tests with the HP kernel or with the newer cciss driver rpm? - Hp kernel rpm/cciss driver rpm are same thing. Hp kernel updates cciss.ko module Did your tests show the issue was resolved with a few more loops? - Check previous summary, Redhat kernel failed at 1, 16, 3, 72 iterations. - Since HP kernel passed 200 iterations and did not crash it seems like probable fix, I am running 300 loops, this should confirm if HP kernel is a fix - There is no point of running HP kernel with fewer iterations, it will definitely work We were still in the process of narrowing the issue down, but if that seems to resolve it then we dig into that and find the change that fixed it and then apply for a hotfix. - I think if diff source of cciss driver in RedHat kernel vs HP kernel, that should give you more insight. This event sent from IssueTracker by djeffery [SEG - Storage] issue 325087
Event posted on 08-07-2009 04:49pm EDT by djeffery In the cores, at least part of the corruption is always the same. There is a 12 byte pattern of 0,0,0x10,0x8,0x46,0,0,0,0,0,0,0 that gets written over the first 12 bytes of a page. So far, no cause in the difference between the Red Hat and HP drivers has been found. Most of the real difference between the two is in initialization, and not changes to memory management or the I/O paths. It will take some more studying to find if the initialization differences are leading to the memory corruption. This event sent from IssueTracker by djeffery [SEG - Storage] issue 325087
The HP cciss driver version I understand the customer tried and doesn't exhibit the problem is 3.6.20-20. So far, I haven't found a difference between it and the RHEL5.3 version that explains where the 12 byte page-aligned corruption is coming from.
With myates' permission, adding the HP Confidential group
HP replied: After looking at the code nothing jumps out at me. I'm also working with our SCSI expert, Steve, to see if we figure out what "fixed" the problem. I'm not able to recreate the issue in my lab. Do you or one of the support engineers have the test the customer is using? I'm dd'ing from one my disks to the tape using the inbox driver and so far no problems. So in reply, the customer has a c program to read/write tape drive. I am attaching source file and parameters to run this utility rwtape -b 65536 -n 65536 -i Loop #!/bin/bash LOGFILE=/tmp/tape.`date +%Y-%m-%d-%H-%M-%S` echo "Starting Test" >> $LOGFILE i=1 while [ $i -lt 100 ] ; do echo -e "---$i---\n" >> $LOGFILE /rfu/rfubin/rwtape -b 65536 -n 65536 -i 2>> $LOGFILE let i=i+1 echo -e "------\n" >> $LOGFILE done echo "End Test" >> $LOGFILE Kernel panics are intermittent, on various iterations. The HP kernel/driver seemed to eliminate or at least mitigate the panics.
Created attachment 359321 [details] customer's test binary
Created attachment 359322 [details] customer's test source
I've run the customers test program several times uning the inbox driver and still have not seen the panic. The tape drive/autoloader in my lab has earlier firmware. The tape drive has version C24W and the autoloader has version 2.10. I'll update the firmware and rerun the customers test.
update: Spoke to US Courts on a conference call today. Thanks to Mike Miller and the HP team for helping us with this issue. Mike it was mentioned on the phone call that during earlier testing the kernel panic was verified. Referring to HP case # 4601613064 What kernels were used during this latest batch of testing ? Our engineer will be running internal testing with different kernels as well. Thanks, Robert
Could we please make this ticket public so the customer can access all the information. I have been posting all the comments to the ticket but the customer would like it public. Thanks Robert
I looked at the diff file and haven't found nothing obvious, but I think that the cciss driver consist not only of cciss.c other source files so the diff file is probably not complete. The link to the HP sources from issue tracker does not work for me.
Created attachment 361109 [details] cciss 3.6.20-20 source files Tomas, Here's the complete set of source files for cciss v3.6.20-20. -- mikem
Event posted on 09-22-2009 12:35pm EDT by djeffery Another test was run with a build of the HP 3.6.20-20 driver, but modifying the st (scsi tape) driver to use the module params buffer_kbs=64 try_direct_io=0. This forces all tape drive I/O in the test to be read/written to a single, linear buffer instead of directly pinning, mapping, and accessing the memory of the rwtape test. This also eliminates large scatter-gather lists (there is only 1 entry). With this configuration, no list corruption nor slab poison corruption was detected. As another interesting data point, it was found that this was the only test without a corrupt log generated by the test and scripts. All previous test logs have been found to have the 12 byte corruption pattern in part of the file. The corruption is always a multiple of 4kb into the file which would be consistent with the beginning of a page in the page cache being corrupted. Note that the st parameter changes may or may not be a valid workaround. More testing is needed to determine if the memory corruption is occurring in or beyond the st linear buffer and insure it wasn't a statistical fluke. This event sent from IssueTracker by djeffery issue 325087
Event posted on 09-22-2009 05:45pm EDT by djeffery To get a handle on what all has been tested by the different parties, What kernel version was used by HP for their tests? Was a RH kernel or a upstream kernel used? And how many test iterations? Sometimes it can take 100-200 iterations to fail. This event sent from IssueTracker by djeffery issue 325087
Current summary of Redhat's reproduction: All testing so far has been using the 2.6.18-128.2.1debug kernel on a Proliant DL385 G5 with a cciss controller (P212) and an Ultrium 3 scsi tape drive. When using the attached test application, both the default cciss driver and a build of the 3.6.20-20 cciss driver would eventually crash do to the same 12 byte corruption pattern as seen in the customer's testing. The only configuration that has not crashed so far involved altering the buffer behavior in the st (scsi tape) driver by setting the parameters buffer_kbs=64 and try_direct_io=0 . As the time to a crash is random, more testing is ongoing to determine with higher certainty if the parameter changes really did change the corruption behavior.
Event posted on 09-23-2009 01:44pm EDT by djeffery The 12 byte corruption pattern has been narrowed down and decoded. It's the mode page for tape density and block size. Most importantly, the pattern has a block size of 0. The tape test program sets a non-zero (64KB for the tests that have been running) value before performing any reads or writes. The test program then sets it back to 0 when done and just before closing the tape's device handle. So there are two places where this value should be coming from. When the test app opens the tape device file, the tape driver will read this mode page and value from the tape drive and save its contents for its own use. When the test app uses an ioctl to request the block size be set to 0, the tape driver will build this pattern and then write it out to the tape drive. This event sent from IssueTracker by djeffery issue 325087
Event posted on 09-23-2009 06:07pm EDT by djeffery In some circumstances, the st driver is using memory it has already freed. It effects the ioctl code path which is why the mode page data from the last ioctl() the app calls is seen. The critical ioctl is the call to change the block size of the tape from 0 to anything non-zero. After the MODE_SELECT scsi command to the tape drive completes, in this specific ioctl case (and only this case), the st driver calls normalize_buffers() which frees the driver's internal buffers but does not zero out the pointers to the released memory. There are only three places an internal buffer will be allocated by calling enlarge_buffer(): at device open, a non-directio read, or a non-directio write. Consequently, any future ioctl command that needs a data buffer can cause memory corruption of if a non-directio read, non-direct write, or closing and reopening of the device does not happen first. It reuses the invalid memory pointers as the ioctl code path assumes there is always a valid buffer. This is why disabling direct io causes the test to pass on our test system. After the test app sets the block size to non-zero and causes the driver to free its buffers, the next operation the test app performs is a read or write. However, with direct io enabled, these reads and writes don't cause a buffer to be allocated. Thus, the value from the last ioctl, which sets the block size back to 0, is seen when the memory corruption occurs. This event sent from IssueTracker by djeffery issue 325087
Created attachment 362492 [details] reallocate a 4kb buffer for st after dropping previous buffers I've attached a basic patch that fixes the problem. So far it has survived over 300 iterations of the test app without any problems. On the ioctl path where st's internal buffer is released, the patch now reallocates a minimal 4kb buffer to insure there is allocated memory for any future ioctl calls. This is similar to what happens in st_open() where a 4kb buffer is allocated with the opening of the device handle.
If your analysis is correct (and it looks good to me), it should be easy to trigger the bug by repeatedly changing block size between zero and nonzero and not bothing with the slow data read/write path at all. Putting the machine under some memory pressure by doing a kernel compile at the same time might help too. Unfortunately, I don't have my tape drive at the moment, and I don't have a cciss controller, so I can't try it myself yet.
Created attachment 362934 [details] remove normalize_buffer() call from block size changing ioctl The patch has been updated after feedback from upstream. The call to normalize_buffer() when changing block size from 0 has been completely removed.
Event posted on 09-28-2009 03:14pm EDT by rmunilla update for bugzilla Testing by customer successful "Test kernel passed 300 iterations twice," hotfix has been requested -Robert This event sent from IssueTracker by rmunilla issue 325087
jgiles: I have a trivial reproducer which is much faster than the test program the customer uses. You might even be able to use it with an iscsi-based virtual tape, (I haven't tried yet), in which case you could even rhts it. djeffery: Are you going to take over RHEL-4 (my reproducer has not triggered a failure there, on the same hardware where RHEL-5 crashes within minutes) and RHEL-6 (Almost certainly vulnerable because Fedora 11/Rawhide are)?
in kernel-2.6.18-167.el5 You can download this test kernel from http://people.redhat.com/dzickus/el5 Please do NOT transition this bugzilla state to VERIFIED until our QE team has sent specific instructions indicating when to do so. However feel free to provide a comment indicating that this fix has been verified.
x86_64 directory is empty. Is that intentional?
(In reply to comment #35) > x86_64 directory is empty. Is that intentional? I think you were too fast, copying was in progress probably.
Thanks.
Event posted on 10-07-2009 08:51am EDT by rmunilla Customer package testing successful. Event posted 10-06-2009 01:55pm EDT by Bhargav_Joshi Rob, Testing kernel-2.6.18-167.el5.x86_64.rpm. Will update once it passes 300 loops Internal Status set to 'Waiting on Engineering' Status set to: Waiting on Tech This event sent from IssueTracker by rmunilla issue 325087
~~ Attention Customers and Partners - RHEL 5.5 Beta is now available on RHN ~~ RHEL 5.5 Beta has been released! There should be a fix present in this release that addresses your request. Please test and report back results here, by March 3rd 2010 (2010-03-03) or sooner. Upon successful verification of this request, post your results and update the Verified field in Bugzilla with the appropriate value. If you encounter any issues while testing, please describe them and set this bug into NEED_INFO. If you encounter new defects or have additional patch(es) to request for inclusion, please clone this bug per each request and escalate through your support representative.
An advisory has been issued which should help the problem described in this bug report. This report is therefore being closed with a resolution of ERRATA. For more information on therefore solution and/or where to find the updated files, please follow the link below. You may reopen this bug report if the solution does not work for you. http://rhn.redhat.com/errata/RHSA-2010-0178.html
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 1000 days