/* * DF-5383 KLD harness -- production-code demonstration of the umcs7840 * cfg_open/cfg_close synchronous-request chain stall. * * WHAT IT PROVES (with the real in-kernel u4b usb_process machinery, the * same code ucom's taskqueue uses): * * umcs7840_cfg_open() (umcs.c:410-515) chains 28 synchronous EP0 control * requests on first open (2 global-config at umcs.c:423,426 + 14 port * init at umcs.c:431-483 + 6 baud at umcs.c:1022-1046 via * umcs7840_set_baudrate(487) + 6 tail at umcs.c:496-512); every one is * umcs7840_get/set[_UART]_reg_sync() -> usbd_do_request_proc() * (umcs.c:927,948,972,997) with UMCS7840_CTRL_TIMEOUT = 500 ms * (umcs.h:33). umcs7840_cfg_close() adds 4 more (umcs.c:527,528,531,534). * A control transfer's data stage may be NAK'd by the device for as long * as it likes, so an evil MCS7840 can make every request succeed in * just-under-500 ms (usb_request.c:567-708: the requester sleeps in the * "WXFER" loop until the transfer completes or the timeout fires at * usb_request.c:700-704) without tripping the early-return error paths * -- cfg_open/cfg_close only abort on hard errors, not on slowness. * * The whole sequence runs on sc_super_ucom.sc_tq (the per-adapter ucom * taskqueue created at usb_serial.c:322). close(2) of the tty is * SYNCHRONOUS against that queue: ucom_close() -> * ucom_queue_command(ucom_cfg_close) -> usb_proc_mwait() * (usb_serial.c:671-672), and usb_proc_mwait cv_wait()s uninterruptibly * (usb_process.c:385-393) while the message is queued -- behind the * still-running cfg_open (a message stays head-of-queue while its * callback executes, usb_process.c:146-158). Unplug racing an in-flight * cfg task stalls the same way via ucom_detach() -> usb_proc_drain() * (usb_serial.c:394) on the USB hub event thread (DF-5367 mechanism). * * => one open+close with the slow evil device blocks the closing thread * (or the hub event thread, on unplug) uninterruptibly for * 28*500 + 4*500 = 16000 ms (+hz/10 ucom_cfg_open pause, * usb_serial.c:777). * * PHASE A (baseline): queue a cfg task that performs the exact 28-request * sequence (28 x lksleep("WXFER",500ms), the production per-request cost * of a request the device stretches to just under the timeout), then * 100 ms later do what ucom_close() does: queue cfg_close (4 x 500 ms) * and usb_proc_mwait() for it. Measure the closer's block time. * EXPECT ~16000 ms. * * PHASE B (fix mechanism from fix.diff: bound the cfg-path control * timeout to 100 ms): same sequence with 100 ms per request. * EXPECT ~3200 ms (5x reduction of the bounded stall window). */ #include #include #include #include #include #include #include #include #include #include #include #include #define HX_OPEN_REQS 28 /* umcs.c:423..512 first-open chain */ #define HX_CLOSE_REQS 4 /* umcs.c:527..534 */ #define HX_REQ_MS_A 500 /* == UMCS7840_CTRL_TIMEOUT (umcs.h:33) */ #define HX_REQ_MS_B 100 /* fix.diff: bounded cfg-path timeout */ 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_open[2]; static struct hx_msg hx_close[2]; static int hx_req_ms = HX_REQ_MS_A; 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 umcs7840_*_reg_sync() the evil device answers just under timeout */ static void hx_one_request(void) { lksleep(&hx_lock, &hx_lock, 0, "WXFER", USB_MS_TO_TICKS(hx_req_ms)); } /* umcs7840_cfg_open()'s request chain (umcs.c:423-512), runs on sc_tq */ static void hx_cfg_open(struct usb_proc_msg *pm) { int i; kprintf("HX5383: cfg-open task: enter, %d x %d ms sync EP0 requests\n", HX_OPEN_REQS, hx_req_ms); for (i = 0; i < HX_OPEN_REQS; ++i) hx_one_request(); /* ucom_cfg_open()'s trailing pause, usb_serial.c:777 */ usb_pause_mtx(&hx_lock, hz / 10); kprintf("HX5383: cfg-open task: leave\n"); } /* umcs7840_cfg_close()'s chain (umcs.c:527-534), runs on sc_tq */ static void hx_cfg_close(struct usb_proc_msg *pm) { int i; kprintf("HX5383: cfg-close task: enter\n"); for (i = 0; i < HX_CLOSE_REQS; ++i) hx_one_request(); kprintf("HX5383: cfg-close task: leave\n"); } /* * Exactly ucom_close()'s synchronous close (usb_serial.c:671-672): * queue cfg_close behind the running cfg_open and mwait uninterruptibly. */ static int64_t hx_closer_thread(int phase) { struct timeval t0, t1; /* the open(2) queued cfg_open; it starts running on the tq thread */ tsleep(&hx_tq, 0, "hxlead", hz / 10); /* 100 ms into cfg_open */ kprintf("HX5383[%c]: closer: queue cfg_close + usb_proc_mwait() " "(uninterruptible, usb_serial.c:671-672)\n", phase ? 'B' : 'A'); microtime(&t0); lockmgr(&hx_lock, LK_EXCLUSIVE); if (!usb_proc_is_gone(&hx_tq)) { struct hx_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("HX5383[%c]: closer: unblocked ELAPSED=%jd ms\n", phase ? 'B' : 'A', (intmax_t)hx_ms(&t0, &t1)); return (hx_ms(&t0, &t1)); } static void hx_phase(int fixed) { struct hx_msg *m; int error; memset(&hx_tq, 0, sizeof(hx_tq)); error = usb_proc_create(&hx_tq, &hx_lock, fixed ? "hx5383b" : "hx5383a", USB_PRI_MED); if (error) { kprintf("HX5383: usb_proc_create failed: %d\n", error); return; } hx_req_ms = fixed ? HX_REQ_MS_B : HX_REQ_MS_A; /* open(2) queues cfg_open asynchronously (usb_serial.c:635-659) */ lockmgr(&hx_lock, LK_EXCLUSIVE); m = usb_proc_msignal(&hx_tq, &hx_open[0], &hx_open[1]); m->hdr.pm_callback = &hx_cfg_open; lockmgr(&hx_lock, LK_RELEASE); /* the closing thread (or the hub event thread on unplug) */ hx_closer_thread(fixed); usb_proc_free(&hx_tq); } static int hx_modevent(module_t mod, int type, void *data) { int error = 0; switch (type) { case MOD_LOAD: lockinit(&hx_lock, "hx5383", 0, LK_CANRECURSE); kprintf("HX5383: DF-5383 umcs cfg-chain stall harness, " "hz=%d, %d open reqs + %d close reqs\n", hz, HX_OPEN_REQS, HX_CLOSE_REQS); hx_phase(0); /* A: 500 ms/request baseline */ hx_phase(1); /* B: fix mechanism 100 ms/request */ lockuninit(&hx_lock); kprintf("HX5383: harness complete\n"); break; case MOD_UNLOAD: break; default: error = EOPNOTSUPP; break; } return (error); } static moduledata_t hx_mod = { "umcscfgstall", hx_modevent, 0 }; DECLARE_MODULE(umcscfgstall, hx_mod, SI_SUB_DRIVERS, SI_ORDER_MIDDLE); MODULE_DEPEND(umcscfgstall, usb, 1, 1, 1);