Skip to contentSkip to conversation

nbd driver for 2.5+: enhanced diagnostics support

PATCH In review Lou Langholtz 2 participants 3 messages Jun 24, 2003

Subsystems (2)
lore
Share & tools
lore
#0 lore raw

PATCH 1/1 nbd driver for 2.5+: enhanced diagnostics support

This third patch (for enhancing diagnostics support) applies incrementally after my last LKML'd patch (for cosmetic changes). These changes introduce configurable KERN_DEBUG level printk output for a variety of different things that the driver does and provides the framework for enhanced future debugging support as well.

As always, comments welcome!

drivers/block/nbd.c +102 -33
diff -urN linux-2.5.72-p2.5/drivers/block/nbd.c linux-2.5.73-p3/drivers/block/nbd.c
@@ -32,6 +32,7 @@
  *   memory corruption from module removal and possible memory corruption
  *   from sending/receiving disk data. <[email protected]>
  * 03-06-23 Cosmetic changes. <[email protected]>
+ * 03-06-23 Enhance diagnostics support. <[email protected]>
  *
  * possible FIXME: make set_sock / set_blksize / set_size / do_it one syscall
  * why not: would need verify_area and friends, would share yet another 
@@ -65,6 +66,23 @@
 
 #define LO_MAGIC 0x68797548
 
+#ifdef NDEBUG
+#define dprintk(flags, fmt...)
+#else /* NDEBUG */
+#define dprintk(flags, fmt...) do { \
+	if (debugflags & (flags)) printk(KERN_DEBUG fmt); \
+} while (0)
+#define DBG_OPEN        0x0001
+#define DBG_RELEASE     0x0002
+#define DBG_IOCTL       0x0004
+#define DBG_INIT        0x0010
+#define DBG_EXIT        0x0020
+#define DBG_BLKDEV      0x0100
+#define DBG_RX          0x0200
+#define DBG_TX          0x0400
+static unsigned int debugflags;
+#endif /* NDEBUG */
+
 static struct nbd_device nbd_dev[MAX_NBD];
 
 /*
@@ -79,19 +97,49 @@
  */
 static spinlock_t nbd_lock = SPIN_LOCK_UNLOCKED;
 
-#define DEBUG( s )
-/* #define DEBUG( s ) printk( s ) 
- */
-
 static int requests_in;
 static int requests_out;
 
+#ifndef NDEBUG
+static const char *ioctl_cmd_to_ascii(int cmd)
+{
+	switch (cmd) {
+	case NBD_SET_SOCK: return "set-sock";
+	case NBD_SET_BLKSIZE: return "set-blksize";
+	case NBD_SET_SIZE: return "set-size";
+	case NBD_DO_IT: return "do-it";
+	case NBD_CLEAR_SOCK: return "clear-sock";
+	case NBD_CLEAR_QUE: return "clear-que";
+	case NBD_PRINT_DEBUG: return "print-debug";
+	case NBD_SET_SIZE_BLOCKS: return "set-size-blocks";
+	case NBD_DISCONNECT: return "disconnect";
+	case BLKROSET: return "set-read-only";
+	case BLKROGET: return "get-read-only";
+	case BLKGETSIZE: return "block-get-size";
+	case BLKFLSBUF: return "flush-buffer-cache";
+	}
+	return "unknown";
+}
+
+static const char *nbdcmd_to_ascii(int cmd)
+{
+	switch (cmd) {
+	case  NBD_CMD_READ: return "read";
+	case NBD_CMD_WRITE: return "write";
+	case  NBD_CMD_DISC: return "disconnect";
+	}
+	return "invalid";
+}
+#endif /* NDEBUG */
+
 static void nbd_end_request(struct request *req)
 {
 	int uptodate = (req->errors == 0) ? 1 : 0;
 	request_queue_t *q = req->q;
 	unsigned long flags;
 
+	dprintk(DBG_BLKDEV, "%s: request %p: %s\n", req->rq_disk->disk_name,
+			req, uptodate? "done": "failed");
 #ifdef PARANOIA
 	requests_out++;
 #endif
@@ -193,8 +241,6 @@
 	unsigned long size = req->nr_sectors << 9;
 	struct socket *sock = lo->sock;
 
-	DEBUG("nbd: sending control, ");
-	
 	request.magic = htonl(NBD_REQUEST_MAGIC);
 	request.type = htonl(nbd_cmd(req));
 	request.from = cpu_to_be64((u64) req->sector << 9);
@@ -204,15 +250,19 @@
 	down(&lo->tx_lock);
 
 	if (!sock || !lo->sock) {
-		printk(KERN_ERR "%s: Attempted sendmsg to closed socket\n",
+		printk(KERN_ERR "%s: Attempted send on closed socket\n",
 				lo->disk->disk_name);
 		goto error_out;
 	}
 
+	dprintk(DBG_TX, "%s: request %p: sending control (%s@%llu,%luB)\n",
+			lo->disk->disk_name, req,
+			nbdcmd_to_ascii(nbd_cmd(req)),
+			req->sector << 9, req->nr_sectors << 9);
 	result = sock_xmit(sock, 1, &request, sizeof(request),
 			(nbd_cmd(req) == NBD_CMD_WRITE)? MSG_MORE: 0);
 	if (result <= 0) {
-		printk(KERN_ERR "%s: Sendmsg failed for control (result %d)\n",
+		printk(KERN_ERR "%s: Send control failed (result %d)\n",
 				lo->disk->disk_name, result);
 		goto error_out;
 	}
@@ -229,7 +279,9 @@
 				flags = 0;
 				if ((i < (bio->bi_vcnt - 1)) || bio->bi_next)
 					flags = MSG_MORE;
-				DEBUG("data, ");
+				dprintk(DBG_TX, "%s: request %p: sending %d bytes data\n",
+						lo->disk->disk_name, req,
+						bvec->bv_len);
 				result = sock_send_bvec(sock, bvec, flags);
 				if (result <= 0) {
 					printk(KERN_ERR "%s: Send data failed (result %d)\n",
@@ -287,56 +339,59 @@
 	struct request *req;
 	struct socket *sock = lo->sock;
 
-	DEBUG("reading control, ");
 	reply.magic = 0;
 	result = sock_xmit(sock, 0, &reply, sizeof(reply), MSG_WAITALL);
 	if (result <= 0) {
-		printk(KERN_ERR "%s: Recv control failed (result %d)\n",
+		printk(KERN_ERR "%s: Receive control failed (result %d)\n",
 				lo->disk->disk_name, result);
 		lo->harderror = result;
 		return NULL;
 	}
 	req = nbd_find_request(lo, reply.handle);
 	if (req == NULL) {
-		printk(KERN_ERR "%s: Unexpected reply (result %d)\n",
-				lo->disk->disk_name, result);
+		printk(KERN_ERR "%s: Unexpected reply (%p)\n",
+				lo->disk->disk_name, reply.handle);
 		lo->harderror = result;
 		return NULL;
 	}
 
-	DEBUG("ok, ");
-	if (ntohl(reply.magic) != NBD_REPLY_MAGIC) {
-		printk(KERN_ERR "%s: Not enough magic (result %d)\n",
-				lo->disk->disk_name, result);
+	reply.magic = ntohl(reply.magic);
+	if (reply.magic != NBD_REPLY_MAGIC) {
+		printk(KERN_ERR "%s: Wrong magic (0x%lx)\n",
+				lo->disk->disk_name,
+				(unsigned long)reply.magic);
 		lo->harderror = result;
 		return NULL;
 	}
-	if (ntohl(reply.error)) {
-		printk(KERN_ERR "%s: Other side returned error (result %d)\n",
-				lo->disk->disk_name, result);
+	reply.error = ntohl(reply.error);
+	if (reply.error) {
+		printk(KERN_ERR "%s: Other side returned error (%d)\n",
+				lo->disk->disk_name, reply.error);
 		req->errors++;
 		return req;
 	}
 
+	dprintk(DBG_RX, "%s: request %p: got reply\n",
+			lo->disk->disk_name, req);
 	if (nbd_cmd(req) == NBD_CMD_READ) {
 		int i;
 		struct bio *bio;
-		DEBUG("data, ");
 		rq_for_each_bio(bio, req) {
 			struct bio_vec *bvec;
 			bio_for_each_segment(bvec, bio, i) {
 				result = sock_recv_bvec(sock, bvec);
 				if (result <= 0) {
-					printk(KERN_ERR "%s: Recv data failed (result %d)\n",
+					printk(KERN_ERR "%s: Receive data failed (result %d)\n",
 							lo->disk->disk_name,
 							result);
 					lo->harderror = result;
 					return NULL;
 				}
+				dprintk(DBG_RX, "%s: request %p: got %d bytes data\n",
+					lo->disk->disk_name, req, bvec->bv_len);
 			}
 		}
 	}
-	DEBUG("done.\n");
 	return req;
 }
 
@@ -347,7 +402,7 @@
 	BUG_ON(lo->magic != LO_MAGIC);
 	while ((req = nbd_read_stat(lo)) != NULL)
 		nbd_end_request(req);
-	printk(KERN_ALERT "%s: req should never be null\n",
+	printk(KERN_NOTICE "%s: req should never be null\n",
 			lo->disk->disk_name);
 	return;
 }
@@ -388,6 +443,8 @@
 		struct nbd_device *lo;
 
 		blkdev_dequeue_request(req);
+		dprintk(DBG_BLKDEV, "%s: request %p: dequeued (flags=%lx)\n",
+				req->rq_disk->disk_name, req, req->flags);
 
 		if (!(req->flags & REQ_CMD))
 			goto error_out;
@@ -431,7 +488,7 @@
 		nbd_send_req(lo, req);
 
 		if (req->errors) {
-			printk(KERN_ERR "%s: nbd_send_req failed\n",
+			printk(KERN_ERR "%s: Request send failed\n",
 					lo->disk->disk_name);
 			spin_lock(&lo->queue_lock);
 			list_del_init(&req->queuelist);
@@ -456,6 +513,9 @@
 static int nbd_open(struct inode *inode, struct file *file)
 {
 	struct nbd_device *lo = inode->i_bdev->bd_disk->private_data;
+
+	dprintk(DBG_OPEN, "%s: %s refcnt=%d\n", lo->disk->disk_name,
+			__FUNCTION__, lo->refcnt);
 	lo->refcnt++;
 	return 0;
 }
@@ -463,10 +523,13 @@
 static int nbd_release(struct inode *inode, struct file *file)
 {
 	struct nbd_device *lo = inode->i_bdev->bd_disk->private_data;
+
 	if (lo->refcnt <= 0)
 		printk(KERN_ALERT "%s: %s: refcount(%d) <= 0\n",
 				lo->disk->disk_name, __FUNCTION__, lo->refcnt);
 	lo->refcnt--;
+	dprintk(DBG_RELEASE, "%s: %s refcnt=%d\n", lo->disk->disk_name,
+			__FUNCTION__, lo->refcnt);
 	/* N.B. Doesn't lo->file need an fput?? */
 	return 0;
 }
@@ -479,6 +542,8 @@
 	struct request sreq ;
 
 	/* Anyone capable of this syscall can do *real bad* things */
+	dprintk(DBG_IOCTL, "%s: %s cmd=%s(0x%x) arg=%lu\n", lo->disk->disk_name,
+			__FUNCTION__, ioctl_cmd_to_ascii(cmd), cmd, arg);
 
 	if (!capable(CAP_SYS_ADMIN))
 		return -EPERM;
@@ -487,6 +552,8 @@
 	        printk(KERN_INFO "%s: NBD_DISCONNECT\n", lo->disk->disk_name);
 		sreq.flags = REQ_SPECIAL;
 		nbd_cmd(&sreq) = NBD_CMD_DISC;
+		sreq.sector = 0;
+		sreq.nr_sectors = 0;
                 if (!lo->sock)
 			return -EINVAL;
                 nbd_send_req(lo, &sreq);
@@ -607,7 +674,7 @@
 	int i;
 
 	if (sizeof(struct nbd_request) != 28) {
-		printk(KERN_CRIT "Sizeof nbd_request needs to be 28 in order to work!\n" );
+		printk(KERN_CRIT "nbd: Sizeof nbd_request needs to be 28 in order to work!\n" );
 		return -EIO;
 	}
 
@@ -633,9 +700,10 @@
 		err = -EIO;
 		goto out;
 	}
-#ifdef MODULE
-	printk("nbd: registered device at major %d\n", NBD_MAJOR);
-#endif
+
+	printk(KERN_INFO "nbd: registered device at major %d\n", NBD_MAJOR);
+	dprintk(DBG_INIT, "nbd: debugflags=0x%x\n", debugflags);
+
 	devfs_mk_dir("nbd");
 	for (i = 0; i < MAX_NBD; i++) {
 		struct gendisk *disk = nbd_dev[i].disk;
@@ -685,9 +753,7 @@
 	}
 	devfs_remove("nbd");
 	unregister_blkdev(NBD_MAJOR, "nbd");
-#ifdef MODULE
-	printk("nbd: unregistered device at major %d\n", NBD_MAJOR);
-#endif
+	printk(KERN_INFO "nbd: unregistered device at major %d\n", NBD_MAJOR);
 }
 
 module_init(nbd_init);
@@ -696,4 +762,7 @@
 MODULE_DESCRIPTION("Network Block Device");
 MODULE_LICENSE("GPL");
 
-
+#ifndef NDEBUG
+MODULE_PARM(debugflags, "i");
+MODULE_PARM_DESC(debugflags, "flags for controlling debug output");
+#endif
#1 lore raw

drivers/block/nbd.c line 119

Quoted 12 lines · Lou Langholtz

This third patch (for enhancing diagnostics support) applies incrementally after my last LKML'd patch (for cosmetic changes). These changes introduce configurable KERN_DEBUG level printk output for a variety of different things that the driver does and provides the framework for enhanced future debugging support as well.

As always, comments welcome!

drivers/block/nbd.c +4 -0
+	case BLKROSET: return "set-read-only";
+	case BLKROGET: return "get-read-only";
+	case BLKGETSIZE: return "block-get-size";
+	case BLKFLSBUF: return "flush-buffer-cache";

The last 4 never make it to the driver (nor should they, being generic ioctls).

drivers/block/nbd.c

Quoted 10 lines
drivers/block/nbd.c +9 -0
+	reply.magic = ntohl(reply.magic);
+	if (reply.magic != NBD_REPLY_MAGIC) {
+		printk(KERN_ERR "%s: Wrong magic (0x%lx)\n",
+				lo->disk->disk_name,
+				(unsigned long)reply.magic);
 
+	reply.error = ntohl(reply.error);
+	if (reply.error) {
+		printk(KERN_ERR "%s: Other side returned error (%d)\n",
+				lo->disk->disk_name, reply.error);

Generally a bad taste - it's harmless in this case, but such endianness conversions in place are asking for trouble.

drivers/block/nbd.c line 534

Quoted 5 lines
drivers/block/nbd.c +2 -0
 	lo->refcnt--;
+	dprintk(DBG_RELEASE, "%s: %s refcnt=%d\n", lo->disk->disk_name,
+			__FUNCTION__, lo->refcnt);
 	/* N.B. Doesn't lo->file need an fput?? */
 	return 0;

a) please, lose __FUNCTION__ - using it in macros is one thing, but directly in a function that got a name shorter than `__FUNCTION__'?

b) no, it doesn't.

c) ->refcnt is never used. How about losing it completely? Along with ->open() and ->release()...

drivers/block/nbd.c line 554

Quoted 2 lines
drivers/block/nbd.c +0 -0
 		sreq.flags = REQ_SPECIAL;
 		nbd_cmd(&sreq) = NBD_CMD_DISC;

;-/

drivers/block/nbd.c line 556

Quoted 2 lines
drivers/block/nbd.c +2 -0
+		sreq.sector = 0;
+		sreq.nr_sectors = 0;

Umm... What for?

drivers/block/nbd.c line 679

Quoted 5 lines
drivers/block/nbd.c +1 -1
 	if (sizeof(struct nbd_request) != 28) {
-		printk(KERN_CRIT "Sizeof nbd_request needs to be 28 in order to work!\n" );
+		printk(KERN_CRIT "nbd: Sizeof nbd_request needs to be 28 in order to work!\n" );
 		return -EIO;
 	}

FWIW, I'm less than sure that struct nbd_request is worth defining. We use it in two places - the check above and nbd_send_req() where it is filled and then its address is cast to char *. It might be better to use u32[7] directly and forget about all alignment issues. Hell knows... In this situation I would probably just define an enum for offsets and be done with that. Same goes for nbd_reply.

#2 lore raw
Quoted 13 lines · [email protected] wrote:

. . .

Review

Quoted 6 lines
(quoted diff) +4 -0
+	case BLKROSET: return "set-read-only";
+	case BLKROGET: return "get-read-only";
+	case BLKGETSIZE: return "block-get-size";
+	case BLKFLSBUF: return "flush-buffer-cache";

The last 4 never make it to the driver (nor should they, being generic ioctls).

Aarg! A little too fast I was with me cut-and-patse! Actually though, BLKFLSBUF and BLKROSET do make it to the driver (at least according to my reading of linux-2.5.73/drivers/block/ioctl.c). The others are gone in the attached updated patch.

Quoted 10 lines
Quoted 7 lines
(quoted diff) +5 -0
+	reply.magic = ntohl(reply.magic);
+	if (reply.magic != NBD_REPLY_MAGIC) {
+		printk(KERN_ERR "%s: Wrong magic (0x%lx)\n",
+				lo->disk->disk_name,
+				(unsigned long)reply.magic);
Quoted 10 lines

Review

Quoted 6 lines
(quoted diff) +4 -0
+	reply.error = ntohl(reply.error);
+	if (reply.error) {
+		printk(KERN_ERR "%s: Other side returned error (%d)\n",
+				lo->disk->disk_name, reply.error);

Generally a bad taste - it's harmless in this case, but such endianness conversions in place are asking for trouble.

Sure. I could have used local variables instead to hold the endianess results (which seems overkill). Or can just call ntohl again in printk and so it is now.

Quoted 12 lines
Quoted 7 lines
	lo->refcnt--;
(quoted diff) +2 -0
+	dprintk(DBG_RELEASE, "%s: %s refcnt=%d\n", lo->disk->disk_name,
+			__FUNCTION__, lo->refcnt);
	/* N.B. Doesn't lo->file need an fput?? */
	return 0;

a) please, lose __FUNCTION__ - using it in macros is one thing, but directly in a function that got a name shorter than `__FUNCTION__'?

Done.

Quoted 3 lines

b) no, it doesn't.

The N.B. is a left over from the original which agreeably can be cleaned up too. So it's gone now too.

Quoted 4 lines

c) ->refcnt is never used. How about losing it completely? Along with ->open() and ->release()...

There's a few other things that could be "lost" too. Like lo->file and lo->blksize_bits. I'm trying to go one step at a time though with these patches. And actually ->open() and ->release() will be needed later when I get that far. ;-)

Quoted 8 lines
Quoted 4 lines
		sreq.flags = REQ_SPECIAL;
		nbd_cmd(&sreq) = NBD_CMD_DISC;

;-/

That's how it was already. Maybe it's wrong too or just not so good. But changing this should wait till a patch that's not dealing with enhanced diags no??

Quoted 7 lines

Review

Quoted 4 lines
(quoted diff) +2 -0
+		sreq.sector = 0;
+		sreq.nr_sectors = 0;

Umm... What for?

I added some comments now to explain why.

Quoted 6 lines
Quoted 6 lines
	if (sizeof(struct nbd_request) != 28) {
(quoted diff) +1 -1
-		printk(KERN_CRIT "Sizeof nbd_request needs to be 28 in order to work!\n" );
+		printk(KERN_CRIT "nbd: Sizeof nbd_request needs to be 28 in order to work!\n" );
		return -EIO;
	}
Quoted 10 lines
Quoted 1 line

FWIW, I'm less than sure that struct nbd_request is worth defining. We use it in two places - the check above and nbd_send_req() where it is filled and then its address is cast to char *. It might be better to use u32[7] directly and forget about all alignment issues. Hell knows... In this situation I would probably just define an enum for offsets and be done with that. Same goes for nbd_reply.

I've thought about this too. I have to say so far that I don't like the idea though of getting rid of these structs. They're shared with the remote end also.

Here's the revised patch then for enhanced diagnostics...

drivers/block/nbd.c +106 -35
diff -urN linux-2.5.72-p2.5/drivers/block/nbd.c linux-2.5.73-p3.1/drivers/block/nbd.c
@@ -32,6 +32,7 @@
  *   memory corruption from module removal and possible memory corruption
  *   from sending/receiving disk data. <[email protected]>
  * 03-06-23 Cosmetic changes. <[email protected]>
+ * 03-06-23 Enhance diagnostics support. <[email protected]>
  *
  * possible FIXME: make set_sock / set_blksize / set_size / do_it one syscall
  * why not: would need verify_area and friends, would share yet another 
@@ -65,6 +66,23 @@
 
 #define LO_MAGIC 0x68797548
 
+#ifdef NDEBUG
+#define dprintk(flags, fmt...)
+#else /* NDEBUG */
+#define dprintk(flags, fmt...) do { \
+	if (debugflags & (flags)) printk(KERN_DEBUG fmt); \
+} while (0)
+#define DBG_OPEN        0x0001
+#define DBG_RELEASE     0x0002
+#define DBG_IOCTL       0x0004
+#define DBG_INIT        0x0010
+#define DBG_EXIT        0x0020
+#define DBG_BLKDEV      0x0100
+#define DBG_RX          0x0200
+#define DBG_TX          0x0400
+static unsigned int debugflags;
+#endif /* NDEBUG */
+
 static struct nbd_device nbd_dev[MAX_NBD];
 
 /*
@@ -79,19 +97,47 @@
  */
 static spinlock_t nbd_lock = SPIN_LOCK_UNLOCKED;
 
-#define DEBUG( s )
-/* #define DEBUG( s ) printk( s ) 
- */
-
 static int requests_in;
 static int requests_out;
 
+#ifndef NDEBUG
+static const char *ioctl_cmd_to_ascii(int cmd)
+{
+	switch (cmd) {
+	case NBD_SET_SOCK: return "set-sock";
+	case NBD_SET_BLKSIZE: return "set-blksize";
+	case NBD_SET_SIZE: return "set-size";
+	case NBD_DO_IT: return "do-it";
+	case NBD_CLEAR_SOCK: return "clear-sock";
+	case NBD_CLEAR_QUE: return "clear-que";
+	case NBD_PRINT_DEBUG: return "print-debug";
+	case NBD_SET_SIZE_BLOCKS: return "set-size-blocks";
+	case NBD_DISCONNECT: return "disconnect";
+	case BLKROSET: return "set-read-only";
+	case BLKFLSBUF: return "flush-buffer-cache";
+	}
+	return "unknown";
+}
+
+static const char *nbdcmd_to_ascii(int cmd)
+{
+	switch (cmd) {
+	case  NBD_CMD_READ: return "read";
+	case NBD_CMD_WRITE: return "write";
+	case  NBD_CMD_DISC: return "disconnect";
+	}
+	return "invalid";
+}
+#endif /* NDEBUG */
+
 static void nbd_end_request(struct request *req)
 {
 	int uptodate = (req->errors == 0) ? 1 : 0;
 	request_queue_t *q = req->q;
 	unsigned long flags;
 
+	dprintk(DBG_BLKDEV, "%s: request %p: %s\n", req->rq_disk->disk_name,
+			req, uptodate? "done": "failed");
 #ifdef PARANOIA
 	requests_out++;
 #endif
@@ -193,8 +239,6 @@
 	unsigned long size = req->nr_sectors << 9;
 	struct socket *sock = lo->sock;
 
-	DEBUG("nbd: sending control, ");
-	
 	request.magic = htonl(NBD_REQUEST_MAGIC);
 	request.type = htonl(nbd_cmd(req));
 	request.from = cpu_to_be64((u64) req->sector << 9);
@@ -204,15 +248,19 @@
 	down(&lo->tx_lock);
 
 	if (!sock || !lo->sock) {
-		printk(KERN_ERR "%s: Attempted sendmsg to closed socket\n",
+		printk(KERN_ERR "%s: Attempted send on closed socket\n",
 				lo->disk->disk_name);
 		goto error_out;
 	}
 
+	dprintk(DBG_TX, "%s: request %p: sending control (%s@%llu,%luB)\n",
+			lo->disk->disk_name, req,
+			nbdcmd_to_ascii(nbd_cmd(req)),
+			req->sector << 9, req->nr_sectors << 9);
 	result = sock_xmit(sock, 1, &request, sizeof(request),
 			(nbd_cmd(req) == NBD_CMD_WRITE)? MSG_MORE: 0);
 	if (result <= 0) {
-		printk(KERN_ERR "%s: Sendmsg failed for control (result %d)\n",
+		printk(KERN_ERR "%s: Send control failed (result %d)\n",
 				lo->disk->disk_name, result);
 		goto error_out;
 	}
@@ -229,7 +277,9 @@
 				flags = 0;
 				if ((i < (bio->bi_vcnt - 1)) || bio->bi_next)
 					flags = MSG_MORE;
-				DEBUG("data, ");
+				dprintk(DBG_TX, "%s: request %p: sending %d bytes data\n",
+						lo->disk->disk_name, req,
+						bvec->bv_len);
 				result = sock_send_bvec(sock, bvec, flags);
 				if (result <= 0) {
 					printk(KERN_ERR "%s: Send data failed (result %d)\n",
@@ -287,56 +337,57 @@
 	struct request *req;
 	struct socket *sock = lo->sock;
 
-	DEBUG("reading control, ");
 	reply.magic = 0;
 	result = sock_xmit(sock, 0, &reply, sizeof(reply), MSG_WAITALL);
 	if (result <= 0) {
-		printk(KERN_ERR "%s: Recv control failed (result %d)\n",
+		printk(KERN_ERR "%s: Receive control failed (result %d)\n",
 				lo->disk->disk_name, result);
 		lo->harderror = result;
 		return NULL;
 	}
 	req = nbd_find_request(lo, reply.handle);
 	if (req == NULL) {
-		printk(KERN_ERR "%s: Unexpected reply (result %d)\n",
-				lo->disk->disk_name, result);
+		printk(KERN_ERR "%s: Unexpected reply (%p)\n",
+				lo->disk->disk_name, reply.handle);
 		lo->harderror = result;
 		return NULL;
 	}
 
-	DEBUG("ok, ");
 	if (ntohl(reply.magic) != NBD_REPLY_MAGIC) {
-		printk(KERN_ERR "%s: Not enough magic (result %d)\n",
-				lo->disk->disk_name, result);
+		printk(KERN_ERR "%s: Wrong magic (0x%lx)\n",
+				lo->disk->disk_name,
+				(unsigned long)ntohl(reply.magic));
 		lo->harderror = result;
 		return NULL;
 	}
 	if (ntohl(reply.error)) {
-		printk(KERN_ERR "%s: Other side returned error (result %d)\n",
-				lo->disk->disk_name, result);
+		printk(KERN_ERR "%s: Other side returned error (%d)\n",
+				lo->disk->disk_name, ntohl(reply.error));
 		req->errors++;
 		return req;
 	}
 
+	dprintk(DBG_RX, "%s: request %p: got reply\n",
+			lo->disk->disk_name, req);
 	if (nbd_cmd(req) == NBD_CMD_READ) {
 		int i;
 		struct bio *bio;
-		DEBUG("data, ");
 		rq_for_each_bio(bio, req) {
 			struct bio_vec *bvec;
 			bio_for_each_segment(bvec, bio, i) {
 				result = sock_recv_bvec(sock, bvec);
 				if (result <= 0) {
-					printk(KERN_ERR "%s: Recv data failed (result %d)\n",
+					printk(KERN_ERR "%s: Receive data failed (result %d)\n",
 							lo->disk->disk_name,
 							result);
 					lo->harderror = result;
 					return NULL;
 				}
+				dprintk(DBG_RX, "%s: request %p: got %d bytes data\n",
+					lo->disk->disk_name, req, bvec->bv_len);
 			}
 		}
 	}
-	DEBUG("done.\n");
 	return req;
 }
 
@@ -347,7 +398,7 @@
 	BUG_ON(lo->magic != LO_MAGIC);
 	while ((req = nbd_read_stat(lo)) != NULL)
 		nbd_end_request(req);
-	printk(KERN_ALERT "%s: req should never be null\n",
+	printk(KERN_NOTICE "%s: req should never be null\n",
 			lo->disk->disk_name);
 	return;
 }
@@ -388,6 +439,8 @@
 		struct nbd_device *lo;
 
 		blkdev_dequeue_request(req);
+		dprintk(DBG_BLKDEV, "%s: request %p: dequeued (flags=%lx)\n",
+				req->rq_disk->disk_name, req, req->flags);
 
 		if (!(req->flags & REQ_CMD))
 			goto error_out;
@@ -431,7 +484,7 @@
 		nbd_send_req(lo, req);
 
 		if (req->errors) {
-			printk(KERN_ERR "%s: nbd_send_req failed\n",
+			printk(KERN_ERR "%s: Request send failed\n",
 					lo->disk->disk_name);
 			spin_lock(&lo->queue_lock);
 			list_del_init(&req->queuelist);
@@ -456,6 +509,9 @@
 static int nbd_open(struct inode *inode, struct file *file)
 {
 	struct nbd_device *lo = inode->i_bdev->bd_disk->private_data;
+
+	dprintk(DBG_OPEN, "%s: nbd_open refcnt=%d\n", lo->disk->disk_name,
+			lo->refcnt);
 	lo->refcnt++;
 	return 0;
 }
@@ -463,11 +519,15 @@
 static int nbd_release(struct inode *inode, struct file *file)
 {
 	struct nbd_device *lo = inode->i_bdev->bd_disk->private_data;
-	if (lo->refcnt <= 0)
-		printk(KERN_ALERT "%s: %s: refcount(%d) <= 0\n",
-				lo->disk->disk_name, __FUNCTION__, lo->refcnt);
+
+	if (lo->refcnt <= 0) {
+		printk(KERN_ALERT "%s: nbd_release: refcount(%d) <= 0\n",
+				lo->disk->disk_name, lo->refcnt);
+		BUG();
+	}
 	lo->refcnt--;
-	/* N.B. Doesn't lo->file need an fput?? */
+	dprintk(DBG_RELEASE, "%s: nbd_release: refcnt=%d\n",
+			lo->disk->disk_name, lo->refcnt);
 	return 0;
 }
 
@@ -479,6 +539,8 @@
 	struct request sreq ;
 
 	/* Anyone capable of this syscall can do *real bad* things */
+	dprintk(DBG_IOCTL, "%s: nbd_ioctl cmd=%s(0x%x) arg=%lu\n",
+			lo->disk->disk_name, ioctl_cmd_to_ascii(cmd), cmd, arg);
 
 	if (!capable(CAP_SYS_ADMIN))
 		return -EPERM;
@@ -487,6 +549,13 @@
 	        printk(KERN_INFO "%s: NBD_DISCONNECT\n", lo->disk->disk_name);
 		sreq.flags = REQ_SPECIAL;
 		nbd_cmd(&sreq) = NBD_CMD_DISC;
+		/*
+		 * Set these to sane values in case server implementation
+		 * fails to check the request type first and also to keep
+		 * debugging output cleaner.
+		 */
+		sreq.sector = 0;
+		sreq.nr_sectors = 0;
                 if (!lo->sock)
 			return -EINVAL;
                 nbd_send_req(lo, &sreq);
@@ -607,7 +676,7 @@
 	int i;
 
 	if (sizeof(struct nbd_request) != 28) {
-		printk(KERN_CRIT "Sizeof nbd_request needs to be 28 in order to work!\n" );
+		printk(KERN_CRIT "nbd: Sizeof nbd_request needs to be 28 in order to work!\n" );
 		return -EIO;
 	}
 
@@ -633,9 +702,10 @@
 		err = -EIO;
 		goto out;
 	}
-#ifdef MODULE
-	printk("nbd: registered device at major %d\n", NBD_MAJOR);
-#endif
+
+	printk(KERN_INFO "nbd: registered device at major %d\n", NBD_MAJOR);
+	dprintk(DBG_INIT, "nbd: debugflags=0x%x\n", debugflags);
+
 	devfs_mk_dir("nbd");
 	for (i = 0; i < MAX_NBD; i++) {
 		struct gendisk *disk = nbd_dev[i].disk;
@@ -685,9 +755,7 @@
 	}
 	devfs_remove("nbd");
 	unregister_blkdev(NBD_MAJOR, "nbd");
-#ifdef MODULE
-	printk("nbd: unregistered device at major %d\n", NBD_MAJOR);
-#endif
+	printk(KERN_INFO "nbd: unregistered device at major %d\n", NBD_MAJOR);
 }
 
 module_init(nbd_init);
@@ -696,4 +764,7 @@
 MODULE_DESCRIPTION("Network Block Device");
 MODULE_LICENSE("GPL");
 
-
+#ifndef NDEBUG
+MODULE_PARM(debugflags, "i");
+MODULE_PARM_DESC(debugflags, "flags for controlling debug output");
+#endif