1. This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn More.

Compiling Toastman-RT with full udhcpc-verbosity

Discussion in 'Tomato Firmware' started by Elbart, Jan 28, 2014.

  1. Elbart

    Elbart LI Guru Member

    I'd like to compile the firmware with full verbosity of udhcpc to debug a DHCP-problem with my internet-connection.

    Following this post I have to change some options in /release/src/router/busybox/config_base, like
    CONFIG_UDHCPD
    CONFIG_DHCPRELAY
    CONFIG_UDHCP_DEBUG

    Is there anything else which needs to be changed?
     
  2. koitsu

    koitsu Network Guru Member

    You need to make sure CONFIG_UDHCP_DEBUG is set to a value equal to or greater than 1, not just simply defined. The default value (of 0) means it's disabled. So set it to 1 and you should be OK.

    You will also need to manually start the daemon with the -v flag after the binary has been compiled with CONFIG_UDHCP_DEBUG. Please see the source code (search for DEBUG, then once you've seen how that's used, search for VERBOSE). If running udhcpc -h doesn't show the -v flag as an available flag then the binary was not built with CONFIG_UDHCP_DEBUG enabled.

    If you run into actual behavioural oddities with udhcpc, please contact the Busybox folks, as their code = their responsibility. I believe what's used with present-day TomatoUSB is Busybox 1.21.0.
     
  3. Elbart

    Elbart LI Guru Member

    Thanks. I made the necessary changes and now udphcp offers the verbose-flag.
    And after some tinkering I'm fairly sure that the DHCP-problem of my connection isn't down to udhcpc.

    Unless the udhcpc (BusyBox 1.20.2) in Ubuntu (13.10) is also modified in some way, Tomato's (Toastman-RT-N 0503.5) udhcpc (BusyBox v1.21.1) is behaving differently than the vanilla one.
    I.e. sending a SIGUSR1 to a udhcpc-instance on Ubuntu only triggers a dhcp-renew (DHCPREQUEST and DHCPACK), but doing the same with Tomato's udhcpc starts the whole DHCP-process, although no DHCPNAK was received and the leasetime hasn't expired yet.

    Log:
    Code:
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Performing a DHCP renew
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Entering listen mode: raw
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Opening raw socket on ifindex 30
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Got raw socket fd
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Attached filter to raw socket fd
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Created raw socket
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Entering listen mode: raw
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Opening raw socket on ifindex 30
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Got raw socket fd
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Attached filter to raw socket fd
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Created raw socket
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Adapter index 30
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: MAC 00:xy:zx:yz:xy:zz
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Adapter mtu 1500
    Jan 28 17:22:40 tomato daemon.info udhcpc[6578]: Adding option: 0x35 01
    etc.
    AFAIK option 0x35 should be 03 (request) when it's just a renew, not 01 (discover).
     
    Last edited: Jan 28, 2014
  4. mstombs

    mstombs Network Guru Member

  5. Elbart

    Elbart LI Guru Member

    Some other notable changes:
    Duplicate lines? http://repo.or.cz/w/tomato.git/blam.../router/busybox/networking/udhcp/dhcpc.c#l630

    Changing LISTEN_KERNEL to LISTEN_RAW:
    http://repo.or.cz/w/tomato.git/blam...router/busybox/networking/udhcp/dhcpc.c#l1089 vs. http://git.busybox.net/busybox/tree/networking/udhcp/dhcpc.c?h=1_21_stable#n1073
    http://repo.or.cz/w/tomato.git/blam...router/busybox/networking/udhcp/dhcpc.c#l1515 vs. http://git.busybox.net/busybox/tree/networking/udhcp/dhcpc.c?h=1_21_stable#n1492
    http://repo.or.cz/w/tomato.git/blob.../router/busybox/networking/udhcp/dhcpc.c#l402

    Could the change to LISTEN_RAW have any negative side-effects, especially for receiving DHCPACKs as unicast after the normal renew-attempts after half the leaste time?
     
  6. mstombs

    mstombs Network Guru Member

    Well I have an ongoing issue with dhcp renewals not working well - lease sometimes expires then resets, so would be interested to know why we can't the use the Busybox version!

    Code:
    Jan 26 06:17:10 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Jan 26 11:35:40 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Jan 26 15:34:31 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Jan 26 16:14:20 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Jan 26 16:34:14 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Jan 26 16:44:11 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Jan 26 16:49:09 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Jan 26 16:51:38 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Jan 26 16:52:52 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Jan 26 16:53:29 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Jan 26 16:53:30 rtn66u daemon.info udhcpc[3005]: Lease of xx.yy.zz.aa obtained, lease time 601469
     
  7. koitsu

    koitsu Network Guru Member

    I'm wondering where the evidence is that this is a client-side problem and not a server-side problem? Rephrased: every ISP seems to run a different kind or implementation of DHCP server where the behaviour varies greatly.

    My point: without doing packet captures on both sides (on the client, and on the server) and looking at what's going on between client and server on both ends, it's difficult to come up with any kind of "solution" for "renewals not working well". What might work better for you could break for someone else. We've had examples of this on the forum already.

    And AFAIK, a client issuing a REQUEST of a renew doesn't have to be honoured by the server every time. Many DHCP servers (including ISC's DHCP server) have configuration directives that can basically say "only honour a full renew after N seconds have transpired between last renew/handout and now, regardless of what the client wants". This gets into a grey area because people seem to think there's a direct 1:1 relationship between the renew and the lease expiration, but there isn't.

    Likewise, if an ISPs DHCP servers are overloaded or they have networking problems (with reachability or load balancing of said DHCP servers) then DHCP requests would also silently be ignored/not responded to. That would manifest itself in the same fashion as the previously-provided log; you wouldn't know the difference without doing actual packet captures (again on both sides, and 99.8% of customers do not have access to the ISPs DHCP server to do this).

    I remember reading about how for quite some time AT&T in the US had problems with their DHCP servers where sometimes DHCP requests would just "disappear into lala land" and after hours and hours of retrying eventually something would work. Root cause was unknown/never disclosed, other than someone concluding "they had DHCP server problems".

    It also doesn't help that Busybox tends to consist of absolutely atrocious code, so it wouldn't surprise me if this was some kind of broken logic bug. The ISC DHCP client is significantly superior in every way.
     
    Last edited: Jan 30, 2014
  8. Elbart

    Elbart LI Guru Member

    Interesting, I have a similar problem with my connection.
    But in my case I eventually get a NAK from the server right before or after the lease expires. I couldn't pinpoint the exact time yet.
    I assume the dhcp-server just ignores all requests unless they're done during the full dhcp-request.

    That's why I wanted the debug-version of udhcpc in the first place: To find out where the problem is.

    FWIW, currently I got tcpdump running, and it captured the initial DHCP-request. Now I'm waiting for half the lease time to run out, which will happen in a few hours.

    The long lease time of my ISP (four days) is also why I'd like to have the normal behavior for the dhcp-renew instead of doing the full request, which doesn't have the problem of getting no reply from the dhcp-server.

    PS: Thank you, koitsu, for writing a guide about compiling TomatoUSB.
     
    Last edited: Jan 30, 2014
  9. Elbart

    Elbart LI Guru Member

    Now the renew was sent, and... nothing.
    Wireshark: http://i.imgur.com/bkGc3aK.png
    Apparently my ISP (cable) is using a DHCP-relay (10.34....), and the renew is being unicasted to that IP. Is that even possible, from a public IP?
    Is there anything else I could do, except of consulting my ISP?
     
  10. mstombs

    mstombs Network Guru Member

    I've always assumed its an ISP thing, my cable connection has a big WAN netmask 255.255.252.0, and over the years the normal lease time has increased to 7 days, I assume the dhcp servers have to deal with TV boxes and modems as well, and be 'secure' against service theft! We now know sticky WAN IP addresses ease their NSA reporting!

    I think it is likely there's a cluster of servers hiding behind a dhcp-relay - there was a popular patch to iptables (included in Tomato) to accept replies from any IP on correct port which was supposed to help this.

    I do wonder if those historic patches to Busybox udhcpc are still needed?
     
  11. Elbart

    Elbart LI Guru Member

    Which is also working, as I get the responses from 10.x during the initial DHCP-talk.
    But then the DHCP-server doesn't get the following dhcprequests, or chooses to ignore them until the leasetime runs out.

    In your case, eventually you do get a reply. Probably after udhcpc switches from unicast to broadcast, which happens when the remaining-lease-timer is below 60 seconds.
    I stumbled over an iptables-rule which changes all sent dhcp-unicasts to broadcasts. Maybe you want to give it a try, although it needs some adaption: http://serverfault.com/questions/35...ery-15-seconds-instead-of-at-t1/391865#391865
     
    Last edited: Jan 31, 2014
  12. mstombs

    mstombs Network Guru Member

    Thanks, will try - but quick question - how to find out the dhcp server IP, preferably without breaking the link between cable and router, although I do have a 100Mbps hub that I could use with wireshark there!
     
  13. Elbart

    Elbart LI Guru Member

    Start tcpdump (linked by koitsu here) in the router's shell and run
    Code:
    tcpdump -i vlan2 -e -v -p -s 0 -n -U 'port 67 or port 68'
    and do a DHCP renew.
    Then quickly kill the tcpdump-instance or you'll be spammed with dhcp-broadcasts. Search for the one ACK with your IP and use the IP of "Server-ID Option 54, length 4:".

    EDIT:
    I tried that rule, and while I now get a reply after a simple renew, I only get a DHCPNAK. Better than nothing.
    And I couldn't delete the rule by exchanging -A with -D, and it wasn't listed when executing "iptables -t nat -nvL --line-numbers". YMMV.

    EDIT2:
    It's probably to be found when using "iptables -t mangle -nvL --line-numbers".
     
    Last edited: Jan 31, 2014
  14. mstombs

    mstombs Network Guru Member

    Thanks I used Rodneys tcpdump to watch a 'renew' invoked from the web gui

    router>Broadcast Discover
    ISP Gateway->router (direct using current WANIP) Offer
    router->Broadcast Request
    ISP Gateway-> router ACK.

    The IP given as the option 54 is a remote IP and is not pingable, so I do wonder if it is really handled locally by the ISP Gateway device, which would explain by unicasts to it don't get a reply! So I am trying this

    Code:
     iptables -t nat -A OUTPUT -d 62.0.0.0/255.0.0.0 -o vlan2 -p udp -m udp --dport 67 -j DNAT --to 255.255.255.255
    
    which does appear with

    Code:
    iptables -nvL -t nat
    ...
    
    Chain OUTPUT (policy ACCEPT 123 packets, 10944 bytes)
    pkts bytes target     prot opt in     out     source               destination
        0     0 DNAT       udp  --  *      vlan2   0.0.0.0/0            62.0.0.0/8          udp dpt:67 to:255.255.255.255
    
    but I have to wait a few days now for current lease to to start to try to auto renew
     
  15. mstombs

    mstombs Network Guru Member

    Well my auto-renew happened, and got a 7 day lease at first attempt, just got a kernel warning...

    Code:
    Feb 3 21:58:09 rtn66u daemon.info udhcpc[3005]: Sending renew...
    Feb 3 21:58:09 rtn66u user.warn kernel: NAT: no longer support implicit source local NAT
    Feb 3 21:58:09 rtn66u user.warn kernel: NAT: packet src 255.255.255.255 -> dst 62.a.b.c
    Feb 3 21:58:09 rtn66u daemon.info udhcpc[3005]: Lease of x.y.z.i obtained, lease time 604800
    So you seem to have fixed my problem Elbart, sorry it doesn't address your original problem...
     
  16. Elbart

    Elbart LI Guru Member

    Good to hear.
    I've got word from my ISP that they've got several issues with their DHCP-servers, and they're working on it. So that's covered too.
     

Share This Page