[Dnsmasq-discuss] log messages

[Tom Metro]

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.


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.


> 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?


> 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.


> 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.


> 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 or host name supplied in 
the offer.

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.

Also, it would be nice to see IPv4 addresses in the familiar dotted quad 
format, and other special values identified, like an infinite lease.


> DHCP packet: transaction-id is 517837001
> Available DHCP range: 192.168.0.200 -- 192.168.0.250

Repeated again for the request?


> 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?


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).

Let me guess the response...patches welcome? :-)

  -Tom

-- 
Tom Metro
Venture Logic, Newton, MA, USA
"Enterprise solutions through open source."
Professional Profile: http://tmetro.venturelogic.com/