* bpfilter logging write errors in dmesg
@ 2020-07-27 10:46 Christian Brauner
2020-07-27 13:28 ` Christoph Hellwig
0 siblings, 1 reply; 9+ messages in thread
From: Christian Brauner @ 2020-07-27 10:46 UTC (permalink / raw)
To: Christoph Hellwig; +Cc: linux-kernel
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.
Thanks!
Christian
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: bpfilter logging write errors in dmesg
2020-07-27 10:46 bpfilter logging write errors in dmesg Christian Brauner
@ 2020-07-27 13:28 ` Christoph Hellwig
2020-07-27 14:13 ` Christian Brauner
0 siblings, 1 reply; 9+ messages in thread
From: Christoph Hellwig @ 2020-07-27 13:28 UTC (permalink / raw)
To: Christian Brauner; +Cc: Christoph Hellwig, linux-kernel
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);
^ permalink raw reply related [flat|nested] 9+ messages in thread
* Re: bpfilter logging write errors in dmesg
2020-07-27 13:28 ` Christoph Hellwig
@ 2020-07-27 14:13 ` Christian Brauner
2020-07-27 14:21 ` Christian Brauner
2020-07-27 14:50 ` Christoph Hellwig
0 siblings, 2 replies; 9+ messages in thread
From: Christian Brauner @ 2020-07-27 14:13 UTC (permalink / raw)
To: Christoph Hellwig; +Cc: linux-kernel
On Mon, Jul 27, 2020 at 03:28:55PM +0200, Christoph Hellwig wrote:
> 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
Hm, odd
>
> That debug patch below should help to pintpoint what is going on for
> you:
Thanks for the debug patch! Applied and ran a kernel and I'm getting:
[ 21.919851] bpfilter: Loaded bpfilter_umh pid 619
[ 22.000229] rw_verify_area
[ 22.000235] bpfilter: write fail -22
[ 22.014686] Started bpfilter
I'm also seeing some other failures later:
[ 236.898220] bpfilter: write fail -22
[ 236.899255] bpfilter: write fail -32
[ 236.922557] bpfilter: Loaded bpfilter_umh pid 1101
[ 236.923310] Started bpfilter
[ 236.923521] rw_verify_area
[ 236.923524] bpfilter: write fail -22
[ 236.925273] bpfilter: read fail 0
[ 236.945117] bpfilter: Loaded bpfilter_umh pid 1103
[ 236.945925] Started bpfilter
[ 236.946123] rw_verify_area
[ 236.946126] bpfilter: write fail -22
[ 236.947641] bpfilter: read fail 0
[ 236.968143] bpfilter: Loaded bpfilter_umh pid 1105
[ 236.968734] Started bpfilter
[ 236.987777] rw_verify_area
[ 236.987781] bpfilter: write fail -22
[ 236.990072] bpfilter: read fail 0
Seems I can trigger this via iptables:
[ 437.922719] bpfilter: write fail -22
[ 437.924488] bpfilter: read fail 0
root@g1-vm:~# iptables -S
iptables v1.8.4 (legacy): can't initialize iptables table `filter': Bad address
Perhaps iptables or your kernel needs to be upgraded.
I have
CONFIG_IP_NF_IPTABLES=m
CONFIG_IP6_NF_IPTABLES=m
maybe I'm just missing another kernel option or something and I have no
idea how this bpfilter thing and iptables relate to each other. So maybe
it's not worth the effort and it's just my setup being broken somehow.
Christian
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: bpfilter logging write errors in dmesg
2020-07-27 14:13 ` Christian Brauner
@ 2020-07-27 14:21 ` Christian Brauner
2020-07-27 14:50 ` Christoph Hellwig
1 sibling, 0 replies; 9+ messages in thread
From: Christian Brauner @ 2020-07-27 14:21 UTC (permalink / raw)
To: Christoph Hellwig; +Cc: linux-kernel
On Mon, Jul 27, 2020 at 04:13:38PM +0200, Christian Brauner wrote:
> On Mon, Jul 27, 2020 at 03:28:55PM +0200, Christoph Hellwig wrote:
> > 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
>
> Hm, odd
>
> >
> > That debug patch below should help to pintpoint what is going on for
> > you:
>
> Thanks for the debug patch! Applied and ran a kernel and I'm getting:
>
> [ 21.919851] bpfilter: Loaded bpfilter_umh pid 619
> [ 22.000229] rw_verify_area
> [ 22.000235] bpfilter: write fail -22
> [ 22.014686] Started bpfilter
>
> I'm also seeing some other failures later:
>
> [ 236.898220] bpfilter: write fail -22
> [ 236.899255] bpfilter: write fail -32
> [ 236.922557] bpfilter: Loaded bpfilter_umh pid 1101
> [ 236.923310] Started bpfilter
> [ 236.923521] rw_verify_area
> [ 236.923524] bpfilter: write fail -22
> [ 236.925273] bpfilter: read fail 0
> [ 236.945117] bpfilter: Loaded bpfilter_umh pid 1103
> [ 236.945925] Started bpfilter
> [ 236.946123] rw_verify_area
> [ 236.946126] bpfilter: write fail -22
> [ 236.947641] bpfilter: read fail 0
> [ 236.968143] bpfilter: Loaded bpfilter_umh pid 1105
> [ 236.968734] Started bpfilter
> [ 236.987777] rw_verify_area
> [ 236.987781] bpfilter: write fail -22
> [ 236.990072] bpfilter: read fail 0
>
> Seems I can trigger this via iptables:
>
> [ 437.922719] bpfilter: write fail -22
> [ 437.924488] bpfilter: read fail 0
> root@g1-vm:~# iptables -S
> iptables v1.8.4 (legacy): can't initialize iptables table `filter': Bad address
> Perhaps iptables or your kernel needs to be upgraded.
>
> I have
> CONFIG_IP_NF_IPTABLES=m
> CONFIG_IP6_NF_IPTABLES=m
> maybe I'm just missing another kernel option or something and I have no
> idea how this bpfilter thing and iptables relate to each other. So maybe
> it's not worth the effort and it's just my setup being broken somehow.
Fwiw, it seems that on kernels that replace iptables with nftables
programs calling into iptables will cause this bpfilter dmesg logging.
Christian
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: bpfilter logging write errors in dmesg
2020-07-27 14:13 ` Christian Brauner
2020-07-27 14:21 ` Christian Brauner
@ 2020-07-27 14:50 ` Christoph Hellwig
2020-07-30 0:59 ` Rodrigo Madera
2020-07-30 7:09 ` Christian Brauner
1 sibling, 2 replies; 9+ messages in thread
From: Christoph Hellwig @ 2020-07-27 14:50 UTC (permalink / raw)
To: Christian Brauner; +Cc: Christoph Hellwig, linux-kernel
Strange. Can you add this additional debugging patch:
diff --git a/fs/read_write.c b/fs/read_write.c
index 4fb797822567a6..d0a8ada1efd954 100644
--- a/fs/read_write.c
+++ b/fs/read_write.c
@@ -369,8 +369,10 @@ int rw_verify_area(int read_write, struct file *file, const loff_t *ppos, size_t
int retval = -EINVAL;
inode = file_inode(file);
- if (unlikely((ssize_t) count < 0))
+ if (unlikely((ssize_t) count < 0)) {
+ printk("count invalid: %zd\n", count);
return retval;
+ }
/*
* ranged mandatory locking does not apply to streams - it makes sense
@@ -380,25 +382,35 @@ int rw_verify_area(int read_write, struct file *file, const loff_t *ppos, size_t
loff_t pos = *ppos;
if (unlikely(pos < 0)) {
- if (!unsigned_offsets(file))
+ if (!unsigned_offsets(file)) {
+ printk("pos invalid: %lld\n", pos);
return retval;
+ }
if (count >= -pos) /* both values are in 0..LLONG_MAX */
return -EOVERFLOW;
} else if (unlikely((loff_t) (pos + count) < 0)) {
- if (!unsigned_offsets(file))
+ if (!unsigned_offsets(file)) {
+ printk("pos+count invalid: %lld, %zd\n", pos, count);
return retval;
+ }
}
if (unlikely(inode->i_flctx && mandatory_lock(inode))) {
retval = locks_mandatory_area(inode, file, pos, pos + count - 1,
read_write == READ ? F_RDLCK : F_WRLCK);
- if (retval < 0)
+ if (retval < 0) {
+ if (retval == -EINVAL)
+ printk("locks_mandatory_area\n");
return retval;
+ }
}
}
- return security_file_permission(file,
+ retval = security_file_permission(file,
read_write == READ ? MAY_READ : MAY_WRITE);
+ if (retval == -EINVAL)
+ printk("security_file_permission\n");
+ return retval;
}
static ssize_t new_sync_read(struct file *filp, char __user *buf, size_t len, loff_t *ppos)
^ permalink raw reply related [flat|nested] 9+ messages in thread
* Re: bpfilter logging write errors in dmesg
2020-07-27 14:50 ` Christoph Hellwig
@ 2020-07-30 0:59 ` Rodrigo Madera
2020-07-30 6:06 ` Christoph Hellwig
2020-07-30 7:09 ` Christian Brauner
1 sibling, 1 reply; 9+ messages in thread
From: Rodrigo Madera @ 2020-07-30 0:59 UTC (permalink / raw)
To: hch; +Cc: christian.brauner, linux-kernel
Christoph,
I see the same issue on my AMD 3990x using v5.8rc7:
[ 10.229424] bpfilter: Loaded bpfilter_umh pid 1906
[ 10.229467] Started bpfilter
[ 10.229538] pos invalid: -131326014643272
[ 10.229539] bpfilter: write fail -22
[ 10.229603] pos invalid: -2127991714
[ 10.229604] bpfilter: write fail -22
[ 10.232222] bpfilter: Loaded bpfilter_umh pid 1908
[ 10.232292] Started bpfilter
[ 10.232355] pos invalid: -131322530713744
[ 10.232357] bpfilter: write fail -22
[ 10.232389] pos invalid: -2127991714
[ 10.232390] bpfilter: write fail -22
[ 10.233986] bpfilter: Loaded bpfilter_umh pid 1911
[ 10.234056] Started bpfilter
[ 10.234898] pos invalid: -2127991714
[ 10.234900] bpfilter: write fail -22
[ 10.234907] pos invalid: -2127991714
[ 10.234908] bpfilter: write fail -22
[ 10.235797] bpfilter: Loaded bpfilter_umh pid 1914
[ 10.235871] Started bpfilter
[ 10.235928] pos invalid: -2127991714
[ 10.235929] bpfilter: write fail -22
[ 10.235936] pos invalid: -2127991714
[ 10.235936] bpfilter: write fail -22
[ 10.236834] bpfilter: Loaded bpfilter_umh pid 1916
[ 10.236897] Started bpfilter
[ 10.236955] pos invalid: -2127991714
[ 10.236957] bpfilter: write fail -22
[ 10.236963] pos invalid: -2127991714
[ 10.236964] bpfilter: write fail -22
[ 10.237801] bpfilter: Loaded bpfilter_umh pid 1918
[ 10.237856] Started bpfilter
[ 10.238463] pos invalid: -2127991714
[ 10.238465] bpfilter: write fail -22
[ 10.238487] pos invalid: -2127991714
[ 10.238488] bpfilter: write fail -22
[ 10.239232] bpfilter: Loaded bpfilter_umh pid 1921
[ 10.239293] Started bpfilter
[ 10.239341] pos invalid: -131323777967304
[ 10.239342] bpfilter: write fail -22
[ 10.239362] pos invalid: -2127991714
[ 10.239363] bpfilter: write fail -22
[ 10.240024] bpfilter: Loaded bpfilter_umh pid 1923
[ 10.240084] Started bpfilter
[ 10.240136] pos invalid: -131322329686184
[ 10.240137] bpfilter: write fail -22
[ 10.240158] pos invalid: -2127991714
[ 10.240159] bpfilter: write fail -22
[ 10.240822] bpfilter: Loaded bpfilter_umh pid 1925
[ 10.240885] Started bpfilter
[ 10.240933] pos invalid: -131323778001336
[ 10.240935] bpfilter: write fail -22
[ 10.240955] pos invalid: -2127991714
[ 10.240955] bpfilter: write fail -22
[ 10.241625] bpfilter: Loaded bpfilter_umh pid 1927
[ 10.241685] Started bpfilter
[ 10.241732] pos invalid: -131323135926520
[ 10.241733] bpfilter: write fail -22
[ 10.241754] pos invalid: -2127991714
[ 10.241754] bpfilter: write fail -22
[ 10.242411] bpfilter: Loaded bpfilter_umh pid 1929
[ 10.242472] Started bpfilter
[ 10.242521] pos invalid: -131322329867000
[ 10.242522] bpfilter: write fail -22
[ 10.242544] pos invalid: -2127991714
[ 10.242545] bpfilter: write fail -22
[ 10.243204] bpfilter: Loaded bpfilter_umh pid 1931
[ 10.243267] Started bpfilter
[ 10.243314] pos invalid: -131322329851800
[ 10.243315] bpfilter: write fail -22
[ 10.243335] pos invalid: -2127991714
[ 10.243335] bpfilter: write fail -22
[ 10.244014] bpfilter: Loaded bpfilter_umh pid 1933
[ 10.244079] Started bpfilter
[ 10.244127] pos invalid: -131322329834712
[ 10.244128] bpfilter: write fail -22
[ 10.244148] pos invalid: -2127991714
[ 10.244148] bpfilter: write fail -22
[ 10.244809] bpfilter: Loaded bpfilter_umh pid 1935
[ 10.244875] Started bpfilter
[ 10.244923] pos invalid: -131323135845432
[ 10.244924] bpfilter: write fail -22
[ 10.244944] pos invalid: -2127991714
[ 10.244944] bpfilter: write fail -22
[ 10.245613] bpfilter: Loaded bpfilter_umh pid 1937
[ 10.245677] Started bpfilter
[ 10.245724] pos invalid: -131323135831656
[ 10.245725] bpfilter: write fail -22
[ 10.245753] pos invalid: -2127991714
[ 10.245753] bpfilter: write fail -22
[ 10.246426] bpfilter: Loaded bpfilter_umh pid 1939
[ 10.246489] Started bpfilter
[ 10.246536] pos invalid: -131323135812112
[ 10.246537] bpfilter: write fail -22
[ 10.246557] pos invalid: -2127991714
[ 10.246557] bpfilter: write fail -22
[ 10.247221] bpfilter: Loaded bpfilter_umh pid 1941
[ 10.247283] Started bpfilter
[ 10.247332] pos invalid: -131323135799288
[ 10.247333] bpfilter: write fail -22
[ 10.247353] pos invalid: -2127991714
[ 10.247354] bpfilter: write fail -22
[ 10.248028] bpfilter: Loaded bpfilter_umh pid 1943
[ 10.248093] Started bpfilter
[ 10.248141] pos invalid: -131322329819936
[ 10.248142] bpfilter: write fail -22
[ 10.248162] pos invalid: -2127991714
[ 10.248163] bpfilter: write fail -22
[ 11.683140] bpfilter: Loaded bpfilter_umh pid 1997
[ 11.683214] Started bpfilter
[ 11.683279] pos invalid: -131322964802512
[ 11.683281] bpfilter: write fail -22
[ 11.683325] pos invalid: -2127991714
[ 11.683326] bpfilter: write fail -22
[ 11.685772] bpfilter: Loaded bpfilter_umh pid 1999
[ 11.685853] Started bpfilter
[ 11.685961] pos invalid: -131323223158688
[ 11.685964] bpfilter: write fail -22
[ 11.686032] pos invalid: -2127991714
[ 11.686033] bpfilter: write fail -22
[ 11.687562] bpfilter: Loaded bpfilter_umh pid 2002
[ 11.687623] Started bpfilter
[ 11.688581] pos invalid: -2127991714
[ 11.688584] bpfilter: write fail -22
[ 11.688592] pos invalid: -2127991714
[ 11.688593] bpfilter: write fail -22
[ 11.689646] bpfilter: Loaded bpfilter_umh pid 2005
[ 11.689731] Started bpfilter
[ 11.689911] pos invalid: -2127991714
[ 11.689913] bpfilter: write fail -22
[ 11.689922] pos invalid: -2127991714
[ 11.689923] bpfilter: write fail -22
[ 11.690982] bpfilter: Loaded bpfilter_umh pid 2007
[ 11.691047] Started bpfilter
[ 11.691151] pos invalid: -2127991714
[ 11.691154] bpfilter: write fail -22
[ 11.691162] pos invalid: -2127991714
[ 11.691163] bpfilter: write fail -22
[ 11.692329] bpfilter: Loaded bpfilter_umh pid 2009
[ 11.692407] Started bpfilter
[ 11.693206] pos invalid: -2127991714
[ 11.693208] bpfilter: write fail -22
[ 11.693250] pos invalid: -2127991714
[ 11.693251] bpfilter: write fail -22
[ 11.694309] bpfilter: Loaded bpfilter_umh pid 2012
[ 11.694369] Started bpfilter
[ 11.694470] pos invalid: -131324827355584
[ 11.694472] bpfilter: write fail -22
[ 11.694519] pos invalid: -2127991714
[ 11.694520] bpfilter: write fail -22
[ 11.695513] bpfilter: Loaded bpfilter_umh pid 2014
[ 11.695573] Started bpfilter
[ 11.695669] pos invalid: -131324827335488
[ 11.695672] bpfilter: write fail -22
[ 11.695707] pos invalid: -2127991714
[ 11.695708] bpfilter: write fail -22
[ 11.696594] bpfilter: Loaded bpfilter_umh pid 2016
[ 11.696667] Started bpfilter
[ 11.696822] pos invalid: -131322940756688
[ 11.696824] bpfilter: write fail -22
[ 11.696876] pos invalid: -2127991714
[ 11.696877] bpfilter: write fail -22
[ 11.697871] bpfilter: Loaded bpfilter_umh pid 2018
[ 11.697941] Started bpfilter
[ 11.698039] pos invalid: -131323134120976
[ 11.698042] bpfilter: write fail -22
[ 11.698079] pos invalid: -2127991714
[ 11.698080] bpfilter: write fail -22
[ 11.698964] bpfilter: Loaded bpfilter_umh pid 2020
[ 11.699041] Started bpfilter
[ 11.699137] pos invalid: -131323134075224
[ 11.699140] bpfilter: write fail -22
[ 11.699197] pos invalid: -2127991714
[ 11.699198] bpfilter: write fail -22
[ 11.700053] bpfilter: Loaded bpfilter_umh pid 2022
[ 11.700123] Started bpfilter
[ 11.700233] pos invalid: -131326994695872
[ 11.700236] bpfilter: write fail -22
[ 11.700291] pos invalid: -2127991714
[ 11.700292] bpfilter: write fail -22
[ 11.701246] bpfilter: Loaded bpfilter_umh pid 2024
[ 11.701307] Started bpfilter
[ 11.701401] pos invalid: -131324827369352
[ 11.701403] bpfilter: write fail -22
[ 11.701439] pos invalid: -2127991714
[ 11.701440] bpfilter: write fail -22
[ 11.702315] bpfilter: Loaded bpfilter_umh pid 2026
[ 11.702389] Started bpfilter
[ 11.702484] pos invalid: -131322939518040
[ 11.702487] bpfilter: write fail -22
[ 11.702522] pos invalid: -2127991714
[ 11.702523] bpfilter: write fail -22
[ 11.703348] bpfilter: Loaded bpfilter_umh pid 2028
[ 11.703423] Started bpfilter
[ 11.703535] pos invalid: -131322939469856
[ 11.703538] bpfilter: write fail -22
[ 11.703573] pos invalid: -2127991714
[ 11.703574] bpfilter: write fail -22
[ 11.704497] bpfilter: Loaded bpfilter_umh pid 2030
[ 11.704572] Started bpfilter
[ 11.704666] pos invalid: -131322939428640
[ 11.704668] bpfilter: write fail -22
[ 11.704718] pos invalid: -2127991714
[ 11.704719] bpfilter: write fail -22
[ 11.705536] bpfilter: Loaded bpfilter_umh pid 2032
[ 11.705605] Started bpfilter
[ 11.705700] pos invalid: -131322939385792
[ 11.705702] bpfilter: write fail -22
[ 11.705738] pos invalid: -2127991714
[ 11.705739] bpfilter: write fail -22
[ 11.706598] bpfilter: Loaded bpfilter_umh pid 2034
[ 11.706666] Started bpfilter
[ 11.706740] pos invalid: -131322939340512
[ 11.706741] bpfilter: write fail -22
[ 11.706768] pos invalid: -2127991714
[ 11.706768] bpfilter: write fail -22
[ 13.141791] bpfilter: Loaded bpfilter_umh pid 2086
[ 13.141840] Started bpfilter
[ 13.141919] pos invalid: -131323223055336
[ 13.141920] bpfilter: write fail -22
[ 13.141983] pos invalid: -2127991714
[ 13.141984] bpfilter: write fail -22
[ 13.144245] bpfilter: Loaded bpfilter_umh pid 2088
[ 13.144312] Started bpfilter
[ 13.144418] pos invalid: -131340777111464
[ 13.144420] bpfilter: write fail -22
[ 13.144457] pos invalid: -2127991714
[ 13.144458] bpfilter: write fail -22
[ 13.145931] bpfilter: Loaded bpfilter_umh pid 2091
[ 13.146005] Started bpfilter
[ 13.146859] pos invalid: -2127991714
[ 13.146861] bpfilter: write fail -22
[ 13.146869] pos invalid: -2127991714
[ 13.146870] bpfilter: write fail -22
[ 13.147936] bpfilter: Loaded bpfilter_umh pid 2094
[ 13.148012] Started bpfilter
[ 13.148142] pos invalid: -2127991714
[ 13.148144] bpfilter: write fail -22
[ 13.148152] pos invalid: -2127991714
[ 13.148153] bpfilter: write fail -22
[ 13.149176] bpfilter: Loaded bpfilter_umh pid 2096
[ 13.149249] Started bpfilter
[ 13.149375] pos invalid: -2127991714
[ 13.149377] bpfilter: write fail -22
[ 13.149385] pos invalid: -2127991714
[ 13.149386] bpfilter: write fail -22
[ 13.150281] bpfilter: Loaded bpfilter_umh pid 2098
[ 13.150338] Started bpfilter
[ 13.151152] pos invalid: -2127991714
[ 13.151154] bpfilter: write fail -22
[ 13.151181] pos invalid: -2127991714
[ 13.151182] bpfilter: write fail -22
[ 13.151976] bpfilter: Loaded bpfilter_umh pid 2101
[ 13.152039] Started bpfilter
[ 13.152138] pos invalid: -131327007189936
[ 13.152140] bpfilter: write fail -22
[ 13.152177] pos invalid: -2127991714
[ 13.152178] bpfilter: write fail -22
[ 13.153016] bpfilter: Loaded bpfilter_umh pid 2103
[ 13.153090] Started bpfilter
[ 13.153193] pos invalid: -131322273461040
[ 13.153196] bpfilter: write fail -22
[ 13.153238] pos invalid: -2127991714
[ 13.153239] bpfilter: write fail -22
[ 13.154129] bpfilter: Loaded bpfilter_umh pid 2105
[ 13.154207] Started bpfilter
[ 13.154318] pos invalid: -131322273403824
[ 13.154320] bpfilter: write fail -22
[ 13.154363] pos invalid: -2127991714
[ 13.154364] bpfilter: write fail -22
[ 13.155105] bpfilter: Loaded bpfilter_umh pid 2107
[ 13.155178] Started bpfilter
[ 13.155276] pos invalid: -131340782823592
[ 13.155279] bpfilter: write fail -22
[ 13.155313] pos invalid: -2127991714
[ 13.155314] bpfilter: write fail -22
[ 13.156060] bpfilter: Loaded bpfilter_umh pid 2109
[ 13.156140] Started bpfilter
[ 13.156221] pos invalid: -131340782780136
[ 13.156223] bpfilter: write fail -22
[ 13.156271] pos invalid: -2127991714
[ 13.156272] bpfilter: write fail -22
[ 13.157018] bpfilter: Loaded bpfilter_umh pid 2111
[ 13.157089] Started bpfilter
[ 13.157198] pos invalid: -131323223027832
[ 13.157200] bpfilter: write fail -22
[ 13.157265] pos invalid: -2127991714
[ 13.157266] bpfilter: write fail -22
[ 13.158051] bpfilter: Loaded bpfilter_umh pid 2113
[ 13.158138] Started bpfilter
[ 13.158249] pos invalid: -131322419105776
[ 13.158252] bpfilter: write fail -22
[ 13.158307] pos invalid: -2127991714
[ 13.158308] bpfilter: write fail -22
[ 13.159041] bpfilter: Loaded bpfilter_umh pid 2115
[ 13.159113] Started bpfilter
[ 13.159208] pos invalid: -131323223046528
[ 13.159210] bpfilter: write fail -22
[ 13.159245] pos invalid: -2127991714
[ 13.159246] bpfilter: write fail -22
[ 13.159991] bpfilter: Loaded bpfilter_umh pid 2117
[ 13.160085] Started bpfilter
[ 13.160181] pos invalid: -131324280863928
[ 13.160184] bpfilter: write fail -22
[ 13.160241] pos invalid: -2127991714
[ 13.160242] bpfilter: write fail -22
[ 13.160999] bpfilter: Loaded bpfilter_umh pid 2119
[ 13.161074] Started bpfilter
[ 13.161156] pos invalid: -131322939045512
[ 13.161158] bpfilter: write fail -22
[ 13.161195] pos invalid: -2127991714
[ 13.161195] bpfilter: write fail -22
[ 13.161931] bpfilter: Loaded bpfilter_umh pid 2121
[ 13.162004] Started bpfilter
[ 13.162101] pos invalid: -131323079063632
[ 13.162103] bpfilter: write fail -22
[ 13.162139] pos invalid: -2127991714
[ 13.162140] bpfilter: write fail -22
[ 13.162886] bpfilter: Loaded bpfilter_umh pid 2123
[ 13.162956] Started bpfilter
[ 13.163053] pos invalid: -131340782774864
[ 13.163055] bpfilter: write fail -22
[ 13.163091] pos invalid: -2127991714
[ 13.163092] bpfilter: write fail -22
After that, the bpfilter output rests.
If I try to start docker, then new bpfilter errors as the ones above are
printed again, with increasing PIDs and similar pseudo-random-looking
positions. I have not tested with other bpfilter-using programs.
Let me know if my system has any information that might help in this matter.
Best regards,
Madera
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: bpfilter logging write errors in dmesg
2020-07-30 0:59 ` Rodrigo Madera
@ 2020-07-30 6:06 ` Christoph Hellwig
2020-07-30 15:55 ` Rodrigo Madera
0 siblings, 1 reply; 9+ messages in thread
From: Christoph Hellwig @ 2020-07-30 6:06 UTC (permalink / raw)
To: Rodrigo Madera; +Cc: hch, christian.brauner, linux-kernel
Ho Rodrigo,
please try this patch:
diff --git a/net/bpfilter/bpfilter_kern.c b/net/bpfilter/bpfilter_kern.c
index 1905e01c3aa9a7..4494ea6056cdb8 100644
--- a/net/bpfilter/bpfilter_kern.c
+++ b/net/bpfilter/bpfilter_kern.c
@@ -39,7 +39,7 @@ static int __bpfilter_process_sockopt(struct sock *sk, int optname,
{
struct mbox_request req;
struct mbox_reply reply;
- loff_t pos;
+ loff_t pos = 0;
ssize_t n;
int ret = -EFAULT;
^ permalink raw reply related [flat|nested] 9+ messages in thread
* Re: bpfilter logging write errors in dmesg
2020-07-27 14:50 ` Christoph Hellwig
2020-07-30 0:59 ` Rodrigo Madera
@ 2020-07-30 7:09 ` Christian Brauner
1 sibling, 0 replies; 9+ messages in thread
From: Christian Brauner @ 2020-07-30 7:09 UTC (permalink / raw)
To: Christoph Hellwig; +Cc: linux-kernel
On Mon, Jul 27, 2020 at 04:50:13PM +0200, Christoph Hellwig wrote:
> Strange. Can you add this additional debugging patch:
Sorry Christoph,
didn't mean to leave you waiting. I got pulled into other stuff.
Christian
>
> diff --git a/fs/read_write.c b/fs/read_write.c
> index 4fb797822567a6..d0a8ada1efd954 100644
> --- a/fs/read_write.c
> +++ b/fs/read_write.c
> @@ -369,8 +369,10 @@ int rw_verify_area(int read_write, struct file *file, const loff_t *ppos, size_t
> int retval = -EINVAL;
>
> inode = file_inode(file);
> - if (unlikely((ssize_t) count < 0))
> + if (unlikely((ssize_t) count < 0)) {
> + printk("count invalid: %zd\n", count);
> return retval;
> + }
>
> /*
> * ranged mandatory locking does not apply to streams - it makes sense
> @@ -380,25 +382,35 @@ int rw_verify_area(int read_write, struct file *file, const loff_t *ppos, size_t
> loff_t pos = *ppos;
>
> if (unlikely(pos < 0)) {
> - if (!unsigned_offsets(file))
> + if (!unsigned_offsets(file)) {
> + printk("pos invalid: %lld\n", pos);
> return retval;
> + }
> if (count >= -pos) /* both values are in 0..LLONG_MAX */
> return -EOVERFLOW;
> } else if (unlikely((loff_t) (pos + count) < 0)) {
> - if (!unsigned_offsets(file))
> + if (!unsigned_offsets(file)) {
> + printk("pos+count invalid: %lld, %zd\n", pos, count);
> return retval;
> + }
> }
>
> if (unlikely(inode->i_flctx && mandatory_lock(inode))) {
> retval = locks_mandatory_area(inode, file, pos, pos + count - 1,
> read_write == READ ? F_RDLCK : F_WRLCK);
> - if (retval < 0)
> + if (retval < 0) {
> + if (retval == -EINVAL)
> + printk("locks_mandatory_area\n");
> return retval;
> + }
> }
> }
>
> - return security_file_permission(file,
> + retval = security_file_permission(file,
> read_write == READ ? MAY_READ : MAY_WRITE);
> + if (retval == -EINVAL)
> + printk("security_file_permission\n");
> + return retval;
> }
>
> static ssize_t new_sync_read(struct file *filp, char __user *buf, size_t len, loff_t *ppos)
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: bpfilter logging write errors in dmesg
2020-07-30 6:06 ` Christoph Hellwig
@ 2020-07-30 15:55 ` Rodrigo Madera
0 siblings, 0 replies; 9+ messages in thread
From: Rodrigo Madera @ 2020-07-30 15:55 UTC (permalink / raw)
To: Christoph Hellwig; +Cc: christian.brauner, linux-kernel
On Thu, Jul 30, 2020 at 08:06:54AM +0200, Christoph Hellwig wrote:
> Ho Rodrigo,
>
> please try this patch:
>
> diff --git a/net/bpfilter/bpfilter_kern.c b/net/bpfilter/bpfilter_kern.c
> index 1905e01c3aa9a7..4494ea6056cdb8 100644
> --- a/net/bpfilter/bpfilter_kern.c
> +++ b/net/bpfilter/bpfilter_kern.c
> @@ -39,7 +39,7 @@ static int __bpfilter_process_sockopt(struct sock *sk, int optname,
> {
> struct mbox_request req;
> struct mbox_reply reply;
> - loff_t pos;
> + loff_t pos = 0;
> ssize_t n;
> int ret = -EFAULT;
>
Christoph,
This killed the issue!
Can't believe I missed it... The pos numbers were a dead giveaway!
Let me know if you wish to do any other tests on my end.
Best regards,
Madera
^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2020-07-30 15:55 UTC | newest]
Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-07-27 10:46 bpfilter logging write errors in dmesg Christian Brauner
2020-07-27 13:28 ` Christoph Hellwig
2020-07-27 14:13 ` Christian Brauner
2020-07-27 14:21 ` Christian Brauner
2020-07-27 14:50 ` Christoph Hellwig
2020-07-30 0:59 ` Rodrigo Madera
2020-07-30 6:06 ` Christoph Hellwig
2020-07-30 15:55 ` Rodrigo Madera
2020-07-30 7:09 ` Christian Brauner
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).