diff mbox

[RFC] vfs: add mount umount logs

Message ID 20170518100804.25538-1-anand.jain@oracle.com (mailing list archive)
State New, archived
Headers show

Commit Message

Anand Jain May 18, 2017, 10:08 a.m. UTC
By looking at the logs we should be able to know when was the FS
mounted and unmounted and the options used, so to help forensic
investigations.

Signed-off-by: Anand Jain <anand.jain@oracle.com>
---
You may want to know that, during boot and shutdown this
adds roughly 25 lines more logs depending on the config, and it
logs even for non block device FS, such as proc, sysfs ..etc.
And blockdev FS only check will eliminate overlay as well, which
is kind of defeats the purpose.
Further, just to highlight if your test script involves mount and
umount, which probably all of fstests does, it will add logs when
FS is mounted and umounted.
Still IMO, these logs are useful for the end purpose as mentioned
above. Its for your feedback. Thanks.

 fs/namespace.c | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

Comments

Carlos Maiolino May 18, 2017, 12:23 p.m. UTC | #1
On Thu, May 18, 2017 at 06:08:04PM +0800, Anand Jain wrote:
> By looking at the logs we should be able to know when was the FS
> mounted and unmounted and the options used, so to help forensic
> investigations.
> 
> Signed-off-by: Anand Jain <anand.jain@oracle.com>
> ---
> You may want to know that, during boot and shutdown this
> adds roughly 25 lines more logs depending on the config, and it
> logs even for non block device FS, such as proc, sysfs ..etc.
> And blockdev FS only check will eliminate overlay as well, which
> is kind of defeats the purpose.
> Further, just to highlight if your test script involves mount and
> umount, which probably all of fstests does, it will add logs when
> FS is mounted and umounted.
> Still IMO, these logs are useful for the end purpose as mentioned
> above. Its for your feedback. Thanks.
> 
>  fs/namespace.c | 15 +++++++++++++++
>  1 file changed, 15 insertions(+)
> 
> diff --git a/fs/namespace.c b/fs/namespace.c
> index b3b115bd4e1e..78375b6f8330 100644
> --- a/fs/namespace.c
> +++ b/fs/namespace.c
> @@ -1686,6 +1686,8 @@ SYSCALL_DEFINE2(umount, char __user *, name, int, flags)
>  	struct mount *mnt;
>  	int retval;
>  	int lookup_flags = 0;
> +	struct super_block *sb;
> +	char umntlog[256] = {0};
>  
>  	if (flags & ~(MNT_FORCE | MNT_DETACH | MNT_EXPIRE | UMOUNT_NOFOLLOW))
>  		return -EINVAL;
> @@ -1711,7 +1713,15 @@ SYSCALL_DEFINE2(umount, char __user *, name, int, flags)
>  	if (flags & MNT_FORCE && !capable(CAP_SYS_ADMIN))
>  		goto dput_and_out;
>  
> +	sb = mnt->mnt.mnt_sb;
> +	snprintf(umntlog, sizeof(umntlog), "umount %s dev:%s flags:%d",
> +		sb->s_type->name, sb->s_id, flags);
> +

This will log a message when the umount has been started, but it won't by any
chance be a confirmation the filesystem has been properly unmounted, wouldn't be
better to log it after the FS has been properly unmounted, or, change the
message to something like "umount started"?

Although, from a forensic POV, would be better to have an "unmount started" +
"unmount finished".

>  	retval = do_umount(mnt, flags);
> +
> +	if (!retval)
> +		printk(KERN_NOTICE "%s\n", umntlog);
> +
>  dput_and_out:
>  	/* we mustn't call path_put() as that would clear mnt_expiry_mark */
>  	dput(path.dentry);
> @@ -2833,6 +2843,11 @@ long do_mount(const char *dev_name, const char __user *dir_name,
>  	else
>  		retval = do_new_mount(&path, type_page, flags, mnt_flags,
>  				      dev_name, data_page);
> +
> +	if (!retval)
> +		printk(KERN_NOTICE "mount %s dev:%s dir:%pd flags:0x%lX opt:%s\n",
> +			type_page, dev_name, path.dentry, flags, (char *)data_page);
> +
>  dput_out:
>  	path_put(&path);
>  	return retval;
> -- 
> 2.10.0
>
Darrick J. Wong May 18, 2017, 5:39 p.m. UTC | #2
On Thu, May 18, 2017 at 06:08:04PM +0800, Anand Jain wrote:
> By looking at the logs we should be able to know when was the FS
> mounted and unmounted and the options used, so to help forensic
> investigations.
> 
> Signed-off-by: Anand Jain <anand.jain@oracle.com>
> ---
> You may want to know that, during boot and shutdown this
> adds roughly 25 lines more logs depending on the config, and it
> logs even for non block device FS, such as proc, sysfs ..etc.
> And blockdev FS only check will eliminate overlay as well, which
> is kind of defeats the purpose.
> Further, just to highlight if your test script involves mount and
> umount, which probably all of fstests does, it will add logs when
> FS is mounted and umounted.
> Still IMO, these logs are useful for the end purpose as mentioned
> above. Its for your feedback. Thanks.

XFS already logs its own unmounts.  I prefer to let each filesystem log
its own unmount, because then the mount/unmount messages also have the
same prefix as all other messages coming from that filesystem driver.

>  fs/namespace.c | 15 +++++++++++++++
>  1 file changed, 15 insertions(+)
> 
> diff --git a/fs/namespace.c b/fs/namespace.c
> index b3b115bd4e1e..78375b6f8330 100644
> --- a/fs/namespace.c
> +++ b/fs/namespace.c
> @@ -1686,6 +1686,8 @@ SYSCALL_DEFINE2(umount, char __user *, name, int, flags)
>  	struct mount *mnt;
>  	int retval;
>  	int lookup_flags = 0;
> +	struct super_block *sb;
> +	char umntlog[256] = {0};

Kind of a lot of stack space...

--D

>  
>  	if (flags & ~(MNT_FORCE | MNT_DETACH | MNT_EXPIRE | UMOUNT_NOFOLLOW))
>  		return -EINVAL;
> @@ -1711,7 +1713,15 @@ SYSCALL_DEFINE2(umount, char __user *, name, int, flags)
>  	if (flags & MNT_FORCE && !capable(CAP_SYS_ADMIN))
>  		goto dput_and_out;
>  
> +	sb = mnt->mnt.mnt_sb;
> +	snprintf(umntlog, sizeof(umntlog), "umount %s dev:%s flags:%d",
> +		sb->s_type->name, sb->s_id, flags);
> +
>  	retval = do_umount(mnt, flags);
> +
> +	if (!retval)
> +		printk(KERN_NOTICE "%s\n", umntlog);
> +
>  dput_and_out:
>  	/* we mustn't call path_put() as that would clear mnt_expiry_mark */
>  	dput(path.dentry);
> @@ -2833,6 +2843,11 @@ long do_mount(const char *dev_name, const char __user *dir_name,
>  	else
>  		retval = do_new_mount(&path, type_page, flags, mnt_flags,
>  				      dev_name, data_page);
> +
> +	if (!retval)
> +		printk(KERN_NOTICE "mount %s dev:%s dir:%pd flags:0x%lX opt:%s\n",
> +			type_page, dev_name, path.dentry, flags, (char *)data_page);
> +
>  dput_out:
>  	path_put(&path);
>  	return retval;
> -- 
> 2.10.0
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Anand Jain May 18, 2017, 10:04 p.m. UTC | #3
On 05/18/2017 08:23 PM, Carlos Maiolino wrote:
> On Thu, May 18, 2017 at 06:08:04PM +0800, Anand Jain wrote:
>> By looking at the logs we should be able to know when was the FS
>> mounted and unmounted and the options used, so to help forensic
>> investigations.
>>
>> Signed-off-by: Anand Jain <anand.jain@oracle.com>
>> ---
>> You may want to know that, during boot and shutdown this
>> adds roughly 25 lines more logs depending on the config, and it
>> logs even for non block device FS, such as proc, sysfs ..etc.
>> And blockdev FS only check will eliminate overlay as well, which
>> is kind of defeats the purpose.
>> Further, just to highlight if your test script involves mount and
>> umount, which probably all of fstests does, it will add logs when
>> FS is mounted and umounted.
>> Still IMO, these logs are useful for the end purpose as mentioned
>> above. Its for your feedback. Thanks.
>>
>>  fs/namespace.c | 15 +++++++++++++++
>>  1 file changed, 15 insertions(+)
>>
>> diff --git a/fs/namespace.c b/fs/namespace.c
>> index b3b115bd4e1e..78375b6f8330 100644
>> --- a/fs/namespace.c
>> +++ b/fs/namespace.c
>> @@ -1686,6 +1686,8 @@ SYSCALL_DEFINE2(umount, char __user *, name, int, flags)
>>  	struct mount *mnt;
>>  	int retval;
>>  	int lookup_flags = 0;
>> +	struct super_block *sb;
>> +	char umntlog[256] = {0};
>>
>>  	if (flags & ~(MNT_FORCE | MNT_DETACH | MNT_EXPIRE | UMOUNT_NOFOLLOW))
>>  		return -EINVAL;
>> @@ -1711,7 +1713,15 @@ SYSCALL_DEFINE2(umount, char __user *, name, int, flags)
>>  	if (flags & MNT_FORCE && !capable(CAP_SYS_ADMIN))
>>  		goto dput_and_out;
>>
>> +	sb = mnt->mnt.mnt_sb;
>> +	snprintf(umntlog, sizeof(umntlog), "umount %s dev:%s flags:%d",
>> +		sb->s_type->name, sb->s_id, flags);
>> +
>
> This will log a message when the umount has been started, but it won't by any
> chance be a confirmation the filesystem has been properly unmounted, wouldn't be
> better to log it after the FS has been properly unmounted, or, change the
> message to something like "umount started"?
>
> Although, from a forensic POV, would be better to have an "unmount started" +
> "unmount finished".


  hm. further below it logs if and only if the umount is successful.
  We don't need user error (such as busy) here, kernel logs aren't
  for that purpose.

Thanks, Anand


>>  	retval = do_umount(mnt, flags);
>> +
>> +	if (!retval)
>> +		printk(KERN_NOTICE "%s\n", umntlog);
>> +
>>  dput_and_out:
>>  	/* we mustn't call path_put() as that would clear mnt_expiry_mark */
>>  	dput(path.dentry);
>> @@ -2833,6 +2843,11 @@ long do_mount(const char *dev_name, const char __user *dir_name,
>>  	else
>>  		retval = do_new_mount(&path, type_page, flags, mnt_flags,
>>  				      dev_name, data_page);
>> +
>> +	if (!retval)
>> +		printk(KERN_NOTICE "mount %s dev:%s dir:%pd flags:0x%lX opt:%s\n",
>> +			type_page, dev_name, path.dentry, flags, (char *)data_page);
>> +
>>  dput_out:
>>  	path_put(&path);
>>  	return retval;
>> --
>> 2.10.0
>>
>
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Anand Jain May 19, 2017, 12:17 a.m. UTC | #4
On 05/19/2017 01:39 AM, Darrick J. Wong wrote:
> On Thu, May 18, 2017 at 06:08:04PM +0800, Anand Jain wrote:
>> By looking at the logs we should be able to know when was the FS
>> mounted and unmounted and the options used, so to help forensic
>> investigations.
>>
>> Signed-off-by: Anand Jain <anand.jain@oracle.com>
>> ---
>> You may want to know that, during boot and shutdown this
>> adds roughly 25 lines more logs depending on the config, and it
>> logs even for non block device FS, such as proc, sysfs ..etc.
>> And blockdev FS only check will eliminate overlay as well, which
>> is kind of defeats the purpose.
>> Further, just to highlight if your test script involves mount and
>> umount, which probably all of fstests does, it will add logs when
>> FS is mounted and umounted.
>> Still IMO, these logs are useful for the end purpose as mentioned
>> above. Its for your feedback. Thanks.
>
> XFS already logs its own unmounts.

  Nice. as far as I know its only in XFS.

>  I prefer to let each filesystem log
> its own unmount, because then the mount/unmount messages also have the
> same prefix as all other messages coming from that filesystem driver.

  Ok. One nitpick though there are other mount types (remount, bind..),
  and subsequent mounts of the same FS and FS driver can't log them
  effectively.

>>  fs/namespace.c | 15 +++++++++++++++
>>  1 file changed, 15 insertions(+)
>>
>> diff --git a/fs/namespace.c b/fs/namespace.c
>> index b3b115bd4e1e..78375b6f8330 100644
>> --- a/fs/namespace.c
>> +++ b/fs/namespace.c
>> @@ -1686,6 +1686,8 @@ SYSCALL_DEFINE2(umount, char __user *, name, int, flags)
>>  	struct mount *mnt;
>>  	int retval;
>>  	int lookup_flags = 0;
>> +	struct super_block *sb;
>> +	char umntlog[256] = {0};
>
> Kind of a lot of stack space...

   oh ok. Will fix it, if we are ok to add this change at namespace.c

Thanks, Anand


> --D
>
>>
>>  	if (flags & ~(MNT_FORCE | MNT_DETACH | MNT_EXPIRE | UMOUNT_NOFOLLOW))
>>  		return -EINVAL;
>> @@ -1711,7 +1713,15 @@ SYSCALL_DEFINE2(umount, char __user *, name, int, flags)
>>  	if (flags & MNT_FORCE && !capable(CAP_SYS_ADMIN))
>>  		goto dput_and_out;
>>
>> +	sb = mnt->mnt.mnt_sb;
>> +	snprintf(umntlog, sizeof(umntlog), "umount %s dev:%s flags:%d",
>> +		sb->s_type->name, sb->s_id, flags);
>> +
>>  	retval = do_umount(mnt, flags);
>> +
>> +	if (!retval)
>> +		printk(KERN_NOTICE "%s\n", umntlog);
>> +
>>  dput_and_out:
>>  	/* we mustn't call path_put() as that would clear mnt_expiry_mark */
>>  	dput(path.dentry);
>> @@ -2833,6 +2843,11 @@ long do_mount(const char *dev_name, const char __user *dir_name,
>>  	else
>>  		retval = do_new_mount(&path, type_page, flags, mnt_flags,
>>  				      dev_name, data_page);
>> +
>> +	if (!retval)
>> +		printk(KERN_NOTICE "mount %s dev:%s dir:%pd flags:0x%lX opt:%s\n",
>> +			type_page, dev_name, path.dentry, flags, (char *)data_page);
>> +
>>  dput_out:
>>  	path_put(&path);
>>  	return retval;
>> --
>> 2.10.0
>>
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Theodore Ts'o May 19, 2017, 3:01 p.m. UTC | #5
On Fri, May 19, 2017 at 08:17:55AM +0800, Anand Jain wrote:
> > XFS already logs its own unmounts.
> 
>  Nice. as far as I know its only in XFS.

Ext4 logs mounts, but not unmounts.

> >  I prefer to let each filesystem log
> > its own unmount, because then the mount/unmount messages also have the
> > same prefix as all other messages coming from that filesystem driver.
> 
>  Ok. One nitpick though there are other mount types (remount, bind..),
>  and subsequent mounts of the same FS and FS driver can't log them
>  effectively.

The other issue is there is a difference between when an unmount is
started, or when a file system is unmounted in one namespace, and when
the file system as a whole is unmounted by the low-level because there
are no longer any references to the file system in any namespace.

More than once I've gotten a bug report for ext4 that was really
caused by the fact that some program had forked a daemon process in
its own namespace, so when the USB thumbdrive was unmounted, it wasn't
*really* unmounted.  So being able to clearly express that in the logs
is also a good thing.

I think the way to do that is to have one set of logs for when the
file system is unmounted from one mount namespace (or from a bind
mount), with perhaps an indication of the number of remaining
refcounts, and to make this be distinct from the unmount of the
underlying low file system code, which should be logged by the file
system code itself.

					- Ted
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Colin Walters May 19, 2017, 3:17 p.m. UTC | #6
On Thu, May 18, 2017, at 06:08 AM, Anand Jain wrote:
> By looking at the logs we should be able to know when was the FS
> mounted and unmounted and the options used, so to help forensic
> investigations.

Worth noting here that systemd already tracks mounts (via monitoring /proc/self/mountinfo) and logs
them to the journal, and for mounts it initiates, logs both start and completion.
It doesn't log the options right now, but that wouldn't be hard to add (particularly
since systemd has structured logging).

On the flip side of course that's only for mount namespaces where systemd is
used, and given user namespaces, a lot of use cases don't involve a systemd-per-container.

But that said, I find the log spam today from e.g. docker + devicemapper + xfs
annoying, and switching to overlay2 fixed that as a side effect which is nice.
Having overlay2 log would reintroduce that problem.
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Anand Jain May 24, 2017, 8:20 a.m. UTC | #7
Thanks for comments.

> But that said, I find the log spam today from e.g. docker + devicemapper + xfs
> annoying, and switching to overlay2 fixed that as a side effect which is nice.
> Having overlay2 log would reintroduce that problem.

You are right, docker with overlay2 logs additional 6 lines during 
container run. Though originally I was thinking overlay logs are 
important, now I have to log only FS of type FS_REQUIRES_DEV. With this 
its just two lines, during docker run.

Added this to v2.

Thanks, Anand
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Anand Jain May 24, 2017, 8:26 a.m. UTC | #8
Thanks for the comments.

On 05/19/2017 11:01 PM, Theodore Ts'o wrote:
> On Fri, May 19, 2017 at 08:17:55AM +0800, Anand Jain wrote:
>>> XFS already logs its own unmounts.
>>
>>  Nice. as far as I know its only in XFS.
>
> Ext4 logs mounts, but not unmounts.
>
>>>  I prefer to let each filesystem log
>>> its own unmount, because then the mount/unmount messages also have the
>>> same prefix as all other messages coming from that filesystem driver.
>>
>>  Ok. One nitpick though there are other mount types (remount, bind..),
>>  and subsequent mounts of the same FS and FS driver can't log them
>>  effectively.
>
> The other issue is there is a difference between when an unmount is
> started, or when a file system is unmounted in one namespace, and when
> the file system as a whole is unmounted by the low-level because there
> are no longer any references to the file system in any namespace.

> More than once I've gotten a bug report for ext4 that was really
> caused by the fact that some program had forked a daemon process in
> its own namespace, so when the USB thumbdrive was unmounted, it wasn't
> *really* unmounted.  So being able to clearly express that in the logs
> is also a good thing.

  Thanks.

> I think the way to do that is to have one set of logs for when the
> file system is unmounted from one mount namespace (or from a bind
> mount), with perhaps an indication of the number of remaining
> refcounts, and to make this be distinct from the unmount of the
> underlying low file system code, which should be logged by the file
> system code itself.

  Thanks for suggesting. I have added sb->s_active in V2 in the ML.
  And s_active value taken after mount and before umount, so it
  may be a little confusing that the number is not seen as decremented
  when umount is run. Also I didn't want to manipulate it (like -1) at
  the time of logging. Unless if there is a better parameter to track
  though.

Thanks, Anand

> 					- Ted

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
diff mbox

Patch

diff --git a/fs/namespace.c b/fs/namespace.c
index b3b115bd4e1e..78375b6f8330 100644
--- a/fs/namespace.c
+++ b/fs/namespace.c
@@ -1686,6 +1686,8 @@  SYSCALL_DEFINE2(umount, char __user *, name, int, flags)
 	struct mount *mnt;
 	int retval;
 	int lookup_flags = 0;
+	struct super_block *sb;
+	char umntlog[256] = {0};
 
 	if (flags & ~(MNT_FORCE | MNT_DETACH | MNT_EXPIRE | UMOUNT_NOFOLLOW))
 		return -EINVAL;
@@ -1711,7 +1713,15 @@  SYSCALL_DEFINE2(umount, char __user *, name, int, flags)
 	if (flags & MNT_FORCE && !capable(CAP_SYS_ADMIN))
 		goto dput_and_out;
 
+	sb = mnt->mnt.mnt_sb;
+	snprintf(umntlog, sizeof(umntlog), "umount %s dev:%s flags:%d",
+		sb->s_type->name, sb->s_id, flags);
+
 	retval = do_umount(mnt, flags);
+
+	if (!retval)
+		printk(KERN_NOTICE "%s\n", umntlog);
+
 dput_and_out:
 	/* we mustn't call path_put() as that would clear mnt_expiry_mark */
 	dput(path.dentry);
@@ -2833,6 +2843,11 @@  long do_mount(const char *dev_name, const char __user *dir_name,
 	else
 		retval = do_new_mount(&path, type_page, flags, mnt_flags,
 				      dev_name, data_page);
+
+	if (!retval)
+		printk(KERN_NOTICE "mount %s dev:%s dir:%pd flags:0x%lX opt:%s\n",
+			type_page, dev_name, path.dentry, flags, (char *)data_page);
+
 dput_out:
 	path_put(&path);
 	return retval;