Re: BUG: scrub reports uncorrectable csum errors linked to readable file (data: single)

[Qu Wenruo <quwenruo.btrfs@gmx.com>]

在 2024/7/4 21:51, Lionel Bouton 写道:
> Le 30/06/2024 à 12:59, Lionel Bouton a écrit :
>> Le 22/06/2024 à 11:41, Qu Wenruo a écrit :
>>>
>>>
>>> 在 2024/6/22 18:21, Lionel Bouton 写道:
>>> [...]
>>>>>
>>>>> I'll mount the filesystem and run a scrub again to see if I can
>>>>> reproduce the problem. It should be noticeably quicker, we made
>>>>> updates to the Ceph cluster and should get approximately 2x the I/O
>>>>> bandwidth.
>>>>> I plan to keep the disk snapshot for at least several weeks so if you
>>>>> want to test something else just say so.
>>>>
>>>>
>>>> The scrub is finished, here are the results :
>>>>
>>>> UUID: 61e86d80-d6e4-4f9e-a312-885194c5e690
>>>> Scrub started:    Wed Jun 19 00:01:59 2024
>>>> Status:           finished
>>>> Duration:         81:04:21
>>>> Total to scrub:   18.83TiB
>>>> Rate:             67.67MiB/s
>>>> Error summary:    no errors found
>>>>
>>>> So the scrub error isn't deterministic. I'll shut down the test VM for
>>>> now and keep the disk snapshot it uses for at least a couple of week if
>>>> it is needed for further tests.
>>>> The original filesystem is scrubbed monthly, I'll reply to this message
>>>> if another error shows up.
>>>
>>> I briefly remembered that there was a bug related to scrub that can
>>> report false alerts:
>>>
>>> f546c4282673 ("btrfs: scrub: avoid use-after-free when chunk length is
>>> not 64K aligned")
>>>
>>> But that should be automatically backported, and in that case it should
>>> have some errors like "unable to find chunk map" error messages in the
>>> kernel log.
>>>
>>> Otherwise, I have no extra clues.
>>>
>>> Have you tried kernels like v6.8/6.9 and can you reproduce the bug in
>>> those newer kernels?
>>
>> I've just upgraded the kernel to 6.9.7 (and btrfs-progs to 6.9.2) and
>> monthly scrubs with it will start next week. That said the last
>> filesystem scrub with 6.6.30 ran without errors so it might be hard to
>> reproduce.
>> One difference with the last scrub vs the previous one which reported
>> checksum errors is the underlying device speed : it is getting faster
>> as we replace HDDs with SSDs on the Ceph cluster (it might be a cause
>> if there's a race condition somewhere). Other than that there's
>> nothing I can think of.
>>
>> In fact the only 2 major changes before the scrub checksum errors where :
>> - a noticeable increase in constant I/O load,
>> - an upgrade to the 6.6 kernel.
>>
>> As nobody else reported the same behavior I'm not ruling out an
>> hardware glitch either.
>> I'll reply to this thread if a future scrub reports a non reproducible
>> checksum error again.
>
> I didn't expect to have something to report so soon...
> Another virtual machine running on another physical server but using the
> same Ceph cluster just reported csum errors that aren't reproducible.
> This was with kernel 6.6.13 and btrfs-progs 6.8.2.
> Fortunately this filesystem is small and can be scrubbed in 2 minutes :
> I just ran the scrub again (less than 5 hours after the one that
> reported errors) and no error are reported this time.
>
> I'll upgrade this VM to 6.9.7+ too. If 6.6 has indeed a scrub bug and
> not 6.9 it might be easier to verify than I anticipated : most of our
> VMs have migrated or are in the process of migrating to 6.6 which is the
> latest LTS. If the problem manifest itself on a small filesystem too I
> expect other systems to fail scrubs sooner or later if 6.6 is affected
> by a scrub bug.

So far it looks like it's the commit f546c4282673 ("btrfs: scrub: avoid
use-after-free when chunk length is not 64K aligned") fixing the error.

In that case, it looks like 6.6 is EOL at that time thus didn't got
backports.

To verify if it's the case, you can dump the chunk tree and check if
their length is 64K aligned, and if the dmesg shows something like this
"      BTRFS critical (device vdb): unable to find chunk map for logical
2214744064 length 4096".

Thanks,
Qu
>
> Like I wrote last time I'll reply here if other scrubs report non
> reproducible csum errors.
>
>>
>> Lionel
>>
>>>
>>> Thanks,
>>> Qu
>>>>
>>>>>
>>>>> Best regards,
>>>>> Lionel
>>>>>
>>>>>>
>>>>>> If btrfs check reports error, and logical-resolve failed to locate
>>>>>> the
>>>>>> file and its position, it means the corruption is in bookend exntets.
>>>>>>
>>>>>> If btrfs check reports error and logical-resolve can locate the
>>>>>> file and
>>>>>> position, it's a different problem then.
>>>>>>
>>>>>> Thanks,
>>>>>> Qu
>>>>>>
>>>>>>>
>>>>>>> The stats output show that this file was not modified since its
>>>>>>> creation
>>>>>>> more than 6 years ago. This is what led me to report a bug in scrub.
>>>>>>>
>>>>>>>
>>>>>>>>
>>>>>>>>> - Some including the original subvolume have only logged 2
>>>>>>>>> warnings and
>>>>>>>>> one (root 151335) logged only one warning.
>>>>>>>>> - All of the snapshots reported a warning for offset 20480.
>>>>>>>>> - When several offsets are logged their order seems random.
>>>>>>>>
>>>>>>>> One problem of scrub is, it may ratelimit the output, thus we
>>>>>>>> can not
>>>>>>>> just rely on dmesg to know the damage.
>>>>>>>
>>>>>>> I wondered about this: I've read other threads where ratelimiting is
>>>>>>> mentioned but I was not sure if it could apply here. Thanks for
>>>>>>> clarifying.
>>>>>>>
>>>>>>>>
>>>>>>>>>
>>>>>>>>> I'm attaching kernel logs beginning with the scrub start and
>>>>>>>>> ending with
>>>>>>>>> the last error. As of now there are no new errors/warnings even
>>>>>>>>> though
>>>>>>>>> the scrub is still ongoing, 15 hours after the last error. I
>>>>>>>>> didn't
>>>>>>>>> clean the log frombalance logs linked to the same filesystem.
>>>>>>>>>
>>>>>>>>> Side-note for the curious or in the unlikely case it could be
>>>>>>>>> linked to
>>>>>>>>> the problem:
>>>>>>>>> Historically this filesystem was mounted with ssd_spread
>>>>>>>>> without any
>>>>>>>>> issue (I guess several years ago it made sense to me reading the
>>>>>>>>> documentation and given the IO latencies I saw on the Ceph
>>>>>>>>> cluster). A
>>>>>>>>> recent kernel filled the whole available space with nearly empty
>>>>>>>>> block
>>>>>>>>> groups which seemed to re-appear each time we mounted with
>>>>>>>>> ssd_spread.
>>>>>>>>> We switched to "ssd" since then and there is a mostly daily 90mn
>>>>>>>>> balance
>>>>>>>>> to reach back the previous stateprogressively (this is the reason
>>>>>>>>> behind
>>>>>>>>> the balance related logs). Having some space available for new
>>>>>>>>> block
>>>>>>>>> groups seems to be a good idea but additionally as we use Ceph
>>>>>>>>> RBD, we
>>>>>>>>> want it to be able to deallocate unused space: having many nearly
>>>>>>>>> empty
>>>>>>>>> block groups could waste resources (especially if the used
>>>>>>>>> space in
>>>>>>>>> these groups is in <4MB continuous chunks which is the default RBD
>>>>>>>>> object size).
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> More information :
>>>>>>>>> The scrub is run monthly. This is the first time an error was ever
>>>>>>>>> reported. The previous scrub was run successfully at the
>>>>>>>>> beginning of
>>>>>>>>> May with a 6.6.13 kernel.
>>>>>>>>>
>>>>>>>>> There is a continuous defragmentation process running (it
>>>>>>>>> processes the
>>>>>>>>> whole filesystem slowly ignoring snapshots and defragments file by
>>>>>>>>> file
>>>>>>>>> based on a fragmentation estimation using filefrag -v). All
>>>>>>>>> defragmentations are logged and I can confirm the file for
>>>>>>>>> which this
>>>>>>>>> error was reported was not defragmented for at least a year (I
>>>>>>>>> checked
>>>>>>>>> because I wanted to rule out a possible race condition between
>>>>>>>>> defragmentation and scrub).
>>>>>>>>
>>>>>>>> I'm wondering if there is any direct IO conflicting with
>>>>>>>> buffered/defrag IO.
>>>>>>>>
>>>>>>>> It's known that conflicting buffered/direct IO can lead to contents
>>>>>>>> change halfway, and lead to btrfs csum mismatch.
>>>>>>>> So far that's the only thing leading to known btrfs csum mismatch I
>>>>>>>> can
>>>>>>>> think of.
>>>>>>>
>>>>>>> But here it seems there isn't an actual mismatch as reading the
>>>>>>> file is
>>>>>>> possible and gives the data which was written in it 6 years ago.
>>>>>>> Tthis
>>>>>>> seems an error in scrub (or a neutrino flipping a bit somewhere
>>>>>>> during
>>>>>>> the scrub). The VM runs on a server with ECC RAM so it is unlikely
>>>>>>> to be
>>>>>>> a simple bitflip but when everything likely has been ruled out...
>>>>>>>
>>>>>>> Thanks for your feedback,
>>>>>>> Lionel
>>>>>>>
>>>>>>>>
>>>>>>>> But 6.x kernel should all log a warning message for it.
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>> Qu
>>>>>>>>>
>>>>>>>>> In addition to the above, among the notable IO are :
>>>>>>>>> - a moderately IO intensive PostgreSQL replication subscriber,
>>>>>>>>> - ponctual large synchronisations using Syncthing,
>>>>>>>>> - snapshot creations/removals occur approximately every 80
>>>>>>>>> minutes. The
>>>>>>>>> last snapshot operation was logged 31 minutes before the errors
>>>>>>>>> (removal
>>>>>>>>> occur asynchronously but where was no unusual load at this time
>>>>>>>>> that
>>>>>>>>> could point to a particularly long snapshot cleanup process).
>>>>>>>>>
>>>>>>>>> To sum up, there are many processes accessing the filesystem but
>>>>>>>>> historically it saw far higher IO load during scrubs than what was
>>>>>>>>> occurring here.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Reproducing this might be difficult: the whole scrub can take a
>>>>>>>>> week
>>>>>>>>> depending on load. That said I can easily prepare a kernel
>>>>>>>>> and/or new
>>>>>>>>> btrfs-progs binaries to launch scrubs or other non-destructive
>>>>>>>>> tasks the
>>>>>>>>> week-end or at the end of the day (UTC+2 timezone).
>>>>>>>>>
>>>>>>>>> Best regards,
>>>>>>>>>
>>>>>>>>> Lionel Bouton
>>>>>>>>
>>>>>>>
>>>>>
>>>>
>>>>
>>
>