Skip to content

Commit

Permalink
Update Logging throughout the driver for #61
Browse files Browse the repository at this point in the history
  • Loading branch information
@Joacchim
Joacchim committed Nov 21, 2014
1 parent 2d58b3c commit 456aaff
Show file tree
Hide file tree
Showing 3 changed files with 78 additions and 74 deletions.
101 changes: 54 additions & 47 deletions srb_driver.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -259,8 +259,8 @@ static int srb_xfer_scl(struct srb_device_s *dev,
struct timeval tv_start;
struct timeval tv_end;

SRB_LOG_DEBUG(dev->debug.level, "srb_xfer_scl: CDMI request %p (%s) for device %p with cdmi %p",
req, req_code_to_str(rq_data_dir(req)), dev, desc);
SRBDEV_LOG_DEBUG(dev, "CDMI request %p (%s) with cdmi_desc %p",
req, req_code_to_str(rq_data_dir(req)), desc);

if (SRB_DEBUG <= dev->debug.level)
do_gettimeofday(&tv_start);
Expand All @@ -280,12 +280,14 @@ static int srb_xfer_scl(struct srb_device_s *dev,

if (SRB_DEBUG <= dev->debug.level) {
do_gettimeofday(&tv_end);
SRB_LOG_DEBUG(dev->debug.level, "cdmi request time: %ldms",
(tv_end.tv_sec - tv_start.tv_sec)*1000 + (tv_end.tv_usec - tv_start.tv_usec)/1000);
SRBDEV_LOG_DEBUG(dev, "Request took %ldms",
(tv_end.tv_sec - tv_start.tv_sec)*1000 +
(tv_end.tv_usec - tv_start.tv_usec)/1000);
}

if (ret) {
SRB_LOG_ERR(dev->debug.level, "CDMI Request using scatterlist failed with IO error: %d", ret);
SRBDEV_LOG_ERR(dev, "CDMI Request using scatterlist failed"
" with IO error: %d", ret);
return -EIO;
}

Expand All @@ -301,7 +303,7 @@ static int srb_free_disk(struct srb_device_s *dev)

disk = dev->disk;
if (!disk) {
SRB_LOG_ERR(dev->debug.level, "%s: Disk is no more available", dev->name);
SRBDEV_LOG_ERR(dev, "Disk is not available anymore (%s)", dev->name);
return -EINVAL;
}
dev->disk = NULL;
Expand Down Expand Up @@ -333,7 +335,7 @@ static int srb_thread(void *data)
struct bio_vec *bvec;
struct srb_cdmi_desc_s *cdmi_desc;

SRB_LOG_DEBUG(((struct srb_device_s *)data)->debug.level, "srb_thread: thread function with data %p", data);
SRBDEV_LOG_DEBUG(((struct srb_device_s *)data), "Thread started with device %p", data);

dev = data;

Expand Down Expand Up @@ -374,17 +376,17 @@ static int srb_thread(void *data)
}

req_flags_to_str(req->cmd_flags, buff);
SRB_LOG_DEBUG(dev->debug.level, "srb_thread: thread %d: New REQ of type %s (%d) flags: %s (%llu)",
th_id, req_code_to_str(rq_data_dir(req)), rq_data_dir(req), buff, req->cmd_flags);
SRBDEV_LOG_DEBUG(dev, "thread %d: New REQ of type %s (%d) flags: %s (%llu)",
th_id, req_code_to_str(rq_data_dir(req)), rq_data_dir(req), buff, req->cmd_flags);
if (req->cmd_flags & REQ_FLUSH) {
SRB_LOG_DEBUG(dev->debug.level, "DEBUG CMD REQ_FLUSH\n");
SRBDEV_LOG_DEBUG(dev, "DEBUG CMD REQ_FLUSH\n");
}
/* XXX: Use iterator instead of internal function (cf linux/blkdev.h)
* __rq_for_each_bio(bio, req) {
*/
rq_for_each_segment(bvec, req, iter) {
if (iter.bio->bi_rw & REQ_FLUSH) {
SRB_LOG_DEBUG(dev->debug.level, "DEBUG VR BIO REQ_FLUSH\n");
SRBDEV_LOG_DEBUG(dev, "DEBUG VR BIO REQ_FLUSH\n");
}
}

Expand All @@ -393,15 +395,18 @@ static int srb_thread(void *data)
sg_init_table(dev->thread_cdmi_desc[th_id]->sgl, DEV_NB_PHYS_SEGS);
dev->thread_cdmi_desc[th_id]->sgl_size = blk_rq_map_sg(dev->q, req, dev->thread_cdmi_desc[th_id]->sgl);

SRB_LOG_DEBUG(dev->debug.level, "srb_thread: scatter_list size %d [nb_seg = %d, sector = %lu, nr_sectors=%u w=%d]",
DEV_NB_PHYS_SEGS, dev->thread_cdmi_desc[th_id]->sgl_size, blk_rq_pos(req), blk_rq_sectors(req), rq_data_dir(req) == WRITE);
SRBDEV_LOG_DEBUG(dev, "scatter_list size %d [nb_seg = %d,"
" sector = %lu, nr_sectors=%u w=%d]",
DEV_NB_PHYS_SEGS,
dev->thread_cdmi_desc[th_id]->sgl_size,
blk_rq_pos(req), blk_rq_sectors(req),
rq_data_dir(req) == WRITE);

/* Call scatter function */
th_ret = srb_xfer_scl(dev, dev->thread_cdmi_desc[th_id], req);

//SRB_DEV_DEBUG("END REQUEST [tid:%d]", th_id);
SRB_LOG_DEBUG(dev->debug.level, "srb_thread: thread %d: REQ done with returned code %d",
th_id, th_ret);;
SRBDEV_LOG_DEBUG(dev, "thread %d: REQ done with returned code %d",
th_id, th_ret);;

/* No IO error testing for the moment */
blk_end_request_all(req, 0);
Expand All @@ -419,7 +424,7 @@ static void srb_rq_fn(struct request_queue *q)

while ((req = blk_fetch_request(q)) != NULL) {
if (req->cmd_type != REQ_TYPE_FS) {
SRB_LOG_DEBUG(dev->debug.level, "srb_rq_fn: Skip non-CMD request");
SRBDEV_LOG_DEBUG(dev, "Skip non-CMD request");

__blk_end_request_all(req, -EIO);
continue;
Expand All @@ -434,12 +439,9 @@ static void srb_rq_fn(struct request_queue *q)

static int srb_open(struct block_device *bdev, fmode_t mode)
{
//srb_device_t *dev = bdev->bd_disk->private_data;
srb_device_t *dev;

SRB_LOG_INFO(srb_log, "srb_open: opening block device %s", bdev->bd_disk->disk_name);
srb_device_t *dev = (srb_device_t*)bdev->bd_disk->private_data;

dev = bdev->bd_disk->private_data;
SRBDEV_LOG_INFO(dev, "Opening device (%s)", bdev->bd_disk->disk_name);

spin_lock(&devtab_lock);
dev->users++;
Expand All @@ -456,10 +458,8 @@ static void srb_release(struct gendisk *disk, fmode_t mode)
{
srb_device_t *dev;

SRB_LOG_INFO(srb_log, "srb_release: releasing disk %s", disk->disk_name);

dev = disk->private_data;

SRBDEV_LOG_INFO(dev, "Releasing device (%s)", disk->disk_name);
spin_lock(&devtab_lock);
dev->users--;
spin_unlock(&devtab_lock);
Expand Down Expand Up @@ -558,8 +558,8 @@ static int srb_init_disk(struct srb_device_s *dev)
}
add_disk(disk);

SRB_LOG_INFO(srb_log, "%s: Added of size 0x%llx",
disk->disk_name, (unsigned long long)dev->disk_size);
SRBDEV_LOG_INFO(dev, "Attached volume %s of size 0x%llx",
disk->disk_name, (unsigned long long)dev->disk_size);

return 0;

Expand Down Expand Up @@ -718,27 +718,28 @@ static int __srb_device_detach(srb_device_t *dev)
int i;
int ret = 0;

SRB_LOG_DEBUG(srb_log, "__srb_device_detach: detaching device %s (%p)", dev->name, dev);
SRB_LOG_DEBUG(srb_log, "detaching device (%p)", dev);

if (!dev) {
SRB_LOG_WARN(srb_log, "__srb_device_detach: empty device");
return -EINVAL;
}

SRBDEV_LOG_DEBUG(dev, "Detaching device (%s)", dev->name);

if (dev->users > 0) {
SRB_LOG_ERR(srb_log, "%s: Unable to remove, device still opened (#users: %d)", dev->name, dev->users);
SRBDEV_LOG_ERR(dev, "Unable to remove, device still opened (#users: %d)", dev->users);
return -EBUSY;
}

if (!dev->disk) {
SRB_LOG_ERR(srb_log, "%s: Disk is no more available", dev->name);
SRBDEV_LOG_ERR(dev, "Device %s is not available anymore", dev->name);
return -EINVAL;
}

SRB_LOG_INFO(srb_log, "%s: Removing disk", dev->disk->disk_name);

/* TODO: Make thread pool variable (Issue #33)
*/
SRBDEV_LOG_INFO(dev, "Stopping device's background processes");
for (i = 0; i < thread_pool_size; i++) {
if (dev->thread[i])
kthread_stop(dev->thread[i]);
Expand All @@ -747,10 +748,10 @@ static int __srb_device_detach(srb_device_t *dev)
/* free disk */
ret = srb_free_disk(dev);
if (0 != ret) {
SRB_LOG_WARN(srb_log, "%s: Failed to remove disk: %d", dev->name, ret);
SRBDEV_LOG_WARN(dev, "Failed to remove device: %d", ret);
}

SRB_LOG_INFO(srb_log, "%s: Removing disk for major %d", dev->name, dev->major);
SRB_LOG_INFO(srb_log, "Unregistering device from BLOCK Subsystem");
/* Remove device */
unregister_blkdev(dev->major, DEV_NAME);

Expand Down Expand Up @@ -790,8 +791,14 @@ static int _srb_detach_devices(void)
if (2 == dev_in_use[i]) {
ret = __srb_device_detach(&devtab[i]);
if (ret != 0) {
SRB_LOG_ERR(srb_log, "Could not remove device %s for volume at unload %s",
devtab[i].name, devtab[i].thread_cdmi_desc ? devtab[i].thread_cdmi_desc[0]->filename : "NULL");
SRBDEV_LOG_ERR(&devtab[i],
"Cannot remove device %s for volume %s"
" on module unload: %i",
devtab[i].name,
devtab[i].thread_cdmi_desc ?
devtab[i].thread_cdmi_desc[0]->filename
: "NULL",
ret);
errcount++;
}
}
Expand Down Expand Up @@ -1178,10 +1185,10 @@ int srb_device_detach(const char *devname)
if (!device_free_slot(&devtab[i])) {
if (strcmp(devname, devtab[i].name) == 0) {
found = 1;
dev = &devtab[i];
if (devtab[i].state == DEV_IN_USE) {
ret = -EBUSY;
} else {
dev = &devtab[i];
/* mark it as ongoing operation */
dev->state = DEV_IN_USE;
ret = 0;
Expand All @@ -1194,18 +1201,18 @@ int srb_device_detach(const char *devname)

/* check status */
if (1 == found && 0 != ret) {
SRB_LOG_ERR(srb_log, "Device %s in use", devname);
SRBDEV_LOG_ERR(dev, "Device %s is in use", devname);
return ret;
}

/* real stuff */
if (1 == found) {
ret = __srb_device_detach(&devtab[i]);
ret = __srb_device_detach(dev);
if (ret != 0) {
SRB_LOG_ERR(srb_log, "Cannot detach device %s", devname);
SRBDEV_LOG_ERR(dev, "Cannot detach device %s", devname);
}
} else {
SRB_LOG_ERR(srb_log, "Device %s not found as attached", devname);
SRBDEV_LOG_ERR(dev, "Device %s was not found as attached", devname);
return -EINVAL;
}

Expand Down Expand Up @@ -1257,11 +1264,11 @@ int srb_device_attach(const char *filename, const char *devname)
spin_unlock(&devtab_lock);

if (1 == found) {
SRB_LOG_ERR(srb_log, "Volume %s already attached as device %s", filename, dev->name);
SRBDEV_LOG_ERR(dev, "Volume %s already attached as device %s", filename, dev->name);
dev = NULL;
return -EEXIST;
} else {
SRB_LOG_INFO(srb_log, "Volume %s not attached as device, using device slot %d", filename, dev->id);
SRB_LOG_INFO(srb_log, "Volume %s not attached yet, using device slot %d", filename, dev->id);
}

cdmi_desc = kmalloc(sizeof(struct srb_cdmi_desc_s), GFP_KERNEL);
Expand Down Expand Up @@ -1293,7 +1300,7 @@ int srb_device_attach(const char *filename, const char *devname)
SRB_LOG_ERR(srb_log, "Unable to get server: %i", rc);
goto cleanup;
}
SRB_LOG_INFO(srb_log, "Adding Device: Picked server "
SRB_LOG_INFO(srb_log, "Attaching Device: Picked server "
"[ip=%s port=%d fullpath=%s]",
cdmi_desc->ip_addr, cdmi_desc->port,
cdmi_desc->filename);
Expand Down Expand Up @@ -1322,9 +1329,9 @@ int srb_device_attach(const char *filename, const char *devname)

srb_sysfs_device_init(dev);

SRB_LOG_INFO(srb_log, "Added device %s (id: %d, major:%d) for server "
SRBDEV_LOG_INFO(dev, "Attached device %s (id: %d) for server "
"[ip=%s port=%d fullpath=%s]",
dev->name, dev->id, dev->major, cdmi_desc->ip_addr,
dev->name, dev->id, cdmi_desc->ip_addr,
cdmi_desc->port, cdmi_desc->filename);

/* mark device as unsued == available */
Expand Down Expand Up @@ -1437,7 +1444,7 @@ int srb_device_extend(const char *filename, unsigned long long size)
}
spin_unlock(&devtab_lock);
if (0 != rc) {
SRB_LOG_ERR(srb_log, "Volume %s attached on device %s and in use", filename, dev->name);
SRBDEV_LOG_ERR(dev, "Cannot extend volume %s: attached on device in use (%s)", filename, dev->name);
dev = NULL;
return rc;
}
Expand Down
42 changes: 20 additions & 22 deletions srb_log.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -85,17 +85,17 @@
*/
#define SRBDEV_INTERNAL_DBG(lvl, dev, dbg, fmt, args...)\
do {\
if (dev == NULL && dbg == NULL && SRB_##lvl != SRB_DEBUG)\
if (dev == NULL && ((dbg) == NULL || (dbg)->name == NULL) && SRB_##lvl != SRB_DEBUG)\
printk(KERN_##lvl SRB_FMT_MINIMAL(lvl, fmt), ##args);\
else if (dev == NULL && dbg == NULL)\
else if (dev == NULL && ((dbg) == NULL || (dbg)->name == NULL))\
printk(KERN_##lvl SRB_FMT_DBG(lvl, fmt), SRB_ARGS_DBG, ##args);\
else if (dev == NULL && SRB_##lvl != SRB_DEBUG)\
printk(KERN_##lvl SRB_FMT_MOD(lvl, fmt), SRB_ARGS_MOD(dbg), ##args);\
else if (dbg == NULL && SRB_##lvl != SRB_DEBUG)\
else if (((dbg) == NULL || (dbg)->name == NULL) && SRB_##lvl != SRB_DEBUG)\
printk(KERN_##lvl SRB_FMT_DEV(lvl, fmt), SRB_ARGS_DEV(dev), ##args);\
else if (dev == NULL)\
printk(KERN_##lvl SRB_FMT_NODEV(lvl, fmt), SRB_ARGS_NODEV(dbg), ##args);\
else if (dbg == NULL)\
else if ((dbg) == NULL || (dbg)->name == NULL)\
printk(KERN_##lvl SRB_FMT_NOMOD(lvl, fmt), SRB_ARGS_NOMOD(dev), ##args);\
else if (SRB_##lvl != SRB_DEBUG)\
printk(KERN_##lvl SRB_FMT_NODBG(lvl, fmt), SRB_ARGS_NODBG(dev, dbg), ##args);\
Expand All @@ -107,8 +107,6 @@
do {\
srb_device_t *dev = NULL;\
srb_debug_t *dbg = NULL;\
(void)dbg;\
(void)dev;\
SRBDEV_INTERNAL_DBG(lvl, dev, dbg, fmt, ##args);\
} while (0)

Expand All @@ -129,22 +127,22 @@
#define SRB_LOG_EMERG(level, fmt, args...) \
if (level >= SRB_EMERG) SRB_INTERNAL_DBG(EMERG, fmt, ##args)

#define SRBDEV_LOG_DEBUG(level, fmt, a...) \
if (level >= SRB_DEBUG) SRBDEV_INTERNAL_DBG(DEBUG, dbg, fmt, ##a)
#define SRBDEV_LOG_INFO(level, fmt, a...) \
if (level >= SRB_INFO) SRBDEV_INTERNAL_DBG(INFO, dbg, fmt, ##a)
#define SRBDEV_LOG_NOTICE(level, fmt, a...) \
if (level >= SRB_NOTICE) SRBDEV_INTERNAL_DBG(NOTICE, dbg, fmt, ##a)
#define SRBDEV_LOG_WARN(level, fmt, a...) \
if (level >= SRB_WARNING) SRBDEV_INTERNAL_DBG(WARNING, dbg, fmt, ##a)
#define SRBDEV_LOG_ERR(level, fmt, a...) \
if (level >= SRB_ERR) SRBDEV_INTERNAL_DBG(ERR, dbg, fmt, ##a)
#define SRBDEV_LOG_CRIT(level, fmt, a...) \
if (level >= SRB_CRIT) SRBDEV_INTERNAL_DBG(CRIT, dbg, fmt, ##a)
#define SRBDEV_LOG_ALERT(level, fmt, a...) \
if (level >= SRB_ALERT) SRBDEV_INTERNAL_DBG(ALERT, dbg, fmt, ##a)
#define SRBDEV_LOG_EMERG(level, fmt, a...) \
if (level >= SRB_EMERG) SRBDEV_INTERNAL_DBG(EMERG, dbg, fmt, ##a)
#define SRBDEV_LOG_DEBUG(dev, fmt, a...) \
if ((dev)->debug.level >= SRB_DEBUG) SRBDEV_INTERNAL_DBG(DEBUG, dev, &((dev)->debug), fmt, ##a)
#define SRBDEV_LOG_INFO(dev, fmt, a...) \
if ((dev)->debug.level >= SRB_INFO) SRBDEV_INTERNAL_DBG(INFO, dev, &((dev)->debug), fmt, ##a)
#define SRBDEV_LOG_NOTICE(dev, fmt, a...) \
if ((dev)->debug.level >= SRB_NOTICE) SRBDEV_INTERNAL_DBG(NOTICE, dev, &((dev)->debug), fmt, ##a)
#define SRBDEV_LOG_WARN(dev, fmt, a...) \
if ((dev)->debug.level >= SRB_WARNING) SRBDEV_INTERNAL_DBG(WARNING, dev, &((dev)->debug), fmt, ##a)
#define SRBDEV_LOG_ERR(dev, fmt, a...) \
if ((dev)->debug.level >= SRB_ERR) SRBDEV_INTERNAL_DBG(ERR, dev, &((dev)->debug), fmt, ##a)
#define SRBDEV_LOG_CRIT(dev, fmt, a...) \
if ((dev)->debug.level >= SRB_CRIT) SRBDEV_INTERNAL_DBG(CRIT, dev, &((dev)->debug), fmt, ##a)
#define SRBDEV_LOG_ALERT(dev, fmt, a...) \
if ((dev)->debug.level >= SRB_ALERT) SRBDEV_INTERNAL_DBG(ALERT, dev, &((dev)->debug), fmt, ##a)
#define SRBDEV_LOG_EMERG(dev, fmt, a...) \
if ((dev)->debug.level >= SRB_EMERG) SRBDEV_INTERNAL_DBG(EMERG, dev, &((dev)->debug), fmt, ##a)


/*
Expand Down
9 changes: 4 additions & 5 deletions srb_sysfs.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -121,12 +121,11 @@ static ssize_t attr_debug_store(struct device *dv,
val = (int) new;
if (val >= 0 && val <= 7) {
dev->debug.level = val;
SRB_LOG_DEBUG(dev->debug.level, "attr_debug_store: Setting Log level to %d for device %s",
val, dev->name);
SRBDEV_LOG_WARN(dev, "Invalid debug value (%d) for device %s in sysfs",
(int)val, dev->name);
}
else
SRB_LOG_WARN(dev->debug.level, "attr_debug_store: Invalid debug value (%d) for device %s in sysfs",
val, dev->name);

SRBDEV_LOG_DEBUG(dev, "Setting Log level to %d for device %s", (int)val, dev->name);

return count;
}
Expand Down

0 comments on commit 456aaff

Please sign in to comment.