Re: bpfilter logging write errors in dmesg

[Christoph Hellwig]

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);