[Dnsmasq-discuss] log messages

Simon Kelley simon at thekelleys.org.uk
Tue Apr 7 19:50:07 BST 2009


Tom Metro wrote:
> 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,

Apologies that I've not had time to read your mail in detail: I will do 
so. In the meantime dnsmasq-2.48test13  has some of your previous 
suggestions,

Prefix each line with transaction-id
Log client-provided hostname
Display option values as dotted-quad or text strings where appropriate.

Cheers

Simon.





More information about the Dnsmasq-discuss mailing list