ChibiOS Free Embedded RTOS

Posted: **Sat Aug 08, 2015 4:06 am**

Hi,
I'm currently experimenting with using NIL + USB CDC on a STM32F042 for a customizable serial / USB adapter. I have encountered a strange intermittent failure that seems to appear (not quite sure) when stopping picocom (e.g., issue not specific to picocom) and restarting it without reconnecting the USB. The issue appears (i.e. assertion fails), when reattaching, not when stopping the terminal program. The issue is highly intermittent but I encountered it ~30 times. I'm using the current HAL from git. I have only tested on a Linux host (Ubuntu 14.04 x64)

Code: Select all

chSysHalt (reason=reason@entry=0x80023e0 <__func__.4955> "osalThreadDequeueAllI") at /home/uli/dev/ChibiTest/ChibiOS/os/nil/src/nil.c:127
(gdb) bt
#0  chSysHalt (reason=reason@entry=0x80023e0 <__func__.4955> "osalThreadDequeueAllI") at /home/uli/dev/ChibiTest/ChibiOS/os/nil/src/nil.c:127
#1  0x0800076a in osalThreadDequeueAllI (tqp=tqp@entry=0x20000714 <SDU1+52>, msg=msg@entry=0x0) at /home/uli/dev/ChibiTest/ChibiOS/os/hal/osal/nil/osal.c:102
#2  0x08000814 in usb_packet_write_from_queue.lto_priv.30 (udp=<optimized out>, oqp=0x20000714 <SDU1+52>, n=<optimized out>) at /home/uli/dev/ChibiTest/ChibiOS/os/hal/ports/STM32/LLD/USBv1/us
b_lld.c:254
#3  0x080010b6 in usb_lld_prepare_transmit (usbp=<optimized out>, ep=<optimized out>) at /home/uli/dev/ChibiTest/ChibiOS/os/hal/ports/STM32/LLD/USBv1/usb_lld.c:719
#4  0x08001c0c in usbPrepareQueuedTransmit (usbp=<optimized out>, ep=<optimized out>, oqp=<optimized out>, n=<optimized out>) at /home/uli/dev/ChibiTest/ChibiOS/os/hal/src/usb.c:489
#5  0x080015fc in sduDataTransmitted (usbp=0x2000065c <USBD1>, ep=<optimized out>) at /home/uli/dev/ChibiTest/ChibiOS/os/hal/src/serial_usb.c:358
#6  0x08000b42 in VectorBC () at /home/uli/dev/ChibiTest/ChibiOS/os/hal/ports/STM32/LLD/USBv1/usb_lld.c:367
#7  <signal handler called>
#8  0x55555554 in ?? ()

Code: Select all

$4 = {
  ctxp = 0x20001144 <serialThreadWA+492>, 
  state = 0x0, 
  u1 = {
    msg = 0x0, 
    p = 0x0, 
    trp = 0x0, 
    semp = 0x0, 
    ewmask = 0x0
  }, 
  timeout = 0x0, 
  epmask = 0x0
}

Failed assertion:

Code: Select all

chDbgAssert(NIL_THD_IS_WTSEM(tr), "not waiting");

In frame 1 (in osalThreadDequeueAllI):

Code: Select all

(gdb) i loc
sp = 0x20000714 <SDU1+52>
tr = 0x20000514 <nil+12>
__func__ = "osalThreadDequeueAllI"

In frame 2:

Code: Select all

(gdb) p oqp->q_waiting
$8 = {
  sem = {
    cnt = 0x0
  }
}

Note that cnt is NOT representative here because it is changed by osalThreadDequeueAllI. I have verified cnt to be -1 when entering the function.

Thread code (works besides this bug. Whoever wants to use it, may do so unter Apache License v2.0):

Code: Select all

sdStart(&SD2, &serialCfg);

  /*
   * Initializes a serial-over-USB CDC driver.
   */
  sduObjectInit(&SDU1);
  sduStart(&SDU1, &serusbcfg);

  usbDisconnectBus(serusbcfg.usbp);
  chThdSleepMilliseconds(200);
  usbStart(serusbcfg.usbp, &usbcfg);
  usbConnectBus(serusbcfg.usbp);
  chThdSleepMilliseconds(200);

  while (true) {
    if(USBD1.state == USB_ACTIVE) { //ep0next --> terminal conn'd
      chSysLock();
      size_t qsize = qSpaceI(&SD2.iqueue);
      chSysUnlock();
      if(qsize > 0) { //Queue not empty
        msg_t read = sdReadTimeout(&SD2, (uint8_t*)rxBuf, qsize, MS2ST(1));
        if(read != Q_TIMEOUT && read != Q_RESET && read > 0) {
          sdWriteTimeout(&SDU1, (uint8_t*)rxBuf, read, MS2ST(1));
        }
        chThdSleepMicroseconds(500); //Wait for some data
      } else {
        chThdSleepMicroseconds(500); //Wait for some data
      }
    } else {
      chThdSleepMilliseconds(1);
    }
  }

NIL_CFG_NUM_THREADS = 1.

I'm not really sure where to look for the underlying issue. In general I believe this might be an issue inside the USB CDC as I would consider repeated restarts of the terminal program a rarely tested circumstance. I can debug via GDB etc.

Any help would be appreciated.

Best regards, Uli

Posted: **Sat Aug 08, 2015 7:42 am**

Hi,

Hard to tell, NIL does not have yet the state checker so not all problems are caught. Would be difficult to try the same code using RT?

In general are all I-class and S-class invoked from critical zones?

Giovanni

Posted: **Sat Aug 08, 2015 12:55 pm**

Hi Giovanni,
yes, unfortunately using RT is impossible right now because the board uses a STM32F042F4P6 which has only 16 kiB flash. With USB & CDC, RT is just too large to fit on that (which is why I use NIL).

However, I'll get my hands on a USB-enabled board using the STM32L151 with 32+ kiB flash in the next week or so. I will try testing it with that board. Until then, I'll try debugging it in the source code.

Thanks for the tip with I/S class functions. I double-checked that: No S-class functions are called and the only two I-class functions are called from ISR lock zones.

Best regards, Uli

Posted: **Sat Aug 08, 2015 1:07 pm**

OK, let me know, I am worried about a possible bug in NIL and want to know if that is the case.

Giovanni

Posted: **Sun Aug 16, 2015 2:14 am**

I got the board but I still can't reliably program it (not a ChibiOS-related problem) so I don't have any results yet.
However, when experimenting around with the source code I noticed that when using

Code: Select all

void setLineCodingHook() {
    //Something is connecting. Empty the buffer.
    chSysLockFromISR();
    oqResetI(&SDU1.oqueue);
    iqResetI(&SD2.iqueue);
    chSysUnlockFromISR();
}

I get this stacktrace:

Code: Select all

#0  chSysHalt (reason=reason@entry=0x8002520 <__func__.4955> "osalThreadDequeueAllI") at /home/uli/dev/MOMSensors/ChibiOS/os/nil/src/nil.c:127
#1  0x080009fa in osalThreadDequeueAllI (tqp=tqp@entry=0x200011f4 <SD2+20>, msg=msg@entry=0xfffffffe) at /home/uli/dev/MOMSensors/ChibiOS/os/hal/osal/nil/osal.c:102
#2  0x08001f14 in iqResetI (iqp=iqp@entry=0x200011f4 <SD2+20>) at /home/uli/dev/MOMSensors/ChibiOS/os/hal/src/hal_queues.c:89
#3  0x08001dc4 in setLineCodingHook () at /home/uli/dev/MOMSensors/applications/RS485i/main.c:147
#4  0x08001e02 in customSduRequestsHook (usbp=<optimized out>) at /home/uli/dev/MOMSensors/drivers/SerialUSB/SerialUSB.c:28
#5  0x0800170e in _usb_ep0setup (usbp=0x20000de0 <USBD1>, ep=<optimized out>) at /home/uli/dev/MOMSensors/ChibiOS/os/hal/src/usb.c:649
#6  0x08000f88 in VectorBC () at /home/uli/dev/MOMSensors/ChibiOS/os/hal/ports/STM32/LLD/USBv1/usb_lld.c:376
#7  <signal handler called>
#8  0x55555554 in ?? ()

This error can reliably be reproduced. It kicks in almost immediately after flashing the firmware. I believe this points to some kind of state checker issue.

Best regards, Uli

Posted: **Sun Aug 16, 2015 3:25 am**

I believe I found at least the issue. It does not seem to have any relation to the state checker:
Note that I have set NIL_CFG_NUM_THREADS.

Lets look at the function osalThreadDequeueAllI(). Note that tqp is the thread queue of SD2.

a) let's assume sp->cnt = 0. This means that no thread is waiting on the semaphore. This is a realistic scenario in my original bug (when reconnecting picocom several times) as the main (and only) thread often sleeps (however, every now and then it will wait on data). In this scenario the loop (and therefore the assertion in question) will never be executed --> No fail

b) Let's assume sp->cnt = -1. This is the ONLY other possible scenario as we only have one thread. This means the thread is waiting for something to happen to the SD2 semaphore. The code is correct. Due to deterministic timing at startup, with the new code with iqResetI(), cnt = -1 in 100% of the cases as the main thread will wait 100 ms for anything to happen on SD2. This means that iqReset() and therefore osalThreadDequeueAllI() will be deterministically executed when &nil.threads[0] is waiting on SD2.

This triggers the bug (exact trigger conditions seem to be: thread index of waiting thread = NIL_CFG_NUM_THREADS - 1 and cnt = 1)

At the start of the loop in osalThreadDequeueAllI, tr is nil.threads[0]. This is correct and in this case this represents the waiting thread. Therefore, osalThreadDequeueAllI() will correctly evaluate (tr->u1.semp == sp) to true and execute the branch (chSchReadyI and so on). Let's look at after the branch: tr++. This means that if tr was &nil.threads[0] before, it is now &nil.threads[1] whether or not the branch was executed.

The assertion states that (tr < &nil.threads[NIL_CFG_NUM_THREADS]) must be true, i.e. in our case (tr < &nil.threads[1]). However, we deduced above that in our case tr is &nil.threads[1], falsely triggering the assertion.

*How to fix*
I believe it is not a good idea at all to change the assertion to (tr <= &nil.threads[NIL_CFG_NUM_THREADS]), even if nil.threads has 1 extra element (i.e. no hardfault is expected). Instead, I recommend adding a if (cnt == 0) {break;} branch after chSchReadyI() (cnt++ is called just before chSchReadyI())

Code: Select all

void osalThreadDequeueAllI(threads_queue_t *tqp, msg_t msg) {
  semaphore_t *sp = &tqp->sem;
  thread_reference_t tr;
  cnt_t cnt;

  cnt = sp->cnt;
  sp->cnt = (cnt_t)0;
  tr = nil.threads;
  while (cnt < (cnt_t)0) {
    /* Is this thread waiting on this semaphore?*/
    if (tr->u1.semp == sp) {

      chDbgAssert(NIL_THD_IS_WTSEM(tr), "not waiting");

      cnt++;
      (void) chSchReadyI(tr, msg);
      if(cnt == 0) {
        break;
      }
    }
    tr++;

    chDbgAssert(tr < &nil.threads[NIL_CFG_NUM_THREADS],
                "pointer out of range");
  }
}

For me, this apparently fixed the bug and I think my explanation sounds reasonable.

This bug can very easily be missed if the last thread in the thread table NEVER waits on some queue with a non-timeout/non-reset result.

This is what I believe caused the issue. I don't think it is possible that chSchReadyI does some weird magic, because it just sets some pointers and other variables so the scheduler knows what to do.

FYI: Not sure if this will help but I believe one can implement a crude checker on Cortex-Mx using PRIMASK. Test code:

Code: Select all

  volatile uint32_t p1 = __get_PRIMASK();
  chSysLock();
  volatile uint32_t p2 = __get_PRIMASK();
  chSysUnlock();
  volatile uint32_t p3 = __get_PRIMASK();
  __BKPT();

Result on M0:

Code: Select all

(gdb) i loc
p1 = 0x0
p2 = 0x1
p3 = 0x0

Best regards, Uli

Posted: **Sun Aug 16, 2015 10:19 pm**

Thanks for all the analysis, tomorrow I will give it a try.

Giovanni

Posted: **Mon Aug 17, 2015 3:26 pm**

Just a question, is your main() function just an empty loop?

Giovanni

Posted: **Mon Aug 17, 2015 3:30 pm**

Yes, after the initialization it is:

Code: Select all

int main(void) {
  //iwdgInit();
  //iwdgStart(&IWDGD, &iwdgConfig);
  //System initialization
  halInit();
  chSysInit();


  /**
   * Remap PA11/PA12 pins
   */
  SYSCFG->CFGR1 |= SYSCFG_CFGR1_PA11_PA12_RMP;

  while(true) {
  }
}

The remap ist required because the STM32F042F4P6 in TSSOP20 package has the USB pins multiplexed with some other pins.

Best regards, Uli

Posted: **Sat Aug 22, 2015 9:54 am**

Hi,

Sorry for the delay, I have been out of "office" for some days.

Added a ticket: https://sourceforge.net/p/chibios/bugs/633/ (bug #633).

What about changing the code like this?

Code: Select all

void osalThreadDequeueAllI(threads_queue_t *tqp, msg_t msg) {
  semaphore_t *sp = &tqp->sem;
  thread_reference_t tr;
  cnt_t cnt;

  cnt = sp->cnt;
  sp->cnt = (cnt_t)0;
  tr = nil.threads;
  while (cnt < (cnt_t)0) {

    chDbgAssert(tr < &nil.threads[NIL_CFG_NUM_THREADS],
                "pointer out of range");

    /* Is this thread waiting on this semaphore?*/
    if (tr->u1.semp == sp) {

      chDbgAssert(NIL_THD_IS_WTSEM(tr), "not waiting");

      cnt++;
      (void) chSchReadyI(tr, msg);
    }
    tr++;
  }
}

This should avoid the extra check, could you give it a try?

BTW, the same problem also affects chSemResetI() which uses a similar loop.

Giovanni

ChibiOS Free Embedded RTOS

USB CDC + NIL osalThreadDequeueAllI assertion fail

USB CDC + NIL osalThreadDequeueAllI assertion fail

Re: USB CDC + NIL osalThreadDequeueAllI assertion fail

Re: USB CDC + NIL osalThreadDequeueAllI assertion fail

Re: USB CDC + NIL osalThreadDequeueAllI assertion fail

Re: USB CDC + NIL osalThreadDequeueAllI assertion fail

Re: USB CDC + NIL osalThreadDequeueAllI assertion fail

Re: USB CDC + NIL osalThreadDequeueAllI assertion fail

Re: USB CDC + NIL osalThreadDequeueAllI assertion fail

Re: USB CDC + NIL osalThreadDequeueAllI assertion fail

Re: USB CDC + NIL osalThreadDequeueAllI assertion fail