[lwip-devel] Cyclic timers not always working

[Patrik Dahlström]

Hello,

We sometimes get an issue where cyclic timers doesn't trigger. I don't
know exactly what causes it, but when it happens cyclic timers only
trigger once, then only the 1 of the timers continue to trigger.

We're using lwip on a Broadcom 7405 SoC running Linux in OS mode.

Unfortunately, due to company policy and whatnot, I cannot share too
much information about our code. Let me go through some pseudo code at
least:

LOG_MESSAGE("Initializing tcpip");
tcpip_init();
while (!tcpip_init_done_flag);
LOG_MESSAGE("Bringing up network interface.");
netif_add();
netif_set_default();
netif_set_up();
dhcp_set_struct(); // same issue with or without this line
dhcp_start();
while (dhcp.state != DHCP_STATE_BOUND) {
  if (dhcp.state != old_state) {
    LOG_TRACE("Waiting for ip.. -- state == %s",stateStr[dhcp.state]);
  }
  sched_yield();
}

I have defined:
#define SYS_DEBUG                       LWIP_DBG_ON
#define TIMERS_DEBUG                    LWIP_DBG_ON
#define DHCP_DEBUG                      LWIP_DBG_ON

Take a look at the log below. From what I can see, the code properly
send out 1 DHCP discover, and dhcp_fine_tmr() gets called 1 time after
that. After that, other cyclic timers gets called _once_. Finally, only
the dns_tmr() timer gets called periodically.
Time stamps are added by Minicom.

[2018-06-07 15:00:50] [MESSAGE]           start_network():00095
Initializing tcpip
[2018-06-07 15:00:50] sys_timeout: 0x4b1960 msecs=1000
handler=cyclic_timer arg=0x45358c
[2018-06-07 15:00:50] sys_timeout: 0x4b194c msecs=1000
handler=cyclic_timer arg=0x453598
[2018-06-07 15:00:50] sys_timeout: 0x4b1938 msecs=60000
handler=cyclic_timer arg=0x4535a4
[2018-06-07 15:00:50] sys_timeout: 0x4b1924 msecs=500
handler=cyclic_timer arg=0x4535b0
[2018-06-07 15:00:50] sys_timeout: 0x4b1910 msecs=1000
handler=cyclic_timer arg=0x4535bc
[2018-06-07 15:00:50] [MESSAGE]           start_network():00107 Bringing
up network interface.
[2018-06-07 15:00:50] dhcp_start(netif=0x4a7e10) e10
[2018-06-07 15:00:50] dhcp_start(): restarting DHCP configuration
[2018-06-07 15:00:50] dhcp_start(): starting DHCP configuration
[2018-06-07 15:00:50] dhcp_discover()
[2018-06-07 15:00:50] transaction id xid(0)
[2018-06-07 15:00:50] dhcp_discover: making request
[2018-06-07 15:00:50] dhcp_discover: realloc()ing
[2018-06-07 15:00:50] dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST,
DHCP_SERVER_PORT)
[2018-06-07 15:00:50] dhcp_discover: deleting()ing
[2018-06-07 15:00:50] dhcp_discover: SELECTING
[2018-06-07 15:00:50] dhcp_discover(): set request timeout 2000 msecs
[2018-06-07 15:00:50] [TRACE]             start_network():00177 Waiting
for ip.. -- state == DHCP_STATE_SELECTING
[2018-06-07 15:00:50] sct calling h=cyclic_timer arg=0x4535b0
[2018-06-07 15:00:50] tcpip: dhcp_fine_tmr()
[2018-06-07 15:00:50] dhcp_fine_tmr(): netif = 0x4a7e10
[2018-06-07 15:00:50] dhcp_fine_tmr(): ticks left = 4
[2018-06-07 15:00:50] sys_timeout: 0x4b1924 msecs=500
handler=cyclic_timer arg=0x4535b0
[2018-06-07 15:00:50] sct calling h=cyclic_timer arg=0x45358c
[2018-06-07 15:00:50] tcpip: ip_reass_tmr()
[2018-06-07 15:00:50] sys_timeout: 0x4b1960 msecs=1000
handler=cyclic_timer arg=0x45358c
[2018-06-07 15:00:50] sct calling h=cyclic_timer arg=0x453598
[2018-06-07 15:00:50] tcpip: etharp_tmr()
[2018-06-07 15:00:50] sys_timeout: 0x4b194c msecs=1000
handler=cyclic_timer arg=0x453598
[2018-06-07 15:00:50] sct calling h=cyclic_timer arg=0x4535bc
[2018-06-07 15:00:50] tcpip: dns_tmr()
[2018-06-07 15:00:50] sys_timeout: 0x4b1910 msecs=1000
handler=cyclic_timer arg=0x4535bc
[2018-06-07 15:00:51] sct calling h=cyclic_timer arg=0x4535bc
[2018-06-07 15:00:51] tcpip: dns_tmr()
[2018-06-07 15:00:51] sys_timeout: 0x4b1910 msecs=1000
handler=cyclic_timer arg=0x4535bc
[2018-06-07 15:00:52] sct calling h=cyclic_timer arg=0x4535bc
[2018-06-07 15:00:52] tcpip: dns_tmr()
[2018-06-07 15:00:52] sys_timeout: 0x4b1910 msecs=1000
handler=cyclic_timer arg=0x4535bc

I would very much appreciate any help on where to begin looking for this
bug. As I said in the start, this only happens _sometimes_.

Best regards
Patrik Dahlström