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 };