/* * DF-5476 KLD harness -- production-code demonstration of the ubsa * (Belkin/eTek/GoHubs/Peracom USB serial, ucom core) cfg-chain * synchronous-request stall. Same rig family as DF-5425 uslcom / * DF-5424 uftdi / DF-5449 uvscom / DF-5456 umoscom. * * WHAT IT PROVES (with the real in-kernel u4b usb_process machinery, * the same taskqueue ucom's cfg callbacks run on): * * Every ubsa 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 (ubsa.c:360), and * the usb_error_t result is DISCARDED at the only site there is * (ubsa_cfg_request(), ubsa.c:361-364 "(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/ttyU0 (ucom_open, usb_serial.c:801-903) queues * param(:842 via ucom_param -> :1691), start(:870), cfg_open(:865), * 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) -- ubsa's first-open param is a NO-OP; ubsa has * no ucom_cfg_open callback (ubsa.c:216-228), so cfg_open only sets * LL_READY with NO hz/10 pause (pause is inside the callback-if, * usb_serial.c:773-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 ubsa_cfg_request (ubsa.c:374, :384, :394). * ubsa_cfg_get_status reads cached bytes (ubsa.c:535-543) -> 0 requests. * => 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): * non-B0 rate: baud(ubsa.c:449) + parity(:460) + data(:478) + * stop(:482) + flow(:491) = 5 x 1000 ms * + core hz/10 pause (usb_serial.c:1636) ~= 5.1 s * B0 (cfsetospeed B0 hangup): flow(:433) + DTR(:434) + RTS(:435) * + parity + data + stop + flow = 7 x 1000 ms * + pause ~= 7.1 s * TIOCMSET DTR+RTS -> 2 x 1000 ms; TIOCSBRK/TIOCCBRK -> 1 x 1000 ms. * * 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:364-393) while messages queued in front run to * completion. ubsa registers no ucom_cfg_close (ubsa.c:216-228), so * the closer purely waits out whatever the user/device queued ahead. * 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, then the * closer queues cfg_close + usb_proc_mwait() 100 ms in. EXPECT ~2900. * PHASE A2 (open + 1 user tcsetattr@9600 + close): + 5 x 1000 ms + 100 ms * pause. EXPECT ~8000 ms. * PHASE A3 (open + 1 user tcsetattr@B0 + close): + 7 x 1000 ms + 100 ms * pause. EXPECT ~10000 ms. * PHASE B (fix.diff mechanism #1: abort each cfg chain on its first * failed request, timeout unchanged): line-state -> 1 x 1000 ms, * param -> 1 x 1000 ms + pause. EXPECT ~2000 ms. * PHASE C (fix.diff mechanism #1+#2: abort + bound the cfg-path control * timeout 1000 -> 250 ms): EXPECT ~600 ms. */ #include #include #include #include #include #include #include #include #include #include #include #include #define UB_LINE_REQS 3 /* ubsa.c:374,384,394 first-open line task */ #define UB_PARAM_REQS 5 /* ubsa.c:449,460,478,482,491 per tcsetattr */ #define UB_PARAM_B0_REQS 7 /* ubsa.c:433,434,435,460,478,482,491 B0 */ #define UB_REQ_MS 1000 /* ubsa.c:360 production cfg timeout */ static struct lock ub_lock; /* stands in for sc->sc_lock */ static struct usb_process ub_tq; /* sc_super_ucom.sc_tq (usb_serial.c:322) */ struct ub_msg { struct usb_proc_msg hdr; }; static struct ub_msg ub_param[2]; /* ucom sc_param_task[2] double buffer */ static struct ub_msg ub_start[2]; /* ucom sc_start_task[2] */ static struct ub_msg ub_open_msg[2]; /* ucom sc_open_task[2] */ static struct ub_msg ub_line[2]; /* ucom sc_line_state_task[2] */ static struct ub_msg ub_status[2]; /* ucom sc_status_task[2] */ static struct ub_msg ub_close[2]; /* ucom sc_close_task[2] */ static int ub_ll_ready; /* UCOM_FLAG_LL_READY, set by cfg_open task */ static int ub_fixed; /* fix mechanism #1: abort on first error */ static int ub_req_ms = UB_REQ_MS;/* fix mechanism #2: bounded timeout */ static int ub_b0; /* this tcsetattr targets B0 (7 requests) */ static struct timeval ub_t0; /* phase start, absolute */ static int64_t ub_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 ub_abs_ms(void) { struct timeval now; microtime(&now); return (ub_ms(&ub_t0, &now)); } /* * One ubsa 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 ubsa * discards (ubsa.c:361-364). 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, caught by absolute-timestamp instrumentation). */ static char ub_req_wchan[16]; /* per-request wait channel */ static int ub_one_request(const char *what, int i, int n) { kprintf("UB5476[%dms]: request %d/%d (%s) START: EP0 vendor write, " "%d ms timeout, silent device\n", (int)ub_abs_ms(), i, n, what, ub_req_ms); lksleep(&ub_req_wchan[i & 15], &ub_lock, 0, "WXFER", USB_MS_TO_TICKS(ub_req_ms)); if (ub_fixed) { /* fix.diff mechanism: the error now propagates and the * cfg chain bails on first failure. */ kprintf("UB5476: 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 ubsa_cfg_param() * (ubsa.c:424-492). 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. */ static void ub_cfg_param(struct usb_proc_msg *pm) { int i, n; if (!ub_ll_ready) { kprintf("UB5476: 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 = ub_b0 ? UB_PARAM_B0_REQS : UB_PARAM_REQS; kprintf("UB5476: cfg-param task: enter, %s chain, %d x %d ms sync " "EP0 writes%s\n", ub_b0 ? "tcsetattr(B0)" : "tcsetattr(rate)", n, ub_req_ms, ub_fixed ? " (fix: abort on first error)" : ""); for (i = 0; i < n; ++i) { if (ub_one_request(ub_b0 ? (i < 3 ? "B0: flow/DTR/RTS" : "parity/data/stop/flow") : "baud/parity/data/stop/flow", i + 1, n)) break; } /* ucom_cfg_param()'s trailing pause, usb_serial.c:1636 */ usb_pause_mtx(&ub_lock, hz / 10); kprintf("UB5476: cfg-param task: leave\n"); } /* ucom_cfg_start_transfers() -- no EP0, no occupancy (no-op here) */ static void ub_cfg_start(struct usb_proc_msg *pm) { kprintf("UB5476: start-transfers task: async bulk/intr only, " "0 EP0 requests\n"); } /* * ucom_cfg_open() (usb_serial.c:757-779): ubsa registers NO * ucom_cfg_open callback (ubsa.c:216-228) -> just sets LL_READY, * 0 requests and NO hz/10 pause (the pause at :777 is inside the * callback-if). */ static void ub_cfg_open(struct usb_proc_msg *pm) { kprintf("UB5476: cfg-open task: no ucom_cfg_open callback in ubsa " "-> set LL_READY only, 0 requests, no pause " "(usb_serial.c:771-778)\n"); ub_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 ubsa_cfg_request * (ubsa.c:374 set_dtr, :384 set_rts, :394 set_break). */ static void ub_cfg_line(struct usb_proc_msg *pm) { int i; if (!ub_ll_ready) return; /* usb_serial.c:1368-1370 */ kprintf("UB5476: line-state task: enter, 3 x %d ms sync EP0 writes " "(DTR=1, RTS=1, BREAK=0)%s\n", ub_req_ms, ub_fixed ? " (fix: abort on first error)" : ""); for (i = 0; i < UB_LINE_REQS; ++i) { if (ub_one_request(i == 0 ? "set_dtr" : (i == 1 ? "set_rts" : "set_break(0)"), i + 1, UB_LINE_REQS)) break; } kprintf("UB5476: line-state task: leave (no core pause)\n"); } /* * ucom_cfg_status_change() -> ubsa_cfg_get_status() (ubsa.c:535-543): * reads CACHED sc_lsr/sc_msr bytes (kept fresh by the intr callback, * ubsa.c:628-629) -> 0 EP0 requests. ubsa never issues control-IN * reads anywhere (the DF-5455/DF-5448 uninit-read class cannot exist * in this driver). */ static void ub_cfg_status(struct usb_proc_msg *pm) { kprintf("UB5476: cfg-status task: cached sc_lsr/sc_msr only " "(ubsa.c:541-542), 0 EP0 requests\n"); } /* ubsa registers no ucom_cfg_close -> ucom_cfg_close() core calls * nothing (usb_serial.c:915-921); the closer waits out the queue. */ static void ub_cfg_close(struct usb_proc_msg *pm) { kprintf("UB5476: cfg-close task: no ucom_cfg_close callback in ubsa " "-> 0 requests (usb_serial.c:915-921)\n"); } /* * Exactly ucom_close()'s synchronous close (usb_serial.c:939-957 + * 671-672): queue cfg_close behind the running/queued cfg tasks and * usb_proc_mwait uninterruptibly (usb_process.c:364-393). */ static int64_t ub_closer_thread(char tag) { struct timeval t0, t1; /* the open chain tasks are running; the first starts immediately */ tsleep(&ub_tq, 0, "ublead", hz / 10); /* 100 ms into the chain */ kprintf("UB5476[%c][%dms]: closer: queue cfg_close + " "usb_proc_mwait() (uninterruptible, usb_serial.c:671-672) " "behind the queue\n", tag, (int)ub_abs_ms()); microtime(&t0); lockmgr(&ub_lock, LK_EXCLUSIVE); if (!usb_proc_is_gone(&ub_tq)) { struct ub_msg *m; m = usb_proc_msignal(&ub_tq, &ub_close[0], &ub_close[1]); m->hdr.pm_callback = &ub_cfg_close; usb_proc_mwait(&ub_tq, &ub_close[0], &ub_close[1]); } lockmgr(&ub_lock, LK_RELEASE); microtime(&t1); kprintf("UB5476[%c][%dms]: closer: unblocked ELAPSED=%jd ms\n", tag, (int)ub_abs_ms(), (intmax_t)ub_ms(&t0, &t1)); return (ub_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(s) queue behind the open chain. */ static void ub_open_chain(int extra_params) { struct ub_msg *m; lockmgr(&ub_lock, LK_EXCLUSIVE); /* ucom_open():842 -> ucom_param() queues cfg_param first */ m = usb_proc_msignal(&ub_tq, &ub_param[0], &ub_param[1]); m->hdr.pm_callback = &ub_cfg_param; /* :870 queue transfer enable command last (from ucom_param :1696) */ m = usb_proc_msignal(&ub_tq, &ub_start[0], &ub_start[1]); m->hdr.pm_callback = &ub_cfg_start; /* :865 cfg_open */ m = usb_proc_msignal(&ub_tq, &ub_open_msg[0], &ub_open_msg[1]); m->hdr.pm_callback = &ub_cfg_open; /* :870 queue transfer enable command last */ m = usb_proc_msignal(&ub_tq, &ub_start[0], &ub_start[1]); m->hdr.pm_callback = &ub_cfg_start; /* :874-878 DTR|RTS + ring-off + break-off -> one line-state task */ m = usb_proc_msignal(&ub_tq, &ub_line[0], &ub_line[1]); m->hdr.pm_callback = &ub_cfg_line; /* :880 ucom_status_change() */ m = usb_proc_msignal(&ub_tq, &ub_status[0], &ub_status[1]); m->hdr.pm_callback = &ub_cfg_status; lockmgr(&ub_lock, LK_RELEASE); /* * The user's tcsetattr(s) come 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. */ tsleep(&ub_tq, 0, "ubtset", hz / 20); while (extra_params--) { lockmgr(&ub_lock, LK_EXCLUSIVE); m = usb_proc_msignal(&ub_tq, &ub_param[0], &ub_param[1]); m->hdr.pm_callback = &ub_cfg_param; lockmgr(&ub_lock, LK_RELEASE); } } static int ub_phase(const char *name, char tag, int extra_params, int b0, int fixed, int req_ms) { int error; memset(&ub_tq, 0, sizeof(ub_tq)); error = usb_proc_create(&ub_tq, &ub_lock, name, USB_PRI_MED); if (error) { kprintf("UB5476: usb_proc_create failed: %d\n", error); return (error); } ub_ll_ready = 0; ub_b0 = b0; ub_fixed = fixed; ub_req_ms = req_ms; microtime(&ub_t0); kprintf("UB5476[%c]: --- phase %s: first open + %d extra " "tcsetattr%s + close --- (t=0)\n", tag, name, extra_params, b0 ? " (B0, 7 reqs)" : ""); /* the user opens the tty */ ub_open_chain(extra_params); /* the closing thread (or the hub event thread on unplug) */ ub_closer_thread(tag); usb_proc_free(&ub_tq); return (0); } static int ub_modevent(module_t mod, int type, void *data) { int error = 0; switch (type) { case MOD_LOAD: lockinit(&ub_lock, "ub5476", 0, LK_CANRECURSE); kprintf("UB5476: DF-5476 ubsa cfg-chain stall harness, hz=%d, " "%d reqs/first-open-line-task, %d reqs/tcsetattr " "(%d for B0), %d reqs/open-task, %d reqs/status-task, " "0 reqs/close-task, %d ms/request (production timeout " "ubsa.c:360)\n", hz, UB_LINE_REQS, UB_PARAM_REQS, UB_PARAM_B0_REQS, 0, 0, UB_REQ_MS); ub_phase("A first-open + close", 'A', 0, 0, 0, UB_REQ_MS); ub_phase("A2 open + tcsetattr@9600 + close", '2', 1, 0, 0, UB_REQ_MS); ub_phase("A3 open + tcsetattr@B0 + close", '0', 1, 1, 0, UB_REQ_MS); ub_phase("B fix#1 abort-on-error", 'B', 1, 0, 1, UB_REQ_MS); ub_phase("C fix#1+#2 abort+250ms", 'C', 1, 0, 1, 250); lockuninit(&ub_lock); kprintf("UB5476: harness complete\n"); break; case MOD_UNLOAD: break; default: error = EOPNOTSUPP; break; } return (error); } static moduledata_t ub_mod = { "ubsa5476stall", ub_modevent, 0 }; DECLARE_MODULE(ubsa5476stall, ub_mod, SI_SUB_DRIVERS, SI_ORDER_MIDDLE); MODULE_DEPEND(ubsa5476stall, usb, 1, 1, 1);