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

[Mark_Andrews at isc.org]

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

	You did whether you were aware of it was on or not.

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

	The client was denied having the RA bit set in the respones
	and any services that required recursion to complete.

	Remember RA is set independent of RD.

> 
> 
--
Mark Andrews, Internet Software Consortium
1 Seymour St., Dundas Valley, NSW 2117, Australia
PHONE: +61 2 9871 4742                 INTERNET: Mark.Andrews at isc.org