usblp_write spins forever after an error

I recently cancelled a print job with the printer's cancel function, and the CUPS backend got stuck in usblp_write (using 100% CPU and not responding to signals).

The printer is a Kyocera Mita FS-1900 (which has some other problems with the linux USB code: usblp_check_status often times out, even though the printer is bidirectional -- but that's a whole different issue).

It looks like the problem is that the write failed, so wcomplete got set to 1 and the status is nonzero. This case appears to be mishandled in usblp.c:

        while (writecount < count) {
                if (!usblp->wcomplete) {
			[... not reaching this code]
                }

                down (&usblp->sem);
                if (!usblp->present) {
                        up (&usblp->sem);
                        return -ENODEV;
                }
                if (usblp->writeurb->status != 0) {

			[ check status? ]

                        schedule ();
                        continue; <-- problem
                }

After the write fails, the current code keeps checking the same status, and never checks for signals or fails. I'm not sure what the right fix is, but it might be something like this:

@@ -645,13 +645,11 @@
                                err = usblp->writeurb->status;
                        } else
                                err = usblp_check_status(usblp, err);
-                       up (&usblp->sem);
 
-                       /* if the fault was due to disconnect, let khubd's
-                        * call to usblp_disconnect() grab usblp->sem ...
-                        */
-                       schedule ();
-                       continue;
+                       writecount += usblp->writeurb->transfer_buffer_length;
+                       up (&usblp->sem);
+                       count = writecount ? writecount : err;
+                       break;
                }
 
                writecount += usblp->writeurb->transfer_buffer_length;

--Andy

Please CC me -- I'm not subscribed.

What kernel are you referring to here?

thanks,

greg k-h

I wrote a patch some time ago to correct a bug exactly at usblp_write. It is still not in the main kernel, but you can give it a try and see if it helps. It applies cleanly against 2.6.2-rc2, but I guess it should apply to 2.6.2-rc3.

This patch corrected a problem for me, that happened when a printer presents an out-of-paper status while printing a document. The driver would send endless garbage to the printer.

I hope this helps,

Paulo Marques - www.grupopie.com
"In a world without walls and fences who needs windows and gates?"

@@ -603,7 +603,7 @@ static ssize_t usblp_write(struct file *
 {
 	DECLARE_WAITQUEUE(wait, current);
 	struct usblp *usblp = file->private_data;
-	int timeout, err = 0;
+	int timeout, err = 0, transfer_length;
 	size_t writecount = 0;
 
 	while (writecount < count) {

@@ -654,19 +654,13 @@ static ssize_t usblp_write(struct file *
 			continue;
 		}
 
-		writecount += usblp->writeurb->transfer_buffer_length;
-		usblp->writeurb->transfer_buffer_length = 0;
+		transfer_length=(count - writecount);
+		if (transfer_length > USBLP_BUF_SIZE)
+			transfer_length = USBLP_BUF_SIZE;
 
-		if (writecount == count) {
-			up (&usblp->sem);
-			break;
-		}
+		usblp->writeurb->transfer_buffer_length = transfer_length;
 
-		usblp->writeurb->transfer_buffer_length = (count - writecount) < USBLP_BUF_SIZE ?
-							  (count - writecount) : USBLP_BUF_SIZE;
-
-		if (copy_from_user(usblp->writeurb->transfer_buffer, buffer + writecount,
-				usblp->writeurb->transfer_buffer_length)) {
+		if (copy_from_user(usblp->writeurb->transfer_buffer, buffer + writecount, transfer_length)) {
 			up(&usblp->sem);
 			return writecount ? writecount : -EFAULT;
 		}

@@ -683,6 +677,8 @@ static ssize_t usblp_write(struct file *
 			break;
 		}
 		up (&usblp->sem);
+
+		writecount += transfer_length;
 	}
 
 	return count;

This patch went in to 2.6.4-rc1, didn't it? It seems to have exacerbated a problem which used to be occasional, but now seems to happen after every print job.

I see the following, and the error repeats until I power cycle the printer (HPLJ 1200 on AMD768 OHCI):

usb 1-1.3.2: control timeout on ep0in drivers/usb/class/usblp.c: usblp0: error -110 reading printer status

dwmw2

Yes, unfortunately it did went into 2.6.4-rc1. However it is already corrected in 2.6.4-rc2. Luckily it didn't went into any "non-rc" official release.

Please try 2.6.4-rc2, and check to see if the bug went away...

Paulo Marques - www.grupopie.com
"In a world without walls and fences who needs windows and gates?"

Seems to work; thanks. Does this need backporting to 2.4 too?

dwmw2

Unfortunately this isn't over yet.

I got suspicious about this bug fix, because I *did* test my patch before submitting it and the kernel that didn't work before, worked fine with my patch.

But now it seems that it is the other way around. After a few digging I found out the problem:

The application that I was testing with uses the usblp handle with non-blocking I/O .

So my patch does work for non-blocking I/O uses of the port, but wrecks the normal blocking mode.

I've already produced a version that works for both cases. I'll just clean it up a bit and submit it to 2.4 and 2.6 kernels.

Paulo Marques - www.grupopie.com
"In a world without walls and fences who needs windows and gates?"

Here it is.

The patch is only one line for 2.6.4-rc2. (I also did a little formatting adjustment to better comply with CodingStyle)

For the 2.4.26-pre1 kernel, I also backported the return codes correction patch from Oliver Neukum.

The problem with the write function was that, in non-blocking mode, after submitting the first urb, the function would return with -EAGAIN, not reporting to the application that in fact it had already sent "transfer_length" bytes. This way the application would have to send the data *again* causing lots of errors.

It did return the correct amount with my first patch, because the writecount was being updated on the end of the loop. However this was wrong for blocking I/O.

The "transfer_length" local variable is still needed because if we used the transfer_buffer_length field from the urb, then on a second call to write, if the urb was still pending (in non-blocking mode), the write would return an incorrect amount of data written.

Anyway, this time I tested it using blocking and non-blocking I/O and it works for both cases. Even better, this patch only changes the behaviour for non-blocking I/O, and keeps the same behaviour for the more usual blocking I/O (at least on kernel 2.6).

Please apply,

Paulo Marques - www.grupopie.com
"In a world without walls and fences who needs windows and gates?"

@@ -609,8 +609,10 @@ static ssize_t usblp_write(struct file *
 	while (writecount < count) {
 		if (!usblp->wcomplete) {
 			barrier();
-			if (file->f_flags & O_NONBLOCK)
+			if (file->f_flags & O_NONBLOCK) {
+				writecount += transfer_length;
 				return writecount ? writecount : -EAGAIN;
+			}
 
 			timeout = USBLP_WRITE_TIMEOUT;
 			add_wait_queue(&usblp->wait, &wait);

@@ -670,7 +672,8 @@ static ssize_t usblp_write(struct file *
 
 		usblp->writeurb->transfer_buffer_length = transfer_length;
 
-		if (copy_from_user(usblp->writeurb->transfer_buffer, buffer + writecount, transfer_length)) {
+		if (copy_from_user(usblp->writeurb->transfer_buffer, 
+				   buffer + writecount, transfer_length)) {
 			up(&usblp->sem);
 			return writecount ? writecount : -EFAULT;
 		}

@@ -604,14 +604,16 @@ static ssize_t usblp_write(struct file *
 {
 	DECLARE_WAITQUEUE(wait, current);
 	struct usblp *usblp = file->private_data;
-	int timeout, err = 0;
+	int timeout, err = 0, transfer_length = 0;
 	size_t writecount = 0;
 
 	while (writecount < count) {
 		if (!usblp->wcomplete) {
 			barrier();
-			if (file->f_flags & O_NONBLOCK)
-				return -EAGAIN;
+			if (file->f_flags & O_NONBLOCK) {
+				writecount += transfer_length;
+				return writecount ? writecount : -EAGAIN;
+			}
 
 			timeout = USBLP_WRITE_TIMEOUT;
 			add_wait_queue(&usblp->wait, &wait);

@@ -655,27 +657,36 @@ static ssize_t usblp_write(struct file *
 			continue;
 		}
 
-		writecount += usblp->writeurb->transfer_buffer_length;
-		usblp->writeurb->transfer_buffer_length = 0;
-
+		/* We must increment writecount here, and not at the
+		 * end of the loop. Otherwise, the final loop iteration may
+		 * be skipped, leading to incomplete printer output.
+		 */
+		writecount += transfer_length;
 		if (writecount == count) {
 			up (&usblp->sem);
 			break;
 		}
 
-		usblp->writeurb->transfer_buffer_length = (count - writecount) < USBLP_BUF_SIZE ?
-							  (count - writecount) : USBLP_BUF_SIZE;
+		transfer_length = count - writecount;
+		if(transfer_length > USBLP_BUF_SIZE) 
+			transfer_length = USBLP_BUF_SIZE;
+		
+		usblp->writeurb->transfer_buffer_length = transfer_length;
 
-		if (copy_from_user(usblp->writeurb->transfer_buffer, buffer + writecount,
-				usblp->writeurb->transfer_buffer_length)) {
+		if (copy_from_user(usblp->writeurb->transfer_buffer, 
+				   buffer + writecount, transfer_length)) {
 			up(&usblp->sem);
 			return writecount ? writecount : -EFAULT;
 		}
 
 		usblp->writeurb->dev = usblp->dev;
 		usblp->wcomplete = 0;
-		if (usb_submit_urb(usblp->writeurb)) {
-			count = -EIO;
+		err = usb_submit_urb(usblp->writeurb);
+		if (err) {
+			if (err != -ENOMEM)
+				count = -EIO;
+			else
+				count = writecount ? writecount : -ENOMEM;
 			up (&usblp->sem);
 			break;
 		}

Thanks, I've applied this to both the 2.4 and 2.6 usb trees.

greg k-h

I'm still seeing problems with an HP LaserJet 1200.

May  7 07:12:56 imladris kernel: usb 1-1.3.2: new full speed USB device using address 10
May  7 07:12:56 imladris kernel: drivers/usb/class/usblp.c: usblp0: USB Bidirectional printer dev 10 if 0 alt 1 proto 2 vid 0x03F0 pid 0x0317
May  8 20:26:12 imladris kernel: drivers/usb/class/usblp.c: usblp0: nonzero read/write bulk status received: -110
May  8 20:26:12 imladris kernel: drivers/usb/class/usblp.c: usblp0: failed reading printer status
May  8 20:26:12 imladris kernel: drivers/usb/class/usblp.c: usblp0: nonzero read/write bulk status received: -110
May  8 20:26:12 imladris kernel: drivers/usb/class/usblp.c: usblp0: error -110 reading printer status
May  8 20:26:43 imladris last message repeated 10225 times
May  8 20:27:09 imladris last message repeated 8780 times

dwmw2

This was 2.6.1 vanilla.

--Andy

BTW, these aren't going to linux-usb-devel because myrealbox.com fails verification. I emailed them -- hopefully they'll fix it soon.