Bind Queries log file format

[Michael Dahlberg]

In upgrading from BIND 9.10 to 9.11, it looks as if the query log file format has changed slightly:

Previously (9.10 variant) the entry looked something like this:

04-Nov-2016 10:34:03.991 queries: info: client 172.20.10.48#38997 (36.2.20.172.in-addr.arpa): query: 36.2.20.172.in-addr.arpa IN PTR + (172.20.4.2)

Now (9.11.0-P2) it looks similar to this:

24-Jan-2017 15:49:00.999 queries: info: client @0x7f6450002ef0 172.20.10.48#60418 (61.2.20.172.in-addr.arpa): query: 61.2.20.172.in-addr.arpa IN PTR + (172.20.2.2)

I can discern what almost all of the fields signify except for the part "@0x7f6450002ef0".  I'm pretty sure its not the hex value for the client IP address because I have many of these types of entries where the client IP address remains the same but the "@0x" value changes. 

Also, I can't seem to find anything in the ARM about this (but I may be looking in the wrong section (I was looking at the text on page 60).

Thanks for any assistance,

Mike

[Tony Finch]

Michael Dahlberg <olga...@gmail.com> wrote:

> I can discern what almost all of the fields signify except for the
> part "@0x7f6450002ef0".

It's the address in memory of the data structure representing the client.
It is mentioned in the CHANGES file (#4471) and in the release notes - see
https://source.isc.org/cgi-bin/gitweb.cgi?p=bind9.git;a=commitdiff;h=c4b7db49326be650fa95a7ede6e066bbe1268561

though the pointer field first turned up in
https://source.isc.org/cgi-bin/gitweb.cgi?p=bind9.git;a=commitdiff;h=a26a62cef2adba0520c5955d740fc75fa7f2c7f5

Tony.
--
f.anthony.n.finch <d...@dotat.at> http://dotat.at/ - I xn--zr8h punycode
Viking, North Utsire: Southerly or southwesterly 5 to 7, increasing gale 8 at
times. Moderate or rough, occasionally very rough. Fair. Moderate or good.

[Steven Carr]

On 25 January 2017 at 10:59, Tony Finch <d...@dotat.at> wrote:
> It's the address in memory of the data structure representing the client.
> It is mentioned in the CHANGES file (#4471) and in the release notes - see
> https://source.isc.org/cgi-bin/gitweb.cgi?p=bind9.git;a=commitdiff;h=c4b7db49326be650fa95a7ede6e066bbe1268561
>
> though the pointer field first turned up in
> https://source.isc.org/cgi-bin/gitweb.cgi?p=bind9.git;a=commitdiff;h=a26a62cef2adba0520c5955d740fc75fa7f2c7f5

Question back to the BIND team... why? what is the purpose of having
this value exposed in query logs? what exactly is it adding? If it was
a debug log then I can understand the need to have the memory address
exposed, but for the "regular" user what is the use case?

[Mukund Sivaraman]

When debugging problems, we look at logs. The pointer value is like a
tag or label that uniquely identifies the client object. Client objects
are recycled (reused) in named, and we look for their "identity" to
separate them from others.

Mukund

[Alan Clegg]

On 1/25/17 7:44 AM, Steven Carr wrote:
> On 25 January 2017 at 10:59, Tony Finch <d...@dotat.at> wrote:
>> It's the address in memory of the data structure representing the client.
>> It is mentioned in the CHANGES file (#4471) and in the release notes - see
>> https://source.isc.org/cgi-bin/gitweb.cgi?p=bind9.git;a=commitdiff;h=c4b7db49326be650fa95a7ede6e066bbe1268561
>>
>> though the pointer field first turned up in
>> https://source.isc.org/cgi-bin/gitweb.cgi?p=bind9.git;a=commitdiff;h=a26a62cef2adba0520c5955d740fc75fa7f2c7f5
>
> Question back to the BIND team... why? what is the purpose of having
> this value exposed in query logs? what exactly is it adding? If it was
> a debug log then I can understand the need to have the memory address
> exposed, but for the "regular" user what is the use case?

BIND is always in debug mode, even when it's not in debug mode.

I find this addition to the log to be annoying and useless in 99% of
actual end-user use cases.

And why shouldn't you need to re-jigger all of your monitoring scripts
to skip that field?

AlanC

[Mukund Sivaraman]

Rememeber that not only users, but even us developers have to look at
your logs when you send them to us.

When things are fine, the sun is shining, hay is growing.. all's fine,
and the fields in the log format that a user wants are sufficient.

When one out of numerous deployments of BIND reports a crash, and we're
not able to reproduce it, all we have is the effects that the reporter
can provide us. named is asynchronous software with numerous concurrent
wheels chugging, with some shared datastructures and non-shared request
specific structures. When things go bad, they show up as bad sometimes
a long time after the fact. If we are not able to reproduce it, looking
at logs and attempting to reconstruct what happened is like looking for
a needle in a haystack. In such cases, we find these bits of extra
information useful. Users may not like an extra field, but please bear
with us because it is helpful when things go bad.

This specific client pointer was useful in debugging such an issue and
that's why it was permanently added to the log.

Mukund

[Michael Dahlberg]

On Wed, Jan 25, 2017 at 8:51 AM, Mukund Sivaraman <mu...@isc.org> wrote:

Rememeber that not only users, but even us developers have to look at
your logs when you send them to us.

When things are fine, the sun is shining, hay is growing.. all's fine,
and the fields in the log format that a user wants are sufficient.

When one out of numerous deployments of BIND reports a crash, and we're
not able to reproduce it, all we have is the effects that the reporter
can provide us. named is asynchronous software with numerous concurrent
wheels chugging, with some shared datastructures and non-shared request
specific structures.  When things go bad, they show up as bad sometimes
a long time after the fact. If we are not able to reproduce it, looking
at logs and attempting to reconstruct what happened is like looking for
a needle in a haystack.  In such cases, we find these bits of extra
information useful. Users may not like an extra field, but please bear
with us because it is helpful when things go bad.

This specific client pointer was useful in debugging such an issue and
that's why it was permanently added to the log.

Mukund:

Yea, I can respect that.  However, I'm not confident that dropping it right in the middle of the log entry was the best place for it.  I have a number of processes that monitor the query logs (it seems like everybody wants to know where everybody else is going), and these logs can get BIG.  To ameliorate the amount of data that needs to be parsed, I throw out  the queries from systems that are not relevant.  With that single entry, everything became relevant according to my regex.  Making this addition to the beginning or the end of the log entry would have provided the developers the necessary data, and preserved my regex.

But, hey, at least now I know.

Thanks,

Mike

[Mukund Sivaraman]

Hi Michael

On Wed, Jan 25, 2017 at 09:11:41AM -0500, Michael Dahlberg wrote:
> Mukund:
>
> Yea, I can respect that. However, I'm not confident that dropping it right
> in the middle of the log entry was the best place for it. I have a number
> of processes that monitor the query logs (it seems like everybody wants to
> know where everybody else is going), and these logs can get BIG. To
> ameliorate the amount of data that needs to be parsed, I throw out the
> queries from systems that are not relevant. With that single entry,
> everything became relevant according to my regex. Making this addition to
> the beginning or the end of the log entry would have provided the
> developers the necessary data, and preserved my regex.

If you don't mind, can you send an email to <bind9...@isc.org> with
the format you'd like it to be in?

The only feedback we got for this change was this: By mistake, we had
introduced this change within an existing stable branch which broke
scripts for some users who understandably didn't expect such a change
within a stable release, whereas the change should have appeared only in
a new release branch made off master (in this case, master -> 9.11
only). If there's a feeling that some change is not up to the mark or
can be done differently, please file a bug and let us know.

(IIRC, the previous format was not consistent too.)

Mukund

[Paul Roberts]

I agree, there are an awful lot of systems and SIEM products that process querylogs. This one change will require a huge amount of re-engineering work in customer environments.

Paul

-----Original Message-----
From: bind-users [mailto:bind-user...@lists.isc.org] On Behalf Of Steven Carr
Sent: 25 January 2017 12:44
To: bind-users <bind-...@lists.isc.org>
Subject: Re: Bind Queries log file format

On 25 January 2017 at 10:59, Tony Finch <d...@dotat.at> wrote:
> It's the address in memory of the data structure representing the client.
> It is mentioned in the CHANGES file (#4471) and in the release notes -
> see
> https://source.isc.org/cgi-bin/gitweb.cgi?p=bind9.git;a=commitdiff;h=c
> 4b7db49326be650fa95a7ede6e066bbe1268561
>
> though the pointer field first turned up in
> https://source.isc.org/cgi-bin/gitweb.cgi?p=bind9.git;a=commitdiff;h=a
> 26a62cef2adba0520c5955d740fc75fa7f2c7f5

Question back to the BIND team... why? what is the purpose of having this value exposed in query logs? what exactly is it adding? If it was a debug log then I can understand the need to have the memory address exposed, but for the "regular" user what is the use case?

_______________________________________________
Please visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list

bind-users mailing list
bind-...@lists.isc.org
https://lists.isc.org/mailman/listinfo/bind-users

[Michael Dahlberg]

.On Thu, Feb 2, 2017 at 2:24 PM, Paul Roberts <pa...@callevanetworks.com> wrote:

I agree, there are an awful lot of systems and SIEM products that process querylogs. This one change will require a huge amount of re-engineering work in customer environments.

Exactly

Mukund:  We use Splunk to analyze the querylogs and we use a regex to drop unnecessary data.  I had to make the change in our regexes to avoid licensing issues.  I did not file a bug report because now that I've made the Splunk config changes, changing it back in the querylog format will once again invalidate my regex.

My criticism was not with the addition of the new data, but rather it's location.  It seems to me that right after the word "client" should come client data (like an IP address or host name), not the memory location for the running process.

Thank you, though, for your work on a fantastic piece of software.

Mike

[MURTARI, JOHN]

Folks at ISC,

> I agree, there are an awful lot of systems and SIEM products that process querylogs. This one change will require a huge amount > of re-engineering work in customer environments.

You know we love you and the work you do! But changing that log format was really a bad idea. I saw your original response that we should report it as a 'bug' and it was added so you could help us debugging problems.

IMHO -- it's not a bug (in the classic sense), it was an intentional change. Regarding needing more info for debug, I'd encourage the approach a lot of tools take: add a debug option to the config, start params, etc... to activate the feature.

Best regards!
John

[Mukund Sivaraman]

Hi John

We have the debug log level, but consider the case when an operator has
a non-deterministic or rare crash that isn't reproducible because the
operator has no information about what caused it. All we have is the
config, log that was already generated before the crash and perhaps a
backtrace and core to deduce the steps leading to the crash. It's not
possible to re-run that scenario with debug logging.

I'll create a ticket to put the client pointer at the end if that'll
help, but note that the syntax in 9.10 was not consistent either. 9.10
would log the client pointer when the client object didn't have a valid
peer.

Mukund

[Alan Clegg]

On 2/3/17 8:01 AM, Mukund Sivaraman wrote:

> We have the debug log level, but consider the case when an operator has
> a non-deterministic or rare crash that isn't reproducible because the
> operator has no information about what caused it. All we have is the
> config, log that was already generated before the crash and perhaps a
> backtrace and core to deduce the steps leading to the crash. It's not
> possible to re-run that scenario with debug logging.
>
> I'll create a ticket to put the client pointer at the end if that'll
> help, but note that the syntax in 9.10 was not consistent either. 9.10
> would log the client pointer when the client object didn't have a valid
> peer.

Adding code to allow enabling or disabling this output on the fly would
work MUCH better (as an example, see "rndc querylog"/ options "querylog
[on | off ]").

Adding a "well, we needed this one time" value to the middle of a
long-standardized log file does no customer any good and inconveniences
everyone.

You own the code and can do whatever you want to, but I'd recommend
making the default log message what it was prior to 9.10 and adding
additional fields via pre-configuration and "rndc".

AlanC

[Mukund Sivaraman]

We may move it to the end of the log message (bugs ticket #44606 has
been created for looking at it). Maybe its location was poor.. please
can everyone who participated in this thread say whether having it at
the end will be ok?

The query log is getting more fields at the end of it such as
CLIENT-SUBNET logging.

Making it a configurable option misses the reason it is the way it is -
please see the first paragraph quoted above.

This seems to be a case where having it is inconvenient, and not having
it is inconvenient.

Mukund

[Alan Clegg]

On 2/3/17 10:45 AM, Mukund Sivaraman wrote:
> On Fri, Feb 03, 2017 at 08:51:01AM -0600, Alan Clegg wrote:
>> On 2/3/17 8:01 AM, Mukund Sivaraman wrote:

>> Adding code to allow enabling or disabling this output on the fly would
>> work MUCH better (as an example, see "rndc querylog"/ options "querylog
>> [on | off ]").
>>
>> Adding a "well, we needed this one time" value to the middle of a
>> long-standardized log file does no customer any good and inconveniences
>> everyone.
>>
>> You own the code and can do whatever you want to, but I'd recommend
>> making the default log message what it was prior to 9.10 and adding
>> additional fields via pre-configuration and "rndc".
>
> We may move it to the end of the log message (bugs ticket #44606 has
> been created for looking at it). Maybe its location was poor.. please
> can everyone who participated in this thread say whether having it at
> the end will be ok?

Since we are all going to have to change our configs (and those of all
the people around the world that don't read this list), just make a
decision.

> Making it a configurable option misses the reason it is the way it is -
> please see the first paragraph quoted above.

The "rndc" option allows those that KNOW that they may need the data
begin the collection where everyone else isn't impacted. If you know
that this customer is at risk, tell them "run this command, it's going
to fark up your log files, but it won't screw over everyone else in the
world... once we get that data we are looking for, you can back down by
doing this other command.

> This seems to be a case where having it is inconvenient, and not having
> it is inconvenient.

I really don't care, but I hate seeing ISC make unilateral decisions
that don't really need to be made and messing up clients everywhere.

I swore after the response that I got last time I offered input on this
thread that I wouldn't be stupid enough to do it again. I've proven
myself to be just as stupid as before.

IMNSHO: THE LOG FILE IS NOT THE PLACE FOR ONE-OFF DEBUGGING INFORMATION.
<SHUT UP, ALAN... SHUT UP>

AlanC

[Michael Dahlberg]

On Fri, Feb 3, 2017 at 11:45 AM, Mukund Sivaraman <mu...@isc.org> wrote:

We may move it to the end of the log message (bugs ticket #44606 has
been created for looking at it). Maybe its location was poor.. please
can everyone who participated in this thread say whether having it at
the end will be ok?

Appending additional info to the entry would be fine.

Mike 

[G.W. Haywood]

Hi there,

For the avoidance of doubt, It seems to me that the stability of BIND
has been improving over the last couple of years.

Thank you. Keep it up.

If I were hunting some rarely-seen fault condition, I think I'd write
any output which is more useful for debugging than anything else to a
separate file - even if that results in duplication of a little of the
information written to more 'routine' logs, and especially if it's the
kind of information which can cheerfully be purged every hour or two.
Debug and routine log rotations (and storage) can then be different.

Of course if the log message format isn't exactly what's needed in any
particular situation, the source code is freely available.

--

73,
Ged.

[Phil Mayers]

On 03/02/17 16:53, Alan Clegg wrote:

> The "rndc" option allows those that KNOW that they may need the data
> begin the collection where everyone else isn't impacted. If you know
> that this customer is at risk, tell them "run this command, it's going

FWIW, I would tend to agree with this approach; piling a bunch of
mostly-unused data into the logs for these very rare events is not an
obvious solution IMHO.

[Phil Mayers]

On 03/02/17 16:45, Mukund Sivaraman wrote:

> The query log is getting more fields at the end of it such as
> CLIENT-SUBNET logging.

Although it would be super-disruptive, has any thought been given to
moving to an entirely new log format, for example k/v or JSON? They're a
lot more extendable going forward and most SIEM/ML systems will read
them with no additional configuration.

Adding the query log hex/ptr thing just inconvenienced me. Strangely,
changing the entire format to k/v would have massively helped me. This
applies across all logs (RPZ in particular).

Obviously one sample isn't enough but it's maybe something to consider?

[Phil Mayers]

Sorry I should expand on this point given my other mail; adding extra
and largely-unused data absent a structured format is not an obvious
solution; structure would change my stance on that, although one still
wants to be reasonably parsimonious with space.

[Timothe Litt]

I'm not sure whether I'm in favor of this approach, but it's not
necessarily very disruptive.

It would be trivial to script a converter from JSON to the current log
format - or even one that took a format string to select whatever fields
in random order. Pipe a new log file though it to existing log readers,
and you're done.

For almost complete transparency, embed in a daemon that continuously
reads the JSON log & appends to the traditional log; the existing log
readers can read the old format in near real-time...

Then when a support issue (or other requirement) comes up, the enhanced
data is in the JSON log.

When your old log processor is upgraded to use a new field, just add it
to the converter (format).

New processors would preferably read the JSON/native format directly.

The only annoyance is having to manage 2 log files (and some disk space).

FWIW

[MURTARI, JOHN]

> We may move it to the end of the log message (bugs ticket #44606 has
> been created for looking at it). Maybe its location was poor.. please
> can everyone who participated in this thread say whether having it at
> the end will be ok?

It's really only for code debug. I'd say give the admin a means via rndc/config
to turn it on 'debug' if needed. That also allows you to add anything else you might
like in the future.
John


-----Original Message-----

From: Mukund Sivaraman <mu...@isc.org>
To: Alan Clegg <al...@clegg.com>
Cc: bind-...@lists.isc.org
Subject: Re: Bind Queries log file format

Message-ID: <20170203164526.GA6221@jurassic>
Content-Type: text/plain; charset="us-ascii"

On Fri, Feb 03, 2017 at 08:51:01AM -0600, Alan Clegg wrote:
> On 2/3/17 8:01 AM, Mukund Sivaraman wrote:
>

> > We have the debug log level, but consider the case when an operator has
> > a non-deterministic or rare crash that isn't reproducible because the
> > operator has no information about what caused it. All we have is the
> > config, log that was already generated before the crash and perhaps a
> > backtrace and core to deduce the steps leading to the crash. It's not
> > possible to re-run that scenario with debug logging.
> >
> > I'll create a ticket to put the client pointer at the end if that'll
> > help, but note that the syntax in 9.10 was not consistent either. 9.10
> > would log the client pointer when the client object didn't have a valid
> > peer.
>

> Adding code to allow enabling or disabling this output on the fly would
> work MUCH better (as an example, see "rndc querylog"/ options "querylog
> [on | off ]").
>
> Adding a "well, we needed this one time" value to the middle of a
> long-standardized log file does no customer any good and inconveniences
> everyone.
>
> You own the code and can do whatever you want to, but I'd recommend
> making the default log message what it was prior to 9.10 and adding
> additional fields via pre-configuration and "rndc".

We may move it to the end of the log message (bugs ticket #44606 has
been created for looking at it). Maybe its location was poor.. please
can everyone who participated in this thread say whether having it at
the end will be ok?

The query log is getting more fields at the end of it such as
CLIENT-SUBNET logging.

Making it a configurable option misses the reason it is the way it is -
please see the first paragraph quoted above.

This seems to be a case where having it is inconvenient, and not having
it is inconvenient.

Mukund

[Warren Kumari]

On Mon, Feb 6, 2017 at 7:44 AM, MURTARI, JOHN <jm5...@att.com> wrote:
>> We may move it to the end of the log message (bugs ticket #44606 has
>> been created for looking at it). Maybe its location was poor.. please
>> can everyone who participated in this thread say whether having it at
>> the end will be ok?
>
> It's really only for code debug. I'd say give the admin a means via rndc/config
> to turn it on 'debug' if needed. That also allows you to add anything else you might
> like in the future.

I suspect perhaps some of the thread got missed (or was unclear).

The reason for adding it to the main log file *by default* is because
of things like:
Customer: "My BIND went Boom! It's been running fine for many years,
and then for no reason at all it went Boom. Here are my log files..."
ISC: "Doh. Sorry. Unfortunately the log file doesn't have sufficient
debug info. Can you please turn on debug using <insert invocation>, so
that we have enough logging info next time this happens?"
Customer: "Bah. Ok. Will do...."
<Customer enables debugging. named runs again for many years. Either
named doesn't oops again, or, more likely, 3 years later customer
wonders why extra logging is on, and turns it off - and then 2 weeks
later named ooopes...>

The additional logging info is specifically for the unusual bugs,
which happen very rarely - asking customers to enable the additional
logs after a rare event (which might not happen again for months /
years) means that ISC cannot hunt down and squash the corner case
bugs...

W

> _______________________________________________
> Please visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list
>
> bind-users mailing list
> bind-...@lists.isc.org
> https://lists.isc.org/mailman/listinfo/bind-users

--
I don't think the execution is relevant when it was obviously a bad
idea in the first place.
This is like putting rabid weasels in your pants, and later expressing
regret at having chosen those particular rabid weasels and that pair
of pants.
---maf

[Reindl Harald]

Am 06.02.2017 um 14:25 schrieb Warren Kumari:
> I suspect perhaps some of the thread got missed (or was unclear).
>
> The reason for adding it to the main log file *by default* is because
> of things like:
> Customer: "My BIND went Boom! It's been running fine for many years,
> and then for no reason at all it went Boom. Here are my log files..."
> ISC: "Doh. Sorry. Unfortunately the log file doesn't have sufficient
> debug info. Can you please turn on debug using <insert invocation>, so
> that we have enough logging info next time this happens?"
> Customer: "Bah. Ok. Will do...."
> <Customer enables debugging. named runs again for many years. Either
> named doesn't oops again, or, more likely, 3 years later customer
> wonders why extra logging is on, and turns it off - and then 2 weeks
> later named ooopes...>
>
> The additional logging info is specifically for the unusual bugs,
> which happen very rarely - asking customers to enable the additional
> logs after a rare event (which might not happen again for months /
> years) means that ISC cannot hunt down and squash the corner case
> bugs...

that was all clear - but it don't justify include debug informations in
the standard query log - in doubt write that informations to a
*specific* logfile by default and give the knowledgebale admin a config
option to disable that debugging logic at all

i have a similar issue currently with logwatch and a by upstream changed
log format of python spf-policyd leading in logwatch spit auch megabyte
large mails every night with "unmatched entries" and at the same time
really useful self written scripts seeking possible whitelist_auth
candidates for spamassassin got broken

touching logformats has unknown consequenses all over the world even at
places nobody would imagine until something got broken

[MURTARI, JOHN]

> From: Warren Kumari [mailto:war...@kumari.net]

> Customer: "My BIND went Boom! It's been running fine for many years,
> and then for no reason at all it went Boom. Here are my log files..."
> ISC: "Doh. Sorry. Unfortunately the log file doesn't have sufficient
> debug info. Can you please turn on debug using <insert invocation>, so
> that we have enough logging info next time this happens?"
> Customer: "Bah. Ok. Will do...."

.....

> The additional logging info is specifically for the unusual bugs,
> which happen very rarely - asking customers to enable the additional
> logs after a rare event (which might not happen again for months /
> years) means that ISC cannot hunt down and squash the corner case
> bugs...

I can understand the above. ISC needs the data to help debug
a once-in-a-blue-moon crash. But many busy sites do not have query logging
turned on at all (or only run sampling periods) and would not benefit anyway.

It would seem this debug info should be moved to a separate log
used only for that purpose and always 'on'. But that brings up other issues....

I've been a sys admin for many years. If a utility crashes enough to
bother me I'll turn on more detailed logging.....

John

[Paul Roberts]

I have to say I agree with the approach of putting this extra info into a separate file. I appreciate this could cause additional problems (disk utilisation, extra I/O's, log rolling etc.) but I would prefer to keep the query log format as stable as possible. I am still mopping up the last big change when ISC added the FQDN reference at the start of each message and I'm getting a little tired of dealing with customers and their broken regex's when log formats change because they've upgraded BIND.

There are also wider implications - there are products out there that hard code the regex and it can't be modified, so that then requires dealing with vendors, submitting bug reports/enhancement requests, providing evidence, business impact statements, also I have to perform root cause analysis for customers why their SIEM is no longer capturing the logs, which can have serious regulatory implications and consequences (banks etc.), then there's testing every upgrade in the lab before we run in production etc., I have enough work on my plate as it is! :-)

Basically there's a whole world of pain out there that can be avoided if you just keep the log format the same. :-)

Thanks,

Paul

-----Original Message-----
From: bind-users [mailto:bind-user...@lists.isc.org] On Behalf Of MURTARI, JOHN
Sent: 06 February 2017 17:05
To: bind-...@lists.isc.org
Subject: RE: Bind Queries log file format

[snip]

> The additional logging info is specifically for the unusual bugs,
> which happen very rarely - asking customers to enable the additional
> logs after a rare event (which might not happen again for months /
> years) means that ISC cannot hunt down and squash the corner case
> bugs...

I can understand the above. ISC needs the data to help debug a once-in-a-blue-moon crash. But many busy sites do not have query logging turned on at all (or only run sampling periods) and would not benefit anyway.

It would seem this debug info should be moved to a separate log used only for that purpose and always 'on'. But that brings up other issues....

I've been a sys admin for many years. If a utility crashes enough to bother me I'll turn on more detailed logging.....

John

[Mark Andrews]

In message <DB6PR0501MB2309198D1...@DB6PR0501MB2309.eurprd05.p

rod.outlook.com>, Paul Roberts writes:
> I have to say I agree with the approach of putting this extra info into a sep
> arate file. I appreciate this could cause additional problems (disk utilisati
> on, extra I/O's, log rolling etc.) but I would prefer to keep the query log f
> ormat as stable as possible. I am still mopping up the last big change when I
> SC added the FQDN reference at the start of each message and I'm getting a li
> ttle tired of dealing with customers and their broken regex's when log format
> s change because they've upgraded BIND.
>
> There are also wider implications - there are products out there that hard co
> de the regex and it can't be modified, so that then requires dealing with ven
> dors, submitting bug reports/enhancement requests, providing evidence, busine
> ss impact statements, also I have to perform root cause analysis for customer
> s why their SIEM is no longer capturing the logs, which can have serious regu
> latory implications and consequences (banks etc.), then there's testing every
> upgrade in the lab before we run in production etc., I have enough work on m
> y plate as it is! :-)
>
> Basically there's a whole world of pain out there that can be avoided if you
> just keep the log format the same. :-)
>
> Thanks,
>
> Paul

Change happens. The DNS protocol has expanded enormously from the
original specification. To expect the summary log line to not
change with that change is just not realistic. We do try to keep
the format change to a .0 release. This one we missed.

We currently log:

client, qname, qclass, qtype, RD (+/-), was the request signed (S),
the EDNS with version, was it over TCP (T), was DO=1 set (D), was
CD=1 set (C), were DNS COOKIES in use and was it a valide server
cookie or just a client cookie (V, K). We log the interface it was
received on and if the ECS option.

Not everyone wants all of these details but someone wants everyone
of these.

9.1.0: client, qname, qclass, qtype
9.2.0: client, qname, qclass, qtype
9.3.0: client, qname, qclass, qtype, RD, signed, EDNS
9.4.0: client, qname, qclass, qtype, RD, signed, EDNS
9.5.0: client, qname, qclass, qtype, RD, signed, EDNS, DO, CD
9.6.0: client, qname, qclass, qtype, RD, signed, EDNS, DO, CD
9.7.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD, local address
9.8.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD, local address
9.9.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD, local address
9.10.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD, local address
9.11.0: client, qname, qclass, qtype, RD, signed, EDNS + version, TCP, DO, CD, cookies, local address
9.12.0: client, qname, qclass, qtype, RD, signed, EDNS + version, TCP, DO, CD, cookies, local address, ecs

That's basically 5 changes in 17 years.

Mark
--
Mark Andrews, ISC
1 Seymour St., Dundas Valley, NSW 2117, Australia
PHONE: +61 2 9871 4742 INTERNET: ma...@isc.org

[Larry Stone]

I’ve been around long enough to remember when upward compatability was something that was expected. A program built to work with the current version of data (e.g. data records, log records, whatever) or even a shared library was expected to be able to continue to work with all future versions without the need for changes or rebuilding/recompiling. For data, that meant new fields went on the end of the record so that anything expecting the old format still found everything where it always was and the new stuff was at the end of the record where the old programs never even looked. But sadly, this appears to be a lost art these days.

Where I work, we have a data set that has 20 years of data in it. Over the years, the record length was extended but once a field was placed at a given point in the record, it never, ever moved so that programs written years ago that had no need for the new fields still ran just fine. And with hundreds if not thousands of programs around the company that read this data set, insuring that format changes did not break things was a very high priority. Occasionally, fields went away in which case that spot in the record was just left blank for all new records.

For the BIND log records described below, what I describe appears to be what was done through 9.10.0. But then at 9.11.0, we have a field in the middle of the record being changed (EDNS changed to EDNS+version). What, IMHO, should have been done here was to put the version on the end (either going with a split filed - EDNS in one place and the version in another or by duplicating EDNS by having it without version where it was and then again with version on the end of the record) so that old programs parsing the log file still worked. So instead of:

> 9.10.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD, local address
> 9.11.0: client, qname, qclass, qtype, RD, signed, EDNS + version, TCP, DO, CD, cookies, local address
> 9.12.0: client, qname, qclass, qtype, RD, signed, EDNS + version, TCP, DO, CD, cookies, local address, ecs

it should have been

> 9.10.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD, local address

> 9.11.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD, cookies, local address, EDNSversion
> 9.12.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD, cookies, local address, EDNSversion, ecs

--
Larry Stone
lsto...@stonejongleux.com

[Paul Kosinski]

"I’ve been around long enough to remember when upward compatibility was
something that was expected."

Having been around since before even Unix, I must say I agree totally.

As I understand it, Linus does not take kindly to Linux Kernel changes
that break forward/upward compatibility (of the ABI). I don't think BIND
should do any less.

If a new format is needed for more extensive logging, then add a new
log option (just as new Kernel interfaces are added from time to time).

[Mark Andrews]

In message <2C577494-613A-419C...@stonejongleux.com>, Larry Stone writes:
> Ive been around long enough to remember when upward compatability was

> something that was expected. A program built to work with the current
> version of data (e.g. data records, log records, whatever) or even a
> shared library was expected to be able to continue to work with all
> future versions without the need for changes or rebuilding/recompiling.
> For data, that meant new fields went on the end of the record so that
> anything expecting the old format still found everything where it always
> was and the new stuff was at the end of the record where the old programs
> never even looked. But sadly, this appears to be a lost art these days.

BIND 9.12.0 will work with valid zone files from BIND 4.8. Named
has got better with detecting errors in those zone files so a modern
version will reject some zone files that were incorrectly accepted
by BIND 4.8.

> Where I work, we have a data set that has 20 years of data in it. Over
> the years, the record length was extended but once a field was placed at
> a given point in the record, it never, ever moved so that programs
> written years ago that had no need for the new fields still ran just
> fine. And with hundreds if not thousands of programs around the company
> that read this data set, insuring that format changes did not break
> things was a very high priority. Occasionally, fields went away in which
> case that spot in the record was just left blank for all new records.
>
> For the BIND log records described below, what I describe appears to be
> what was done through 9.10.0. But then at 9.11.0, we have a field in the
> middle of the record being changed (EDNS changed to EDNS+version).

No, we have a field that has more information in it. Same field E -> E(version)

08-Feb-2017 15:15:44.532 client @0x7fc1c803c600 127.0.0.1#57982/key external (rock.dv.isc.org): view external: query: rock.dv.isc.org IN A -SE(0)DV (127.0.0.1)

Or with ECS

08-Feb-2017 15:56:27.109 client @0x7fc1c503e800 127.0.0.1#63454 (.): view external: query: . IN SOA -E(0)DV (127.0.0.1) [ECS 127.0.0.0/8/0]

Or from a stub resolver.

08-Feb-2017 16:02:22.971 client @0x7fc1c490dc00 127.0.0.1#61028 (sprocket.isc.org): view secure: query: sprocket.isc.org IN A + (127.0.0.1)

Mark

> What,
> IMHO, should have been done here was to put the version on the end
> (either going with a split filed - EDNS in one place and the version in
> another or by duplicating EDNS by having it without version where it was
> and then again with version on the end of the record) so that old
> programs parsing the log file still worked. So instead of:
> > 9.10.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD,
> local address
> > 9.11.0: client, qname, qclass, qtype, RD, signed, EDNS + version, TCP,
> DO, CD, cookies, local address
> > 9.12.0: client, qname, qclass, qtype, RD, signed, EDNS + version, TCP,
> DO, CD, cookies, local address, ecs
>
>
> it should have been
> > 9.10.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD,
> local address
> > 9.11.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD,
> cookies, local address, EDNSversion
> > 9.12.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD,
> cookies, local address, EDNSversion, ecs
>

> --
> Larry Stone
> lsto...@stonejongleux.com

[Larry Stone]

> On Feb 7, 2017, at 11:07 PM, Mark Andrews <ma...@isc.org> wrote:
>
>
> No, we have a field that has more information in it. Same field E -> E(version)
>
> 08-Feb-2017 15:15:44.532 client @0x7fc1c803c600 127.0.0.1#57982/key external (rock.dv.isc.org): view external: query: rock.dv.isc.org IN A -SE(0)DV (127.0.0.1)
>
> Or with ECS
>
> 08-Feb-2017 15:56:27.109 client @0x7fc1c503e800 127.0.0.1#63454 (.): view external: query: . IN SOA -E(0)DV (127.0.0.1) [ECS 127.0.0.0/8/0]
>
> Or from a stub resolver.
>
> 08-Feb-2017 16:02:22.971 client @0x7fc1c490dc00 127.0.0.1#61028 (sprocket.isc.org): view secure: query: sprocket.isc.org IN A + (127.0.0.1)

Fair enough, provided depending on how the format of the log record is defined (columns or by field delimiters), it’s still the same format and E(version) is something that will make sense (for however you would define sense here) to an older program expecting just E.

But in my haste in my original posting, I picked up on E to E(version) change but missed that in going from 9.10.0 to 9.11.0, you inserted cookies between CD and local address. That should have gone on the end (perhaps that’s what this whole thing is about - I rarely look at BIND log files and when I do, it’s just me reading them, no parsing program involved). So restating what I originally posted, instead of:

9.10.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD, local address
9.11.0: client, qname, qclass, qtype, RD, signed, EDNS + version, TCP, DO, CD, cookies, local address
9.12.0: client, qname, qclass, qtype, RD, signed, EDNS + version, TCP, DO, CD, cookies, local address, ecs


it should have been
9.10.0: client, qname, qclass, qtype, RD, signed, EDNS, TCP, DO, CD, local address

9.11.0: client, qname, qclass, qtype, RD, signed, EDNS + version, TCP, DO, CD, local address, cookies
9.12.0: client, qname, qclass, qtype, RD, signed, EDNS + version, TCP, DO, CD, local address, cookies, ecs

--
Larry Stone
lsto...@stonejongleux.com