staging: unisys: add error messages to visornic

Add error message to genuine rare error paths, and debug messages
to enable relatively non-verbose tracing of code paths

You can enable debug messages by including this on the kernel command line:

    visornic.dyndbg=+p

or by this from the command line:

    echo "module visornic +p" > <debugfs>/dynamic_debug/control

Refer to Documentation/dynamic-debug-howto.txt for more details.

In addition to the new debug and error messages, a message like the
following will be logged every time a visornic device is probed, which
will enable you to map back-and-forth between visorbus device names
(e.g., "vbus2:dev0") and netdev names (e.g., "eth0"):

    visornic vbus2:dev0: visornic_probe success netdev=eth0

With this patch and visornic debugging enabled, you should expect to see
messages like the following in the most-common scenarios:

* driver loaded:

      visornic_init

* device probed:

      visornic vbus2:dev0: visornic_probe
      visor_thread_start
      visor_thread_start success

* network interface configured (ifconfig):

      net eth0: visornic_open
      net eth0: visornic_enable_with_timeout
      net eth0: visornic_enable_with_timeout success
      net eth0: visornic_open success

Signed-off-by: Tim Sell <Timothy.Sell@unisys.com>
Signed-off-by: Benjamin Romer <benjamin.romer@unisys.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

diff --git a/drivers/staging/unisys/visornic/visornic_main.c b/drivers/staging/unisys/visornic/visornic_main.c
index 915c913..de05ac7 100644 (file)
--- a/drivers/staging/unisys/visornic/visornic_main.c
+++ b/drivers/staging/unisys/visornic/visornic_main.c
@@ -299,6 +299,8 @@ static int visor_thread_start(struct visor_thread_info *thrinfo,
        init_completion(&thrinfo->has_stopped);
        thrinfo->task = kthread_run(threadfn, thrcontext, name);
        if (IS_ERR(thrinfo->task)) {
+               pr_debug("%s failed (%ld)\n",
+                        __func__, PTR_ERR(thrinfo->task));
                thrinfo->id = 0;
                return -EINVAL;
        }
@@ -572,6 +574,8 @@ visornic_serverdown(struct visornic_devdata *devdata,
                queue_work(visornic_serverdown_workqueue,
                           &devdata->serverdown_completion);
        } else if (devdata->server_change_state) {
+               dev_dbg(&devdata->dev->device, "%s changing state\n",
+                       __func__);
                return -EINVAL;
        }
        return 0;
@@ -708,6 +712,8 @@ visornic_disable_with_timeout(struct net_device *netdev, const int timeout)
                        break;
                if (devdata->server_down || devdata->server_change_state) {
                        spin_unlock_irqrestore(&devdata->priv_lock, flags);
+                       dev_dbg(&netdev->dev, "%s server went away\n",
+                               __func__);
                        return -EIO;
                }
                set_current_state(TASK_INTERRUPTIBLE);
@@ -821,8 +827,11 @@ visornic_enable_with_timeout(struct net_device *netdev, const int timeout)
         * gets a disable.
         */
        i = init_rcv_bufs(netdev, devdata);
-       if (i < 0)
+       if (i < 0) {
+               dev_err(&netdev->dev,
+                       "%s failed to init rcv bufs (%d)\n", __func__, i);
                return i;
+       }
 
        spin_lock_irqsave(&devdata->priv_lock, flags);
        devdata->enabled = 1;
@@ -845,6 +854,8 @@ visornic_enable_with_timeout(struct net_device *netdev, const int timeout)
                        break;
                if (devdata->server_down || devdata->server_change_state) {
                        spin_unlock_irqrestore(&devdata->priv_lock, flags);
+                       dev_dbg(&netdev->dev, "%s server went away\n",
+                               __func__);
                        return -EIO;
                }
                set_current_state(TASK_INTERRUPTIBLE);
@@ -855,8 +866,10 @@ visornic_enable_with_timeout(struct net_device *netdev, const int timeout)
 
        spin_unlock_irqrestore(&devdata->priv_lock, flags);
 
-       if (!devdata->enab_dis_acked)
+       if (!devdata->enab_dis_acked) {
+               dev_err(&netdev->dev, "%s missing ACK\n", __func__);
                return -EIO;
+       }
 
        /* find an open slot in the array to save off VisorNic references
         * for debug
@@ -968,6 +981,8 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
            devdata->server_change_state) {
                spin_unlock_irqrestore(&devdata->priv_lock, flags);
                devdata->busy_cnt++;
+               dev_dbg(&netdev->dev,
+                       "%s busy - queue stopped\n", __func__);
                return NETDEV_TX_BUSY;
        }
 
@@ -986,6 +1001,9 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
        if (firstfraglen < ETH_HEADER_SIZE) {
                spin_unlock_irqrestore(&devdata->priv_lock, flags);
                devdata->busy_cnt++;
+               dev_err(&netdev->dev,
+                       "%s busy - first frag too small (%d)\n",
+                       __func__, firstfraglen);
                return NETDEV_TX_BUSY;
        }
 
@@ -1025,6 +1043,9 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
                netif_stop_queue(netdev);
                spin_unlock_irqrestore(&devdata->priv_lock, flags);
                devdata->busy_cnt++;
+               dev_dbg(&netdev->dev,
+                       "%s busy - waiting for iovm to catch up\n",
+                       __func__);
                return NETDEV_TX_BUSY;
        }
        if (devdata->queuefullmsg_logged)
@@ -1065,6 +1086,8 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
        if (cmdrsp->net.xmt.num_frags == -1) {
                spin_unlock_irqrestore(&devdata->priv_lock, flags);
                devdata->busy_cnt++;
+               dev_err(&netdev->dev,
+                       "%s busy - copy frags failed\n", __func__);
                return NETDEV_TX_BUSY;
        }
 
@@ -1073,6 +1096,8 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
                netif_stop_queue(netdev);
                spin_unlock_irqrestore(&devdata->priv_lock, flags);
                devdata->busy_cnt++;
+               dev_dbg(&netdev->dev,
+                       "%s busy - signalinsert failed\n", __func__);
                return NETDEV_TX_BUSY;
        }
 
@@ -1105,6 +1130,9 @@ visornic_xmit(struct sk_buff *skb, struct net_device *netdev)
                                           * netif_wake_queue() after lower
                                           * threshold
                                           */
+               dev_dbg(&netdev->dev,
+                       "%s busy - invoking iovm flow control\n",
+                       __func__);
                devdata->flow_control_upper_hits++;
        }
        spin_unlock_irqrestore(&devdata->priv_lock, flags);
@@ -1211,6 +1239,8 @@ visornic_xmit_timeout(struct net_device *netdev)
        /* Ensure that a ServerDown message hasn't been received */
        if (!devdata->enabled ||
            (devdata->server_down && !devdata->server_change_state)) {
+               dev_dbg(&netdev->dev, "%s no processing\n",
+                       __func__);
                spin_unlock_irqrestore(&devdata->priv_lock, flags);
                return;
        }
@@ -1808,8 +1838,11 @@ static int visornic_probe(struct visor_device *dev)
        u64 features;
 
        netdev = alloc_etherdev(sizeof(struct visornic_devdata));
-       if (!netdev)
+       if (!netdev) {
+               dev_err(&dev->device,
+                       "%s alloc_etherdev failed\n", __func__);
                return -ENOMEM;
+       }
 
        netdev->netdev_ops = &visornic_dev_ops;
        netdev->watchdog_timeo = (5 * HZ);
@@ -1821,11 +1854,17 @@ static int visornic_probe(struct visor_device *dev)
                                  vnic.macaddr);
        err = visorbus_read_channel(dev, channel_offset, netdev->dev_addr,
                                    ETH_ALEN);
-       if (err < 0)
+       if (err < 0) {
+               dev_err(&dev->device,
+                       "%s failed to get mac addr from chan (%d)\n",
+                       __func__, err);
                goto cleanup_netdev;
+       }
 
        devdata = devdata_initialize(netdev_priv(netdev), dev);
        if (!devdata) {
+               dev_err(&dev->device,
+                       "%s devdata_initialize failed\n", __func__);
                err = -ENOMEM;
                goto cleanup_netdev;
        }
@@ -1842,8 +1881,12 @@ static int visornic_probe(struct visor_device *dev)
                                  vnic.num_rcv_bufs);
        err = visorbus_read_channel(dev, channel_offset,
                                    &devdata->num_rcv_bufs, 4);
-       if (err)
+       if (err) {
+               dev_err(&dev->device,
+                       "%s failed to get #rcv bufs from chan (%d)\n",
+                       __func__, err);
                goto cleanup_netdev;
+       }
 
        devdata->rcvbuf = kzalloc(sizeof(struct sk_buff *) *
                                  devdata->num_rcv_bufs, GFP_KERNEL);
@@ -1884,38 +1927,58 @@ static int visornic_probe(struct visor_device *dev)
        channel_offset = offsetof(struct spar_io_channel_protocol,
                                  vnic.mtu);
        err = visorbus_read_channel(dev, channel_offset, &netdev->mtu, 4);
-       if (err)
+       if (err) {
+               dev_err(&dev->device,
+                       "%s failed to get mtu from chan (%d)\n",
+                       __func__, err);
                goto cleanup_xmit_cmdrsp;
+       }
 
        /* TODO: Setup Interrupt information */
        /* Let's start our threads to get responses */
        channel_offset = offsetof(struct spar_io_channel_protocol,
                                  channel_header.features);
        err = visorbus_read_channel(dev, channel_offset, &features, 8);
-       if (err)
+       if (err) {
+               dev_err(&dev->device,
+                       "%s failed to get features from chan (%d)\n",
+                       __func__, err);
                goto cleanup_xmit_cmdrsp;
+       }
 
        features |= ULTRA_IO_CHANNEL_IS_POLLING;
        err = visorbus_write_channel(dev, channel_offset, &features, 8);
-       if (err)
+       if (err) {
+               dev_err(&dev->device,
+                       "%s failed to set features in chan (%d)\n",
+                       __func__, err);
                goto cleanup_xmit_cmdrsp;
+       }
 
        devdata->thread_wait_ms = 2;
        visor_thread_start(&devdata->threadinfo, process_incoming_rsps,
                           devdata, "vnic_incoming");
 
        err = register_netdev(netdev);
-       if (err)
+       if (err) {
+               dev_err(&dev->device,
+                       "%s register_netdev failed (%d)\n", __func__, err);
                goto cleanup_thread_stop;
+       }
 
        /* create debgug/sysfs directories */
        devdata->eth_debugfs_dir = debugfs_create_dir(netdev->name,
                                                      visornic_debugfs_dir);
        if (!devdata->eth_debugfs_dir) {
+               dev_err(&dev->device,
+                       "%s debugfs_create_dir %s failed\n",
+                       __func__, netdev->name);
                err = -ENOMEM;
                goto cleanup_thread_stop;
        }
 
+       dev_info(&dev->device, "%s success netdev=%s\n",
+                __func__, netdev->name);
        return 0;
 
 cleanup_thread_stop:
@@ -1963,8 +2026,10 @@ static void visornic_remove(struct visor_device *dev)
 {
        struct visornic_devdata *devdata = dev_get_drvdata(&dev->device);
 
-       if (!devdata)
+       if (!devdata) {
+               dev_err(&dev->device, "%s no devdata\n", __func__);
                return;
+       }
        dev_set_drvdata(&dev->device, NULL);
        host_side_disappeared(devdata);
        kref_put(&devdata->kref, devdata_release);
@@ -2010,8 +2075,10 @@ static int visornic_resume(struct visor_device *dev,
        unsigned long flags;
 
        devdata = dev_get_drvdata(&dev->device);
-       if (!devdata)
+       if (!devdata) {
+               dev_err(&dev->device, "%s no devdata\n", __func__);
                return -EINVAL;
+       }
 
        netdev = devdata->netdev;
 
@@ -2039,6 +2106,8 @@ static int visornic_resume(struct visor_device *dev,
                 */
                send_enbdis(netdev, 1, devdata);
        } else if (devdata->server_change_state) {
+               dev_err(&dev->device, "%s server_change_state\n",
+                       __func__);
                return -EIO;
        }