[PATCH] i2c: Prevent endless uevent loop with dev_dbg

[PATCH] i2c: Prevent endless uevent loop with dev_dbg

[Jan Glauber]

After enabling CONFIG_I2C_DEBUG_CORE my system was broken
(no network, console login not possible). System log was
flooded with the this message:

 ...
[  608.052077] rtc-ds1307 0-0068: uevent
[  608.052500] rtc-ds1307 0-0068: uevent
[  608.052925] rtc-ds1307 0-0068: uevent
 ...

The culprit is the dev_dbg printk in the i2c uevent handler.
If this is activated (for instance by CONFIG_I2C_DEBUG_CORE)
it results in an endless loop with systemd-journald.

This happens if user-space scans the system log and reads the uevent
file to get information about a newly created device, which seems fair
use to me. Unfortunately reading the "uevent" file uses the same
function that runs for creating the uevent for a new device,
generating the next syslog entry.

Ideally user-space would implement a recursion detection and
after reading the same device file for the 1000th time call it a
day, but nevertheless I think we should avoid this problem by
removing the debug print completly or using another print variant.

The same problem seems to be reported here:
https://bugs.freedesktop.org/show_bug.cgi?id=76886

Signed-off-by: Jan Glauber <jglauber@cavium.com>
---
 drivers/i2c/i2c-core.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/drivers/i2c/i2c-core.c b/drivers/i2c/i2c-core.c
index 0f2f848..84165d9 100644
--- a/drivers/i2c/i2c-core.c
+++ b/drivers/i2c/i2c-core.c
@@ -539,7 +539,7 @@ static int i2c_device_uevent(struct device *dev, struct kobj_uevent_env *env)
 	if (add_uevent_var(env, "MODALIAS=%s%s",
 			   I2C_MODULE_PREFIX, client->name))
 		return -ENOMEM;
-	dev_dbg(dev, "uevent\n");
+	pr_debug("uevent: device: %s\n", dev_name(dev));
 	return 0;
 }
 
-- 
1.9.1

Re: [PATCH] i2c: Prevent endless uevent loop with dev_dbg

[Alexander Sverdlin]

Hi!

On 23/03/16 16:50, EXT Jan Glauber wrote:
> After enabling CONFIG_I2C_DEBUG_CORE my system was broken
> (no network, console login not possible). System log was
> flooded with the this message:
> 
>  ...
> [  608.052077] rtc-ds1307 0-0068: uevent
> [  608.052500] rtc-ds1307 0-0068: uevent
> [  608.052925] rtc-ds1307 0-0068: uevent
>  ...
> 
> The culprit is the dev_dbg printk in the i2c uevent handler.
> If this is activated (for instance by CONFIG_I2C_DEBUG_CORE)
> it results in an endless loop with systemd-journald.
> 
> This happens if user-space scans the system log and reads the uevent
> file to get information about a newly created device, which seems fair
> use to me. Unfortunately reading the "uevent" file uses the same
> function that runs for creating the uevent for a new device,
> generating the next syslog entry.
> 
> Ideally user-space would implement a recursion detection and
> after reading the same device file for the 1000th time call it a
> day, but nevertheless I think we should avoid this problem by
> removing the debug print completly or using another print variant.
> 
> The same problem seems to be reported here:
> https://bugs.freedesktop.org/show_bug.cgi?id=76886
> 
> Signed-off-by: Jan Glauber <jglauber@cavium.com>

Yes, this is evil thing. Both components do legal stuff, but someone has
to stop this madness... I've analyzed journald code and it will suffer
from removing this uevent access and I see no easy way how to provide the
same level of information about the device in the log.
On the other hand the fix in the Kernel is trivial and we have no information
loss.
Maybe it deserves a comment, so that this call is not changed back at some
point in the future. But, in general:

Acked-by: Alexander Sverdlin <alexander.sverdlin@nokia.com>

> ---
>  drivers/i2c/i2c-core.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/drivers/i2c/i2c-core.c b/drivers/i2c/i2c-core.c
> index 0f2f848..84165d9 100644
> --- a/drivers/i2c/i2c-core.c
> +++ b/drivers/i2c/i2c-core.c
> @@ -539,7 +539,7 @@ static int i2c_device_uevent(struct device *dev, struct kobj_uevent_env *env)
>  	if (add_uevent_var(env, "MODALIAS=%s%s",
>  			   I2C_MODULE_PREFIX, client->name))
>  		return -ENOMEM;
> -	dev_dbg(dev, "uevent\n");
> +	pr_debug("uevent: device: %s\n", dev_name(dev));
>  	return 0;
>  }

Re: [PATCH] i2c: Prevent endless uevent loop with dev_dbg

[Wolfram Sang]

[-- Attachment #1: Type: text/plain, Size: 2229 bytes --]

On Wed, Mar 23, 2016 at 04:50:47PM +0100, Jan Glauber wrote:
> After enabling CONFIG_I2C_DEBUG_CORE my system was broken
> (no network, console login not possible). System log was
> flooded with the this message:
> 
>  ...
> [  608.052077] rtc-ds1307 0-0068: uevent
> [  608.052500] rtc-ds1307 0-0068: uevent
> [  608.052925] rtc-ds1307 0-0068: uevent
>  ...
> 
> The culprit is the dev_dbg printk in the i2c uevent handler.
> If this is activated (for instance by CONFIG_I2C_DEBUG_CORE)
> it results in an endless loop with systemd-journald.
> 
> This happens if user-space scans the system log and reads the uevent
> file to get information about a newly created device, which seems fair
> use to me. Unfortunately reading the "uevent" file uses the same
> function that runs for creating the uevent for a new device,
> generating the next syslog entry.
> 
> Ideally user-space would implement a recursion detection and
> after reading the same device file for the 1000th time call it a
> day, but nevertheless I think we should avoid this problem by
> removing the debug print completly or using another print variant.

Thanks for pointing out this problem. I think this debug can go. I also
think the function can be cleaned up some more. Can you test this patch?

Thanks,

   Wolfram

diff --git a/drivers/i2c/i2c-core.c b/drivers/i2c/i2c-core.c
index 0f2f8484e8ec1f..e584d88ee337f6 100644
--- a/drivers/i2c/i2c-core.c
+++ b/drivers/i2c/i2c-core.c
@@ -525,22 +525,16 @@ static int i2c_device_match(struct device *dev, struct device_driver *drv)
 	return 0;
 }
 
-
-/* uevent helps with hotplug: modprobe -q $(MODALIAS) */
 static int i2c_device_uevent(struct device *dev, struct kobj_uevent_env *env)
 {
-	struct i2c_client	*client = to_i2c_client(dev);
+	struct i2c_client *client = to_i2c_client(dev);
 	int rc;
 
 	rc = acpi_device_uevent_modalias(dev, env);
 	if (rc != -ENODEV)
 		return rc;
 
-	if (add_uevent_var(env, "MODALIAS=%s%s",
-			   I2C_MODULE_PREFIX, client->name))
-		return -ENOMEM;
-	dev_dbg(dev, "uevent\n");
-	return 0;
+	return add_uevent_var(env, "MODALIAS=%s%s", I2C_MODULE_PREFIX, client->name);
 }
 
 /* i2c bus recovery routines */


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 819 bytes --]

Re: [PATCH] i2c: Prevent endless uevent loop with dev_dbg

[Jan Glauber]

On Wed, Mar 23, 2016 at 05:50:33PM +0100, Wolfram Sang wrote:
> On Wed, Mar 23, 2016 at 04:50:47PM +0100, Jan Glauber wrote:
> > After enabling CONFIG_I2C_DEBUG_CORE my system was broken
> > (no network, console login not possible). System log was
> > flooded with the this message:
> > 
> >  ...
> > [  608.052077] rtc-ds1307 0-0068: uevent
> > [  608.052500] rtc-ds1307 0-0068: uevent
> > [  608.052925] rtc-ds1307 0-0068: uevent
> >  ...
> > 
> > The culprit is the dev_dbg printk in the i2c uevent handler.
> > If this is activated (for instance by CONFIG_I2C_DEBUG_CORE)
> > it results in an endless loop with systemd-journald.
> > 
> > This happens if user-space scans the system log and reads the uevent
> > file to get information about a newly created device, which seems fair
> > use to me. Unfortunately reading the "uevent" file uses the same
> > function that runs for creating the uevent for a new device,
> > generating the next syslog entry.
> > 
> > Ideally user-space would implement a recursion detection and
> > after reading the same device file for the 1000th time call it a
> > day, but nevertheless I think we should avoid this problem by
> > removing the debug print completly or using another print variant.
> 
> Thanks for pointing out this problem. I think this debug can go. I also
> think the function can be cleaned up some more. Can you test this patch?

Works for me!

Thanks, Jan

> Thanks,
> 
>    Wolfram
> 
> diff --git a/drivers/i2c/i2c-core.c b/drivers/i2c/i2c-core.c
> index 0f2f8484e8ec1f..e584d88ee337f6 100644
> --- a/drivers/i2c/i2c-core.c
> +++ b/drivers/i2c/i2c-core.c
> @@ -525,22 +525,16 @@ static int i2c_device_match(struct device *dev, struct device_driver *drv)
>  	return 0;
>  }
>  
> -
> -/* uevent helps with hotplug: modprobe -q $(MODALIAS) */
>  static int i2c_device_uevent(struct device *dev, struct kobj_uevent_env *env)
>  {
> -	struct i2c_client	*client = to_i2c_client(dev);
> +	struct i2c_client *client = to_i2c_client(dev);
>  	int rc;
>  
>  	rc = acpi_device_uevent_modalias(dev, env);
>  	if (rc != -ENODEV)
>  		return rc;
>  
> -	if (add_uevent_var(env, "MODALIAS=%s%s",
> -			   I2C_MODULE_PREFIX, client->name))
> -		return -ENOMEM;
> -	dev_dbg(dev, "uevent\n");
> -	return 0;
> +	return add_uevent_var(env, "MODALIAS=%s%s", I2C_MODULE_PREFIX, client->name);
>  }
>  
>  /* i2c bus recovery routines */
>