xtimer: timer already in the list

[immesys]

I initially reported this on the mailing list, but I figured I should add an issue.

I was getting strange lockups on my nodes, and managed to work out that a timer was being inserted into the list when it was already in the list, which would cause an infinite loop here

I modified the function with this inside the while loop:

if (*list_head == timer || (*list_head)->next == timer){
   disableIRQ();
   while(1);
}

And waited to see where the invocation was coming from. It triggered (on the second condition in the if statement), and this was the call chain:

#0  _add_timer_to_list (list_head=0x200021ac <sampling_stack+1755>, list_head@entry=0x20000630 <timer_list_head>, timer=timer@entry=0x2000148c <comms_stack+1832>) at //sys/xtimer/xtimer_core.c:226
#1  0x00000d12 in _xtimer_set_absolute (timer=0x2000148c <comms_stack+1832>, target=1963159872) at //sys/xtimer/xtimer_core.c:197
#2  0x00000dec in xtimer_set (timer=timer@entry=0x2000148c <comms_stack+1832>, offset=offset@entry=1000000) at //sys/xtimer/xtimer_core.c:133
#3  0x00000a4e in xtimer_set_msg (target_pid=<optimized out>, msg=0x20001484 <comms_stack+1824>, offset=1000000, timer=0x2000148c <comms_stack+1832>) at //sys/xtimer/xtimer.c:124
#4  xtimer_msg_receive_timeout (msg=msg@entry=0x200014bc <comms_stack+1880>, us=us@entry=1000000) at //sys/xtimer/xtimer.c:200
#5  0x00001c94 in comms (arg=<optimized out>) at //Apps/accel/main.c:192
#6  0x00000288 in sched_switch (other_prio=<optimized out>) at //core/sched.c:180
#7  0x20001404 in comms_stack ()

The comms thread looks basically like this (I am working on isolated reproducer):

msg_t dns_msg; //type set to MSG_TYPE_DNS_TIMER once in main
xtimer_t dns_timer; //nobody else uses this
void *comms(void *arg)
{
  msg_t msg;
  msg_init_queue(_comms_msg_queue, COMMS_QUEUE_SIZE);
  gnrc_netreg_entry_t entry = { NULL, 4041, thread_getpid() };
  gnrc_netreg_register(GNRC_NETTYPE_UDP, &entry))
  while(1) {
    if (xtimer_msg_receive_timeout(&msg, NETWORK_MAXRTT_US) < 0)
      msg.type = MSG_TYPE_MUST_TX; //default to resending old packet
    switch(msg.type) {
      case GNRC_NETAPI_MSG_TYPE_RCV: {
          /* snip */
          gnrc_pktbuf_release((gnrc_pktsnip_t *) msg.content.ptr);
          //Deliberately do not break
      }
      case MSG_TYPE_MUST_TX: { //Sent every ~100ms from sampling_thread
          /* snip building packet 'ip' */
          gnrc_netapi_dispatch_send(GNRC_NETTYPE_UDP, GNRC_NETREG_DEMUX_CTX_ALL, ip)
          break;
      }
      case MSG_TYPE_DNS_TIMER: { //sent once by main, otherwise only to ourselves
        update_dns_record(); //Sends a UDP packet, like above
        xtimer_set_msg(&dns_timer, DNS_INTERVAL, &dns_msg, thread_getpid());
        break;
      }
    } //end switch
  } //end while
} //endfun

So essentially the xtimer_msg_receive_timeout(&msg, NETWORK_MAXRTT_US) is sometimes causing a stack-allocated timer to appear in the timer list twice. This is pretty interesting considering that there is a call to remove the timer earlier in the call chain, although they are in different critical sections, so maybe something is happening between them.

I will do my best to reproduce this with a small application that runs on the SAMR21-xpro.

Also, apologies if this is user error, I am still getting the hang of RIOT.

[kaspar030]

I managed to trigger a timer that is twice in xtimer's list, but by intentionally setting the same timer concurrently from user and ISR context.

@immesys Did you succeed in creating a small reproducer? Or can you share the rest of your code somehow?

[immesys]

I think I hit this problem again, and I have #4903 in my code base. Has someone else tested this? It's certainly less frequent though

[kaspar030]

My ISR hammering test case breaks without #4903, and runs fine with it. I didn't succeed in triggering it with #4903 included. @immesys does your code break using the same guard?

[immesys]

I think it might have something to do with my debugger actually. Does the chip (SAMR21) behave differently when a JTAG probe is attached?

Anyway, as I can't really reliably reproduce the problem, I'd say go ahead with merging it in. I'll come back and do more testing when I get a chance but it will probably only be in a few weeks.

edit: for the record though, whenever I got the lockup, the backtrace was in _remove.

[kaspar030]

As noone currently can reproduce, I'll retag for next release.

[OlegHahm]

I managed to trigger a timer that is twice in xtimer's list, but by intentionally setting the same timer concurrently from user and ISR context.

Is this still a problem?

[OlegHahm]

Btw currently it looks like that replacing the xtimer_msg_receive_timeout() with a simple msg_receive() "solved" the problem. Hence, we should take a closer look at this function.

[kaspar030]

Is this still a problem?

In theory it might still happen when concurrently setting the same timer with values < XTIMER_BACKOFF. #4903 fixed this only for some (most) cases.

[kaspar030]

Probably fixed by #5428.

[kYc0o]

Since #5428 is open and probably won't be merged for this release, I'll postpone this issue.

[mlohse]

Hi, I ran into this issue and spent an entire day tracing it down to a semaphore used by lwip:
In 'sema_wait_timed_msg' a 'timer_t' is created as a local variable, the timer is set, but before it expires or is removed the function's scope can be left and the xtimer_t removed from the stack:

int sema_wait_timed_msg(sema_t *sema, uint64_t timeout, msg_t *msg)
{
    unsigned old_state;
    msg_t timeout_msg;
    xtimer_t timeout_timer;

    if (sema == NULL) {
        return -EINVAL;
    }
    if (timeout != 0) {
        old_state = irq_disable();
        timeout_timer.target = 0, timeout_timer.long_target = 0;
        timeout_msg.type = MSG_TIMEOUT;
        timeout_msg.content.ptr = sema;
        /* we will stay in the same stack context so we can use timeout_msg */
        xtimer_set_msg64(&timeout_timer, timeout, &timeout_msg, sched_active_pid);
        irq_restore(old_state);
    }
    while (1) {
        priority_queue_node_t n;
        unsigned value;

        old_state = irq_disable();
        value = sema->value;
        if (value != 0) {
            sema->value = value - 1;
            irq_restore(old_state);
            return 0; <-- timeout_timer is removed from stack, but still in the list!
        }
        ...
    }
}

This is bad already an can lead to a crash, but it get's better:
When 'sema_wait_timed_msg' is called again, chances seem to be surprisingly high, that the new xtimer_t is located at the exact same location. The timers .target and .long_target are reset to '0'.
So when the timer is set although already in the list, it survives the superficial check in '_is_set'...

static inline int _is_set(xtimer_t *timer)
{
    return (timer->target || timer->long_target);
}

...hence the timer is not removed before it gets added again. When 'xtimer_set' returns the list is left in a broken state with timer_list_head->next pointing to itself (instead of '0').
So the next function trying to iterate over the list (e.g. when the timer interrupt is fired or when another timer is added) ends up in an endless-loop and RiotOS hangs :(

[kaspar030]

Wow, nice catch and thanks a lot for digging this deep!

@miri64 Do you want to fix this (... having the sema rewrite (#6155) in mind)?

[miri64]

As #6155 (comment) points out, that function is removed in that fix. But as far as I understood this there is also a bug in xtimer, not checking the identity of an added xtimer_t struct. This should be an easy fix to xtimer, doesn't it?

[mlohse]

@miri64 As long as xtimer is used correctly it works as expected.
I forgot to mention, that removing the timer before returning from 'sema_wait_timed_msg' fixed this issue for me:

int sema_wait_timed_msg(sema_t *sema, uint64_t timeout, msg_t *msg)
{
    ...
    while (1) {
        priority_queue_node_t n;
        unsigned value;
        old_state = irq_disable();

        value = sema->value;
        if (value != 0) {
            sema->value = value - 1;
            irq_restore(old_state);
            if (timeout != 0) {
                xtimer_remove(&timeout_timer);
            }
            return 0;
        }
        ...
    }
}

Considering the impact (RiotOS hanging) of a wrongly used timer and how difficult it is to trace such bugs back, one could argue that a more careful check should be done. A safer implementation involves iterating at least over the list where the timer would be added to, which costs some additional time... in a critical section, while interrupts are disabled...

[miri64]

@kaspar030 Mhhhh... What is xtimer internally: A circular list or a linear list? If it is the latter you can check if the xtimer is part of (any) list by checking the next value. If it is NULL it obviously is part of a list (most likely the timer queue), if not it is either not already scheduled or at the very end of a queue (which means you need to traverse the queue anyways to add it).

[lebrush]

I think it's not that simple. This would only be true if the xtimer variable is in the same place of the stack. But if in the next iteration is placed in another position, the previous xtimer in the list now points to unpredictable data (corrupt data). And you will not catch that they are actually the same timer. Hence, as @mlohse pointed out, one has to be careful to use the xtimer correctly...

EDIT: sorry, brainfart. We are talking about two separate things. One is the "overwritten" timer which @mlohse was mentioning. The other is a orphan xtimer which would cause unexpected behaviour. For the second one can only make sure a correct timer use. For the first a pointer check shall suffice.

[OlegHahm]

So, who has the token on this?

[lebrush]

@OlegHahm this should be "solved" when #6158 and #6155 are merged

[miri64]

@lebrush seems unrelated to the OP... (just the one reported by @mlohse) or am I mistaking?

[DipSwitch]

I had the same problem and in combination with TCP.

It seems that the problem triggers if an other msg is received (from interrupt in my case) while the xtimer_msg_receive_timeout is waiting or has timed out or is restarting... Or the timer triggers while another message is queued. I have no idea lol.

And sorry about the close my touchpad was enabled =(

[miri64]

@OlegHahm this should be "solved" when #6158 and #6155 are merged

Those PRs were merged a while ago. Ist his issue fixed then?

[immesys]

I have not seen it again, so I think it is ok to close this. We can reopen if it shows up

[miri64]

Alright