After reviewing the code from version 4.0 and up, it looks like the
intended behavior is to not log an access log entry if an error occurs.
In fact, the request was not serviced, so an entry in the access log
would be incorrect, the correct log entry would be a 500 internal server
error.
I just found another bug, and the fact that errors are not returning an
internal server error message indicates that there are further bugs in
the way the code works.
My guess is that if the internal server handler runs that the log entry
will show up, we'll see.
Anyway, here is another test adp which exposes another bug:
<%
ns_adp_puts whatsup
ns_log Notice "Before include adp exception = [ns_adp_exception]"
ns_adp_include test.adp
ns_log Notice "adp exception = [ns_adp_exception]"
ns_log Notice "I shouldn't be running"
%>
The include file test.adp:
<%
ns_return 200 text/plain hi
ns_adp_abort
ns_log Notice "After abort, I shouldn't be running"
%>
<%
ns_log Notice "in separate adp block"
%>
With the bug the log notice after ns_adp_abort, inside the test.adp file
does not execute (this is expected), but the statements after
ns_adp_include do run, this is bad. Execution should stop with the
include statement since test.adp returned ADP_ABORT.
Here is a fix for the bug from
line 1010 of nsd/adpeval.c
/*
* Clear the return exception and reset result.
*/
switch (itPtr->adp.exception) {
case ADP_OK:
break;
case ADP_RETURN:
itPtr->adp.exception = ADP_OK;
result = TCL_OK;
break;
case ADP_ABORT:
result = TCL_ERROR;
break;
default:
result = TCL_OK;
break;
}
But the code still has the bug which you identified, it may have to do
with an actual error not clearing the adp.exception setting.
tom jackson
On Fri, 2009-04-03 at 14:54 -0500, Andrew Steets wrote:
> My original concern was with the access logging proc, which happens to
> be run as a trace filter. I think that the access log entries should
> be generated regardless of whether or not ns_adp_abort is called. I
> don't care too much about anything else that was installed as a trace
> filter.
>
> Do you agree that access log entries should be generated if
> ns_adp_abort is called?
>
> -Andrew
>
> On Fri, Apr 3, 2009 at 10:33 AM, Tom Jackson <[email protected]> wrote:
> Andrew,
>
> I wasted a little more time looking at the actual code. My
> impression is
> that everything is working as expected. If there is an error
> in a
> postauth filter or in adp processing (registered proc), trace
> filters
> are skipped. Until about 4.5, errors during preauth also
> skipped trace
> filters. Not sure why this change was made.
>
> The only think that matters is what happens in Ns_AdpRequest.
> If there
> were no errors, the request will be logged. In order to get
> ns_adp_abort
> to work correctly, the tcl result must be set to TCL_ERROR
> until code
> returns to Ns_AdpRequest. This is why an additional structure
> is
> maintained for the adp exception, which is independent of the
> tcl
> exception. In this case, adp.exception indicates what actually
> happened
> during adp processing.
>
> So things seem to be working as intended, and they have been
> working the
> same way for a long time. It might be possible that you are
> misusing
> ns_adp_abort, or something else is messing up.
>
> Could you provide a simple test case, probably a few nested
> adp
> includes, which repeats the issue? Without a test case of what
> you think
> should work differently, it is hard to give any more advice.
>
> In general, when an error occurs during a request, the
> response is by
> definition an error response, so the original request might
> get
> transformed into an internal redirect to your error handling
> page. An
> error in this page, or a missing error page could cause
> further
> problems.
>
> Bottom line: no reason to believe that this is a bug.
>
> tom jackson
>
> p.s. this case seems to validate my belief that the hardest
> bug to find
> and fix is one that doesn't actually exist.
>
> On Thu, 2009-04-02 at 18:03 -0500, Andrew Steets wrote:
>
>
> > What was the original purpose of "trace" filters? At the C
> API level
> > there is a distinction between between a trace filter and a
> cleanup
> > callback, but it doesn't look like you can register a
> cleanup proc
> > from TCL. Maybe this was mistakenly omitted?
> >
> > The cleanup procs run unconditionally. It seems like that
> is the most
> > appropriate place to handle "cleanup of resources."
> Alternatively we
> > could change the trace filters to run regardless of the
> > Ns_ConnRunRequest() return status, but then that would make
> them
> > basically the same as the cleanups.
> >
> > I looked a little deeper into the source. The confusion
> seems to
> > arise in NsAdpFlush() which is run at the end of all ADP
> processing.
> > The code there is smart enough to recognize when an abort
> exception
> > has been signalled; it sets the TCL result to "adp flush
> disabled: adp
> > aborted", but it still returns TCL_ERROR. That is
> essentially where
> > the TCL exception gets turned into a full blown connection
> processing
> > error. We could change NsAdpFlush() to return success when
> it
> > recognizes the abort exception, or just not run NsAdpFlush()
> for abort
> > exceptions.
> >
> > There would still be cases where trace filters would not run
> though.
> > For instance if you called ns_returnxxx without calling
> ns_adp_abort.
> > I'm not sure if that is a bad thing.
> >
> > It would be nice to hear from anyone who knows about the
> original
> > motivation for the trace and cleanup filters.
> >
> > -Andrew
> >
> > On Thu, Apr 2, 2009 at 3:53 PM, Tom Jackson
> <[email protected]> wrote:
> > Gustaf,
> >
> > You may be "using" traces but not realize it, it
> sounds like
> > ns_adp_abort isn't don't what was originally
> intended.
> >
> > I wouldn't worry about an runtime error caused
> during running
> > traces, it
> > would be an error to even use ns_adp_abort in a
> trace filter
> > because the
> > connection is already finished. This is analogous to
> calling
> > [break]
> > outside of a loop.
> >
> > It seems important to consider ns_adp_abort,
> ns_adp_return and
> > ns_adp_break as a unit. They add necessary loop type
> controls
> > so that
> > developers can create deeply nested code and still
> get out of
> > it without
> > the need to use [catch]. But, like a lot of
> AOLserver specific
> > procedures, there is no hand-holding in their use.
> They can be
> > misued.
> >
> > In this particular case, it looks like somewhere
> along the
> > way,
> > ns_adp_abort was modified to not work as expected.
> >
> > The desired effect is exactly what you would get by
> returning
> > filter_return from a preauth or postauth filter.
> This effect
> > is to skip
> > to trace filters, not past them.
> >
> > Skipping trace filters even on an aborted connection
> would be
> > a disaster
> > for any application which relies on cleanup of
> resources.
> >
> > tom jackson
> >
> >
> > On Thu, 2009-04-02 at 11:12 +0200, Gustaf Neumann
> wrote:
> > > Andrew Steets schrieb:
> > > > The patch I sent earlier seems to fulfill these
> needs, but
> > I am
> > > > worried about corner cases where LogTrace (from
> the nslog
> > module)
> > > > could blow up. Nothing about the state of the
> Conn *
> > seems to be
> > > > guaranteed when the ConnCleanup callbacks are
> called.
> > > >
> > > Dear Andrew,
> > >
> > > i think most (all?) of the repondents seems to
> agree that
> > writing in the
> > > about case to
> > > the access log file. For me there are still two
> quesions
> > open:
> > >
> > > a) is it possoble to call ns_adp_abort at some
> time, where
> > the server
> > > might crash
> > > (in normal operations, everthing looks fine to
> me,
> > problems might
> > > occur in
> > > when called from some traces; other calls are
> likely to
> > have similar
> > > problems)
> > >
> > > b) the patch replaces the call to the regular
> server trace
> > by a
> > > connection cleanup call.
> > > this means, at least in 4.5.*, ns_adp_abort
> seems to
> > cancel all
> > > traces (also
> > > these registered with ns_register_trace). Is
> this
> > desired?
> > >
> > > From Tom's website:
> > http://rmadilo.com/files/nsapi/ns_adp_abort.html
> > > the doc of ns_adp_abort says
> > >
> > > ... Every ns_returnxxx call in an ADP should be
> followed
> > with a call
> > > to ns_adp_abort....
> > >
> > > With this recommendation, cancelling traces
> seem wrong to
> > me; or at
> > > least,
> > > this should be documented.
> > >
> > > We don't use traces, all of OpenACS does not use
> it, so this
> > is no
> > > current issue for us.
> > >
> > > -gustaf neumann
> > >
> > >
> > > --
> > > AOLserver - http://www.aolserver.com/
> > >
> > > To Remove yourself from this list, simply send an
> email to
> > <[email protected]> with the
> > > body of "SIGNOFF AOLSERVER" in the email message.
> You can
> > leave the Subject: field of your email blank.
> > >
> >
> >
> > --
> > AOLserver - http://www.aolserver.com/
> >
> > To Remove yourself from this list, simply send an
> email to
> > <[email protected]> with the
> > body of "SIGNOFF AOLSERVER" in the email message.
> You can
> > leave the Subject: field of your email blank.
> >
> >
> >
> > --
> > AOLserver - http://www.aolserver.com/
> >
> >
> >
> > To Remove yourself from this list, simply send an email to
> <[email protected]> with the
> > body of "SIGNOFF AOLSERVER" in the email message. You can
> leave the Subject: field of your email blank.
> >
> >
>
>
> --
> AOLserver - http://www.aolserver.com/
>
> To Remove yourself from this list, simply send an email to
> <[email protected]> with the
> body of "SIGNOFF AOLSERVER" in the email message. You can
> leave the Subject: field of your email blank.
>
>
>
> --
> AOLserver - http://www.aolserver.com/
>
>
>
> To Remove yourself from this list, simply send an email to
> <[email protected]> with the
> body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
> field of your email blank.
>
>
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to
<[email protected]> with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
