serial transport miss data for the first transfer

[tomaszduda23]

1. first transfer trigger flash erase
2. USB CDC port is suspended
3. device sends rc
4. serial port is resumed

req: req_hdr->nh_group 1, req_hdr->nh_id 1
[00:00:07.430,175] <inf> usb_cdc_acm: Device suspended
[00:00:11.661,621] <inf> mcumgr_img_grp: Erased 0x41000 bytes of image slot
[00:00:11.767,700] <inf> mcumgr_img_grp: Erased 0x1000 bytes of image slot trailer
response nh_group 3, nh_id 1
[00:00:11.767,974] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,005] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,005] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,035] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,035] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,066] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,066] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,096] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,096] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,127] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,157] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,157] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,157] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,188] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,218] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,218] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,218] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,249] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,280] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,280] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,310] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,310] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,341] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,341] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,371] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,371] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,402] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,402] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,432] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,432] <inf> usb_cdc_acm: USB device not ready, drop data
[00:00:11.768,463] <inf> usb_cdc_acm: USB device not ready, drop data
response rc 0
[00:00:44.874,206] <inf> usb_cdc_acm: Device resumed
[00:00:44.874,237] <inf> usb_cdc_acm: from suspend
[00:00:47.445,831] <inf> usb_cdc_acm: Device suspended

with mcumgr in go it looks like this

reqquest req_hdr->nh_group 1, req_hdr->nh_id 1
[00:07:29.650,085] <inf> usb_cdc_acm: Device suspended
[00:07:30.281,494] <inf> usb_cdc_acm: Device resumed
[00:07:30.281,494] <inf> usb_cdc_acm: from suspend
[00:07:32.900,299] <inf> usb_cdc_acm: Device suspended
[00:07:33.303,741] <inf> usb_cdc_acm: Device resumed
[00:07:33.303,741] <inf> usb_cdc_acm: from suspend
[00:07:34.037,933] <inf> mcumgr_img_grp: Erased 0x41000 bytes of image slot
[00:07:34.146,759] <inf> mcumgr_img_grp: Erased 0x1000 bytes of image slot trailer
respose nh_group 3, nh_id 1
rc 0

It seems that go is able to wake up port before transfer or keep it from long suspend.

[JPHutchins]

I'll look into it! I haven't used the "erase flash all at once" before, instead doing page by page.

It looks like it took ~34 seconds to erase. Can you set the timeout to 45 seconds and try again? It would be helpful to try from smpmgr where you could set --timeout 45 and --loglevel DEBUG then paste the smpgmr/smpclient logs.

[tomaszduda23]

The problem is that python allows usb_cdc_acm to go to susspend for a long time. Read from serial port stop working when cdc is in susspend (at least in python). It does not happen in go version somehow. USB susspend is controlled by host so it seems a port configuration or something. I have the same problem with esphome log over cdc. It stop working if device not send data for a long time. I didn't look in details why it happens. One of solution which I tested was toggle 'dtr' line just to keep cdc resumed. It works. It is far from perfect solution though. I guess there has to be a better way.

[tomaszduda23]

the other words if you could force printing this log

<inf> usb_cdc_acm: Device resumed
<inf> usb_cdc_acm: from suspend

before that one

<inf> mcumgr_img_grp: Erased 0x41000 bytes of image slot
<inf> mcumgr_img_grp: Erased 0x1000 bytes of image slot trailer

issue would be solved

[JPHutchins]

It's not clear to me why the usb_cdc_acm driver is being suspended at all, I'll need to look into the Zephyr code.

[tomaszduda23]

CONFIG_USB_DEVICE_REMOTE_WAKEUP=n can be used as workaround. In golang it seems to be working so maybe it would be possible to solve on host side.
Let's close it here since it seems to be related to python.

[JPHutchins]

Not a ton of info here: https://docs.zephyrproject.org/latest/kconfig.html#CONFIG_USB_DEVICE_REMOTE_WAKEUP

Re: your note about disabling logging, keep in mind that Zephyr has coexistence with logs when using the SMP "shell" transport. The requirement would be that all logs use the Zephyr logging system - so, generally, SMP must be the only thing on the transport unless the FW has been designed to handle both. And it ain't perfect - see my investigation here: intercreate/smpmgr#8

And this note here about reworking smpclient support for shell transport: #12

We are using the Shell Transport to update a coprocessor from a main processor. The main processor has the Zephyr shell enabled and is capable to receive SMP. So we've defined the Intercreate command group as a means of uploading data to an arbitrary location, in this case another MCU connected via UART.

[tomaszduda23]

A few services on one uart can be a problem.
One of the solutions is to add new CDC device for mcumgr esphome/esphome@61a25cf

[JPHutchins]

A few services on one uart can be a problem.
One of the solutions is to add new CDC device for mcumgr esphome/esphome@61a25cf

Whoa, hadn't considered that this was possible... but why not, "virtual" com ports!

https://devzone.nordicsemi.com/f/nordic-q-a/108073/multiple-virtual-com-ports-cdc-acm-connections-via-usb