[Ocfs2-devel] Do you know this issue? thanks

Linux ocfs2 filesystem development
 help / color / mirror / Atom feed

* [Ocfs2-devel] Do you know this issue? thanks
       [not found] <55AFBD47020000F90000F7DF@relay2.provo.novell.com>
@ 2015-07-23  2:37 ` Joseph Qi
  2015-07-23  7:14   ` Gang He
  0 siblings, 1 reply; 8+ messages in thread
From: Joseph Qi @ 2015-07-23  2:37 UTC (permalink / raw)
  To: ocfs2-devel

I have never seen this bug.
From the bug expression, it is caused by inode in memory and disk
mismatch. Previously we found jbd2_journal_restart is not called
correctly in ocfs2 and will cause inconsistent. I am not sure if it has
relations.
So could you check if there is any error occurred before (like storage
link down)?

On 2015/7/22 15:56, Gang He wrote:
> Hello Joseph and Junxiao,
> 
> I know you guys worked on OCFS2 for a few years.
> Here, the customer reported a bug when they were running Pacemaker+OCFS2+SAP application on SLES11SP3 two nodes.
> But they did not provided the core dump file, or reproduce steps (seemed that they encountered this issue two times occasionally), 
> then I want to know if you saw the similar issue in the past, very thanks.
> The panic backtrace is as below (looks that inode size does not match disk inode's size, then trigger a bug()),
> 
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157139] (sapstart,15094,6):ocfs2_truncate_file:466 ERROR: bug expression: le64_to_cpu(fe->i_size) != i_size_read(inode)
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157148] (sapstart,15094,6):ocfs2_truncate_file:466 ERROR: Inode 293533, inode i_size = 853 != di i_size = 827, i_flags = 0x1
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157186] ------------[ cut here ]------------
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157197] kernel BUG at /usr/src/packages/BUILD/ocfs2-1.6/default/ocfs2/file.c:466!
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157204] invalid opcode: 0000 [#1] SMP
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157210] CPU 6
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157213] Modules linked in: af_packet ocfs2 jbd2 ocfs2_nodemanager quota_tree ocfs2_stack_user ocfs2_stackglue dlm sctp crc32c libcrc32c configfs hpwdt iTCO_wdt iTCO_vendor_support i6300esb ib700wdt advantechwdt acquirewdt pcwd_usb usbcore usb_common wdt_pci pcwd_pci autofs4 edd nfs lockd fscache auth_rpcgss nfs_acl sunrpc mperf microcode fuse loop dm_mod ppdev parport_pc parport floppy ipv6 ipv6_lib vmw_balloon(X) mptctl pciehp sg serio_raw intel_agp pcspkr vmxnet3 sr_mod intel_gtt cdrom shpchp rtc_cmos ac i2c_piix4 container i2c_core pci_hotplug button ext3 jbd mbcache sd_mod crc_t10dif processor thermal_sys hwmon scsi_dh_hp_sw scsi_dh_rdac scsi_dh_emc scsi_dh_alua scsi_dh ata_generic ata_piix libata mptspi mptscsih mptbase scsi_transport_spi scsi_mod
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157318] Supported: Yes, External
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157322]
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157327] Pid: 15094, comm: sapstart Tainted: G             X 3.0.101-0.47.52-default #1 VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157340] RIP: 0010:[<ffffffffa058cb85>]  [<ffffffffa058cb85>] ocfs2_truncate_file+0xa5/0x490 [ocfs2]
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157391] RSP: 0018:ffff88082a3b5b68  EFLAGS: 00010296
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157396] RAX: 000000000000008a RBX: ffff88085c0cc580 RCX: 0000000000005457
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157402] RDX: 0000000000000000 RSI: 0000000000000003 RDI: 0000000000000246
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157407] RBP: 1000000000000000 R08: ffffffff81d9fac0 R09: 0000000000000000
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157413] R10: 0000000000000003 R11: 00000000ffffffff R12: ffff8808ce63b4f8
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157419] R13: ffff88085c0ccbc8 R14: ffff8808f61ee000 R15: 0000000000000355
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157425] FS:  00007f66e8272720(0000) GS:ffff88123fc00000(0000) knlGS:0000000000000000
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157431] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157436] CR2: 00007fd0ac029000 CR3: 000000081cda6000 CR4: 00000000000407e0
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157501] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157539] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157545] Process sapstart (pid: 15094, threadinfo ffff88082a3b4000, task ffff88085c0cc580)
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157551] Stack:
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157554]  0000000000047a9d 0000000000000355 000000000000033b ffff880800000001
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157564]  ffff8808fb5ab748 ffff8812052d3000 ffff8808ce63b080 0000000000000000
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157572]  ffff8808fb7f2c00 0000000000000001 0000000000047a9d 000000000000000c
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157581] Call Trace:
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157666]  [<ffffffffa058f426>] ocfs2_setattr+0x276/0xa90 [ocfs2]
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157710]  [<ffffffff81177b6f>] notify_change+0x19f/0x2f0
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157724]  [<ffffffff8115c217>] do_truncate+0x57/0x80
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157737]  [<ffffffff8116abe3>] do_last+0x603/0x800
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157747]  [<ffffffff8116ba49>] path_openat+0xd9/0x420
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157757]  [<ffffffff8116becc>] do_filp_open+0x4c/0xc0
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157765]  [<ffffffff8115cb5f>] do_sys_open+0x17f/0x250
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157776]  [<ffffffff8146cb92>] system_call_fastpath+0x16/0x1b
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157795]  [<00007f66e7025790>] 0x7f66e702578f
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157799] Code: 6e 20 4d 8b bc 24 d0 00 00 00 49 39 ef 74 20 48 bd 00 00 00 00 00 00 00 10 48 85 2d 46 b8 f7 ff 74 09 48 85 2d 7d d7 f7 ff 74 74 <0f> 0b eb fe 49 39 ed 0f 86 6c 01 00 00 8b 05 30 b2 0a 00 85 c0
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157848] RIP  [<ffffffffa058cb85>] ocfs2_truncate_file+0xa5/0x490 [ocfs2]
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157879]  RSP <ffff88082a3b5b68>
> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157886] ---[ end trace fb7a3c1bdf30e68e ]---
> Jul 15 08:35:05 ruh1kepapp2 SAPInstance(ERS51)[14667]: INFO: SAP Instance KEP-ERS51 stopped:  15.07.2015 08:35:05 WaitforStopped OK
> Jul 15 08:35:05 ruh1kepapp2 crmd[4335]:   notice: process_lrm_event: LRM operation ERS51_stop_0 (call=105, rc=0, cib-update=492, confirmed=true) ok
> 
> Thanks
> Gang
> 
> .
> 

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [Ocfs2-devel] Do you know this issue? thanks
  2015-07-23  2:37 ` [Ocfs2-devel] Do you know this issue? thanks Joseph Qi
@ 2015-07-23  7:14   ` Gang He
  2015-08-03  9:28     ` Gang He
  0 siblings, 1 reply; 8+ messages in thread
From: Gang He @ 2015-07-23  7:14 UTC (permalink / raw)
  To: ocfs2-devel

Hi All,

From the message on node2 (before ocfs2 kernel panic), I found that the node2 just fenced the node1, next the node2 replayed the journal for the node1.
Maybe the journal replay process modified the related inode buffer, make the inode in memory not inconsitent with the inode disk buffer? 

The detailed log:
Jul 15 08:32:20 ruh1kepapp2 sbd: [13905]: info: Message successfully delivered.
Jul 15 08:32:21 ruh1kepapp2 stonith-ng[4331]:   notice: log_operation: Operation 'reboot' [13894] (call 3 from crmd.4335) for host 'ruh1kepapp1' with device 'stonith-sbd' returned: 0 (OK)
Jul 15 08:32:21 ruh1kepapp2 stonith-ng[4331]:   notice: remote_op_done: Operation reboot of ruh1kepapp1 by ruh1kepapp2 for crmd.4335 at ruh1kepapp2.77c17f26: OK
Jul 15 08:32:21 ruh1kepapp2 crmd[4335]:   notice: tengine_stonith_callback: Stonith operation 3/59:90:0:5868c9e9-69dd-46ee-a7dc-6caea229882d: OK (0)
Jul 15 08:32:21 ruh1kepapp2 crmd[4335]:   notice: tengine_stonith_notify: Peer ruh1kepapp1 was terminated (reboot) by ruh1kepapp2 for ruh1kepapp2: OK (ref=77c17f26-d1c6-4de8-94b3-842bf8ff71b5) by client crmd.4335
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: fence_node_time: Node 1084766062/ruh1kepapp1 was last shot 'now'
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 969E8438425C45E484D7AB283185E731 check_fencing 1084766062 done add 1436879638 fail 1436938320 last 1436938342
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 969E8438425C45E484D7AB283185E731 check_fencing done
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_quorum_done: 969E8438425C45E484D7AB283185E731 check_quorum disabled
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 969E8438425C45E484D7AB283185E731 check_fs nodeid 1084766062 clear
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 969E8438425C45E484D7AB283185E731 check_fs done
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: send_info: 969E8438425C45E484D7AB283185E731 send_start cg 3 flags 2 data2 0 counts 2 1 0 1 1
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: fence_node_time: Node 1084766062/ruh1kepapp1 was last shot 'now'
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 165E3E4A04FB4BC28C50684293325854 check_fencing 1084766062 done add 1436879638 fail 1436938320 last 1436938342
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 165E3E4A04FB4BC28C50684293325854 check_fencing done
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_quorum_done: 165E3E4A04FB4BC28C50684293325854 check_quorum disabled
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 165E3E4A04FB4BC28C50684293325854 check_fs nodeid 1084766062 clear
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 165E3E4A04FB4BC28C50684293325854 check_fs done
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: send_info: 165E3E4A04FB4BC28C50684293325854 send_start cg 3 flags 2 data2 0 counts 2 1 0 1 1
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: receive_start: 969E8438425C45E484D7AB283185E731 receive_start 1084766063:3 len 76
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: match_change: 969E8438425C45E484D7AB283185E731 match_change 1084766063:3 matches cg 3
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: wait_messages_done: 969E8438425C45E484D7AB283185E731 wait_messages cg 3 got all 1
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: start_kernel: 969E8438425C45E484D7AB283185E731 start_kernel cg 3 member_count 1
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 1084766062
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 1084766063
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: set_configfs_members: set_members rmdir "/sys/kernel/config/dlm/cluster/spaces/969E8438425C45E484D7AB283185E731/nodes/1084766062"
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: do_sysfs: write "1" to "/sys/kernel/dlm/969E8438425C45E484D7AB283185E731/control"
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: receive_start: 165E3E4A04FB4BC28C50684293325854 receive_start 1084766063:3 len 76
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: match_change: 165E3E4A04FB4BC28C50684293325854 match_change 1084766063:3 matches cg 3
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: wait_messages_done: 165E3E4A04FB4BC28C50684293325854 wait_messages cg 3 got all 1
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: start_kernel: 165E3E4A04FB4BC28C50684293325854 start_kernel cg 3 member_count 1
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 1084766062
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 1084766063
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: set_configfs_members: set_members rmdir "/sys/kernel/config/dlm/cluster/spaces/165E3E4A04FB4BC28C50684293325854/nodes/1084766062"
Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: do_sysfs: write "1" to "/sys/kernel/dlm/165E3E4A04FB4BC28C50684293325854/control"
Jul 15 08:32:22 ruh1kepapp2 kernel: [61880.467934] (ocfs2rec,13862,6):ocfs2_replay_journal:1549 Recovering node 1084766062 from slot 1 on device (8,49)
Jul 15 08:32:22 ruh1kepapp2 kernel: [61880.506685] (ocfs2rec,13861,9):ocfs2_replay_journal:1549 Recovering node 1084766062 from slot 1 on device (8,33)
Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.232721] (ocfs2rec,13862,0):ocfs2_begin_quota_recovery:407 Beginning quota recovery in slot 1
Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.380880] (ocfs2rec,13861,6):ocfs2_begin_quota_recovery:407 Beginning quota recovery in slot 1
Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.389531] (kworker/u:3,11960,0):ocfs2_finish_quota_recovery:599 Finishing quota recovery in slot 1
Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.392216] (kworker/u:3,11960,1):ocfs2_finish_quota_recovery:599 Finishing quota recovery in slot 1
Jul 15 08:32:25 ruh1kepapp2 SAPInstance(D60)[13863]: INFO: Stopping SAP Instance KEP-D60:  15.07.2015 08:32:25 Stop OK
Jul 15 08:32:53 ruh1kepapp2 SAPKEP_60[13261]: Q41 Monitoring: Snapshot 1 created

Thanks
Gang


>>> 
> I have never seen this bug.
> From the bug expression, it is caused by inode in memory and disk
> mismatch. Previously we found jbd2_journal_restart is not called
> correctly in ocfs2 and will cause inconsistent. I am not sure if it has
> relations.
> So could you check if there is any error occurred before (like storage
> link down)?
> 
> On 2015/7/22 15:56, Gang He wrote:
>> Hello Joseph and Junxiao,
>> 
>> I know you guys worked on OCFS2 for a few years.
>> Here, the customer reported a bug when they were running Pacemaker+OCFS2+SAP 
> application on SLES11SP3 two nodes.
>> But they did not provided the core dump file, or reproduce steps (seemed 
> that they encountered this issue two times occasionally), 
>> then I want to know if you saw the similar issue in the past, very thanks.
>> The panic backtrace is as below (looks that inode size does not match disk 
> inode's size, then trigger a bug()),
>> 
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157139] 
> (sapstart,15094,6):ocfs2_truncate_file:466 ERROR: bug expression: 
> le64_to_cpu(fe->i_size) != i_size_read(inode)
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157148] 
> (sapstart,15094,6):ocfs2_truncate_file:466 ERROR: Inode 293533, inode i_size 
> = 853 != di i_size = 827, i_flags = 0x1
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157186] ------------[ cut here ]------------
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157197] kernel BUG at 
> /usr/src/packages/BUILD/ocfs2-1.6/default/ocfs2/file.c:466!
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157204] invalid opcode: 0000 [#1] 
> SMP
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157210] CPU 6
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157213] Modules linked in: 
> af_packet ocfs2 jbd2 ocfs2_nodemanager quota_tree ocfs2_stack_user 
> ocfs2_stackglue dlm sctp crc32c libcrc32c configfs hpwdt iTCO_wdt 
> iTCO_vendor_support i6300esb ib700wdt advantechwdt acquirewdt pcwd_usb 
> usbcore usb_common wdt_pci pcwd_pci autofs4 edd nfs lockd fscache auth_rpcgss 
> nfs_acl sunrpc mperf microcode fuse loop dm_mod ppdev parport_pc parport 
> floppy ipv6 ipv6_lib vmw_balloon(X) mptctl pciehp sg serio_raw intel_agp 
> pcspkr vmxnet3 sr_mod intel_gtt cdrom shpchp rtc_cmos ac i2c_piix4 container 
> i2c_core pci_hotplug button ext3 jbd mbcache sd_mod crc_t10dif processor 
> thermal_sys hwmon scsi_dh_hp_sw scsi_dh_rdac scsi_dh_emc scsi_dh_alua scsi_dh 
> ata_generic ata_piix libata mptspi mptscsih mptbase scsi_transport_spi 
> scsi_mod
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157318] Supported: Yes, External
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157322]
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157327] Pid: 15094, comm: 
> sapstart Tainted: G             X 3.0.101-0.47.52-default #1 VMware, Inc. 
> VMware Virtual Platform/440BX Desktop Reference Platform
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157340] RIP: 
>0010:[<ffffffffa058cb85>]  [<ffffffffa058cb85>] ocfs2_truncate_file+0xa5/0x490 
> [ocfs2]
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157391] RSP: 
> 0018:ffff88082a3b5b68  EFLAGS: 00010296
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157396] RAX: 000000000000008a 
> RBX: ffff88085c0cc580 RCX: 0000000000005457
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157402] RDX: 0000000000000000 
> RSI: 0000000000000003 RDI: 0000000000000246
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157407] RBP: 1000000000000000 
> R08: ffffffff81d9fac0 R09: 0000000000000000
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157413] R10: 0000000000000003 
> R11: 00000000ffffffff R12: ffff8808ce63b4f8
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157419] R13: ffff88085c0ccbc8 
> R14: ffff8808f61ee000 R15: 0000000000000355
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157425] FS:  
> 00007f66e8272720(0000) GS:ffff88123fc00000(0000) knlGS:0000000000000000
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157431] CS:  0010 DS: 0000 ES: 
> 0000 CR0: 000000008005003b
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157436] CR2: 00007fd0ac029000 
> CR3: 000000081cda6000 CR4: 00000000000407e0
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157501] DR0: 0000000000000000 
> DR1: 0000000000000000 DR2: 0000000000000000
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157539] DR3: 0000000000000000 
> DR6: 00000000ffff0ff0 DR7: 0000000000000400
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157545] Process sapstart (pid: 
> 15094, threadinfo ffff88082a3b4000, task ffff88085c0cc580)
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157551] Stack:
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157554]  0000000000047a9d 
> 0000000000000355 000000000000033b ffff880800000001
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157564]  ffff8808fb5ab748 
> ffff8812052d3000 ffff8808ce63b080 0000000000000000
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157572]  ffff8808fb7f2c00 
> 0000000000000001 0000000000047a9d 000000000000000c
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157581] Call Trace:
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157666]  [<ffffffffa058f426>] 
> ocfs2_setattr+0x276/0xa90 [ocfs2]
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157710]  [<ffffffff81177b6f>] 
> notify_change+0x19f/0x2f0
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157724]  [<ffffffff8115c217>] 
> do_truncate+0x57/0x80
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157737]  [<ffffffff8116abe3>] 
> do_last+0x603/0x800
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157747]  [<ffffffff8116ba49>] 
> path_openat+0xd9/0x420
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157757]  [<ffffffff8116becc>] 
> do_filp_open+0x4c/0xc0
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157765]  [<ffffffff8115cb5f>] 
> do_sys_open+0x17f/0x250
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157776]  [<ffffffff8146cb92>] 
> system_call_fastpath+0x16/0x1b
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157795]  [<00007f66e7025790>] 
> 0x7f66e702578f
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157799] Code: 6e 20 4d 8b bc 24 
> d0 00 00 00 49 39 ef 74 20 48 bd 00 00 00 00 00 00 00 10 48 85 2d 46 b8 f7 ff 
> 74 09 48 85 2d 7d d7 f7 ff 74 74 <0f> 0b eb fe 49 39 ed 0f 86 6c 01 00 00 8b 05 
> 30 b2 0a 00 85 c0
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157848] RIP  [<ffffffffa058cb85>] 
> ocfs2_truncate_file+0xa5/0x490 [ocfs2]
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157879]  RSP <ffff88082a3b5b68>
>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157886] ---[ end trace 
> fb7a3c1bdf30e68e ]---
>> Jul 15 08:35:05 ruh1kepapp2 SAPInstance(ERS51)[14667]: INFO: SAP Instance 
> KEP-ERS51 stopped:  15.07.2015 08:35:05 WaitforStopped OK
>> Jul 15 08:35:05 ruh1kepapp2 crmd[4335]:   notice: process_lrm_event: LRM 
> operation ERS51_stop_0 (call=105, rc=0, cib-update=492, confirmed=true) ok
>> 
>> Thanks
>> Gang
>> 
>> .
>> 

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [Ocfs2-devel] Do you know this issue? thanks
  2015-07-23  7:14   ` Gang He
@ 2015-08-03  9:28     ` Gang He
  2015-08-03 10:21       ` Joseph Qi
  0 siblings, 1 reply; 8+ messages in thread
From: Gang He @ 2015-08-03  9:28 UTC (permalink / raw)
  To: ocfs2-devel

Hello guys,

I went through OCFS2 journal and JBD2 code, I just have one question as below,
If there are some nodes which are running, one node (node A) suddenly crashes, one another node (node B) will recover node A's journal records. But here looks a problem, if node B ever changed one file, and node A also changed this same file, then node B will replay these changed meta buffers, JBD2 recovery code will memcpy the journal meta buffer to the node B's memory, this inode's meta buffer will be replaced by node A's journal record, but this inode structure in memory will not be reflected, this will cause this kind of issue? I feel that my guess should be wrong, since this problem looks too obvious, but who can help to figure out how to solve this problem when a running node try to recover a crashed node's journal.


Thanks
Gang 


>>> 
> Hi All,
> 
>>From the message on node2 (before ocfs2 kernel panic), I found that the node2 
> just fenced the node1, next the node2 replayed the journal for the node1.
> Maybe the journal replay process modified the related inode buffer, make the 
> inode in memory not inconsitent with the inode disk buffer? 
> 
> The detailed log:
> Jul 15 08:32:20 ruh1kepapp2 sbd: [13905]: info: Message successfully 
> delivered.
> Jul 15 08:32:21 ruh1kepapp2 stonith-ng[4331]:   notice: log_operation: 
> Operation 'reboot' [13894] (call 3 from crmd.4335) for host 'ruh1kepapp1' 
> with device 'stonith-sbd' returned: 0 (OK)
> Jul 15 08:32:21 ruh1kepapp2 stonith-ng[4331]:   notice: remote_op_done: 
> Operation reboot of ruh1kepapp1 by ruh1kepapp2 for 
> crmd.4335 at ruh1kepapp2.77c17f26: OK
> Jul 15 08:32:21 ruh1kepapp2 crmd[4335]:   notice: tengine_stonith_callback: 
> Stonith operation 3/59:90:0:5868c9e9-69dd-46ee-a7dc-6caea229882d: OK (0)
> Jul 15 08:32:21 ruh1kepapp2 crmd[4335]:   notice: tengine_stonith_notify: 
> Peer ruh1kepapp1 was terminated (reboot) by ruh1kepapp2 for ruh1kepapp2: OK 
> (ref=77c17f26-d1c6-4de8-94b3-842bf8ff71b5) by client crmd.4335
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: fence_node_time: Node 
> 1084766062/ruh1kepapp1 was last shot 'now'
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
> 969E8438425C45E484D7AB283185E731 check_fencing 1084766062 done add 1436879638 
> fail 1436938320 last 1436938342
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
> 969E8438425C45E484D7AB283185E731 check_fencing done
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_quorum_done: 
> 969E8438425C45E484D7AB283185E731 check_quorum disabled
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
> 969E8438425C45E484D7AB283185E731 check_fs nodeid 1084766062 clear
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
> 969E8438425C45E484D7AB283185E731 check_fs done
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: send_info: 
> 969E8438425C45E484D7AB283185E731 send_start cg 3 flags 2 data2 0 counts 2 1 0 
> 1 1
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: fence_node_time: Node 
> 1084766062/ruh1kepapp1 was last shot 'now'
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
> 165E3E4A04FB4BC28C50684293325854 check_fencing 1084766062 done add 1436879638 
> fail 1436938320 last 1436938342
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
> 165E3E4A04FB4BC28C50684293325854 check_fencing done
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_quorum_done: 
> 165E3E4A04FB4BC28C50684293325854 check_quorum disabled
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
> 165E3E4A04FB4BC28C50684293325854 check_fs nodeid 1084766062 clear
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
> 165E3E4A04FB4BC28C50684293325854 check_fs done
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: send_info: 
> 165E3E4A04FB4BC28C50684293325854 send_start cg 3 flags 2 data2 0 counts 2 1 0 
> 1 1
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: receive_start: 
> 969E8438425C45E484D7AB283185E731 receive_start 1084766063:3 len 76
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: match_change: 
> 969E8438425C45E484D7AB283185E731 match_change 1084766063:3 matches cg 3
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: wait_messages_done: 
> 969E8438425C45E484D7AB283185E731 wait_messages cg 3 got all 1
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: start_kernel: 
> 969E8438425C45E484D7AB283185E731 start_kernel cg 3 member_count 1
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
> 1084766062
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
> 1084766063
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: set_configfs_members: 
> set_members rmdir 
> "/sys/kernel/config/dlm/cluster/spaces/969E8438425C45E484D7AB283185E731/nodes
> /1084766062"
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: do_sysfs: write "1" to 
> "/sys/kernel/dlm/969E8438425C45E484D7AB283185E731/control"
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: receive_start: 
> 165E3E4A04FB4BC28C50684293325854 receive_start 1084766063:3 len 76
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: match_change: 
> 165E3E4A04FB4BC28C50684293325854 match_change 1084766063:3 matches cg 3
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: wait_messages_done: 
> 165E3E4A04FB4BC28C50684293325854 wait_messages cg 3 got all 1
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: start_kernel: 
> 165E3E4A04FB4BC28C50684293325854 start_kernel cg 3 member_count 1
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
> 1084766062
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
> 1084766063
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: set_configfs_members: 
> set_members rmdir 
> "/sys/kernel/config/dlm/cluster/spaces/165E3E4A04FB4BC28C50684293325854/nodes
> /1084766062"
> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: do_sysfs: write "1" to 
> "/sys/kernel/dlm/165E3E4A04FB4BC28C50684293325854/control"
> Jul 15 08:32:22 ruh1kepapp2 kernel: [61880.467934] 
> (ocfs2rec,13862,6):ocfs2_replay_journal:1549 Recovering node 1084766062 from 
> slot 1 on device (8,49)
> Jul 15 08:32:22 ruh1kepapp2 kernel: [61880.506685] 
> (ocfs2rec,13861,9):ocfs2_replay_journal:1549 Recovering node 1084766062 from 
> slot 1 on device (8,33)
> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.232721] 
> (ocfs2rec,13862,0):ocfs2_begin_quota_recovery:407 Beginning quota recovery in 
> slot 1
> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.380880] 
> (ocfs2rec,13861,6):ocfs2_begin_quota_recovery:407 Beginning quota recovery in 
> slot 1
> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.389531] 
> (kworker/u:3,11960,0):ocfs2_finish_quota_recovery:599 Finishing quota 
> recovery in slot 1
> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.392216] 
> (kworker/u:3,11960,1):ocfs2_finish_quota_recovery:599 Finishing quota 
> recovery in slot 1
> Jul 15 08:32:25 ruh1kepapp2 SAPInstance(D60)[13863]: INFO: Stopping SAP 
> Instance KEP-D60:  15.07.2015 08:32:25 Stop OK
> Jul 15 08:32:53 ruh1kepapp2 SAPKEP_60[13261]: Q41 Monitoring: Snapshot 1 
> created
> 
> Thanks
> Gang
> 
> 
>>>> 
>> I have never seen this bug.
>> From the bug expression, it is caused by inode in memory and disk
>> mismatch. Previously we found jbd2_journal_restart is not called
>> correctly in ocfs2 and will cause inconsistent. I am not sure if it has
>> relations.
>> So could you check if there is any error occurred before (like storage
>> link down)?
>> 
>> On 2015/7/22 15:56, Gang He wrote:
>>> Hello Joseph and Junxiao,
>>> 
>>> I know you guys worked on OCFS2 for a few years.
>>> Here, the customer reported a bug when they were running Pacemaker+OCFS2+SAP 
> 
>> application on SLES11SP3 two nodes.
>>> But they did not provided the core dump file, or reproduce steps (seemed 
>> that they encountered this issue two times occasionally), 
>>> then I want to know if you saw the similar issue in the past, very thanks.
>>> The panic backtrace is as below (looks that inode size does not match disk 
>> inode's size, then trigger a bug()),
>>> 
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157139] 
>> (sapstart,15094,6):ocfs2_truncate_file:466 ERROR: bug expression: 
>> le64_to_cpu(fe->i_size) != i_size_read(inode)
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157148] 
>> (sapstart,15094,6):ocfs2_truncate_file:466 ERROR: Inode 293533, inode i_size 
> 
>> = 853 != di i_size = 827, i_flags = 0x1
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157186] ------------[ cut here ]------------
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157197] kernel BUG at 
>> /usr/src/packages/BUILD/ocfs2-1.6/default/ocfs2/file.c:466!
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157204] invalid opcode: 0000 [#1] 
> 
>> SMP
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157210] CPU 6
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157213] Modules linked in: 
>> af_packet ocfs2 jbd2 ocfs2_nodemanager quota_tree ocfs2_stack_user 
>> ocfs2_stackglue dlm sctp crc32c libcrc32c configfs hpwdt iTCO_wdt 
>> iTCO_vendor_support i6300esb ib700wdt advantechwdt acquirewdt pcwd_usb 
>> usbcore usb_common wdt_pci pcwd_pci autofs4 edd nfs lockd fscache 
> auth_rpcgss 
>> nfs_acl sunrpc mperf microcode fuse loop dm_mod ppdev parport_pc parport 
>> floppy ipv6 ipv6_lib vmw_balloon(X) mptctl pciehp sg serio_raw intel_agp 
>> pcspkr vmxnet3 sr_mod intel_gtt cdrom shpchp rtc_cmos ac i2c_piix4 container 
> 
>> i2c_core pci_hotplug button ext3 jbd mbcache sd_mod crc_t10dif processor 
>> thermal_sys hwmon scsi_dh_hp_sw scsi_dh_rdac scsi_dh_emc scsi_dh_alua 
> scsi_dh 
>> ata_generic ata_piix libata mptspi mptscsih mptbase scsi_transport_spi 
>> scsi_mod
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157318] Supported: Yes, External
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157322]
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157327] Pid: 15094, comm: 
>> sapstart Tainted: G             X 3.0.101-0.47.52-default #1 VMware, Inc. 
>> VMware Virtual Platform/440BX Desktop Reference Platform
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157340] RIP: 
>>0010:[<ffffffffa058cb85>]  [<ffffffffa058cb85>] ocfs2_truncate_file+0xa5/0x490 
>> [ocfs2]
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157391] RSP: 
>> 0018:ffff88082a3b5b68  EFLAGS: 00010296
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157396] RAX: 000000000000008a 
>> RBX: ffff88085c0cc580 RCX: 0000000000005457
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157402] RDX: 0000000000000000 
>> RSI: 0000000000000003 RDI: 0000000000000246
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157407] RBP: 1000000000000000 
>> R08: ffffffff81d9fac0 R09: 0000000000000000
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157413] R10: 0000000000000003 
>> R11: 00000000ffffffff R12: ffff8808ce63b4f8
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157419] R13: ffff88085c0ccbc8 
>> R14: ffff8808f61ee000 R15: 0000000000000355
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157425] FS:  
>> 00007f66e8272720(0000) GS:ffff88123fc00000(0000) knlGS:0000000000000000
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157431] CS:  0010 DS: 0000 ES: 
>> 0000 CR0: 000000008005003b
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157436] CR2: 00007fd0ac029000 
>> CR3: 000000081cda6000 CR4: 00000000000407e0
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157501] DR0: 0000000000000000 
>> DR1: 0000000000000000 DR2: 0000000000000000
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157539] DR3: 0000000000000000 
>> DR6: 00000000ffff0ff0 DR7: 0000000000000400
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157545] Process sapstart (pid: 
>> 15094, threadinfo ffff88082a3b4000, task ffff88085c0cc580)
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157551] Stack:
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157554]  0000000000047a9d 
>> 0000000000000355 000000000000033b ffff880800000001
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157564]  ffff8808fb5ab748 
>> ffff8812052d3000 ffff8808ce63b080 0000000000000000
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157572]  ffff8808fb7f2c00 
>> 0000000000000001 0000000000047a9d 000000000000000c
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157581] Call Trace:
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157666]  [<ffffffffa058f426>] 
>> ocfs2_setattr+0x276/0xa90 [ocfs2]
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157710]  [<ffffffff81177b6f>] 
>> notify_change+0x19f/0x2f0
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157724]  [<ffffffff8115c217>] 
>> do_truncate+0x57/0x80
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157737]  [<ffffffff8116abe3>] 
>> do_last+0x603/0x800
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157747]  [<ffffffff8116ba49>] 
>> path_openat+0xd9/0x420
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157757]  [<ffffffff8116becc>] 
>> do_filp_open+0x4c/0xc0
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157765]  [<ffffffff8115cb5f>] 
>> do_sys_open+0x17f/0x250
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157776]  [<ffffffff8146cb92>] 
>> system_call_fastpath+0x16/0x1b
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157795]  [<00007f66e7025790>] 
>> 0x7f66e702578f
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157799] Code: 6e 20 4d 8b bc 24 
>> d0 00 00 00 49 39 ef 74 20 48 bd 00 00 00 00 00 00 00 10 48 85 2d 46 b8 f7 
> ff 
>> 74 09 48 85 2d 7d d7 f7 ff 74 74 <0f> 0b eb fe 49 39 ed 0f 86 6c 01 00 00 8b 
> 05 
>> 30 b2 0a 00 85 c0
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157848] RIP  [<ffffffffa058cb85>] 
>> ocfs2_truncate_file+0xa5/0x490 [ocfs2]
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157879]  RSP <ffff88082a3b5b68>
>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157886] ---[ end trace 
>> fb7a3c1bdf30e68e ]---
>>> Jul 15 08:35:05 ruh1kepapp2 SAPInstance(ERS51)[14667]: INFO: SAP Instance 
>> KEP-ERS51 stopped:  15.07.2015 08:35:05 WaitforStopped OK
>>> Jul 15 08:35:05 ruh1kepapp2 crmd[4335]:   notice: process_lrm_event: LRM 
>> operation ERS51_stop_0 (call=105, rc=0, cib-update=492, confirmed=true) ok
>>> 
>>> Thanks
>>> Gang
>>> 
>>> .
>>> 
> 
> _______________________________________________
> Ocfs2-devel mailing list
> Ocfs2-devel at oss.oracle.com 
> https://oss.oracle.com/mailman/listinfo/ocfs2-devel

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [Ocfs2-devel] Do you know this issue? thanks
  2015-08-03  9:28     ` Gang He
@ 2015-08-03 10:21       ` Joseph Qi
  2015-08-04  3:21         ` Gang He
  0 siblings, 1 reply; 8+ messages in thread
From: Joseph Qi @ 2015-08-03 10:21 UTC (permalink / raw)
  To: ocfs2-devel

Hi Gang,
On 2015/8/3 17:28, Gang He wrote:
> Hello guys,
> 
> I went through OCFS2 journal and JBD2 code, I just have one question as below,
> If there are some nodes which are running, one node (node A) suddenly crashes, one another node (node B) will recover node A's journal records. But here looks a problem, if node B ever changed one file, and node A also changed this same file, then node B will replay these changed meta buffers, JBD2 recovery code will memcpy the journal meta buffer to the node B's memory, this inode's meta buffer will be replaced by node A's journal record, but this inode structure in memory will not be reflected, this will cause this kind of issue? I feel that my guess should be wrong, since this problem looks too obvious, but who can help to figure out how to solve this problem when a running node try to recover a crashed node's journal.
> 
Please note that nodes can update the same inode only after it has got
the cluster lock. And if the lock level is not compatible, it will
downcovert first, which will do the checkpoint.
So I don't think the issue you described really exists.

Thanks
Joseph
> 
> Thanks
> Gang 
> 
> 
>>>>
>> Hi All,
>>
>> >From the message on node2 (before ocfs2 kernel panic), I found that the node2 
>> just fenced the node1, next the node2 replayed the journal for the node1.
>> Maybe the journal replay process modified the related inode buffer, make the 
>> inode in memory not inconsitent with the inode disk buffer? 
>>
>> The detailed log:
>> Jul 15 08:32:20 ruh1kepapp2 sbd: [13905]: info: Message successfully 
>> delivered.
>> Jul 15 08:32:21 ruh1kepapp2 stonith-ng[4331]:   notice: log_operation: 
>> Operation 'reboot' [13894] (call 3 from crmd.4335) for host 'ruh1kepapp1' 
>> with device 'stonith-sbd' returned: 0 (OK)
>> Jul 15 08:32:21 ruh1kepapp2 stonith-ng[4331]:   notice: remote_op_done: 
>> Operation reboot of ruh1kepapp1 by ruh1kepapp2 for 
>> crmd.4335 at ruh1kepapp2.77c17f26: OK
>> Jul 15 08:32:21 ruh1kepapp2 crmd[4335]:   notice: tengine_stonith_callback: 
>> Stonith operation 3/59:90:0:5868c9e9-69dd-46ee-a7dc-6caea229882d: OK (0)
>> Jul 15 08:32:21 ruh1kepapp2 crmd[4335]:   notice: tengine_stonith_notify: 
>> Peer ruh1kepapp1 was terminated (reboot) by ruh1kepapp2 for ruh1kepapp2: OK 
>> (ref=77c17f26-d1c6-4de8-94b3-842bf8ff71b5) by client crmd.4335
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: fence_node_time: Node 
>> 1084766062/ruh1kepapp1 was last shot 'now'
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
>> 969E8438425C45E484D7AB283185E731 check_fencing 1084766062 done add 1436879638 
>> fail 1436938320 last 1436938342
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
>> 969E8438425C45E484D7AB283185E731 check_fencing done
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_quorum_done: 
>> 969E8438425C45E484D7AB283185E731 check_quorum disabled
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
>> 969E8438425C45E484D7AB283185E731 check_fs nodeid 1084766062 clear
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
>> 969E8438425C45E484D7AB283185E731 check_fs done
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: send_info: 
>> 969E8438425C45E484D7AB283185E731 send_start cg 3 flags 2 data2 0 counts 2 1 0 
>> 1 1
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: fence_node_time: Node 
>> 1084766062/ruh1kepapp1 was last shot 'now'
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
>> 165E3E4A04FB4BC28C50684293325854 check_fencing 1084766062 done add 1436879638 
>> fail 1436938320 last 1436938342
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
>> 165E3E4A04FB4BC28C50684293325854 check_fencing done
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_quorum_done: 
>> 165E3E4A04FB4BC28C50684293325854 check_quorum disabled
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
>> 165E3E4A04FB4BC28C50684293325854 check_fs nodeid 1084766062 clear
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
>> 165E3E4A04FB4BC28C50684293325854 check_fs done
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: send_info: 
>> 165E3E4A04FB4BC28C50684293325854 send_start cg 3 flags 2 data2 0 counts 2 1 0 
>> 1 1
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: receive_start: 
>> 969E8438425C45E484D7AB283185E731 receive_start 1084766063:3 len 76
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: match_change: 
>> 969E8438425C45E484D7AB283185E731 match_change 1084766063:3 matches cg 3
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: wait_messages_done: 
>> 969E8438425C45E484D7AB283185E731 wait_messages cg 3 got all 1
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: start_kernel: 
>> 969E8438425C45E484D7AB283185E731 start_kernel cg 3 member_count 1
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
>> 1084766062
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
>> 1084766063
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: set_configfs_members: 
>> set_members rmdir 
>> "/sys/kernel/config/dlm/cluster/spaces/969E8438425C45E484D7AB283185E731/nodes
>> /1084766062"
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: do_sysfs: write "1" to 
>> "/sys/kernel/dlm/969E8438425C45E484D7AB283185E731/control"
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: receive_start: 
>> 165E3E4A04FB4BC28C50684293325854 receive_start 1084766063:3 len 76
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: match_change: 
>> 165E3E4A04FB4BC28C50684293325854 match_change 1084766063:3 matches cg 3
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: wait_messages_done: 
>> 165E3E4A04FB4BC28C50684293325854 wait_messages cg 3 got all 1
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: start_kernel: 
>> 165E3E4A04FB4BC28C50684293325854 start_kernel cg 3 member_count 1
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
>> 1084766062
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
>> 1084766063
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: set_configfs_members: 
>> set_members rmdir 
>> "/sys/kernel/config/dlm/cluster/spaces/165E3E4A04FB4BC28C50684293325854/nodes
>> /1084766062"
>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: do_sysfs: write "1" to 
>> "/sys/kernel/dlm/165E3E4A04FB4BC28C50684293325854/control"
>> Jul 15 08:32:22 ruh1kepapp2 kernel: [61880.467934] 
>> (ocfs2rec,13862,6):ocfs2_replay_journal:1549 Recovering node 1084766062 from 
>> slot 1 on device (8,49)
>> Jul 15 08:32:22 ruh1kepapp2 kernel: [61880.506685] 
>> (ocfs2rec,13861,9):ocfs2_replay_journal:1549 Recovering node 1084766062 from 
>> slot 1 on device (8,33)
>> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.232721] 
>> (ocfs2rec,13862,0):ocfs2_begin_quota_recovery:407 Beginning quota recovery in 
>> slot 1
>> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.380880] 
>> (ocfs2rec,13861,6):ocfs2_begin_quota_recovery:407 Beginning quota recovery in 
>> slot 1
>> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.389531] 
>> (kworker/u:3,11960,0):ocfs2_finish_quota_recovery:599 Finishing quota 
>> recovery in slot 1
>> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.392216] 
>> (kworker/u:3,11960,1):ocfs2_finish_quota_recovery:599 Finishing quota 
>> recovery in slot 1
>> Jul 15 08:32:25 ruh1kepapp2 SAPInstance(D60)[13863]: INFO: Stopping SAP 
>> Instance KEP-D60:  15.07.2015 08:32:25 Stop OK
>> Jul 15 08:32:53 ruh1kepapp2 SAPKEP_60[13261]: Q41 Monitoring: Snapshot 1 
>> created
>>
>> Thanks
>> Gang
>>
>>
>>>>>
>>> I have never seen this bug.
>>> From the bug expression, it is caused by inode in memory and disk
>>> mismatch. Previously we found jbd2_journal_restart is not called
>>> correctly in ocfs2 and will cause inconsistent. I am not sure if it has
>>> relations.
>>> So could you check if there is any error occurred before (like storage
>>> link down)?
>>>
>>> On 2015/7/22 15:56, Gang He wrote:
>>>> Hello Joseph and Junxiao,
>>>>
>>>> I know you guys worked on OCFS2 for a few years.
>>>> Here, the customer reported a bug when they were running Pacemaker+OCFS2+SAP 
>>
>>> application on SLES11SP3 two nodes.
>>>> But they did not provided the core dump file, or reproduce steps (seemed 
>>> that they encountered this issue two times occasionally), 
>>>> then I want to know if you saw the similar issue in the past, very thanks.
>>>> The panic backtrace is as below (looks that inode size does not match disk 
>>> inode's size, then trigger a bug()),
>>>>
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157139] 
>>> (sapstart,15094,6):ocfs2_truncate_file:466 ERROR: bug expression: 
>>> le64_to_cpu(fe->i_size) != i_size_read(inode)
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157148] 
>>> (sapstart,15094,6):ocfs2_truncate_file:466 ERROR: Inode 293533, inode i_size 
>>
>>> = 853 != di i_size = 827, i_flags = 0x1
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157186] ------------[ cut here ]------------
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157197] kernel BUG at 
>>> /usr/src/packages/BUILD/ocfs2-1.6/default/ocfs2/file.c:466!
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157204] invalid opcode: 0000 [#1] 
>>
>>> SMP
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157210] CPU 6
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157213] Modules linked in: 
>>> af_packet ocfs2 jbd2 ocfs2_nodemanager quota_tree ocfs2_stack_user 
>>> ocfs2_stackglue dlm sctp crc32c libcrc32c configfs hpwdt iTCO_wdt 
>>> iTCO_vendor_support i6300esb ib700wdt advantechwdt acquirewdt pcwd_usb 
>>> usbcore usb_common wdt_pci pcwd_pci autofs4 edd nfs lockd fscache 
>> auth_rpcgss 
>>> nfs_acl sunrpc mperf microcode fuse loop dm_mod ppdev parport_pc parport 
>>> floppy ipv6 ipv6_lib vmw_balloon(X) mptctl pciehp sg serio_raw intel_agp 
>>> pcspkr vmxnet3 sr_mod intel_gtt cdrom shpchp rtc_cmos ac i2c_piix4 container 
>>
>>> i2c_core pci_hotplug button ext3 jbd mbcache sd_mod crc_t10dif processor 
>>> thermal_sys hwmon scsi_dh_hp_sw scsi_dh_rdac scsi_dh_emc scsi_dh_alua 
>> scsi_dh 
>>> ata_generic ata_piix libata mptspi mptscsih mptbase scsi_transport_spi 
>>> scsi_mod
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157318] Supported: Yes, External
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157322]
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157327] Pid: 15094, comm: 
>>> sapstart Tainted: G             X 3.0.101-0.47.52-default #1 VMware, Inc. 
>>> VMware Virtual Platform/440BX Desktop Reference Platform
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157340] RIP: 
>>> 0010:[<ffffffffa058cb85>]  [<ffffffffa058cb85>] ocfs2_truncate_file+0xa5/0x490 
>>> [ocfs2]
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157391] RSP: 
>>> 0018:ffff88082a3b5b68  EFLAGS: 00010296
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157396] RAX: 000000000000008a 
>>> RBX: ffff88085c0cc580 RCX: 0000000000005457
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157402] RDX: 0000000000000000 
>>> RSI: 0000000000000003 RDI: 0000000000000246
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157407] RBP: 1000000000000000 
>>> R08: ffffffff81d9fac0 R09: 0000000000000000
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157413] R10: 0000000000000003 
>>> R11: 00000000ffffffff R12: ffff8808ce63b4f8
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157419] R13: ffff88085c0ccbc8 
>>> R14: ffff8808f61ee000 R15: 0000000000000355
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157425] FS:  
>>> 00007f66e8272720(0000) GS:ffff88123fc00000(0000) knlGS:0000000000000000
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157431] CS:  0010 DS: 0000 ES: 
>>> 0000 CR0: 000000008005003b
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157436] CR2: 00007fd0ac029000 
>>> CR3: 000000081cda6000 CR4: 00000000000407e0
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157501] DR0: 0000000000000000 
>>> DR1: 0000000000000000 DR2: 0000000000000000
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157539] DR3: 0000000000000000 
>>> DR6: 00000000ffff0ff0 DR7: 0000000000000400
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157545] Process sapstart (pid: 
>>> 15094, threadinfo ffff88082a3b4000, task ffff88085c0cc580)
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157551] Stack:
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157554]  0000000000047a9d 
>>> 0000000000000355 000000000000033b ffff880800000001
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157564]  ffff8808fb5ab748 
>>> ffff8812052d3000 ffff8808ce63b080 0000000000000000
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157572]  ffff8808fb7f2c00 
>>> 0000000000000001 0000000000047a9d 000000000000000c
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157581] Call Trace:
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157666]  [<ffffffffa058f426>] 
>>> ocfs2_setattr+0x276/0xa90 [ocfs2]
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157710]  [<ffffffff81177b6f>] 
>>> notify_change+0x19f/0x2f0
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157724]  [<ffffffff8115c217>] 
>>> do_truncate+0x57/0x80
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157737]  [<ffffffff8116abe3>] 
>>> do_last+0x603/0x800
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157747]  [<ffffffff8116ba49>] 
>>> path_openat+0xd9/0x420
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157757]  [<ffffffff8116becc>] 
>>> do_filp_open+0x4c/0xc0
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157765]  [<ffffffff8115cb5f>] 
>>> do_sys_open+0x17f/0x250
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157776]  [<ffffffff8146cb92>] 
>>> system_call_fastpath+0x16/0x1b
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157795]  [<00007f66e7025790>] 
>>> 0x7f66e702578f
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157799] Code: 6e 20 4d 8b bc 24 
>>> d0 00 00 00 49 39 ef 74 20 48 bd 00 00 00 00 00 00 00 10 48 85 2d 46 b8 f7 
>> ff 
>>> 74 09 48 85 2d 7d d7 f7 ff 74 74 <0f> 0b eb fe 49 39 ed 0f 86 6c 01 00 00 8b 
>> 05 
>>> 30 b2 0a 00 85 c0
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157848] RIP  [<ffffffffa058cb85>] 
>>> ocfs2_truncate_file+0xa5/0x490 [ocfs2]
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157879]  RSP <ffff88082a3b5b68>
>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157886] ---[ end trace 
>>> fb7a3c1bdf30e68e ]---
>>>> Jul 15 08:35:05 ruh1kepapp2 SAPInstance(ERS51)[14667]: INFO: SAP Instance 
>>> KEP-ERS51 stopped:  15.07.2015 08:35:05 WaitforStopped OK
>>>> Jul 15 08:35:05 ruh1kepapp2 crmd[4335]:   notice: process_lrm_event: LRM 
>>> operation ERS51_stop_0 (call=105, rc=0, cib-update=492, confirmed=true) ok
>>>>
>>>> Thanks
>>>> Gang
>>>>
>>>> .
>>>>
>>
>> _______________________________________________
>> Ocfs2-devel mailing list
>> Ocfs2-devel at oss.oracle.com 
>> https://oss.oracle.com/mailman/listinfo/ocfs2-devel
> 
> .
> 

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [Ocfs2-devel] Do you know this issue? thanks
  2015-08-03 10:21       ` Joseph Qi
@ 2015-08-04  3:21         ` Gang He
  2015-08-04  9:13           ` Joseph Qi
  0 siblings, 1 reply; 8+ messages in thread
From: Gang He @ 2015-08-04  3:21 UTC (permalink / raw)
  To: ocfs2-devel

Hi Joseph,

Thank for your good explaining, have more one question.


>>> 
> Hi Gang,
> On 2015/8/3 17:28, Gang He wrote:
>> Hello guys,
>> 
>> I went through OCFS2 journal and JBD2 code, I just have one question as 
> below,
>> If there are some nodes which are running, one node (node A) suddenly 
> crashes, one another node (node B) will recover node A's journal records. But 
> here looks a problem, if node B ever changed one file, and node A also 
> changed this same file, then node B will replay these changed meta buffers, 
> JBD2 recovery code will memcpy the journal meta buffer to the node B's 
> memory, this inode's meta buffer will be replaced by node A's journal record, 
> but this inode structure in memory will not be reflected, this will cause 
> this kind of issue? I feel that my guess should be wrong, since this problem 
> looks too obvious, but who can help to figure out how to solve this problem 
> when a running node try to recover a crashed node's journal.
>> 
> Please note that nodes can update the same inode only after it has got
> the cluster lock. And if the lock level is not compatible, it will
> downcovert first, which will do the checkpoint.
> So I don't think the issue you described really exists.
You means, if Node A try to change the same file when Node B is changing (or just changed) this file, it must wait until Node B finishes the checkpoint for these meta buffers,
then, Node A will re-read these meta buffers from the shared disk and gets the lock, my understanding is right? if yes, how the inode meta buffer reflect the inode structure in the memory?
There is a case, if Node A ever read a file, then Node B changes the same file and write the journal records to the log file (the meta buffers are not flushed to the file system) and crashes, at this moment, Node A is replaying the journal records and a user is trying to access/change this file, what will happen? the memory inode will be inconsistent with just recovered meta buffer? looks a little complicated.

Thanks
Gang   
 

> 
> Thanks
> Joseph
>> 
>> Thanks
>> Gang 
>> 
>> 
>>>>>
>>> Hi All,
>>>
>>> >From the message on node2 (before ocfs2 kernel panic), I found that the 
> node2 
>>> just fenced the node1, next the node2 replayed the journal for the node1.
>>> Maybe the journal replay process modified the related inode buffer, make the 
> 
>>> inode in memory not inconsitent with the inode disk buffer? 
>>>
>>> The detailed log:
>>> Jul 15 08:32:20 ruh1kepapp2 sbd: [13905]: info: Message successfully 
>>> delivered.
>>> Jul 15 08:32:21 ruh1kepapp2 stonith-ng[4331]:   notice: log_operation: 
>>> Operation 'reboot' [13894] (call 3 from crmd.4335) for host 'ruh1kepapp1' 
>>> with device 'stonith-sbd' returned: 0 (OK)
>>> Jul 15 08:32:21 ruh1kepapp2 stonith-ng[4331]:   notice: remote_op_done: 
>>> Operation reboot of ruh1kepapp1 by ruh1kepapp2 for 
>>> crmd.4335 at ruh1kepapp2.77c17f26: OK
>>> Jul 15 08:32:21 ruh1kepapp2 crmd[4335]:   notice: tengine_stonith_callback: 
>>> Stonith operation 3/59:90:0:5868c9e9-69dd-46ee-a7dc-6caea229882d: OK (0)
>>> Jul 15 08:32:21 ruh1kepapp2 crmd[4335]:   notice: tengine_stonith_notify: 
>>> Peer ruh1kepapp1 was terminated (reboot) by ruh1kepapp2 for ruh1kepapp2: OK 
>>> (ref=77c17f26-d1c6-4de8-94b3-842bf8ff71b5) by client crmd.4335
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: fence_node_time: Node 
>>> 1084766062/ruh1kepapp1 was last shot 'now'
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
>>> 969E8438425C45E484D7AB283185E731 check_fencing 1084766062 done add 
> 1436879638 
>>> fail 1436938320 last 1436938342
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
>>> 969E8438425C45E484D7AB283185E731 check_fencing done
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_quorum_done: 
>>> 969E8438425C45E484D7AB283185E731 check_quorum disabled
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
>>> 969E8438425C45E484D7AB283185E731 check_fs nodeid 1084766062 clear
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
>>> 969E8438425C45E484D7AB283185E731 check_fs done
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: send_info: 
>>> 969E8438425C45E484D7AB283185E731 send_start cg 3 flags 2 data2 0 counts 2 1 
> 0 
>>> 1 1
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: fence_node_time: Node 
>>> 1084766062/ruh1kepapp1 was last shot 'now'
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
>>> 165E3E4A04FB4BC28C50684293325854 check_fencing 1084766062 done add 
> 1436879638 
>>> fail 1436938320 last 1436938342
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fencing_done: 
>>> 165E3E4A04FB4BC28C50684293325854 check_fencing done
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_quorum_done: 
>>> 165E3E4A04FB4BC28C50684293325854 check_quorum disabled
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
>>> 165E3E4A04FB4BC28C50684293325854 check_fs nodeid 1084766062 clear
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: check_fs_done: 
>>> 165E3E4A04FB4BC28C50684293325854 check_fs done
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: send_info: 
>>> 165E3E4A04FB4BC28C50684293325854 send_start cg 3 flags 2 data2 0 counts 2 1 
> 0 
>>> 1 1
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: receive_start: 
>>> 969E8438425C45E484D7AB283185E731 receive_start 1084766063:3 len 76
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: match_change: 
>>> 969E8438425C45E484D7AB283185E731 match_change 1084766063:3 matches cg 3
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: wait_messages_done: 
>>> 969E8438425C45E484D7AB283185E731 wait_messages cg 3 got all 1
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: start_kernel: 
>>> 969E8438425C45E484D7AB283185E731 start_kernel cg 3 member_count 1
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
> 
>>> 1084766062
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
> 
>>> 1084766063
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: set_configfs_members: 
>>> set_members rmdir 
>>> 
> "/sys/kernel/config/dlm/cluster/spaces/969E8438425C45E484D7AB283185E731/nodes
>>> /1084766062"
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: do_sysfs: write "1" to 
>>> "/sys/kernel/dlm/969E8438425C45E484D7AB283185E731/control"
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: receive_start: 
>>> 165E3E4A04FB4BC28C50684293325854 receive_start 1084766063:3 len 76
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: match_change: 
>>> 165E3E4A04FB4BC28C50684293325854 match_change 1084766063:3 matches cg 3
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: wait_messages_done: 
>>> 165E3E4A04FB4BC28C50684293325854 wait_messages cg 3 got all 1
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: start_kernel: 
>>> 165E3E4A04FB4BC28C50684293325854 start_kernel cg 3 member_count 1
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
> 
>>> 1084766062
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: update_dir_members: dir_member 
> 
>>> 1084766063
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: set_configfs_members: 
>>> set_members rmdir 
>>> 
> "/sys/kernel/config/dlm/cluster/spaces/165E3E4A04FB4BC28C50684293325854/nodes
>>> /1084766062"
>>> Jul 15 08:32:22 ruh1kepapp2 cluster-dlm[4699]: do_sysfs: write "1" to 
>>> "/sys/kernel/dlm/165E3E4A04FB4BC28C50684293325854/control"
>>> Jul 15 08:32:22 ruh1kepapp2 kernel: [61880.467934] 
>>> (ocfs2rec,13862,6):ocfs2_replay_journal:1549 Recovering node 1084766062 from 
> 
>>> slot 1 on device (8,49)
>>> Jul 15 08:32:22 ruh1kepapp2 kernel: [61880.506685] 
>>> (ocfs2rec,13861,9):ocfs2_replay_journal:1549 Recovering node 1084766062 from 
> 
>>> slot 1 on device (8,33)
>>> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.232721] 
>>> (ocfs2rec,13862,0):ocfs2_begin_quota_recovery:407 Beginning quota recovery 
> in 
>>> slot 1
>>> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.380880] 
>>> (ocfs2rec,13861,6):ocfs2_begin_quota_recovery:407 Beginning quota recovery 
> in 
>>> slot 1
>>> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.389531] 
>>> (kworker/u:3,11960,0):ocfs2_finish_quota_recovery:599 Finishing quota 
>>> recovery in slot 1
>>> Jul 15 08:32:25 ruh1kepapp2 kernel: [61883.392216] 
>>> (kworker/u:3,11960,1):ocfs2_finish_quota_recovery:599 Finishing quota 
>>> recovery in slot 1
>>> Jul 15 08:32:25 ruh1kepapp2 SAPInstance(D60)[13863]: INFO: Stopping SAP 
>>> Instance KEP-D60:  15.07.2015 08:32:25 Stop OK
>>> Jul 15 08:32:53 ruh1kepapp2 SAPKEP_60[13261]: Q41 Monitoring: Snapshot 1 
>>> created
>>>
>>> Thanks
>>> Gang
>>>
>>>
>>>>>>
>>>> I have never seen this bug.
>>>> From the bug expression, it is caused by inode in memory and disk
>>>> mismatch. Previously we found jbd2_journal_restart is not called
>>>> correctly in ocfs2 and will cause inconsistent. I am not sure if it has
>>>> relations.
>>>> So could you check if there is any error occurred before (like storage
>>>> link down)?
>>>>
>>>> On 2015/7/22 15:56, Gang He wrote:
>>>>> Hello Joseph and Junxiao,
>>>>>
>>>>> I know you guys worked on OCFS2 for a few years.
>>>>> Here, the customer reported a bug when they were running Pacemaker+OCFS2+SAP 
> 
>>>
>>>> application on SLES11SP3 two nodes.
>>>>> But they did not provided the core dump file, or reproduce steps (seemed 
>>>> that they encountered this issue two times occasionally), 
>>>>> then I want to know if you saw the similar issue in the past, very thanks.
>>>>> The panic backtrace is as below (looks that inode size does not match disk 
>>>> inode's size, then trigger a bug()),
>>>>>
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157139] 
>>>> (sapstart,15094,6):ocfs2_truncate_file:466 ERROR: bug expression: 
>>>> le64_to_cpu(fe->i_size) != i_size_read(inode)
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157148] 
>>>> (sapstart,15094,6):ocfs2_truncate_file:466 ERROR: Inode 293533, inode i_size 
> 
>>>
>>>> = 853 != di i_size = 827, i_flags = 0x1
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157186] ------------[ cut here ]------------
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157197] kernel BUG at 
>>>> /usr/src/packages/BUILD/ocfs2-1.6/default/ocfs2/file.c:466!
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157204] invalid opcode: 0000 [#1] 
> 
>>>
>>>> SMP
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157210] CPU 6
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157213] Modules linked in: 
>>>> af_packet ocfs2 jbd2 ocfs2_nodemanager quota_tree ocfs2_stack_user 
>>>> ocfs2_stackglue dlm sctp crc32c libcrc32c configfs hpwdt iTCO_wdt 
>>>> iTCO_vendor_support i6300esb ib700wdt advantechwdt acquirewdt pcwd_usb 
>>>> usbcore usb_common wdt_pci pcwd_pci autofs4 edd nfs lockd fscache 
>>> auth_rpcgss 
>>>> nfs_acl sunrpc mperf microcode fuse loop dm_mod ppdev parport_pc parport 
>>>> floppy ipv6 ipv6_lib vmw_balloon(X) mptctl pciehp sg serio_raw intel_agp 
>>>> pcspkr vmxnet3 sr_mod intel_gtt cdrom shpchp rtc_cmos ac i2c_piix4 container 
> 
>>>
>>>> i2c_core pci_hotplug button ext3 jbd mbcache sd_mod crc_t10dif processor 
>>>> thermal_sys hwmon scsi_dh_hp_sw scsi_dh_rdac scsi_dh_emc scsi_dh_alua 
>>> scsi_dh 
>>>> ata_generic ata_piix libata mptspi mptscsih mptbase scsi_transport_spi 
>>>> scsi_mod
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157318] Supported: Yes, External
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157322]
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157327] Pid: 15094, comm: 
>>>> sapstart Tainted: G             X 3.0.101-0.47.52-default #1 VMware, Inc. 
>>>> VMware Virtual Platform/440BX Desktop Reference Platform
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157340] RIP: 
>>>> 0010:[<ffffffffa058cb85>]  [<ffffffffa058cb85>] ocfs2_truncate_file+0xa5/0x490 
>>>> [ocfs2]
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157391] RSP: 
>>>> 0018:ffff88082a3b5b68  EFLAGS: 00010296
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157396] RAX: 000000000000008a 
>>>> RBX: ffff88085c0cc580 RCX: 0000000000005457
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157402] RDX: 0000000000000000 
>>>> RSI: 0000000000000003 RDI: 0000000000000246
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157407] RBP: 1000000000000000 
>>>> R08: ffffffff81d9fac0 R09: 0000000000000000
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157413] R10: 0000000000000003 
>>>> R11: 00000000ffffffff R12: ffff8808ce63b4f8
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157419] R13: ffff88085c0ccbc8 
>>>> R14: ffff8808f61ee000 R15: 0000000000000355
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157425] FS:  
>>>> 00007f66e8272720(0000) GS:ffff88123fc00000(0000) knlGS:0000000000000000
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157431] CS:  0010 DS: 0000 ES: 
>>>> 0000 CR0: 000000008005003b
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157436] CR2: 00007fd0ac029000 
>>>> CR3: 000000081cda6000 CR4: 00000000000407e0
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157501] DR0: 0000000000000000 
>>>> DR1: 0000000000000000 DR2: 0000000000000000
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157539] DR3: 0000000000000000 
>>>> DR6: 00000000ffff0ff0 DR7: 0000000000000400
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157545] Process sapstart (pid: 
>>>> 15094, threadinfo ffff88082a3b4000, task ffff88085c0cc580)
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157551] Stack:
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157554]  0000000000047a9d 
>>>> 0000000000000355 000000000000033b ffff880800000001
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157564]  ffff8808fb5ab748 
>>>> ffff8812052d3000 ffff8808ce63b080 0000000000000000
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157572]  ffff8808fb7f2c00 
>>>> 0000000000000001 0000000000047a9d 000000000000000c
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157581] Call Trace:
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157666]  [<ffffffffa058f426>] 
>>>> ocfs2_setattr+0x276/0xa90 [ocfs2]
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157710]  [<ffffffff81177b6f>] 
>>>> notify_change+0x19f/0x2f0
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157724]  [<ffffffff8115c217>] 
>>>> do_truncate+0x57/0x80
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157737]  [<ffffffff8116abe3>] 
>>>> do_last+0x603/0x800
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157747]  [<ffffffff8116ba49>] 
>>>> path_openat+0xd9/0x420
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157757]  [<ffffffff8116becc>] 
>>>> do_filp_open+0x4c/0xc0
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157765]  [<ffffffff8115cb5f>] 
>>>> do_sys_open+0x17f/0x250
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157776]  [<ffffffff8146cb92>] 
>>>> system_call_fastpath+0x16/0x1b
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157795]  [<00007f66e7025790>] 
>>>> 0x7f66e702578f
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157799] Code: 6e 20 4d 8b bc 24 
>>>> d0 00 00 00 49 39 ef 74 20 48 bd 00 00 00 00 00 00 00 10 48 85 2d 46 b8 f7 
>>> ff 
>>>> 74 09 48 85 2d 7d d7 f7 ff 74 74 <0f> 0b eb fe 49 39 ed 0f 86 6c 01 00 00 8b 
>>> 05 
>>>> 30 b2 0a 00 85 c0
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157848] RIP  [<ffffffffa058cb85>] 
>>>> ocfs2_truncate_file+0xa5/0x490 [ocfs2]
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157879]  RSP <ffff88082a3b5b68>
>>>>> Jul 15 08:35:03 ruh1kepapp2 kernel: [62041.157886] ---[ end trace 
>>>> fb7a3c1bdf30e68e ]---
>>>>> Jul 15 08:35:05 ruh1kepapp2 SAPInstance(ERS51)[14667]: INFO: SAP Instance 
>>>> KEP-ERS51 stopped:  15.07.2015 08:35:05 WaitforStopped OK
>>>>> Jul 15 08:35:05 ruh1kepapp2 crmd[4335]:   notice: process_lrm_event: LRM 
>>>> operation ERS51_stop_0 (call=105, rc=0, cib-update=492, confirmed=true) ok
>>>>>
>>>>> Thanks
>>>>> Gang
>>>>>
>>>>> .
>>>>>
>>>
>>> _______________________________________________
>>> Ocfs2-devel mailing list
>>> Ocfs2-devel at oss.oracle.com 
>>> https://oss.oracle.com/mailman/listinfo/ocfs2-devel 
>> 
>> .
>> 

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [Ocfs2-devel] Do you know this issue? thanks
  2015-08-04  3:21         ` Gang He
@ 2015-08-04  9:13           ` Joseph Qi
  2015-08-05  2:20             ` Gang He
  0 siblings, 1 reply; 8+ messages in thread
From: Joseph Qi @ 2015-08-04  9:13 UTC (permalink / raw)
  To: ocfs2-devel

Hi Gang,

On 2015/8/4 11:21, Gang He wrote:
> Hi Joseph,
> 
> Thank for your good explaining, have more one question.
> 
> 
>>>>
>> Hi Gang,
>> On 2015/8/3 17:28, Gang He wrote:
>>> Hello guys,
>>>
>>> I went through OCFS2 journal and JBD2 code, I just have one question as 
>> below,
>>> If there are some nodes which are running, one node (node A) suddenly 
>> crashes, one another node (node B) will recover node A's journal records. But 
>> here looks a problem, if node B ever changed one file, and node A also 
>> changed this same file, then node B will replay these changed meta buffers, 
>> JBD2 recovery code will memcpy the journal meta buffer to the node B's 
>> memory, this inode's meta buffer will be replaced by node A's journal record, 
>> but this inode structure in memory will not be reflected, this will cause 
>> this kind of issue? I feel that my guess should be wrong, since this problem 
>> looks too obvious, but who can help to figure out how to solve this problem 
>> when a running node try to recover a crashed node's journal.
>>>
>> Please note that nodes can update the same inode only after it has got
>> the cluster lock. And if the lock level is not compatible, it will
>> downcovert first, which will do the checkpoint.
>> So I don't think the issue you described really exists.
> You means, if Node A try to change the same file when Node B is changing (or just changed) this file, it must wait until Node B finishes the checkpoint for these meta buffers,
> then, Node A will re-read these meta buffers from the shared disk and gets the lock, my understanding is right? if yes, how the inode meta buffer reflect the inode structure in the memory?
> There is a case, if Node A ever read a file, then Node B changes the same file and write the journal records to the log file (the meta buffers are not flushed to the file system) and crashes, at this moment, Node A is replaying the journal records and a user is trying to access/change this file, what will happen? the memory inode will be inconsistent with just recovered meta buffer? looks a little complicated.
> 
Node A reads a file (take inode lock, level PR), then Node B changes the
same file (take inode lock, level EX). Here when Node B takes the inode
EX lock, Node A should downcovert to NL because PR and EX are incompatible.
So inode cache in Node A is invalid now.
And only after recovering Node B successfully, Node A can access the file.
(Because lock is holding by Node B).

> Thanks
> Gang   
>  
> 
>>
>> Thanks
>> Joseph
>>>
>>> Thanks
>>> Gang 

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [Ocfs2-devel] Do you know this issue? thanks
  2015-08-04  9:13           ` Joseph Qi
@ 2015-08-05  2:20             ` Gang He
  2015-08-05  2:37               ` Joseph Qi
  0 siblings, 1 reply; 8+ messages in thread
From: Gang He @ 2015-08-05  2:20 UTC (permalink / raw)
  To: ocfs2-devel

Hi Joseph,

Thank a lot, more one question.


>>> 
> Hi Gang,
> 
> On 2015/8/4 11:21, Gang He wrote:
>> Hi Joseph,
>> 
>> Thank for your good explaining, have more one question.
>> 
>> 
>>>>>
>>> Hi Gang,
>>> On 2015/8/3 17:28, Gang He wrote:
>>>> Hello guys,
>>>>
>>>> I went through OCFS2 journal and JBD2 code, I just have one question as 
>>> below,
>>>> If there are some nodes which are running, one node (node A) suddenly 
>>> crashes, one another node (node B) will recover node A's journal records. 
> But 
>>> here looks a problem, if node B ever changed one file, and node A also 
>>> changed this same file, then node B will replay these changed meta buffers, 
>>> JBD2 recovery code will memcpy the journal meta buffer to the node B's 
>>> memory, this inode's meta buffer will be replaced by node A's journal 
> record, 
>>> but this inode structure in memory will not be reflected, this will cause 
>>> this kind of issue? I feel that my guess should be wrong, since this problem 
> 
>>> looks too obvious, but who can help to figure out how to solve this problem 
>>> when a running node try to recover a crashed node's journal.
>>>>
>>> Please note that nodes can update the same inode only after it has got
>>> the cluster lock. And if the lock level is not compatible, it will
>>> downcovert first, which will do the checkpoint.
>>> So I don't think the issue you described really exists.
>> You means, if Node A try to change the same file when Node B is changing (or 
> just changed) this file, it must wait until Node B finishes the checkpoint 
> for these meta buffers,
>> then, Node A will re-read these meta buffers from the shared disk and gets 
> the lock, my understanding is right? if yes, how the inode meta buffer 
> reflect the inode structure in the memory?
>> There is a case, if Node A ever read a file, then Node B changes the same 
> file and write the journal records to the log file (the meta buffers are not 
> flushed to the file system) and crashes, at this moment, Node A is replaying 
> the journal records and a user is trying to access/change this file, what 
> will happen? the memory inode will be inconsistent with just recovered meta 
> buffer? looks a little complicated.
>> 
> Node A reads a file (take inode lock, level PR), then Node B changes the
> same file (take inode lock, level EX). Here when Node B takes the inode
> EX lock, Node A should downcovert to NL because PR and EX are incompatible.
> So inode cache in Node A is invalid now.
> And only after recovering Node B successfully, Node A can access the file.
> (Because lock is holding by Node B).
The answer looks reasonable, just one question for how Node A re-get  the file(inode) lock after Node B crashed?
since Node B crashed, it no longer do anything, how Node A re-get the file cluster lock? base on timeout? or journal recovery of Node B from another Node (maybe or not maybe Node A), I just doubt that journal records do not include any DLM lock related information.


Thanks
Gang

> 
>> Thanks
>> Gang   
>>  
>> 
>>>
>>> Thanks
>>> Joseph
>>>>
>>>> Thanks
>>>> Gang 

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [Ocfs2-devel] Do you know this issue? thanks
  2015-08-05  2:20             ` Gang He
@ 2015-08-05  2:37               ` Joseph Qi
  0 siblings, 0 replies; 8+ messages in thread
From: Joseph Qi @ 2015-08-05  2:37 UTC (permalink / raw)
  To: ocfs2-devel

On 2015/8/5 10:20, Gang He wrote:
> Hi Joseph,
> 
> Thank a lot, more one question.
> 
> 
>>>>
>> Hi Gang,
>>
>> On 2015/8/4 11:21, Gang He wrote:
>>> Hi Joseph,
>>>
>>> Thank for your good explaining, have more one question.
>>>
>>>
>>>>>>
>>>> Hi Gang,
>>>> On 2015/8/3 17:28, Gang He wrote:
>>>>> Hello guys,
>>>>>
>>>>> I went through OCFS2 journal and JBD2 code, I just have one question as 
>>>> below,
>>>>> If there are some nodes which are running, one node (node A) suddenly 
>>>> crashes, one another node (node B) will recover node A's journal records. 
>> But 
>>>> here looks a problem, if node B ever changed one file, and node A also 
>>>> changed this same file, then node B will replay these changed meta buffers, 
>>>> JBD2 recovery code will memcpy the journal meta buffer to the node B's 
>>>> memory, this inode's meta buffer will be replaced by node A's journal 
>> record, 
>>>> but this inode structure in memory will not be reflected, this will cause 
>>>> this kind of issue? I feel that my guess should be wrong, since this problem 
>>
>>>> looks too obvious, but who can help to figure out how to solve this problem 
>>>> when a running node try to recover a crashed node's journal.
>>>>>
>>>> Please note that nodes can update the same inode only after it has got
>>>> the cluster lock. And if the lock level is not compatible, it will
>>>> downcovert first, which will do the checkpoint.
>>>> So I don't think the issue you described really exists.
>>> You means, if Node A try to change the same file when Node B is changing (or 
>> just changed) this file, it must wait until Node B finishes the checkpoint 
>> for these meta buffers,
>>> then, Node A will re-read these meta buffers from the shared disk and gets 
>> the lock, my understanding is right? if yes, how the inode meta buffer 
>> reflect the inode structure in the memory?
>>> There is a case, if Node A ever read a file, then Node B changes the same 
>> file and write the journal records to the log file (the meta buffers are not 
>> flushed to the file system) and crashes, at this moment, Node A is replaying 
>> the journal records and a user is trying to access/change this file, what 
>> will happen? the memory inode will be inconsistent with just recovered meta 
>> buffer? looks a little complicated.
>>>
>> Node A reads a file (take inode lock, level PR), then Node B changes the
>> same file (take inode lock, level EX). Here when Node B takes the inode
>> EX lock, Node A should downcovert to NL because PR and EX are incompatible.
>> So inode cache in Node A is invalid now.
>> And only after recovering Node B successfully, Node A can access the file.
>> (Because lock is holding by Node B).
> The answer looks reasonable, just one question for how Node A re-get  the file(inode) lock after Node B crashed?
> since Node B crashed, it no longer do anything, how Node A re-get the file cluster lock? base on timeout? or journal recovery of Node B from another Node (maybe or not maybe Node A), I just doubt that journal records do not include any DLM lock related information.
> 
As described in the previous mail, though Node B has crashed, but the
lockres master still thinks Node B has got the EX lock. Now Node A wants
to take the PR lock and it will be blocked. This requires DLM recovery
first.

Thanks,
Joseph
> 
> Thanks
> Gang
> 
>>
>>> Thanks
>>> Gang   
>>>  
>>>
>>>>
>>>> Thanks
>>>> Joseph
>>>>>
>>>>> Thanks
>>>>> Gang 
> 
> 
> .
> 

^ permalink raw reply	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2015-08-05  2:37 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
     [not found] <55AFBD47020000F90000F7DF@relay2.provo.novell.com>
2015-07-23  2:37 ` [Ocfs2-devel] Do you know this issue? thanks Joseph Qi
2015-07-23  7:14   ` Gang He
2015-08-03  9:28     ` Gang He
2015-08-03 10:21       ` Joseph Qi
2015-08-04  3:21         ` Gang He
2015-08-04  9:13           ` Joseph Qi
2015-08-05  2:20             ` Gang He
2015-08-05  2:37               ` Joseph Qi

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox