{"id":1256,"date":"2011-10-30T07:27:30","date_gmt":"2011-10-30T11:27:30","guid":{"rendered":"http:\/\/cd34.com\/blog\/?p=1256"},"modified":"2011-10-30T07:27:30","modified_gmt":"2011-10-30T11:27:30","slug":"gfs2-kernel-oops","status":"publish","type":"post","link":"https:\/\/cd34.com\/blog\/scalability\/gfs2-kernel-oops\/","title":{"rendered":"GFS2 Kernel Oops"},"content":{"rendered":"<p>For a few years I&#8217;ve run a system using DRBD replication between two machines with GFS2 running in dual primary mode to test a theory on a particular type of web hosting I&#8217;ve been developing.<\/p>\n<p>For months the system will run fine, then, out of the blue, one of the nodes will drop from the cluster, reboot and we&#8217;ve never seen anything in the logs. It&#8217;ll run another 120-180 days without incident and then will reboot again with no real indication of the problem. We knew it was a kernel panic or kernel oops, but, the logs never were flushed to disk when the machine was rebooted.<\/p>\n<p>Imagine our luck when two days in a row, at roughly the same time of day, the node rebooted. Even though we have remote syslog set up, we&#8217;ve never caught it.<\/p>\n<p>\/etc\/sysctl.conf was changed so that panic_on_oops was set to 0, a number of terminal sessions were opened from another machine tailing various logs, and we were hoping to have the problem occur again.<\/p>\n<p>\/etc\/sysctl.conf:<\/p>\n<pre>\r\nkernel.panic=5\r\nkernel.panic_on_oops=0\r\n<\/pre>\n<p>At 6:25am, coincidentally during log rotation, the GFS2 partition umounted, but, the machine didn&#8217;t reboot. Checking our terminal, we still had access to dmesg, and, we had some logs:<\/p>\n<pre>\r\nGFS2: fsid=gamma:gfs1.0: fatal: invalid metadata block\r\nGFS2: fsid=gamma:gfs1.0:   bh = 1211322 (magic number)\r\nGFS2: fsid=gamma:gfs1.0:   function = gfs2_meta_indirect_buffer, file = fs\/gfs2\/meta_io.c, line = 401\r\nGFS2: fsid=gamma:gfs1.0: about to withdraw this file system\r\nGFS2: fsid=gamma:gfs1.0: telling LM to unmount\r\nGFS2: fsid=gamma:gfs1.0: withdrawn\r\nPid: 18047, comm: gzip Not tainted 3.0.0 #1\r\nCall Trace:\r\n [<ffffffff811701ba>] ? gfs2_lm_withdraw+0xd9\/0x10a\r\n [<ffffffff81170425>] ? gfs2_meta_check_ii+0x3c\/0x48\r\n [<ffffffff8115f5a3>] ? gfs2_meta_indirect_buffer+0xf0\/0x14a\r\n [<ffffffff811536db>] ? gfs2_block_map+0x1a3\/0x9fe\r\n [<ffffffff8118305f>] ? drive_stat_acct+0xf3\/0x12e\r\n [<ffffffff810ad37d>] ? do_mpage_readpage+0x160\/0x49f\r\n [<ffffffff810683fa>] ? pagevec_lru_move_fn+0xab\/0xc1\r\n [<ffffffff81153538>] ? gfs2_unstuff_dinode+0x383\/0x383\r\n [<ffffffff810ad806>] ? mpage_readpages+0xd0\/0x12a\r\n [<ffffffff81153538>] ? gfs2_unstuff_dinode+0x383\/0x383\r\n [<ffffffff8103ec2b>] ? bit_waitqueue+0x14\/0x63\r\n [<ffffffff81160000>] ? gfs2_readpages+0x67\/0xa8\r\n [<ffffffff81271848>] ? sd_prep_fn+0x2c1\/0x902\r\n [<ffffffff8115ffd4>] ? gfs2_readpages+0x3b\/0xa8\r\n [<ffffffff81067686>] ? __do_page_cache_readahead+0x11b\/0x1c0\r\n [<ffffffff8106795b>] ? ra_submit+0x19\/0x1d\r\n [<ffffffff81061b35>] ? generic_file_aio_read+0x2b4\/0x5e0\r\n [<ffffffff81086b15>] ? do_sync_read+0xab\/0xe3\r\n [<ffffffff810870f7>] ? vfs_read+0xa3\/0x10f\r\n [<ffffffff810871a8>] ? sys_read+0x45\/0x6e\r\n [<ffffffff813bf3bb>] ? system_call_fastpath+0x16\/0x1b\r\n------------[ cut here ]------------\r\nWARNING: at fs\/buffer.c:1188 gfs2_block_map+0x2be\/0x9fe()\r\nHardware name: PDSMi\r\nVFS: brelse: Trying to free free buffer\r\nModules linked in:\r\nPid: 18047, comm: gzip Not tainted 3.0.0 #1\r\nCall Trace:\r\n [<ffffffff811537f6>] ? gfs2_block_map+0x2be\/0x9fe\r\n [<ffffffff8102a7c9>] ? warn_slowpath_common+0x78\/0x8c\r\n [<ffffffff8102a875>] ? warn_slowpath_fmt+0x45\/0x4a\r\n [<ffffffff811537f6>] ? gfs2_block_map+0x2be\/0x9fe\r\n [<ffffffff8118305f>] ? drive_stat_acct+0xf3\/0x12e\r\n [<ffffffff810ad37d>] ? do_mpage_readpage+0x160\/0x49f\r\n [<ffffffff810683fa>] ? pagevec_lru_move_fn+0xab\/0xc1\r\n [<ffffffff81153538>] ? gfs2_unstuff_dinode+0x383\/0x383\r\n [<ffffffff810ad806>] ? mpage_readpages+0xd0\/0x12a\r\n [<ffffffff81153538>] ? gfs2_unstuff_dinode+0x383\/0x383\r\n [<ffffffff8103ec2b>] ? bit_waitqueue+0x14\/0x63\r\n [<ffffffff81160000>] ? gfs2_readpages+0x67\/0xa8\r\n [<ffffffff81271848>] ? sd_prep_fn+0x2c1\/0x902\r\n [<ffffffff8115ffd4>] ? gfs2_readpages+0x3b\/0xa8\r\n [<ffffffff81067686>] ? __do_page_cache_readahead+0x11b\/0x1c0\r\n [<ffffffff8106795b>] ? ra_submit+0x19\/0x1d\r\n [<ffffffff81061b35>] ? generic_file_aio_read+0x2b4\/0x5e0\r\n [<ffffffff81086b15>] ? do_sync_read+0xab\/0xe3\r\n [<ffffffff810870f7>] ? vfs_read+0xa3\/0x10f\r\n [<ffffffff810871a8>] ? sys_read+0x45\/0x6e\r\n [<ffffffff813bf3bb>] ? system_call_fastpath+0x16\/0x1b\r\n---[ end trace 54fad1a4877f173c ]---\r\nBUG: unable to handle kernel paging request at ffffffff813b8f0f\r\nIP: [<ffffffff810a6a17>] __brelse+0x7\/0x26\r\nPGD 1625067 PUD 1629063 PMD 12001e1 \r\nOops: 0003 [#1] SMP \r\nCPU 0 \r\nModules linked in:\r\n\r\nPid: 18047, comm: gzip Tainted: G        W   3.0.0 #1 Supermicro PDSMi\/PDSMi+\r\nRIP: 0010:[<\/ffffffff810a6a17><ffffffff810a6a17>]  [<\/ffffffff810a6a17><ffffffff810a6a17>] __brelse+0x7\/0x26\r\nRSP: 0018:ffff880185d85800  EFLAGS: 00010286\r\nRAX: 00000000e8df8948 RBX: ffff8801f3fb6c18 RCX: ffff880185d857d0\r\nRDX: 0000000000000010 RSI: 000000000002ccee RDI: ffffffff813b8eaf\r\nRBP: 0000000000000000 R08: ffff880185d85890 R09: ffff8801f3fb6c18\r\nR10: 00000000000029e0 R11: 0000000000000078 R12: ffff880147986000\r\nR13: ffff880147986140 R14: 00000000000029c1 R15: 0000000000001000\r\nFS:  00007fb7d320f700(0000) GS:ffff88021fc00000(0000) knlGS:0000000000000000\r\nCS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033\r\nCR2: ffffffff813b8f0f CR3: 0000000212a73000 CR4: 00000000000006f0\r\nDR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000\r\nDR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400\r\nProcess gzip (pid: 18047, threadinfo ffff880185d84000, task ffff880147dc4ed0)\r\nStack:\r\n ffffffff811537f6 0000000000000000 00000000000022a1 0000000000000001\r\n 000000000000ffff 0000000000000000 ffffffff8102a7ce 0000000000000001\r\n 0000000100000008 00000000fffffffb 0000000000000001 ffff8801f3fb6c18\r\nCall Trace:\r\n [<ffffffff811537f6>] ? gfs2_block_map+0x2be\/0x9fe\r\n [<ffffffff8102a7ce>] ? warn_slowpath_common+0x7d\/0x8c\r\n [<ffffffff813b8eaf>] ? printk+0x43\/0x48\r\n [<ffffffff810a6158>] ? alloc_page_buffers+0x62\/0xba\r\n [<ffffffff810a6792>] ? block_read_full_page+0x141\/0x260\r\n [<ffffffff81153538>] ? gfs2_unstuff_dinode+0x383\/0x383\r\n [<ffffffff810ad6b8>] ? do_mpage_readpage+0x49b\/0x49f\r\n [<ffffffff810683fa>] ? pagevec_lru_move_fn+0xab\/0xc1\r\n [<ffffffff81153538>] ? gfs2_unstuff_dinode+0x383\/0x383\r\n [<ffffffff810ad806>] ? mpage_readpages+0xd0\/0x12a\r\n [<ffffffff81153538>] ? gfs2_unstuff_dinode+0x383\/0x383\r\n [<ffffffff8103ec2b>] ? bit_waitqueue+0x14\/0x63\r\n [<ffffffff81160000>] ? gfs2_readpages+0x67\/0xa8\r\n [<ffffffff81271848>] ? sd_prep_fn+0x2c1\/0x902\r\n [<ffffffff8115ffd4>] ? gfs2_readpages+0x3b\/0xa8\r\n [<ffffffff81067686>] ? __do_page_cache_readahead+0x11b\/0x1c0\r\n [<ffffffff8106795b>] ? ra_submit+0x19\/0x1d\r\n [<ffffffff81061b35>] ? generic_file_aio_read+0x2b4\/0x5e0\r\n [<ffffffff81086b15>] ? do_sync_read+0xab\/0xe3\r\n [<ffffffff810870f7>] ? vfs_read+0xa3\/0x10f\r\n [<ffffffff810871a8>] ? sys_read+0x45\/0x6e\r\n [<ffffffff813bf3bb>] ? system_call_fastpath+0x16\/0x1b\r\nCode: 31 00 45 31 f6 fe 85 88 00 00 00 48 89 df e8 a2 1a fc ff eb 03 45 31 f6 5b 4c 89 f0 5d 41 5c 41 5d 41 5e c3 8b 47 60 85 c0 74 05 <f0> ff 4f 60 c3 48 c7 c2 96 7b 4d 81 be a4 04 00 00 31 c0 48 c7 \r\nRIP  [<ffffffff810a6a17>] __brelse+0x7\/0x26\r\n RSP <ffff880185d85800>\r\nCR2: ffffffff813b8f0f\r\n---[ end trace 54fad1a4877f173d ]---\r\n<\/ffff880185d85800><\/ffffffff810a6a17><\/f0><\/ffffffff813bf3bb><\/ffffffff810871a8><\/ffffffff810870f7><\/ffffffff81086b15><\/ffffffff81061b35><\/ffffffff8106795b><\/ffffffff81067686><\/ffffffff8115ffd4><\/ffffffff81271848><\/ffffffff81160000><\/ffffffff8103ec2b><\/ffffffff81153538><\/ffffffff810ad806><\/ffffffff81153538><\/ffffffff810683fa><\/ffffffff810ad6b8><\/ffffffff81153538><\/ffffffff810a6792><\/ffffffff810a6158><\/ffffffff813b8eaf><\/ffffffff8102a7ce><\/ffffffff811537f6><\/ffffffff810a6a17><\/ffffffff813bf3bb><\/ffffffff810871a8><\/ffffffff810870f7><\/ffffffff81086b15><\/ffffffff81061b35><\/ffffffff8106795b><\/ffffffff81067686><\/ffffffff8115ffd4><\/ffffffff81271848><\/ffffffff81160000><\/ffffffff8103ec2b><\/ffffffff81153538><\/ffffffff810ad806><\/ffffffff81153538><\/ffffffff810683fa><\/ffffffff810ad37d><\/ffffffff8118305f><\/ffffffff811537f6><\/ffffffff8102a875><\/ffffffff8102a7c9><\/ffffffff811537f6><\/ffffffff813bf3bb><\/ffffffff810871a8><\/ffffffff810870f7><\/ffffffff81086b15><\/ffffffff81061b35><\/ffffffff8106795b><\/ffffffff81067686><\/ffffffff8115ffd4><\/ffffffff81271848><\/ffffffff81160000><\/ffffffff8103ec2b><\/ffffffff81153538><\/ffffffff810ad806><\/ffffffff81153538><\/ffffffff810683fa><\/ffffffff810ad37d><\/ffffffff8118305f><\/ffffffff811536db><\/ffffffff8115f5a3><\/ffffffff81170425><\/ffffffff811701ba><\/pre>\n<p>As I suspected, log rotation appeared to trigger the problem and handed us the above traceback. Running fsck.gfs2 resulted in:<\/p>\n<pre>\r\n\r\n# fsck.gfs2 -y \/dev\/drbd1\r\nInitializing fsck\r\nValidating Resource Group index.\r\nLevel 1 RG check.\r\n(level 1 passed)\r\nError: resource group 7339665 (0x6ffe91): free space (64473) does not match bitmap (64658)\r\nThe rgrp was fixed.\r\nError: resource group 7405179 (0x70fe7b): free space (64249) does not match bitmap (64299)\r\n(50 blocks were reclaimed)\r\nThe rgrp was fixed.\r\nError: resource group 7470693 (0x71fe65): free space (65456) does not match bitmap (65464)\r\n(8 blocks were reclaimed)\r\nThe rgrp was fixed.\r\n\r\n...snip...\r\n\r\nOndisk and fsck bitmaps differ at block 133061348 (0x7ee5ae4) \r\nOndisk status is 1 (Data) but FSCK thinks it should be 0 (Free)\r\nMetadata type is 0 (free)\r\nSucceeded.\r\nOndisk and fsck bitmaps differ at block 133061349 (0x7ee5ae5) \r\nOndisk status is 1 (Data) but FSCK thinks it should be 0 (Free)\r\nMetadata type is 0 (free)\r\nSucceeded.\r\nRG #133061031 (0x7ee59a7) free count inconsistent: is 65232 should be 65508\r\nInode count inconsistent: is 37 should be 0\r\nResource group counts updated\r\nInode count inconsistent: is 1267 should be 1266\r\nResource group counts updated\r\nPass5 complete      \r\nThe statfs file is wrong:\r\n\r\nCurrent statfs values:\r\nblocks:  188730628 (0xb3fcd04)\r\nfree:    176443034 (0xa844e9a)\r\ndinodes: 644117 (0x9d415)\r\n\r\nCalculated statfs values:\r\nblocks:  188730628 (0xb3fcd04)\r\nfree:    177426468 (0xa935024)\r\ndinodes: 493059 (0x78603)\r\nThe statfs file was fixed.\r\nWriting changes to disk\r\ngfs2_fsck complete \r\n<\/pre>\n<p>Filesystem was remounted after a 7 minute fsck and we&#8217;ll see if it happens again tomorrow.<\/p>\n<div style=\"float:left;\">\n<div id=\"fb-root\"><\/div>\n<fb:like href=\"https:\/\/cd34.com\/blog\/scalability\/gfs2-kernel-oops\/\" width=\"250\" send=\"false\" show_faces=\"false\" layout=\"button_count\" action=\"recommend\"><\/fb:like>\n<\/div><div style=\"clear:both;\"><\/div>","protected":false},"excerpt":{"rendered":"<p>For a few years I&#8217;ve run a system using DRBD replication between two machines with GFS2 running in dual primary mode to test a theory on a particular type of web hosting I&#8217;ve been developing. For months the system will run fine, then, out of the blue, one of the nodes will drop from the [&hellip;]<\/p>\n<div style=\"float:left;\">\n<div id=\"fb-root\"><\/div>\n<fb:like href=\"https:\/\/cd34.com\/blog\/scalability\/gfs2-kernel-oops\/\" width=\"250\" send=\"false\" show_faces=\"false\" layout=\"button_count\" action=\"recommend\"><\/fb:like>\n<\/div><div style=\"clear:both;\"><\/div>","protected":false},"author":15,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[12],"tags":[203,93],"class_list":["post-1256","post","type-post","status-publish","format-standard","hentry","category-scalability","tag-drbd","tag-gfs2"],"_links":{"self":[{"href":"https:\/\/cd34.com\/blog\/wp-json\/wp\/v2\/posts\/1256","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/cd34.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/cd34.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/cd34.com\/blog\/wp-json\/wp\/v2\/users\/15"}],"replies":[{"embeddable":true,"href":"https:\/\/cd34.com\/blog\/wp-json\/wp\/v2\/comments?post=1256"}],"version-history":[{"count":1,"href":"https:\/\/cd34.com\/blog\/wp-json\/wp\/v2\/posts\/1256\/revisions"}],"predecessor-version":[{"id":1257,"href":"https:\/\/cd34.com\/blog\/wp-json\/wp\/v2\/posts\/1256\/revisions\/1257"}],"wp:attachment":[{"href":"https:\/\/cd34.com\/blog\/wp-json\/wp\/v2\/media?parent=1256"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/cd34.com\/blog\/wp-json\/wp\/v2\/categories?post=1256"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/cd34.com\/blog\/wp-json\/wp\/v2\/tags?post=1256"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}