DF-5476 / run.log
UB5476: DF-5476 ubsa cfg-chain stall harness, hz=100, 3 reqs/first-open-line-task, 5 reqs/tcsetattr (7 for B0), 0 reqs/open-task, 0 reqs/status-task, 0 reqs/close-task, 1000 ms/request (production timeout ubsa.c:360) UB5476[A]: --- phase A first-open + close: first open + 0 extra tcsetattr + close --- (t=0) 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) UB5476: start-transfers task: async bulk/intr only, 0 EP0 requests UB5476: cfg-open task: no ucom_cfg_open callback in ubsa -> set LL_READY only, 0 requests, no pause (usb_serial.c:771-778) UB5476: start-transfers task: async bulk/intr only, 0 EP0 requests UB5476: line-state task: enter, 3 x 1000 ms sync EP0 writes (DTR=1, RTS=1, BREAK=0) UB5476[56ms]: request 1/3 (set_dtr) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[A][156ms]: closer: queue cfg_close + usb_proc_mwait() (uninterruptible, usb_serial.c:671-672) behind the queue UB5476[1036ms]: request 2/3 (set_rts) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[2026ms]: request 3/3 (set_break(0)) START: EP0 vendor write, 1000 ms timeout, silent device UB5476: line-state task: leave (no core pause) UB5476: cfg-status task: cached sc_lsr/sc_msr only (ubsa.c:541-542), 0 EP0 requests UB5476: cfg-close task: no ucom_cfg_close callback in ubsa -> 0 requests (usb_serial.c:915-921) UB5476[A][3049ms]: closer: unblocked ELAPSED=2877 ms UB5476[2]: --- phase A2 open + tcsetattr@9600 + close: first open + 1 extra tcsetattr + close --- (t=0) 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) UB5476: start-transfers task: async bulk/intr only, 0 EP0 requests UB5476: cfg-open task: no ucom_cfg_open callback in ubsa -> set LL_READY only, 0 requests, no pause (usb_serial.c:771-778) UB5476: start-transfers task: async bulk/intr only, 0 EP0 requests UB5476: line-state task: enter, 3 x 1000 ms sync EP0 writes (DTR=1, RTS=1, BREAK=0) UB5476[30ms]: request 1/3 (set_dtr) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[2][151ms]: closer: queue cfg_close + usb_proc_mwait() (uninterruptible, usb_serial.c:671-672) behind the queue UB5476[1013ms]: request 2/3 (set_rts) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[1994ms]: request 3/3 (set_break(0)) START: EP0 vendor write, 1000 ms timeout, silent device UB5476: line-state task: leave (no core pause) UB5476: cfg-status task: cached sc_lsr/sc_msr only (ubsa.c:541-542), 0 EP0 requests UB5476: cfg-param task: enter, tcsetattr(rate) chain, 5 x 1000 ms sync EP0 writes UB5476[2993ms]: request 1/5 (baud/parity/data/stop/flow) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[3974ms]: request 2/5 (baud/parity/data/stop/flow) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[4964ms]: request 3/5 (baud/parity/data/stop/flow) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[5954ms]: request 4/5 (baud/parity/data/stop/flow) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[6944ms]: request 5/5 (baud/parity/data/stop/flow) START: EP0 vendor write, 1000 ms timeout, silent device UB5476: cfg-param task: leave UB5476: cfg-close task: no ucom_cfg_close callback in ubsa -> 0 requests (usb_serial.c:915-921) UB5476[2][8054ms]: closer: unblocked ELAPSED=7893 ms UB5476[0]: --- phase A3 open + tcsetattr@B0 + close: first open + 1 extra tcsetattr (B0, 7 reqs) + close --- (t=0) 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) UB5476: start-transfers task: async bulk/intr only, 0 EP0 requests UB5476: cfg-open task: no ucom_cfg_open callback in ubsa -> set LL_READY only, 0 requests, no pause (usb_serial.c:771-778) UB5476: start-transfers task: async bulk/intr only, 0 EP0 requests UB5476: line-state task: enter, 3 x 1000 ms sync EP0 writes (DTR=1, RTS=1, BREAK=0) UB5476[58ms]: request 1/3 (set_dtr) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[0][159ms]: closer: queue cfg_close + usb_proc_mwait() (uninterruptible, usb_serial.c:671-672) behind the queue UB5476[1042ms]: request 2/3 (set_rts) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[2032ms]: request 3/3 (set_break(0)) START: EP0 vendor write, 1000 ms timeout, silent device UB5476: line-state task: leave (no core pause) UB5476: cfg-status task: cached sc_lsr/sc_msr only (ubsa.c:541-542), 0 EP0 requests UB5476: cfg-param task: enter, tcsetattr(B0) chain, 7 x 1000 ms sync EP0 writes UB5476[3070ms]: request 1/7 (B0: flow/DTR/RTS) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[4052ms]: request 2/7 (B0: flow/DTR/RTS) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[5042ms]: request 3/7 (B0: flow/DTR/RTS) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[6042ms]: request 4/7 (parity/data/stop/flow) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[7032ms]: request 5/7 (parity/data/stop/flow) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[8032ms]: request 6/7 (parity/data/stop/flow) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[9022ms]: request 7/7 (parity/data/stop/flow) START: EP0 vendor write, 1000 ms timeout, silent device UB5476: cfg-param task: leave UB5476: cfg-close task: no ucom_cfg_close callback in ubsa -> 0 requests (usb_serial.c:915-921) UB5476[0][10144ms]: closer: unblocked ELAPSED=9974 ms UB5476[B]: --- phase B fix#1 abort-on-error: first open + 1 extra tcsetattr + close --- (t=0) 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) UB5476: start-transfers task: async bulk/intr only, 0 EP0 requests UB5476: cfg-open task: no ucom_cfg_open callback in ubsa -> set LL_READY only, 0 requests, no pause (usb_serial.c:771-778) UB5476: start-transfers task: async bulk/intr only, 0 EP0 requests UB5476: line-state task: enter, 3 x 1000 ms sync EP0 writes (DTR=1, RTS=1, BREAK=0) (fix: abort on first error) UB5476[59ms]: request 1/3 (set_dtr) START: EP0 vendor write, 1000 ms timeout, silent device UB5476[B][158ms]: closer: queue cfg_close + usb_proc_mwait() (uninterruptible, usb_serial.c:671-672) behind the queue UB5476: request 1/3 (set_dtr) FAILED (USB_ERR_TIMEOUT) -> abort chain (fixed) UB5476: line-state task: leave (no core pause) UB5476: cfg-status task: cached sc_lsr/sc_msr only (ubsa.c:541-542), 0 EP0 requests UB5476: cfg-param task: enter, tcsetattr(rate) chain, 5 x 1000 ms sync EP0 writes (fix: abort on first error) UB5476[1087ms]: request 1/5 (baud/parity/data/stop/flow) START: EP0 vendor write, 1000 ms timeout, silent device UB5476: request 1/5 (baud/parity/data/stop/flow) FAILED (USB_ERR_TIMEOUT) -> abort chain (fixed) UB5476: cfg-param task: leave UB5476: cfg-close task: no ucom_cfg_close callback in ubsa -> 0 requests (usb_serial.c:915-921) UB5476[B][2206ms]: closer: unblocked ELAPSED=2035 ms UB5476[C]: --- phase C fix#1+#2 abort+250ms: first open + 1 extra tcsetattr + close --- (t=0) 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) UB5476: start-transfers task: async bulk/intr only, 0 EP0 requests UB5476: cfg-open task: no ucom_cfg_open callback in ubsa -> set LL_READY only, 0 requests, no pause (usb_serial.c:771-778) UB5476: start-transfers task: async bulk/intr only, 0 EP0 requests UB5476: line-state task: enter, 3 x 250 ms sync EP0 writes (DTR=1, RTS=1, BREAK=0) (fix: abort on first error) UB5476[57ms]: request 1/3 (set_dtr) START: EP0 vendor write, 250 ms timeout, silent device UB5476[C][158ms]: closer: queue cfg_close + usb_proc_mwait() (uninterruptible, usb_serial.c:671-672) behind the queue UB5476: request 1/3 (set_dtr) FAILED (USB_ERR_TIMEOUT) -> abort chain (fixed) UB5476: line-state task: leave (no core pause) UB5476: cfg-status task: cached sc_lsr/sc_msr only (ubsa.c:541-542), 0 EP0 requests UB5476: cfg-param task: enter, tcsetattr(rate) chain, 5 x 250 ms sync EP0 writes (fix: abort on first error) UB5476[342ms]: request 1/5 (baud/parity/data/stop/flow) START: EP0 vendor write, 250 ms timeout, silent device UB5476: request 1/5 (baud/parity/data/stop/flow) FAILED (USB_ERR_TIMEOUT) -> abort chain (fixed) UB5476: cfg-param task: leave UB5476: cfg-close task: no ucom_cfg_close callback in ubsa -> 0 requests (usb_serial.c:915-921) UB5476[C][728ms]: closer: unblocked ELAPSED=557 ms UB5476: harness complete