[PATCH] btrfs: improve messages when devices rescanned

[PATCH] btrfs: improve messages when devices rescanned

[Anand Jain]

Systems booting without the initramfs seems to scan an unusual kind
of device path. And at a later time, the device is updated to the
correct path. We generally print the process name and PID of the process
scanning the device but we don't capture the same information if the
device path is rescanned with a different pathname.

But the current message is too long, so drop the unwanted words and add
process name and PID.

While at this also update the duplicate device warning to include the
process name and PID.

Reported-by: https://bugzilla.kernel.org/show_bug.cgi?id=89721
Signed-off-by: Anand Jain <anand.jain@oracle.com>
---
 fs/btrfs/volumes.c | 14 ++++++++------
 1 file changed, 8 insertions(+), 6 deletions(-)

diff --git a/fs/btrfs/volumes.c b/fs/btrfs/volumes.c
index dc81646b13c0..c386ad722ae1 100644
--- a/fs/btrfs/volumes.c
+++ b/fs/btrfs/volumes.c
@@ -942,16 +942,18 @@ static noinline struct btrfs_device *device_list_add(const char *path,
 				bdput(path_bdev);
 				mutex_unlock(&fs_devices->device_list_mutex);
 				btrfs_warn_in_rcu(device->fs_info,
-			"duplicate device fsid:devid for %pU:%llu old:%s new:%s",
-					disk_super->fsid, devid,
-					rcu_str_deref(device->name), path);
+	"duplicate device %s devid %llu generation %llu scanned by %s (%d)",
+						  path, devid, found_transid,
+						  current->comm,
+						  task_pid_nr(current));
 				return ERR_PTR(-EEXIST);
 			}
 			bdput(path_bdev);
 			btrfs_info_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);
+				"device path %s changed to %s by %s (pid %d)",
+					  rcu_str_deref(device->name),
+					  path, current->comm,
+					  task_pid_nr(current));
 		}
 
 		name = rcu_string_strdup(path, GFP_NOFS);
-- 
2.25.1

Re: [PATCH] btrfs: improve messages when devices rescanned

[Nikolay Borisov]

On 3.09.20 г. 10:27 ч., Anand Jain wrote:
> Systems booting without the initramfs seems to scan an unusual kind
> of device path. And at a later time, the device is updated to the
> correct path. We generally print the process name and PID of the process
> scanning the device but we don't capture the same information if the
> device path is rescanned with a different pathname.
> 
> But the current message is too long, so drop the unwanted words and add
> process name and PID.
> 
> While at this also update the duplicate device warning to include the
> process name and PID.
> 
> Reported-by: https://bugzilla.kernel.org/show_bug.cgi?id=89721
> Signed-off-by: Anand Jain <anand.jain@oracle.com>
> ---
>  fs/btrfs/volumes.c | 14 ++++++++------
>  1 file changed, 8 insertions(+), 6 deletions(-)
> 
> diff --git a/fs/btrfs/volumes.c b/fs/btrfs/volumes.c
> index dc81646b13c0..c386ad722ae1 100644
> --- a/fs/btrfs/volumes.c
> +++ b/fs/btrfs/volumes.c
> @@ -942,16 +942,18 @@ static noinline struct btrfs_device *device_list_add(const char *path,
>  				bdput(path_bdev);
>  				mutex_unlock(&fs_devices->device_list_mutex);
>  				btrfs_warn_in_rcu(device->fs_info,
> -			"duplicate device fsid:devid for %pU:%llu old:%s new:%s",
> -					disk_super->fsid, devid,
> -					rcu_str_deref(device->name), path);
> +	"duplicate device %s devid %llu generation %llu scanned by %s (%d)",
> +						  path, devid, found_transid,
> +						  current->comm,
> +						  task_pid_nr(current));
>  				return ERR_PTR(-EEXIST);
>  			}
>  			bdput(path_bdev);
>  			btrfs_info_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);
> +				"device path %s changed to %s by %s (pid %d)",
> +					  rcu_str_deref(device->name),
> +					  path, current->comm,
> +					  task_pid_nr(current));

This 2nd messages is misleading, it's not the process calling
device_list_add which have changed the path per-se but rather it sees
the changed path. It's not possible to know why it changed in this
context. The idea here is "

"Process %pid saw different dev path %new_dev_path for dev %old_path"

>  		}
>  
>  		name = rcu_string_strdup(path, GFP_NOFS);
> 

Re: [PATCH] btrfs: improve messages when devices rescanned

[Anand Jain]

On 3/9/20 4:16 pm, Nikolay Borisov wrote:
> 
> 
> On 3.09.20 г. 10:27 ч., Anand Jain wrote:
>> Systems booting without the initramfs seems to scan an unusual kind
>> of device path. And at a later time, the device is updated to the
>> correct path. We generally print the process name and PID of the process
>> scanning the device but we don't capture the same information if the
>> device path is rescanned with a different pathname.
>>
>> But the current message is too long, so drop the unwanted words and add
>> process name and PID.
>>
>> While at this also update the duplicate device warning to include the
>> process name and PID.
>>
>> Reported-by: https://bugzilla.kernel.org/show_bug.cgi?id=89721
>> Signed-off-by: Anand Jain <anand.jain@oracle.com>
>> ---
>>   fs/btrfs/volumes.c | 14 ++++++++------
>>   1 file changed, 8 insertions(+), 6 deletions(-)
>>
>> diff --git a/fs/btrfs/volumes.c b/fs/btrfs/volumes.c
>> index dc81646b13c0..c386ad722ae1 100644
>> --- a/fs/btrfs/volumes.c
>> +++ b/fs/btrfs/volumes.c
>> @@ -942,16 +942,18 @@ static noinline struct btrfs_device *device_list_add(const char *path,
>>   				bdput(path_bdev);
>>   				mutex_unlock(&fs_devices->device_list_mutex);
>>   				btrfs_warn_in_rcu(device->fs_info,
>> -			"duplicate device fsid:devid for %pU:%llu old:%s new:%s",
>> -					disk_super->fsid, devid,
>> -					rcu_str_deref(device->name), path);
>> +	"duplicate device %s devid %llu generation %llu scanned by %s (%d)",
>> +						  path, devid, found_transid,
>> +						  current->comm,
>> +						  task_pid_nr(current));
>>   				return ERR_PTR(-EEXIST);
>>   			}
>>   			bdput(path_bdev);
>>   			btrfs_info_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);
>> +				"device path %s changed to %s by %s (pid %d)",
>> +					  rcu_str_deref(device->name),
>> +					  path, current->comm,
>> +					  task_pid_nr(current));
> 
> This 2nd messages is misleading, it's not the process calling
> device_list_add which have changed the path per-se but rather it sees
> the changed path. It's not possible to know why it changed in this
> context. The idea here is "
> 
> "Process %pid saw different dev path %new_dev_path for dev %old_path"

   Hm. How about we stick to the usual scanned by. That is..

   "device path %s changed to %s scanned by %s (pid %d)",

Thanks, Anand

> 
>>   		}
>>   
>>   		name = rcu_string_strdup(path, GFP_NOFS);
>>

Re: [PATCH] btrfs: improve messages when devices rescanned

[Nikolay Borisov]

On 3.09.20 г. 12:41 ч., Anand Jain wrote:
> On 3/9/20 4:16 pm, Nikolay Borisov wrote:
>>
>>
>> On 3.09.20 г. 10:27 ч., Anand Jain wrote:
>>> Systems booting without the initramfs seems to scan an unusual kind
>>> of device path. And at a later time, the device is updated to the
>>> correct path. We generally print the process name and PID of the process
>>> scanning the device but we don't capture the same information if the
>>> device path is rescanned with a different pathname.
>>>
>>> But the current message is too long, so drop the unwanted words and add
>>> process name and PID.
>>>
>>> While at this also update the duplicate device warning to include the
>>> process name and PID.
>>>
>>> Reported-by: https://bugzilla.kernel.org/show_bug.cgi?id=89721
>>> Signed-off-by: Anand Jain <anand.jain@oracle.com>
>>> ---
>>>   fs/btrfs/volumes.c | 14 ++++++++------
>>>   1 file changed, 8 insertions(+), 6 deletions(-)
>>>
>>> diff --git a/fs/btrfs/volumes.c b/fs/btrfs/volumes.c
>>> index dc81646b13c0..c386ad722ae1 100644
>>> --- a/fs/btrfs/volumes.c
>>> +++ b/fs/btrfs/volumes.c
>>> @@ -942,16 +942,18 @@ static noinline struct btrfs_device
>>> *device_list_add(const char *path,
>>>                   bdput(path_bdev);
>>>                   mutex_unlock(&fs_devices->device_list_mutex);
>>>                   btrfs_warn_in_rcu(device->fs_info,
>>> -            "duplicate device fsid:devid for %pU:%llu old:%s new:%s",
>>> -                    disk_super->fsid, devid,
>>> -                    rcu_str_deref(device->name), path);
>>> +    "duplicate device %s devid %llu generation %llu scanned by %s
>>> (%d)",
>>> +                          path, devid, found_transid,
>>> +                          current->comm,
>>> +                          task_pid_nr(current));
>>>                   return ERR_PTR(-EEXIST);
>>>               }
>>>               bdput(path_bdev);
>>>               btrfs_info_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);
>>> +                "device path %s changed to %s by %s (pid %d)",
>>> +                      rcu_str_deref(device->name),
>>> +                      path, current->comm,
>>> +                      task_pid_nr(current));
>>
>> This 2nd messages is misleading, it's not the process calling
>> device_list_add which have changed the path per-se but rather it sees
>> the changed path. It's not possible to know why it changed in this
>> context. The idea here is "
>>
>> "Process %pid saw different dev path %new_dev_path for dev %old_path"
> 
>   Hm. How about we stick to the usual scanned by. That is..
> 
>   "device path %s changed to %s scanned by %s (pid %d)",

works for me.

> 
> Thanks, Anand
> 
>>
>>>           }
>>>             name = rcu_string_strdup(path, GFP_NOFS);
>>>
> 

Re: [PATCH] btrfs: improve messages when devices rescanned

[David Sterba]

On Thu, Sep 03, 2020 at 12:42:09PM +0300, Nikolay Borisov wrote:
> 
> 
> On 3.09.20 г. 12:41 ч., Anand Jain wrote:
> > On 3/9/20 4:16 pm, Nikolay Borisov wrote:
> >>
> >>
> >> On 3.09.20 г. 10:27 ч., Anand Jain wrote:
> >>> Systems booting without the initramfs seems to scan an unusual kind
> >>> of device path. And at a later time, the device is updated to the
> >>> correct path. We generally print the process name and PID of the process
> >>> scanning the device but we don't capture the same information if the
> >>> device path is rescanned with a different pathname.
> >>>
> >>> But the current message is too long, so drop the unwanted words and add
> >>> process name and PID.
> >>>
> >>> While at this also update the duplicate device warning to include the
> >>> process name and PID.
> >>>
> >>> Reported-by: https://bugzilla.kernel.org/show_bug.cgi?id=89721
> >>> Signed-off-by: Anand Jain <anand.jain@oracle.com>
> >>> ---
> >>>   fs/btrfs/volumes.c | 14 ++++++++------
> >>>   1 file changed, 8 insertions(+), 6 deletions(-)
> >>>
> >>> diff --git a/fs/btrfs/volumes.c b/fs/btrfs/volumes.c
> >>> index dc81646b13c0..c386ad722ae1 100644
> >>> --- a/fs/btrfs/volumes.c
> >>> +++ b/fs/btrfs/volumes.c
> >>> @@ -942,16 +942,18 @@ static noinline struct btrfs_device
> >>> *device_list_add(const char *path,
> >>>                   bdput(path_bdev);
> >>>                   mutex_unlock(&fs_devices->device_list_mutex);
> >>>                   btrfs_warn_in_rcu(device->fs_info,
> >>> -            "duplicate device fsid:devid for %pU:%llu old:%s new:%s",
> >>> -                    disk_super->fsid, devid,
> >>> -                    rcu_str_deref(device->name), path);
> >>> +    "duplicate device %s devid %llu generation %llu scanned by %s
> >>> (%d)",
> >>> +                          path, devid, found_transid,
> >>> +                          current->comm,
> >>> +                          task_pid_nr(current));
> >>>                   return ERR_PTR(-EEXIST);
> >>>               }
> >>>               bdput(path_bdev);
> >>>               btrfs_info_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);
> >>> +                "device path %s changed to %s by %s (pid %d)",
> >>> +                      rcu_str_deref(device->name),
> >>> +                      path, current->comm,
> >>> +                      task_pid_nr(current));
> >>
> >> This 2nd messages is misleading, it's not the process calling
> >> device_list_add which have changed the path per-se but rather it sees
> >> the changed path. It's not possible to know why it changed in this
> >> context. The idea here is "
> >>
> >> "Process %pid saw different dev path %new_dev_path for dev %old_path"
> > 
> >   Hm. How about we stick to the usual scanned by. That is..
> > 
> >   "device path %s changed to %s scanned by %s (pid %d)",
> 
> works for me.

The device id should still be there, the filesystem is referred to by
the device name as printed by btrfs_info* so its uuid can be dropped
from the message itself.

[PATCH v2] btrfs: improve messages when devices rescanned

[Anand Jain]

Systems booting without the initramfs seems to scan an unusual kind
of device path. And at a later time, the device is updated to the
correct path. We generally print the process name and PID of the process
scanning the device but we don't capture the same information if the
device path is rescanned with a different pathname.

But the current message is too long, so drop the unwanted words and add
process name and PID.

While at this also update the duplicate device warning to include the
process name and PID.

Reported-by: https://bugzilla.kernel.org/show_bug.cgi?id=89721
Signed-off-by: Anand Jain <anand.jain@oracle.com>
---
v2: adds devid and scanned

 fs/btrfs/volumes.c | 14 ++++++++------
 1 file changed, 8 insertions(+), 6 deletions(-)

diff --git a/fs/btrfs/volumes.c b/fs/btrfs/volumes.c
index dc81646b13c0..60f8ea7232b5 100644
--- a/fs/btrfs/volumes.c
+++ b/fs/btrfs/volumes.c
@@ -942,16 +942,18 @@ static noinline struct btrfs_device *device_list_add(const char *path,
 				bdput(path_bdev);
 				mutex_unlock(&fs_devices->device_list_mutex);
 				btrfs_warn_in_rcu(device->fs_info,
-			"duplicate device fsid:devid for %pU:%llu old:%s new:%s",
-					disk_super->fsid, devid,
-					rcu_str_deref(device->name), path);
+	"duplicate device %s devid %llu generation %llu scanned by %s (%d)",
+						  path, devid, found_transid,
+						  current->comm,
+						  task_pid_nr(current));
 				return ERR_PTR(-EEXIST);
 			}
 			bdput(path_bdev);
 			btrfs_info_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);
+	"devid %llu device path %s changed to %s scanned by %s (pid %d)",
+					  devid, rcu_str_deref(device->name),
+					  path, current->comm,
+					  task_pid_nr(current));
 		}
 
 		name = rcu_string_strdup(path, GFP_NOFS);
-- 
2.25.1

Re: [PATCH v2] btrfs: improve messages when devices rescanned

[David Sterba]

On Thu, Sep 03, 2020 at 09:30:12PM +0800, Anand Jain wrote:
> --- a/fs/btrfs/volumes.c
> +++ b/fs/btrfs/volumes.c
> +	"duplicate device %s devid %llu generation %llu scanned by %s (%d)",

> +	"devid %llu device path %s changed to %s scanned by %s (pid %d)",

I haven't found a wording that would make the messages follow the same
pattern, eg. that both describe the change and then print the details.
The path change should keep the devid first and the old/new paths
together. So let it be the way it was sent, with the 'pid' removed.
Added to misc-next, thanks.