⬢ DragonFlyBSD Kernel Audit
DF-5424 / uftdi_cfgstall_harness.c
← back to finding ↓ download raw
/*
 * DF-5424 KLD harness -- production-code demonstration of the uftdi (FTDI
 * FT8U232AM/SIO) cfg-chain synchronous-request stall.
 *
 * WHAT IT PROVES (with the real in-kernel u4b usb_process machinery, the
 * same taskqueue ucom's cfg callbacks run on):
 *
 *   uftdi_cfg_param() (uftdi.c:665-703) chains 3 synchronous EP0 vendor
 *   control requests per tcsetattr:
 *     uftdi.c:680-686  FTDI_SIO_SET_BAUD_RATE -> 1 write
 *     uftdi.c:688-694  FTDI_SIO_SET_DATA      -> 1 write
 *     uftdi.c:696-702  FTDI_SIO_SET_FLOW_CTRL -> 1 write
 *   uftdi_cfg_open() (uftdi.c:354-387) adds 2 more per open(2):
 *     uftdi.c:364-370  FTDI_SIO_RESET         -> 1 write
 *     uftdi.c:374-380  FTDI_SIO_SET_FLOW_CTRL -> 1 write
 *   plus set_dtr/set_rts/set_break each add 1 more (uftdi.c:494-554).
 *   Every request is ucom_cfg_do_request(sc->sc_udev, ..., 1000) -- the
 *   macro expands to usbd_do_request_proc(..., timo=1000) (usb_serial.h:220)
 *   and uftdi DISCARDS the usb_error_t return everywhere, so no chain step
 *   ever aborts.  A control transfer's data stage may be NAK'd by the
 *   device for as long as it likes: a silent evil FTDI (probe is a pure
 *   VID/PID table match, uftdi.c:205-269) makes each request eat its full
 *   1000 ms timeout (usb_request.c:642-644 WXFER loop, 699-704 timeout)
 *   and the chain marches on; a device answering just-under-timeout makes
 *   every request *succeed* at ~999 ms with no error to abort on.
 *
 *   The chain runs on sc_super_ucom.sc_tq (per-adapter ucom taskqueue,
 *   usb_serial.c:322).  close(2) is SYNCHRONOUS against that queue:
 *   ucom_close() -> ucom_queue_command(ucom_cfg_close) -> usb_proc_mwait()
 *   (usb_serial.c:671-672, 955-957), uninterruptible cv_wait
 *   (usb_process.c:385-393) while a message stays head-of-queue for the
 *   duration of its callback (usb_process.c:146-158).  Unplug mid-cycle
 *   stalls the USB hub event thread the same way via ucom_detach() ->
 *   usb_proc_drain() (usb_serial.c:394).  Every tcsetattr of an open tty
 *   re-queues the param task (ucom's sc_param_task[2] double buffer,
 *   usb_serial.c:1691-1693), so a user driving the tty multiplies the
 *   occupancy: 2 outstanding param tasks = ~8.2 s of uninterruptible
 *   close(2)/unplug block.
 *
 *   => one open(2) with the evil device costs ~5.2 s of tq occupancy
 *      (2 x 1000 + hz/10 pause + 3 x 1000 + hz/10 pause); one tcsetattr
 *      ~3.1 s; two queued tcsetattrs block a closer ~8.2 s.
 *
 * PHASE A (baseline): queue the open(2) chain (cfg_open: 2 x 1000 ms +
 *   hz/10 pause) then ONE param-chain task (3 x lksleep("WXFER", 1000 ms)
 *   -- the exact production per-request cost of a request the device
 *   stretches past its timeout -- + hz/10 pause), then what ucom_close()
 *   does: queue cfg_close + usb_proc_mwait().  Measure the closer's block
 *   time.  EXPECT ~5100-5400 ms.
 *
 * PHASE A2 (amplification): open + queue the param task TWICE (two
 *   tcsetattr equivalent, production double-buffer shape) then the closer.
 *   EXPECT ~8200-8500 ms.
 *
 * PHASE B (fix mechanism from fix.diff: abort each cfg chain on its first
 *   failed request): silent evil device -> request #1 of each chain times
 *   out at 1000 ms -> error propagated -> chain aborts.
 *   EXPECT ~2100-2400 ms.
 */
#include <sys/param.h>
#include <sys/systm.h>
#include <sys/kernel.h>
#include <sys/module.h>
#include <sys/lock.h>
#include <sys/condvar.h>
#include <sys/time.h>
#include <sys/types.h>

#include <sys/bus.h>
#include <bus/u4b/usb.h>
#include <bus/u4b/usbdi.h>
#include <bus/u4b/usb_process.h>

#define	HX_PARAM_REQS	3	/* uftdi.c:680..702 per-tcsetattr chain */
#define	HX_OPEN_REQS	2	/* uftdi.c:364..380 first-open chain */
#define	HX_REQ_MS	1000	/* uftdi.c:370/380/686/694/702 timeout */
#define	HX_REQ_MS_FIXED	HX_REQ_MS	/* fix keeps timeout, aborts on error */

static struct lock hx_lock;		/* stands in for sc->sc_lock */
static struct usb_process hx_tq;	/* sc_super_ucom.sc_tq (usb_serial.c:322) */

struct hx_msg {
	struct usb_proc_msg hdr;
};
static struct hx_msg hx_param[2];	/* ucom sc_param_task[2] double buffer */
static struct hx_msg hx_open_msg[2];	/* ucom sc_open_task[2] */
static struct hx_close_msg {
	struct usb_proc_msg hdr;
} hx_close[2];				/* ucom sc_close_task[2] */

static int hx_fixed;			/* phase B: error-abort fix mechanism */
static int hx_aborted;

static int64_t
hx_ms(struct timeval *t0, struct timeval *t1)
{
	return ((int64_t)(t1->tv_sec - t0->tv_sec) * 1000 +
	    (t1->tv_usec - t0->tv_usec) / 1000);
}

/*
 * One ucom_cfg_do_request() (uftdi.c:369-370 etc.) against the silent evil
 * FTDI: the device never answers the data stage, so the requester sleeps
 * in the "WXFER" loop until the 1000 ms timeout fires (usb_request.c:642-644,
 * 699-704) and the request returns USB_ERR_TIMEOUT -- which production
 * uftdi discards (macro result unused at every call site).
 */
static int
hx_one_request(void)
{
	lksleep(&hx_lock, &hx_lock, 0, "WXFER", USB_MS_TO_TICKS(HX_REQ_MS_FIXED));
	return (0);	/* production: even a timeout is ignored */
}

/* uftdi_cfg_param()'s 3-request chain (uftdi.c:665-703), runs on sc_tq */
static void
hx_cfg_param(struct usb_proc_msg *pm)
{
	int i;

	kprintf("HX5424: cfg-param task: enter, %d x %d ms sync EP0 requests%s\n",
	    HX_PARAM_REQS, HX_REQ_MS_FIXED,
	    hx_fixed ? " (fix: abort on first error)" : "");
	hx_aborted = 0;
	for (i = 0; i < HX_PARAM_REQS; ++i) {
		hx_one_request();	/* the request that times out */
		if (hx_fixed) {
			/*
			 * fix.diff mechanism: cfg request returns the error,
			 * chain bails on first failure.  With the silent
			 * device request #1 fails after its timeout.
			 */
			kprintf("HX5424: cfg-param: request %d/%d failed "
			    "(USB_ERR_TIMEOUT) -> abort chain (fixed)\n",
			    i + 1, HX_PARAM_REQS);
			hx_aborted = 1;
			break;
		}
	}
	/* ucom_cfg_param()'s trailing pause, usb_serial.c:1636 */
	usb_pause_mtx(&hx_lock, hz / 10);
	kprintf("HX5424: cfg-param task: leave (%d/%d requests issued)\n",
	    hx_aborted ? 1 : HX_PARAM_REQS, HX_PARAM_REQS);
}

/* uftdi_cfg_open()'s 2-request chain (uftdi.c:354-387), runs on sc_tq */
static void
hx_cfg_open(struct usb_proc_msg *pm)
{
	int i;

	kprintf("HX5424: cfg-open task: enter, %d x %d ms sync EP0 requests%s\n",
	    HX_OPEN_REQS, HX_REQ_MS_FIXED,
	    hx_fixed ? " (fix: abort on first error)" : "");
	for (i = 0; i < HX_OPEN_REQS; ++i) {
		hx_one_request();	/* the request that times out */
		if (hx_fixed) {
			kprintf("HX5424: cfg-open: request %d/%d failed "
			    "(USB_ERR_TIMEOUT) -> abort chain (fixed)\n",
			    i + 1, HX_OPEN_REQS);
			break;
		}
	}
	/* ucom_cfg_open()'s trailing pause, usb_serial.c:777 */
	usb_pause_mtx(&hx_lock, hz / 10);
	kprintf("HX5424: cfg-open task: leave\n");
}

/* ucom_cfg_close() (fast for uftdi: no ucom_cfg_close callback) */
static void
hx_cfg_close(struct usb_proc_msg *pm)
{
	kprintf("HX5424: cfg-close task: enter+leave (uftdi has no "
	    "ucom_cfg_close callback)\n");
}

/*
 * Exactly ucom_close()'s synchronous close (usb_serial.c:671-672 + 955-957):
 * queue cfg_close behind the running/queued cfg_param task(s) and mwait
 * uninterruptibly (usb_process.c:385-393).
 */
static int64_t
hx_closer_thread(int phase, int nparam)
{
	struct timeval t0, t1;
	char tag = phase == 2 ? 'B' : (nparam > 1 ? '2' : 'A');

	/* the tcsetattr(s) queued cfg_param; the first starts running */
	tsleep(&hx_tq, 0, "hxlead", hz / 10);	/* 100 ms into the chain */

	kprintf("HX5424[%c]: closer: queue cfg_close + usb_proc_mwait() "
	    "(uninterruptible, usb_serial.c:671-672) behind %d param task(s)\n",
	    tag, nparam);
	microtime(&t0);
	lockmgr(&hx_lock, LK_EXCLUSIVE);
	if (!usb_proc_is_gone(&hx_tq)) {
		struct hx_close_msg *m;

		m = usb_proc_msignal(&hx_tq, &hx_close[0], &hx_close[1]);
		m->hdr.pm_callback = &hx_cfg_close;
		/* usb_serial.c:671-672 */
		usb_proc_mwait(&hx_tq, &hx_close[0], &hx_close[1]);
	}
	lockmgr(&hx_lock, LK_RELEASE);
	microtime(&t1);
	kprintf("HX5424[%c]: closer: unblocked  ELAPSED=%jd ms\n",
	    tag, (intmax_t)hx_ms(&t0, &t1));
	return (hx_ms(&t0, &t1));
}

/*
 * The open(2) path: ucom_open() queues ucom_cfg_open first
 * (usb_serial.c:865-867) -- 2 x 1000 ms for the evil device.
 */
static void
hx_open(void)
{
	struct hx_msg *m;

	lockmgr(&hx_lock, LK_EXCLUSIVE);
	m = usb_proc_msignal(&hx_tq, &hx_open_msg[0], &hx_open_msg[1]);
	m->hdr.pm_callback = &hx_cfg_open;
	lockmgr(&hx_lock, LK_RELEASE);
}

/*
 * The user's tcsetattr(2): ucom_param() -> ucom_queue_command(
 * ucom_cfg_param, ..., &sc->sc_param_task[0].hdr, &sc->sc_param_task[1].hdr)
 * (usb_serial.c:1691-1693) -- double-buffered, so two tsetattrs leave two
 * outstanding tasks.
 */
static void
hx_tcsetattr(int n)
{
	struct hx_msg *m;

	lockmgr(&hx_lock, LK_EXCLUSIVE);
	while (n--) {
		m = usb_proc_msignal(&hx_tq, &hx_param[0], &hx_param[1]);
		m->hdr.pm_callback = &hx_cfg_param;
	}
	lockmgr(&hx_lock, LK_RELEASE);
}

static int
hx_phase(int phase, int nparam)
{
	int error;

	memset(&hx_tq, 0, sizeof(hx_tq));
	error = usb_proc_create(&hx_tq, &hx_lock,
	    phase == 2 ? "hx5424b" : "hx5424a", USB_PRI_MED);
	if (error) {
		kprintf("HX5424: usb_proc_create failed: %d\n", error);
		return (error);
	}
	hx_fixed = (phase == 2);

	/* the user opens the tty (queues cfg_open) and tcsetattr's nparam times */
	hx_open();
	hx_tcsetattr(nparam);

	/* the closing thread (or the hub event thread on unplug) */
	hx_closer_thread(phase, nparam);

	usb_proc_free(&hx_tq);
	return (0);
}

static int
hx_modevent(module_t mod, int type, void *data)
{
	int error = 0;

	switch (type) {
	case MOD_LOAD:
		lockinit(&hx_lock, "hx5424", 0, LK_CANRECURSE);

		kprintf("HX5424: DF-5424 uftdi cfg-chain stall harness, "
		    "hz=%d, %d reqs/param-task, %d reqs/open-task, "
		    "%d ms/request\n",
		    hz, HX_PARAM_REQS, HX_OPEN_REQS, HX_REQ_MS_FIXED);

		hx_phase(0, 1);		/* A: open+1 tcsetattr+close ~5.3 s */
		hx_phase(1, 2);		/* A2: open+2 tcsetattr+close ~8.3 s */
		hx_phase(2, 1);		/* B: fix mechanism (abort) ~2.3 s */

		lockuninit(&hx_lock);
		kprintf("HX5424: harness complete\n");
		break;
	case MOD_UNLOAD:
		break;
	default:
		error = EOPNOTSUPP;
		break;
	}
	return (error);
}

static moduledata_t hx_mod = { "uftdicfgstall", hx_modevent, 0 };
DECLARE_MODULE(uftdicfgstall, hx_mod, SI_SUB_DRIVERS, SI_ORDER_MIDDLE);
MODULE_DEPEND(uftdicfgstall, usb, 1, 1, 1);