search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.59k stars 7.27k forks source link

tusb_serial_device not working (IDFGH-13925) #14764

Open LeonBirkel opened 2 hours ago

LeonBirkel commented 2 hours ago

Answers checklist.

IDF version.

v5.3.1

Espressif SoC revision.

ESP32-s3 (QFN56) (revision v0.2)

Operating System used.

Windows

How did you build your project?

VS Code IDE

If you are using Windows, please specify command line type.

PowerShell

Development Kit.

ESP32 S3 DevKitC 1 N16R8 ESP32 S3 WROOM1 N16R8 Development Board

Power Supply used.

USB

What is the expected behavior?

After importing the example, builing and flashing. I expect the pytest to run.

What is the actual behavior?

Pytest is failing (Debug Logs)

Steps to reproduce.

  1. Import example
  2. build and flash
  3. run pytest

Debug Logs.

PS C:\BA\bastion\hardware-trust-anchor\board-v5> pytest ./pytest_usb_device_serial.py
============================================================ test session starts ============================================================
platform win32 -- Python 3.13.0, pytest-8.3.3, pluggy-1.5.0
rootdir: C:\BA\bastion\hardware-trust-anchor\board-v5
plugins: embedded-1.11.6
collected 1 item

pytest_usb_device_serial.py F                                                                                                          [100%]

================================================================= FAILURES ==================================================================
______________________________________________________ test_usb_device_serial_example _______________________________________________________

self = <pytest_embedded.dut.Dut object at 0x0000022A6F335FD0>, pattern = 'USB initialization DONE', expect_all = False, not_matching = ()
args = (), kwargs = {}, patterns = ['USB initialization DONE'], res = []
debug_str = 'Not found "USB initialization DONE"\nBytes in current buffer (color code eliminated): \nPlease check the full log her...ers\\leonb\\AppData\\Local\\Temp\\pytest-embedded\\2024-10-22_09-27-25-840324\\test_usb_device_serial_example\\dut.log'

    @functools.wraps(func)
    def wrapper(
        self, pattern, *args, expect_all: bool = False, not_matching: List[Union[str, re.Pattern]] = (), **kwargs
    ) -> Union[Union[Match, AnyStr], List[Union[Match, AnyStr]]]:
        patterns = to_list(pattern)
        res = []
        while patterns:
            try:
>               index = func(self, pattern, *args, **kwargs)

c:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pytest_embedded\dut.py:76:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
c:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pytest_embedded\dut.py:153: in expect_exact
    return self.pexpect_proc.expect_exact(pattern, **kwargs)
C:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pexpect\spawnbase.py:432: in expect_exact
    return exp.expect_loop(timeout)
C:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pexpect\expect.py:181: in expect_loop
    return self.timeout(e)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <pexpect.expect.Expecter object at 0x0000022A6F336270>
err = TIMEOUT("<pytest_embedded.log.PexpectProcess object at 0x0000022A6F335A90>\nsearcher: searcher_string:\n    0: b'USB initialization DONE'")

    def timeout(self, err=None):
        spawn = self.spawn

        spawn.before = spawn._before.getvalue()
        spawn.after = TIMEOUT
        index = self.searcher.timeout_index
        if index >= 0:
            spawn.match = TIMEOUT
            spawn.match_index = index
            return index
        else:
            spawn.match = None
            spawn.match_index = None
            msg = str(spawn)
            msg += '\nsearcher: %s' % self.searcher
            if err is not None:
                msg = str(err) + '\n' + msg

            exc = TIMEOUT(msg)
            exc.__cause__ = None    # in Python 3.x we can use "raise exc from None"
>           raise exc
E           pexpect.exceptions.TIMEOUT: <pytest_embedded.log.PexpectProcess object at 0x0000022A6F335A90>
E           searcher: searcher_string:
E               0: b'USB initialization DONE'
E           <pytest_embedded.log.PexpectProcess object at 0x0000022A6F335A90>
E           searcher: searcher_string:
E               0: b'USB initialization DONE'

C:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pexpect\expect.py:144: TIMEOUT

The above exception was the direct cause of the following exception:

dut = <pytest_embedded.dut.Dut object at 0x0000022A6F335FD0>

    @pytest.mark.esp32s3
    # @pytest.mark.esp32p4
    @pytest.mark.temp_skip_ci(targets=['esp32s3'], reason='lack of runners with usb_device tag')
    @pytest.mark.usb_device
    def test_usb_device_serial_example(dut: Dut) -> None:
>       dut.expect_exact('USB initialization DONE')

pytest_usb_device_serial.py:17:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <pytest_embedded.dut.Dut object at 0x0000022A6F335FD0>, pattern = 'USB initialization DONE', expect_all = False, not_matching = ()     
args = (), kwargs = {}, patterns = ['USB initialization DONE'], res = []
debug_str = 'Not found "USB initialization DONE"\nBytes in current buffer (color code eliminated): \nPlease check the full log her...ers\\leonb\\AppData\\Local\\Temp\\pytest-embedded\\2024-10-22_09-27-25-840324\\test_usb_device_serial_example\\dut.log'

    @functools.wraps(func)
    def wrapper(
        self, pattern, *args, expect_all: bool = False, not_matching: List[Union[str, re.Pattern]] = (), **kwargs
    ) -> Union[Union[Match, AnyStr], List[Union[Match, AnyStr]]]:
        patterns = to_list(pattern)
        res = []
        while patterns:
            try:
                index = func(self, pattern, *args, **kwargs)
            except (pexpect.EOF, pexpect.TIMEOUT) as e:
                debug_str = (
                    f'Not found "{pattern!s}"\n'
                    f'Bytes in current buffer (color code eliminated): {self.pexpect_proc.buffer_debug_str}\n'
                    f'Please check the full log here: {self.logfile}'
                )
>               raise e.__class__(debug_str) from e
E               pexpect.exceptions.TIMEOUT: Not found "USB initialization DONE"
E               Bytes in current buffer (color code eliminated): 
E               Please check the full log here: C:\Users\leonb\AppData\Local\Temp\pytest-embedded\2024-10-22_09-27-25-840324\test_usb_device_serial_example\dut.log

c:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pytest_embedded\dut.py:83: TIMEOUT
nMarkWarning: Unknown pytest.mark.temp_skip_ci - is this a typo?  You can register custom marks to avoid this warning - for details, see https://docs.pytest.org/en/stable/how-to/mark.html
    @pytest.mark.temp_skip_ci(targets=['esp32s3'], reason='lack of runners with usb_device tag')

pytest_usb_device_serial.py:15
  C:\BA\bastion\hardware-trust-anchor\board-v5\pytest_usb_device_serial.py:15: PytestUnknownMarkWarning: Unknown pytest.mark.usb_device - is this a typo?  You can register custom marks to avoid this warning - for details, see https://docs.pytest.org/en/stable/how-to/mark.html        
    @pytest.mark.usb_device

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
========================================================== short test summary info ========================================================== 
FAILED pytest_usb_device_serial.py::test_usb_device_serial_example - pexpect.exceptions.TIMEOUT: Not found "USB initialization DONE"
====================================================== 1 failed, 3 warnings in 30.13s ======================================================= 
PS C:\BA\bastion\hardware-trust-anchor\board-v5>

                                                 pytest ./pytest_usb_device_serial.py
============================================================ test session starts ============================================================
platform win32 -- Python 3.13.0, pytest-8.3.3, pluggy-1.5.0
rootdir: C:\BA\bastion\hardware-trust-anchor\board-v5
plugins: embedded-1.11.6
collected 1 item

pytest_usb_device_serial.py F                                                                                                          [100%]

================================================================= FAILURES ==================================================================
______________________________________________________ test_usb_device_serial_example _______________________________________________________ 

self = <pytest_embedded.dut.Dut object at 0x00000210EEE95FD0>, pattern = 'USB initialization DONE', expect_all = False, not_matching = ()     
args = (), kwargs = {}, patterns = ['USB initialization DONE'], res = []
debug_str = 'Not found "USB initialization DONE"\nBytes in current buffer (color code eliminated): \nPlease check the full log her...ers\\leonb\\AppData\\Local\\Temp\\pytest-embedded\\2024-10-22_09-32-23-859453\\test_usb_device_serial_example\\dut.log'

    @functools.wraps(func)
    def wrapper(
        self, pattern, *args, expect_all: bool = False, not_matching: List[Union[str, re.Pattern]] = (), **kwargs
    ) -> Union[Union[Match, AnyStr], List[Union[Match, AnyStr]]]:
        patterns = to_list(pattern)
        res = []
        while patterns:
            try:
>               index = func(self, pattern, *args, **kwargs)

c:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pytest_embedded\dut.py:76:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
c:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pytest_embedded\dut.py:153: in expect_exact
    return self.pexpect_proc.expect_exact(pattern, **kwargs)
C:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pexpect\spawnbase.py:432: in expect_exact
    return exp.expect_loop(timeout)
C:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pexpect\expect.py:181: in expect_loop
    return self.timeout(e)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <pexpect.expect.Expecter object at 0x00000210EEE96270>
err = TIMEOUT("<pytest_embedded.log.PexpectProcess object at 0x00000210EEE95A90>\nsearcher: searcher_string:\n    0: b'USB initialization DONE'")

    def timeout(self, err=None):
        spawn = self.spawn

        spawn.before = spawn._before.getvalue()
        spawn.after = TIMEOUT
        index = self.searcher.timeout_index
        if index >= 0:
            spawn.match = TIMEOUT
            spawn.match_index = index
            return index
        else:
            spawn.match = None
            spawn.match_index = None
            msg = str(spawn)
            msg += '\nsearcher: %s' % self.searcher
            if err is not None:
                msg = str(err) + '\n' + msg

            exc = TIMEOUT(msg)
            exc.__cause__ = None    # in Python 3.x we can use "raise exc from None"
>           raise exc
E           pexpect.exceptions.TIMEOUT: <pytest_embedded.log.PexpectProcess object at 0x00000210EEE95A90>
E           searcher: searcher_string:
E               0: b'USB initialization DONE'
E           <pytest_embedded.log.PexpectProcess object at 0x00000210EEE95A90>
E           searcher: searcher_string:
E               0: b'USB initialization DONE'

C:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pexpect\expect.py:144: TIMEOUT

The above exception was the direct cause of the following exception:

dut = <pytest_embedded.dut.Dut object at 0x00000210EEE95FD0>

    @pytest.mark.esp32s3
    # @pytest.mark.esp32p4
    @pytest.mark.temp_skip_ci(targets=['esp32s3'], reason='lack of runners with usb_device tag')
    @pytest.mark.usb_device
    def test_usb_device_serial_example(dut: Dut) -> None:
>       dut.expect_exact('USB initialization DONE')

pytest_usb_device_serial.py:17:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <pytest_embedded.dut.Dut object at 0x00000210EEE95FD0>, pattern = 'USB initialization DONE', expect_all = False, not_matching = ()     
args = (), kwargs = {}, patterns = ['USB initialization DONE'], res = []
debug_str = 'Not found "USB initialization DONE"\nBytes in current buffer (color code eliminated): \nPlease check the full log her...ers\\leonb\\AppData\\Local\\Temp\\pytest-embedded\\2024-10-22_09-32-23-859453\\test_usb_device_serial_example\\dut.log'

    @functools.wraps(func)
    def wrapper(
        self, pattern, *args, expect_all: bool = False, not_matching: List[Union[str, re.Pattern]] = (), **kwargs
    ) -> Union[Union[Match, AnyStr], List[Union[Match, AnyStr]]]:
        patterns = to_list(pattern)
        res = []
        while patterns:
            try:
                index = func(self, pattern, *args, **kwargs)
            except (pexpect.EOF, pexpect.TIMEOUT) as e:
                debug_str = (
                    f'Not found "{pattern!s}"\n'
                    f'Bytes in current buffer (color code eliminated): {self.pexpect_proc.buffer_debug_str}\n'
                    f'Please check the full log here: {self.logfile}'
                )
>               raise e.__class__(debug_str) from e
E               pexpect.exceptions.TIMEOUT: Not found "USB initialization DONE"
E               Bytes in current buffer (color code eliminated): 
E               Please check the full log here: C:\Users\leonb\AppData\Local\Temp\pytest-embedded\2024-10-22_09-32-23-859453\test_usb_device_serial_example\dut.log

c:\Users\leonb\AppData\Local\Programs\Python\Python313\Lib\site-packages\pytest_embedded\dut.py:83: TIMEOUT
============================================================= warnings summary ============================================================== 
pytest_usb_device_serial.py:12
  C:\BA\bastion\hardware-trust-anchor\board-v5\pytest_usb_device_serial.py:12: PytestUnknownMarkWarning: Unknown pytest.mark.esp32s3 - is this a typo?  You can register custom marks to avoid this warning - for details, see https://docs.pytest.org/en/stable/how-to/mark.html
    @pytest.mark.esp32s3

pytest_usb_device_serial.py:14
  C:\BA\bastion\hardware-trust-anchor\board-v5\pytest_usb_device_serial.py:14: PytestUnknownMarkWarning: Unknown pytest.mark.temp_skip_ci - is this a typo?  You can register custom marks to avoid this warning - for details, see https://docs.pytest.org/en/stable/how-to/mark.html      
    @pytest.mark.temp_skip_ci(targets=['esp32s3'], reason='lack of runners with usb_device tag')

pytest_usb_device_serial.py:15
  C:\BA\bastion\hardware-trust-anchor\board-v5\pytest_usb_device_serial.py:15: PytestUnknownMarkWarning: Unknown pytest.mark.usb_device - is this a typo?  You can register custom marks to avoid this warning - for details, see https://docs.pytest.org/en/stable/how-to/mark.html        
    @pytest.mark.usb_device

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
========================================================== short test summary info ========================================================== 
FAILED pytest_usb_device_serial.py::test_usb_device_serial_example - pexpect.exceptions.TIMEOUT: Not found "USB initialization DONE"
====================================================== 1 failed, 3 warnings in 30.14s =======================================================

More Information.

I did not do Pin Assignment since I undestand that this is not required for my board. Both USB cables are currently connected. If I do manual tests(putty), I can see the example log outputs on the board, but it seems like the board cannot send any data back. See below for more details to my manual testing

image

PS C:\BA\bastion\hardware-trust-anchor\board-v5> & 'C:\Users\leonb\.espressif\python_env\idf5.3_py3.11_env\Scripts\python.exe' 'C:\Users\leonb\esp\v5.3.1\esp-idf\tools\idf_monitor.py' -p COM9 -b 115200 --toolchain-prefix xtensa-esp32s3-elf- --target esp32s3 'c:\BA\bastion\hardware-trust-anchor\board-v5\build\board-v5.elf'
--- Warning: GDB cannot open serial ports accessed as COMx
--- Using \\.\COM9 instead...
--- esp-idf-monitor 1.5.0 on \\.\COM9 115200
--- Warning: ELF file 'c:\BA\bastion\hardware-trust-anchor\board-v5\build\board-v5.elf' does not exist
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce2810,len:0x178c
load:0x403c8700,len:0x4
load:0x403c8704,len:0xcb8
load:0x403cb700,len:0x2db0
entry 0x403c8914
I (27) boot: ESP-IDF v5.3.1-dirty 2nd stage bootloader
I (27) boot: compile time Oct 22 2024 10:49:27
I (27) boot: Multicore bootloader
I (30) boot: chip revision: v0.2
I (34) boot.esp32s3: Boot SPI Speed : 80MHz
I (39) boot.esp32s3: SPI Mode       : DIO
I (44) boot.esp32s3: SPI Flash Size : 2MB
I (48) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (57) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (72) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (80) boot:  2 factory          factory app      00 00 00010000 00100000
I (87) boot: End of partition table
I (91) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=0ad8ch ( 44428) map
I (108) esp_image: segment 1: paddr=0001adb4 vaddr=3fc92500 size=02ad4h ( 10964) load
I (110) esp_image: segment 2: paddr=0001d890 vaddr=40374000 size=02788h ( 10120) load
I (119) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=1fa94h (129684) map
I (148) esp_image: segment 4: paddr=0003fabc vaddr=40376788 size=0bc7ch ( 48252) load
I (165) boot: Loaded app from partition at offset 0x10000
I (165) boot: Disabling RNG early entropy source...
I (177) cpu_start: Multicore app
I (186) cpu_start: Pro cpu start user code
I (191) cpu_start: cpu freq: 160000000 Hz
I (191) app_init: Application information:
I (194) app_init: Project name:     board-v5
I (199) app_init: App version:      d6d6919-dirty
I (205) app_init: Compile time:     Oct 22 2024 10:49:18
I (211) app_init: ELF file SHA256:  116124e3c...
I (216) app_init: ESP-IDF:          v5.3.1-dirty
I (221) efuse_init: Min chip rev:     v0.0
I (226) efuse_init: Max chip rev:     v0.99 
I (231) efuse_init: Chip rev:         v0.2
I (236) heap_init: Initializing. RAM available for dynamic allocation:
I (243) heap_init: At 3FC962E0 len 00053430 (333 KiB): RAM
I (249) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
I (255) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (261) heap_init: At 600FE100 len 00001EE8 (7 KiB): RTCRAM
I (269) spi_flash: detected chip: generic
I (272) spi_flash: flash io: dio
W (276) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (289) sleep: Configure to isolate all GPIO pins in sleep state
I (296) sleep: Enable automatic switching of GPIO sleep configuration
I (304) main_task: Started on CPU0
I (324) main_task: Calling app_main()
I (324) example: USB initialization
W (324) tusb_desc: No Device descriptor provided, using default.
W (324) tusb_desc: No FullSpeed configuration descriptor provided, using default.
W (334) tusb_desc: No String descriptors provided, using default.
I (344) tusb_desc:
┌─────────────────────────────────┐
│  USB Device Descriptor Summary  │
├───────────────────┬─────────────┤
│bDeviceClass       │ 239         │
├───────────────────┼─────────────┤
│bDeviceSubClass    │ 2           │
├───────────────────┼─────────────┤
│bDeviceProtocol    │ 1           │
├───────────────────┼─────────────┤
│bMaxPacketSize0    │ 64          │
├───────────────────┼─────────────┤
│idVendor           │ 0x303a      │
├───────────────────┼─────────────┤
│idProduct          │ 0x4001      │
├───────────────────┼─────────────┤
│bcdDevice          │ 0x100       │
├───────────────────┼─────────────┤
│iManufacturer      │ 0x1         │
├───────────────────┼─────────────┤
│iProduct           │ 0x2         │
├───────────────────┼─────────────┤
│iSerialNumber      │ 0x3         │
├───────────────────┼─────────────┤
│bNumConfigurations │ 0x1         │
└───────────────────┴─────────────┘
I (514) TinyUSB: TinyUSB Driver installed
I (514) example: USB initialization DONE
I (824) example: Line state changed on channel 0: DTR:0, RTS:0
I (2554) example: Line state changed on channel 0: DTR:1, RTS:1
I (12164) example: GGGGG 
I (12164) example: Data from channel 0:
I (12164) example: 0x3fc98b50   74 65 73 74                                       |test|
I (12164) example: TEST
roma-jam commented 2 hours ago

Hi @LeonBirkel,

could you provide all the commands, how do you configure esp-idf (install & export), build and flash example and run pytest.

Thanks.

LeonBirkel commented 2 hours ago

Thank you for the fast reply. Pytest: PS C:\BA\bastion\hardware-trust-anchor\board-v5> pytest ./pytest_usb_device_serial.py

Install & import is handled by the VsCode extension. I select Express installation.

For building and flashing I use the VScode UI, it prints this command into my console: C:\Users\leonb.espressif\python_env\idf5.3_py3.11_env\Scripts\python.exe C:\Users\leonb\esp\v5.3.1\esp-idf\components\esptool_py\esptool\esptool.py -p COM9 -b 460800 --before default_reset --after hard_reset --chip esp32s3 write_flash --flash_mode dio --flash_freq 80m --flash_size 2MB 0x0 bootloader/bootloader.bin 0x10000 board-v5.bin 0x8000 partition_table/partition-table.bin

Is this the information you need @roma-jam or did I misunterstand something?