<div dir="ltr"><div><div><div><div><div>Hi, this is the test I run<br><br></div>cluster 4 nodes 2 nic each.<br></div>A guest running on node id 0 (that is also zookeeper leader).<br></div>eth0 is bridged, and user by zookeeper.<br>
</div>eth1 is I/O nic.<br><br></div><div>I removed the cable from eth0.<br></div><div>The guest continues to work as nothing happened.<br></div><div>I write a small file (inside the guest) of 10M and I get no errors.<br></div>
<div>I run 'sync' and it hangs.<br></div><div>I can stop it by ctrl+c and no errors are shown.<br><br></div><div>After 120 seconds it pops up the usual message<br><span class=""><span> 'Task XXX blocked for more than 120 seconds'<br>
<br></span></span></div><div><span class=""><span>I reconnect the cable and, as soon the node rejoin the cluster, I get lots of <br></span></span></div><div><span class=""><span> 'Buffer I/O error on device vda1, logical block 511XX'<br>
</span></span></div><div><span class=""><span>in the console.<br><br></span></span></div><div><span class=""><span>0) is it correct to receive the Buffer I/O error when the node is back?<br></span></span></div><div><span class=""><span><br>
</span></span></div><div><span class=""><span>In /var/log/messages I get this:<br><br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741188] jbd2/vda1-8 D ffff88001fd13780 0 150 2 0x00000000<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741202] ffff88001c24d6d0 0000000000000046 ffff88001e392898 ffff88001fa06f60<br>
Dec 19 10:27:52 wheezytemplate kernel: [ 360.741215] 0000000000013780 ffff88001be01fd8 ffff88001be01fd8 ffff88001c24d6d0<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741225] ffff88001e392898 ffffffff81065dbd ffff88001f914980 ffff88001fd13fd0<br>
Dec 19 10:27:52 wheezytemplate kernel: [ 360.741235] Call Trace:<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741254] [<ffffffff81065dbd>] ? timekeeping_get_ns+0xd/0x2a<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741266] [<ffffffff8111c835>] ? wait_on_buffer+0x28/0x28<br>
Dec 19 10:27:52 wheezytemplate kernel: [ 360.741276] [<ffffffff8134bf7c>] ? io_schedule+0x59/0x71<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741285] [<ffffffff8111c83b>] ? sleep_on_buffer+0x6/0xa<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741293] [<ffffffff8134c3bf>] ? __wait_on_bit+0x3e/0x71<br>
Dec 19 10:27:52 wheezytemplate kernel: [ 360.741301] [<ffffffff8134c461>] ? out_of_line_wait_on_bit+0x6f/0x78<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741309] [<ffffffff8111c835>] ? wait_on_buffer+0x28/0x28<br>
Dec 19 10:27:52 wheezytemplate kernel: [ 360.741320] [<ffffffff8105f87d>] ? autoremove_wake_function+0x2a/0x2a<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741371] [<ffffffffa010b9c0>] ? jbd2_journal_commit_transaction+0xb9b/0x1057 [jbd2]<br>
Dec 19 10:27:52 wheezytemplate kernel: [ 360.741389] [<ffffffff8100d02f>] ? load_TLS+0x7/0xa<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741403] [<ffffffff8100d69e>] ? __switch_to+0x133/0x258<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741418] [<ffffffff8134d03c>] ? _raw_spin_lock_irqsave+0x9/0x25<br>
Dec 19 10:27:52 wheezytemplate kernel: [ 360.741433] [<ffffffff81052212>] ? lock_timer_base.isra.29+0x23/0x47<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741456] [<ffffffffa010f0ae>] ? kjournald2+0xc0/0x20a [jbd2]<br>
Dec 19 10:27:52 wheezytemplate kernel: [ 360.741471] [<ffffffff8105f853>] ? add_wait_queue+0x3c/0x3c<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741490] [<ffffffffa010efee>] ? commit_timeout+0x5/0x5 [jbd2]<br>
Dec 19 10:27:52 wheezytemplate kernel: [ 360.741506] [<ffffffff8105f201>] ? kthread+0x76/0x7e<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741521] [<ffffffff81354174>] ? kernel_thread_helper+0x4/0x10<br>
Dec 19 10:27:52 wheezytemplate kernel: [ 360.741537] [<ffffffff8105f18b>] ? kthread_worker_fn+0x139/0x139<br>Dec 19 10:27:52 wheezytemplate kernel: [ 360.741550] [<ffffffff81354170>] ? gs_change+0x13/0x13<br>
Dec 19 10:29:00 wheezytemplate kernel: vda1, logical block 49398<br>Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 524288 size 524288 starting block 49664)<br>
Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 1048576 size 524288 starting block 49792)<br>Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 1572864 size 524288 starting block 49920)<br>
Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 2097152 size 524288 starting block 50048)<br>Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 2621440 size 524288 starting block 50176)<br>
Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 3145728 size 524288 starting block 50304)<br>Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 3670016 size 524288 starting block 50432)<br>
Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 4194304 size 524288 starting block 50560)<br>Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 4718592 size 524288 starting block 50688)<br>
Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 5242880 size 524288 starting block 50816)<br>Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 5767168 size 524288 starting block 50944)<br>
Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 6291456 size 524288 starting block 51072)<br>Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 6815744 size 524288 starting block 51200)<br>
Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 7340032 size 524288 starting block 51328)<br>Dec 19 10:29:00 wheezytemplate kernel: [ 426.107078] EXT4-fs warning (device vda1): ext4_end_bio:251: I/O error writing to inode 260693 (offset 7864320 size 524288 starting block 51456)<br>
Dec 19 10:29:00 wheezytemplate kernel: [ 428.812824] JBD2: Detected IO errors while flushing file data on vda1-8<br><br></span></span></div><div><span class=""><span>1) I've been writing two more file and rebooted the guest and, after ti, they were there.<br>
</span></span></div><div><span class=""><span> That's the most important thing :-)<br></span></span></div><div><span class=""><span><br><br></span></span></div><div><span class=""><span>Now I wish to focus on sheep.log<br>
<br>First look at cluster info<br><br>Epoch Time Version <br>
2013-12-19 10:28:57 14 [<a href="http://192.168.10.4:7000">192.168.10.4:7000</a>, <a href="http://192.168.10.5:7000">192.168.10.5:7000</a>, <a href="http://192.168.10.6:7000">192.168.10.6:7000</a>, <a href="http://192.168.10.7:7000">192.168.10.7:7000</a>] <br>
2013-12-19 10:23:44 13 [<a href="http://192.168.10.5:7000">192.168.10.5:7000</a>, <a href="http://192.168.10.6:7000">192.168.10.6:7000</a>, <a href="http://192.168.10.7:7000">192.168.10.7:7000</a>] <br>
2013-12-19 08:39:58 12 [<a href="http://192.168.10.4:7000">192.168.10.4:7000</a>, <a href="http://192.168.10.5:7000">192.168.10.5:7000</a>, <a href="http://192.168.10.6:7000">192.168.10.6:7000</a>, <a href="http://192.168.10.7:7000">192.168.10.7:7000</a>]<br>
<br></span></span></div><div><span class=""><span>This is sheep.log of the disconnected node<br></span></span></div><div><span class=""><span>(...) means the last row repeats many times.<br></span></span></div><div><span class=""><span><br>
Dec 19 10:24:17 ERROR [gway 8654] wait_forward_request(461) fail 5ddf8800000000, Request has an old epoch<br>Dec 19 10:24:17 ERROR [gway 8654] wait_forward_request(461) fail 5ddf8800000000, Request has an old epoch<br>Dec 19 10:24:17 ERROR [gway 8655] wait_forward_request(461) fail 5ddf8800000400, Request has an old epoch<br>
Dec 19 10:24:17 ERROR [gway 8653] wait_forward_request(461) fail 5ddf8800000600, Request has an old epoch<br>Dec 19 10:24:17 ERROR [gway 8685] wait_forward_request(461) fail 5ddf8800000420, Request has an old epoch<br>Dec 19 10:24:17 ERROR [gway 8685] wait_forward_request(461) fail 5ddf8800000420, Request has an old epoch<br>
Dec 19 10:24:41 ERROR [gway 8683] sheep_exec_req(1008) failed Request has an old epoch<br>Dec 19 10:24:41 ERROR [gway 8683] sheep_exec_req(1008) failed Request has an old epoch<br>Dec 19 10:24:41 ERROR [gway 8654] sheep_exec_req(1008) failed Request has an old epoc<br>
...<br>Dec 19 10:28:57 ERROR [main] zk_event_handler(1194) detect a session timeout. reconnecting...<br>Dec 19 10:28:57 INFO [main] send_join_request(777) IPv4 ip:192.168.10.4 port:7000<br>Dec 19 10:28:57 INFO [main] zk_find_master(803) detect master leave, start to compete master<br>
Dec 19 10:28:57 INFO [main] zk_event_handler(1196) reconnected<br>Dec 19 10:28:57 INFO [main] recover_object_main(841) object 5ddf8800000400 is recovered (1/216)<br>Dec 19 10:28:57 INFO [main] recover_object_main(841) object 5ddf8800000600 is recovered (2/216)<br>
Dec 19 10:28:58 INFO [main] recover_object_main(841) object 5ddf88000000b1 is recovered (3/216)<br>...<br><br></span></span></div><div><span class=""><span>2) There are tons of the same message:<br><br></span></span></div>
<div><span class=""><span>grep -c 'sheep_exec_req(1008) failed Request has an old epoch' /var/sheep/sheep.log <br>
1141544<br><br><br></span></span></div><div><span class=""><span>This is sheep.log of another node:<br><br>Dec 19 10:24:17 ERROR [main] check_request_epoch(151) old node version 13, 12 (WRITE_PEER)<br>Dec 19 10:24:41 ERROR [main] check_request_epoch(151) old node version 13, 12 (READ_PEER)<br>
Dec 19 10:24:41 ERROR [main] check_request_epoch(151) old node version 13, 12 (READ_PEER)<br>...<br>Dec 19 10:28:57 INFO [main] recover_object_main(841) object 5ddf8800000052 is recovered (1/197)<br>Dec 19 10:28:57 INFO [main] recover_object_main(841) object 5ddf8800000094 is recovered (2/197)<br>
...<br><br></span></span></div><div><span class=""><span>sheep.log size is 96M<br></span></span></div><div><span class=""><span><br></span></span><br><span class=""><span><span class=""><span>3) also this message is repeated many many times<br>
<br></span></span>grep -c 'check_request_epoch(151) old node version 13, 12 (READ_PEER)' /var/sheep/sheep.log <br>223375<br><br></span></span></div><div><span class=""><span>sheep.log size is 50M<br><br><br></span></span></div>
<div><span class=""><span><br></span></span></div><div><span class=""><span>4) I fear that, if the cable stay disconnecter for long time, sheep.log will grow to much.<br><br><br></span></span></div><div><span class=""><span>Make your considerations and tell me if there's something that may be consider as a bug or wish list and I'll file it in launch pad.<br>
<br></span></span></div><div><span class=""><span><br></span></span></div><div><span class=""><span><br></span></span></div><span class=""><span></span></span></div>