facedancer: Control OUT transfer sometimes gets stuck with Requested non-existent endpoint EP0/OUT for configured device!

[kevinmehall]

In testing Facedancer 3.0.0's minimal.py (modified with changed VID, PID, and control request numbers), making requests with nusb's control transfer example on Linux 6.8, about 10% of the time I'm seeing it get stuck with the message

ERROR   | device         | Requested non-existent endpoint EP0/OUT for configured device!
ERROR   | device         | Received 4 bytes of data on invalid EP0/OUT.

With -v5:

DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_CONTROL 0 0
DEBUG   | moondancer     | handle_receive_control(0)
DEBUG   | moondancer     |   moondancer.api.read_control(0) -> 8 'IN STANDARD request GET_STATUS (0x00) to DEVICE [value=0x0000, index=0x0000, length=2]'
TRACE   | moondancer     |   is_out:False  has_data:True
TRACE   | moondancer     |   connected_device.handle_request(IN STANDARD request GET_STATUS (0x00) to DEVICE [value=0x0000, index=0x0000, length=2])
DEBUG   | device         | generic device received request: IN STANDARD request GET_STATUS (0x00) to DEVICE [value=0x0000, index=0x0000, length=2]
DEBUG   | device         | received GET_STATUS request
DEBUG   | moondancer     | moondancer.send_on_endpoint(0, 2, False)
TRACE   | moondancer     |   moondancer.api.write_endpoint(0, False, 2)
DEBUG   | moondancer     |   CONTROL IN -> prime ep to receive zlp
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_PACKET 0 0
DEBUG   | moondancer     | moondancer.handle_receive_packet(0) pending:None
TRACE   | moondancer     |   moondancer.api.read_endpoint(0) -> 0
DEBUG   | moondancer     |   received ZLP on ep0
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_CONTROL 0 0
DEBUG   | moondancer     | handle_receive_control(0)
DEBUG   | moondancer     |   moondancer.api.read_control(0) -> 8 'OUT STANDARD request CLEAR_FEATURE (0x01) to DEVICE [value=0x0001, index=0x0000, length=0]'
TRACE   | moondancer     |   is_out:True  has_data:False
TRACE   | moondancer     |   connected_device.handle_request(OUT STANDARD request CLEAR_FEATURE (0x01) to DEVICE [value=0x0001, index=0x0000, length=0])
DEBUG   | device         | generic device received request: OUT STANDARD request CLEAR_FEATURE (0x01) to DEVICE [value=0x0001, index=0x0000, length=0]
DEBUG   | device         | Received CLEAR_FEATURE request with type 1 and value 1.
DEBUG   | moondancer     | moondancer.send_on_endpoint(0, 0, False)
TRACE   | moondancer     |   moondancer.api.write_endpoint(0, False, 0)
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_PACKET 0 0
DEBUG   | moondancer     | moondancer.handle_receive_packet(0) pending:None
TRACE   | moondancer     |   moondancer.api.read_endpoint(0) -> 4
ERROR   | device         | Requested non-existent endpoint EP0/OUT for configured device!
ERROR   | device         | Received 4 bytes of data on invalid EP0/OUT.
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_CONTROL 0 0
DEBUG   | moondancer     | handle_receive_control(0)
DEBUG   | moondancer     |   moondancer.api.read_control(0) -> 8 'OUT VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=4]'
TRACE   | moondancer     |   is_out:True  has_data:True
DEBUG   | moondancer     |   setup packet has data - queueing read

Comparing to a successful run:

DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_CONTROL 0 0
DEBUG   | moondancer     | handle_receive_control(0)
DEBUG   | moondancer     |   moondancer.api.read_control(0) -> 8 'IN STANDARD request GET_STATUS (0x00) to DEVICE [value=0x0000, index=0x0000, length=2]'
TRACE   | moondancer     |   is_out:False  has_data:True
TRACE   | moondancer     |   connected_device.handle_request(IN STANDARD request GET_STATUS (0x00) to DEVICE [value=0x0000, index=0x0000, length=2])
DEBUG   | device         | generic device received request: IN STANDARD request GET_STATUS (0x00) to DEVICE [value=0x0000, index=0x0000, length=2]
DEBUG   | device         | received GET_STATUS request
DEBUG   | moondancer     | moondancer.send_on_endpoint(0, 2, False)
TRACE   | moondancer     |   moondancer.api.write_endpoint(0, False, 2)
DEBUG   | moondancer     |   CONTROL IN -> prime ep to receive zlp
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_PACKET 0 0
DEBUG   | moondancer     | moondancer.handle_receive_packet(0) pending:None
TRACE   | moondancer     |   moondancer.api.read_endpoint(0) -> 0
DEBUG   | moondancer     |   received ZLP on ep0
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_CONTROL 0 0
DEBUG   | moondancer     | handle_receive_control(0)
DEBUG   | moondancer     |   moondancer.api.read_control(0) -> 8 'OUT STANDARD request CLEAR_FEATURE (0x01) to DEVICE [value=0x0001, index=0x0000, length=0]'
TRACE   | moondancer     |   is_out:True  has_data:False
TRACE   | moondancer     |   connected_device.handle_request(OUT STANDARD request CLEAR_FEATURE (0x01) to DEVICE [value=0x0001, index=0x0000, length=0])
DEBUG   | device         | generic device received request: OUT STANDARD request CLEAR_FEATURE (0x01) to DEVICE [value=0x0001, index=0x0000, length=0]
DEBUG   | device         | Received CLEAR_FEATURE request with type 1 and value 1.
DEBUG   | moondancer     | moondancer.send_on_endpoint(0, 0, False)
TRACE   | moondancer     |   moondancer.api.write_endpoint(0, False, 0)
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_CONTROL 0 0
DEBUG   | moondancer     | handle_receive_control(0)
DEBUG   | moondancer     |   moondancer.api.read_control(0) -> 8 'OUT VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=4]'
TRACE   | moondancer     |   is_out:True  has_data:True
DEBUG   | moondancer     |   setup packet has data - queueing read
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_PACKET 0 0
DEBUG   | moondancer     | moondancer.handle_receive_packet(0) pending:OUT VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=4]
DEBUG   | moondancer     |   handling control data stage: 4 bytes
TRACE   | moondancer     |   moondancer.api.read_endpoint(0) -> 4
DEBUG   | device         | generic device received request: OUT VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=4]
INFO    | minimal        | device received 39321 39321 b'\x01\x02\x03\x04' on control endpoint
DEBUG   | moondancer     | moondancer.send_on_endpoint(0, 0, False)
TRACE   | moondancer     |   moondancer.api.write_endpoint(0, False, 0)
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_CONTROL 0 0
DEBUG   | moondancer     | handle_receive_control(0)
DEBUG   | moondancer     |   moondancer.api.read_control(0) -> 8 'IN VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=256]'
TRACE   | moondancer     |   is_out:False  has_data:True
TRACE   | moondancer     |   connected_device.handle_request(IN VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=256])
DEBUG   | device         | generic device received request: IN VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=256]
INFO    | minimal        | my_in_vendor_request_handler
DEBUG   | moondancer     | moondancer.send_on_endpoint(0, 26, False)
TRACE   | moondancer     |   moondancer.api.write_endpoint(0, False, 26)
DEBUG   | moondancer     |   CONTROL IN -> prime ep to receive zlp
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_PACKET 0 0
DEBUG   | moondancer     | moondancer.handle_receive_packet(0) pending:None
TRACE   | moondancer     |   moondancer.api.read_endpoint(0) -> 0
DEBUG   | moondancer     |   received ZLP on ep0
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_CONTROL 0 0
DEBUG   | moondancer     | handle_receive_control(0)
DEBUG   | moondancer     |   moondancer.api.read_control(0) -> 8 'OUT VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=4]'
TRACE   | moondancer     |   is_out:True  has_data:True
DEBUG   | moondancer     |   setup packet has data - queueing read
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_PACKET 0 0
DEBUG   | moondancer     | moondancer.handle_receive_packet(0) pending:OUT VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=4]
DEBUG   | moondancer     |   handling control data stage: 4 bytes
TRACE   | moondancer     |   moondancer.api.read_endpoint(0) -> 4
DEBUG   | device         | generic device received request: OUT VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=4]
INFO    | minimal        | device received 39321 39321 b'\x01\x02\x03\x04' on control endpoint
DEBUG   | moondancer     | moondancer.send_on_endpoint(0, 0, False)
TRACE   | moondancer     |   moondancer.api.write_endpoint(0, False, 0)
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_CONTROL 0 0
DEBUG   | moondancer     | handle_receive_control(0)
DEBUG   | moondancer     |   moondancer.api.read_control(0) -> 8 'IN VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=256]'
TRACE   | moondancer     |   is_out:False  has_data:True
TRACE   | moondancer     |   connected_device.handle_request(IN VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=256])
DEBUG   | device         | generic device received request: IN VENDOR request 0x81 to DEVICE [value=0x9999, index=0x9999, length=256]
INFO    | minimal        | my_in_vendor_request_handler
DEBUG   | moondancer     | moondancer.send_on_endpoint(0, 26, False)
TRACE   | moondancer     |   moondancer.api.write_endpoint(0, False, 26)
DEBUG   | moondancer     |   CONTROL IN -> prime ep to receive zlp
DEBUG   | moondancer     | MD IRQ => USB_RECEIVE_PACKET 0 0
DEBUG   | moondancer     | moondancer.handle_receive_packet(0) pending:None
TRACE   | moondancer     |   moondancer.api.read_endpoint(0) -> 0
DEBUG   | moondancer     |   received ZLP on ep0

My interpretation is that when it fails, the MD IRQ => USB_RECEIVE_PACKET 0 0 arrives before the MD IRQ => USB_RECEIVE_CONTROL 0 0, so it is not expecting the data packet and tries to process it as if EP0 were a regular endpoint. On the successful run, the USB_RECEIVE_CONTROL is processed before the USB_RECEIVE_PACKET.

❯ cynthion info
Cynthion version: 0.1.3
Apollo version: 1.1.0
Python version: 3.12.3 (main, Apr 10 2024, 05:33:47) [GCC 13.2.0]

Found Apollo stub interface!
        Bitstream: Facedancer (Cynthion Project)
        Vendor ID: 1d50
        Product ID: 615b
        bcdDevice: 0104
        Bitstream serial number: 337b7acba3ac60de

[antoinevg]

Fixed in #183 and greatscottgadgets/facedancer#115