Re: [Ocfs2-devel] [PATCH v3] ocfs2: call journal flush to mark journal as empty after journal recovery when mount

[Likai]

On 2019/12/20 17:14, piaojun wrote:
>
> On 2019/12/20 9:11, Joseph Qi wrote:
>>
>> On 19/12/19 22:15, piaojun wrote:
>>>
>>> On 2019/12/17 10:01, Kai Li wrote:
>>>> If journal is dirty when mount, it will be replayed but jbd2 sb
>>>> log tail cannot be updated to mark a new start because
>>>> journal->j_flag has already been set with JBD2_ABORT first
>>>> in journal_init_common. When a new transaction is committed, it
>>>> will be recored in block 1 first(journal->j_tail is set to 1 in
>>>> journal_reset).If emergency restart happens again before journal
>>>> super block is updated unfortunately, the new recorded trans will
>>>> not be replayed in the next mount.
>>>>
>>>> The following steps describe this procedure in detail.
>>>> 1. mount and touch some files
>>>> 2. these transactions are committed to journal area but not checkpointed
>>>> 3. emergency restart
>>>> 4. mount again and its journals are replayed
>>>> 5. journal super block's first s_start is 1, but its s_seq is not updated
>>>> 6. touch a new file and its trans is committed but not checkpointed
>>>> 7. emergency restart again
>>>> 8. mount and journal is dirty, but trans committed in 6 will not be
>>>> replayed.
>>>>
>>>> This exception happens easily when this lun is used by only one node. If it
>>>> is used by multi-nodes, other node will replay its journal and its
>>>> journal super block will be updated after recovery like what this patch
>>>> does.
>>>>
>>>> ocfs2_recover_node->ocfs2_replay_journal.
>>>>
>>>> The following jbd2 journal can be generated by touching a new file after
>>>> journal is replayed, and seq 15 is the first valid commit, but first seq
>>>> is 13 in journal super block.
>>>> logdump:
>>>> Block 0: Journal Superblock
>>>> Seq: 0   Type: 4 (JBD2_SUPERBLOCK_V2)
>>>> Blocksize: 4096   Total Blocks: 32768   First Block: 1
>>>> First Commit ID: 13   Start Log Blknum: 1
>>>> Error: 0
>>>> Feature Compat: 0
>>>> Feature Incompat: 2 block64
>>>> Feature RO compat: 0
>>>> Journal UUID: 4ED3822C54294467A4F8E87D2BA4BC36
>>>> FS Share Cnt: 1   Dynamic Superblk Blknum: 0
>>>> Per Txn Block Limit    Journal: 0    Data: 0
>>>>
>>>> Block 1: Journal Commit Block
>>>> Seq: 14   Type: 2 (JBD2_COMMIT_BLOCK)
>>>>
>>>> Block 2: Journal Descriptor
>>>> Seq: 15   Type: 1 (JBD2_DESCRIPTOR_BLOCK)
>>>> No. Blocknum        Flags
>>>>  0. 587             none
>>>> UUID: 00000000000000000000000000000000
>>>>  1. 8257792         JBD2_FLAG_SAME_UUID
>>>>  2. 619             JBD2_FLAG_SAME_UUID
>>>>  3. 24772864        JBD2_FLAG_SAME_UUID
>>>>  4. 8257802         JBD2_FLAG_SAME_UUID
>>>>  5. 513             JBD2_FLAG_SAME_UUID JBD2_FLAG_LAST_TAG
>>>> ...
>>>> Block 7: Inode
>>>> Inode: 8257802   Mode: 0640   Generation: 57157641 (0x3682809)
>>>> FS Generation: 2839773110 (0xa9437fb6)
>>>> CRC32: 00000000   ECC: 0000
>>>> Type: Regular   Attr: 0x0   Flags: Valid
>>>> Dynamic Features: (0x1) InlineData
>>>> User: 0 (root)   Group: 0 (root)   Size: 7
>>>> Links: 1   Clusters: 0
>>>> ctime: 0x5de5d870 0x11104c61 -- Tue Dec  3 11:37:20.286280801 2019
>>>> atime: 0x5de5d870 0x113181a1 -- Tue Dec  3 11:37:20.288457121 2019
>>>> mtime: 0x5de5d870 0x11104c61 -- Tue Dec  3 11:37:20.286280801 2019
>>>> dtime: 0x0 -- Thu Jan  1 08:00:00 1970
>>>> ...
>>>> Block 9: Journal Commit Block
>>>> Seq: 15   Type: 2 (JBD2_COMMIT_BLOCK)
>>>>
>>>> The following is jouranl recovery log when recovering the upper jbd2
>>>> journal when mount again.
>>>> syslog:
>>>> [ 2265.648622] ocfs2: File system on device (252,1) was not unmounted cleanly, recovering it.
>>>> [ 2265.649695] fs/jbd2/recovery.c:(do_one_pass, 449): Starting recovery pass 0
>>>> [ 2265.650407] fs/jbd2/recovery.c:(do_one_pass, 449): Starting recovery pass 1
>>>> [ 2265.650409] fs/jbd2/recovery.c:(do_one_pass, 449): Starting recovery pass 2
>>>> [ 2265.650410] fs/jbd2/recovery.c:(jbd2_journal_recover, 278): JBD2: recovery, exit status 0, recovered transactions 13 to 13
>>>>
>>>> Due to first commit seq 13 recorded in journal super is not consistent
>>>> with the value recorded in block 1(seq is 14), journal recovery will be
>>>> terminated before seq 15 even though it is an unbroken commit, inode
>>>> 8257802 is a new file and it will be lost.
>>>>
>>>> Signed-off-by: Kai Li <li.kai4@xxxxxxx>
>>>> ---
>>>>  fs/ocfs2/journal.c | 8 ++++++++
>>>>  1 file changed, 8 insertions(+)
>>>>
>>>> diff --git a/fs/ocfs2/journal.c b/fs/ocfs2/journal.c
>>>> index 1afe57f425a0..68ba354cf361 100644
>>>> --- a/fs/ocfs2/journal.c
>>>> +++ b/fs/ocfs2/journal.c
>>>> @@ -1066,6 +1066,14 @@ int ocfs2_journal_load(struct ocfs2_journal *journal, int local, int replayed)
>>>>  
>>>>  	ocfs2_clear_journal_error(osb->sb, journal->j_journal, osb->slot_num);
>>>>  
>>>> +	if (replayed) {
>>>> +		jbd2_journal_lock_updates(journal->j_journal);
>>>> +		status = jbd2_journal_flush(journal->j_journal);
>>> What if jbd2_journal_flush gets failed? The 's_sequence' and 's_start'
>>> won't be reset, and I wonder if the problem still remains.
>>>
>> Yes, but we don't want this to fail the mount process, instead we just log
>> an error and system administrator should know the result.
>>
> Thanks for your reply and I have another question about this issue. IMO
> the second trans is not complete as jbd2 sb has not been updated, so we
> do not need to replay it when mount again.
>
> Jun
>
>
I don't think so. The problem is that jbd2 sb should be updated to mark
a new start after mount rather than whether trans committed later is
complete or not.

In fact , the trans is complete too as the commit log described.

Thanks