[DONE] STM32F107 USB hangs

panacekcz · Post by **panacekcz** » Mon Jan 13, 2014 4:55 pm

Hi,
I am trying to use USB serial. I use custom board with STM32F107, 16 MHz HSE, ChibiOS 2.6.2, GCC.

The program I use is based on the USB demo

Code: Select all

int main(void) {
  halInit();
  chSysInit();
  sduObjectInit(&SDU1);
  sduStart(&SDU1, &serusbcfg);
  usbDisconnectBus(serusbcfg.usbp);
  chThdSleepMilliseconds(1000);
  usbStart(serusbcfg.usbp, &usbcfg);
  usbConnectBus(serusbcfg.usbp);
  for(;;){
   //could be anything here (echoing the byte, blinking led, ...)
   chnGetTimeout(&SDU1, 1000); 
  }
}

I use this testing script (in Linux):

Code: Select all

while true
do echo "X" > /dev/ttyACM0 # Open the serial USB and close it again
echo "OK" # Write to the terminal to see that it works
done

The script works for a random number of cycles and then starts to report IO errors - it hangs when opening the file (there is some communication when opening it).
(If I open cat /dev/ttyACM0 in another terminal, then this communication does not happen every time the file is opened for writing and everything works fine. So I think it never occurs when transferring data but only when opening and closing.)
The main program on the board continues to run normally (blinking LED or whatever).
When I pause the program in debugger after it hangs, I see that usbp->ep0state is USB_EP0_SENDING_STS and usbp->transmitting is (mostly) 1. I suspect this can be the problematic state because if I pause it before it hangs, usbp->ep0state is usually USB_EP0_WAITING_SETUP. But I don't understand those states very much.

At first I used -Os and running from RAM, but now I use -O0 and the common linker script and the problem happens too although usually later than when running from RAM.

I don't know how to continue now, maybe if someone could try to reproduce it. Before sending this post I tried using as much original source from /ChibiOS_2.6.2/testhal/STM32F1xx/USB_CDC_F107 as possible, I only changed the LED pin, board.c and board.h, and clock settings in mcuconf.h. It can run OK for some minutes, but eventually hangs too.

Post by **Giovanni** » Mon Jan 13, 2014 5:47 pm

Hi,

The USB driver has internally a worker thread operating at very low priority, if the main() thread never goes into a sleep state then the worker thread is starved and the USB does not work.

Could this be your case?

Also, are the debugging options enabled in chconf.h?

Giovanni

panacekcz · Post by **panacekcz** » Mon Jan 13, 2014 7:43 pm

Hi,
all the CH_DBG_ macros in chconf.h are TRUE.
I tried more variants of the main thread. It can be:

Code: Select all

for(;;){
 chThdSleepMilliseconds(1000);
 palTogglePad(GPIOC, GPIOC_LED13);
 }

That is not much activity and the problem still happens. I even tried:

Code: Select all

chThdExit(0);

Or setting the USB thread priority to HIGHPRIO.

I also simplified the BASH test script, so that it does not send any data (so the application doesn't have to process them).

Code: Select all

x=0
while true
do touch /dev/ttyACM0 
echo "OK" $x
x=$[x+1]
done

It also shows the number of open/close cycles, which is random, but seems to depend on compile options and maybe other things.
The example in ChibiOS_2.6.2/testhal/STM32F1xx/USB_CDC_F107 (with -O2) can survive 10000 cycles, in the "minimal program" I created, with -Os or -O0, it is around 100, and the program I originally had (with -Os too) usually died before 10 cycles which is why I started to investigate this.
Or is -Os not supported? With -O2 I can probably get enough cycles not to notice the problem in practice but I wanted to save space because it is a bootloader.

Post by **Giovanni** » Mon Jan 13, 2014 7:49 pm

Compiler options should not matter.

Does your application consume the X you send? are you sure to consume all the sent X? meaning you have to attempt a read until the queue is reported empty.

Giovanni

panacekcz · Post by **panacekcz** » Mon Jan 13, 2014 10:23 pm

Hi, thanks for the replies!

It's true I am not consuming the X, but with the second version of the script, I am not even sending them. I am just opening and closing the file.
But to be 100% sure, I changed the main loop to this:

Code: Select all

for(;;){
 chnGetTimeout(&SDU1, TIME_INFINITE);
}

I can't imagine a safer version - it reads all the data and suspends when there are not any.

Furthermore, to be sure I am not too fast, I inserted a sleep to the test script.

Code: Select all

#!/bin/bash
x=0
while true
do touch /dev/ttyACM0 
sleep 1
echo "OK" $x
x=$[x+1]
done

Now it is not faster than one open/close per second, not sending any real data. And it still fails after ~200 cycles.
I am getting more convinced that there is always some probability that opening/closing would trigger the error. And in the program I was developing it got so high I started noticing it even when communicating by hand.

Before submitting this post I even tried inserting another 1-second sleep between opening and closing the file. It worked for 800 cycles (half an hour) but then failed.

Also, here is what I get from usbmon, if it could help somehow.
A successful open/close.

Code: Select all

ffff88006ae30d80 3322959924 S Ii:6:011:2 -115:128 8 <
ffff8800637f3300 3322959942 S Co:6:011:0 s 21 22 0003 0000 0000 0
ffff8800637f3300 3322961428 C Co:6:011:0 0 0
ffff88007a5fa500 3322961468 S Bi:6:011:1 -115 128 <
ffff88007a5faec0 3322961481 S Bi:6:011:1 -115 128 <
ffff88007a8b3800 3322961485 S Bi:6:011:1 -115 128 <
ffff88007a8a0f00 3322961488 S Bi:6:011:1 -115 128 <
ffff880036b29680 3322961493 S Bi:6:011:1 -115 128 <
ffff880036b29980 3322961498 S Bi:6:011:1 -115 128 <
ffff880036b29800 3322961502 S Bi:6:011:1 -115 128 <
ffff880036b29ec0 3322961505 S Bi:6:011:1 -115 128 <
ffff88007a04ad80 3322961510 S Bi:6:011:1 -115 128 <
ffff88007a5fa2c0 3322961514 S Bi:6:011:1 -115 128 <
ffff88007a5fa440 3322961517 S Bi:6:011:1 -115 128 <
ffff88007a5fac80 3322961522 S Bi:6:011:1 -115 128 <
ffff88007a5faa40 3322961526 S Bi:6:011:1 -115 128 <
ffff88007a5fa380 3322961530 S Bi:6:011:1 -115 128 <
ffff88007a8a06c0 3322961534 S Bi:6:011:1 -115 128 <
ffff88007a5fa140 3322961537 S Bi:6:011:1 -115 128 <
ffff8800637f3300 3322961716 S Co:6:011:0 s 21 22 0000 0000 0000 0
ffff8800637f3300 3322962425 C Co:6:011:0 0 0
ffff88006ae30d80 3322963424 C Ii:6:011:2 -2:128 0
ffff88007a5fa500 3322964423 C Bi:6:011:1 -2 0
ffff88007a5faec0 3322965422 C Bi:6:011:1 -2 0
ffff88007a8b3800 3322966423 C Bi:6:011:1 -2 0
ffff88007a8a0f00 3322967424 C Bi:6:011:1 -2 0
ffff880036b29680 3322968422 C Bi:6:011:1 -2 0
ffff880036b29980 3322969403 C Bi:6:011:1 -2 0
ffff880036b29800 3322970421 C Bi:6:011:1 -2 0
ffff880036b29ec0 3322971433 C Bi:6:011:1 -2 0
ffff88007a04ad80 3322972433 C Bi:6:011:1 -2 0
ffff88007a5fa2c0 3322973424 C Bi:6:011:1 -2 0
ffff88007a5fa440 3322974425 C Bi:6:011:1 -2 0
ffff88007a5fac80 3322975424 C Bi:6:011:1 -2 0
ffff88007a5faa40 3322976422 C Bi:6:011:1 -2 0
ffff88007a5fa380 3322977424 C Bi:6:011:1 -2 0
ffff88007a8a06c0 3322978423 C Bi:6:011:1 -2 0
ffff88007a5fa140 3322979423 C Bi:6:011:1 -2 0

1 second later, a problem occurs when closing (note the 5-second delay and -2 response from ep 0)

Code: Select all

ffff88006ae30d80 3323983377 S Ii:6:011:2 -115:128 8 <
ffff88006aaf5b00 3323983393 S Co:6:011:0 s 21 22 0003 0000 0000 0
ffff88006aaf5b00 3323984450 C Co:6:011:0 0 0
ffff88007a5fa500 3323984474 S Bi:6:011:1 -115 128 <
ffff88007a5faec0 3323984479 S Bi:6:011:1 -115 128 <
ffff88007a8b3800 3323984481 S Bi:6:011:1 -115 128 <
ffff88007a8a0f00 3323984483 S Bi:6:011:1 -115 128 <
ffff880036b29680 3323984486 S Bi:6:011:1 -115 128 <
ffff880036b29980 3323984488 S Bi:6:011:1 -115 128 <
ffff880036b29800 3323984490 S Bi:6:011:1 -115 128 <
ffff880036b29ec0 3323984493 S Bi:6:011:1 -115 128 <
ffff88007a04ad80 3323984495 S Bi:6:011:1 -115 128 <
ffff88007a5fa2c0 3323984497 S Bi:6:011:1 -115 128 <
ffff88007a5fa440 3323984499 S Bi:6:011:1 -115 128 <
ffff88007a5fac80 3323984501 S Bi:6:011:1 -115 128 <
ffff88007a5faa40 3323984504 S Bi:6:011:1 -115 128 <
ffff88007a5fa380 3323984506 S Bi:6:011:1 -115 128 <
ffff88007a8a06c0 3323984508 S Bi:6:011:1 -115 128 <
ffff88007a5fa140 3323984511 S Bi:6:011:1 -115 128 <
ffff88006aaf5b00 3323984591 S Co:6:011:0 s 21 22 0000 0000 0000 0
ffff88006aaf5b00 3328982559 C Co:6:011:0 -2 0
ffff88006ae30d80 3328983555 C Ii:6:011:2 -2:128 0
ffff88007a5fa500 3328984557 C Bi:6:011:1 -2 0
ffff88007a5faec0 3328985557 C Bi:6:011:1 -2 0
ffff88007a8b3800 3328986554 C Bi:6:011:1 -2 0
ffff88007a8a0f00 3328987554 C Bi:6:011:1 -2 0
ffff880036b29680 3328988553 C Bi:6:011:1 -2 0
ffff880036b29980 3328989556 C Bi:6:011:1 -2 0
ffff880036b29800 3328990553 C Bi:6:011:1 -2 0
ffff880036b29ec0 3328991554 C Bi:6:011:1 -2 0
ffff88007a04ad80 3328992554 C Bi:6:011:1 -2 0
ffff88007a5fa2c0 3328993555 C Bi:6:011:1 -2 0
ffff88007a5fa440 3328994552 C Bi:6:011:1 -2 0
ffff88007a5fac80 3328995556 C Bi:6:011:1 -2 0
ffff88007a5faa40 3328996556 C Bi:6:011:1 -2 0
ffff88007a5fa380 3328997557 C Bi:6:011:1 -2 0
ffff88007a8a06c0 3328998554 C Bi:6:011:1 -2 0
ffff88007a5fa140 3328999555 C Bi:6:011:1 -2 0

All following attempts fail.

Code: Select all

ffff88006ae30d80 3330005302 S Ii:6:011:2 -115:128 8 <
ffff88006aaf5b00 3330005319 S Co:6:011:0 s 21 22 0003 0000 0000 0
ffff88006aaf5b00 3335006681 C Co:6:011:0 -2 0
ffff88006aaf5b00 3335006741 S Co:6:011:0 s 21 22 0000 0000 0000 0
ffff88006aaf5b00 3340006799 C Co:6:011:0 -2 0
ffff88006ae30d80 3340007796 C Ii:6:011:2 -2:128 0

Vlastimil Dort

Post by **Giovanni** » Mon Jan 13, 2014 11:12 pm

Not sure how to read those logs. What is the message sent on close? there is no real open/close operations, it must be some CDC-specific message, may be an unimplemented message that then hangs the endpoint.

Note that not all the possible CDC messages are implemented in Serial_USB.

Giovanni

panacekcz · Post by **panacekcz** » Tue Jan 14, 2014 2:06 pm

Hi, thanks for the reply.
I looked it up in linux driver source. It is SET_CONTROL_LINE_STATE (0x22) request.
In acm_tty_open it sets it to 3 (ACM_CTRL_DTR | ACM_CTRL_RTS), in acm_port_down it sets it to 0.

I see this is handled in sduRequestsHook with zero-sized response. This takes it to the USB_EP0_SENDING_STS state.

I tried to inspect the usb driver by debugger and UART outputs and this came to my attention

Code: Select all

static void otg_epin_handler(USBDriver *usbp, usbep_t ep) {
  stm32_otg_t *otgp = usbp->otg;
  uint32_t epint = otgp->ie[ep].DIEPINT;
  otgp->ie[ep].DIEPINT = 0xFFFFFFFF;

I think you might be missing interrupts here. I tried:

Code: Select all

  otgp->ie[ep].DIEPINT = epint;

Seems to solve the problem!

Vlastimil Dort

Post by **Giovanni** » Tue Jan 14, 2014 4:24 pm

Hi,

I need to go examine that code carefully, marking the thread as TODO.

Giovanni

Post by **Giovanni** » Sat Jan 18, 2014 9:59 am

Hi,

Thanks for finding, the fix has been committed on the repositor and tracked as bug #457. There was another similar error in otg_epout_handler(), I fixed this one as well.

Could you confirm that the current code is working for you?

Giovanni

panacekcz · Post by **panacekcz** » Sun Jan 19, 2014 10:22 am

Hi,
now everything works as expected. Thank you.
Vlastimil Dort

ChibiOS Free Embedded RTOS

[DONE] STM32F107 USB hangs

[DONE] STM32F107 USB hangs

Re: STM32F107 USB hangs

Re: STM32F107 USB hangs

Re: STM32F107 USB hangs

Re: STM32F107 USB hangs

Re: STM32F107 USB hangs

Re: STM32F107 USB hangs

Re: STM32F107 USB hangs

Re: [TODO] STM32F107 USB hangs

Re: [DONE] STM32F107 USB hangs