usb: gadget: f_fs: Add support for ipc logging

Log function entry and exit and dump relevant values
into ipc log buffer. This allows to debug various
race conditions and stability issues.

Change-Id: I15011d79fc2f054e64f8bbd1f8f5db8944b46ada
Signed-off-by: Hemant Kumar <hemantk@codeaurora.org>

1 files changed, 365 insertions, 1 deletions

diff --git a/drivers/usb/gadget/function/f_fs.c b/drivers/usb/gadget/function/f_fs.c
index 48f987d77e91..722d9c39290f 100644
--- a/drivers/usb/gadget/function/f_fs.c
+++ b/drivers/usb/gadget/function/f_fs.c
@@ -24,6 +24,7 @@
 #include <linux/hid.h>
 #include <linux/module.h>
 #include <linux/uio.h>
+#include <linux/ipc_logging.h>
 #include <asm/unaligned.h>
 
 #include <linux/usb/composite.h>
@@ -41,6 +42,15 @@
 
 #define FUNCTIONFS_MAGIC	0xa647361 /* Chosen by a honest dice roll ;) */
 
+#define NUM_PAGES	10 /* # of pages for ipc logging */
+
+static void *ffs_ipc_log;
+#define ffs_log(fmt, ...) do { \
+	ipc_log_string(ffs_ipc_log, "%s: " fmt,  __func__, \
+			##__VA_ARGS__); \
+	pr_debug(fmt, ##__VA_ARGS__); \
+} while (0)
+
 /* Reference counter handling */
 static void ffs_data_get(struct ffs_data *ffs);
 static void ffs_data_put(struct ffs_data *ffs);
@@ -214,6 +224,9 @@ static int __ffs_ep0_queue_wait(struct ffs_data *ffs, char *data, size_t len)
 
 	spin_unlock_irq(&ffs->ev.waitq.lock);
 
+	ffs_log("enter: state %d setup_state %d flags %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
+
 	req->buf      = data;
 	req->length   = len;
 
@@ -238,11 +251,18 @@ static int __ffs_ep0_queue_wait(struct ffs_data *ffs, char *data, size_t len)
 	}
 
 	ffs->setup_state = FFS_NO_SETUP;
+
+	ffs_log("exit: state %d setup_state %d flags %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
+
 	return req->status ? req->status : req->actual;
 }
 
 static int __ffs_ep0_stall(struct ffs_data *ffs)
 {
+	ffs_log("state %d setup_state %d flags %lu can_stall %d", ffs->state,
+		ffs->setup_state, ffs->flags, ffs->ev.can_stall);
+
 	if (ffs->ev.can_stall) {
 		pr_vdebug("ep0 stall\n");
 		usb_ep_set_halt(ffs->gadget->ep0);
@@ -263,6 +283,9 @@ static ssize_t ffs_ep0_write(struct file *file, const char __user *buf,
 
 	ENTER();
 
+	ffs_log("enter:len %zu state %d setup_state %d flags %lu", len,
+		ffs->state, ffs->setup_state, ffs->flags);
+
 	/* Fast check if setup was canceled */
 	if (ffs_setup_state_clear_cancelled(ffs) == FFS_SETUP_CANCELLED)
 		return -EIDRM;
@@ -391,6 +414,9 @@ done_spin:
 		break;
 	}
 
+	ffs_log("exit:ret %zu state %d setup_state %d flags %lu", ret,
+		ffs->state, ffs->setup_state, ffs->flags);
+
 	mutex_unlock(&ffs->mutex);
 	return ret;
 }
@@ -424,6 +450,10 @@ static ssize_t __ffs_ep0_read_events(struct ffs_data *ffs, char __user *buf,
 			ffs->ev.count * sizeof *ffs->ev.types);
 
 	spin_unlock_irq(&ffs->ev.waitq.lock);
+
+	ffs_log("state %d setup_state %d flags %lu #evt %zu", ffs->state,
+		ffs->setup_state, ffs->flags, n);
+
 	mutex_unlock(&ffs->mutex);
 
 	return unlikely(copy_to_user(buf, events, size)) ? -EFAULT : size;
@@ -439,6 +469,9 @@ static ssize_t ffs_ep0_read(struct file *file, char __user *buf,
 
 	ENTER();
 
+	ffs_log("enter:len %zu state %d setup_state %d flags %lu", len,
+		ffs->state, ffs->setup_state, ffs->flags);
+
 	/* Fast check if setup was canceled */
 	if (ffs_setup_state_clear_cancelled(ffs) == FFS_SETUP_CANCELLED)
 		return -EIDRM;
@@ -527,8 +560,12 @@ static ssize_t ffs_ep0_read(struct file *file, char __user *buf,
 
 	spin_unlock_irq(&ffs->ev.waitq.lock);
 done_mutex:
+	ffs_log("exit:ret %d state %d setup_state %d flags %lu", ret,
+		ffs->state, ffs->setup_state, ffs->flags);
+
 	mutex_unlock(&ffs->mutex);
 	kfree(data);
+
 	return ret;
 }
 
@@ -538,6 +575,9 @@ static int ffs_ep0_open(struct inode *inode, struct file *file)
 
 	ENTER();
 
+	ffs_log("state %d setup_state %d flags %lu opened %d", ffs->state,
+		ffs->setup_state, ffs->flags, atomic_read(&ffs->opened));
+
 	if (unlikely(ffs->state == FFS_CLOSING))
 		return -EBUSY;
 
@@ -557,6 +597,9 @@ static int ffs_ep0_release(struct inode *inode, struct file *file)
 
 	ENTER();
 
+	ffs_log("state %d setup_state %d flags %lu opened %d", ffs->state,
+		ffs->setup_state, ffs->flags, atomic_read(&ffs->opened));
+
 	ffs_data_closed(ffs);
 
 	return 0;
@@ -570,6 +613,9 @@ static long ffs_ep0_ioctl(struct file *file, unsigned code, unsigned long value)
 
 	ENTER();
 
+	ffs_log("state %d setup_state %d flags %lu opened %d", ffs->state,
+		ffs->setup_state, ffs->flags, atomic_read(&ffs->opened));
+
 	if (code == FUNCTIONFS_INTERFACE_REVMAP) {
 		struct ffs_function *func = ffs->func;
 		ret = func ? ffs_func_revmap_intf(func, value) : -ENODEV;
@@ -588,6 +634,9 @@ static unsigned int ffs_ep0_poll(struct file *file, poll_table *wait)
 	unsigned int mask = POLLWRNORM;
 	int ret;
 
+	ffs_log("enter:state %d setup_state %d flags %lu opened %d", ffs->state,
+		ffs->setup_state, ffs->flags, atomic_read(&ffs->opened));
+
 	poll_wait(file, &ffs->ev.waitq, wait);
 
 	ret = ffs_mutex_lock(&ffs->mutex, file->f_flags & O_NONBLOCK);
@@ -618,6 +667,8 @@ static unsigned int ffs_ep0_poll(struct file *file, poll_table *wait)
 		break;
 	}
 
+	ffs_log("exit: mask %u", mask);
+
 	mutex_unlock(&ffs->mutex);
 
 	return mask;
@@ -648,6 +699,7 @@ static void ffs_epfile_io_complete(struct usb_ep *_ep, struct usb_request *req)
 		ep->status = req->status ? req->status : req->actual;
 		/* Set is_busy false to indicate completion of last request */
 		ep->is_busy = false;
+		ffs_log("ep status %d for req %p", ep->status, req);
 		complete(req->context);
 	}
 }
@@ -659,6 +711,8 @@ static void ffs_user_copy_worker(struct work_struct *work)
 	int ret = io_data->req->status ? io_data->req->status :
 					 io_data->req->actual;
 
+	ffs_log("enter: ret %d", ret);
+
 	if (io_data->read && ret > 0) {
 		use_mm(io_data->mm);
 		ret = copy_to_iter(io_data->buf, ret, &io_data->data);
@@ -680,6 +734,8 @@ static void ffs_user_copy_worker(struct work_struct *work)
 		kfree(io_data->to_free);
 	kfree(io_data->buf);
 	kfree(io_data);
+
+	ffs_log("exit");
 }
 
 static void ffs_epfile_async_io_complete(struct usb_ep *_ep,
@@ -689,8 +745,12 @@ static void ffs_epfile_async_io_complete(struct usb_ep *_ep,
 
 	ENTER();
 
+	ffs_log("enter");
+
 	INIT_WORK(&io_data->work, ffs_user_copy_worker);
 	schedule_work(&io_data->work);
+
+	ffs_log("exit");
 }
 
 static ssize_t ffs_epfile_io(struct file *file, struct ffs_io_data *io_data)
@@ -701,6 +761,9 @@ static ssize_t ffs_epfile_io(struct file *file, struct ffs_io_data *io_data)
 	ssize_t ret, data_len = -EINVAL;
 	int halt;
 
+	ffs_log("enter: epfile name %s epfile err %d", epfile->name,
+		atomic_read(&epfile->error));
+
 	smp_mb__before_atomic();
 	if (atomic_read(&epfile->error))
 		return -ENODEV;
@@ -927,6 +990,9 @@ static ssize_t ffs_epfile_io(struct file *file, struct ffs_io_data *io_data)
 	}
 
 	mutex_unlock(&epfile->mutex);
+
+	ffs_log("exit:ret %zu", ret);
+
 	return ret;
 
 error_lock:
@@ -934,6 +1000,9 @@ error_lock:
 	mutex_unlock(&epfile->mutex);
 error:
 	kfree(data);
+
+	ffs_log("exit: ret %zu", ret);
+
 	return ret;
 }
 
@@ -944,6 +1013,9 @@ ffs_epfile_open(struct inode *inode, struct file *file)
 
 	ENTER();
 
+	ffs_log("enter:state %d setup_state %d flag %lu", epfile->ffs->state,
+		epfile->ffs->setup_state, epfile->ffs->flags);
+
 	if (WARN_ON(epfile->ffs->state != FFS_ACTIVE))
 		return -ENODEV;
 
@@ -962,6 +1034,9 @@ ffs_epfile_open(struct inode *inode, struct file *file)
 	smp_mb__before_atomic();
 	atomic_set(&epfile->error, 0);
 
+	ffs_log("exit:state %d setup_state %d flag %lu", epfile->ffs->state,
+		epfile->ffs->setup_state, epfile->ffs->flags);
+
 	return 0;
 }
 
@@ -973,6 +1048,9 @@ static int ffs_aio_cancel(struct kiocb *kiocb)
 
 	ENTER();
 
+	ffs_log("enter:state %d setup_state %d flag %lu", epfile->ffs->state,
+		epfile->ffs->setup_state, epfile->ffs->flags);
+
 	spin_lock_irq(&epfile->ffs->eps_lock);
 
 	if (likely(io_data && io_data->ep && io_data->req))
@@ -982,6 +1060,8 @@ static int ffs_aio_cancel(struct kiocb *kiocb)
 
 	spin_unlock_irq(&epfile->ffs->eps_lock);
 
+	ffs_log("exit: value %d", value);
+
 	return value;
 }
 
@@ -992,6 +1072,8 @@ static ssize_t ffs_epfile_write_iter(struct kiocb *kiocb, struct iov_iter *from)
 
 	ENTER();
 
+	ffs_log("enter");
+
 	if (!is_sync_kiocb(kiocb)) {
 		p = kmalloc(sizeof(io_data), GFP_KERNEL);
 		if (unlikely(!p))
@@ -1018,6 +1100,9 @@ static ssize_t ffs_epfile_write_iter(struct kiocb *kiocb, struct iov_iter *from)
 		kfree(p);
 	else
 		*from = p->data;
+
+	ffs_log("exit");
+
 	return res;
 }
 
@@ -1028,6 +1113,8 @@ static ssize_t ffs_epfile_read_iter(struct kiocb *kiocb, struct iov_iter *to)
 
 	ENTER();
 
+	ffs_log("enter");
+
 	if (!is_sync_kiocb(kiocb)) {
 		p = kmalloc(sizeof(io_data), GFP_KERNEL);
 		if (unlikely(!p))
@@ -1066,6 +1153,9 @@ static ssize_t ffs_epfile_read_iter(struct kiocb *kiocb, struct iov_iter *to)
 	} else {
 		*to = p->data;
 	}
+
+	ffs_log("enter");
+
 	return res;
 }
 
@@ -1076,12 +1166,17 @@ ffs_epfile_release(struct inode *inode, struct file *file)
 
 	ENTER();
 
+	ffs_log("enter:state %d setup_state %d flag %lu", epfile->ffs->state,
+		epfile->ffs->setup_state, epfile->ffs->flags);
+
 	smp_mb__before_atomic();
 	atomic_set(&epfile->opened, 0);
 	atomic_set(&epfile->error, 1);
 	ffs_data_closed(epfile->ffs);
 	file->private_data = NULL;
 
+	ffs_log("exit");
+
 	return 0;
 }
 
@@ -1093,6 +1188,9 @@ static long ffs_epfile_ioctl(struct file *file, unsigned code,
 
 	ENTER();
 
+	ffs_log("enter:state %d setup_state %d flag %lu", epfile->ffs->state,
+		epfile->ffs->setup_state, epfile->ffs->flags);
+
 	if (WARN_ON(epfile->ffs->state != FFS_ACTIVE))
 		return -ENODEV;
 
@@ -1143,6 +1241,8 @@ static long ffs_epfile_ioctl(struct file *file, unsigned code,
 	}
 	spin_unlock_irq(&epfile->ffs->eps_lock);
 
+	ffs_log("exit:ret %d", ret);
+
 	return ret;
 }
 
@@ -1174,6 +1274,8 @@ ffs_sb_make_inode(struct super_block *sb, void *data,
 
 	ENTER();
 
+	ffs_log("enter");
+
 	inode = new_inode(sb);
 
 	if (likely(inode)) {
@@ -1193,6 +1295,8 @@ ffs_sb_make_inode(struct super_block *sb, void *data,
 			inode->i_op  = iops;
 	}
 
+	ffs_log("exit");
+
 	return inode;
 }
 
@@ -1207,6 +1311,8 @@ static struct dentry *ffs_sb_create_file(struct super_block *sb,
 
 	ENTER();
 
+	ffs_log("enter");
+
 	dentry = d_alloc_name(sb->s_root, name);
 	if (unlikely(!dentry))
 		return NULL;
@@ -1218,6 +1324,9 @@ static struct dentry *ffs_sb_create_file(struct super_block *sb,
 	}
 
 	d_add(dentry, inode);
+
+	ffs_log("exit");
+
 	return dentry;
 }
 
@@ -1243,6 +1352,8 @@ static int ffs_sb_fill(struct super_block *sb, void *_data, int silent)
 
 	ENTER();
 
+	ffs_log("enter");
+
 	ffs->sb              = sb;
 	data->ffs_data       = NULL;
 	sb->s_fs_info        = ffs;
@@ -1267,6 +1378,8 @@ static int ffs_sb_fill(struct super_block *sb, void *_data, int silent)
 					 &ffs_ep0_operations)))
 		return -ENOMEM;
 
+	ffs_log("exit");
+
 	return 0;
 }
 
@@ -1274,6 +1387,8 @@ static int ffs_fs_parse_opts(struct ffs_sb_fill_data *data, char *opts)
 {
 	ENTER();
 
+	ffs_log("enter");
+
 	if (!opts || !*opts)
 		return 0;
 
@@ -1356,6 +1471,8 @@ invalid:
 		opts = comma + 1;
 	}
 
+	ffs_log("exit");
+
 	return 0;
 }
 
@@ -1381,6 +1498,8 @@ ffs_fs_mount(struct file_system_type *t, int flags,
 
 	ENTER();
 
+	ffs_log("enter");
+
 	ret = ffs_fs_parse_opts(&data, opts);
 	if (unlikely(ret < 0))
 		return ERR_PTR(ret);
@@ -1410,6 +1529,9 @@ ffs_fs_mount(struct file_system_type *t, int flags,
 		ffs_release_dev(data.ffs_data);
 		ffs_data_put(data.ffs_data);
 	}
+
+	ffs_log("exit");
+
 	return rv;
 }
 
@@ -1418,12 +1540,16 @@ ffs_fs_kill_sb(struct super_block *sb)
 {
 	ENTER();
 
+	ffs_log("enter");
+
 	kill_litter_super(sb);
 	if (sb->s_fs_info) {
 		ffs_release_dev(sb->s_fs_info);
 		ffs_data_closed(sb->s_fs_info);
 		ffs_data_put(sb->s_fs_info);
 	}
+
+	ffs_log("exit");
 }
 
 static struct file_system_type ffs_fs_type = {
@@ -1449,6 +1575,8 @@ static int functionfs_init(void)
 	else
 		pr_err("failed registering file system (%d)\n", ret);
 
+	ffs_ipc_log = ipc_log_context_create(NUM_PAGES, "f_fs", 0);
+
 	return ret;
 }
 
@@ -1470,14 +1598,21 @@ static void ffs_data_get(struct ffs_data *ffs)
 {
 	ENTER();
 
+	ffs_log("enter");
+
 	smp_mb__before_atomic();
 	atomic_inc(&ffs->ref);
+
+	ffs_log("exit");
 }
 
 static void ffs_data_opened(struct ffs_data *ffs)
 {
 	ENTER();
 
+	ffs_log("enter: state %d setup_state %d flag %lu opened %d", ffs->state,
+		ffs->setup_state, ffs->flags, atomic_read(&ffs->opened));
+
 	smp_mb__before_atomic();
 	atomic_inc(&ffs->ref);
 	if (atomic_add_return(1, &ffs->opened) == 1 &&
@@ -1485,12 +1620,17 @@ static void ffs_data_opened(struct ffs_data *ffs)
 		ffs->state = FFS_CLOSING;
 		ffs_data_reset(ffs);
 	}
+
+	ffs_log("exit: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
 }
 
 static void ffs_data_put(struct ffs_data *ffs)
 {
 	ENTER();
 
+	ffs_log("enter");
+
 	smp_mb__before_atomic();
 	if (unlikely(atomic_dec_and_test(&ffs->ref))) {
 		pr_info("%s(): freeing\n", __func__);
@@ -1500,12 +1640,17 @@ static void ffs_data_put(struct ffs_data *ffs)
 		kfree(ffs->dev_name);
 		kfree(ffs);
 	}
+
+	ffs_log("exit");
 }
 
 static void ffs_data_closed(struct ffs_data *ffs)
 {
 	ENTER();
 
+	ffs_log("enter: state %d setup_state %d flag %lu opened %d", ffs->state,
+		ffs->setup_state, ffs->flags, atomic_read(&ffs->opened));
+
 	smp_mb__before_atomic();
 	if (atomic_dec_and_test(&ffs->opened)) {
 		if (ffs->no_disconnect) {
@@ -1529,6 +1674,9 @@ static void ffs_data_closed(struct ffs_data *ffs)
 		ffs_data_reset(ffs);
 	}
 
+	ffs_log("exit: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
+
 	ffs_data_put(ffs);
 }
 
@@ -1540,6 +1688,8 @@ static struct ffs_data *ffs_data_new(void)
 
 	ENTER();
 
+	ffs_log("enter");
+
 	atomic_set(&ffs->ref, 1);
 	atomic_set(&ffs->opened, 0);
 	ffs->state = FFS_READ_DESCRIPTORS;
@@ -1553,6 +1703,8 @@ static struct ffs_data *ffs_data_new(void)
 	/* XXX REVISIT need to update it in some places, or do we? */
 	ffs->ev.can_stall = 1;
 
+	ffs_log("exit");
+
 	return ffs;
 }
 
@@ -1560,6 +1712,9 @@ static void ffs_data_clear(struct ffs_data *ffs)
 {
 	ENTER();
 
+	ffs_log("enter: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
+
 	pr_debug("%s: ffs->gadget= %p, ffs->flags= %lu\n",
 				__func__, ffs->gadget, ffs->flags);
 	ffs_closed(ffs);
@@ -1578,12 +1733,18 @@ static void ffs_data_clear(struct ffs_data *ffs)
 	kfree(ffs->raw_descs_data);
 	kfree(ffs->raw_strings);
 	kfree(ffs->stringtabs);
+
+	ffs_log("exit: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
 }
 
 static void ffs_data_reset(struct ffs_data *ffs)
 {
 	ENTER();
 
+	ffs_log("enter: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
+
 	ffs_data_clear(ffs);
 
 	ffs->epfiles = NULL;
@@ -1606,6 +1767,9 @@ static void ffs_data_reset(struct ffs_data *ffs)
 	ffs->state = FFS_READ_DESCRIPTORS;
 	ffs->setup_state = FFS_NO_SETUP;
 	ffs->flags = 0;
+
+	ffs_log("exit: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
 }
 
 
@@ -1616,6 +1780,9 @@ static int functionfs_bind(struct ffs_data *ffs, struct usb_composite_dev *cdev)
 
 	ENTER();
 
+	ffs_log("enter: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
+
 	if (WARN_ON(ffs->state != FFS_ACTIVE
 		 || test_and_set_bit(FFS_FL_BOUND, &ffs->flags)))
 		return -EBADFD;
@@ -1641,6 +1808,10 @@ static int functionfs_bind(struct ffs_data *ffs, struct usb_composite_dev *cdev)
 	}
 
 	ffs->gadget = cdev->gadget;
+
+	ffs_log("exit: state %d setup_state %d flag %lu gadget %p\n",
+			ffs->state, ffs->setup_state, ffs->flags, ffs->gadget);
+
 	ffs_data_get(ffs);
 	return 0;
 }
@@ -1654,6 +1825,8 @@ static void functionfs_unbind(struct ffs_data *ffs)
 		ffs->ep0req = NULL;
 		ffs->gadget = NULL;
 		clear_bit(FFS_FL_BOUND, &ffs->flags);
+		ffs_log("state %d setup_state %d flag %lu gadget %p\n",
+			ffs->state, ffs->setup_state, ffs->flags, ffs->gadget);
 		ffs_data_put(ffs);
 	}
 }
@@ -1665,6 +1838,9 @@ static int ffs_epfiles_create(struct ffs_data *ffs)
 
 	ENTER();
 
+	ffs_log("enter: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
+
 	count = ffs->eps_count;
 	epfiles = kcalloc(count, sizeof(*epfiles), GFP_KERNEL);
 	if (!epfiles)
@@ -1690,6 +1866,10 @@ static int ffs_epfiles_create(struct ffs_data *ffs)
 	}
 
 	ffs->epfiles = epfiles;
+
+	ffs_log("exit: epfile name %s state %d setup_state %d flag %lu",
+		epfile->name, ffs->state, ffs->setup_state, ffs->flags);
+
 	return 0;
 }
 
@@ -1699,6 +1879,8 @@ static void ffs_epfiles_destroy(struct ffs_epfile *epfiles, unsigned count)
 
 	ENTER();
 
+	ffs_log("enter: epfilename %s", epfile->name);
+
 	for (; count; --count, ++epfile) {
 		BUG_ON(mutex_is_locked(&epfile->mutex) ||
 		       waitqueue_active(&epfile->wait));
@@ -1710,6 +1892,8 @@ static void ffs_epfiles_destroy(struct ffs_epfile *epfiles, unsigned count)
 	}
 
 	kfree(epfiles);
+
+	ffs_log("exit");
 }
 
 static void ffs_func_eps_disable(struct ffs_function *func)
@@ -1719,6 +1903,9 @@ static void ffs_func_eps_disable(struct ffs_function *func)
 	unsigned count            = func->ffs->eps_count;
 	unsigned long flags;
 
+	ffs_log("enter: state %d setup_state %d flag %lu", func->ffs->state,
+		func->ffs->setup_state, func->ffs->flags);
+
 	spin_lock_irqsave(&func->ffs->eps_lock, flags);
 	do {
 
@@ -1738,6 +1925,8 @@ static void ffs_func_eps_disable(struct ffs_function *func)
 		}
 	} while (--count);
 	spin_unlock_irqrestore(&func->ffs->eps_lock, flags);
+
+	ffs_log("exit");
 }
 
 static int ffs_func_eps_enable(struct ffs_function *func)
@@ -1749,6 +1938,9 @@ static int ffs_func_eps_enable(struct ffs_function *func)
 	unsigned long flags;
 	int ret = 0;
 
+	ffs_log("enter: state %d setup_state %d flag %lu", func->ffs->state,
+		func->ffs->setup_state, func->ffs->flags);
+
 	spin_lock_irqsave(&func->ffs->eps_lock, flags);
 	do {
 		struct usb_endpoint_descriptor *ds;
@@ -1786,6 +1978,7 @@ static int ffs_func_eps_enable(struct ffs_function *func)
 			epfile->ep = ep;
 			epfile->in = usb_endpoint_dir_in(ds);
 			epfile->isoc = usb_endpoint_xfer_isoc(ds);
+			ffs_log("usb_ep_enable %s", ep->ep->name);
 		} else {
 			break;
 		}
@@ -1797,6 +1990,8 @@ static int ffs_func_eps_enable(struct ffs_function *func)
 	} while (--count);
 	spin_unlock_irqrestore(&func->ffs->eps_lock, flags);
 
+	ffs_log("exit: ret %d", ret);
+
 	return ret;
 }
 
@@ -1837,6 +2032,8 @@ static int __must_check ffs_do_single_desc(char *data, unsigned len,
 
 	ENTER();
 
+	ffs_log("enter: len %u", len);
+
 	/* At least two bytes are required: length and type */
 	if (len < 2) {
 		pr_vdebug("descriptor too short\n");
@@ -1953,6 +2150,8 @@ inv_length:
 #undef __entity_check_STRING
 #undef __entity_check_ENDPOINT
 
+	ffs_log("exit: desc type %d length %d", _ds->bDescriptorType, length);
+
 	return length;
 }
 
@@ -1964,6 +2163,8 @@ static int __must_check ffs_do_descs(unsigned count, char *data, unsigned len,
 
 	ENTER();
 
+	ffs_log("enter: len %u", len);
+
 	for (;;) {
 		int ret;
 
@@ -1991,6 +2192,8 @@ static int __must_check ffs_do_descs(unsigned count, char *data, unsigned len,
 		data += ret;
 		++num;
 	}
+
+	ffs_log("exit: len %u", len);
 }
 
 static int __ffs_data_do_entity(enum ffs_entity_type type,
@@ -2002,6 +2205,8 @@ static int __ffs_data_do_entity(enum ffs_entity_type type,
 
 	ENTER();
 
+	ffs_log("enter: type %u", type);
+
 	switch (type) {
 	case FFS_DESCRIPTOR:
 		break;
@@ -2040,6 +2245,8 @@ static int __ffs_data_do_entity(enum ffs_entity_type type,
 		break;
 	}
 
+	ffs_log("exit");
+
 	return 0;
 }
 
@@ -2049,6 +2256,8 @@ static int __ffs_do_os_desc_header(enum ffs_os_desc_type *next_type,
 	u16 bcd_version = le16_to_cpu(desc->bcdVersion);
 	u16 w_index = le16_to_cpu(desc->wIndex);
 
+	ffs_log("enter");
+
 	if (bcd_version != 1) {
 		pr_vdebug("unsupported os descriptors version: %d",
 			  bcd_version);
@@ -2066,6 +2275,8 @@ static int __ffs_do_os_desc_header(enum ffs_os_desc_type *next_type,
 		return -EINVAL;
 	}
 
+	ffs_log("exit: size of desc %lu", sizeof(*desc));
+
 	return sizeof(*desc);
 }
 
@@ -2085,6 +2296,8 @@ static int __must_check ffs_do_single_os_desc(char *data, unsigned len,
 
 	ENTER();
 
+	ffs_log("enter: len %u os desc type %d", len, type);
+
 	/* loop over all ext compat/ext prop descriptors */
 	while (feature_count--) {
 		ret = entity(type, h, data, len, priv);
@@ -2095,6 +2308,9 @@ static int __must_check ffs_do_single_os_desc(char *data, unsigned len,
 		data += ret;
 		len -= ret;
 	}
+
+	ffs_log("exit");
+
 	return _len - len;
 }
 
@@ -2108,6 +2324,8 @@ static int __must_check ffs_do_os_descs(unsigned count,
 
 	ENTER();
 
+	ffs_log("enter: len %u", len);
+
 	for (num = 0; num < count; ++num) {
 		int ret;
 		enum ffs_os_desc_type type;
@@ -2157,6 +2375,9 @@ static int __must_check ffs_do_os_descs(unsigned count,
 		len -= ret;
 		data += ret;
 	}
+
+	ffs_log("exit");
+
 	return _len - len;
 }
 
@@ -2172,6 +2393,8 @@ static int __ffs_data_do_os_desc(enum ffs_os_desc_type type,
 
 	ENTER();
 
+	ffs_log("enter: len %u", len);
+
 	switch (type) {
 	case FFS_OS_DESC_EXT_COMPAT: {
 		struct usb_ext_compat_desc *d = data;
@@ -2226,6 +2449,9 @@ static int __ffs_data_do_os_desc(enum ffs_os_desc_type type,
 		pr_vdebug("unknown descriptor: %d\n", type);
 		return -EINVAL;
 	}
+
+	ffs_log("exit");
+
 	return length;
 }
 
@@ -2239,6 +2465,8 @@ static int __ffs_data_got_descs(struct ffs_data *ffs,
 
 	ENTER();
 
+	ffs_log("enter: len %zu", len);
+
 	if (get_unaligned_le32(data + 4) != len)
 		goto error;
 
@@ -2349,10 +2577,13 @@ static int __ffs_data_got_descs(struct ffs_data *ffs,
 	ffs->ss_descs_count	= counts[2];
 	ffs->ms_os_descs_count	= os_descs_count;
 
+	ffs_log("exit");
+
 	return 0;
 
 error:
 	kfree(_data);
+	ffs_log("exit: ret %d", ret);
 	return ret;
 }
 
@@ -2366,6 +2597,8 @@ static int __ffs_data_got_strings(struct ffs_data *ffs,
 
 	ENTER();
 
+	ffs_log("enter: len %zu", len);
+
 	if (unlikely(get_unaligned_le32(data) != FUNCTIONFS_STRINGS_MAGIC ||
 		     get_unaligned_le32(data + 4) != len))
 		goto error;
@@ -2480,12 +2713,14 @@ static int __ffs_data_got_strings(struct ffs_data *ffs,
 	ffs->stringtabs = stringtabs;
 	ffs->raw_strings = _data;
 
+	ffs_log("exit");
 	return 0;
 
 error_free:
 	kfree(stringtabs);
 error:
 	kfree(_data);
+	ffs_log("exit: -EINVAL");
 	return -EINVAL;
 }
 
@@ -2498,6 +2733,9 @@ static void __ffs_event_add(struct ffs_data *ffs,
 	enum usb_functionfs_event_type rem_type1, rem_type2 = type;
 	int neg = 0;
 
+	ffs_log("enter: type %d state %d setup_state %d flag %lu", type,
+		ffs->state, ffs->setup_state, ffs->flags);
+
 	/*
 	 * Abort any unhandled setup
 	 *
@@ -2557,6 +2795,9 @@ static void __ffs_event_add(struct ffs_data *ffs,
 	wake_up_locked(&ffs->ev.waitq);
 	if (ffs->ffs_eventfd)
 		eventfd_signal(ffs->ffs_eventfd, 1);
+
+	ffs_log("exit: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
 }
 
 static void ffs_event_add(struct ffs_data *ffs,
@@ -2591,6 +2832,8 @@ static int __ffs_func_bind_do_descs(enum ffs_entity_type type, u8 *valuep,
 	int idx;
 	static const char *speed_names[] = { "full", "high", "super" };
 
+	ffs_log("enter");
+
 	if (type != FFS_DESCRIPTOR)
 		return 0;
 
@@ -2666,6 +2909,8 @@ static int __ffs_func_bind_do_descs(enum ffs_entity_type type, u8 *valuep,
 	}
 	ffs_dump_mem(": Rewritten ep desc", ds, ds->bLength);
 
+	ffs_log("exit");
+
 	return 0;
 }
 
@@ -2677,6 +2922,8 @@ static int __ffs_func_bind_do_nums(enum ffs_entity_type type, u8 *valuep,
 	unsigned idx;
 	u8 newValue;
 
+	ffs_log("enter: type %d", type);
+
 	switch (type) {
 	default:
 	case FFS_DESCRIPTOR:
@@ -2721,6 +2968,9 @@ static int __ffs_func_bind_do_nums(enum ffs_entity_type type, u8 *valuep,
 
 	pr_vdebug("%02x -> %02x\n", *valuep, newValue);
 	*valuep = newValue;
+
+	ffs_log("exit: newValue %d", newValue);
+
 	return 0;
 }
 
@@ -2731,6 +2981,8 @@ static int __ffs_func_bind_do_os_desc(enum ffs_os_desc_type type,
 	struct ffs_function *func = priv;
 	u8 length = 0;
 
+	ffs_log("enter: type %d", type);
+
 	switch (type) {
 	case FFS_OS_DESC_EXT_COMPAT: {
 		struct usb_ext_compat_desc *desc = data;
@@ -2800,6 +3052,8 @@ static int __ffs_func_bind_do_os_desc(enum ffs_os_desc_type type,
 		pr_vdebug("unknown descriptor: %d\n", type);
 	}
 
+	ffs_log("exit");
+
 	return length;
 }
 
@@ -2813,6 +3067,8 @@ static inline struct f_fs_opts *ffs_do_functionfs_bind(struct usb_function *f,
 
 	ENTER();
 
+	ffs_log("enter");
+
 	/*
 	 * Legacy gadget triggers binding in functionfs_ready_callback,
 	 * which already uses locking; taking the same lock here would
@@ -2847,6 +3103,8 @@ static inline struct f_fs_opts *ffs_do_functionfs_bind(struct usb_function *f,
 	ffs_opts->refcnt++;
 	func->function.strings = func->ffs->stringtabs;
 
+	ffs_log("exit");
+
 	return ffs_opts;
 }
 
@@ -2889,6 +3147,9 @@ static int _ffs_func_bind(struct usb_configuration *c,
 
 	ENTER();
 
+	ffs_log("enter: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
+
 	/* Has descriptors only for speeds gadget does not support */
 	if (unlikely(!(full | high | super)))
 		return -ENOTSUPP;
@@ -3006,10 +3267,15 @@ static int _ffs_func_bind(struct usb_configuration *c,
 
 	/* And we're done */
 	ffs_event_add(ffs, FUNCTIONFS_BIND);
+
+	ffs_log("exit: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
+
 	return 0;
 
 error:
 	/* XXX Do we need to release all claimed endpoints here? */
+	ffs_log("exit: ret %d", ret);
 	return ret;
 }
 
@@ -3020,6 +3286,8 @@ static int ffs_func_bind(struct usb_configuration *c,
 	struct ffs_function *func = ffs_func_from_usb(f);
 	int ret;
 
+	ffs_log("enter");
+
 	if (IS_ERR(ffs_opts))
 		return PTR_ERR(ffs_opts);
 
@@ -3027,6 +3295,8 @@ static int ffs_func_bind(struct usb_configuration *c,
 	if (ret && !--ffs_opts->refcnt)
 		functionfs_unbind(func->ffs);
 
+	ffs_log("exit: ret %d", ret);
+
 	return ret;
 }
 
@@ -3037,7 +3307,12 @@ static void ffs_reset_work(struct work_struct *work)
 {
 	struct ffs_data *ffs = container_of(work,
 		struct ffs_data, reset_work);
+
+	ffs_log("enter");
+
 	ffs_data_reset(ffs);
+
+	ffs_log("exit");
 }
 
 static int ffs_func_set_alt(struct usb_function *f,
@@ -3047,6 +3322,8 @@ static int ffs_func_set_alt(struct usb_function *f,
 	struct ffs_data *ffs = func->ffs;
 	int ret = 0, intf;
 
+	ffs_log("enter");
+
 	if (alt != (unsigned)-1) {
 		intf = ffs_func_revmap_intf(func, interface);
 		if (unlikely(intf < 0))
@@ -3082,6 +3359,8 @@ static int ffs_func_set_alt(struct usb_function *f,
 		usb_gadget_autopm_get_async(ffs->gadget);
 	}
 
+	ffs_log("exit: ret %d", ret);
+
 	return ret;
 }
 
@@ -3090,9 +3369,13 @@ static void ffs_func_disable(struct usb_function *f)
 	struct ffs_function *func = ffs_func_from_usb(f);
 	struct ffs_data *ffs = func->ffs;
 
+	ffs_log("enter");
+
 	ffs_func_set_alt(f, 0, (unsigned)-1);
 	/* matching put to allow LPM on disconnect */
 	usb_gadget_autopm_put_async(ffs->gadget);
+
+	ffs_log("exit");
 }
 
 static int ffs_func_setup(struct usb_function *f,
@@ -3105,6 +3388,8 @@ static int ffs_func_setup(struct usb_function *f,
 
 	ENTER();
 
+	ffs_log("enter");
+
 	pr_vdebug("creq->bRequestType = %02x\n", creq->bRequestType);
 	pr_vdebug("creq->bRequest     = %02x\n", creq->bRequest);
 	pr_vdebug("creq->wValue       = %04x\n", le16_to_cpu(creq->wValue));
@@ -3148,19 +3433,31 @@ static int ffs_func_setup(struct usb_function *f,
 	__ffs_event_add(ffs, FUNCTIONFS_SETUP);
 	spin_unlock_irqrestore(&ffs->ev.waitq.lock, flags);
 
+	ffs_log("exit");
+
 	return 0;
 }
 
 static void ffs_func_suspend(struct usb_function *f)
 {
 	ENTER();
+
+	ffs_log("enter");
+
 	ffs_event_add(ffs_func_from_usb(f)->ffs, FUNCTIONFS_SUSPEND);
+
+	ffs_log("exit");
 }
 
 static void ffs_func_resume(struct usb_function *f)
 {
 	ENTER();
+
+	ffs_log("enter");
+
 	ffs_event_add(ffs_func_from_usb(f)->ffs, FUNCTIONFS_RESUME);
+
+	ffs_log("exit");
 }
 
 
@@ -3177,11 +3474,15 @@ static int ffs_func_revmap_intf(struct ffs_function *func, u8 intf)
 	short *nums = func->interfaces_nums;
 	unsigned count = func->ffs->interfaces_count;
 
+	ffs_log("enter");
+
 	for (; count; --count, ++nums) {
 		if (*nums >= 0 && *nums == intf)
 			return nums - func->interfaces_nums;
 	}
 
+	ffs_log("exit");
+
 	return -EDOM;
 }
 
@@ -3194,6 +3495,8 @@ static struct ffs_dev *_ffs_do_find_dev(const char *name)
 {
 	struct ffs_dev *dev;
 
+	ffs_log("enter");
+
 	list_for_each_entry(dev, &ffs_devices, entry) {
 		if (!dev->name || !name)
 			continue;
@@ -3201,6 +3504,8 @@ static struct ffs_dev *_ffs_do_find_dev(const char *name)
 			return dev;
 	}
 
+	ffs_log("exit");
+
 	return NULL;
 }
 
@@ -3211,12 +3516,16 @@ static struct ffs_dev *_ffs_get_single_dev(void)
 {
 	struct ffs_dev *dev;
 
+	ffs_log("enter");
+
 	if (list_is_singular(&ffs_devices)) {
 		dev = list_first_entry(&ffs_devices, struct ffs_dev, entry);
 		if (dev->single)
 			return dev;
 	}
 
+	ffs_log("exit");
+
 	return NULL;
 }
 
@@ -3227,11 +3536,17 @@ static struct ffs_dev *_ffs_find_dev(const char *name)
 {
 	struct ffs_dev *dev;
 
+	ffs_log("enter");
+
 	dev = _ffs_get_single_dev();
 	if (dev)
 		return dev;
 
-	return _ffs_do_find_dev(name);
+	dev = _ffs_do_find_dev(name);
+
+	ffs_log("exit");
+
+	return dev;
 }
 
 /* Configfs support *********************************************************/
@@ -3353,6 +3668,10 @@ static void ffs_func_unbind(struct usb_configuration *c,
 	unsigned long flags;
 
 	ENTER();
+
+	ffs_log("enter: state %d setup_state %d flag %lu", ffs->state,
+		ffs->setup_state, ffs->flags);
+
 	if (ffs->func == func) {
 		ffs_func_eps_disable(func);
 		ffs->func = NULL;
@@ -3383,6 +3702,9 @@ static void ffs_func_unbind(struct usb_configuration *c,
 	func->interfaces_nums = NULL;
 
 	ffs_event_add(ffs, FUNCTIONFS_UNBIND);
+
+	ffs_log("exit: state %d setup_state %d flag %lu", ffs->state,
+	ffs->setup_state, ffs->flags);
 }
 
 static struct usb_function *ffs_alloc(struct usb_function_instance *fi)
@@ -3445,12 +3767,16 @@ static int _ffs_name_dev(struct ffs_dev *dev, const char *name)
 {
 	struct ffs_dev *existing;
 
+	ffs_log("enter");
+
 	existing = _ffs_do_find_dev(name);
 	if (existing)
 		return -EBUSY;
 
 	dev->name = name;
 
+	ffs_log("exit");
+
 	return 0;
 }
 
@@ -3461,10 +3787,14 @@ int ffs_name_dev(struct ffs_dev *dev, const char *name)
 {
 	int ret;
 
+	ffs_log("enter");
+
 	ffs_dev_lock();
 	ret = _ffs_name_dev(dev, name);
 	ffs_dev_unlock();
 
+	ffs_log("exit");
+
 	return ret;
 }
 EXPORT_SYMBOL_GPL(ffs_name_dev);
@@ -3473,6 +3803,8 @@ int ffs_single_dev(struct ffs_dev *dev)
 {
 	int ret;
 
+	ffs_log("enter");
+
 	ret = 0;
 	ffs_dev_lock();
 
@@ -3482,6 +3814,9 @@ int ffs_single_dev(struct ffs_dev *dev)
 		dev->single = true;
 
 	ffs_dev_unlock();
+
+	ffs_log("exit");
+
 	return ret;
 }
 EXPORT_SYMBOL_GPL(ffs_single_dev);
@@ -3491,12 +3826,17 @@ EXPORT_SYMBOL_GPL(ffs_single_dev);
  */
 static void _ffs_free_dev(struct ffs_dev *dev)
 {
+
+	ffs_log("enter");
+
 	list_del(&dev->entry);
 	if (dev->name_allocated)
 		kfree(dev->name);
 	kfree(dev);
 	if (list_empty(&ffs_devices))
 		functionfs_cleanup();
+
+	ffs_log("exit");
 }
 
 static void *ffs_acquire_dev(const char *dev_name)
@@ -3504,6 +3844,9 @@ static void *ffs_acquire_dev(const char *dev_name)
 	struct ffs_dev *ffs_dev;
 
 	ENTER();
+
+	ffs_log("enter");
+
 	ffs_dev_lock();
 
 	ffs_dev = _ffs_find_dev(dev_name);
@@ -3518,6 +3861,9 @@ static void *ffs_acquire_dev(const char *dev_name)
 		ffs_dev->mounted = true;
 
 	ffs_dev_unlock();
+
+	ffs_log("exit");
+
 	return ffs_dev;
 }
 
@@ -3526,6 +3872,9 @@ static void ffs_release_dev(struct ffs_data *ffs_data)
 	struct ffs_dev *ffs_dev;
 
 	ENTER();
+
+	ffs_log("enter");
+
 	ffs_dev_lock();
 
 	ffs_dev = ffs_data->private_data;
@@ -3537,6 +3886,8 @@ static void ffs_release_dev(struct ffs_data *ffs_data)
 	}
 
 	ffs_dev_unlock();
+
+	ffs_log("exit");
 }
 
 static int ffs_ready(struct ffs_data *ffs)
@@ -3545,6 +3896,9 @@ static int ffs_ready(struct ffs_data *ffs)
 	int ret = 0;
 
 	ENTER();
+
+	ffs_log("enter");
+
 	ffs_dev_lock();
 
 	ffs_obj = ffs->private_data;
@@ -3569,6 +3923,9 @@ static int ffs_ready(struct ffs_data *ffs)
 	set_bit(FFS_FL_CALL_CLOSED_CALLBACK, &ffs->flags);
 done:
 	ffs_dev_unlock();
+
+	ffs_log("exit");
+
 	return ret;
 }
 
@@ -3578,6 +3935,9 @@ static void ffs_closed(struct ffs_data *ffs)
 	struct f_fs_opts *opts;
 
 	ENTER();
+
+	ffs_log("enter");
+
 	ffs_dev_lock();
 
 	ffs_obj = ffs->private_data;
@@ -3602,8 +3962,12 @@ static void ffs_closed(struct ffs_data *ffs)
 
 	unregister_gadget_item(ffs_obj->opts->
 			       func_inst.group.cg_item.ci_parent->ci_parent);
+
+	ffs_log("unreg gadget done");
 done:
 	ffs_dev_unlock();
+
+	ffs_log("exit");
 }
 
 /* Misc helper functions ****************************************************/