[Dnsmasq-discuss] log messages

[Simon Kelley]

Tom Metro wrote:
> Simon Kelley wrote:
>> Tom Metro wrote:
>>> ...it'd be great if Dnsmasq's logging could be enhanced to include
>>> some of the identifying information supplied by the client, an
>>> indication of what rule Dnsmasq used to determine the assigned IP
>>> address, and an indication of whether Dnsmasq is receiving or sending
>>> the packets.
>>
>> DHCPOFFER, DHCPACK and DHCPNAK are _sent_ by dnsmasq, every other
>> packet type is sent by the client.
> 
> Well, sure, it's easy enough to figure out if you happen to already know 
> the DHCP protocol. But for a casual user, adding some hints would help.
> 
> 
>>> Perhaps there's a debug mode that provides this?
>>
>> log-dhcp will dump a lot of extra information. 
> 
> I turned on log-dhcp, and it does add some additional useful 
> information, but there are still some information gaps, and the ordering 
> of the log messages is less than ideal.

The ordering is largely determined by when the information is available. 
dnsmasq runs on small systems, including MMU-less ones, so freely 
malloc-ing memory is to be avoided. The code is carefully written to 
extract all the required information from an incoming packet and then 
construct the outgoing packet in its place. Thus some information may 
have evaporated by the time the code reaches a "natural" place to log it.
> 
> 
> Taking a look at some example log lines:
> 
>> DHCP packet: transaction-id is 517837001
> 
> Is this an ID that applies to all the packets in a 
> discover/offer/request/ack handshake? If so, isn't that something that 
> should be incorporated into each log line related to that transaction so 
> that overlapping requests in the log can be correlated? Similar to how 
> mail servers will tag all related lines with a queue ID.
> 
That's probably possible, and worth doing.

> 
>> Available DHCP range: 192.168.0.200 -- 192.168.0.250
> 
> Why is this repeated in the log at the start of each handshake? Isn't it 
> static configuration information? Or is this providing some indication 
> of what network Dnsmasq thinks it is serving at the moment, based on 
> attributes of the discover?
> 
The later.
> 
>> Vendor class: udhcp 0.9.9-pre
> 
> I presume this is an attribute of the offer, but it seems disembodied 
> from the offer packet that hasn't been logged yet.
>

See first paragraph.

> 
>> DHCPDISCOVER(eth0) 00:04:61:4b:d1:33 
> 
> Can inclusion of the interface be made conditional upon configuration 
> settings that make it relevant? For the vast majority of use cases, 
> there will only be one interface.
> 
Many setups have multiple interfaces. Every firewall with a DMZ, for 
instance.

> 
>> DHCPOFFER(eth0) 192.168.0.235 00:04:61:4b:d1:33 requested options: 
>> 1:netmask, 3:router, 6:dns-server, 12:hostname, requested options: 
>> 15:domain-name, 17:root-path, 28:broadcast, requested options: 
>> 40:nis-domain, 41:nis-server, 42:ntp-server
> 
> These requested lines are affiliated with the discover (no?), but are 
> logged after the offer. That's a bit misleading.
> 
> Missing is a clear indication of the client ID 
The client-ID comes from the client, not the server.
> or host name supplied in 
> the offer.
> 
The hostname is logged as the last field of a DHCPACK message.

> Also missing is some indication of what logic Dnsmasq used to determine 
> the IP address to assign. I'm not sure how config file rules would be 
> identified, but Dnsmasq must contain some sort of a decision tree, and 
> each branch could log appropriate messages, like "matched dhcp-host rule 
> 23" or "no rule match; assigning from dynamic pool."
> 
> 
>> bootfile name: dongle.bin
>> server name: mythtv
>> next server: 192.168.0.35
> 
> These are attributes sent in the offer, but that isn't clearly indicated.
> 
> 
>> tags: known, eth0
> 
> In contrast, this is a Dnsmasq internal attribute, right?
> 
> 
>> sent size:  1 option: 53:message-type  02
>> sent size:  4 option: 54:server-identifier  c0:a8:00:23
>> sent size:  4 option: 51:lease-time  ff:ff:ff:ff
> 
> Is the size information generally useful for debugging DHCP problems? It 
> sounds like something that is statically declared in the source.
The hex printout of long options is truncated, so total size is useful.

> 
> Also, it would be nice to see IPv4 addresses in the familiar dotted quad 
> format, and other special values identified, like an infinite lease.
> 
> 
That used not to be possible, since dnsmasq had no knowledge of the 
data-format of options. Since is no does know at least which options 
carry lists of IP addresses, that could be done better.

>> DHCP packet: transaction-id is 517837001
>> Available DHCP range: 192.168.0.200 -- 192.168.0.250
> 
> Repeated again for the request?
> 
It's calculated and used for each DHCP packet.

> 
>> DHCPOFFER(eth0) 192.168.0.235 00:04:...:d1:33 
> ...
>> DHCPACK(eth0) 192.168.0.235 00:04:...:d1:33 indianpoint
> 
> Is it an accurate reflection of the packet contents that a DHCPACK reply 
> logs a host name, but the DHCPOFFER does not?
> 

It's not a reflection of packet contents (that field can contain other 
messages)
> 
> Here's a hypothetical log without extended log information:
> 
> 517837001: DHCPDISCOVER from 00:04:...:d1:33 (CID: indianpoint, host: 
> indianpoint)
> 517837001: DHCPOFFER to 00:04:...:d1:33: IP: 192.168.0.235, host: 
> indianpoint
> 517837001: DHCPREQUEST from 00:04:...:d1:33: for IP: 192.168.0.235
> 517837001: DHCPACK to 00:04:...:d1:33: IP: 192.168.0.235, host: indianpoint
> 
> 
> And one with the extended log information:
> 
> 517837001: DHCPDISCOVER from 00:04:...:d1:33 (CID: mythtv, host: mythtv)
> 517837001: DHCPDISCOVER: req attr: vendor class: udhcp 0.9.9-pre
> 517837001: DHCPDISCOVER: req attr: client ID: mythtv
> 517837001: DHCPDISCOVER: req attr: host: mythtv
> 517837001: DHCPDISCOVER: req opt: netmask[1], router[3], dns-server[6], 
> hostname[12],
> 517837001: DHCPDISCOVER: req opt: domain-name[15], root-path[17], 
> broadcast[28],
> 517837001: DHCPDISCOVER: req opt: nis-domain[40], nis-server[41], 
> ntp-server[42]
> 517837001: tags: known, eth0
> 517837001: matched dhcp-host rule 23, host: mythtv
> 517837001: DHCPOFFER to 00:04:...:d1:33: IP: 192.168.0.235, host: mythtv
> 517837001: DHCPOFFER: sent atr: bootfile name: dongle.bin
> 517837001: DHCPOFFER: sent atr: server name: mythtv
> 517837001: DHCPOFFER: sent atr: next server: 192.168.0.35
> 517837001: DHCPOFFER: sent opt: message-type[53]: 02 (size 1)
> 517837001: DHCPOFFER: sent opt: server-identifier[54]: 192.168.0.35 
> (size 4)
> 517837001: DHCPOFFER: sent opt: lease-time[51]: ff:ff:ff:ff (infinite) 
> (size 4)
> [...]
> 
> The DHCPREQUEST looks pretty much the same as the DHCPDISCOVER, and 
> likewise for the DHCPOFFER/DHCPACK pair.
> 
> When Dnsmasq receives a DHCPREQUEST, does it go through the IP 
> assignment logic again, or does it have that cached from the offer? I 
> presume that you'd do a few sanity checks on the request to make sure it 
> is consistent with the original discover, but primarily look at the 
> request to determine which options to include in the ack. If so, there 
> probably isn't anything useful to log between the request and ack 
> (unlike above where knowing what rules led from discover to offer is 
> useful).

Lease renewal and clients in INIt_REBOOT state only exhange REQUEST and 
ACK packets, so it's certainly useful to log them.

> 
> Let me guess the response...patches welcome? :-)
Patches are always welcome :-)
> 

It sounds like you're trying to understand DHCP, in which case the log 
messages from dnsmasq might not be the best tool. I suggest trying 
wireshark, which is a superb tool for displaying the contents of DHCP 
(and all other) packets, and RFC-2131 for the specification of the protocol.


Cheers,

Simon.


>  -Tom
>