"btrfs: harden agaist duplicate fsid" spams syslog

"btrfs: harden agaist duplicate fsid" spams syslog

[Graham Cobb]

Anand's Nov 2018 patch "btrfs: harden agaist duplicate fsid" has
recently percolated through to my Debian buster server system.

And it is spamming my log files.

Each of my btrfs filesystem devices logs 4 messages every 2 minutes.
Here is an example of the 4 messages related to one device:

Jul 10 19:32:27 black kernel: [33017.407252] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
Jul 10 19:32:27 black kernel: [33017.522242] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
Jul 10 19:32:29 black kernel: [33018.797161] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
Jul 10 19:32:29 black kernel: [33019.061631] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup

What is happening here is that each device is actually an LVM logical
volume, and it is known by a /dev/mapper name and a /dev/dm name. And
every 2 minutes something cause btrfs to notice that there are two names
for the same device and it swaps them around. Logging a message to say
it has done so. And doing it 4 times.

I presume that the swapping doesn't cause any problem. I wonder slightly
whether ordering guarantees and barriers all work correctly but I
haven't noticed any problems.

I also assume it has been doing this for a while -- just silently before
this patch came along.

Is btrfs noticing this itself or is something else (udev or systemd, for
example) triggering it?

Should I worry about it?

Is there any way to not have my log files full of this?

Graham

[This started with a Debian testing kernel a couple of months ago.
Current uname -a gives: Linux black 4.19.0-5-amd64 #1 SMP Debian
4.19.37-5 (2019-06-19) x86_64 GNU/Linux]

Re: "btrfs: harden agaist duplicate fsid" spams syslog

[Anand Jain]

Right. It happened even without this patch but we just know it now.

In the original investigations of the patch, the moment you copy a
device image into another device, the autoscan would scan the new
device into the btrfs kernel and created a mess. Now with this patch
we won't replace the device path unless it's the same device (and we
have to let that happen).

Now the question I am trying to understand, why same device is being
scanned every 2 mins, even though its already mount-ed. I am guessing
its toggling the same device paths trying to mount the device-path
which is not mounted. So autofs's check for the device mount seems to
be path based.

Would you please provide your LVM configs and I believe you are using
dm-mapping too. What are the device paths used in the fstab and in grub.
And do you see these messages for all devices of
4d1ba5af-8b89-4cb5-96c6-55d1f028a202 or just devid 4? Would you please
provide more logs at least a complete cycle of the repeating logs.

-Anand


On 11/7/19 2:49 AM, Graham Cobb wrote:
> Anand's Nov 2018 patch "btrfs: harden agaist duplicate fsid" has
> recently percolated through to my Debian buster server system.
> 
> And it is spamming my log files.
> 
> Each of my btrfs filesystem devices logs 4 messages every 2 minutes.
> Here is an example of the 4 messages related to one device:
> 
> Jul 10 19:32:27 black kernel: [33017.407252] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> Jul 10 19:32:27 black kernel: [33017.522242] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> Jul 10 19:32:29 black kernel: [33018.797161] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> Jul 10 19:32:29 black kernel: [33019.061631] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> 
> What is happening here is that each device is actually an LVM logical
> volume, and it is known by a /dev/mapper name and a /dev/dm name. And
> every 2 minutes something cause btrfs to notice that there are two names
> for the same device and it swaps them around. Logging a message to say
> it has done so. And doing it 4 times.
> 
> I presume that the swapping doesn't cause any problem. I wonder slightly
> whether ordering guarantees and barriers all work correctly but I
> haven't noticed any problems.
> 
> I also assume it has been doing this for a while -- just silently before
> this patch came along.
> 
> Is btrfs noticing this itself or is something else (udev or systemd, for
> example) triggering it?
> 
> Should I worry about it?
> 
> Is there any way to not have my log files full of this?
> 
> Graham
> 
> [This started with a Debian testing kernel a couple of months ago.
> Current uname -a gives: Linux black 4.19.0-5-amd64 #1 SMP Debian
> 4.19.37-5 (2019-06-19) x86_64 GNU/Linux]
> 

Re: "btrfs: harden agaist duplicate fsid" spams syslog

[Graham Cobb]

On 11/07/2019 03:46, Anand Jain wrote:
> Now the question I am trying to understand, why same device is being
> scanned every 2 mins, even though its already mount-ed. I am guessing
> its toggling the same device paths trying to mount the device-path
> which is not mounted. So autofs's check for the device mount seems to
> be path based.
> 
> Would you please provide your LVM configs and I believe you are using
> dm-mapping too. What are the device paths used in the fstab and in grub.
> And do you see these messages for all devices of
> 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 or just devid 4? Would you please
> provide more logs at least a complete cycle of the repeating logs.

My setup is quite complex, with three btrfs-over-LVM-over-LUKS
filesystems, so I will explain it fully in a separate message in case it
is important. Let me first answer your questions regarding
4d1ba5af-8b89-4cb5-96c6-55d1f028a202, which was the example I used in my
initial log extract.

4d1b...a202 is a filesystem with a main mount point of /mnt/backup2/:

black:~# btrfs fi show /mnt/backup2/
Label: 'snap12tb'  uuid: 4d1ba5af-8b89-4cb5-96c6-55d1f028a202
        Total devices 2 FS bytes used 10.97TiB
        devid    1 size 10.82TiB used 10.82TiB path /dev/sdc3
        devid    4 size 3.62TiB used 199.00GiB path
/dev/mapper/cryptdata4tb--vg-backup

In this particular filesystem, it has two devices: one is a real disk
partition (/dev/sdc3), the other is an LVM logical volume. It has also
had other LVM devices added and removed at various times, but this is
the current setup.

Note: when I added this LV, I used path /dev/mapper/cryptdata4tb--vg-backup.

black:~# lvdisplay /dev/cryptdata4tb-vg/backup
  --- Logical volume ---
  LV Path                /dev/cryptdata4tb-vg/backup
  LV Name                backup
  VG Name                cryptdata4tb-vg
  LV UUID                TZaWfo-goG1-GsNV-GCZL-rpbz-IW0H-gNmXBf
  LV Write Access        read/write
  LV Creation host, time black, 2019-07-10 10:40:28 +0100
  LV Status              available
  # open                 1
  LV Size                3.62 TiB
  Current LE             949089
  Segments               1
  Allocation             inherit
  Read ahead sectors     auto
  - currently set to     256
  Block device           254:13

The LVM logical volume is exposed as /dev/mapper/cryptdata4tb--vg-backup
which is a symlink (set up by LVM, I believe) to /dev/dm-13.

For the 4d1b...a202 filesystem I currently only see the messages for
devid 4. But I presume that is because devid 1 is a real device, which
only appears in /dev once. I did, for a while, have two LV devices in
this filesystem and, looking at the old logs, I can see that every 2
minutes the swapping between /dev/mapper/whatever and /dev/dm-N was
happening for both LV devids (but not for the physical device devid)

This particular device is not a root device and I do not believe it is
referenced in grub or initramfs. It is mounted in /etc/fstab/:

LABEL=snap12tb  /mnt/backup2    btrfs
defaults,subvolid=0,noatime,nodiratime,compress=lzo,skip_balance,space_cache=v2
       0       3

Note that /dev/disk/by-label/snap12tb is a symlink to the dm-N alias of
the LV device (set up by LVM or udev or something - not by me):

black:~# ls -l /dev/disk/by-label/snap12tb
lrwxrwxrwx 1 root root 11 Jul 11 18:18 /dev/disk/by-label/snap12tb ->
../../dm-13

Here is a log extract of the cycling messages for the 4d1b...a202
filesystem:

Jul 11 18:46:28 black kernel: [116657.825658] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
Jul 11 18:46:28 black kernel: [116658.048042] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
Jul 11 18:46:29 black kernel: [116659.157392] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
Jul 11 18:46:29 black kernel: [116659.337504] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
Jul 11 18:48:28 black kernel: [116777.727262] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
Jul 11 18:48:28 black kernel: [116778.019874] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
Jul 11 18:48:29 black kernel: [116779.157038] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
Jul 11 18:48:30 black kernel: [116779.364959] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
Jul 11 18:50:28 black kernel: [116897.705568] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
Jul 11 18:50:28 black kernel: [116897.911805] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
Jul 11 18:50:29 black kernel: [116899.053046] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
Jul 11 18:50:29 black kernel: [116899.213067] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup


I will, later, provide more detailed configuration information,
including the other filesystems and more logs. As that will be very long
I plan to send it directly to you, Anand, rather than to the list.

Graham

Re: "btrfs: harden agaist duplicate fsid" spams syslog

[Christoph Anton Mitterer]

I'm also seeing these since quite a while on Debian sid:

Jul 11 13:33:56 heisenberg kernel: BTRFS info (device dm-0): device fsid 60[...]3c devid 1 moved old:/dev/mapper/system new:/dev/dm-0
Jul 11 13:33:56 heisenberg kernel: BTRFS info (device dm-0): device fsid 60[...]3c devid 1 moved old:/dev/dm-0 new:/dev/mapper/system
Jul 11 23:43:35 heisenberg kernel: BTRFS info (device dm-0): device fsid 60[...]3c devid 1 moved old:/dev/mapper/system new:/dev/dm-0
Jul 11 23:43:35 heisenberg kernel: BTRFS info (device dm-0): device fsid 60[...]3c devid 1 moved old:/dev/dm-0 new:/dev/mapper/system

In my case it's a simply dm-crypt layer below the fs.


Some years ago, there was a longer thread on this list about the
fragility of btrfs with respect to accidentally or intentionally
colliding UUIDs.
IIRC there were quite some concerns that this could have even a big
security impact when an attacker e.g. plugs in a device with a certain
UUID and the kernel or userland automatically adds or somehow else uses
such device (just by UUID).
Back then it was said this would be looked into... has anything
happened there?


Cheers,
Chris.

Re: "btrfs: harden agaist duplicate fsid" spams syslog

[Anand Jain]

I am unable to reproduce, I have tried with/without dm-crypt on both
oraclelinux and opensuse (I am yet to try debian).

The patch in $subject is fair, but changing device path indicates
there is some problem in the system. However, I didn't expect
same device pointed by both /dev/dm-x and /dev/mapper/abc would
contended.

One fix for this is to make it a ratelimit print. But then the same
thing happens without notice. If you monitor /proc/self/mounts
probably you will notice that mount device changes every ~2mins.

I will be more keen to find the module which is causing this issue,
that is calling 'btrfs dev scan' every ~2mins or trying to mount
an unmounted device without understanding that its mapper is already
mounted.

Thanks, Anand



On 12/7/19 2:00 AM, Graham Cobb wrote:
> On 11/07/2019 03:46, Anand Jain wrote:
>> Now the question I am trying to understand, why same device is being
>> scanned every 2 mins, even though its already mount-ed. I am guessing
>> its toggling the same device paths trying to mount the device-path
>> which is not mounted. So autofs's check for the device mount seems to
>> be path based.
>>
>> Would you please provide your LVM configs and I believe you are using
>> dm-mapping too. What are the device paths used in the fstab and in grub.
>> And do you see these messages for all devices of
>> 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 or just devid 4? Would you please
>> provide more logs at least a complete cycle of the repeating logs.
> 
> My setup is quite complex, with three btrfs-over-LVM-over-LUKS
> filesystems, so I will explain it fully in a separate message in case it
> is important. Let me first answer your questions regarding
> 4d1ba5af-8b89-4cb5-96c6-55d1f028a202, which was the example I used in my
> initial log extract.
> 
> 4d1b...a202 is a filesystem with a main mount point of /mnt/backup2/:
> 
> black:~# btrfs fi show /mnt/backup2/
> Label: 'snap12tb'  uuid: 4d1ba5af-8b89-4cb5-96c6-55d1f028a202
>          Total devices 2 FS bytes used 10.97TiB
>          devid    1 size 10.82TiB used 10.82TiB path /dev/sdc3
>          devid    4 size 3.62TiB used 199.00GiB path
> /dev/mapper/cryptdata4tb--vg-backup
> 
> In this particular filesystem, it has two devices: one is a real disk
> partition (/dev/sdc3), the other is an LVM logical volume. It has also
> had other LVM devices added and removed at various times, but this is
> the current setup.
> 
> Note: when I added this LV, I used path /dev/mapper/cryptdata4tb--vg-backup.
> 
> black:~# lvdisplay /dev/cryptdata4tb-vg/backup
>    --- Logical volume ---
>    LV Path                /dev/cryptdata4tb-vg/backup
>    LV Name                backup
>    VG Name                cryptdata4tb-vg
>    LV UUID                TZaWfo-goG1-GsNV-GCZL-rpbz-IW0H-gNmXBf
>    LV Write Access        read/write
>    LV Creation host, time black, 2019-07-10 10:40:28 +0100
>    LV Status              available
>    # open                 1
>    LV Size                3.62 TiB
>    Current LE             949089
>    Segments               1
>    Allocation             inherit
>    Read ahead sectors     auto
>    - currently set to     256
>    Block device           254:13
> 
> The LVM logical volume is exposed as /dev/mapper/cryptdata4tb--vg-backup
> which is a symlink (set up by LVM, I believe) to /dev/dm-13.
> 
> For the 4d1b...a202 filesystem I currently only see the messages for
> devid 4. But I presume that is because devid 1 is a real device, which
> only appears in /dev once. I did, for a while, have two LV devices in
> this filesystem and, looking at the old logs, I can see that every 2
> minutes the swapping between /dev/mapper/whatever and /dev/dm-N was
> happening for both LV devids (but not for the physical device devid)
> 
> This particular device is not a root device and I do not believe it is
> referenced in grub or initramfs. It is mounted in /etc/fstab/:
> 
> LABEL=snap12tb  /mnt/backup2    btrfs
> defaults,subvolid=0,noatime,nodiratime,compress=lzo,skip_balance,space_cache=v2
>         0       3
> 
> Note that /dev/disk/by-label/snap12tb is a symlink to the dm-N alias of
> the LV device (set up by LVM or udev or something - not by me):
> 
> black:~# ls -l /dev/disk/by-label/snap12tb
> lrwxrwxrwx 1 root root 11 Jul 11 18:18 /dev/disk/by-label/snap12tb ->
> .../../dm-13
> 
> Here is a log extract of the cycling messages for the 4d1b...a202
> filesystem:
> 
> Jul 11 18:46:28 black kernel: [116657.825658] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> Jul 11 18:46:28 black kernel: [116658.048042] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> Jul 11 18:46:29 black kernel: [116659.157392] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> Jul 11 18:46:29 black kernel: [116659.337504] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> Jul 11 18:48:28 black kernel: [116777.727262] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> Jul 11 18:48:28 black kernel: [116778.019874] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> Jul 11 18:48:29 black kernel: [116779.157038] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> Jul 11 18:48:30 black kernel: [116779.364959] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> Jul 11 18:50:28 black kernel: [116897.705568] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> Jul 11 18:50:28 black kernel: [116897.911805] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> Jul 11 18:50:29 black kernel: [116899.053046] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> Jul 11 18:50:29 black kernel: [116899.213067] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> 
> 
> I will, later, provide more detailed configuration information,
> including the other filesystems and more logs. As that will be very long
> I plan to send it directly to you, Anand, rather than to the list.
> 
> Graham
> 

Re: "btrfs: harden agaist duplicate fsid" spams syslog

[Anand Jain]

On 12/7/19 7:06 AM, Christoph Anton Mitterer wrote:
> I'm also seeing these since quite a while on Debian sid:
> 
> Jul 11 13:33:56 heisenberg kernel: BTRFS info (device dm-0): device fsid 60[...]3c devid 1 moved old:/dev/mapper/system new:/dev/dm-0
> Jul 11 13:33:56 heisenberg kernel: BTRFS info (device dm-0): device fsid 60[...]3c devid 1 moved old:/dev/dm-0 new:/dev/mapper/system
> Jul 11 23:43:35 heisenberg kernel: BTRFS info (device dm-0): device fsid 60[...]3c devid 1 moved old:/dev/mapper/system new:/dev/dm-0
> Jul 11 23:43:35 heisenberg kernel: BTRFS info (device dm-0): device fsid 60[...]3c devid 1 moved old:/dev/dm-0 new:/dev/mapper/system
> 
> In my case it's a simply dm-crypt layer below the fs.
> 
> 
> Some years ago, there was a longer thread on this list about the
> fragility of btrfs with respect to accidentally or intentionally
> colliding UUIDs.

> IIRC there were quite some concerns that this could have even a big
> security impact when an attacker e.g. plugs in a device with a certain
> UUID and the kernel or userland automatically adds or somehow else uses
> such device (just by UUID).

> Back then it was said this would be looked into... has anything
> happened there?

Thanks for refreshing on that report. Looking into it.

-Anand

> 
> Cheers,
> Chris.
> 

Re: "btrfs: harden agaist duplicate fsid" spams syslog

[Graham Cobb]

On 12/07/2019 13:46, Anand Jain wrote:
> I am unable to reproduce, I have tried with/without dm-crypt on both
> oraclelinux and opensuse (I am yet to try debian).

I understand. I am going to be away for a week but I am happy to look
into trying to create a smaller reproducer (for example in a vm) once I
get back.

> The patch in $subject is fair, but changing device path indicates
> there is some problem in the system. However, I didn't expect
> same device pointed by both /dev/dm-x and /dev/mapper/abc would
> contended.

It is weird, because there are other symlinks also pointing to the
device. In my case, lvm sets up both /dev/mapper/cryptdata4tb--vg-backup
and /dev/cryptdata4tb-vg/backup as symlinks to ../dm-13 but only the
first one fights with /dev/dm-13 for the devid.

> One fix for this is to make it a ratelimit print. But then the same
> thing happens without notice. If you monitor /proc/self/mounts
> probably you will notice that mount device changes every ~2mins.

I haven't managed to catch it. Presumably because, according to the
logs, it seems to switch the devices back again within less than a second.

> I will be more keen to find the module which is causing this issue,
> that is calling 'btrfs dev scan' every ~2mins or trying to mount
> an unmounted device without understanding that its mapper is already
> mounted.

Any ideas how we can determine that?

Can I try something like stopping udev for 5 minutes to see if it stops?
Or will that break my system (I can't schedule any downtime until after
I am back)? Note (in case it is relevant) this is a systemd system so
udev is actually systemd-udevd.service.

Thanks
Graham

Re: "btrfs: harden agaist duplicate fsid" spams syslog

[Patrik Lundquist]

On Fri, 12 Jul 2019 at 14:48, Anand Jain <anand.jain@oracle.com> wrote:
> I am unable to reproduce, I have tried with/without dm-crypt on both
> oraclelinux and opensuse (I am yet to try debian).

I'm using Debian testing 4.19.0-5-amd64 without problem. Raid1 with 5
LUKS disks. Mounting with the UUID but not(!) automounted.

Running "btrfs device scan --all-devices" doesn't trigger the fsid move.

$ sudo btrfs fi show /raid/
Label: 'btrfs_pool'  uuid: 4242423a-990c-4650-b615-14fe009b0edd
    Total devices 5 FS bytes used 7.85TiB
    devid    1 size 7.28TiB used 5.85TiB path /dev/mapper/sdb1_crypt
    devid    2 size 1.82TiB used 1.44TiB path /dev/mapper/sda1_crypt
    devid    3 size 1.82TiB used 1.34TiB path /dev/mapper/sdc1_crypt
    devid    4 size 5.46TiB used 4.98TiB path /dev/mapper/sdd1_crypt
    devid    5 size 2.73TiB used 2.25TiB path /dev/mapper/sdf1_crypt

$ ll /dev/dm-*
brw-rw---- 1 root disk 254, 0 jul  9 15:08 /dev/dm-0
brw-rw---- 1 root disk 254, 1 jul  9 15:08 /dev/dm-1
brw-rw---- 1 root disk 254, 2 jul  9 15:08 /dev/dm-2
brw-rw---- 1 root disk 254, 3 jul  9 15:08 /dev/dm-3
brw-rw---- 1 root disk 254, 4 jul  9 15:08 /dev/dm-4

$ ll /dev/mapper/
total 0
drwxr-xr-x  2 root root     160 jul  9 15:08 ./
drwxr-xr-x 18 root root    3640 jul 10 08:16 ../
crw-------  1 root root 10, 236 jul  9 15:08 control
lrwxrwxrwx  1 root root       7 jul  9 15:08 sda1_crypt -> ../dm-0
lrwxrwxrwx  1 root root       7 jul  9 15:08 sdb1_crypt -> ../dm-1
lrwxrwxrwx  1 root root       7 jul  9 15:08 sdc1_crypt -> ../dm-2
lrwxrwxrwx  1 root root       7 jul  9 15:08 sdd1_crypt -> ../dm-3
lrwxrwxrwx  1 root root       7 jul  9 15:08 sdf1_crypt -> ../dm-4

Re: "btrfs: harden agaist duplicate fsid" spams syslog

[Graham Cobb]

On 12/07/2019 14:35, Patrik Lundquist wrote:
> On Fri, 12 Jul 2019 at 14:48, Anand Jain <anand.jain@oracle.com> wrote:
>> I am unable to reproduce, I have tried with/without dm-crypt on both
>> oraclelinux and opensuse (I am yet to try debian).
> 
> I'm using Debian testing 4.19.0-5-amd64 without problem. Raid1 with 5
> LUKS disks. Mounting with the UUID but not(!) automounted.
> 
> Running "btrfs device scan --all-devices" doesn't trigger the fsid move.

Thanks Patrik. So is it something to do with LVM, not dm-crypt, I
wonder? Note that in my case I am using LVM-over-dm-crypt, and it is the
LV that I mount, not the encrypted partition.

[PATCH] btrfs: ratelimit device path change info on mounted device

[Anand Jain]

If there are more than one path to a device, the last scanned path
will map to the mounted FS. In some Linux based os there appears to be a
system script (autofs?) which fails to notice that a device's alternative
path is already mounted, and so the change in device-path gets logged
every ~2mins whenever such a script is active.

kernel: [33017.407252] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
kernel: [33017.522242] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
kernel: [33018.797161] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
kernel: [33019.061631] BTRFS info (device sdc3):
device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup

Fix this by using the ratelimit printk.

Signed-off-by: Anand Jain <anand.jain@oracle.com>
Reported-by: g.btrfs@cobb.uk.net
Reported-by: calestyo@scientia.net
---
 fs/btrfs/volumes.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/fs/btrfs/volumes.c b/fs/btrfs/volumes.c
index a13ddba1ebc3..b4c4add7b5e7 100644
--- a/fs/btrfs/volumes.c
+++ b/fs/btrfs/volumes.c
@@ -1086,7 +1086,7 @@ static noinline struct btrfs_device *device_list_add(const char *path,
 				return ERR_PTR(-EEXIST);
 			}
 			bdput(path_bdev);
-			btrfs_info_in_rcu(device->fs_info,
+			btrfs_info_rl_in_rcu(device->fs_info,
 				"device fsid %pU devid %llu moved old:%s new:%s",
 				disk_super->fsid, devid,
 				rcu_str_deref(device->name), path);
-- 
2.21.0 (Apple Git-120)

Re: [PATCH] btrfs: ratelimit device path change info on mounted device

[Anand Jain]

Graham, Chris,

  I am unable to reproduce, would you be able to try this patch and let 
me know if this fixes the problem?

Thanks, Anand


On 16/7/19 9:59 PM, Anand Jain wrote:
> If there are more than one path to a device, the last scanned path
> will map to the mounted FS. In some Linux based os there appears to be a
> system script (autofs?) which fails to notice that a device's alternative
> path is already mounted, and so the change in device-path gets logged
> every ~2mins whenever such a script is active.
> 
> kernel: [33017.407252] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> kernel: [33017.522242] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> kernel: [33018.797161] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> kernel: [33019.061631] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> 
> Fix this by using the ratelimit printk.
> 
> Signed-off-by: Anand Jain <anand.jain@oracle.com>
> Reported-by: g.btrfs@cobb.uk.net
> Reported-by: calestyo@scientia.net
> ---
>   fs/btrfs/volumes.c | 2 +-
>   1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/fs/btrfs/volumes.c b/fs/btrfs/volumes.c
> index a13ddba1ebc3..b4c4add7b5e7 100644
> --- a/fs/btrfs/volumes.c
> +++ b/fs/btrfs/volumes.c
> @@ -1086,7 +1086,7 @@ static noinline struct btrfs_device *device_list_add(const char *path,
>   				return ERR_PTR(-EEXIST);
>   			}
>   			bdput(path_bdev);
> -			btrfs_info_in_rcu(device->fs_info,
> +			btrfs_info_rl_in_rcu(device->fs_info,
>   				"device fsid %pU devid %llu moved old:%s new:%s",
>   				disk_super->fsid, devid,
>   				rcu_str_deref(device->name), path);
> 

Re: [PATCH] btrfs: ratelimit device path change info on mounted device

[David Sterba]

On Tue, Jul 16, 2019 at 09:59:10PM +0800, Anand Jain wrote:
> If there are more than one path to a device, the last scanned path
> will map to the mounted FS. In some Linux based os there appears to be a
> system script (autofs?) which fails to notice that a device's alternative
> path is already mounted, and so the change in device-path gets logged
> every ~2mins whenever such a script is active.
> 
> kernel: [33017.407252] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> kernel: [33017.522242] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> kernel: [33018.797161] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/mapper/cryptdata4tb--vg-backup new:/dev/dm-13
> kernel: [33019.061631] BTRFS info (device sdc3):
> device fsid 4d1ba5af-8b89-4cb5-96c6-55d1f028a202 devid 4 moved
> old:/dev/dm-13 new:/dev/mapper/cryptdata4tb--vg-backup
> 
> Fix this by using the ratelimit printk.

The ratelimiting will most certainly not stop the repeated messages,
btrfs_info_rl_in_rcu uses the default settings which is to limit within
5 seconds and allow burts of 10 messages.

Re: "btrfs: harden agaist duplicate fsid" spams syslog

[David Sterba]

On Fri, Jul 12, 2019 at 02:32:10PM +0100, Graham Cobb wrote:
> It is weird, because there are other symlinks also pointing to the
> device. In my case, lvm sets up both /dev/mapper/cryptdata4tb--vg-backup
> and /dev/cryptdata4tb-vg/backup as symlinks to ../dm-13 but only the
> first one fights with /dev/dm-13 for the devid.

'btrfs' utility has code to canonicalize the device mapper names and use
only '/dev/mapper' and not /dev/dm-*, but I think systemd/udev has own
utility for device scanning that might not do the translation.

> > One fix for this is to make it a ratelimit print. But then the same
> > thing happens without notice. If you monitor /proc/self/mounts
> > probably you will notice that mount device changes every ~2mins.
> 
> I haven't managed to catch it. Presumably because, according to the
> logs, it seems to switch the devices back again within less than a second.

This looks like some device enumeration takes any name for a given
device and calls scan on it. I have seen that eg. systemd tries to
deactivate a swap partition by all names it found under /dev/disk/* .

> > I will be more keen to find the module which is causing this issue,
> > that is calling 'btrfs dev scan' every ~2mins or trying to mount
> > an unmounted device without understanding that its mapper is already
> > mounted.
> 
> Any ideas how we can determine that?
> 
> Can I try something like stopping udev for 5 minutes to see if it stops?
> Or will that break my system (I can't schedule any downtime until after
> I am back)? Note (in case it is relevant) this is a systemd system so
> udev is actually systemd-udevd.service.

'udevadm monitor' can tell something about the device changes.

We still don't understand what happens but I'm inclined to think that
the fix should be in btrfs scanning code to print the message only once
for a given device with the first name.

The device path must exist in system and can be always traced either to
the /dev/dm-* or to /dev/mapper name, so it's maybe a minor usability
issue expecing user to resolve the path to see the pretty name.