[Dnsmasq-discuss] log messages

Tom Metro tmetro+dnsmasq at gmail.com
Mon Apr 6 21:55:11 BST 2009


Simon Kelley wrote:
> Tom Metro wrote:
>> ...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...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.

I figured that, but take for example the logging of requested options, 
which occurs after the offer is logged. I'm guessing this happens 
because the routine to construct the offer packet first logs that it is 
sending an offer, then parses the previously received discover to 
determine what to put into the offer, and the logging of the requested 
options happens as a side effect of the parsing.

If that's the case, maybe the ordering can be nudged closer to the ideal 
simply by delaying the point in the code where the offer packet gets logged.

If lines are descriptively tagged, the ordering doesn't matter so much, 
so mostly I'm just suggesting that the code might benefit from a review 
to see if easy improvements can be made.


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

Makes sense. Incorporating that into the slightly more verbose log 
format I proposed might look like:

517837001: DHCPDISCOVER from 00:04:...:d1:33 on eth0


>> Missing is a clear indication of the client ID 
>> or host name supplied in the offer.
>
> The client-ID comes from the client, not the server.

Sorry, I meant to say discover above.

The point being that both can be critical in how an IP address is 
selected by Dnsmasq, so being able to confirm that your client is 
sending the expected identifiers is very useful.


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

Is it an oversight that it gets logged for the offer and not the ack, if 
both packets contain the same host name? Is the thought something like, 
we won't bother logging this extraneous detail until it is finalized, 
and then we'll log it just once?

There's logic in that, but I'd rather see these per-packet log message 
be orthogonal and consistent, and a separate summary log line (see 
below) used to convey the final result of the transaction.


>> 517837001: tags: known, eth0
>> 517837001: matched dhcp-host rule 23, host: mythtv
>>
>> 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.

To clarify, I was asking whether it made sense to log the two lines 
shown above that indicate what logic Dnsmasq applied to the inbound 
packet to arrive at the response. But I think your comment answers the 
question. Same rules apply to both packet pairs.


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

Actually wireshark is precisely what I'm trying to avoid. I'm trying to 
think back to Dnsmasq debugging scenarios and determine what information 
Dnsmasq has at its disposal that it can log which will more rapidly lead 
to determining whether it is a client or server side problem.

There is also information internal to Dnsmasq that can't be gleaned from 
wireshark, like what config rule Dnsmasq employed for determining the reply.


On a related note, I could see some benefit to having a single log line 
that summaries the success or failure of an entire DHCP transaction. For 
example:

DHCP: assigned 192.168.0.235 to 00:04:...:d1:33 on eth0 with host mythtv
DHCP: nak to 00:04:...:d1:33 on eth0: (error message)

This could be provided in addition to the low-detail log messages 
(probably with a different syslog priority), or become the default 
logging output, with the per-packet messages appearing only in the 
log-dhcp enabled output.

It would handy for those that just want a record of what got assigned to 
who. (These lines would also be of use to log summary tools, like 
logwatch.) Of course the DHCPACK message effectively serves this 
purpose...the summary line would just present it in a slightly more 
friendly way and eliminate the clutter of the other packet log lines.

  -Tom

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



More information about the Dnsmasq-discuss mailing list