[BUG] USB CDC/ACM write message lost

[SPRESENSE]

Description / Steps to reproduce the issue

Due to #15931, the write messages via USB CDC/ACM may be lost.
Before this PR, the problem does not occur.

I am checking with the Spresense board, is there any problem with other boards?

How to reproduce:

1. Enable the following configurations.

• CONFIG_EXAMPLES_USBSERIAL=y
• CONFIG_EXAMPLES_USBSERIAL_CONFIG_WAIT=y
• CONFIG_EXAMPLES_USBSERIAL_INONLY=y
• CONFIG_EXAMPLES_USBSERIAL_IN_WAITING_TIME=1
• CONFIG_EXAMPLES_USBSERIAL_ONLYBIG=y

2. Run usbserial on NuttShell to receive strings on the USB CDC/ACM serial device.
   The same message is received repeatedly, but after several hours of testing, the message may not be received.
   Below is a log of when the problem occurred, with some messages missing.

I know already, by your forwardness, that you have deserved rewards and crowns; and we do assure you, on the word of a prince, they shall be duly paid you. In the mean my lieutenant general shall be in my stead, than whom never prince commanded a more noble and worthy subject; not doubting by your obedience to my general, by your concord in the camp, and by your valour in the field, we shall shortly have a famous victory over the enemies of my God, of my kingdom, and of my people.
port, but being resolved, in the midst and heat of the battle, to live or die amongst you all; to lay down, for my God, and for my kingdom, and for my people, my honour and my blood, even the dust.

There is no problem when USB debug log (CONFIG_DEBUG_USB_INFO) is enabled, so there may be some potential timing defect.

On which OS does this issue occur?

[OS: Linux]

What is the version of your OS?

Ubuntu 22.04

NuttX Version

master (e4ca1a2)

Issue Architecture

[Arch: arm]

Issue Area

[Area: Drivers]

Host information

No response

Verification

• I have verified before submitting the report.

[xiaoxiang781216]

@yangsong8-a1 please look at this problem.

[yangsong8-a1]

@SPRESENSE After the problem occurred, the log will always miss data. Is it impossible to recover? I will try to reproduce this issue.

[SPRESENSE]

@yangsong8-a1 No, after some strings are lost, it works correctly thereafter.

[acassis]

@xiaoxiang781216 @SPRESENSE it should be nice to include an automated test to catch this failure, this way case it happen again we will be alerted

[yangsong8-a1]

@SPRESENSE Based on this patch #15931, I tested it in sim:usbdev and esp32s3-devkit:usb_device for about 11 hours. Then I analyzed the output log and found no problems.

I used a python script to analy the output. This python script will remove duplicate content and keep a copy of the first occurrence in the output file.

  1 def remove_duplicate_lines_with_line_numbers(input_file, output_file):
  2     # save line number
  3     lines = []
  4     seen_lines = {}
  5     
  6     with open(input_file, 'r') as f:
  7         for i, line in enumerate(f, start=1):
  8             stripped_line = line.strip()
  9             lines.append((line, i))
 10     
 11     unique_lines = []
 12     for line, line_number in lines:
 13         stripped_line = line.strip()
 14         if stripped_line:
 15             if stripped_line not in seen_lines:
 16                 seen_lines[stripped_line] = line_number
 17                 unique_lines.append((line, line_number))
 18         else:
 19             unique_lines.append((line, line_number))  # keep space line
 20     
 21     # Write unique lines to the output file and label them with line numbers
 22     with open(output_file, 'w') as f:
 23         for line, line_number in unique_lines:
 24             stripped_line = line.strip()
 25             if stripped_line:
 26                 f.write(f"Line {line_number}: {line}")
 27             else:
 28                 f.write(line)  # keep space line                                                                                                                                                                                                                                      
 29 
 30 if __name__ == "__main__":
 31     input_file = "cdcacm_esp32.log"
 32     output_file = "esp32_py_enhance.txt"
 33     remove_duplicate_lines_with_line_numbers(input_file, output_file)

Did you compile the project using the spresense:rndis_composite configuration?

[yangsong8-a1]

@SPRESENSE What serial port receiving tool are you using? Could you try this command and test again? thank you.
cat /dev/ttyACM0 | tee cdcacm_esp32.log

[yangsong8-a1]

@SPRESENSE I find a apresense board. After I use flash_writer.py to flash image, the system can not run with a serial log:

[    0.000000] cxd56_farapiinitialize: Mismatched version: loader(20585) != Self(20596) 
[    0.000000] cxd56_farapiinitialize: Please update loader and gnssfw firmwares!!

I find a bootloader form https://developer.sony.com/file/download/download-spresense-firmware-v3-3-0, and update it.
Another issue occur: spresense:rndis_composite and spresense:rndis still not work and with nothing serial log.
Is it a bootloader problem? Which version should I use?

[acassis]

@yangsong8-a1 I had and fixed this issue:

https://acassis.wordpress.com/2023/03/24/compiling-and-flashing-nuttx-on-sony-spresense-board/

You need to update the board bootloader, dnnrt, gnns, etc, otherwise this error will happen!

[SPRESENSE]

@yangsong8-a1
I find when priv->wrcontainer == NULL therefore cdcacm_sndpacket() is executed. the problem of lost write messages occurs.
I still don't know why it fails into this condition. How about esp32s3-devkit? Is this line executed?

nuttx/drivers/usbdev/cdcacm.c

Lines 1096 to 1099 in 809de89

	if (priv->wrcontainer == NULL)
	{
	cdcacm_sndpacket(priv);
	}

[SPRESENSE]

@yangsong8-a1 Thanks for your support.

I found this issue in our application with Spresense SDK.
Here is the procedure to reproduce it in the NuttX-only environment on a Spresense board.

• defconfig configuration
  defconfig.txt

• It's necessary to patch for boot.

diff --git a/sched/clock/clock_systime_ticks.c b/sched/clock/clock_systime_ticks.c
index a99d8e1040..46d9b5cba2 100644
--- a/sched/clock/clock_systime_ticks.c
+++ b/sched/clock/clock_systime_ticks.c
@@ -77,7 +77,7 @@

 clock_t clock_systime_ticks(void)
 {
-#ifdef CONFIG_RTC_HIRES
+#if defined(CONFIG_RTC_HIRES) && !defined(CONFIG_CXD56_RTC_LATEINIT)
   struct timespec ts =
     {
       0

• Run usbserial

nsh> usbserial

• This is the result that your python script executed.

Line 1: The Spanish Armada a Speech by Queen Elizabeth I of England
Line 2: Addressed to the English army at Tilbury Fort - 1588
Line 3: My loving people, we have been persuaded by some, that are careful of our safety, to take heed how we commit ourselves to armed multitudes, or fear of treachery; but I assure you, I do not desire to live to distrust my faithful and loving people.
Line 4: Let tyrants fear; I have always so behaved myself that, under God, I have placed my chiefest strength and safeguard in the loyal hearts and good will of my subjects. And therefore I am come amongst you at this time, not as for my recreation or sport, but being resolved, in the midst and heat of the battle, to live or die amongst you all; to lay down, for my God, and for my kingdom, and for my people, my honour and my blood, even the dust.
Line 5: I know I have but the body of a weak and feeble woman; but I have the heart of a king, and of a king of England, too; and think foul scorn hat Parma or Spain, or any prince of Europe, should dare to invade the borders of my realms: to which, rather than any dishonour should grow by me, I myself will take up arms; I myself will be your general, judge, and rewarder of every one of your virtues in the field.
Line 6: I know already, by your forwardness, that you have deserved rewards and crowns; and we do assure you, on the word of a prince, they shall be duly paid you. In the mean my lieutenant general shall be in my stead, than whom never prince commanded a more noble and worthy subject; not doubting by your obedience to my general, by your concord in the camp, and by your valour in the field, we shall shortly have a famous victory over the enemies of my God, of my kingdom, and of my people.
Line 223: port, but being resolved, in the midst and heat of the battle, to live or die amongst you all; to lay down, for my God, and for my kingdom, and for my people, my honour and my blood, even the dust.

[yangsong8-a1]

@yangsong8-a1 I had and fixed this issue:

https://acassis.wordpress.com/2023/03/24/compiling-and-flashing-nuttx-on-sony-spresense-board/

You need to update the board bootloader, dnnrt, gnns, etc, otherwise this error will happen!

@acassis @SPRESENSE thank you, refer to the method you provided, I tried updating multiple versions of loader:

1. This problem still occurs when loader version form 2.0.0 to 3.2.0.
2. When using version 3.3, this updating loader log does not appear. and the spresense:nsh configuration can be executed normally. But the rndis and rndis_composite configuration cannot enter nsh normally, and the usbmsc configuration cannot recognize the USB device. I try rndis_composite configuration, because it contain cdcacm.

So the USB on my board is not running properly yet.
I am using this board. Do I need to set any special hardware settings? For example, jumpers.