[PATCH 0/3] device: core: Adjust device probe log messages to ease error detection

[PATCH 0/3] device: core: Adjust device probe log messages to ease error detection

[Nícolas F. R. A. Prado]

This series adjusts log message's log levels and helper functions to
make it easier to detect issues with the probe of devices.

This is the rationale:

- The dev_* printk variants should be used to log information related to
  the probe of a device so that the messages get the device's metadata
  attached and can easily be correlated to it.
- Issues in the probe of a device should be logged at the error level.
  If it is likely that an issue has ocurred, but not guaranteed, log at
  the warning level.

Signed-off-by: Nícolas F. R. A. Prado <nfraprado@collabora.com>
---
Nícolas F. R. A. Prado (3):
      driver: core: Log probe failure as error and with device metadata
      driver: core: Use dev_* instead of pr_* so device metadata is added
      device: core: Log warning for devices pending deferred probe on timeout

 drivers/base/dd.c | 32 +++++++++++++++-----------------
 1 file changed, 15 insertions(+), 17 deletions(-)
---
base-commit: 11afac187274a6177a7ac82997f8691c0f469e41
change-id: 20240305-device-probe-error-ec99e7bdd2d3

Best regards,
-- 
Nícolas F. R. A. Prado <nfraprado@collabora.com>

[PATCH 1/3] driver: core: Log probe failure as error and with device metadata

[Nícolas F. R. A. Prado]

Drivers can return -ENODEV or -ENXIO from their probe to reject a device
match, and return -EPROBE_DEFER if probe should be retried. Any other
error code is not expected during normal behavior and indicates an
issue occurred, so it should be logged at the error level.

Also make use of the device variant, dev_err(), so that the device
metadata is attached to the log message.

Signed-off-by: Nícolas F. R. A. Prado <nfraprado@collabora.com>
---
 drivers/base/dd.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index 85152537dbf1..0b7cf4516796 100644
--- a/drivers/base/dd.c
+++ b/drivers/base/dd.c
@@ -592,8 +592,8 @@ static int call_driver_probe(struct device *dev, struct device_driver *drv)
 		break;
 	default:
 		/* driver matched but the probe failed */
-		pr_warn("%s: probe of %s failed with error %d\n",
-			drv->name, dev_name(dev), ret);
+		dev_err(dev, "probe with driver %s failed with error %d\n",
+			drv->name, ret);
 		break;
 	}
 

-- 
2.44.0

[PATCH 2/3] driver: core: Use dev_* instead of pr_* so device metadata is added

[Nícolas F. R. A. Prado]

Use the dev_* instead of the pr_* functions to log the status of device
probe so that the log message gets the device metadata attached to it.

Signed-off-by: Nícolas F. R. A. Prado <nfraprado@collabora.com>
---
 drivers/base/dd.c | 26 ++++++++++++--------------
 1 file changed, 12 insertions(+), 14 deletions(-)

diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index 0b7cf4516796..d6e7933e2521 100644
--- a/drivers/base/dd.c
+++ b/drivers/base/dd.c
@@ -397,13 +397,12 @@ bool device_is_bound(struct device *dev)
 static void driver_bound(struct device *dev)
 {
 	if (device_is_bound(dev)) {
-		pr_warn("%s: device %s already bound\n",
-			__func__, kobject_name(&dev->kobj));
+		dev_warn(dev, "%s: device already bound\n", __func__);
 		return;
 	}
 
-	pr_debug("driver: '%s': %s: bound to device '%s'\n", dev->driver->name,
-		 __func__, dev_name(dev));
+	dev_dbg(dev, "driver: '%s': %s: bound to device\n", dev->driver->name,
+		__func__);
 
 	klist_add_tail(&dev->p->knode_driver, &dev->driver->p->klist_devices);
 	device_links_driver_bound(dev);
@@ -587,8 +586,8 @@ static int call_driver_probe(struct device *dev, struct device_driver *drv)
 		break;
 	case -ENODEV:
 	case -ENXIO:
-		pr_debug("%s: probe of %s rejects match %d\n",
-			 drv->name, dev_name(dev), ret);
+		dev_dbg(dev, "probe with driver %s rejects match %d\n",
+			drv->name, ret);
 		break;
 	default:
 		/* driver matched but the probe failed */
@@ -620,8 +619,8 @@ static int really_probe(struct device *dev, struct device_driver *drv)
 	if (link_ret == -EPROBE_DEFER)
 		return link_ret;
 
-	pr_debug("bus: '%s': %s: probing driver %s with device %s\n",
-		 drv->bus->name, __func__, drv->name, dev_name(dev));
+	dev_dbg(dev, "bus: '%s': %s: probing driver %s with device\n",
+		drv->bus->name, __func__, drv->name);
 	if (!list_empty(&dev->devres_head)) {
 		dev_crit(dev, "Resources present before probing\n");
 		ret = -EBUSY;
@@ -644,8 +643,7 @@ static int really_probe(struct device *dev, struct device_driver *drv)
 
 	ret = driver_sysfs_add(dev);
 	if (ret) {
-		pr_err("%s: driver_sysfs_add(%s) failed\n",
-		       __func__, dev_name(dev));
+		dev_err(dev, "%s: driver_sysfs_add failed\n", __func__);
 		goto sysfs_failed;
 	}
 
@@ -706,8 +704,8 @@ static int really_probe(struct device *dev, struct device_driver *drv)
 		dev->pm_domain->sync(dev);
 
 	driver_bound(dev);
-	pr_debug("bus: '%s': %s: bound device %s to driver %s\n",
-		 drv->bus->name, __func__, dev_name(dev), drv->name);
+	dev_dbg(dev, "bus: '%s': %s: bound device to driver %s\n",
+		drv->bus->name, __func__, drv->name);
 	goto done;
 
 dev_sysfs_state_synced_failed:
@@ -786,8 +784,8 @@ static int __driver_probe_device(struct device_driver *drv, struct device *dev)
 		return -EBUSY;
 
 	dev->can_match = true;
-	pr_debug("bus: '%s': %s: matched device %s with driver %s\n",
-		 drv->bus->name, __func__, dev_name(dev), drv->name);
+	dev_dbg(dev, "bus: '%s': %s: matched device with driver %s\n",
+		drv->bus->name, __func__, drv->name);
 
 	pm_runtime_get_suppliers(dev);
 	if (dev->parent)

-- 
2.44.0

[PATCH 3/3] device: core: Log warning for devices pending deferred probe on timeout

[Nícolas F. R. A. Prado]

Once the deferred probe timeout has elapsed it is very likely that the
devices that are still deferring probe won't ever be probed. Therefore
log the defer probe pending reason at the warning level instead to bring
attention to the issue.

Signed-off-by: Nícolas F. R. A. Prado <nfraprado@collabora.com>
---
 drivers/base/dd.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index d6e7933e2521..83d352394fdf 100644
--- a/drivers/base/dd.c
+++ b/drivers/base/dd.c
@@ -313,7 +313,7 @@ static void deferred_probe_timeout_work_func(struct work_struct *work)
 
 	mutex_lock(&deferred_probe_mutex);
 	list_for_each_entry(p, &deferred_probe_pending_list, deferred_probe)
-		dev_info(p->device, "deferred probe pending: %s", p->deferred_probe_reason ?: "(reason unknown)\n");
+		dev_warn(p->device, "deferred probe pending: %s", p->deferred_probe_reason ?: "(reason unknown)\n");
 	mutex_unlock(&deferred_probe_mutex);
 
 	fw_devlink_probing_done();

-- 
2.44.0