Re: bpfilter logging write errors in dmesg

[Christoph Hellwig <hch@lst.de>]

On Mon, Jul 27, 2020 at 12:46:36PM +0200, Christian Brauner wrote:
> Hey Christoph,
> 
> Seems that commit
> 6955a76fbcd5 ("bpfilter: switch to kernel_write")
> causes bpfilter to spew these useless messages in dmesg?
> 
> [   26.356824] Started bpfilter
> [   26.357059] bpfilter: write fail -22
> [   26.396244] Started bpfilter
> [   26.396325] bpfilter: Loaded bpfilter_umh pid 637
> [   26.396542] bpfilter: write fail -22
> [   26.409588] bpfilter: Loaded bpfilter_umh pid 638
> [   26.410790] Started bpfilter
> [   26.410960] bpfilter: write fail -22
> [   26.445718] Started bpfilter
> [   26.445799] bpfilter: Loaded bpfilter_umh pid 640
> [   26.445983] bpfilter: write fail -22
> [   26.451122] bpfilter: read fail 0
> [   26.496497] bpfilter: Loaded bpfilter_umh pid 648
> [   26.497889] Started bpfilter
> [   26.750028] bpfilter: write fail -22
> [   26.768400] Started bpfilter
> [   26.768496] bpfilter: Loaded bpfilter_umh pid 661
> [   26.768699] bpfilter: write fail -22
> [   26.806550] Started bpfilter
> [   26.806616] bpfilter: Loaded bpfilter_umh pid 663
> [   26.864708] bpfilter: write fail -22
> [   26.872345] bpfilter: Loaded bpfilter_umh pid 666
> [   26.873072] Started bpfilter
> [   26.873194] bpfilter: write fail -22
> [   27.295514] kauditd_printk_skb: 22 callbacks suppressed
> 
> This is on a pure v5.8-rc7 via make bindep-pkg. I'm not using bpfilter
> in any shape or form afaict and haven't seen those messages before and
> this seems to be the last change I see.

I don't see any of those on 5.8-rc, just:

root@testvm:~# dmesg | grep bpf
[    6.692550] bpfilter: Loaded bpfilter_umh pid 1849

That debug patch below should help to pintpoint what is going on for
you:


diff --git a/fs/read_write.c b/fs/read_write.c
index 4fb797822567a6..15232ddea197b2 100644
--- a/fs/read_write.c
+++ b/fs/read_write.c
@@ -516,8 +516,10 @@ ssize_t __kernel_write(struct file *file, const void *buf, size_t count, loff_t
 
 	if (WARN_ON_ONCE(!(file->f_mode & FMODE_WRITE)))
 		return -EBADF;
-	if (!(file->f_mode & FMODE_CAN_WRITE))
+	if (!(file->f_mode & FMODE_CAN_WRITE)) {
+		pr_info_ratelimited("file can't write\n");
 		return -EINVAL;
+	}
 
 	old_fs = get_fs();
 	set_fs(KERNEL_DS);
@@ -528,8 +530,10 @@ ssize_t __kernel_write(struct file *file, const void *buf, size_t count, loff_t
 		ret = file->f_op->write(file, p, count, pos);
 	else if (file->f_op->write_iter)
 		ret = new_sync_write(file, p, count, pos);
-	else
+	else {
+		pr_info_ratelimited("file has no write method\n");
 		ret = -EINVAL;
+	}
 	set_fs(old_fs);
 	if (ret > 0) {
 		fsnotify_modify(file);
@@ -545,8 +549,10 @@ ssize_t kernel_write(struct file *file, const void *buf, size_t count,
 	ssize_t ret;
 
 	ret = rw_verify_area(WRITE, file, pos, count);
-	if (ret)
+	if (ret) {
+		pr_info_ratelimited("rw_verify_area\n");
 		return ret;
+	}
 
 	file_start_write(file);
 	ret =  __kernel_write(file, buf, count, pos);