[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