Skip to contentSkip to conversation

cxacru: Use appropriate logging for errors

PATCH In review Simon Arlott 3 participants 12 messages Sep 23, 2007 – Sep 25, 2007

Subsystems (3)
USB ATM Conexant accessrunner USB driver
lore
Share & tools
lore

Simon Arlott

author
#0 lore raw

PATCH 1/2 cxacru: Use appropriate logging for errors

When an error occurs, existing logging uses dbg() so the cause of a problem is hard to determine. Error conditions shouldn't only be properly reported with debugging enabled.

A side effect of this change is that when an uninitialised device is started, a log message similar to the following is sent:

	cxacru 5-2:1.0: receive of cm 0x90 failed (-104)

This is normal - the device did not respond so firmware will be loaded.

Signed-off-by Simon Arlott <[email protected]>

---
This could be added to 2.6.23 since it only makes error logging more verbose.

 drivers/usb/atm/cxacru.c |   29 ++++++++++++++++++-----------
 1 files changed, 18 insertions(+), 11 deletions(-)
drivers/usb/atm/cxacru.c +18 -11
index a73e714..8d8a107 100644
@@ -482,7 +482,8 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	int rbuflen = ((rsize - 1) / stride + 1) * CMD_PACKET_SIZE;
 
 	if (wbuflen > PAGE_SIZE || rbuflen > PAGE_SIZE) {
-		dbg("too big transfer requested");
+		usb_err(instance->usbatm, "requested transfer size too large (%d, %d)\n",
+			wbuflen, rbuflen);
 		ret = -ENOMEM;
 		goto fail;
 	}

@@ -493,7 +494,8 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	init_completion(&instance->rcv_done);
 	ret = usb_submit_urb(instance->rcv_urb, GFP_KERNEL);
 	if (ret < 0) {
-		dbg("submitting read urb for cm %#x failed", cm);
+		usb_err(instance->usbatm, "submit of read urb for cm %#x failed (%d)\n",
+			cm, ret);
 		ret = ret;
 		goto fail;
 	}

@@ -510,27 +512,28 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	init_completion(&instance->snd_done);
 	ret = usb_submit_urb(instance->snd_urb, GFP_KERNEL);
 	if (ret < 0) {
-		dbg("submitting write urb for cm %#x failed", cm);
+		usb_err(instance->usbatm, "submit of write urb for cm %#x failed (%d)\n",
+			cm, ret);
 		ret = ret;
 		goto fail;
 	}
 
 	ret = cxacru_start_wait_urb(instance->snd_urb, &instance->snd_done, NULL);
 	if (ret < 0) {
-		dbg("sending cm %#x failed", cm);
+		usb_err(instance->usbatm, "send of cm %#x failed (%d)\n", cm, ret);
 		ret = ret;
 		goto fail;
 	}
 
 	ret = cxacru_start_wait_urb(instance->rcv_urb, &instance->rcv_done, &actlen);
 	if (ret < 0) {
-		dbg("receiving cm %#x failed", cm);
+		usb_err(instance->usbatm, "receive of cm %#x failed (%d)\n", cm, ret);
 		ret = ret;
 		goto fail;
 	}
 	if (actlen % CMD_PACKET_SIZE || !actlen) {
-		dbg("response is not a positive multiple of %d: %#x",
-				CMD_PACKET_SIZE, actlen);
+		usb_err(instance->usbatm, "invalid response length to cm %#x: %d\n",
+			cm, actlen);
 		ret = -EIO;
 		goto fail;
 	}

@@ -538,12 +541,14 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	/* check the return status and copy the data to the output buffer, if needed */
 	for (offb = offd = 0; offd < rsize && offb < actlen; offb += CMD_PACKET_SIZE) {
 		if (rbuf[offb] != cm) {
-			dbg("wrong cm %#x in response", rbuf[offb]);
+			usb_err(instance->usbatm, "wrong cm %#x in response to cm %#x\n",
+				rbuf[offb], cm);
 			ret = -EIO;
 			goto fail;
 		}
 		if (rbuf[offb + 1] != CM_STATUS_SUCCESS) {
-			dbg("response failed: %#x", rbuf[offb + 1]);
+			usb_err(instance->usbatm, "response to cm %#x failed: %#x\n",
+				cm, rbuf[offb + 1]);
 			ret = -EIO;
 			goto fail;
 		}

@@ -582,14 +587,16 @@ static int cxacru_cm_get_array(struct cxacru_data *instance, enum cxacru_cm_requ
 	for (offb = 0; offb < len; ) {
 		int l = le32_to_cpu(buf[offb++]);
 		if (l > stride || l > (len - offb) / 2) {
-			dbg("wrong data length %#x in response", l);
+			usb_err(instance->usbatm, "invalid data length from cm %#x: %d\n",
+				cm, l);
 			ret = -EIO;
 			goto cleanup;
 		}
 		while (l--) {
 			offd = le32_to_cpu(buf[offb++]);
 			if (offd >= size) {
-				dbg("wrong index %#x in response", offd);
+				usb_err(instance->usbatm, "wrong index #%x in response to cm #%x\n",
+					offd, cm);
 				ret = -EIO;
 				goto cleanup;
 			}
Signature · 4 lines
1.5.0.1

-- 
Simon Arlott
author
#1 lore raw

PATCH 2/3 cxacru: Reduce initialisation delay

Since card status updates appear to only occur every second, a delay of 1000ms on startup may not be sufficient - change to 1500ms.

The long delay of 4000ms is likely to be related to the time required for the ADSL line to come up - the driver should not need to do this.

Overall delay when loading firmware will change from 5000ms to 1500ms.

Signed-off-by Simon Arlott <[email protected]>
---
 drivers/usb/atm/cxacru.c |    9 +++++----
 1 files changed, 5 insertions(+), 4 deletions(-)
drivers/usb/atm/cxacru.c +5 -4
index 8d8a107..35308a8 100644
@@ -931,9 +931,10 @@ static void cxacru_upload_firmware(struct cxacru_data *instance,
 		usb_err(usbatm, "Passing control to firmware failed: %d\n", ret);
 		return;
 	}
+	usb_info(usbatm, "started firmware\n");
 
 	/* Delay to allow firmware to start up. */
-	msleep_interruptible(1000);
+	msleep(1500);
 
 	usb_clear_halt(usb_dev, usb_sndbulkpipe(usb_dev, CXACRU_EP_CMD));
 	usb_clear_halt(usb_dev, usb_rcvbulkpipe(usb_dev, CXACRU_EP_CMD));

@@ -947,7 +948,7 @@ static void cxacru_upload_firmware(struct cxacru_data *instance,
 	}
 
 	/* Load config data (le32), doing one packet at a time */
-	if (cf)
+	if (cf) {
 		for (off = 0; off < cf->size / 4; ) {
 			u32 buf[CMD_PACKET_SIZE / 4 - 1];
 			int i, len = min_t(int, cf->size / 4 - off, CMD_PACKET_SIZE / 4 / 2 - 1);

@@ -963,8 +964,8 @@ static void cxacru_upload_firmware(struct cxacru_data *instance,
 				return;
 			}
 		}
-
-	msleep_interruptible(4000);
+		usb_info(usbatm, "loaded config data\n");
+	}
 }
 
 static int cxacru_find_firmware(struct cxacru_data *instance,
Signature · 4 lines
1.5.0.1

-- 
Simon Arlott
#2 lore raw

Re: [PATCH 2/3] cxacru: Reduce initialisation delay

Hi Simon,

Quoted 1 line
drivers/usb/atm/cxacru.c +1 -0
+	usb_info(usbatm, "started firmware\n");

...

drivers/usb/atm/cxacru.c static void cxacru_upload_firmware(struct cxacru_data *instance, · line 967

Quoted 1 line
drivers/usb/atm/cxacru.c +1 -0
+		usb_info(usbatm, "loaded config data\n");

maybe these should be debug messages. When are they useful?

Ciao,

Duncan.

author
#3 lore raw

Re: [PATCH 2/3] cxacru: Reduce initialisation delay

Quoted 7 lines · Duncan Sands

Hi Simon,

Quoted 1 line
drivers/usb/atm/cxacru.c +1 -0
+	usb_info(usbatm, "started firmware\n");

...

drivers/usb/atm/cxacru.c static void cxacru_upload_firmware(struct cxacru_data *instance, · line 967

Quoted 1 line
drivers/usb/atm/cxacru.c +1 -0
+		usb_info(usbatm, "loaded config data\n");

maybe these should be debug messages. When are they useful?

They are probably only useful as debug messages - although it may be desirable to know when the configuration has been set.

Also... it doesn't make sense to load the configuration only in heavy_init - if the configuration is changed then there's no way in the module to resend it without powering the device down and up. Some sysfs parameters to change configuration could be useful... except there's no information as to what these settings are.

Signature · 1 line
Simon Arlott
author
#4 lore raw

Re: [PATCH 3/3] cxacru: Cleanup code by removing "ret = ret;" assignments

In reply to Simon Arlott

Cleanup code by removing "ret = ret;" assignments.

Signed-off-by Simon Arlott <[email protected]>
---
 drivers/usb/atm/cxacru.c |    4 ----
 1 files changed, 0 insertions(+), 4 deletions(-)
drivers/usb/atm/cxacru.c +0 -4
index 35308a8..bb3169c 100644
@@ -496,7 +496,6 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	if (ret < 0) {
 		usb_err(instance->usbatm, "submit of read urb for cm %#x failed (%d)\n",
 			cm, ret);
-		ret = ret;
 		goto fail;
 	}
 

@@ -514,21 +513,18 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	if (ret < 0) {
 		usb_err(instance->usbatm, "submit of write urb for cm %#x failed (%d)\n",
 			cm, ret);
-		ret = ret;
 		goto fail;
 	}
 
 	ret = cxacru_start_wait_urb(instance->snd_urb, &instance->snd_done, NULL);
 	if (ret < 0) {
 		usb_err(instance->usbatm, "send of cm %#x failed (%d)\n", cm, ret);
-		ret = ret;
 		goto fail;
 	}
 
 	ret = cxacru_start_wait_urb(instance->rcv_urb, &instance->rcv_done, &actlen);
 	if (ret < 0) {
 		usb_err(instance->usbatm, "receive of cm %#x failed (%d)\n", cm, ret);
-		ret = ret;
 		goto fail;
 	}
 	if (actlen % CMD_PACKET_SIZE || !actlen) {
Signature · 4 lines
1.5.0.1

-- 
Simon Arlott
author Nacked-by NAK
#6 lore raw

Re: [PATCH 3/3] cxacru: Cleanup code by removing "ret = ret;" assignments

Quoted 6 lines · Duncan Sands
Quoted 3 lines · On Sunday 23 September 2007 17:36:08 Simon Arlott wrote:

Cleanup code by removing "ret = ret;" assignments.

Signed-off-by Simon Arlott <[email protected]>
Acked-by Duncan Sands <[email protected]>
Nacked-by Simon Arlott <[email protected]>

I'm only going to create a merge conflict with myself with this :| It'll be included with 1/3 shortly.

Signature · 1 line
Simon Arlott
#7 lore raw

Re: [PATCH 3/3] cxacru: Cleanup code by removing "ret = ret;" assignments

Quoted 4 lines · Simon Arlott
Quoted 3 lines · Duncan Sands
Quoted 2 lines · On Sunday 23 September 2007 17:36:08 Simon Arlott wrote:

Cleanup code by removing "ret = ret;" assignments.

Quoted 8 lines
Quoted 3 lines
Quoted 1 line
Signed-off-by Simon Arlott <[email protected]>
Acked-by Duncan Sands <[email protected]>
Nacked-by Simon Arlott <[email protected]>

I'm only going to create a merge conflict with myself with this :| It'll be included with 1/3 shortly.

Ok, I'm totally confused :)

Can you resend the patches you want to have included here, that are acked by both you and Duncan?

thanks,

greg k-h

author
#8 lore raw

PATCH 1/1 cxacru: Use appropriate logging for errors

When an error occurs, existing logging uses dbg() so the cause of a problem is hard to determine. Error conditions shouldn't only be properly reported with debugging enabled.

A side effect of this change is that when an uninitialised device is started, a log message similar to the following is sent:

	cxacru 5-2:1.0: receive of cm 0x90 failed (-104)

This is normal - the device did not respond so firmware will be loaded.

Signed-off-by Simon Arlott <[email protected]>
Acked-by Duncan Sands <[email protected]>

---

Quoted 4 lines · Greg KH
Quoted 2 lines · Simon Arlott

I'm only going to create a merge conflict with myself with this :| It'll be included with 1/3 shortly.

Quoted 8 lines

Ok, I'm totally confused :)

Can you resend the patches you want to have included here, that are acked by both you and Duncan?

thanks,

greg k-h

 drivers/usb/atm/cxacru.c |   43 ++++++++++++++++++++++++++++---------------
 1 files changed, 28 insertions(+), 15 deletions(-)
drivers/usb/atm/cxacru.c +28 -15
index 1e5ee88..50249a5 100644
@@ -482,7 +482,9 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	int rbuflen = ((rsize - 1) / stride + 1) * CMD_PACKET_SIZE;
 
 	if (wbuflen > PAGE_SIZE || rbuflen > PAGE_SIZE) {
-		dbg("too big transfer requested");
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "requested transfer size too large (%d, %d)\n",
+				wbuflen, rbuflen);
 		ret = -ENOMEM;
 		goto fail;
 	}

@@ -493,8 +495,9 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	init_completion(&instance->rcv_done);
 	ret = usb_submit_urb(instance->rcv_urb, GFP_KERNEL);
 	if (ret < 0) {
-		dbg("submitting read urb for cm %#x failed", cm);
-		ret = ret;
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "submit of read urb for cm %#x failed (%d)\n",
+				cm, ret);
 		goto fail;
 	}
 

@@ -510,27 +513,29 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	init_completion(&instance->snd_done);
 	ret = usb_submit_urb(instance->snd_urb, GFP_KERNEL);
 	if (ret < 0) {
-		dbg("submitting write urb for cm %#x failed", cm);
-		ret = ret;
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "submit of write urb for cm %#x failed (%d)\n",
+				cm, ret);
 		goto fail;
 	}
 
 	ret = cxacru_start_wait_urb(instance->snd_urb, &instance->snd_done, NULL);
 	if (ret < 0) {
-		dbg("sending cm %#x failed", cm);
-		ret = ret;
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "send of cm %#x failed (%d)\n", cm, ret);
 		goto fail;
 	}
 
 	ret = cxacru_start_wait_urb(instance->rcv_urb, &instance->rcv_done, &actlen);
 	if (ret < 0) {
-		dbg("receiving cm %#x failed", cm);
-		ret = ret;
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "receive of cm %#x failed (%d)\n", cm, ret);
 		goto fail;
 	}
 	if (actlen % CMD_PACKET_SIZE || !actlen) {
-		dbg("response is not a positive multiple of %d: %#x",
-				CMD_PACKET_SIZE, actlen);
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "invalid response length to cm %#x: %d\n",
+				cm, actlen);
 		ret = -EIO;
 		goto fail;
 	}

@@ -538,12 +543,16 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	/* check the return status and copy the data to the output buffer, if needed */
 	for (offb = offd = 0; offd < rsize && offb < actlen; offb += CMD_PACKET_SIZE) {
 		if (rbuf[offb] != cm) {
-			dbg("wrong cm %#x in response", rbuf[offb]);
+			if (printk_ratelimit())
+				usb_err(instance->usbatm, "wrong cm %#x in response to cm %#x\n",
+					rbuf[offb], cm);
 			ret = -EIO;
 			goto fail;
 		}
 		if (rbuf[offb + 1] != CM_STATUS_SUCCESS) {
-			dbg("response failed: %#x", rbuf[offb + 1]);
+			if (printk_ratelimit())
+				usb_err(instance->usbatm, "response to cm %#x failed: %#x\n",
+					cm, rbuf[offb + 1]);
 			ret = -EIO;
 			goto fail;
 		}

@@ -582,14 +591,18 @@ static int cxacru_cm_get_array(struct cxacru_data *instance, enum cxacru_cm_requ
 	for (offb = 0; offb < len; ) {
 		int l = le32_to_cpu(buf[offb++]);
 		if (l > stride || l > (len - offb) / 2) {
-			dbg("wrong data length %#x in response", l);
+			if (printk_ratelimit())
+				usb_err(instance->usbatm, "invalid data length from cm %#x: %d\n",
+					cm, l);
 			ret = -EIO;
 			goto cleanup;
 		}
 		while (l--) {
 			offd = le32_to_cpu(buf[offb++]);
 			if (offd >= size) {
-				dbg("wrong index %#x in response", offd);
+				if (printk_ratelimit())
+					usb_err(instance->usbatm, "wrong index #%x in response to cm #%x\n",
+						offd, cm);
 				ret = -EIO;
 				goto cleanup;
 			}
Signature · 4 lines
1.5.0.1

-- 
Simon Arlott
#9 lore raw
In reply to Simon Arlott

Hi Simon, don't these error messages (except the first) risk spamming the log if something goes wrong (like the modem being unplugged)? How about rate-limiting them, like usbatm does?

Ciao,

Duncan.

author
#10 lore raw

PATCH 1/2 cxacru: Use appropriate logging for errors

When an error occurs, existing logging uses dbg() so the cause of a problem is hard to determine. Error conditions shouldn't only be properly reported with debugging enabled.

A side effect of this change is that when an uninitialised device is started, a log message similar to the following is sent:

	cxacru 5-2:1.0: receive of cm 0x90 failed (-104)

This is normal - the device did not respond so firmware will be loaded.

Signed-off-by Simon Arlott <[email protected]>

---

Quoted 7 lines · Duncan Sands

Hi Simon, don't these error messages (except the first) risk spamming the log if something goes wrong (like the modem being unplugged)? How about rate-limiting them, like usbatm does?

Ciao,

Duncan.

Ok.

 drivers/usb/atm/cxacru.c |   43 ++++++++++++++++++++++++++++---------------
 1 files changed, 28 insertions(+), 15 deletions(-)
drivers/usb/atm/cxacru.c +28 -15
index 1e5ee88..50249a5 100644
@@ -482,7 +482,9 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	int rbuflen = ((rsize - 1) / stride + 1) * CMD_PACKET_SIZE;
 
 	if (wbuflen > PAGE_SIZE || rbuflen > PAGE_SIZE) {
-		dbg("too big transfer requested");
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "requested transfer size too large (%d, %d)\n",
+				wbuflen, rbuflen);
 		ret = -ENOMEM;
 		goto fail;
 	}

@@ -493,8 +495,9 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	init_completion(&instance->rcv_done);
 	ret = usb_submit_urb(instance->rcv_urb, GFP_KERNEL);
 	if (ret < 0) {
-		dbg("submitting read urb for cm %#x failed", cm);
-		ret = ret;
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "submit of read urb for cm %#x failed (%d)\n",
+				cm, ret);
 		goto fail;
 	}
 

@@ -510,27 +513,29 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	init_completion(&instance->snd_done);
 	ret = usb_submit_urb(instance->snd_urb, GFP_KERNEL);
 	if (ret < 0) {
-		dbg("submitting write urb for cm %#x failed", cm);
-		ret = ret;
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "submit of write urb for cm %#x failed (%d)\n",
+				cm, ret);
 		goto fail;
 	}
 
 	ret = cxacru_start_wait_urb(instance->snd_urb, &instance->snd_done, NULL);
 	if (ret < 0) {
-		dbg("sending cm %#x failed", cm);
-		ret = ret;
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "send of cm %#x failed (%d)\n", cm, ret);
 		goto fail;
 	}
 
 	ret = cxacru_start_wait_urb(instance->rcv_urb, &instance->rcv_done, &actlen);
 	if (ret < 0) {
-		dbg("receiving cm %#x failed", cm);
-		ret = ret;
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "receive of cm %#x failed (%d)\n", cm, ret);
 		goto fail;
 	}
 	if (actlen % CMD_PACKET_SIZE || !actlen) {
-		dbg("response is not a positive multiple of %d: %#x",
-				CMD_PACKET_SIZE, actlen);
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "invalid response length to cm %#x: %d\n",
+				cm, actlen);
 		ret = -EIO;
 		goto fail;
 	}

@@ -538,12 +543,16 @@ static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm,
 	/* check the return status and copy the data to the output buffer, if needed */
 	for (offb = offd = 0; offd < rsize && offb < actlen; offb += CMD_PACKET_SIZE) {
 		if (rbuf[offb] != cm) {
-			dbg("wrong cm %#x in response", rbuf[offb]);
+			if (printk_ratelimit())
+				usb_err(instance->usbatm, "wrong cm %#x in response to cm %#x\n",
+					rbuf[offb], cm);
 			ret = -EIO;
 			goto fail;
 		}
 		if (rbuf[offb + 1] != CM_STATUS_SUCCESS) {
-			dbg("response failed: %#x", rbuf[offb + 1]);
+			if (printk_ratelimit())
+				usb_err(instance->usbatm, "response to cm %#x failed: %#x\n",
+					cm, rbuf[offb + 1]);
 			ret = -EIO;
 			goto fail;
 		}

@@ -582,14 +591,18 @@ static int cxacru_cm_get_array(struct cxacru_data *instance, enum cxacru_cm_requ
 	for (offb = 0; offb < len; ) {
 		int l = le32_to_cpu(buf[offb++]);
 		if (l > stride || l > (len - offb) / 2) {
-			dbg("wrong data length %#x in response", l);
+			if (printk_ratelimit())
+				usb_err(instance->usbatm, "invalid data length from cm %#x: %d\n",
+					cm, l);
 			ret = -EIO;
 			goto cleanup;
 		}
 		while (l--) {
 			offd = le32_to_cpu(buf[offb++]);
 			if (offd >= size) {
-				dbg("wrong index %#x in response", offd);
+				if (printk_ratelimit())
+					usb_err(instance->usbatm, "wrong index #%x in response to cm #%x\n",
+						offd, cm);
 				ret = -EIO;
 				goto cleanup;
 			}
Signature · 4 lines
1.5.0.1

-- 
Simon Arlott
Acked-by on v1 1/2
#11 lore raw

drivers/usb/atm/cxacru.c static int cxacru_cm(struct cxacru_data *instance, enum cxacru_cm_request cm, · line 487

Quoted 4 lines
drivers/usb/atm/cxacru.c +3 -1
-		dbg("too big transfer requested");
+		if (printk_ratelimit())
+			usb_err(instance->usbatm, "requested transfer size too large (%d, %d)\n",
+				wbuflen, rbuflen);

etc

Acked-by Duncan Sands <[email protected]>