/* * DF-5496 KLD harness -- production-code demonstration of the umct * (Magic Control Technology / Belkin F5U109/F5U409 / Sitecom USB-RS232, * ucom core) cfg-chain synchronous-request stall. Same rig family as * DF-5476 ubsa / DF-5425 uslcom / DF-5424 uftdi / DF-5449 uvscom / * DF-5456 umoscom / DF-5487 uvisor. * * WHAT IT PROVES (with the real in-kernel u4b usb_process machinery, * the same taskqueue ucom's cfg callbacks run on): * * Every umct cfg callback step is a synchronous EP0 vendor control * write through ucom_cfg_do_request() (usb_serial.h:220-221 -> * usbd_do_request_proc) carrying a 1000 ms timeout (umct.c:333), and * the usb_error_t result is DISCARDED at the only site there is * (umct_cfg_do_request(), umct.c:334-337 "(ignored)"), so no chain * step ever aborts. A silent evil adapter makes each request eat * its full 1000 ms timeout (usb_request.c:561 max_ticks, :643 * "WXFER" sleep, :700-704 USB_ERR_TIMEOUT) and the chain marches on; * a slow-but-answer-at-999 ms evil adapter makes every request * *succeed*. * * Production chain accounting (pass-2 precision, LL_READY-gated): * * FIRST open(2) of /dev/ttyUx (ucom_open, usb_serial.c:801-903) * queues param(:842 via ucom_param -> :1691), start(:870 via * ucom_param :1696), cfg_open(:865), start(:870), line-state * (:874-878), status(:880). The first param task runs BEFORE the * cfg_open task and BAILS (ucom_cfg_param, usb_serial.c:1626-1628: * !UCOM_FLAG_LL_READY) -- umct's first-open param is a NO-OP; umct * has no ucom_cfg_open callback (umct.c:175-187), so cfg_open only * sets LL_READY with NO hz/10 pause (pause is inside the * callback-if, usb_serial.c:771-778). What issues EP0 on first open * is the ONE coalesced line-state task (usb_serial.c:1357-1420): * DTR=1 + RTS=1 + BREAK=0 -> 3 x umct_cfg_do_request * (umct.c:413 SET_MCR, :426 SET_MCR, :400 SET_LCR). * umct_cfg_get_status reads cached bytes (umct.c:381-388, kept fresh * by umct_intr_callback_sub, umct.c:360-361) -> 0 requests; umct * issues NO control-IN reads anywhere (UMCT_GET_MSR/UMCT_GET_LCR at * umct.c:72-75 are dead constants -- the DF-1062/2342/5448/5455 * uninit-read class cannot exist in this driver). * => first open = 3 x 1000 ms ~= 3.0 s of per-adapter taskqueue * occupancy. * * EVERY later tcsetattr of the open tty re-queues the param task * (double-buffered, usb_serial.c:1691-1693; LL_READY now set): * ANY rate (there is no B0 branch -- umct_pre_param accepts * everything, umct.c:459-463, and umct_cfg_param programs the * same two registers for B0 as for any other speed): * SET_BAUD(umct.c:472) + SET_LCR(umct.c:503) * = 2 x 1000 ms * + core hz/10 pause (usb_serial.c:1636) ~= 2.1 s * TIOCMSET DTR+RTS -> 2 x 1000 ms; TIOCSBRK/TIOCCBRK -> 1 x 1000 ms. * The double buffer COALESCES a rapid tcsetattr burst to at most 2 * queued instances (usb_proc_msignal t==3 branch, usb_process.c: * 259-331): a burst of 5 executes 2 full chains; a PACED or * sustained loop keeps the tq busy ~2.1 s per instance for as long * as the abuser keeps queueing. * * close(2) is SYNCHRONOUS against that queue: ucom_close() -> * ucom_shutdown() (HUPCL default: TTYDEF_CFLAG) queues ONE more * set_dtr request (usb_serial.c:694-696 -> umct.c:413), then * ucom_queue_command(ucom_cfg_close) -> usb_proc_mwait() * (usb_serial.c:671-672 + 955-957), uninterruptible cv_wait * (usb_process.c:364-393) while messages queued in front run to * completion. umct registers no ucom_cfg_close (umct.c:175-187), so * the closer purely waits out whatever the user/device queued ahead * plus its own 1 x 1000 ms HUPCL DTR drop. * Unplug mid-cycle stalls the USB hub event thread identically via * ucom_detach() -> usb_proc_drain() (usb_serial.c:394). * * PHASE A (first open + close): 3 x 1000 ms line-state task + the * closer's own 1 x 1000 ms HUPCL DTR drop; closer queues 100 ms in. * EXPECT ~3900 ms. * PHASE A2 (open + 1 user tcsetattr@9600 + close): + 2 x 1000 ms + * 100 ms pause. EXPECT ~6000 ms. * PHASE A3 (open + burst of 5 tcsetattr + close): coalesced to 2 param * executions -> + 2 x 2100 ms. EXPECT ~8100 ms (burst ceiling; a * paced/sustained loop extends without bound until the abuser stops, * because usb_proc_mwait cv_wait drops sc_lock while asleep). * PHASE B (fix.diff mechanism #1: abort each cfg chain on its first * failed request, timeout unchanged): line 1 x 1000 ms, param 1 x * 1000 ms + pause, HUPCL DTR 1 x 1000 ms. EXPECT ~3000 ms. * PHASE C (fix.diff mechanism #1+#2: abort + bound the cfg-path * control timeout 1000 -> 250 ms): EXPECT ~750 ms. */ #include #include #include #include #include #include #include #include #include #include #include #include #define UM_LINE_REQS 3 /* umct.c:413,426,400 first-open line task */ #define UM_PARAM_REQS 2 /* umct.c:472,503 per tcsetattr (any rate) */ #define UM_CLOSE_DTR 1 /* umct.c:413 via ucom_shutdown HUPCL */ #define UM_REQ_MS 1000 /* umct.c:333 production cfg timeout */ static struct lock um_lock; /* stands in for sc->sc_lock */ static struct usb_process um_tq; /* sc_super_ucom.sc_tq (usb_serial.c:322) */ struct um_msg { struct usb_proc_msg hdr; }; static struct um_msg um_param[2]; /* ucom sc_param_task[2] double buffer */ static struct um_msg um_start[2]; /* ucom sc_start_task[2] */ static struct um_msg um_open_msg[2]; /* ucom sc_open_task[2] */ static struct um_msg um_line[2]; /* ucom sc_line_state_task[2] */ static struct um_msg um_status[2]; /* ucom sc_status_task[2] */ static struct um_msg um_close[2]; /* ucom sc_close_task[2] */ static struct um_msg um_hupcl[2]; /* same line task; dedicated rig pair so the 1-request HUPCL instance cannot race the 3-request open instance's request count */ static int um_ll_ready; /* UCOM_FLAG_LL_READY, set by cfg_open task */ static int um_fixed; /* fix mechanism #1: abort on first error */ static int um_req_ms = UM_REQ_MS;/* fix mechanism #2: bounded timeout */ static int um_param_execs; /* coalescing instrumentation (A3) */ static struct timeval um_t0; /* phase start, absolute */ static int64_t um_ms(struct timeval *t0, struct timeval *t1) { return ((int64_t)(t1->tv_sec - t0->tv_sec) * 1000 + (t1->tv_usec - t0->tv_usec) / 1000); } static int64_t um_abs_ms(void) { struct timeval now; microtime(&now); return (um_ms(&um_t0, &now)); } /* * One umct vendor request against the silent evil adapter: the device * never answers the data/status stage, so the requester sleeps in the * "WXFER" loop until the timeout fires (usb_request.c:643, :700-704) * and the request returns USB_ERR_TIMEOUT -- which production umct * discards (umct.c:334-337). The sleep ident must be UNIQUE per * request like the production "xfer" pointer is: sleeping on the lock * address would let unrelated lockmgr handoffs wake the request early * (harness v1 bug family, caught by absolute-timestamp instrumentation * in DF-5476; same fix carried here). */ static char um_req_wchan[16]; /* per-request wait channel */ static int um_one_request(const char *what, int i, int n) { kprintf("UM5496[%dms]: request %d/%d (%s) START: EP0 vendor write, " "%d ms timeout, silent device\n", (int)um_abs_ms(), i, n, what, um_req_ms); lksleep(&um_req_wchan[i & 15], &um_lock, 0, "WXFER", USB_MS_TO_TICKS(um_req_ms)); if (um_fixed) { /* fix.diff mechanism: the error now propagates and the * cfg chain bails on first failure. */ kprintf("UM5496: request %d/%d (%s) FAILED " "(USB_ERR_TIMEOUT) -> abort chain (fixed)\n", i, n, what); return (1); } return (0); } /* * ucom_cfg_param() (usb_serial.c:1619-1637) wrapping umct_cfg_param() * (umct.c:465-504). NOTE the production LL_READY gate at 1626-1628: * the first-open instance (queued at usb_serial.c:842, BEFORE cfg_open * at :865) runs first and BAILS -- modelled here. umct programs the * same SET_BAUD+SET_LCR pair for ANY rate (no B0 branch). */ static void um_cfg_param(struct usb_proc_msg *pm) { int i, n; if (!um_ll_ready) { kprintf("UM5496: cfg-param task: !LL_READY -> early return, " "0 requests (usb_serial.c:1626-1628; first-open param " "is a no-op for every ucom driver)\n"); return; } n = UM_PARAM_REQS; um_param_execs++; kprintf("UM5496: cfg-param task: enter (#%d), tcsetattr chain " "(any rate, no B0 branch in umct.c:465-504), %d x %d ms sync " "EP0 writes%s\n", um_param_execs, n, um_req_ms, um_fixed ? " (fix: abort on first error)" : ""); for (i = 0; i < n; ++i) { if (um_one_request(i == 0 ? "SET_BAUD divisor" : "SET_LCR", i + 1, n)) break; } /* ucom_cfg_param()'s trailing pause, usb_serial.c:1636 */ usb_pause_mtx(&um_lock, hz / 10); kprintf("UM5496: cfg-param task: leave\n"); } /* ucom_cfg_start_transfers() -- no EP0, no occupancy (no-op here) */ static void um_cfg_start(struct usb_proc_msg *pm) { kprintf("UM5496: start-transfers task: async bulk/intr only, " "0 EP0 requests\n"); } /* * ucom_cfg_open() (usb_serial.c:757-779): umct registers NO * ucom_cfg_open callback (umct.c:175-187) -> just sets LL_READY, * 0 requests and NO hz/10 pause (the pause at :777 is inside the * callback-if). */ static void um_cfg_open(struct usb_proc_msg *pm) { kprintf("UM5496: cfg-open task: no ucom_cfg_open callback in umct " "-> set LL_READY only, 0 requests, no pause " "(usb_serial.c:771-778)\n"); um_ll_ready = 1; } /* * The first-open line-state task (usb_serial.c:874-878 -> 1357-1420 * coalesced): DTR=1, RTS=1, BREAK=0 -> 3 x umct_cfg_do_request * (umct.c:413 set_dtr, :426 set_rts, :400 set_break(0)). */ static void um_cfg_line(struct usb_proc_msg *pm) { int i; if (!um_ll_ready) return; /* usb_serial.c:1368-1370 */ kprintf("UM5496: line-state task: enter, 3 x %d ms sync EP0 writes " "(DTR=1 SET_MCR, RTS=1 SET_MCR, BREAK=0 SET_LCR)%s\n", um_req_ms, um_fixed ? " (fix: abort on first error)" : ""); for (i = 0; i < UM_LINE_REQS; ++i) { if (um_one_request(i == 0 ? "set_dtr" : (i == 1 ? "set_rts" : "set_break(0)"), i + 1, UM_LINE_REQS)) break; } kprintf("UM5496: line-state task: leave (no core pause)\n"); } /* * ucom_cfg_status_change() -> umct_cfg_get_status() (umct.c:381-388): * reads CACHED sc_lsr/sc_msr bytes (kept fresh by the intr callback, * umct.c:360-361, behind a correct actlen<2 gate at umct.c:353-358) * -> 0 EP0 requests. umct never issues control-IN reads anywhere * (UMCT_GET_MSR/UMCT_GET_LCR, umct.c:72-75, are dead constants -- the * DF-1062/2342/5448/5455 uninit-read class cannot exist here). */ static void um_cfg_status(struct usb_proc_msg *pm) { kprintf("UM5496: cfg-status task: cached sc_lsr/sc_msr only " "(umct.c:386-387), 0 EP0 requests, no control-IN anywhere\n"); } /* umct registers no ucom_cfg_close -> ucom_cfg_close() core calls * nothing (usb_serial.c:915-921); the closer's own cost is the HUPCL * DTR drop queued below. */ static void um_cfg_close(struct usb_proc_msg *pm) { kprintf("UM5496: cfg-close task: no ucom_cfg_close callback in umct " "-> 0 requests (usb_serial.c:915-921)\n"); } /* * The HUPCL line-state instance ucom_shutdown() queues at close time * (usb_serial.c:694-696): DTR=0 only -> 1 x set_dtr request * (umct.c:413). Runs on the tq thread like every other cfg task. */ static void um_cfg_hupcl(struct usb_proc_msg *pm) { if (!um_ll_ready) return; /* usb_serial.c:1368-1370 */ kprintf("UM5496: line-state task (HUPCL): enter, 1 x %d ms sync EP0 " "write (DTR=0 SET_MCR)%s\n", um_req_ms, um_fixed ? " (fix: abort on first error)" : ""); um_one_request("HUPCL set_dtr(0)", 1, UM_CLOSE_DTR); kprintf("UM5496: line-state task (HUPCL): leave\n"); } /* * Exactly ucom_close()'s synchronous close (usb_serial.c:939-957): * first ucom_shutdown() queues the HUPCL DTR drop (usb_serial.c:694-696 * -> ONE set_dtr request, umct.c:413) on the line-state double buffer, * then ucom_queue_command(ucom_cfg_close) -> usb_proc_mwait() * uninterruptibly (usb_serial.c:671-672; usb_process.c:364-393). */ static int64_t um_closer_thread(char tag) { struct timeval t0, t1; /* the open chain tasks are running; the first starts immediately */ tsleep(&um_tq, 0, "umlead", hz / 10); /* 100 ms into the chain */ kprintf("UM5496[%c][%dms]: closer: ucom_shutdown HUPCL queues " "set_dtr(0), then cfg_close + usb_proc_mwait() " "(uninterruptible, usb_serial.c:671-672) behind the queue\n", tag, (int)um_abs_ms()); microtime(&t0); lockmgr(&um_lock, LK_EXCLUSIVE); if (!usb_proc_is_gone(&um_tq)) { struct um_msg *m; /* ucom_shutdown(): HUPCL -> 1 x set_dtr (umct.c:413) */ m = usb_proc_msignal(&um_tq, &um_hupcl[0], &um_hupcl[1]); m->hdr.pm_callback = &um_cfg_hupcl; /* ucom_close(): queue cfg_close and wait synchronously */ m = usb_proc_msignal(&um_tq, &um_close[0], &um_close[1]); m->hdr.pm_callback = &um_cfg_close; usb_proc_mwait(&um_tq, &um_close[0], &um_close[1]); } lockmgr(&um_lock, LK_RELEASE); microtime(&t1); kprintf("UM5496[%c][%dms]: closer: unblocked ELAPSED=%jd ms\n", tag, (int)um_abs_ms(), (intmax_t)um_ms(&t0, &t1)); return (um_ms(&t0, &t1)); } /* * The open(2) path, production queueing order (usb_serial.c:842 param, * :870 start, :865 cfg_open, :870 start again via :874-878 context, * :874-878 line-state, :880 status-change), then the local user's * tcsetattr burst(s) queue behind the open chain. */ static void um_open_chain(int extra_params) { struct um_msg *m; lockmgr(&um_lock, LK_EXCLUSIVE); /* ucom_open():842 -> ucom_param() queues cfg_param first */ m = usb_proc_msignal(&um_tq, &um_param[0], &um_param[1]); m->hdr.pm_callback = &um_cfg_param; /* :870 queue transfer enable command last (from ucom_param :1696) */ m = usb_proc_msignal(&um_tq, &um_start[0], &um_start[1]); m->hdr.pm_callback = &um_cfg_start; /* :865 cfg_open */ m = usb_proc_msignal(&um_tq, &um_open_msg[0], &um_open_msg[1]); m->hdr.pm_callback = &um_cfg_open; /* :870 queue transfer enable command last */ m = usb_proc_msignal(&um_tq, &um_start[0], &um_start[1]); m->hdr.pm_callback = &um_cfg_start; /* :874-878 DTR|RTS + ring-off + break-off -> one line-state task */ m = usb_proc_msignal(&um_tq, &um_line[0], &um_line[1]); m->hdr.pm_callback = &um_cfg_line; /* :880 ucom_status_change() */ m = usb_proc_msignal(&um_tq, &um_status[0], &um_status[1]); m->hdr.pm_callback = &um_cfg_status; lockmgr(&um_lock, LK_RELEASE); /* * The user's tcsetattr burst comes after open(2) returned; give * the tq thread a moment so the (instantly-bailing) first param * task has completed and the re-used double buffer enqueues * fresh. The msignal t==3 branch coalesces a burst of 5 down to * 2 queued instances -- production behavior, instrumented. */ tsleep(&um_tq, 0, "umtset", hz / 20); while (extra_params--) { lockmgr(&um_lock, LK_EXCLUSIVE); m = usb_proc_msignal(&um_tq, &um_param[0], &um_param[1]); m->hdr.pm_callback = &um_cfg_param; lockmgr(&um_lock, LK_RELEASE); } } static int um_phase(const char *name, char tag, int extra_params, int fixed, int req_ms) { int error; memset(&um_tq, 0, sizeof(um_tq)); error = usb_proc_create(&um_tq, &um_lock, name, USB_PRI_MED); if (error) { kprintf("UM5496: usb_proc_create failed: %d\n", error); return (error); } um_ll_ready = 0; um_param_execs = 0; um_fixed = fixed; um_req_ms = req_ms; microtime(&um_t0); kprintf("UM5496[%c]: --- phase %s: first open + %d tcsetattr " "burst + close --- (t=0)\n", tag, name, extra_params); /* the user opens the tty */ um_open_chain(extra_params); /* the closing thread (or the hub event thread on unplug) */ um_closer_thread(tag); usb_proc_free(&um_tq); return (0); } static int um_modevent(module_t mod, int type, void *data) { int error = 0; switch (type) { case MOD_LOAD: lockinit(&um_lock, "um5496", 0, LK_CANRECURSE); kprintf("UM5496: DF-5496 umct cfg-chain stall harness, hz=%d, " "%d reqs/first-open-line-task, %d reqs/tcsetattr " "(any rate incl. B0 -- no branch), %d reqs/HUPCL-close, " "%d reqs/open-task, %d reqs/status-task, 0 reqs/close-" "task, %d ms/request (production timeout umct.c:333)\n", hz, UM_LINE_REQS, UM_PARAM_REQS, UM_CLOSE_DTR, 0, 0, UM_REQ_MS); um_phase("A first-open + close", 'A', 0, 0, UM_REQ_MS); um_phase("A2 open + 1 tcsetattr + close", '2', 1, 0, UM_REQ_MS); um_phase("A3 open + burst of 5 tcsetattr + close", '3', 5, 0, UM_REQ_MS); um_phase("B fix#1 abort-on-error", 'B', 1, 1, UM_REQ_MS); um_phase("C fix#1+#2 abort+250ms", 'C', 1, 1, 250); lockuninit(&um_lock); kprintf("UM5496: harness complete\n"); break; case MOD_UNLOAD: break; default: error = EOPNOTSUPP; break; } return (error); } static moduledata_t um_mod = { "umct5496stall", um_modevent, 0 }; DECLARE_MODULE(umct5496stall, um_mod, SI_SUB_DRIVERS, SI_ORDER_MIDDLE); MODULE_DEPEND(umct5496stall, usb, 1, 1, 1);