From ba7e9f6335ed608dabd2685812eb3ca70316aef7 Mon Sep 17 00:00:00 2001 From: Jack Pham Date: Thu, 28 Jul 2016 11:51:07 -0700 Subject: [PATCH] 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. Allow this to be enabled with CONFIG_USB_F_FS_IPC_LOGGING which is dependent on CONFIG_QGKI. Change-Id: I15011d79fc2f054e64f8bbd1f8f5db8944b46ada Signed-off-by: Hemant Kumar Signed-off-by: Mayank Rana Signed-off-by: Jack Pham --- drivers/usb/gadget/Kconfig | 12 ++ drivers/usb/gadget/function/f_fs.c | 331 +++++++++++++++++++++++++++-- drivers/usb/gadget/function/u_fs.h | 4 + 3 files changed, 325 insertions(+), 22 deletions(-) diff --git a/drivers/usb/gadget/Kconfig b/drivers/usb/gadget/Kconfig index a71866bfdaf0..4cd21810e280 100644 --- a/drivers/usb/gadget/Kconfig +++ b/drivers/usb/gadget/Kconfig @@ -237,6 +237,18 @@ config USB_F_CDEV config USB_F_GSI tristate +config USB_F_FS_IPC_LOGGING + bool "Enable IPC logging for FunctionFS" + depends on QGKI + default IPC_LOGGING + help + Enables additional debug messages in FunctionFS driver to be + output via IPC Logging mechanism. This can be useful when + troubleshooting transfer stalls or other general failures and + determine if the issue is in the kernel gadget or the userspace + client. Separate IPC log contexts are created for each function + instance at mount time. + # this first set of drivers all depend on bulk-capable hardware. config USB_CONFIGFS diff --git a/drivers/usb/gadget/function/f_fs.c b/drivers/usb/gadget/function/f_fs.c index f34fa5d32222..2695368efcd8 100644 --- a/drivers/usb/gadget/function/f_fs.c +++ b/drivers/usb/gadget/function/f_fs.c @@ -43,6 +43,41 @@ #define FUNCTIONFS_MAGIC 0xa647361 /* Chosen by a honest dice roll ;) */ +#ifdef CONFIG_USB_F_FS_IPC_LOGGING +static inline void ffs_ipc_log_create(struct ffs_data *ffs, + const char *dev_name) +{ + char ipcname[24] = "usb_ffs_"; + + strlcat(ipcname, dev_name, sizeof(ipcname)); + ffs->ipc_log = ipc_log_context_create(10, ipcname, 0); + if (IS_ERR_OR_NULL(ffs->ipc_log)) + ffs->ipc_log = NULL; +} + +static inline void ffs_ipc_log_destroy(struct ffs_data *ffs) +{ + ipc_log_context_destroy(ffs->ipc_log); + ffs->ipc_log = NULL; +} + +#ifdef CONFIG_DYNAMIC_DEBUG +#define ffs_log(fmt, ...) do { \ + ipc_log_string(ffs->ipc_log, "%s: " fmt, __func__, ##__VA_ARGS__); \ + dynamic_pr_debug("%s: " fmt, __func__, ##__VA_ARGS__); \ +} while (0) +#else +#define ffs_log(fmt, ...) \ + ipc_log_string(ffs->ipc_log, "%s: " fmt, __func__, ##__VA_ARGS__) +#endif +#else +static inline void ffs_ipc_log_create(struct ffs_data *ffs, + const char *dev_name) { } +static inline void ffs_ipc_log_destroy(struct ffs_data *ffs) { } +#define ffs_log(fmt, ...) \ + pr_debug("%s: %s: " fmt, ffs->dev_name, __func__, ##__VA_ARGS__) +#endif + /* Reference counter handling */ static void ffs_data_get(struct ffs_data *ffs); static void ffs_data_put(struct ffs_data *ffs); @@ -282,6 +317,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; @@ -306,11 +344,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); @@ -331,6 +376,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; @@ -459,6 +507,9 @@ done_spin: break; } + ffs_log("exit:ret %zd state %d setup_state %d flags %lu", ret, + ffs->state, ffs->setup_state, ffs->flags); + mutex_unlock(&ffs->mutex); return ret; } @@ -493,6 +544,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; @@ -508,6 +563,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; @@ -597,6 +655,9 @@ 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; @@ -608,6 +669,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; @@ -623,6 +687,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; @@ -636,6 +703,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; @@ -654,6 +724,9 @@ static __poll_t ffs_ep0_poll(struct file *file, poll_table *wait) __poll_t mask = EPOLLWRNORM; 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); @@ -684,6 +757,8 @@ static __poll_t ffs_ep0_poll(struct file *file, poll_table *wait) break; } + ffs_log("exit: mask %u", mask); + mutex_unlock(&ffs->mutex); return mask; @@ -819,10 +894,13 @@ static void ffs_user_copy_worker(struct work_struct *work) { struct ffs_io_data *io_data = container_of(work, struct ffs_io_data, work); + struct ffs_data *ffs = io_data->ffs; int ret = io_data->req->status ? io_data->req->status : io_data->req->actual; bool kiocb_has_eventfd = io_data->kiocb->ki_flags & IOCB_EVENTFD; + ffs_log("enter: ret %d for %s", ret, io_data->read ? "read" : "write"); + if (io_data->read && ret > 0) { mm_segment_t oldfs = get_fs(); @@ -844,6 +922,8 @@ static void ffs_user_copy_worker(struct work_struct *work) kfree(io_data->to_free); ffs_free_buffer(io_data); kfree(io_data); + + ffs_log("exit"); } static void ffs_epfile_async_io_complete(struct usb_ep *_ep, @@ -854,6 +934,8 @@ static void ffs_epfile_async_io_complete(struct usb_ep *_ep, ENTER(); + ffs_log("enter"); + INIT_WORK(&io_data->work, ffs_user_copy_worker); queue_work(ffs->io_completion_wq, &io_data->work); } @@ -943,12 +1025,15 @@ static ssize_t __ffs_epfile_read_data(struct ffs_epfile *epfile, static ssize_t ffs_epfile_io(struct file *file, struct ffs_io_data *io_data) { struct ffs_epfile *epfile = file->private_data; + struct ffs_data *ffs = epfile->ffs; struct usb_request *req; struct ffs_ep *ep; char *data = NULL; ssize_t ret, data_len = -EINVAL; int halt; + ffs_log("enter: %s", epfile->name); + /* Are we still active? */ if (WARN_ON(epfile->ffs->state != FFS_ACTIVE)) return -ENODEV; @@ -1076,6 +1161,8 @@ static ssize_t ffs_epfile_io(struct file *file, struct ffs_io_data *io_data) spin_unlock_irq(&epfile->ffs->eps_lock); + ffs_log("queued %zd bytes on %s", data_len, epfile->name); + if (unlikely(wait_for_completion_interruptible(&done))) { /* * To avoid race condition with ffs_epfile_io_complete, @@ -1088,6 +1175,9 @@ static ssize_t ffs_epfile_io(struct file *file, struct ffs_io_data *io_data) interrupted = ep->status < 0; } + ffs_log("%s:ep status %d for req %pK", epfile->name, ep->status, + req); + if (interrupted) ret = -EINTR; else if (io_data->read && ep->status > 0) @@ -1122,6 +1212,8 @@ static ssize_t ffs_epfile_io(struct file *file, struct ffs_io_data *io_data) goto error_lock; } + ffs_log("queued %zd bytes on %s", data_len, epfile->name); + ret = -EIOCBQUEUED; /* * Do not kfree the buffer in this function. It will be freed @@ -1137,6 +1229,9 @@ error_mutex: error: if (ret != -EIOCBQUEUED) /* don't free if there is iocb queued */ ffs_free_buffer(io_data); + + ffs_log("exit: %s ret %zd", epfile->name, ret); + return ret; } @@ -1144,9 +1239,14 @@ static int ffs_epfile_open(struct inode *inode, struct file *file) { struct ffs_epfile *epfile = inode->i_private; + struct ffs_data *ffs = epfile->ffs; ENTER(); + ffs_log("%s: state %d setup_state %d flag %lu", epfile->name, + epfile->ffs->state, epfile->ffs->setup_state, + epfile->ffs->flags); + if (WARN_ON(epfile->ffs->state != FFS_ACTIVE)) return -ENODEV; @@ -1160,10 +1260,14 @@ static int ffs_aio_cancel(struct kiocb *kiocb) { struct ffs_io_data *io_data = kiocb->private; struct ffs_epfile *epfile = kiocb->ki_filp->private_data; + struct ffs_data *ffs = epfile->ffs; int value; 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)) @@ -1173,16 +1277,22 @@ static int ffs_aio_cancel(struct kiocb *kiocb) spin_unlock_irq(&epfile->ffs->eps_lock); + ffs_log("exit: value %d", value); + return value; } static ssize_t ffs_epfile_write_iter(struct kiocb *kiocb, struct iov_iter *from) { + struct ffs_epfile *epfile = kiocb->ki_filp->private_data; + struct ffs_data *ffs = epfile->ffs; struct ffs_io_data io_data, *p = &io_data; ssize_t res; ENTER(); + ffs_log("enter"); + if (!is_sync_kiocb(kiocb)) { p = kzalloc(sizeof(io_data), GFP_KERNEL); if (unlikely(!p)) @@ -1210,16 +1320,23 @@ static ssize_t ffs_epfile_write_iter(struct kiocb *kiocb, struct iov_iter *from) kfree(p); else *from = p->data; + + ffs_log("exit: ret %zd", res); + return res; } static ssize_t ffs_epfile_read_iter(struct kiocb *kiocb, struct iov_iter *to) { + struct ffs_epfile *epfile = kiocb->ki_filp->private_data; + struct ffs_data *ffs = epfile->ffs; struct ffs_io_data io_data, *p = &io_data; ssize_t res; ENTER(); + ffs_log("enter"); + if (!is_sync_kiocb(kiocb)) { p = kzalloc(sizeof(io_data), GFP_KERNEL); if (unlikely(!p)) @@ -1259,6 +1376,9 @@ static ssize_t ffs_epfile_read_iter(struct kiocb *kiocb, struct iov_iter *to) } else { *to = p->data; } + + ffs_log("exit: ret %zd", res); + return res; } @@ -1266,10 +1386,15 @@ static int ffs_epfile_release(struct inode *inode, struct file *file) { struct ffs_epfile *epfile = inode->i_private; + struct ffs_data *ffs = epfile->ffs; ENTER(); __ffs_epfile_read_buffer_free(epfile); + ffs_log("%s: state %d setup_state %d flag %lu", epfile->name, + epfile->ffs->state, epfile->ffs->setup_state, + epfile->ffs->flags); + ffs_data_closed(epfile->ffs); return 0; @@ -1279,11 +1404,16 @@ static long ffs_epfile_ioctl(struct file *file, unsigned code, unsigned long value) { struct ffs_epfile *epfile = file->private_data; + struct ffs_data *ffs = epfile->ffs; struct ffs_ep *ep; int ret; ENTER(); + ffs_log("%s: code 0x%08x value %#lx state %d setup_state %d flag %lu", + epfile->name, code, value, epfile->ffs->state, + epfile->ffs->setup_state, epfile->ffs->flags); + if (WARN_ON(epfile->ffs->state != FFS_ACTIVE)) return -ENODEV; @@ -1351,6 +1481,8 @@ static long ffs_epfile_ioctl(struct file *file, unsigned code, } spin_unlock_irq(&epfile->ffs->eps_lock); + ffs_log("exit: %s: ret %d\n", epfile->name, ret); + return ret; } @@ -1389,10 +1521,13 @@ ffs_sb_make_inode(struct super_block *sb, void *data, const struct inode_operations *iops, struct ffs_file_perms *perms) { + struct ffs_data *ffs = sb->s_fs_info; struct inode *inode; ENTER(); + ffs_log("enter"); + inode = new_inode(sb); if (likely(inode)) { @@ -1426,6 +1561,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; @@ -1462,6 +1599,8 @@ static int ffs_sb_fill(struct super_block *sb, struct fs_context *fc) ENTER(); + ffs_log("enter"); + ffs->sb = sb; data->ffs_data = NULL; sb->s_fs_info = ffs; @@ -1694,6 +1833,8 @@ static void ffs_data_get(struct ffs_data *ffs) { ENTER(); + ffs_log("ref %u", refcount_read(&ffs->ref)); + refcount_inc(&ffs->ref); } @@ -1701,6 +1842,10 @@ static void ffs_data_opened(struct ffs_data *ffs) { ENTER(); + ffs_log("enter: state %d setup_state %d flag %lu opened %d ref %d", + ffs->state, ffs->setup_state, ffs->flags, + atomic_read(&ffs->opened), refcount_read(&ffs->ref)); + refcount_inc(&ffs->ref); if (atomic_add_return(1, &ffs->opened) == 1 && ffs->state == FFS_DEACTIVATED) { @@ -1713,6 +1858,8 @@ static void ffs_data_put(struct ffs_data *ffs) { ENTER(); + ffs_log("ref %u", refcount_read(&ffs->ref)); + if (unlikely(refcount_dec_and_test(&ffs->ref))) { pr_info("%s(): freeing\n", __func__); ffs_data_clear(ffs); @@ -1720,6 +1867,7 @@ static void ffs_data_put(struct ffs_data *ffs) waitqueue_active(&ffs->ep0req_completion.wait) || waitqueue_active(&ffs->wait)); destroy_workqueue(ffs->io_completion_wq); + ffs_ipc_log_destroy(ffs); kfree(ffs->dev_name); kfree(ffs); } @@ -1729,6 +1877,9 @@ static void ffs_data_closed(struct ffs_data *ffs) { ENTER(); + ffs_log("state %d setup_state %d flag %lu opened %d", ffs->state, + ffs->setup_state, ffs->flags, atomic_read(&ffs->opened)); + if (atomic_dec_and_test(&ffs->opened)) { if (ffs->no_disconnect) { ffs->state = FFS_DEACTIVATED; @@ -1754,10 +1905,18 @@ static void ffs_data_closed(struct ffs_data *ffs) static struct ffs_data *ffs_data_new(const char *dev_name) { + struct ffs_dev *ffs_dev; struct ffs_data *ffs = kzalloc(sizeof *ffs, GFP_KERNEL); if (unlikely(!ffs)) return NULL; + ffs_dev = _ffs_find_dev(dev_name); + if (ffs_dev && ffs_dev->mounted) { + pr_info("%s(): %s Already mounted\n", __func__, dev_name); + kfree(ffs); + return ERR_PTR(-EBUSY); + } + ENTER(); ffs->io_completion_wq = alloc_ordered_workqueue("%s", 0, dev_name); @@ -1778,6 +1937,8 @@ static struct ffs_data *ffs_data_new(const char *dev_name) /* XXX REVISIT need to update it in some places, or do we? */ ffs->ev.can_stall = 1; + ffs_ipc_log_create(ffs, dev_name); + return ffs; } @@ -1785,6 +1946,11 @@ 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= %pK, ffs->flags= %lu\n", + __func__, ffs->gadget, ffs->flags); ffs_closed(ffs); BUG_ON(ffs->gadget); @@ -1804,6 +1970,9 @@ 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; @@ -1836,6 +2005,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; @@ -1874,6 +2046,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 %pK\n", + ffs->state, ffs->setup_state, ffs->flags, ffs->gadget); ffs_data_put(ffs); } } @@ -1885,6 +2059,9 @@ static int ffs_epfiles_create(struct ffs_data *ffs) ENTER(); + ffs_log("enter: eps_count %u state %d setup_state %d flag %lu", + ffs->eps_count, ffs->state, ffs->setup_state, ffs->flags); + count = ffs->eps_count; epfiles = kcalloc(count, sizeof(*epfiles), GFP_KERNEL); if (!epfiles) @@ -1914,9 +2091,12 @@ static int ffs_epfiles_create(struct ffs_data *ffs) static void ffs_epfiles_destroy(struct ffs_epfile *epfiles, unsigned count) { struct ffs_epfile *epfile = epfiles; + struct ffs_data *ffs = epfiles->ffs; ENTER(); + ffs_log("enter: count %u", count); + for (; count; --count, ++epfile) { BUG_ON(mutex_is_locked(&epfile->mutex)); if (epfile->dentry) { @@ -1932,10 +2112,14 @@ static void ffs_epfiles_destroy(struct ffs_epfile *epfiles, unsigned count) static void ffs_func_eps_disable(struct ffs_function *func) { struct ffs_ep *ep = func->eps; + struct ffs_data *ffs = func->ffs; struct ffs_epfile *epfile = func->ffs->epfiles; 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); while (count--) { /* pending requests get nuked */ @@ -1961,6 +2145,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); while(count--) { ep->ep->driver_data = ep; @@ -1977,7 +2164,9 @@ static int ffs_func_eps_enable(struct ffs_function *func) epfile->ep = ep; epfile->in = usb_endpoint_dir_in(ep->ep->desc); epfile->isoc = usb_endpoint_xfer_isoc(ep->ep->desc); + ffs_log("usb_ep_enable %s", ep->ep->name); } else { + ffs_log("usb_ep_enable %s ret %d", ep->ep->name, ret); break; } @@ -2018,7 +2207,8 @@ typedef int (*ffs_os_desc_callback)(enum ffs_os_desc_type entity, struct usb_os_desc_header *h, void *data, unsigned len, void *priv); -static int __must_check ffs_do_single_desc(char *data, unsigned len, +static int __must_check ffs_do_single_desc(struct ffs_data *ffs, + char *data, unsigned int len, ffs_entity_callback entity, void *priv, int *current_class) { @@ -2028,6 +2218,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"); @@ -2156,10 +2348,13 @@ inv_length: #undef __entity_check_STRING #undef __entity_check_ENDPOINT + ffs_log("exit: desc type %d length %d", _ds->bDescriptorType, length); + return length; } -static int __must_check ffs_do_descs(unsigned count, char *data, unsigned len, +static int __must_check ffs_do_descs(struct ffs_data *ffs, unsigned int count, + char *data, unsigned int len, ffs_entity_callback entity, void *priv) { const unsigned _len = len; @@ -2168,6 +2363,8 @@ static int __must_check ffs_do_descs(unsigned count, char *data, unsigned len, ENTER(); + ffs_log("enter: len %u", len); + for (;;) { int ret; @@ -2185,7 +2382,7 @@ static int __must_check ffs_do_descs(unsigned count, char *data, unsigned len, if (!data) return _len - len; - ret = ffs_do_single_desc(data, len, entity, priv, + ret = ffs_do_single_desc(ffs, data, len, entity, priv, ¤t_class); if (unlikely(ret < 0)) { pr_debug("%s returns %d\n", __func__, ret); @@ -2203,10 +2400,13 @@ static int __ffs_data_do_entity(enum ffs_entity_type type, void *priv) { struct ffs_desc_helper *helper = priv; + struct ffs_data *ffs = helper->ffs; struct usb_endpoint_descriptor *d; ENTER(); + ffs_log("enter: type %u", type); + switch (type) { case FFS_DESCRIPTOR: break; @@ -2248,12 +2448,15 @@ static int __ffs_data_do_entity(enum ffs_entity_type type, return 0; } -static int __ffs_do_os_desc_header(enum ffs_os_desc_type *next_type, +static int __ffs_do_os_desc_header(struct ffs_data *ffs, + enum ffs_os_desc_type *next_type, struct usb_os_desc_header *desc) { u16 bcd_version = le16_to_cpu(desc->bcdVersion); u16 w_index = le16_to_cpu(desc->wIndex); + ffs_log("enter: bcd:%x w_index:%d", bcd_version, w_index); + if (bcd_version != 1) { pr_vdebug("unsupported os descriptors version: %d", bcd_version); @@ -2278,7 +2481,8 @@ static int __ffs_do_os_desc_header(enum ffs_os_desc_type *next_type, * Process all extended compatibility/extended property descriptors * of a feature descriptor */ -static int __must_check ffs_do_single_os_desc(char *data, unsigned len, +static int __must_check ffs_do_single_os_desc(struct ffs_data *ffs, + char *data, unsigned int len, enum ffs_os_desc_type type, u16 feature_count, ffs_os_desc_callback entity, @@ -2290,11 +2494,13 @@ 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); if (unlikely(ret < 0)) { - pr_debug("bad OS descriptor, type: %d\n", type); + ffs_log("bad OS descriptor, type: %d\n", type); return ret; } data += ret; @@ -2304,8 +2510,9 @@ static int __must_check ffs_do_single_os_desc(char *data, unsigned len, } /* Process a number of complete Feature Descriptors (Ext Compat or Ext Prop) */ -static int __must_check ffs_do_os_descs(unsigned count, - char *data, unsigned len, +static int __must_check ffs_do_os_descs(struct ffs_data *ffs, + unsigned int count, char *data, + unsigned int len, ffs_os_desc_callback entity, void *priv) { const unsigned _len = len; @@ -2313,6 +2520,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; @@ -2332,9 +2541,9 @@ static int __must_check ffs_do_os_descs(unsigned count, if (le32_to_cpu(desc->dwLength) > len) return -EINVAL; - ret = __ffs_do_os_desc_header(&type, desc); + ret = __ffs_do_os_desc_header(ffs, &type, desc); if (unlikely(ret < 0)) { - pr_debug("entity OS_DESCRIPTOR(%02lx); ret = %d\n", + ffs_log("entity OS_DESCRIPTOR(%02lx); ret = %d\n", num, ret); return ret; } @@ -2352,10 +2561,10 @@ static int __must_check ffs_do_os_descs(unsigned count, * Process all function/property descriptors * of this Feature Descriptor */ - ret = ffs_do_single_os_desc(data, len, type, + ret = ffs_do_single_os_desc(ffs, data, len, type, feature_count, entity, priv, desc); if (unlikely(ret < 0)) { - pr_debug("%s returns %d\n", __func__, ret); + ffs_log("%s returns %d\n", __func__, ret); return ret; } @@ -2377,6 +2586,8 @@ static int __ffs_data_do_os_desc(enum ffs_os_desc_type type, ENTER(); + ffs_log("enter: type %d len %u", type, len); + switch (type) { case FFS_OS_DESC_EXT_COMPAT: { struct usb_ext_compat_desc *d = data; @@ -2454,6 +2665,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; @@ -2527,7 +2740,7 @@ static int __ffs_data_got_descs(struct ffs_data *ffs, continue; helper.interfaces_count = 0; helper.eps_count = 0; - ret = ffs_do_descs(counts[i], data, len, + ret = ffs_do_descs(ffs, counts[i], data, len, __ffs_data_do_entity, &helper); if (ret < 0) goto error; @@ -2548,7 +2761,7 @@ static int __ffs_data_got_descs(struct ffs_data *ffs, len -= ret; } if (os_descs_count) { - ret = ffs_do_os_descs(os_descs_count, data, len, + ret = ffs_do_os_descs(ffs, os_descs_count, data, len, __ffs_data_do_os_desc, ffs); if (ret < 0) goto error; @@ -2586,6 +2799,8 @@ static int __ffs_data_got_strings(struct ffs_data *ffs, ENTER(); + ffs_log("enter: len %zu", len); + if (unlikely(len < 16 || get_unaligned_le32(data) != FUNCTIONFS_STRINGS_MAGIC || get_unaligned_le32(data + 4) != len)) @@ -2718,6 +2933,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 * @@ -2806,11 +3024,14 @@ static int __ffs_func_bind_do_descs(enum ffs_entity_type type, u8 *valuep, { struct usb_endpoint_descriptor *ds = (void *)desc; struct ffs_function *func = priv; + struct ffs_data *ffs = func->ffs; struct ffs_ep *ffs_ep; unsigned ep_desc_id; int idx; static const char *speed_names[] = { "full", "high", "super" }; + ffs_log("enter"); + if (type != FFS_DESCRIPTOR) return 0; @@ -2905,9 +3126,12 @@ static int __ffs_func_bind_do_nums(enum ffs_entity_type type, u8 *valuep, void *priv) { struct ffs_function *func = priv; + struct ffs_data *ffs = func->ffs; unsigned idx; u8 newValue; + ffs_log("enter: type %d", type); + switch (type) { default: case FFS_DESCRIPTOR: @@ -2952,6 +3176,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; } @@ -2960,8 +3187,11 @@ static int __ffs_func_bind_do_os_desc(enum ffs_os_desc_type type, unsigned len, void *priv) { struct ffs_function *func = priv; + struct ffs_data *ffs = func->ffs; u8 length = 0; + ffs_log("enter: type %d", type); + switch (type) { case FFS_OS_DESC_EXT_COMPAT: { struct usb_ext_compat_desc *desc = data; @@ -3040,6 +3270,7 @@ static inline struct f_fs_opts *ffs_do_functionfs_bind(struct usb_function *f, struct ffs_function *func = ffs_func_from_usb(f); struct f_fs_opts *ffs_opts = container_of(f->fi, struct f_fs_opts, func_inst); + struct ffs_data *ffs = ffs_opts->dev->ffs_data; int ret; ENTER(); @@ -3072,8 +3303,10 @@ static inline struct f_fs_opts *ffs_do_functionfs_bind(struct usb_function *f, */ if (!ffs_opts->refcnt) { ret = functionfs_bind(func->ffs, c->cdev); - if (ret) + if (ret) { + ffs_log("functionfs_bind returned %d", ret); return ERR_PTR(ret); + } } ffs_opts->refcnt++; func->function.strings = func->ffs->stringtabs; @@ -3121,6 +3354,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; @@ -3158,7 +3394,7 @@ static int _ffs_func_bind(struct usb_configuration *c, */ if (likely(full)) { func->function.fs_descriptors = vla_ptr(vlabuf, d, fs_descs); - fs_len = ffs_do_descs(ffs->fs_descs_count, + fs_len = ffs_do_descs(ffs, ffs->fs_descs_count, vla_ptr(vlabuf, d, raw_descs), d_raw_descs__sz, __ffs_func_bind_do_descs, func); @@ -3172,7 +3408,7 @@ static int _ffs_func_bind(struct usb_configuration *c, if (likely(high)) { func->function.hs_descriptors = vla_ptr(vlabuf, d, hs_descs); - hs_len = ffs_do_descs(ffs->hs_descs_count, + hs_len = ffs_do_descs(ffs, ffs->hs_descs_count, vla_ptr(vlabuf, d, raw_descs) + fs_len, d_raw_descs__sz - fs_len, __ffs_func_bind_do_descs, func); @@ -3186,7 +3422,7 @@ static int _ffs_func_bind(struct usb_configuration *c, if (likely(super)) { func->function.ss_descriptors = vla_ptr(vlabuf, d, ss_descs); - ss_len = ffs_do_descs(ffs->ss_descs_count, + ss_len = ffs_do_descs(ffs, ffs->ss_descs_count, vla_ptr(vlabuf, d, raw_descs) + fs_len + hs_len, d_raw_descs__sz - fs_len - hs_len, __ffs_func_bind_do_descs, func); @@ -3203,7 +3439,7 @@ static int _ffs_func_bind(struct usb_configuration *c, * endpoint numbers rewriting. We can do that in one go * now. */ - ret = ffs_do_descs(ffs->fs_descs_count + + ret = ffs_do_descs(ffs, ffs->fs_descs_count + (high ? ffs->hs_descs_count : 0) + (super ? ffs->ss_descs_count : 0), vla_ptr(vlabuf, d, raw_descs), d_raw_descs__sz, @@ -3223,7 +3459,7 @@ static int _ffs_func_bind(struct usb_configuration *c, vla_ptr(vlabuf, d, ext_compat) + i * 16; INIT_LIST_HEAD(&desc->ext_prop); } - ret = ffs_do_os_descs(ffs->ms_os_descs_count, + ret = ffs_do_os_descs(ffs, ffs->ms_os_descs_count, vla_ptr(vlabuf, d, raw_descs) + fs_len + hs_len + ss_len, d_raw_descs__sz - fs_len - hs_len - @@ -3241,6 +3477,7 @@ static int _ffs_func_bind(struct usb_configuration *c, error: /* XXX Do we need to release all claimed endpoints here? */ + ffs_log("exit: ret %d", ret); return ret; } @@ -3249,11 +3486,14 @@ static int ffs_func_bind(struct usb_configuration *c, { struct f_fs_opts *ffs_opts = ffs_do_functionfs_bind(f, c); struct ffs_function *func = ffs_func_from_usb(f); + struct ffs_data *ffs = func->ffs; int ret; if (IS_ERR(ffs_opts)) return PTR_ERR(ffs_opts); + ffs_log("enter"); + ret = _ffs_func_bind(c, f); if (ret && !--ffs_opts->refcnt) functionfs_unbind(func->ffs); @@ -3268,6 +3508,9 @@ 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); } @@ -3278,6 +3521,8 @@ static int ffs_func_set_alt(struct usb_function *f, struct ffs_data *ffs = func->ffs; int ret = 0, intf; + ffs_log("enter: alt %d", (int)alt); + if (alt != (unsigned)-1) { intf = ffs_func_revmap_intf(func, interface); if (unlikely(intf < 0)) @@ -3312,6 +3557,10 @@ static int ffs_func_set_alt(struct usb_function *f, 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); } @@ -3331,6 +3580,11 @@ static int ffs_func_setup(struct usb_function *f, pr_vdebug("creq->wIndex = %04x\n", le16_to_cpu(creq->wIndex)); pr_vdebug("creq->wLength = %04x\n", le16_to_cpu(creq->wLength)); + ffs_log("enter: state %d reqtype=%02x req=%02x wv=%04x wi=%04x wl=%04x", + ffs->state, creq->bRequestType, creq->bRequest, + le16_to_cpu(creq->wValue), le16_to_cpu(creq->wIndex), + le16_to_cpu(creq->wLength)); + /* * Most requests directed to interface go through here * (notable exceptions are set/get interface) so we need to @@ -3399,13 +3653,23 @@ static bool ffs_func_req_match(struct usb_function *f, static void ffs_func_suspend(struct usb_function *f) { + struct ffs_data *ffs = ffs_func_from_usb(f)->ffs; + ENTER(); + + ffs_log("enter"); + ffs_event_add(ffs_func_from_usb(f)->ffs, FUNCTIONFS_SUSPEND); } static void ffs_func_resume(struct usb_function *f) { + struct ffs_data *ffs = ffs_func_from_usb(f)->ffs; + ENTER(); + + ffs_log("enter"); + ffs_event_add(ffs_func_from_usb(f)->ffs, FUNCTIONFS_RESUME); } @@ -3478,7 +3742,9 @@ static struct ffs_dev *_ffs_find_dev(const char *name) if (dev) return dev; - return _ffs_do_find_dev(name); + dev = _ffs_do_find_dev(name); + + return dev; } /* Configfs support *********************************************************/ @@ -3569,6 +3835,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; @@ -3598,6 +3868,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) @@ -3751,6 +4024,9 @@ static int ffs_ready(struct ffs_data *ffs) int ret = 0; ENTER(); + + ffs_log("enter"); + ffs_dev_lock(); ffs_obj = ffs->private_data; @@ -3775,6 +4051,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: ret %d", ret); + return ret; } @@ -3785,6 +4064,9 @@ static void ffs_closed(struct ffs_data *ffs) struct config_item *ci; ENTER(); + + ffs_log("enter"); + ffs_dev_lock(); ffs_obj = ffs->private_data; @@ -3810,11 +4092,16 @@ static void ffs_closed(struct ffs_data *ffs) ci = opts->func_inst.group.cg_item.ci_parent->ci_parent; ffs_dev_unlock(); - if (test_bit(FFS_FL_BOUND, &ffs->flags)) + if (test_bit(FFS_FL_BOUND, &ffs->flags)) { unregister_gadget_item(ci); + ffs_log("unreg gadget done"); + } + return; done: ffs_dev_unlock(); + + ffs_log("exit error"); } /* Misc helper functions ****************************************************/ diff --git a/drivers/usb/gadget/function/u_fs.h b/drivers/usb/gadget/function/u_fs.h index f9b0cf67360d..4a5a60592b36 100644 --- a/drivers/usb/gadget/function/u_fs.h +++ b/drivers/usb/gadget/function/u_fs.h @@ -18,6 +18,7 @@ #include #include #include +#include #ifdef VERBOSE_DEBUG #ifndef pr_vdebug @@ -285,6 +286,9 @@ struct ffs_data { * destroyed by ffs_epfiles_destroy(). */ struct ffs_epfile *epfiles; +#ifdef CONFIG_USB_F_FS_IPC_LOGGING + void *ipc_log; +#endif };