ip_set: protocol %u message -- useful?

ip_set: protocol %u message -- useful?

[Ilia Mirkin]

Hello,

I've recently noticed a lot of

[356872.380595] ip_set: protocol 6

messages in my dmesg. This might be because of some local
configuration changes I've made, or perhaps a kernel upgrade. Either
way, it appears this message has been a pr_notice since the original
code added it in a7b4f989a62 ("netfilter: ipset: IP set core
support").

Does this message provide a lot of value? Or could it be made into a pr_debug?

FWIW commit 1785e8f473 ("netfiler: ipset: Add net namespace for
ipset"), merged in v3.13-rc1 changed the code around which may have
made it more likely to appear in dmesg (with the namespace stuff). Not
sure though. I don't (purposely) use namespaces.

I'm happy to put together a patch demoting it to pr_debug if people
think it's OK.

Thanks,

  -ilia

Re: ip_set: protocol %u message -- useful?

[Jozsef Kadlecsik]

On Thu, 13 Feb 2014, Ilia Mirkin wrote:

> I've recently noticed a lot of
> 
> [356872.380595] ip_set: protocol 6

That means the ip_set module has been loaded in multiple times.
 
> messages in my dmesg. This might be because of some local
> configuration changes I've made, or perhaps a kernel upgrade. Either
> way, it appears this message has been a pr_notice since the original
> code added it in a7b4f989a62 ("netfilter: ipset: IP set core
> support").
> 
> Does this message provide a lot of value? Or could it be made into a pr_debug?

That's a report message on the protocol version used by the ipset 
subsystem. There was (and possibly will be) multiple protocols, so it 
helps to catch basic userpsace/kernelspace communication issues.
 
> FWIW commit 1785e8f473 ("netfiler: ipset: Add net namespace for
> ipset"), merged in v3.13-rc1 changed the code around which may have
> made it more likely to appear in dmesg (with the namespace stuff). Not
> sure though. I don't (purposely) use namespaces.

Namespaces can explain why you see the message so many times, but then you 
must have namespaces activated.
 
> I'm happy to put together a patch demoting it to pr_debug if people
> think it's OK.

I'm fine with it, it's OK.

Best regards,
Jozsef
-
E-mail  : kadlec@blackhole.kfki.hu, kadlecsik.jozsef@wigner.mta.hu
PGP key : http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address : Wigner Research Centre for Physics, Hungarian Academy of Sciences
          H-1525 Budapest 114, POB. 49, Hungary

Re: ip_set: protocol %u message -- useful?

[Cong Wang]

On Thu, Feb 13, 2014 at 2:30 AM, Jozsef Kadlecsik
<kadlec@blackhole.kfki.hu> wrote:
> On Thu, 13 Feb 2014, Ilia Mirkin wrote:
>> messages in my dmesg. This might be because of some local
>> configuration changes I've made, or perhaps a kernel upgrade. Either
>> way, it appears this message has been a pr_notice since the original
>> code added it in a7b4f989a62 ("netfilter: ipset: IP set core
>> support").
>>
>> Does this message provide a lot of value? Or could it be made into a pr_debug?
>
> That's a report message on the protocol version used by the ipset
> subsystem. There was (and possibly will be) multiple protocols, so it
> helps to catch basic userpsace/kernelspace communication issues.

But still it doesn't deserve a pr_notice()... pr_info() should be enough.

diff --git a/net/netfilter/ipset/ip_set_core.c
b/net/netfilter/ipset/ip_set_core.c
index de770ec..5ea063f 100644
--- a/net/netfilter/ipset/ip_set_core.c
+++ b/net/netfilter/ipset/ip_set_core.c
@@ -1945,7 +1945,7 @@ ip_set_net_init(struct net *net)
                return -ENOMEM;
        inst->is_deleted = 0;
        rcu_assign_pointer(inst->ip_set_list, list);
-       pr_notice("ip_set: protocol %u\n", IPSET_PROTOCOL);
+       pr_info("ip_set: protocol %u\n", IPSET_PROTOCOL);
        return 0;
 }

Re: ip_set: protocol %u message -- useful?

[Patrick McHardy]

On Thu, Feb 13, 2014 at 10:32:45AM -0800, Cong Wang wrote:
> On Thu, Feb 13, 2014 at 2:30 AM, Jozsef Kadlecsik
> <kadlec@blackhole.kfki.hu> wrote:
> > On Thu, 13 Feb 2014, Ilia Mirkin wrote:
> >> messages in my dmesg. This might be because of some local
> >> configuration changes I've made, or perhaps a kernel upgrade. Either
> >> way, it appears this message has been a pr_notice since the original
> >> code added it in a7b4f989a62 ("netfilter: ipset: IP set core
> >> support").
> >>
> >> Does this message provide a lot of value? Or could it be made into a pr_debug?
> >
> > That's a report message on the protocol version used by the ipset
> > subsystem. There was (and possibly will be) multiple protocols, so it
> > helps to catch basic userpsace/kernelspace communication issues.
> 
> But still it doesn't deserve a pr_notice()... pr_info() should be enough.

Maybe printing "using protocol version X" will make it appear less like
a debugging message referring to packet contents or something similar.

> diff --git a/net/netfilter/ipset/ip_set_core.c
> b/net/netfilter/ipset/ip_set_core.c
> index de770ec..5ea063f 100644
> --- a/net/netfilter/ipset/ip_set_core.c
> +++ b/net/netfilter/ipset/ip_set_core.c
> @@ -1945,7 +1945,7 @@ ip_set_net_init(struct net *net)
>                 return -ENOMEM;
>         inst->is_deleted = 0;
>         rcu_assign_pointer(inst->ip_set_list, list);
> -       pr_notice("ip_set: protocol %u\n", IPSET_PROTOCOL);
> +       pr_info("ip_set: protocol %u\n", IPSET_PROTOCOL);
>         return 0;
>  }

Re: ip_set: protocol %u message -- useful?

[Ilia Mirkin]

On Thu, Feb 13, 2014 at 1:42 PM, Patrick McHardy <kaber@trash.net> wrote:
> On Thu, Feb 13, 2014 at 10:32:45AM -0800, Cong Wang wrote:
>> On Thu, Feb 13, 2014 at 2:30 AM, Jozsef Kadlecsik
>> <kadlec@blackhole.kfki.hu> wrote:
>> > On Thu, 13 Feb 2014, Ilia Mirkin wrote:
>> >> messages in my dmesg. This might be because of some local
>> >> configuration changes I've made, or perhaps a kernel upgrade. Either
>> >> way, it appears this message has been a pr_notice since the original
>> >> code added it in a7b4f989a62 ("netfilter: ipset: IP set core
>> >> support").
>> >>
>> >> Does this message provide a lot of value? Or could it be made into a pr_debug?
>> >
>> > That's a report message on the protocol version used by the ipset
>> > subsystem. There was (and possibly will be) multiple protocols, so it
>> > helps to catch basic userpsace/kernelspace communication issues.
>>
>> But still it doesn't deserve a pr_notice()... pr_info() should be enough.
>
> Maybe printing "using protocol version X" will make it appear less like
> a debugging message referring to packet contents or something similar.

With pr_info it'll still appear in dmesg, and it'll still be "random
non-sensical message appears over and over in dmesg" type of
situation, to the vast majority of users. Do we need a print every
time someone creates a new tcp connection too? I'm still not totally
clear on the cause of this message getting printed, but I was seeing
it a whole bunch in my configuration...

>
>> diff --git a/net/netfilter/ipset/ip_set_core.c
>> b/net/netfilter/ipset/ip_set_core.c
>> index de770ec..5ea063f 100644
>> --- a/net/netfilter/ipset/ip_set_core.c
>> +++ b/net/netfilter/ipset/ip_set_core.c
>> @@ -1945,7 +1945,7 @@ ip_set_net_init(struct net *net)
>>                 return -ENOMEM;
>>         inst->is_deleted = 0;
>>         rcu_assign_pointer(inst->ip_set_list, list);
>> -       pr_notice("ip_set: protocol %u\n", IPSET_PROTOCOL);
>> +       pr_info("ip_set: protocol %u\n", IPSET_PROTOCOL);
>>         return 0;
>>  }

Re: ip_set: protocol %u message -- useful?

[Florian Westphal]

Ilia Mirkin <imirkin@alum.mit.edu> wrote:
> > Maybe printing "using protocol version X" will make it appear less like
> > a debugging message referring to packet contents or something similar.
> 
> With pr_info it'll still appear in dmesg, and it'll still be "random
> non-sensical message appears over and over in dmesg" type of
> situation, to the vast majority of users. Do we need a print every
> time someone creates a new tcp connection too? I'm still not totally
> clear on the cause of this message getting printed, but I was seeing
> it a whole bunch in my configuration...

Yes, because it erronously got moved into the netns init function.

And thats what causes the spew.  Moving it back into module init
function should be enough.

Re: ip_set: protocol %u message -- useful?

[Jozsef Kadlecsik]

On Thu, 13 Feb 2014, Florian Westphal wrote:

> Ilia Mirkin <imirkin@alum.mit.edu> wrote:
> > > Maybe printing "using protocol version X" will make it appear less like
> > > a debugging message referring to packet contents or something similar.
> > 
> > With pr_info it'll still appear in dmesg, and it'll still be "random
> > non-sensical message appears over and over in dmesg" type of
> > situation, to the vast majority of users. Do we need a print every
> > time someone creates a new tcp connection too? I'm still not totally
> > clear on the cause of this message getting printed, but I was seeing
> > it a whole bunch in my configuration...
> 
> Yes, because it erronously got moved into the netns init function.
> 
> And thats what causes the spew.  Moving it back into module init
> function should be enough.

Florian has got right, that'd be the best.

Best regards,
Jozsef
-
E-mail  : kadlec@blackhole.kfki.hu, kadlecsik.jozsef@wigner.mta.hu
PGP key : http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address : Wigner Research Centre for Physics, Hungarian Academy of Sciences
          H-1525 Budapest 114, POB. 49, Hungary

Re: ip_set: protocol %u message -- useful?

[Joe Perches]

On Thu, 2014-02-13 at 18:42 +0000, Patrick McHardy wrote:
> On Thu, Feb 13, 2014 at 10:32:45AM -0800, Cong Wang wrote:
> > On Thu, Feb 13, 2014 at 2:30 AM, Jozsef Kadlecsik
> > <kadlec@blackhole.kfki.hu> wrote:
> > > On Thu, 13 Feb 2014, Ilia Mirkin wrote:
> > >> messages in my dmesg. This might be because of some local
> > >> configuration changes I've made, or perhaps a kernel upgrade. Either
> > >> way, it appears this message has been a pr_notice since the original
> > >> code added it in a7b4f989a62 ("netfilter: ipset: IP set core
> > >> support").
> > >>
> > >> Does this message provide a lot of value? Or could it be made into a pr_debug?
> > >
> > > That's a report message on the protocol version used by the ipset
> > > subsystem. There was (and possibly will be) multiple protocols, so it
> > > helps to catch basic userpsace/kernelspace communication issues.
> > 
> > But still it doesn't deserve a pr_notice()... pr_info() should be enough.
> 
> Maybe printing "using protocol version X" will make it appear less like
> a debugging message referring to packet contents or something similar.

Maybe making all the ip_set messages be prefixed with "ip_set: "
would help too.

Add pr_fmt
Remove embedded ip_set prefixes
Convert pr_warning to pr_warn
Realign arguments

---
 net/netfilter/ipset/ip_set_core.c | 39 ++++++++++++++++++++-------------------
 1 file changed, 20 insertions(+), 19 deletions(-)

diff --git a/net/netfilter/ipset/ip_set_core.c b/net/netfilter/ipset/ip_set_core.c
index de770ec..1d4396f 100644
--- a/net/netfilter/ipset/ip_set_core.c
+++ b/net/netfilter/ipset/ip_set_core.c
@@ -9,6 +9,8 @@
 
 /* Kernel module for IP set management */
 
+#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt
+
 #include <linux/init.h>
 #include <linux/module.h>
 #include <linux/moduleparam.h>
@@ -101,7 +103,7 @@ load_settype(const char *name)
 	nfnl_unlock(NFNL_SUBSYS_IPSET);
 	pr_debug("try to load ip_set_%s\n", name);
 	if (request_module("ip_set_%s", name) < 0) {
-		pr_warning("Can't find ip_set type %s\n", name);
+		pr_warn("Can't find type %s\n", name);
 		nfnl_lock(NFNL_SUBSYS_IPSET);
 		return false;
 	}
@@ -195,25 +197,24 @@ ip_set_type_register(struct ip_set_type *type)
 	int ret = 0;
 
 	if (type->protocol != IPSET_PROTOCOL) {
-		pr_warning("ip_set type %s, family %s, revision %u:%u uses "
-			   "wrong protocol version %u (want %u)\n",
-			   type->name, family_name(type->family),
-			   type->revision_min, type->revision_max,
-			   type->protocol, IPSET_PROTOCOL);
+		pr_warn("type %s, family %s, revision %u:%u uses wrong protocol version %u (want %u)\n",
+			type->name, family_name(type->family),
+			type->revision_min, type->revision_max,
+			type->protocol, IPSET_PROTOCOL);
 		return -EINVAL;
 	}
 
 	ip_set_type_lock();
 	if (find_set_type(type->name, type->family, type->revision_min)) {
 		/* Duplicate! */
-		pr_warning("ip_set type %s, family %s with revision min %u "
-			   "already registered!\n", type->name,
-			   family_name(type->family), type->revision_min);
+		pr_warn("type %s, family %s with revision min %u already registered!\n",
+			type->name, family_name(type->family),
+			type->revision_min);
 		ret = -EINVAL;
 		goto unlock;
 	}
 	list_add_rcu(&type->list, &ip_set_type_list);
-	pr_debug("type %s, family %s, revision %u:%u registered.\n",
+	pr_debug("type %s, family %s, revision %u:%u registered\n",
 		 type->name, family_name(type->family),
 		 type->revision_min, type->revision_max);
 unlock:
@@ -228,13 +229,13 @@ ip_set_type_unregister(struct ip_set_type *type)
 {
 	ip_set_type_lock();
 	if (!find_set_type(type->name, type->family, type->revision_min)) {
-		pr_warning("ip_set type %s, family %s with revision min %u "
-			   "not registered\n", type->name,
-			   family_name(type->family), type->revision_min);
+		pr_warn("type %s, family %s with revision min %u not registered\n",
+			type->name, family_name(type->family),
+			type->revision_min);
 		goto unlock;
 	}
 	list_del_rcu(&type->list);
-	pr_debug("type %s, family %s with revision min %u unregistered.\n",
+	pr_debug("type %s, family %s with revision min %u unregistered\n",
 		 type->name, family_name(type->family), type->revision_min);
 unlock:
 	ip_set_type_unlock();
@@ -269,8 +270,8 @@ EXPORT_SYMBOL_GPL(ip_set_alloc);
 void
 ip_set_free(void *members)
 {
-	pr_debug("%p: free with %s\n", members,
-		 is_vmalloc_addr(members) ? "vfree" : "kfree");
+	pr_debug("%p: free with %s\n",
+		 members, is_vmalloc_addr(members) ? "vfree" : "kfree");
 	if (is_vmalloc_addr(members))
 		vfree(members);
 	else
@@ -1945,7 +1946,7 @@ ip_set_net_init(struct net *net)
 		return -ENOMEM;
 	inst->is_deleted = 0;
 	rcu_assign_pointer(inst->ip_set_list, list);
-	pr_notice("ip_set: protocol %u\n", IPSET_PROTOCOL);
+	pr_notice("protocol %u\n", IPSET_PROTOCOL);
 	return 0;
 }
 
@@ -1980,7 +1981,7 @@ ip_set_init(void)
 {
 	int ret = nfnetlink_subsys_register(&ip_set_netlink_subsys);
 	if (ret != 0) {
-		pr_err("ip_set: cannot register with nfnetlink.\n");
+		pr_err("cannot register with nfnetlink\n");
 		return ret;
 	}
 	ret = nf_register_sockopt(&so_set);
@@ -1991,7 +1992,7 @@ ip_set_init(void)
 	}
 	ret = register_pernet_subsys(&ip_set_net_ops);
 	if (ret) {
-		pr_err("ip_set: cannot register pernet_subsys.\n");
+		pr_err("cannot register pernet_subsys\n");
 		nf_unregister_sockopt(&so_set);
 		nfnetlink_subsys_unregister(&ip_set_netlink_subsys);
 		return ret;