[lwip-users] DHCP request fails after 5th try (memory leack?)

[George Ruinelli]

Hi all

I experiencing some weird behavior with DHCP requests.
As far as I can see it seems to be a memory overflow in dhcp_start() / 
dhcp_stop().
DHCP requests work for 5 times but will fail at the 6th time with this error: 
"dhcp_start(): could not obtain pcb"
Looking at the log below you can see that it calls 
  udp_new()
then
  udp_remove()
and then again
  udp_new()
without removing it again.

Do you have any explanation for this?
I am using an STM32 with FreeRTOS 7.1.1 and lwip 1.4.1

Please see below a summarized log as well as a detailed log with a good/bad 
DHCP request:

Thank you very much for any hint
George

-------------- Summary Log ----------------------------------

####################### OK #######################

19:00:12.731> DHCP request started
19:00:12.731> ########### dhcp_start()
19:00:12.731> ########### udp_new()
19:00:12.982> DHCP waiting for reply... (Runtime: 0.255)
19:00:13.246> DHCP waiting for reply... (Runtime: 0.509)
19:00:13.491> DHCP waiting for reply... (Runtime: 0.763)
19:00:13.741> DHCP waiting for reply... (Runtime: 1.017)
19:00:13.741> DHCP assigned: 192.168.103.20
19:00:13.761> ########### dhcp_stop()
19:00:13.761> ########### udp_remove()
19:00:13.761> ########### udp_new()


####################### FAIL #######################

19:01:04.723> DHCP request started
19:01:04.723> ########### dhcp_start()
19:01:04.723> ########### udp_new()
19:01:04.975> DHCP waiting for reply... (Runtime: 0.254)
19:01:05.244> DHCP waiting for reply... (Runtime: 0.508)
19:01:05.492> DHCP waiting for reply... (Runtime: 0.762)
19:01:05.737> DHCP waiting for reply... (Runtime: 1.016)
19:01:06.003> DHCP waiting for reply... (Runtime: 1.270)
19:01:06.245> DHCP waiting for reply... (Runtime: 1.524)
19:01:06.503> DHCP waiting for reply... (Runtime: 1.778)
19:01:06.753> DHCP waiting for reply... (Runtime: 2.032)
19:01:07.021> DHCP waiting for reply... (Runtime: 2.286)
19:01:07.271> DHCP waiting for reply... (Runtime: 2.540)
19:01:07.516> DHCP waiting for reply... (Runtime: 2.794)
19:01:07.771> DHCP waiting for reply... (Runtime: 3.048)
19:01:08.030> DHCP waiting for reply... (Runtime: 3.302)
19:01:08.280> DHCP waiting for reply... (Runtime: 3.556)
19:01:08.531> DHCP waiting for reply... (Runtime: 3.810)
19:01:08.795> DHCP waiting for reply... (Runtime: 4.064)
19:01:09.048> DHCP waiting for reply... (Runtime: 4.318)
19:01:09.294> DHCP waiting for reply... (Runtime: 4.572)
19:01:09.561> DHCP waiting for reply... (Runtime: 4.826)
19:01:09.800> DHCP waiting for reply... (Runtime: 5.080)
19:01:10.060> DHCP waiting for reply... (Runtime: 5.334)
...



-------------- Detailed Log ----------------------------------

####################### OK #######################

19:06:27.662> DHCP request started
19:06:27.662> ########### dhcp_start()
19:06:27.662> dhcp_start(netif=20012774) st0
19:06:27.662> dhcp_start(): restarting DHCP configuration
19:06:27.662> ########### udp_new()
19:06:27.662> dhcp_start(): starting DHCP configuration
19:06:27.662> dhcp_discover()
19:06:27.674> transaction id xid(1e4abe23)
19:06:27.674> dhcp_discover: making request
19:06:27.674> dhcp_discover: realloc()ing
19:06:27.688> dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, 
DHCP_SERVER_PORT)
19:06:27.688> dhcp_discover: deleting()ing
19:06:27.688> dhcp_discover: SELECTING
19:06:27.688> dhcp_discover(): set request timeout 2000 msecs
19:06:27.706> dhcp_recv(pbuf = 200111A0) from DHCP server 192.168.103.251 port 
67
19:06:27.706> pbuf->len = 303
19:06:27.706> pbuf->tot_len = 303
19:06:27.706> skipping option 43 in options
19:06:27.706> searching DHCP_OPTION_MESSAGE_TYPE
19:06:27.726> DHCP_OFFER received in DHCP_SELECTING state
19:06:27.726> dhcp_handle_offer(netif=20012774) st0
19:06:27.726> dhcp_handle_offer(): server 0x1b64a8c0
19:06:27.726> dhcp_handle_offer(): offer for 0x1467a8c0
19:06:27.736> REQUESTING
19:06:27.736> dhcp_select(): set request timeout 2000 msecs
19:06:27.726> dhcp_select(netif=20012774) st0
19:06:27.726> transaction id xid(8d6ba7eb)
19:06:27.750> er 192.168.103.252 port 67
19:06:27.750> pbuf->len = 303
19:06:27.750> pbuf->tot_len = 303
19:06:27.750> transaction id mismatch 
reply_msg->xid(1e4abe23)!=dhcp->xid(8d6ba7eb)
19:06:27.766> dhcp_select: (pbuf = 200115A8) from DHCP server 192.168.103.251 
port 67
19:06:27.766> pbuf->len = 303
19:06:27.766> pbuf->tot_len = 303
19:06:27.782> transaction id mismatch 
reply_msg->xid(1e4abe23)!=dhcp->xid(8d6ba7eb)
19:06:27.782> dhcp_recv(pbuf = 200117AC) from DHCP server 192.168.103.252 port 
67
19:06:27.782> pbuf->len = 303
19:06:27.782> pbuf->tot_len = 303
19:06:27.799> d(8d6ba7eb)
19:06:27.799> dhcp_recv(pbuf = 200119B0) from DHCP server 192.168.103.251 port 
67
19:06:27.822> AGE_TYPE
19:06:27.822> DHCP_ACK received
19:06:27.831> options
19:06:27.831> searching DHCP_OPTION_MESSAGE_TYPE
19:06:27.831> DHCP_ACK received
19:06:27.822> ON_MESSAGE_TYPE
19:06:27.822> DHCP_ACK received
19:06:27.822> _check(): set request timeout 500 msecs
19:06:27.822> dhcp_recv(pbuf = 20010F9C) from DHCP server 192.168.103.252 port 
67
19:06:27.822> pbuf->len = 303
19:06:27.822> pbuf->tot_len = 303
19:06:27.799> uest timeout 500 msecs
19:06:27.799> dhcp_recv(pbuf = 20010F9C) from DHCP server 192.168.103.252 port 
67
19:06:27.954> p_recv(pbuf = 20010F9C) from DHCP server 192.168.103.252 poDHCP 
waiting for reply... (Runtime: 0.293)
19:06:27.986> dhcp_fine_tmr(): request timeout
19:06:27.986> dhcp_timeout()
19:06:27.986> dhcp_timeout(): CHECKING, ARP request timed out
19:06:27.986> dhcp_check(netif=20012774) st
19:06:28.005> et request timeout 500 msecs
19:06:28.203> dhcp_check(): sDHCP waiting for reply... (Runtime: 0.547)
19:06:28.453> DHCP waiting for reply... (Runtime: 0.801)
19:06:28.499> dhcp_fine_tmr(): request timeout
19:06:28.499> dhcp_timeout()
19:06:28.499> dhcp_timeout(): CHECKING, ARP request timed out
19:06:28.519> dhcp_bind(netif=20012774) st0
19:06:28.519> dhcp_bind(): t1 renewal timer 86400 secs
19:06:28.519> dhcp_bind(): set request timeout 86400000 msecs
19:06:28.533> bind(): IP: 0x1467a8c0
19:06:28.533> dhcp_bind(): SN: 0x00ffffff
19:06:28.533> dhcp_bind(): GW: 0xfe67a8c0
19:06:28.519> dhcp_bind(): t2 rebind timer 151200 secs
19:06:28.519> dhcp_bind(): set request timeout 151200000 msecs
19:06:28.704> dhcp_DHCP waiting for reply... (Runtime: 1.055)
19:06:28.718> DHCP assigned: 192.168.103.20
19:06:28.718> ########### dhcp_stop()
19:06:28.718> dhcp_stop()
19:06:28.718> ########### udp_remove()
19:06:28.718> ########### udp_new()
19:06:29.035> (Checksum: 104), Done

19:06:49.510> dhcp_arp_reply()



####################### FAIL #######################

19:08:37.827> DHCP request started
19:08:37.827> ########### dhcp_start()
19:08:37.827> dhcp_start(netif=20012774) st0
19:08:37.843> dhcp_start(): restarting DHCP configuration
19:08:37.843> ########### udp_new()
19:08:37.843> dhcp_start(): could not obtain pcb                  <= No memory 
left !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
19:08:38.093> DHCP waiting for reply... (Runtime: 0.265)
19:08:38.358> DHCP waiting for reply... (Runtime: 0.519)
19:08:38.612> DHCP waiting for reply... (Runtime: 0.773)
19:08:38.859> DHCP waiting for reply... (Runtime: 1.027)
19:08:39.107> DHCP waiting for reply... (Runtime: 1.281)
19:08:39.361> DHCP waiting for reply... (Runtime: 1.535)
19:08:39.622> DHCP waiting for reply... (Runtime: 1.789)
19:08:39.872> DHCP waiting for reply... (Runtime: 2.043)
19:08:40.136> DHCP waiting for reply... (Runtime: 2.297)
19:08:40.389> DHCP waiting for reply... (Runtime: 2.551)
19:08:40.639> DHCP waiting for reply... (Runtime: 2.805)
19:08:40.885> DHCP waiting for reply... (Runtime: 3.059)
19:08:41.150> DHCP waiting for reply... (Runtime: 3.313)
19:08:41.399> DHCP waiting for reply... (Runtime: 3.567)
...