Re: [lwip-users] lwip 1.3 UDP - DNS strange behaviour

[Sergio Sider]

Hi All,
I turned on several DEBUG messages and waited for netif_is_up before
call dns_gethostbyname, but the problem is present.
I tried calling dns_gethostbyname 5 seconds AFTER the network
interface is up and it worked, but I recall that in the past I still
had problems sometimes, even with the delay.
When using DHCP, there is no problem, even if I call dns_gethostbyname
immediately after receiving the designated IP.


Here are the logs of my application:
================ without the explicit delay===================
- No timeout occurs and the callback is never called
- the dns UDP packet is not really sent, although the messages told me so



Powering SD-CARD socket
Initialing I2C
Initializing RTC Chip
Loading config from E2PROM
Configuring Systick
Initializing Filesystem
PRE-Loading ini defaults
Trying to load IDC.INI
Parsing inifile
Inifile read ok!
IDC.INI read!
Openning IDC_CHAM.TXT for check
Size = 2079296, 32489 records
Verifying last 50 calls
Openning IDC_AGEN.TXT for check
Size = 98397, 1131 records
End of file checking
Mac Address = 00:1a:b6:00:03:b7
initialing tcp/ip stack (IPADDR_USE_STATIC)
dns_init: initializing
udp_bind(ipaddr = 0.0.0.0, port = 0)
udp_bind: bound to 0.0.0.0, port 4096
netif_set_ipaddr: netif address being changed
netif: IP address of interface lm set to 192.168.0.180
netif: netmask of interface lm set to 255.255.255.0
netif: GW address of interface lm set to 192.168.0.2
netif: added interface lm IP addr 192.168.0.180 netmask 255.255.255.0
gw 192.168.0.2
netif: setting default interface lm
find_entry: found empty entry 0
find_entry: selecting empty entry 0
etharp_request: sending ARP request.
etharp_raw: sending raw ARP packet.
initializing http server
tcp_bind: bind to port 4321
Setting UART2 for IDC serial
Entering cooperative multitasking loop
SNTP: ip address defined and interface is up!
IP:    192.168.0.180
MASK:  255.255.255.0
GW:    192.168.0.2
DNS1:  200.30.0.97
DNS2:  200.204.0.10
gethostbyname for host time.nist.gov
dns_enqueue: "time.nist.gov": use DNS entry 0
dns_send: dns_servers[0] "time.nist.gov": request
udp_connect: connected to 200.30.0.97,port 53
udp_send
udp_send: added header in given pbuf 200015f8
udp_send: sending datagram of length 39
udp_send: UDP packet length 39
inet_chksum_pseudo(): checksumming pbuf 200015f8 (has next 0)
inet_chksum_pseudo(): pbuf chain lwip_chksum()=12c5
udp_send: UDP checksum 0xed3a
udp_send: ip_output_if (,,,,IP_PROTO_UDP,)
ip_output_if: lm0
IP header:
+-------------------------------+
| 4 | 5 |  0x00 |        59     | (v, hl, tos, len)
+-------------------------------+
|        0      |000|       0   | (id, flags, offset)
+-------------------------------+
|  255  |   17  |    0x31d6     | (ttl, proto, chksum)
+-------------------------------+
|  192  |  168  |    0  |  180  | (src)
+-------------------------------+
|  200  |   30  |    0  |   97  | (dest)
+-------------------------------+
netif->output()find_entry: found empty entry 1
find_entry: selecting empty entry 1
etharp_request: sending ARP request.
etharp_raw: sending raw ARP packet.
etharp_query: queued packet 200015f8 on ARP entry 1
Initial response = -14
[fa]IDCPC found on serial-port!
[80][ea]IDCPC ready for lines 1-4
udp_bind(ipaddr = 0.0.0.0, port = 0)
udp_bind: bound to 0.0.0.0, port 4097
udp_connect: connected to 192.168.0.255,port 1234
udp_send
udp_send: added header in given pbuf 200016cc
udp_send: sending datagram of length 86
udp_send: UDP packet length 86
inet_chksum_pseudo(): checksumming pbuf 200016cc (has next 0)
inet_chksum_pseudo(): pbuf chain lwip_chksum()=d5e7
udp_send: UDP checksum 0x2a18
udp_send: ip_output_if (,,,,IP_PROTO_UDP,)
ip_output_if: lm0
IP header:
+-------------------------------+
| 4 | 5 |  0x00 |       106     | (v, hl, tos, len)
+-------------------------------+
|        1      |000|       0   | (id, flags, offset)
+-------------------------------+
|  255  |   17  |    0x387e     | (ttl, proto, chksum)
+-------------------------------+
|  192  |  168  |    0  |  180  | (src)
+-------------------------------+
|  192  |  168  |    0  |  255  | (dest)
+-------------------------------+
netif->output()etharp_send_ip: sending packet 200016cc
Sending BROADCAST ( 78) [01|0|  |  |                         |
|192.168.000.180               | ]
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
etharp_timer
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
etharp_timer
etharp_timer: expired pending entry 0.
etharp_timer: expired pending entry 1.
etharp_timer: freeing entry 1, packet queue 2000821c.
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
...



================ with explicit 5 seconds delay===================
WORKED



Powering SD-CARD socket
Initialing I2C
Initializing RTC Chip
Loading config from E2PROM
Configuring Systick
Initializing Filesystem
PRE-Loading ini defaults
Trying to load IDC.INI
Parsing inifile
Inifile read ok!
IDC.INI read!
Openning IDC_CHAM.TXT for check
Size = 2079296, 32489 records
Verifying last 50 calls
Openning IDC_AGEN.TXT for check
Size = 98397, 1131 records
End of file checking
Mac Address = 00:1a:b6:00:03:b7
initialing tcp/ip stack (IPADDR_USE_STATIC)
dns_init: initializing
udp_bind(ipaddr = 0.0.0.0, port = 0)
udp_bind: bound to 0.0.0.0, port 4096
netif_set_ipaddr: netif address being changed
netif: IP address of interface lm set to 192.168.0.180
netif: netmask of interface lm set to 255.255.255.0
netif: GW address of interface lm set to 192.168.0.2
netif: added interface lm IP addr 192.168.0.180 netmask 255.255.255.0
gw 192.168.0.2
netif: setting default interface lm
find_entry: found empty entry 0
find_entry: selecting empty entry 0
etharp_request: sending ARP request.
etharp_raw: sending raw ARP packet.
initializing http server
tcp_bind: bind to port 4321
Setting UART2 for IDC serial
Entering cooperative multitasking loop
SNTP: ip address defined and interface is up!
IP:    192.168.0.180
MASK:  255.255.255.0
GW:    192.168.0.2
DNS1:  200.30.0.97
DNS2:  200.204.0.10
[fa]IDCPC found on serial-port!
[80][ea]IDCPC ready for lines 1-4
udp_bind(ipaddr = 0.0.0.0, port = 0)
udp_bind: bound to 0.0.0.0, port 4097
udp_connect: connected to 192.168.0.255,port 1234
udp_send
udp_send: added header in given pbuf 200015f8
udp_send: sending datagram of length 86
udp_send: UDP packet length 86
inet_chksum_pseudo(): checksumming pbuf 200015f8 (has next 0)
inet_chksum_pseudo(): pbuf chain lwip_chksum()=d5e7
udp_send: UDP checksum 0x2a18
udp_send: ip_output_if (,,,,IP_PROTO_UDP,)
ip_output_if: lm0
IP header:
+-------------------------------+
| 4 | 5 |  0x00 |       106     | (v, hl, tos, len)
+-------------------------------+
|        0      |000|       0   | (id, flags, offset)
+-------------------------------+
|  255  |   17  |    0x387f     | (ttl, proto, chksum)
+-------------------------------+
|  192  |  168  |    0  |  180  | (src)
+-------------------------------+
|  192  |  168  |    0  |  255  | (dest)
+-------------------------------+
netif->output()etharp_send_ip: sending packet 200015f8
Sending BROADCAST ( 78) [01|0|  |  |                         |
|192.168.000.180               | ]
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
tcp_slowtmr: no active pcbs
etharp_timer
gethostbyname for host time.nist.gov
dns_enqueue: "time.nist.gov": use DNS entry 0
dns_send: dns_servers[0] "time.nist.gov": request
udp_connect: connected to 200.30.0.97,port 53
udp_send
udp_send: added header in given pbuf 200015f8
udp_send: sending datagram of length 39
udp_send: UDP packet length 39
inet_chksum_pseudo(): checksumming pbuf 200015f8 (has next 0)
inet_chksum_pseudo(): pbuf chain lwip_chksum()=12c5
udp_send: UDP checksum 0xed3a
udp_send: ip_output_if (,,,,IP_PROTO_UDP,)
ip_output_if: lm0
IP header:
+-------------------------------+
| 4 | 5 |  0x00 |        59     | (v, hl, tos, len)
+-------------------------------+
|        1      |000|       0   | (id, flags, offset)
+-------------------------------+
|  255  |   17  |    0x31d5     | (ttl, proto, chksum)
+-------------------------------+
|  192  |  168  |    0  |  180  | (src)
+-------------------------------+
|  200  |   30  |    0  |   97  | (dest)
+-------------------------------+
netif->output()find_entry: found empty entry 1
find_entry: selecting empty entry 1
etharp_request: sending ARP request.
etharp_raw: sending raw ARP packet.
etharp_query: queued packet 200015f8 on ARP entry 1
Initial response = -14
update_arp_entry()
update_arp_entry: 192.168.0.2 - 00:1b:2f:e6:74:a4
find_entry: found matching pending entry 1
update_arp_entry: updating stable entry 1
etharp_send_ip: sending packet 20001668
etharp_arp_input: incoming ARP reply
dhcp_arp_reply()
ip_input: iphdr->dest 0xb400a8c0 netif->ip_addr 0xb400a8c0 (0xa8c0,
0xa8c0, 0xb4000000)
ip_input: packet accepted on interface lm
ip_input:
IP header:
+-------------------------------+
| 4 | 5 |  0x00 |       153     | (v, hl, tos, len)
+-------------------------------+
|    59434      |010|       0   | (id, flags, offset)
+-------------------------------+
|  247  |   17  |    0x114d     | (ttl, proto, chksum)
+-------------------------------+
|  200  |   30  |    0  |   97  | (src)
+-------------------------------+
|  192  |  168  |    0  |  180  | (dest)
+-------------------------------+
ip_input: p->len 153 p->tot_len 153
udp_input: received datagram of length 133
UDP header:
+-------------------------------+
|        53     |      4096     | (src port, dest port)
+-------------------------------+
|       133     |     0xbb0a    | (len, chksum)
+-------------------------------+
udp (192.168.0.180, 4096) <-- (200.30.0.97, 53)
pcb (0.0.0.0, 4096) --- (200.30.0.97, 53)
udp_input: calculating checksum
inet_chksum_pseudo(): checksumming pbuf 20009c14 (has next 0)
inet_chksum_pseudo(): pbuf chain lwip_chksum()=ffff
dns_recv: "time.nist.gov": response = 192.43.244.18
Found ip of host time.nist.gov = 192.43.244.18



Any idea ? Could by ARP related?

Thanks,
Sergio








On Mon, Jan 19, 2009 at 5:04 PM, Jonathan Larmour <address@hidden> wrote:
>
> Rejean Groleau wrote:
> > Hi Sergio,
> >
> > I had the same problem a while back. My problem was two-fold:
> >
> > First, I did not have enough pbufs (PBUF_POOL_SIZE and MEMP_NUM_PBUF)
> > to do everything I was doing at startup. Once I got the LWIP_DEBUGF
> > and LWIP_PLATFORM_DIAG macros properly implemented, I was able to see
> > the errors coming from the dns_send() function.
>
> That should have timed out eventually though, right? Just checking there
> isn't a real bug in the lwIP DNS code here - it shoudl be able to cope with
> running out of pbufs.
>
> > Then, I was not waiting for the interface to be up and initialized before
> > calling dns_gethostbyname(). This was solved by calling netif_is_up().
>
> Again, did it time out eventually? Or it should have worked shortly after
> the interface was up, even if that wasn't straight away.
>
> Jifl
> --
> eCosCentric Limited      http://www.eCosCentric.com/     The eCos experts
> Barnwell House, Barnwell Drive, Cambridge, UK.       Tel: +44 1223 245571
> Registered in England and Wales: Reg No 4422071.
> ------["Si fractum non sit, noli id reficere"]------       Opinions==mine
>
>
> _______________________________________________
> lwip-users mailing list
> address@hidden
> http://lists.nongnu.org/mailman/listinfo/lwip-users