Logger <LOGGER_INTERNAL> doesn't work (maybe concurrency issue)

[ohmtech-rdi]

Description

When using the Logger over "internal USB", logging either does work, or doesn't work at all, or just a few frames of logs are received and then it doesn't work anymore.

• This is dependent on the program
• Sometimes it works, sometimes not
• Sometimes launching the program using openocd makes it work, or the inverse

Analysis

template <LoggerDestination dest>
void Logger<dest>::StartLog(bool wait_for_pc)
{
    impl_.Init();   // will trigger OTG_FS_IRQHandler interruption at some point

    /* if waiting for PC, use blocking transmission */
    pc_sync_ = wait_for_pc ? LOGGER_SYNC_IN : LOGGER_SYNC_OUT;
    /** transmit something to stall the UART until a terminal is connected
     * at least two separate calls are required
     */
    PrintLine("Daisy is online");
    PrintLine("===============");
    System::Delay(10);
}

After impl_.Init(); is called, PrintLine will immediately start to CDC_Transmit_FS.
At some point of time, a OTG_FS_IRQHandler interruption will be fired, in which it will setup the CDC.
Typically when the bug happens:

CDC_Init_FS@0x08008e2e (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/src/usbd/usbd_cdc_if.c:178)
USBD_CDC_Init@0x080136bc (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/Middlewares/ST/STM32_USB_Device_Library/Class/CDC/Src/usbd_cdc.c:546)
USBD_SetClassConfig@0x0801382e (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/Middlewares/ST/STM32_USB_Device_Library/Core/Src/usbd_core.c:231)
USBD_SetConfig@0x08013cf0 (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/Middlewares/ST/STM32_USB_Device_Library/Core/Src/usbd_ctlreq.c:584)
USBD_StdDevReq@0x08013e40 (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/Middlewares/ST/STM32_USB_Device_Library/Core/Src/usbd_ctlreq.c:136)
USBD_LL_SetupStage@0x0801388a (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/Middlewares/ST/STM32_USB_Device_Library/Core/Src/usbd_core.c:272)
HAL_PCD_SetupStageCallback@0x08009022 (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/src/usbd/usbd_conf.c:212)
PCD_EP_OutSetupPacket_int@0x0800e804 (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/Drivers/STM32H7xx_HAL_Driver/Src/stm32h7xx_hal_pcd.c:2188)
HAL_PCD_IRQHandler@0x0800e9da (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/Drivers/STM32H7xx_HAL_Driver/Src/stm32h7xx_hal_pcd.c:1083)
OTG_FS_IRQHandler@0x080067b4 (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/src/hid/usb.cpp:173)
<signal handler called>@0xffffffe9 (Unknown Source:0)
daisy::UsbHandle::TransmitInternal@0x08006786 (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/src/hid/usb.cpp:128)
daisy::LoggerImpl<(daisy::LoggerDestination)1>::Transmit@0x0800657e (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/src/hid/logger_impl.h:61)
daisy::Logger<(daisy::LoggerDestination)1>::TransmitSync@0x0800657e (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/src/hid/logger.h:113)
daisy::Logger<(daisy::LoggerDestination)1>::TransmitBuf@0x0800657e (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/src/hid/logger.cpp:76)
daisy::Logger<(daisy::LoggerDestination)1>::PrintLineV@0x08006630 (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/src/hid/logger.cpp:44)
daisy::Logger<(daisy::LoggerDestination)1>::PrintLine@0x0800664e (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/src/hid/logger.cpp:32)
daisy::Logger<(daisy::LoggerDestination)1>::StartLog@0x08006672 (/Users/raf/Desktop/dev/eurorack-blocks/submodules/libDaisy/src/hid/logger.cpp:56)
main@0x0800189c (/Users/raf/Desktop/dev/eurorack/frohmage-erb/artifacts/perf/main.cpp:154)

The first time CDC_Transmit_FS is called:

uint8_t CDC_Transmit_FS(uint8_t* Buf, uint16_t Len)
{
    uint8_t result = USBD_OK;
    /* USER CODE BEGIN 7 */
    USBD_CDC_HandleTypeDef* hcdc
        = (USBD_CDC_HandleTypeDef*)hUsbDeviceFS.pClassData;
    if(hcdc->TxState != 0)
    {
        return USBD_BUSY;
    }
    USBD_CDC_SetTxBuffer(&hUsbDeviceFS, Buf, Len);
    result = USBD_CDC_TransmitPacket(&hUsbDeviceFS);
    /* USER CODE END 7 */
    return result;
}

hcdc is NULL, and it seems that hcdc is big enough for the TxState to be mapped to an address that can be at least read.

Workaround

I introduced a delay between impl_.Init(); and before CDC_Transmit_FS is first called:

template <LoggerDestination dest>
void Logger<dest>::StartLog(bool wait_for_pc)
{
    impl_.Init();   // will trigger OTG_FS_IRQHandler interruption at some point

    System::Delay(1000); // wait for CDC_Init_FS to be called

    /* if waiting for PC, use blocking transmission */
    pc_sync_ = wait_for_pc ? LOGGER_SYNC_IN : LOGGER_SYNC_OUT;
    /** transmit something to stall the UART until a terminal is connected
     * at least two separate calls are required
     */
    PrintLine("Daisy is online");
    PrintLine("===============");
    System::Delay(10);
}

And that seems to solve it, at least when the program is living in the FLASH section.

[takumi-ogata]

Hi Raphael! I'm sorry for the delay in response.
Thank you for documenting and reporting the issue as well as a temporary workaround.

We'll have a closer look at this when we get a chance.

[stephenhensley]

@ohmtech-rdi

So I haven't quite been able to reproduce this yet, but I have seen the occasional windows warning complaining of an unknown device. This doesn't seem to exactly match what you're running into, but it could very well be related.

Most of the class functions (CDC_Transfer/Receive Packet) seem to fail safely if the USB has not completed setup.

Do you have any other code that would execute within that first 1000ms delay you posted as a workaround that would block IRQs from happening?
That would likely result in an actual failure to negotiate the setup with the host rather than to just fail to print.

A few things that would make this easier to track down (and to potentially avoid) would be a bit of added error handling to both the Logger, and the UsbHandle classes, as well as the ability to check current connection/USB status.

I'll continue to look into this.
There are a few other USB related things I'll be looking at over the next week or so.
As I find more I'll let you know.

If you could provide a minimal example that triggers this error for you (even if only intermittently) that would be quite helpful.
Thanks!