Re: [PATCH i-g-t v2 8/8] tests/core_hotunplug: Print info between steps

[Andrzej Hajda <andrzej.hajda@intel.com>]

On 05.08.2024 16:37, Kamil Konieczny wrote:
> There are some info printed directly into kernel dmesg before
> subtest steps. Turn comment before steps into direct prints
> to stdout to help differentiate which steps where a success
> and where it starts failing.
>
> Fixed also one misspelling s/realoading/reloading/
>
> Signed-off-by: Kamil Konieczny <kamil.konieczny@linux.intel.com>

IGT is mostly very quiet, unless error occurs, then accumulated debug is 
printed.
This patch changes it, the output becomes chatty, could you explain more 
why such change,
why previous approach is not enough.

> ---
>   tests/core_hotunplug.c | 26 ++++++++++++++++++++------
>   1 file changed, 20 insertions(+), 6 deletions(-)
>
> diff --git a/tests/core_hotunplug.c b/tests/core_hotunplug.c
> index 51edee985..415c74381 100644
> --- a/tests/core_hotunplug.c
> +++ b/tests/core_hotunplug.c
> @@ -184,12 +184,13 @@ static void prepare(struct hotunplug *priv)
>   	igt_assert_fd(priv->fd.sysfs_bus);
>   
>   	priv->fd.sysfs_dev = close_sysfs(priv->fd.sysfs_dev);
> +	igt_info("Preparations done\n");
>   }
>   
> -/* Unbind the driver from the device */
>   static void driver_unbind(struct hotunplug *priv, const char *prefix,
>   			  int timeout)
>   {
> +	igt_info("Unbind the driver from the device (bus: %s)\n", priv->dev_bus_addr);

I see inconsistent ways of printing priv->dev_bus_addr:
1. "...(bus: %s)\n"
2. "...(%s)\n"
3. "%s\n"

Another question: do we need to print it in multpile lines, maybe one 
line at the beginning would be enough.


>   	/*
>   	 * FIXME: on some devices, the audio driver (snd_hda_intel)
>   	 * binds into the i915 driver. On such hardware, kernel warnings
> @@ -216,11 +217,13 @@ static void driver_unbind(struct hotunplug *priv, const char *prefix,
>   
>   	igt_assert_f(faccessat(priv->fd.sysfs_drv, priv->dev_bus_addr, F_OK, 0),
>   		     "Unbound device still present (%s)\n", priv->dev_bus_addr);
> +
> +	igt_info("Unbind done\n");
>   }
>   
> -/* Re-bind the driver to the device */
>   static void driver_bind(struct hotunplug *priv, int timeout)
>   {
> +	igt_info("Re-bind the driver to the device (bus: %s)\n", priv->dev_bus_addr);
>   	local_debug("%s\n", "rebinding the driver to the device");
with this we have after expansion:
igt_info
igt_debug
igt_kmsg

why do we need to print it twice on console, with different levels.

>   	priv->failure = "Driver re-bind failure!";
>   
> @@ -235,17 +238,19 @@ static void driver_bind(struct hotunplug *priv, int timeout)
>   		      "Rebound device not present (%s)!\n", priv->dev_bus_addr);
>   
>   	if (priv->snd_driver) {
> -		igt_info("Realoading %s\n", priv->snd_driver);
> +		igt_info("Reloading %s\n", priv->snd_driver);
>   		igt_kmod_load(priv->snd_driver, NULL);
>   		free(priv->snd_driver);
>   		priv->snd_driver = NULL;
>   	}
> +
> +	igt_info("Re-bind done\n");
>   }
>   
> -/* Remove (virtually unplug) the device from its bus */
>   static void device_unplug(struct hotunplug *priv, const char *prefix,
>   			  int timeout)
>   {
> +	igt_info("Remove (virtually unplug) the device from its bus (%s)\n", priv->dev_bus_addr);
>   	igt_require(priv->fd.sysfs_dev == -1);
>   
>   	/*
> @@ -267,7 +272,8 @@ static void device_unplug(struct hotunplug *priv, const char *prefix,
>   				    O_DIRECTORY);
>   	igt_assert_fd(priv->fd.sysfs_dev);
>   
> -	local_debug("%sunplugging the device\n", prefix);
> +	igt_info("%sunplugging the device %s\n", prefix, priv->dev_bus_addr);
> +	local_debug("%sunplugging the device %s\n", prefix, priv->dev_bus_addr);
>   	priv->failure = "Device unplug failure!";
>   
>   	igt_set_timeout(timeout, "Device unplug timeout!");
> @@ -280,11 +286,13 @@ static void device_unplug(struct hotunplug *priv, const char *prefix,
>   
>   	igt_assert_f(faccessat(priv->fd.sysfs_bus, priv->dev_bus_addr, F_OK, 0),
>   		     "Unplugged device still present (%s)\n", priv->dev_bus_addr);
> +
> +	igt_info("Unplug done\n");
>   }
>   
> -/* Re-discover the device by rescanning its bus */
>   static void bus_rescan(struct hotunplug *priv, int timeout)
>   {
> +	igt_info("Re-discover the device by rescanning its bus (%s)\n", priv->dev_bus_addr);
>   	local_debug("%s\n", "rediscovering the device");
>   	priv->failure = "Bus rescan failure!";
>   
> @@ -303,6 +311,8 @@ static void bus_rescan(struct hotunplug *priv, int timeout)
>   		free(priv->snd_driver);
>   		priv->snd_driver = NULL;
>   	}
> +
> +	igt_info("Bus rescan done\n");
>   }
>   
>   static void cleanup(struct hotunplug *priv)
> @@ -317,6 +327,7 @@ static void cleanup(struct hotunplug *priv)
>   	}
>   
>   	priv->fd.sysfs_dev = close_sysfs(priv->fd.sysfs_dev);
> +	igt_info("Cleanup done\n");
>   }
>   
>   static bool local_i915_is_wedged(int i915)
> @@ -498,6 +509,8 @@ static bool healthcheck(struct hotunplug *priv, bool recover)
>   		node_healthcheck(priv,
>   				 FLAG_RENDER | (recover ? FLAG_RECOVER : 0));
>   
> +	igt_info("Healthcheck: %s\n", priv->failure ? "failed" : "ok");
> +

Before you use "done" here "ok", no big deal, just another ask for 
consistency :)

Regards
Andrzej


>   	return !priv->failure;
>   }
>   
> @@ -532,6 +545,7 @@ static void recover(struct hotunplug *priv)
>   	else if (faccessat(priv->fd.sysfs_drv, priv->dev_bus_addr, F_OK, 0))
>   		driver_bind(priv, 60);
>   
> +	igt_info("Recovery: %s\n", priv->failure ? "failed" : "ok");
>   	if (priv->failure)
>   		igt_assert_f(healthcheck(priv, true), "%s\n", priv->failure);
>   }