carsten’s blog

Während einiger Wartungsarbeiten und einem damit verbundenen Kernelupdate auf die derzeit
für SLES 11 SP2 aktuelle Kernel Version 3.0.80 bin ich auf einen Fehler in Verbindung mit DRBD gestoßen.

Das Update selbst liefert keine neuen drbd kmp Pakete mit, sondern verwendet weiterhin eine Vorgängerversion (8.4.2_3.0.51_0.7.9-0.6.6.4)

Der Fehler äußert sich direkt beim Laden des drbd Moduls mit folgender Meldung:

[ 154.173134] events: mcg drbd: 3
[ 154.174916] BUG: unable to handle kernel NULL pointer dereference at (null)
[ 154.174927] IP: [] cleanup_module+0xb0/0x150 [drbd]
[ 154.174949] PGD 7927f8067 PUD 7a0a83067 PMD 0
[ 154.174954] Oops: 0000 [#1] SMP
[ 154.174959] CPU 7
[ 154.174960] Modules linked in: drbd(+) crc32c libcrc32c ip6table_filter ip6_tables iptable_filter ip_tables x_tables nbd usbbk netbk blkbk blkback_pagemap blktap xenbus_be gntdev evtchn mpt2sas scsi_transport_sas raid_class mptctl mptbase ipmi_devintf ipmi_si ipmi_msghandler dell_rbu(X) bridge 8021q garp stp llc bonding microcode fuse loop dm_mod joydev bnx2 usbhid hid sg ses enclosure sr_mod 8250_pnp ipv6 ipv6_lib pcspkr tpm_tis tpm tpm_bios i2c_piix4 i2c_core dcdbas(X) k10temp domctl 8250 serial_core rtc_cmos serio_raw button acpi_power_meter ohci_hcd ehci_hcd usbcore usb_common sd_mod crc_t10dif scsi_dh_hp_sw scsi_dh_alua scsi_dh_rdac scsi_dh_emc scsi_dh xenblk cdrom xennet edd ext3 mbcache jbd fan processor ata_generic pata_atiixp ahci libahci libata megaraid_sas scsi_mod thermal thermal_sys hwmon
[ 154.175039] Supported: Yes, External
[ 154.175041]
[ 154.175044] Pid: 12110, comm: modprobe Tainted: G X 3.0.80-0.5-xen #1 Dell Inc. PowerEdge R515/03X0MN
[ 154.175050] RIP: e030:[] [] cleanup_module+0xb0/0x150 [drbd]
[ 154.175064] RSP: e02b:ffff88079e8efef8 EFLAGS: 00010203
[ 154.175066] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 154.175069] RDX: fffffffffffffff8 RSI: ffff88079e8eff0c RDI: ffffffffa04fe600
[ 154.175072] RBP: ffff88079e8eff0c R08: 0000000000000000 R09: 0000000800040008
[ 154.175075] R10: 0000000100030008 R11: 0000001800010006 R12: ffffffffa0508000
[ 154.175078] R13: 0000000000000000 R14: 0000000000623230 R15: 0000000000000000
[ 154.175084] FS: 00007f92fdf3a700(0000) GS:ffff8807c14e0000(0000) knlGS:0000000000000000
[ 154.175088] CS: e033 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 154.175090] CR2: 0000000000000000 CR3: 00000007a793c000 CR4: 0000000000000660
[ 154.175094] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 154.175097] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 154.175100] Process modprobe (pid: 12110, threadinfo ffff88079e8ee000, task ffff880792438580)
[ 154.175103] Stack:
[ 154.175105] 0000000000000000 ffffffffa04d8f05 0000000000000000 00000000fffffff4
[ 154.175110] 0000000000081dd8 ffffffffa0508085 ffffffffa04fe240 ffffffff8000403b
[ 154.175115] 0000000000000000 ffffffffa04fe240 0000000000081dd8 00007f92fdeb7000
[ 154.175121] Call Trace:
[ 154.175158] [] init_module+0x85/0x1000 [drbd]
[ 154.175177] [] do_one_initcall+0x3b/0x190
[ 154.175185] [] sys_init_module+0xcf/0x240
[ 154.175192] [] system_call_fastpath+0x16/0x1b
[ 154.175201] [<00007f92fda9635a>] 0x7f92fda96359
[ 154.175204] Code: 24 14 01 48 89 ee 48 c7 c7 00 e6 4f a0 e8 69 80 d3 df 48 85 c0 48 89 c3 75 b1 48 8b 05 ba 59 02 00 48 8d 50 f8 48 3d 20 e6 4f a0
[ 154.175228] 8b 4a 08 74 5b 48 8d 59 f8 eb 07 0f 1f 40 00 48 89 f3 48 8b
[ 154.175241] RIP [] cleanup_module+0xb0/0x150 [drbd]
[ 154.175253] RSP
[ 154.175255] CR2: 0000000000000000
[ 154.175258] —[ end trace ae9d139fe656969d ]—
[ 171.660668] IPMI System Interface driver.
[ 171.660720] ipmi_si: probing via SMBIOS
[ 171.660724] ipmi_si: SMBIOS: io 0xca8 regsize 1 spacing 4 irq 0
[ 171.660727] ipmi_si: Adding SMBIOS-specified kcs state machine
[ 171.660733] ipmi_si: Trying SMBIOS-specified kcs state machine at i/o address 0xca8, slave address 0x20, irq 0
[ 172.742032] ipmi_si ipmi_si.0: Found new BMC (man_id: 0x0002a2, prod_id: 0x0100, dev_id: 0x20)
[ 172.742111] ipmi_si ipmi_si.0: IPMI kcs interface initialized

Ich habe den Fehler dann direkt (19.06.2013) als Servicerequest bei Novell gemeldet, heute am 21.06.2013 wurde mir ein PTF bereit gestellt der das Problem behebt.
Zwischenzeitlich hatte ich ein Kerneldowngrade auf die Version 3.0.74-0.6.10.1 durchgeführt, damit meine Systeme wieder einwandfrei arbeiten.

Ursache des ganzen war folgendes:

It is because of a silent change in KABI for xen.
Which requires the drbd module to be re-compiled against the actual
kernel. Also we have found and fixed the NULL pointer dereference possibility
in drbd code.

Öffentlich soll der Fix im laufe der KW26 werden, sofern nichts größeres dazwischen kommt.

Update 25.06.2013:
Der Vorabfix wurde heute von SUSE zurück gezogen und ein komplettes Kernel Update angekündigt, da die KABI
Änderungen wohl umfangreicher ausfallen. Nach dem Update soll das alte drbd Kernel Modul wieder kompatibel sein.

Update 05.07.2013:
Ein neues Kernelupdate (SUSE-SU-2013:1151-1 / Version 3.0.80-0.7.1) wurde released, welches das Problem nun final löst.

Gestern habe ich von Novell einen aktualisierten Kernel bekommen in dem der CIFS Bug
behoben ist. Der Kernel hat, zumindesst vorübergehend (bis zum finalen release),
die Version 2.6.32.13-0.5.1.1726.0.PTF-default.

Im changelog findet sich folgender Eintrag:

– patches.fixes/cifs-fix-vfs-busy-inode-errors: Revert the commit that fixes
page refcount leak which is not required but causes hangs (bnc#627518).

Der neue Kernel ist noch nicht öffentlich verfügbar, die Änderung wird
aber aller vorrausicht nacht so in den Hauptkernel und somit das nächste
Update einfließen.

Update (13.09.2010 21:13):

Das offizielle Update des Kernels wurde heute frei geben, neben diversen Sicherheitsfixes wurden auch einige Bugs beseitigt.

Details dazu gibt es hier

Anfang dieser Woche ist mir nach der Neuinstallation einer Workstation bzw. beim updaten vorhandener Systeme ein Kernel BUG im CIFS Treiber untergekommen.

Bei gemounteten Freigaben unseres Samba Servers kommt es beim Lesen oder Schreiben (Verzeichnislisting funktionert – “ls -al”) auf die Freigabe zu einem Lockup, welcher sich im Systemlog wie folgt darstellt.

Aug 10 12:26:03 linux-l4nm kernel: [  213.425273] BUG: Bad page state in process cp  pfn:694cc
Aug 10 12:26:03 linux-l4nm kernel: [  213.425276] page:ffffea0001708ca0 flags:0020000000000010 count:0 mapcount:0 mapping:ffff880069c62ea8 index:e
Aug 10 12:26:03 linux-l4nm kernel: [  213.425279] Pid: 3289, comm: cp Tainted: G    B   W  X 2.6.32.13-0.5-default #1
Aug 10 12:26:03 linux-l4nm kernel: [  213.425281] Call Trace:
Aug 10 12:26:03 linux-l4nm kernel: [  213.425286]  [<ffffffff810061dc>] dump_trace+0x6c/0x2d0
Aug 10 12:26:03 linux-l4nm kernel: [  213.425291]  [<ffffffff81394848>] dump_stack+0x69/0x71
Aug 10 12:26:03 linux-l4nm kernel: [  213.425296]  [<ffffffff810b9343>] bad_page+0xe3/0x170
Aug 10 12:26:03 linux-l4nm kernel: [  213.425300]  [<ffffffff810bc729>] __pagevec_free+0x39/0x50
Aug 10 12:26:04 linux-l4nm kernel: [  213.425305]  [<ffffffff810bf65a>] release_pages+0x1fa/0x250
Aug 10 12:26:04 linux-l4nm kernel: [  213.425311]  [<ffffffff810bf890>] ____pagevec_lru_add+0x1e0/0x200
Aug 10 12:26:04 linux-l4nm kernel: [  213.425320]  [<ffffffffa04c06fc>] cifs_readpages+0x3dc/0x4d0 [cifs]
Aug 10 12:26:04 linux-l4nm kernel: [  213.425335]  [<ffffffff810be83a>] __do_page_cache_readahead+0x14a/0x220
Aug 10 12:26:04 linux-l4nm kernel: [  213.425340]  [<ffffffff810be92c>] ra_submit+0x1c/0x30
Aug 10 12:26:04 linux-l4nm kernel: [  213.425345]  [<ffffffff810b5a5e>] do_generic_file_read+0x33e/0x460
Aug 10 12:26:04 linux-l4nm kernel: [  213.425350]  [<ffffffff810b6296>] generic_file_aio_read+0xd6/0x1f0
Aug 10 12:26:04 linux-l4nm kernel: [  213.425355]  [<ffffffff810fc7e3>] do_sync_read+0xe3/0x130
Aug 10 12:26:04 linux-l4nm kernel: [  213.425360]  [<ffffffff810fcf87>] vfs_read+0xc7/0x130
Aug 10 12:26:04 linux-l4nm kernel: [  213.425365]  [<ffffffff810fd0f3>] sys_read+0x53/0xa0
Aug 10 12:26:04 linux-l4nm kernel: [  213.425370]  [<ffffffff81002f7b>] system_call_fastpath+0x16/0x1b
Aug 10 12:26:04 linux-l4nm kernel: [  213.425376]  [<00007f05e409df30>] 0x7f05e409df30

Ich habe dazu bei Novell einen Service Request geöffnet welcher, derzeit vom Engineering bearbeitet wird und vorraussichtlich mit einem neuen Kernelupdate gefixt wird.

In fast jeder VMware ESX Umgebung habe ich den folgenden Softlockup auf CentOS 5 Gastsystemen gesehen. Allerdings nur mit installierten VMware-Tools. Auf Nachfrage beim Support hat sich herrausgestellt, das dieses Verhalten dadurch zustande kommt, das die jeweilige CPU kurzzeitig nicht zur Verfügung steht weil Sie z.B. von einer anderen virtuellen Maschine benutzt wird. Der Fehler tritt besonders häufig auf wenn die VM vier CPU Cores zugeweisen bekommt.

Auf einem Dual Quad Core Host mit zwei VMs mit je vier Cores ist es also leicht reproduzierbar, da auf dem ersten Core ja zusätzlich noch die Serviceconsole von VMware ESX läuft.  Den Virtuellen Systemen sind also mehr Cores zugeweisen als eigentlich verfügbar. Im Normalfall ist das kein Problem solang die VMs nicht unter hoher Last laufen, bei extremer Auslastung der einzelnen Cores in den VMs kann dieses Verhalten dann ausgelöst werden. Vorbeugend kann man die VMs nur auf zwei Cores heruntersetzen.

BUG: soft lockup – CPU#1 stuck for 10s! [sh:2723]
CPU 1:
Modules linked in: xt_tcpudp iptable_nat ip_nat ip_conntrack nfnetlink ip_tables x_tables ipv6 xfrm_nalgo crypto_api nfsd exportfs lockd nfs_acl auth_rpcgss vmmemctl(U) sunrpc vmhgfs(U) dm_mirror dm_multipath dm_mod video sbs backlight i2c_ec button battery asus_acpi acpi_memhotplug ac lp sg i2c_piix4 ide_cd shpchp floppy i2c_core cdrom e1000 pcspkr parport_pc serio_raw parport ata_piix libata mptspi mptscsih mptbase scsi_transport_spi sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd
Pid: 2723, comm: sh Tainted: G      2.6.18-92.1.22.el5 #1
RIP: 0010:[<ffffffff80064af8>]  [<ffffffff80064af8>] _spin_unlock_irqrestore+0x8/0x9
RSP: 0018:ffff810227b39d50  EFLAGS: 00000296
RAX: ffff8102feb27b30 RBX: ffff8102feb27ac0 RCX: 000000000000003b
RDX: ffff810100000000 RSI: 0000000000000296 RDI: ffff8102feb27b2c
RBP: 000000000048c04e R08: ffff8102feb27ac0 R09: ffff81010d29e800
R10: 0000000000000008 R11: 000000d000000001 R12: 0000000000000008
R13: 000000d000000001 R14: ffffffff800093b2 R15: 0000000000000018
FS:  00002aec39b81dc0(0000) GS:ffff81010d30c840(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 000000000048c04e CR3: 000000022ddbd000 CR4: 00000000000006e0

Call Trace:
[<ffffffff800668a2>] do_page_fault+0x4fe/0x830
[<ffffffff80013388>] filemap_nopage+0x188/0x322
[<ffffffff8005dde9>] error_exit+0x0/0x84
[<ffffffff8003688b>] __strncpy_from_user+0x28/0x41
[<ffffffff8003687a>] __strncpy_from_user+0x17/0x41
[<ffffffff80012336>] getname+0x15b/0x1c1
[<ffffffff8001976e>] do_sys_open+0x17/0xbe
[<ffffffff8005d116>] system_call+0x7e/0x83