"recursion available: denied" message even for non-recursive queries?

[gschmid at notes.cc.sunysb.edu]

> > gschmid at notes.cc.sunysb.edu wrote:
> >
> > > I'm running 9.2.0 on a Tru64/DEC UNIX box.
> > >
> > > In my named.conf file I have an
> > >       allow-recursion { acl_list; };
> > > statement.
> > >
> > > Everything seems to be working as expected.
> > > Hosts on the acl list get answers to all queries.
> > > Hosts not on the acl list do not get answers to
> > > recursive queries.
> > >
> > > The question that I have is with the logging of the
> > > security category messages when my name server
> > > is queried from hosts not on the acl list.
> > >
> > > I get the following log message:
> > >
> > > recursion available: denied
> > >
> > > when hosts who are not on the acl list make
> > > recursive *and* non-recursive queries.  I would
> > > have expected that message only when hosts
> > > not on the acl list make recursive queries.
> > > Why do I also get the message when hosts not
> > > on the acl list make non-recursive queries
> > > (and get answers to those non-rec. queries)?
> >
> > I'd consider it a logging bug. Even if the message is intended to be
> > purely informational, it shouldn't use the term "denied" in this
> situation, nor should it log to the "security" category.
> >
> >
> > - Kevin
>
>              Well if you turn on debugging you get lots of additional
>              things logged.
>
>              Mark
>
> OK, I've restarted named with a "-d 9" and made two queries, one
recursive
> and one non-recursive.
>
> The security log file shows:
>
> Apr 04 10:04:06.825 security: client 192.168.99.28#10203: recursion
> available: denied
> Apr 04 10:04:25.864 security: client 192.168.99.28#10195: recursion
> available: denied
>
> and the named.run file shows:
>
> Apr 04 10:04:06.824 client 192.168.99.28#10203: UDP request
> Apr 04 10:04:06.825 client 192.168.99.28#10203: using view '_default'
> Apr 04 10:04:06.825 client 192.168.99.28#10203: query
> Apr 04 10:04:06.827 client 192.168.99.28#10203: send
> Apr 04 10:04:06.827 client 192.168.99.28#10203: sendto
> Apr 04 10:04:06.828 client 192.168.99.28#10203: senddone
> Apr 04 10:04:06.828 client 192.168.99.28#10203: next
> Apr 04 10:04:06.828 client 192.168.99.28#10203: endrequest
> Apr 04 10:04:06.828 client @14010aa00: udprecv
> Apr 04 10:04:25.862 client 192.168.99.28#10195: UDP request
> Apr 04 10:04:25.864 client 192.168.99.28#10195: using view '_default'
> Apr 04 10:04:25.864 client 192.168.99.28#10195: query
> Apr 04 10:04:25.867 client 192.168.99.28#10195: send
> Apr 04 10:04:25.868 client 192.168.99.28#10195: sendto
> Apr 04 10:04:25.868 client 192.168.99.28#10195: senddone
> Apr 04 10:04:25.868 client 192.168.99.28#10195: next
> Apr 04 10:04:25.868 client 192.168.99.28#10195: endrequest
> Apr 04 10:04:25.869 client @140106700: udprecv
>
> The debugging info looks the same for both queries.
> Was "-d 9" not the correct debug switch & level?
> When you said "if you turn on debugging you get lots of additional
> things logged", is this what was expected?
> I'm not too familiar with running in debug mode,
> pls lemme know if there's anything else I can check.
>
> Thanks.
>
>
>            You had already turned on debugging.  The message in question
only
>            gets logged when debugging is enabled.
>
>       if (client->view->resolver != NULL &&
>            client->view->recursion == ISC_TRUE &&
>            /* XXX this will log too much too early */
>            ns_client_checkacl(client, "recursion available:",
>                                client->view->recursionacl,
>                               ISC_TRUE, ISC_LOG_DEBUG(1)) ==
ISC_R_SUCCESS)

Umm, no, I didn't have debugging enabled when
I got the "recursion available: denied" messages.

I only enabled the debugging after you said "Well if you turn on
debugging you get lots of additional things logged."
So I turned it on and got the named.run output  which is shown
above.

And after all this, I still haven't heard why a "denied" message
is logged when the response was given.
A non-recursive query was sent to my name server, it sent
back a reply, the debug level was 0, and the logged message said:

"recursion available: denied"

which is not true, the query was not denied.