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

[Joseph Qi]

On 19/12/16 20:12, Likai wrote:
> On 2019/12/16 18:02, Joseph Qi wrote:
>>
>> On 19/12/12 14:00, 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 | 9 +++++++++
>>>  1 file changed, 9 insertions(+)
>>>
>>> diff --git a/fs/ocfs2/journal.c b/fs/ocfs2/journal.c
>>> index 1afe57f425a0..5c7a489f47b0 100644
>>> --- a/fs/ocfs2/journal.c
>>> +++ b/fs/ocfs2/journal.c
>>> @@ -1066,6 +1066,15 @@ 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) {
>>> +		mlog(ML_NOTICE, "journal recovery complete");
>> I don't think this log is appropriate, or we can change it to something like:
>> "Journal is dirty, wipe it first"?
>>
>> Thanks,
>> Joseph
> This log is not used to interpret journal flush's purpose and calling
> journal flush to make jbd2 super block become normal should be a
> requisite operation internally,
> maybe a mark should be better I think if necessary.
> In addition,  ocfs2 prints a log like 'ocfs2: File system on device (%s)
> was not  unmounted cleanly, recovering it' before,
> and  journal has already been replayed in
> jbd2_journal_load->jbd2_journal_recover,  this log just means that it is
> done here.
> So I don't think it is inappropriate,  could you think abort my proposal
> again?
> 
Not really, just think that this log has no actual meaning.
Or we can simply remove it.

Thanks,
Joseph