Re: [lwip-devel] Cyclic timers not always working

[Patrik Dahlström]

Hello,

Sorry for the noise. It turns out that I was able to solve this issue by
updating our porting code with the code from contrib-2.0.1.zip. We
initially did our port based on v1.4 and recently upgraded to
lwip-2.0.3, but without updating the porting code.

Updating the Unix port code fixed this issue.

Best regards
// Patrik

On 06/08/2018 11:39 AM, Patrik Dahlström wrote:
> 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
> 
> _______________________________________________
> lwip-devel mailing list
> address@hidden
> https://lists.nongnu.org/mailman/listinfo/lwip-devel
>