Re: [AOLSERVER] missing access log entries
You can try the "diff" link to the parent at the following two links. The second one is older, but each patch is to different files. But please note that my queue.c file (first patch below) is not identical to CVS HEAD, so the patch line numbers will not match up. On Fri, 2009-04-17 at 00:32 +0400, Alexey Pechnikov wrote: http://www.junom.com/gitweb/gitweb.perl?p=aolserver.git;a=commit;h=7ab44 http://www.junom.com/gitweb/gitweb.perl?p=aolserver.git;a=commit;h=20f65 tom jackson -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
Hello! On Monday 13 April 2009 09:12:20 Tom Jackson wrote: > Attached is a patch based upon the original code, not my last attempt, > and more info at: > > http://www.junom.com/gitweb/gitweb.perl?p=aolserver.git;a=commit;h=7ab44 I need to build AOL with complete resolved subj problem. Which patches I must apply now? Best regards, Alexey Pechnikov. http://pechnikov.tel/ -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
On Mon, 2009-04-13 at 13:49 -0400, Jim Davidson wrote:
> Hi,
>
> A bit old but let me try to be helpful here...
>
>
> On Apr 3, 2009, at 11:45 PM, Tom Jackson wrote:
Jim,
Thanks for adding some back story. Over the weekend I spent more time
looking into this problem and basically rewrote one portion of ConnRun
and pulled out the auth part of the code into another static function.
As Gustaf noticed, there was a little confusion in the code, I think
mostly related to the use and meaning of the "status" variable. This
variable has several meanings at different points in ConnRun and it gets
confusing. Plus I wasn't completely sure what was supposed to happen at
each point.
I think I finally figured it out, and it now appears to me that
including the access logging trace where it is makes perfect sense. What
didn't make sense, and was a bug, was the meaning of the value of
"status" at the point trace filters, server traces and void traces ran.
In effect, "status" must indicate the success/failure of sending a
response to the client. The current code didn't do that. Here is my
rewrite of the two affected functions, with comments added:
/*
*--
*
* ConnAuthorize --
*
* Try to authorize a connection.
*
* Results:
* NS_OK on successful authorization,
* NS_FILTER_RETURN on authorization failure, or
* NS_ERROR on error.
*
* Side effects:
* Connection request is authorized. On failure an alternative
* response may be sent to the client.
*
*--
*/
static int
ConnAuthorize(Conn *connPtr)
{
Ns_Conn *conn = (Ns_Conn *) connPtr;
NsServer *servPtr = connPtr->servPtr;
intstatus;
status = Ns_AuthorizeRequest(servPtr->server,
connPtr->request->method, connPtr->request->url,
connPtr->authUser, connPtr->authPasswd, connPtr->peer);
switch (status) {
case NS_OK:
break;
case NS_FORBIDDEN:
/*
* NS_OK indicates that a response was sent to the client
* a this point, we must fast-forward to traces,
* so we convert the NS_OK to NS_FILTER_RETURN.
*/
if ((status = Ns_ConnReturnForbidden(conn)) == NS_OK) {
status = NS_FILTER_RETURN;
}
break;
case NS_UNAUTHORIZED:
/*
* NS_OK indicates that a response was sent to the client
* a this point, we must fast-forward to traces,
* so we convert the NS_OK to NS_FILTER_RETURN.
*/
if ((status = Ns_ConnReturnUnauthorized(conn)) == NS_OK) {
status = NS_FILTER_RETURN;
}
break;
case NS_ERROR:
default:
status = NS_ERROR;
break;
}
return status;
}
/*
*--
*
* ConnRun --
*
* Run a valid connection.
*
* Results:
* None.
*
* Side effects:
* Connection request is read and parsed and the cooresponding
* service routine is called.
*
*--
*/
static void
ConnRun(Conn *connPtr)
{
Ns_Conn *conn = (Ns_Conn *) connPtr;
NsServer *servPtr = connPtr->servPtr;
inti, status;
Tcl_Encodingencoding = NULL;
/*
* Initialize the connection encodings and headers.
*/
connPtr->outputheaders = Ns_SetCreate(NULL);
encoding = NsGetInputEncoding(connPtr);
if (encoding == NULL) {
encoding = NsGetOutputEncoding(connPtr);
if (encoding == NULL) {
encoding = connPtr->servPtr->urlEncoding;
}
}
Ns_ConnSetUrlEncoding(conn, encoding);
if (servPtr->opts.hdrcase != Preserve) {
for (i = 0; i < Ns_SetSize(connPtr->headers); ++i) {
if (servPtr->opts.hdrcase == ToLower) {
Ns_StrToLower(Ns_SetKey(connPtr->headers, i));
} else {
Ns_StrToUpper(Ns_SetKey(connPtr->headers, i));
}
}
}
/*
* Run the request.
*/
while (1) {
/*
* Proxy requests replace request logic
*/
if (connPtr->request->protocol != NULL
&& connPtr->request->host != NULL) {
status = NsConnRunProxyRequest((Ns_Conn *) connPtr);
break;
}
/*
* Each stage of request processing can return one of three
* possible results:
* NS_OK means continue to next stage
* NS_FILTER_RETURN means skip to traces
* NS_ERROR means skip to 500 response attempt
*/
status = NsRunFilters(conn, NS_FILTER_PRE_AUTH);
if (status != NS_OK) {
break;
}
status = ConnAuthorize(connPtr);
if (status != NS_OK) {
break;
}
Re: [AOLSERVER] missing access log entries
Jim,
I'm thinking along the same lines. The while {1} thing is similar to a
try block, but it handles the special case where there is really only on
exception, on error or a successful return, fast-forward to
traces...actually check for an error then maybe do traces.
What I'm not sure about is some of the looping which happens with
redirects. Specifically redirecting to non-200 codes. I'm not sure why
there is a need to reauthorize before running client or server error
handlers. In essence there is a chance that the original failure will be
lost in this process and a new failure will replace it.
***Digression***
I seem to remember that you once said it would be nice if there were
more filter points available.
What would be interesting is if you could fast-forward, or rewind to
more points. Right now we have NS_FILTER_BREAK, NS_FILTER_RETURN, NS_OK
and NS_ERROR, which all go to pre-determined points. These really are
not states, just a rough indication of something.
Right now we can rewind to authorization, but then we skip post-auth
filters and run the new request.
Anyway, it seems like the while loop could change to some kind of
generic state machine.
Instead of a fixed set of steps, each step could potentially end with a
restart with a new set of steps, or just a restart of the same set. You
could use this to avoid running through the list of filters for urls
which will never match the current url/method.
Maybe I can do a mock-up in Tcl.
***End Digression***
Anyway, here is where I'm at with the error loop:
After a few additional changes I have got one thing working: all errors
are handled after the while {1} loop. I have one remaining problem with
Ns_ConnReturnInternalError. It looks like this:
Ns_ConnReturnInternalError(Ns_Conn *conn)
{
int result;
Ns_SetTrunc(conn->outputheaders, 0);
if (ReturnRedirect(conn, 500, &result)) {
return result;
}
return Ns_ConnReturnNotice(conn, 500, "Server Error",
"The requested URL cannot be accessed "
"due to a system error on this server.");
}
The problem is that the "result" is returned base upon the existence of
a redirect mapping. This works for everything except errors which take
place when trying to run the configured error handler.
This case highlights exactly what you are talking about. The result is
an error, but ReturnRedirect found a handler. Why did the handler fail?
In the bug I'm working on, the request line is "PROPFIND /abc HTTP/1.1"
It seems like the correct error is a 501 "Not Implemented", but that
error should have shown up before the 404 redirect.
I'm thinking the problem is in ReturnRedirect and how redirect are
mapped (they leave out the method). Adding a method in the redirect
mapping would be interesting, allowing different handlers for different
methods.
The other thing I'm looking at is trying to short circuit the redirect
code so that it doesn't redirect to the same url.
tom jackson
On Wed, 2009-04-15 at 13:55 -0400, Jim Davidson wrote:
> I'm wondering if there needs to be some more specific exception flags
> stored in the connection structure to handle all these cases and some
> C and Tcl api's to access/modify the same. It seems you're doing the
> good work of rationalizing all the error conditions that had been
> pretty confused together and shuffling / updating the code to handle
> the various cases but more explicit tracking of the error conditions
> (execution, pre/post filter, connection, auth, etc.) could make things
> easier.This may lead the code to look like more try/catch type
> exception handling instead of a non-obvious code path understandable
> only with the surrounding comments.
>
> -Jim
>
>
>
> On Apr 15, 2009, at 11:12 AM, Tom Jackson wrote:
>
> > Gustaf,
> > Thanks for testing on a production server. I haven't tested this with
> > the authorization module, but it seems like it should work okay.
> >
> > The internal server loop bug that I tracked down yesterday led me to
> > another function which contains code very similar to the new
> > ConnAuthorize function, so I'm wondering if I should see if I should
> > maybe export ConnAuthorize to NsConnAuthorize. The overall idea is to
> > only run Ns_ConnReturnInternalError at the end of the request and not
> > from inside the authorization or redirection functions (because the
> > returns Ns_ConnReturnForbidden and Ns_ConnReturnUnauthorized could
> > also
> > return NS_ERROR.
> >
> > Any ideas are welcome. (I think just removing
> > Ns_ConnReturnInternalError
> > from Ns_ConnRedirect will break the loop.)
> >
> > tom jackson
> >
> > Here's the two chunks of code:
> >
> > static int
> > ConnAuthorize(Conn *connPtr)
> > {
> >Ns_Conn*conn = (Ns_Conn *) connPtr;
> >NsServer *servPtr = connPtr->servPtr;
> >intstatus;
> >
> >status = Ns_AuthorizeRequest(servPtr->server,
> > connPtr->request->method, connPtr->request->url,
> >
Re: [AOLSERVER] missing access log entries
I'm wondering if there needs to be some more specific exception flags
stored in the connection structure to handle all these cases and some
C and Tcl api's to access/modify the same. It seems you're doing the
good work of rationalizing all the error conditions that had been
pretty confused together and shuffling / updating the code to handle
the various cases but more explicit tracking of the error conditions
(execution, pre/post filter, connection, auth, etc.) could make things
easier.This may lead the code to look like more try/catch type
exception handling instead of a non-obvious code path understandable
only with the surrounding comments.
-Jim
On Apr 15, 2009, at 11:12 AM, Tom Jackson wrote:
Gustaf,
Thanks for testing on a production server. I haven't tested this with
the authorization module, but it seems like it should work okay.
The internal server loop bug that I tracked down yesterday led me to
another function which contains code very similar to the new
ConnAuthorize function, so I'm wondering if I should see if I should
maybe export ConnAuthorize to NsConnAuthorize. The overall idea is to
only run Ns_ConnReturnInternalError at the end of the request and not
from inside the authorization or redirection functions (because the
returns Ns_ConnReturnForbidden and Ns_ConnReturnUnauthorized could
also
return NS_ERROR.
Any ideas are welcome. (I think just removing
Ns_ConnReturnInternalError
from Ns_ConnRedirect will break the loop.)
tom jackson
Here's the two chunks of code:
static int
ConnAuthorize(Conn *connPtr)
{
Ns_Conn*conn = (Ns_Conn *) connPtr;
NsServer *servPtr = connPtr->servPtr;
intstatus;
status = Ns_AuthorizeRequest(servPtr->server,
connPtr->request->method, connPtr->request->url,
connPtr->authUser, connPtr->authPasswd, connPtr->peer);
switch (status) {
case NS_OK:
break;
case NS_FORBIDDEN:
if ((status = Ns_ConnReturnForbidden(conn)) == NS_OK) {
status = NS_FILTER_RETURN;
}
break;
case NS_UNAUTHORIZED:
if ((status = Ns_ConnReturnUnauthorized(conn)) == NS_OK) {
status = NS_FILTER_RETURN;
}
break;
case NS_ERROR:
default:
status = NS_ERROR;
break;
}
return status;
}
and from op.c:
int
Ns_ConnRedirect(Ns_Conn *conn, char *url)
{
Conn *connPtr = (Conn *) conn;
int status;
++connPtr->recursionCount;
/*
* Update the request URL.
*/
Ns_SetRequestUrl(conn->request, url);
/*
* Re-authorize and run the request.
*/
status = Ns_AuthorizeRequest(Ns_ConnServer(conn), conn->request-
>method,
conn->request->url, conn->authUser,
conn->authPasswd, Ns_ConnPeer(conn));
switch (status) {
case NS_OK:
status = Ns_ConnRunRequest(conn);
break;
case NS_FORBIDDEN:
status = Ns_ConnReturnForbidden(conn);
break;
case NS_UNAUTHORIZED:
status = Ns_ConnReturnUnauthorized(conn);
break;
case NS_ERROR:
default:
status = Ns_ConnReturnInternalError(conn);
break;
}
return status;
}
On Wed, 2009-04-15 at 12:52 +0200, Gustaf Neumann wrote:
your rewrite of the two functions below look fine to me. The structure
is much clearer now, results of the authorization handling are
handled
now consistently. I am useing these functions since a few days on one
of my servers and found nothing unusual. Many thanks to Tom!
Andrew, did you test this version as well for your test-cases?
If thise works for you as well (i would assume so), i would think
that version should go into CVS.
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to > 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
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
Re: [AOLSERVER] missing access log entries
Gustaf,
Thanks for testing on a production server. I haven't tested this with
the authorization module, but it seems like it should work okay.
The internal server loop bug that I tracked down yesterday led me to
another function which contains code very similar to the new
ConnAuthorize function, so I'm wondering if I should see if I should
maybe export ConnAuthorize to NsConnAuthorize. The overall idea is to
only run Ns_ConnReturnInternalError at the end of the request and not
from inside the authorization or redirection functions (because the
returns Ns_ConnReturnForbidden and Ns_ConnReturnUnauthorized could also
return NS_ERROR.
Any ideas are welcome. (I think just removing Ns_ConnReturnInternalError
from Ns_ConnRedirect will break the loop.)
tom jackson
Here's the two chunks of code:
static int
ConnAuthorize(Conn *connPtr)
{
Ns_Conn *conn = (Ns_Conn *) connPtr;
NsServer *servPtr = connPtr->servPtr;
intstatus;
status = Ns_AuthorizeRequest(servPtr->server,
connPtr->request->method, connPtr->request->url,
connPtr->authUser, connPtr->authPasswd, connPtr->peer);
switch (status) {
case NS_OK:
break;
case NS_FORBIDDEN:
if ((status = Ns_ConnReturnForbidden(conn)) == NS_OK) {
status = NS_FILTER_RETURN;
}
break;
case NS_UNAUTHORIZED:
if ((status = Ns_ConnReturnUnauthorized(conn)) == NS_OK) {
status = NS_FILTER_RETURN;
}
break;
case NS_ERROR:
default:
status = NS_ERROR;
break;
}
return status;
}
and from op.c:
int
Ns_ConnRedirect(Ns_Conn *conn, char *url)
{
Conn *connPtr = (Conn *) conn;
int status;
++connPtr->recursionCount;
/*
* Update the request URL.
*/
Ns_SetRequestUrl(conn->request, url);
/*
* Re-authorize and run the request.
*/
status = Ns_AuthorizeRequest(Ns_ConnServer(conn), conn->request->method,
conn->request->url, conn->authUser,
conn->authPasswd, Ns_ConnPeer(conn));
switch (status) {
case NS_OK:
status = Ns_ConnRunRequest(conn);
break;
case NS_FORBIDDEN:
status = Ns_ConnReturnForbidden(conn);
break;
case NS_UNAUTHORIZED:
status = Ns_ConnReturnUnauthorized(conn);
break;
case NS_ERROR:
default:
status = Ns_ConnReturnInternalError(conn);
break;
}
return status;
}
On Wed, 2009-04-15 at 12:52 +0200, Gustaf Neumann wrote:
your rewrite of the two functions below look fine to me. The structure
> is much clearer now, results of the authorization handling are handled
> now consistently. I am useing these functions since a few days on one
> of my servers and found nothing unusual. Many thanks to Tom!
>
> Andrew, did you test this version as well for your test-cases?
> If thise works for you as well (i would assume so), i would think
> that version should go into CVS.
>
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
Re: [AOLSERVER] missing access log entries
Hi,
I haven't been able to test myself but the changes make sense to me
too. Thanks Tom!
-Jim
On Apr 15, 2009, at 6:52 AM, Gustaf Neumann wrote:
Dear Tom,
your rewrite of the two functions below look fine to me. The structure
is much clearer now, results of the authorization handling are handled
now consistently. I am useing these functions since a few days on one
of my servers and found nothing unusual. Many thanks to Tom!
Andrew, did you test this version as well for your test-cases?
If thise works for you as well (i would assume so), i would think
that version should go into CVS.
best regards
-gustaf neumann
Tom Jackson schrieb:
I think I finally figured it out, and it now appears to me that
including the access logging trace where it is makes perfect sense.
What
didn't make sense, and was a bug, was the meaning of the value of
"status" at the point trace filters, server traces and void traces
ran.
In effect, "status" must indicate the success/failure of sending a
response to the client. The current code didn't do that. Here is my
rewrite of the two affected functions, with comments added:
/*
*--
*
* ConnAuthorize --
*
* Try to authorize a connection.
*
* Results:
* NS_OK on successful authorization,
* NS_FILTER_RETURN on authorization failure, or
* NS_ERROR on error.
*
* Side effects:
* Connection request is authorized. On failure an alternative
* response may be sent to the client.
*
*--
*/
static int
ConnAuthorize(Conn *connPtr)
{
Ns_Conn*conn = (Ns_Conn *) connPtr;
NsServer *servPtr = connPtr->servPtr;
intstatus;
status = Ns_AuthorizeRequest(servPtr->server,
connPtr->request->method, connPtr->request->url, connPtr-
>authUser, connPtr->authPasswd, connPtr->peer);
switch (status) {
case NS_OK:
break;
case NS_FORBIDDEN:
/*
* NS_OK indicates that a response was sent to the client
* a this point, we must fast-forward to traces,
* so we convert the NS_OK to NS_FILTER_RETURN.
*/
if ((status = Ns_ConnReturnForbidden(conn)) == NS_OK) {
status = NS_FILTER_RETURN;
}
break;
case NS_UNAUTHORIZED:
/*
* NS_OK indicates that a response was sent to the client
* a this point, we must fast-forward to traces,
* so we convert the NS_OK to NS_FILTER_RETURN.
*/
if ((status = Ns_ConnReturnUnauthorized(conn)) == NS_OK) {
status = NS_FILTER_RETURN;
}
break;
case NS_ERROR:
default:
status = NS_ERROR;
break;
}
return status;
}
/*
*--
*
* ConnRun --
*
* Run a valid connection.
*
* Results:
* None.
*
* Side effects:
* Connection request is read and parsed and the cooresponding
* service routine is called.
*
*--
*/
static void
ConnRun(Conn *connPtr)
{
Ns_Conn*conn = (Ns_Conn *) connPtr;
NsServer *servPtr = connPtr->servPtr;
inti, status;
Tcl_Encodingencoding = NULL;
/*
* Initialize the connection encodings and headers. */
connPtr->outputheaders = Ns_SetCreate(NULL);
encoding = NsGetInputEncoding(connPtr);
if (encoding == NULL) {
encoding = NsGetOutputEncoding(connPtr);
if (encoding == NULL) {
encoding = connPtr->servPtr->urlEncoding;
}
}
Ns_ConnSetUrlEncoding(conn, encoding);
if (servPtr->opts.hdrcase != Preserve) {
for (i = 0; i < Ns_SetSize(connPtr->headers); ++i) {
if (servPtr->opts.hdrcase == ToLower) {
Ns_StrToLower(Ns_SetKey(connPtr->headers, i));
} else {
Ns_StrToUpper(Ns_SetKey(connPtr->headers, i));
}
}
}
/*
* Run the request.
*/
while (1) {
/*
* Proxy requests replace request logic
*/
if (connPtr->request->protocol != NULL
&& connPtr->request->host != NULL) {
status = NsConnRunProxyRequest((Ns_Conn *) connPtr);
break;
}
/*
* Each stage of request processing can return one of three
* possible results:
* NS_OK means continue to next stage
* NS_FILTER_RETURN means skip to traces
* NS_ERROR means skip to 500 response attempt
*/
status = NsRunFilters(conn, NS_FILTER_PRE_AUTH);
if (status != NS_OK) {
break;
}
status = ConnAuthorize(connPtr);
if (status != NS_OK) {
break;
}
status = NsRunFilters(conn, NS_FILTER_POST_AUTH);
if (status != NS_OK) {
break;
}
status = Ns_ConnRunRequest(conn);
break;
Re: [AOLSERVER] missing access log entries
Dear Tom,
your rewrite of the two functions below look fine to me. The structure
is much clearer now, results of the authorization handling are handled
now consistently. I am useing these functions since a few days on one
of my servers and found nothing unusual. Many thanks to Tom!
Andrew, did you test this version as well for your test-cases?
If thise works for you as well (i would assume so), i would think
that version should go into CVS.
best regards
-gustaf neumann
Tom Jackson schrieb:
I think I finally figured it out, and it now appears to me that
including the access logging trace where it is makes perfect sense. What
didn't make sense, and was a bug, was the meaning of the value of
"status" at the point trace filters, server traces and void traces ran.
In effect, "status" must indicate the success/failure of sending a
response to the client. The current code didn't do that. Here is my
rewrite of the two affected functions, with comments added:
/*
*--
*
* ConnAuthorize --
*
* Try to authorize a connection.
*
* Results:
* NS_OK on successful authorization,
* NS_FILTER_RETURN on authorization failure, or
* NS_ERROR on error.
*
* Side effects:
* Connection request is authorized. On failure an alternative
* response may be sent to the client.
*
*--
*/
static int
ConnAuthorize(Conn *connPtr)
{
Ns_Conn *conn = (Ns_Conn *) connPtr;
NsServer *servPtr = connPtr->servPtr;
intstatus;
status = Ns_AuthorizeRequest(servPtr->server,
connPtr->request->method, connPtr->request->url,
connPtr->authUser, connPtr->authPasswd, connPtr->peer);
switch (status) {
case NS_OK:
break;
case NS_FORBIDDEN:
/*
* NS_OK indicates that a response was sent to the client
* a this point, we must fast-forward to traces,
* so we convert the NS_OK to NS_FILTER_RETURN.
*/
if ((status = Ns_ConnReturnForbidden(conn)) == NS_OK) {
status = NS_FILTER_RETURN;
}
break;
case NS_UNAUTHORIZED:
/*
* NS_OK indicates that a response was sent to the client
* a this point, we must fast-forward to traces,
* so we convert the NS_OK to NS_FILTER_RETURN.
*/
if ((status = Ns_ConnReturnUnauthorized(conn)) == NS_OK) {
status = NS_FILTER_RETURN;
}
break;
case NS_ERROR:
default:
status = NS_ERROR;
break;
}
return status;
}
/*
*--
*
* ConnRun --
*
* Run a valid connection.
*
* Results:
* None.
*
* Side effects:
* Connection request is read and parsed and the cooresponding
* service routine is called.
*
*--
*/
static void
ConnRun(Conn *connPtr)
{
Ns_Conn *conn = (Ns_Conn *) connPtr;
NsServer *servPtr = connPtr->servPtr;
inti, status;
Tcl_Encodingencoding = NULL;
/*
* Initialize the connection encodings and headers.
*/
connPtr->outputheaders = Ns_SetCreate(NULL);
encoding = NsGetInputEncoding(connPtr);
if (encoding == NULL) {
encoding = NsGetOutputEncoding(connPtr);
if (encoding == NULL) {
encoding = connPtr->servPtr->urlEncoding;
}
}
Ns_ConnSetUrlEncoding(conn, encoding);
if (servPtr->opts.hdrcase != Preserve) {
for (i = 0; i < Ns_SetSize(connPtr->headers); ++i) {
if (servPtr->opts.hdrcase == ToLower) {
Ns_StrToLower(Ns_SetKey(connPtr->headers, i));
} else {
Ns_StrToUpper(Ns_SetKey(connPtr->headers, i));
}
}
}
/*
* Run the request.
*/
while (1) {
/*
* Proxy requests replace request logic
*/
if (connPtr->request->protocol != NULL
&& connPtr->request->host != NULL) {
status = NsConnRunProxyRequest((Ns_Conn *) connPtr);
break;
}
/*
* Each stage of request processing can return one of three
* possible results:
* NS_OK means continue to next stage
* NS_FILTER_RETURN means skip to traces
* NS_ERROR means skip to 500 response attempt
*/
status = NsRunFilters(conn, NS_FILTER_PRE_AUTH);
if (status != NS_OK) {
break;
}
status = ConnAuthorize(connPtr);
if (status != NS_OK) {
break;
}
status = NsRunFilters(conn, NS_FILTER_POST_AUTH);
if (status != NS_OK) {
break;
}
status = Ns_ConnRunRequest(conn);
break;
}
if (status == NS_ERROR) {
statu
Re: [AOLSERVER] missing access log entries
Hi,
Yes -- I think in general, the meaning of "status" with regards to a
connection processing (or a filter that may preempt it) was that "a
valid HTTP response was sent..."If you look deep in the rat's nest
of connio.c, you'll find:
int
Ns_WriteConn(Ns_Conn *conn, char *buf, int len)
{
if (Ns_ConnWrite(conn, buf, len) != len) {
return NS_ERROR;
}
return NS_OK;
}
Ns_ConnWrite eventually calls the "send" routine from the driver (sock
or ssl). If the driver can't send the # of bytes intended, it returns
NS_ERROR. This turns any network send error into a simple "couldn't
send" error. That code was the original place where NS_ERROR could be
generated and made sense when it was sending content from a file.
There are some complications -- originally the headers were sent
before the content, i.e., there was no buffering. That was a
performance irritant so a level of buffering was put in place and so
results which previously may have meant "headers not sent due to
dropped connection" now silently buffer result and return NS_OK
always. Then with ADP there grew some encoding issues and/or gzip'ing
goals that also led to more of "get a big whole buffer ready and blast
that in one attempt, using iovec's if possible..." You can see that
in the Ns_ConnFlush and Ns_ConnFlushDirect complexity.
So, the simple "NS_ERROR means conn failed..." isn't so valid
anymore. In fact, on a long running connection the code could
cheerfully be creating a buffer to send over a socket that may have
already dropped. That knowledge -- async socket drop -- is actually
something the I/O event thread (sometimes confusing called the driver
thread for the DriverThread routine in driver.c) could easily detect.
Event-driven socket code is often more efficient than thread-based I/
O. For AOLserver, the read-side was made event-driven years ago
(helps with denial of service attacks and general efficient) but the
write side remained thread-based mostly because of the expectations
(smart or dumb) of traces and order of execution, i.e., you have a
thread that gets the read-ahead buffer, does the work, sends
(synchronously) the response, and the proceeds to the traces, cleanup,
etc. Note to add some confusion, the I/O thread currently gracefully
closes connections already -- it's possible that generates an error
condition which is never accurately logged (note the comment "NB:
Timeout Sock on end-of-file or error." -- result becomes "pretend it
actually worked and just close socket...).
If I had to do this all over again, I'd have all the I/O be event
driven. It would read the request as it does now, allow for some
async-work if needed (possible now but not used as far as I know),
dispatch the complete request context to an execution thread to do
script-stuff and provide result back to the I/O thread where event-
driven code would send result and generate a smart log entry,
including all cases of request bad, code failed, send failed, or all
ok. If while the thread was executing the I/O thread detected a
dropped socket, it could send an async-exception message to the
execution thread which may or may not be noticed or handled but an
attempt could be made.
While this may be nifty, today it would mean traces and filters would
run before the content was already sent. For a connection cleanup
(i.e., dump this temp resource), it would make sense but for an old-
school common log format it may be odd (or at least suspect, but
perhaps no less suspect than what's going on now).
-Jim
On Apr 13, 2009, at 2:48 PM, Tom Jackson wrote:
On Mon, 2009-04-13 at 13:49 -0400, Jim Davidson wrote:
Hi,
A bit old but let me try to be helpful here...
On Apr 3, 2009, at 11:45 PM, Tom Jackson wrote:
Jim,
Thanks for adding some back story. Over the weekend I spent more time
looking into this problem and basically rewrote one portion of
ConnRun
and pulled out the auth part of the code into another static function.
As Gustaf noticed, there was a little confusion in the code, I think
mostly related to the use and meaning of the "status" variable. This
variable has several meanings at different points in ConnRun and it
gets
confusing. Plus I wasn't completely sure what was supposed to happen
at
each point.
I think I finally figured it out, and it now appears to me that
including the access logging trace where it is makes perfect sense.
What
didn't make sense, and was a bug, was the meaning of the value of
"status" at the point trace filters, server traces and void traces
ran.
In effect, "status" must indicate the success/failure of sending a
response to the client. The current code didn't do that. Here is my
rewrite of the two affected functions, with comments added:
/*
*--
*
* ConnAuthorize --
*
* Try to authorize a connection.
*
*
Re: [AOLSERVER] missing access log entries
On Mon, 2009-04-13 at 13:49 -0400, Jim Davidson wrote: > > On Apr 3, 2009, at 11:45 PM, Tom Jackson wrote: > > > > * Filters seem uniquely superior when the url pattern determines which > > code should run. Unfortunately filters are many times registered to / > > *, > > the global pattern. This is not a filter in the typical sense. The > > only > > benefit is the ability to stage code to run in a particular order at a > > particular stage. The question is if there should be a separate stage > > for global filters, or a separate mechanism to register global code > > which runs at certain point, maybe conditioned on previous events. > > This > > is a like a generalized ns_atclose. > > > I think a good idea gets implemented, bad ideas linger to avoid > breaking things so that's why both exist. > > BTW: I remembered why the newer "connection cleanup" stuff was added > -- it was designed to interact with the "connection local storage API" > which can be accessed in the driver thread, ostensibly to fetch and > store network-related assets in an efficient manner. The model is > similar to Pthreads local storage and thus needed non-conditional > cleanup callbacks. I should point out a mistake I made in the above analysis. The access logging filter is a global filter. It actually works exactly like I was proposing. Until I actually looked at the nslog module, I assumed it was registered as a "filter". It isn't. It is a "server trace" A server trace is identical to a "cleanup trace", it just runs at a different point, and is based upon successfully sending a response to the client. This "success" is indicated/protected by status = NS_OK||NS_FILTER_RETURN. I experimented with using a cleanup trace in nslog.c, and it worked exactly the same. This required the following adjustment: Ns_RegisterServerTrace(server, LogTrace, logPtr); changed to: Ns_RegisterConnCleanup(server, LogTrace, logPtr); An important distinction between this API and the filter API is that an interp is not required. You can run generic C code. There is also no url pattern matching and all traces/cleanups run. > > > > > * The access logging module is ancient, simple and in desperate need > > of > > professional help. > > > Agreed. And, google analytics and chartbeat.com are pretty cool :) Anyone have ideas on using these? > > > > * The Internal redirecting functionality is poorly documented and > > understood. These are configured as proxies or redirects. > > > Yes -- it was always a great disappointment for me :( Yeah, it seems like you could use it for lots of things, like a generic FSM engine. tom jackson -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
Hi, A bit old but let me try to be helpful here... On Apr 3, 2009, at 11:45 PM, Tom Jackson wrote: On Fri, 2009-04-03 at 16:20 -0600, Jim Davidson wrote: HI, Sorry -- I wrote the original and goofy code leading to this confusion... Thanks for monitoring our head scratching! I have a few random thoughts, and I'm not sure they add up to a particular conclusion or not. But here goes: * The adp code is squishy. It doesn't necessarily execute with the same precision as Tcl code. Under some configurations errors might not instantly terminate execution. Yes - because some errors could be "caught" as in the end it's just a Tcl engine. * The adp code does not execute like an equivalent tcl page, probably due 100% to tcl pages using ns_tcl_abort and the generic tcl error handling. Yes -- the "tcl page" stuff is more CGI like, i.e., code which includes and generates embedded HTML. The ADP is more PHP, ASP, etc. like, i.e., HTML code with embedded Tcl. ADP is actually pretty good and efficient at what it does and includes a clever although arcane feature for caching bits of execution (e.g., results of a seldom- checked, slow remote services). The PHP'ish nature of ADP does make the ability to "unwind everything and start over..." technically imprecise. In practice I think most people don't use streaming and the odd case of "catch"'ing an exception doesn't happen much so it mostly works. Although, as we've discovered, the "squishiness" of mixing Tcl error/exception conditions with the weak concept of a connection statues has led to a bug in ns_adp_abort not doing the right thing. * The adp code has "evolved" over the years, actually there have been significant changes to the structure of the code. During the evolution, the detailed logic changed, sometimes bugs were introduced to fix perceived problems. It is amazing that nobody has noticed these differences. My guess is that nobody noticed because the changes have been uniquely backwards compatible, except when an actual error occurred. But since the errors were never logged, nobody was looking for the cause. All true. Remember the code was mostly developed in the context of AOL's operations requirements when they used it for most all published content (they use it for almost nothing now) and so if something weird didn't get exercised in the AOL context it was never discovered. Conversely, if something was useful to AOL (e.g., the per-chunk caching), that may never have been publicized or used outside AOL. * There is a good argument to be made that when an error occurs, everything that follows is crap. Therefore, further execution is pointless and may lead to compounded errors. Reasonable assumption. Weirdness is the way filters, code, etc. can be re-used and layered together so one components error (e.g., one failed ADP include) is not interesting or an error to some other component (e.g., logging). * Trace filters could be thought of as a way to clean up stuff that was initialized during the request processing. But this is a hackish and currently invalid method in AOLserver. Why? The url can change during a connection, so code initialized in a preauth or postauth filter due to url matching might not get cleaned up with a matching url when trace filters run. Traces were created to have some sort of API for what at the time was only logging. Not sure what else useful ever used it. * ns_atclose used to be a great way to clean up initialized code. It still works for connection based code, but it used to work for scheduled procs. ns_atclose has good qualities: it is registered only when code is initialized, so if the connection craps out before the initialization code runs, the ns_atclose code does not run. The other quality is that the code runs regardless of errors. It simply runs when the connection closes. This would be a great place for logging! Agreed -- that thing was always a special-case thing, I think it had to do with closing files or something in the past. * If the server experiences an internal error, it should attempt to return this information to the client. Maybe the client has dropped the connection, but this is not an internal server error (and AOLserver silently forgets about client drops). On error, the server should destroy all headers and all content and return a 500 response. The 500 response should get logged. This is the actual result of the request: an error. You have to tell the client what happened. Lots of code paths in AOLserver follow this rule, but not ADP code. Agreed -- ADP is close but broken but the intent is as you described. The 500 error response stuff is comparatively low-level and very old. * Access logging should happen whenever a response is returned, but we should keep in mind that an access log entry includes the response code and the length of the response, if the
Re: [AOLSERVER] missing access log entries
Gustaf,
Yep, you are right. Looking at this again, I noticed a few additional
things which might help get this working as expected.
For one, the log trace is registered with Ns_RegisterServerTrace. The
documentation with this function says:
* Register a connection trace procedure. Traces registered
* with this procedure are only called in FIFO order if the
* connection request procedure successfully responds to the
* clients request.
I read this to include successfully sending a forbidden, unauthorized or
internal server error response (Otherwise the access log would contain
only 200 response codes).
So I have rearranged the code so that the status code reflects the
actual status of sending a response to the client.
Attached is a patch based upon the original code, not my last attempt,
and more info at:
http://www.junom.com/gitweb/gitweb.perl?p=aolserver.git;a=commit;h=7ab44
tom jackson
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
diff --git a/aolserver/nsd/queue.c b/aolserver/nsd/queue.c
index c620393..051abdc 100644
--- a/aolserver/nsd/queue.c
+++ b/aolserver/nsd/queue.c
@@ -56,6 +56,7 @@ typedef struct ConnData {
*/
static void ConnRun(Conn *connPtr); /* Connection run routine. */
+static int ConnAuthorize(Conn *connPtr); /* Connection Authorize routine. */
static void AppendConnList(Tcl_DString *dsPtr, Conn *firstPtr, char *state);
/*
@@ -533,6 +534,59 @@ NsConnThread(void *arg)
/*
*--
*
+ * ConnAuthorize --
+ *
+ * Try to authorize a connection.
+ *
+ * Results:
+ * NS_OK on successful authorization,
+ * NS_FILTER_RETURN on failure, or
+ * NS_ERROR on error.
+ *
+ * Side effects:
+ * Connection request is authorized. On failure an alternative
+ * response may be sent to the client.
+ *
+ *--
+ */
+
+static int
+ConnAuthorize(Conn *connPtr)
+{
+Ns_Conn *conn = (Ns_Conn *) connPtr;
+NsServer *servPtr = connPtr->servPtr;
+intstatus;
+
+status = Ns_AuthorizeRequest(servPtr->server,
+ connPtr->request->method, connPtr->request->url,
+ connPtr->authUser, connPtr->authPasswd, connPtr->peer);
+
+switch (status) {
+case NS_OK:
+break;
+case NS_FORBIDDEN:
+if ((status = Ns_ConnReturnForbidden(conn)) == NS_OK) {
+ status = NS_FILTER_RETURN;
+}
+break;
+case NS_UNAUTHORIZED:
+if ((status = Ns_ConnReturnUnauthorized(conn)) == NS_OK) {
+status = NS_FILTER_RETURN;
+}
+break;
+case NS_ERROR:
+default:
+status = NS_ERROR;
+break;
+}
+
+return status;
+}
+
+
+/*
+ *--
+ *
* ConnRun --
*
* Run a valid connection.
@@ -582,52 +636,49 @@ ConnRun(Conn *connPtr)
* Run the request.
*/
-if (connPtr->request->protocol != NULL && connPtr->request->host != NULL) {
- status = NsConnRunProxyRequest((Ns_Conn *) connPtr);
-} else {
- status = NsRunFilters(conn, NS_FILTER_PRE_AUTH);
- if (status == NS_OK) {
- status = Ns_AuthorizeRequest(servPtr->server,
- connPtr->request->method, connPtr->request->url,
- connPtr->authUser, connPtr->authPasswd, connPtr->peer);
- switch (status) {
- case NS_OK:
- status = NsRunFilters(conn, NS_FILTER_POST_AUTH);
- if (status == NS_OK) {
- status = Ns_ConnRunRequest(conn);
- }
- break;
-
- case NS_FORBIDDEN:
- Ns_ConnReturnForbidden(conn);
- break;
-
- case NS_UNAUTHORIZED:
- Ns_ConnReturnUnauthorized(conn);
- break;
-
- case NS_ERROR:
- default:
- Ns_ConnReturnInternalError(conn);
- break;
- }
-} else if (status != NS_FILTER_RETURN) {
-/* if not ok or filter_return, then the pre-auth filter coughed
- * an error. We are not going to proceed, but also we
- * can't count on the filter to have sent a response
- * back to the client. So, send an error response.
- */
-Ns_ConnReturnInternalError(conn);
-status = NS_FILTER_RETURN; /* to allow tracing to happen */
+while (1) {
+
+if (connPtr->request->protocol != NULL
+&& connPtr->request->host != NULL) {
+
+status = NsConnRunProxyRequest((Ns_Conn *) connPtr);
+break;
+}
+
+status = NsRunFilters(conn, NS_FILTER_PRE_AUTH);
+if (status != NS_OK) {
+break;
+}
+
+status = ConnAuthorize(connPtr);
+if (status != NS_OK) {
+break;
}
+
+status = NsRunFilters(conn, NS_FILTER_POST_AUTH);
+if (status != NS_OK) {
+break;
+}
+
+
Re: [AOLSERVER] missing access log entries
Tom Jackson schrieb: Hey, I just noticed that my patch to queue.c misses one case. If an authorization proc returns NS_ERROR, a 500 response is returned, but no trace filters run. This seems like a bug, ... i was as well looking at the result of Ns_AuthorizeRequest, and not at the result of a filter proc. > More filters and the traces are run, when the status is NS_OK > or NS_FILTER_RETURN. If i look at the code, i wonder, > what happens with filters and traces for status codes like > NS_FORBIDDEN, NS_UNAUTHORIZED, or NS_SHUTDOWN? > Since the status code is handled in the same proc, we have to deal with it consistently To be consistent, the NS_ERROR/default block should be: case NS_ERROR: default: Ns_ConnReturnInternalError(conn); status = NS_OK; break; That is still just one case. If i read the code correctly even with the patch above, the trace filters and the traces are not run when AuthorizeRequest returns NS_FORBIDDEN or NS_UNAUTHORIZED. Therefore, these entries won't show up in the access log-file, which looks as a bug to me. The return codes NS_OK and NS_FILTER_RETURN (which can be set by a filter, by the request or the authorization) mean in the 4.5 code-line: NS_OK: run filters with NS_FILTER_TRACE, run filters with NS_FILTER_VOID_TRACE, run traces NS_FILTER_RETURN run filters with NS_FILTER_TRACE, which is something i don't understand. By looking into the code, i see that a VOID_TRACE filter is registered by the NsTclRegisterTraceObjCmd (when a trace is registered). Why we have actually TRACE and VOID_TRACE? Wouldn't be a single TRACE enough? Shouln't be servertraces marked as deprecated in favor of TRACE filters? (or vice versa)? nslog is the only place, in the common code, where a servertrace is registered. This could be replaced by a call to register a TRACE filter. Then, we should simplify the distinction between NS_OK and NS_FILTER_TRACE to a single case, where the traces are always run. That would be a nice simplificaton and would make it easier to achieve a consitent behavior. -gustaf neumann PS: i wrote this just by reading the code. There might be certainly some imporant cases/reasones missing. -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
Hey,
I just noticed that my patch to queue.c misses one case. If an
authorization proc returns NS_ERROR, a 500 response is returned, but no
trace filters run. This seems like a bug, but further indicates to me
that a decision was made to return an error response and log errors, but
the code didn't get completed. Basically the code was in great
structural shape, but not all code paths were worked on. Maybe I'm just
projecting my own development style, get something to work in one place
and then run out of time or focus before it is applied everywhere.
Here is the current code:
status = Ns_AuthorizeRequest(servPtr->server,
connPtr->request->method, connPtr->request->url,
connPtr->authUser, connPtr->authPasswd, connPtr->peer);
switch (status) {
...
case NS_ERROR:
default:
Ns_ConnReturnInternalError(conn);
break;
}
To be consistent, the NS_ERROR/default block should be:
case NS_ERROR:
default:
Ns_ConnReturnInternalError(conn);
status = NS_OK;
break;
On Sat, 2009-04-11 at 11:14 -0700, Tom Jackson wrote:
> Gustaf,
>
> Here is the blowhard answer (the short answers are below):
>
> I agree that there must be some additional code paths which haven't been
> checked. I'll try to go through what I discovered based on your
> questions, but if I miss something ask again.
>
> One nice thing about the AOLserver code is that usually all of the logic
> for a particular level of processing is contained in a single function.
>
> For a running a request, we have ConnRun in queue.c.
>
> The basic logic is: run preauth filters, check the return code, if
> NS_OK, continue to authorization, if NS_OK, continue to postauth
> filters, if NS_OK, continue to the registered proc, if NS_OK, continue
> to trace filters, etc.
>
> All filters must return either NS_OK, NS_ERROR, NS_FILTER_BREAK,
> NS_FILTER_RETURN, otherwise the filter running function returns
> NS_ERROR. (Actually not sure if I've ever seen a filter return NS_ERROR,
> or what the point would be in doing so.)
>
> The authorization proc returns one of the authorization return codes,
> but these are handled in ConnRun. It would be an error for a filter to
> return one of these codes.
>
> The newest code in ConnRun is different from the original code which
> used a "goto:" if any of the request stages returned NS_ERROR. The new
> code, before my proposed patch allows trace filters to run if preauth
> filters return an NS_ERROR.
>
> There was some discussion that trace filters were always skipped
> (originally) because code may not have been initialized, but who knows,
> it may have also been a simple way to signal that the request was done
> and no additional code should run. (This is also the intended effect of
> ns_adp_abort and ns_tcl_abort, but they only operate within a particular
> stage.)
>
> But this argument, if it ever existed, is no invalid. We now have proxy
> requests, internal redirects, etc. These very useful features make it
> impossible to rely on code initialization based upon a particular url
> pattern. By the time the trace filter runs, the url may have changed.
> Also, if a new return code (500, 404) is set, a proxy runs which might
> access a configured procedure or file.
>
> So my best guess is that when this latest code was written, some of
> these observations may have been in play, but the change was only
> applied to preauth filters.
>
> My changes are based upon the code comment which explains what is going
> on with preauth errors:
>
> status = NsRunFilters(conn, NS_FILTER_PRE_AUTH);
> if (status == NS_OK) {
> ...
> } else if (status != NS_FILTER_RETURN) {
> /* if not ok or filter_return, then the pre-auth filter coughed
> * an error. We are not going to proceed, but also we
> * can't count on the filter to have sent a response
> * back to the client. So, send an error response.
> */
> Ns_ConnReturnInternalError(conn);
> status = NS_FILTER_RETURN; /* to allow tracing to happen */
> }
>
> Of course we can never count on an error being sent back if in the cases
> where postauth filters or the registered proc return an internal error,
> so the same reasoning should apply in those cases as well.
>
> Note that Ns_ConnReturnInternalError will just generate an error.log
> error message if the conn is closed.
>
> The changes I made to the other two files just allow the code in queue.c
> to work as expected. Before the bug patch, non-errors were seen as
> errors in ConnRun, so trace filters were skipped, including logging of
> 200 responses.
>
> What happens when code ends with "break", "continue"? This would be a
> bug in the Tcl code, it is a Tcl error to call break or contin
Re: [AOLSERVER] missing access log entries
Gustaf,
Here is the blowhard answer (the short answers are below):
I agree that there must be some additional code paths which haven't been
checked. I'll try to go through what I discovered based on your
questions, but if I miss something ask again.
One nice thing about the AOLserver code is that usually all of the logic
for a particular level of processing is contained in a single function.
For a running a request, we have ConnRun in queue.c.
The basic logic is: run preauth filters, check the return code, if
NS_OK, continue to authorization, if NS_OK, continue to postauth
filters, if NS_OK, continue to the registered proc, if NS_OK, continue
to trace filters, etc.
All filters must return either NS_OK, NS_ERROR, NS_FILTER_BREAK,
NS_FILTER_RETURN, otherwise the filter running function returns
NS_ERROR. (Actually not sure if I've ever seen a filter return NS_ERROR,
or what the point would be in doing so.)
The authorization proc returns one of the authorization return codes,
but these are handled in ConnRun. It would be an error for a filter to
return one of these codes.
The newest code in ConnRun is different from the original code which
used a "goto:" if any of the request stages returned NS_ERROR. The new
code, before my proposed patch allows trace filters to run if preauth
filters return an NS_ERROR.
There was some discussion that trace filters were always skipped
(originally) because code may not have been initialized, but who knows,
it may have also been a simple way to signal that the request was done
and no additional code should run. (This is also the intended effect of
ns_adp_abort and ns_tcl_abort, but they only operate within a particular
stage.)
But this argument, if it ever existed, is no invalid. We now have proxy
requests, internal redirects, etc. These very useful features make it
impossible to rely on code initialization based upon a particular url
pattern. By the time the trace filter runs, the url may have changed.
Also, if a new return code (500, 404) is set, a proxy runs which might
access a configured procedure or file.
So my best guess is that when this latest code was written, some of
these observations may have been in play, but the change was only
applied to preauth filters.
My changes are based upon the code comment which explains what is going
on with preauth errors:
status = NsRunFilters(conn, NS_FILTER_PRE_AUTH);
if (status == NS_OK) {
...
} else if (status != NS_FILTER_RETURN) {
/* if not ok or filter_return, then the pre-auth filter coughed
* an error. We are not going to proceed, but also we
* can't count on the filter to have sent a response
* back to the client. So, send an error response.
*/
Ns_ConnReturnInternalError(conn);
status = NS_FILTER_RETURN; /* to allow tracing to happen */
}
Of course we can never count on an error being sent back if in the cases
where postauth filters or the registered proc return an internal error,
so the same reasoning should apply in those cases as well.
Note that Ns_ConnReturnInternalError will just generate an error.log
error message if the conn is closed.
The changes I made to the other two files just allow the code in queue.c
to work as expected. Before the bug patch, non-errors were seen as
errors in ConnRun, so trace filters were skipped, including logging of
200 responses.
What happens when code ends with "break", "continue"? This would be a
bug in the Tcl code, it is a Tcl error to call break or continue outside
of a loop, where the loop is bounded by a procedure body. Any procedure
which ends with [continue] or [break] will end up returning a Tcl
error.
In fact, the way I discovered the solution to this issue was due to
problems with using ns_return inside a procedure or file that was
followed by additional code which I didn't want to run. In a tcl file,
you have to use ns_tcl_abort to correctly back out of deeply nested
code. The command generate a Tcl error until it reaches the top-level
where it is converted to NS_OK/TCL_OK.
So a procedure which ends in [continue] or [break] will be both a Tcl
error and an error in using the correct abort mechanism
You said:
> - when either the POST_AUTH filter or the request returns != NS_OK
>the server returns a 500 error
> - if there was an earlier "ns_return XXX", it is ignored.
>
This isn't exactly true. The server always attempts to run
Ns_ConnReturnInternalError. The code in ConnRun doesn't know anything
about any earlier ns_returnXXX. If you use ns_returnXXX, it should be
followed by ns_adp_abort or ns_tcl_abort. However, it is possible that
you might want to run code after and ns_returnXXX, but before abort. My
opinion is that you should probably wrap this in a [catch] so that any
errors are caught and handled correctly in the local code. But it might
not be absolutely necessary. The Ns_ConnReturnInternalError will noti
Re: [AOLSERVER] missing access log entries
Tom Jackson schrieb: Andrew, Okay, great! The changes should probably be divided into two patches: good idea. While the changes in queue.c are somewhat non-obvious the changes related to adprequest.c and adpeval.c are more clear to me. They address the original problem. i was not able to follow the full discussion and most likely one needs more thoughts and largers test cases to consider. Do i understand correctly: - when either the POST_AUTH filter or the request returns != NS_OK the server returns a 500 error - if there was an earlier "ns_return XXX", it is ignored. NsRunFilters retuns either NS_OK or NS_FILTER_BREAK, NS_FILTER_TRACE or NS_FILTER_RETURN. Don't we have to deal with the other non-ok cases? More filters and the traces are run, when the status is NS_OK or NS_FILTER_RETURN. If i look at the code, i wonder, what happens with filters and traces for status codes like NS_FORBIDDEN, NS_UNAUTHORIZED, or NS_SHUTDOWN? Have you checked what happens, when a Ns_ConnRunRequest ended in Tcl with a "return", "break" or "continue"? -gustaf neumann -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
Andrew, Okay, great! The changes should probably be divided into two patches: queue.c is a behavior change and doesn't address any bugs, just returns a 500 response if possible, and allows trace filters to run. My guess is that this patch is backwards compatible with all code because someone would have noticed by now that trace filters don't always run (assuming their code relied on them running). If they noticed that trace filters were not running, then they would have someone adapted their code to the known behavior, so their code should still work. In addition, it is now dangerous to rely on code to initialize in a pre/postauth filter and then run in a trace filter because the request url may have changed, which would alter what trace filters run, unless they are registered to the global pattern /*. In that case, you can now use ns_ictl to run traces with/without a conn (you shouldn't need a conn in a trace except for logging about the conn). ns_atclose might work in some cases, it might still have info about the conn. The other patch is to adprequest.c and adpeval.c, which is a pure bug-fix. It only restores the expected behavior of ns_adp_return, ns_adp_break and ns_adp_abort, as well as returning the previously documented AOLserver request return codes NS_OK or NS_ERROR. Unless there are additional questions about the bugfix, I'll checkout the HEAD version and commit a patch. The patch to queue.c needs at least a little community feedback, and should also include a changelog and maybe some documentation changes. tom jackson On Thu, 2009-04-09 at 20:10 -0500, Andrew Steets wrote: > Hi Tom, sorry to go dark for so long. It was operator error. I was > in a hurry and I don't think I restarted the server after I installed > the patched version of the server. > > I checked again just now and everything works as expected. > > -Andrew > > On Mon, Apr 6, 2009 at 4:14 PM, Tom Jackson wrote: > > Andrew, > > > > Hmmm, well without knowing how you tested this, I can't help much. I > > created a few test adp pages. I tested them before my changes to > > identify the problems. > > > > Here is an example set of pages: > > include.adp: > > <% > > ns_adp_puts "before include" > > ns_adp_include test-ns-return.adp > > ns_adp_puts "after include" > > ns_log Notice "finished include.adp" > > %> > > test-ns-return.adp: > > <% > > ns_return 200 text/plain hi > > ns_adp_abort > > ns_log Notice "test-ns-return.adp after ns_adp_abort" > > %> > > > > The error.log should contain neither of the Notice logs. > > The access.log should have a 200 response of content length 2. > > > > Even this produces an access.log entry: > > > > <% > > ns_adp_puts hi > > ns_adp_abort > > %> > > > > A zero length 200 response: > > > > 127.0.0.1 - - [06/Apr/2009:13:54:52 -0700] "GET /just-abort.adp > > HTTP/1.1" 200 0 "" "" > > > > Did you patch the other two files? (Note that my queue.c file is not > > identical to yours, so the patch needs to be applied by hand I think.) > > > > queue.c handles changes to allow logging during error conditions > > > > adprequest.c changes allows distinguishing between actual errors and adp > > signaling and translates Tcl return codes into AOLserver request return > > codes. Changes also ensure that the adp buffer is cleaned up in all > > cases. > > > > adpeval.c changes just ensure that the tcl error code is set to > > correspond to the ADP exception code. The code probably needs a comment > > because actual errors in ADP processing is signaled when the Tcl return > > code is TCL_OK and the adp exception code is ADP_OK. Why? Because on a > > tcl error, the ADP code doesn't get to change adp.exception to something > > else. > > > > The bugs in the current code were due to the awkward but necessary > > maintenance of these two return codes. The ADP code has gone through a > > lot of significant changes, so it is easy to see how these details > > didn't make it through correctly. But the simplicity of fixing them > > indicates that the code is in pretty good shape. > > > > Anyway, that is the bugs. The code in queue.c is not bug related, but > > allows the client to receive a 500 response on error and to allow > > logging during error conditions. > > > > Here is a link to my patch to my code: > > > > http://www.junom.com/gitweb/gitweb.perl?p=aolserver.git;a=commit;h=ca26f1a > > > > tom jackson > > > > > > > > > -- > AOLserver - http://www.aolserver.com/ > > To Remove yourself from this list, simply send an email to > 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 with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
Hi Tom, sorry to go dark for so long. It was operator error. I was in a hurry and I don't think I restarted the server after I installed the patched version of the server. I checked again just now and everything works as expected. -Andrew On Mon, Apr 6, 2009 at 4:14 PM, Tom Jackson wrote: > Andrew, > > Hmmm, well without knowing how you tested this, I can't help much. I > created a few test adp pages. I tested them before my changes to > identify the problems. > > Here is an example set of pages: > include.adp: > <% > ns_adp_puts "before include" > ns_adp_include test-ns-return.adp > ns_adp_puts "after include" > ns_log Notice "finished include.adp" > %> > test-ns-return.adp: > <% > ns_return 200 text/plain hi > ns_adp_abort > ns_log Notice "test-ns-return.adp after ns_adp_abort" > %> > > The error.log should contain neither of the Notice logs. > The access.log should have a 200 response of content length 2. > > Even this produces an access.log entry: > > <% > ns_adp_puts hi > ns_adp_abort > %> > > A zero length 200 response: > > 127.0.0.1 - - [06/Apr/2009:13:54:52 -0700] "GET /just-abort.adp > HTTP/1.1" 200 0 "" "" > > Did you patch the other two files? (Note that my queue.c file is not > identical to yours, so the patch needs to be applied by hand I think.) > > queue.c handles changes to allow logging during error conditions > > adprequest.c changes allows distinguishing between actual errors and adp > signaling and translates Tcl return codes into AOLserver request return > codes. Changes also ensure that the adp buffer is cleaned up in all > cases. > > adpeval.c changes just ensure that the tcl error code is set to > correspond to the ADP exception code. The code probably needs a comment > because actual errors in ADP processing is signaled when the Tcl return > code is TCL_OK and the adp exception code is ADP_OK. Why? Because on a > tcl error, the ADP code doesn't get to change adp.exception to something > else. > > The bugs in the current code were due to the awkward but necessary > maintenance of these two return codes. The ADP code has gone through a > lot of significant changes, so it is easy to see how these details > didn't make it through correctly. But the simplicity of fixing them > indicates that the code is in pretty good shape. > > Anyway, that is the bugs. The code in queue.c is not bug related, but > allows the client to receive a 500 response on error and to allow > logging during error conditions. > > Here is a link to my patch to my code: > > http://www.junom.com/gitweb/gitweb.perl?p=aolserver.git;a=commit;h=ca26f1a > > tom jackson > > > -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
Andrew, Hmmm, well without knowing how you tested this, I can't help much. I created a few test adp pages. I tested them before my changes to identify the problems. Here is an example set of pages: include.adp: <% ns_adp_puts "before include" ns_adp_include test-ns-return.adp ns_adp_puts "after include" ns_log Notice "finished include.adp" %> test-ns-return.adp: <% ns_return 200 text/plain hi ns_adp_abort ns_log Notice "test-ns-return.adp after ns_adp_abort" %> The error.log should contain neither of the Notice logs. The access.log should have a 200 response of content length 2. Even this produces an access.log entry: <% ns_adp_puts hi ns_adp_abort %> A zero length 200 response: 127.0.0.1 - - [06/Apr/2009:13:54:52 -0700] "GET /just-abort.adp HTTP/1.1" 200 0 "" "" Did you patch the other two files? (Note that my queue.c file is not identical to yours, so the patch needs to be applied by hand I think.) queue.c handles changes to allow logging during error conditions adprequest.c changes allows distinguishing between actual errors and adp signaling and translates Tcl return codes into AOLserver request return codes. Changes also ensure that the adp buffer is cleaned up in all cases. adpeval.c changes just ensure that the tcl error code is set to correspond to the ADP exception code. The code probably needs a comment because actual errors in ADP processing is signaled when the Tcl return code is TCL_OK and the adp exception code is ADP_OK. Why? Because on a tcl error, the ADP code doesn't get to change adp.exception to something else. The bugs in the current code were due to the awkward but necessary maintenance of these two return codes. The ADP code has gone through a lot of significant changes, so it is easy to see how these details didn't make it through correctly. But the simplicity of fixing them indicates that the code is in pretty good shape. Anyway, that is the bugs. The code in queue.c is not bug related, but allows the client to receive a 500 response on error and to allow logging during error conditions. Here is a link to my patch to my code: http://www.junom.com/gitweb/gitweb.perl?p=aolserver.git;a=commit;h=ca26f1a tom jackson On Mon, 2009-04-06 at 11:13 -0500, Andrew Steets wrote: > I got a chance to test this out this morning. I don't understand what > it is supposed to fix. I still don't get access log entries when > ns_adp_abort is called. > > On Sun, Apr 5, 2009 at 12:52 PM, Tom Jackson wrote: > > The attached patch fixes ns_adp_break, it differs from the previous > > patch by one line in adpeval.c > > > > tom jackson > > > > On Sat, 2009-04-04 at 16:25 -0500, Andrew Steets wrote: > >> Hi Tom, > >> > >> Attachments seem to work ok on this list. > > > > > > > > -- > > AOLserver - http://www.aolserver.com/ > > > > To Remove yourself from this list, simply send an email to > > 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 > 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 with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
I got a chance to test this out this morning. I don't understand what it is supposed to fix. I still don't get access log entries when ns_adp_abort is called. On Sun, Apr 5, 2009 at 12:52 PM, Tom Jackson wrote: > The attached patch fixes ns_adp_break, it differs from the previous > patch by one line in adpeval.c > > tom jackson > > On Sat, 2009-04-04 at 16:25 -0500, Andrew Steets wrote: >> Hi Tom, >> >> Attachments seem to work ok on this list. > > > > -- > AOLserver - http://www.aolserver.com/ > > To Remove yourself from this list, simply send an email to > 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 with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
The attached patch fixes ns_adp_break, it differs from the previous
patch by one line in adpeval.c
tom jackson
On Sat, 2009-04-04 at 16:25 -0500, Andrew Steets wrote:
> Hi Tom,
>
> Attachments seem to work ok on this list.
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
t...@boron:~/cvs/aolserver/aolserver/nsd$ diff -u adpeval.c /web/tnt/aolserver/aolserver/nsd/adpeval.c
--- adpeval.c 2008-06-10 17:23:02.0 -0700
+++ /web/tnt/aolserver/aolserver/nsd/adpeval.c 2009-04-05 10:43:01.0 -0700
@@ -1017,7 +1017,12 @@
break;
case ADP_RETURN:
itPtr->adp.exception = ADP_OK;
- /* FALLTHROUGH */
+ result = TCL_OK;
+ break;
+case ADP_ABORT:
+case ADP_BREAK:
+result = TCL_ERROR;
+break;
default:
result = TCL_OK;
break;
t...@boron:~/cvs/aolserver/aolserver/nsd$ diff -u adprequest.c /web/tnt/aolserver/aolserver/nsd/adprequest.c
--- adprequest.c 2008-06-10 17:23:02.0 -0700
+++ /web/tnt/aolserver/aolserver/nsd/adprequest.c 2009-04-04 09:33:00.0 -0700
@@ -154,9 +154,15 @@
result = NsAdpInclude(itPtr, 2, objv, start, ttlPtr);
Tcl_DecrRefCount(objv[0]);
Tcl_DecrRefCount(objv[1]);
-if (NsAdpFlush(itPtr, 0) != TCL_OK || result != TCL_OK) {
- return NS_ERROR;
+if ((result != TCL_OK) && (itPtr->adp.exception == ADP_OK)) {
+ itPtr->adp.exception = ADP_ABORT;
+ NsAdpFlush(itPtr, 0);
+ return NS_ERROR;
}
+if (NsAdpFlush(itPtr, 0) != TCL_OK) {
+ return NS_ERROR;
+}
+
return NS_OK;
}
@@ -216,6 +222,7 @@
Tcl_ResetResult(interp);
if (itPtr->adp.exception == ADP_ABORT) {
Tcl_SetResult(interp, "adp flush disabled: adp aborted", TCL_STATIC);
+ result = TCL_OK;
} else if (len == 0 && stream) {
result = TCL_OK;
} else {
t...@boron:~/cvs/aolserver/aolserver/nsd$ diff -u queue.c /web/tnt/aolserver/aolserver/nsd/queue.c
--- queue.c 2009-04-04 08:43:56.0 -0700
+++ /web/tnt/aolserver/aolserver/nsd/queue.c 2009-04-03 16:17:46.0 -0700
@@ -595,6 +595,13 @@
status = NsRunFilters(conn, NS_FILTER_POST_AUTH);
if (status == NS_OK) {
status = Ns_ConnRunRequest(conn);
+ if (status != NS_OK) {
+ Ns_ConnReturnInternalError(conn);
+ status = NS_OK; /* to allow tracing to happen */
+ }
+ } else {
+ Ns_ConnReturnInternalError(conn);
+ status = NS_FILTER_RETURN; /* to allow tracing to happen */
}
break;
Re: [AOLSERVER] missing access log entries
Andrew, If the connection has been closed, nothing will be sent. But anyone who uses streaming output will have to live with the possibility that an error will occur mid-response. I don't recommend using streaming output for many reasons, but the most obvious is the one you mention: you (the generic developer) made a mistake in assuming that the response would complete without error. HTTP supports chunked output to handle situations where an entire response could never fit into memory. Anyway, there are many useless rules in the HTTP standards, but the basic signaling of what happened and maybe why is not in this category. Beyond returning information to the client, it is also useful to log the correct response code. My second to last post included a long list of observations about AOLserver code. One of these observations is that the AOLserver API includes a number of API which seem easy to use but actually require a lot of care in application. The entire ADP API falls into this category and also extends to ADP configuration options. What that means is that even with bug free API code, application developers must do lots of experimentation to verify how stuff actually works. The patch is not an attempt to change the basic algorithm of request processing. There were a few bugs which allowed confusion of actual errors and adp signaling. And there was the original behavior of skipping trace filters, including logging, when an error occurred, and this behavior has changed over time. My patch fixes a few bugs and applies the same error handling to all errors, regardless of where they occur. One other note: the ns_adp_ctl seems to have some bugs. Errors are only logged once (after calling ns_adp_ctl stricterror 1), and then the error logging flag seems to remain in place forever. It seems that this flag should be reset for each request, otherwise errors are not logged. tom jackson On Sat, 2009-04-04 at 16:25 -0500, Andrew Steets wrote: > Hi Tom, > > Attachments seem to work ok on this list. > > I don't think we can return 500 internal server error after > Ns_ConnRunRequest has been invoked as it may have already sent an http > response code via streaming output or ns_returnxxx. > > -Andrew > > On Sat, Apr 4, 2009 at 12:00 PM, Tom Jackson wrote: > > Here is a test patch for the ns_adp_abort issue. > > > > The patch enables sending an error message in the case of an actual > > error during adp processing, or after a postauth filter (preauth errors > > already allow this behavior). > > > > Also, logging is enabled in all cases. If an error occurs, a 500 > > response is sent and this is what is logged. > > > > I haven't tested this with ns_adp_break. But it works with ns_adp_return > > and ns_adp_abort as well as error handling in and adp. > > > > tom jackson > > > > Not sure if I can attach the patch, but here goes: > > > > > > > > > > -- > > AOLserver - http://www.aolserver.com/ > > > > To Remove yourself from this list, simply send an email to > > 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 > 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 with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
Hi Tom, Attachments seem to work ok on this list. I don't think we can return 500 internal server error after Ns_ConnRunRequest has been invoked as it may have already sent an http response code via streaming output or ns_returnxxx. -Andrew On Sat, Apr 4, 2009 at 12:00 PM, Tom Jackson wrote: > Here is a test patch for the ns_adp_abort issue. > > The patch enables sending an error message in the case of an actual > error during adp processing, or after a postauth filter (preauth errors > already allow this behavior). > > Also, logging is enabled in all cases. If an error occurs, a 500 > response is sent and this is what is logged. > > I haven't tested this with ns_adp_break. But it works with ns_adp_return > and ns_adp_abort as well as error handling in and adp. > > tom jackson > > Not sure if I can attach the patch, but here goes: > > > > > -- > AOLserver - http://www.aolserver.com/ > > To Remove yourself from this list, simply send an email to > 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 with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
Here is a test patch for the ns_adp_abort issue.
The patch enables sending an error message in the case of an actual
error during adp processing, or after a postauth filter (preauth errors
already allow this behavior).
Also, logging is enabled in all cases. If an error occurs, a 500
response is sent and this is what is logged.
I haven't tested this with ns_adp_break. But it works with ns_adp_return
and ns_adp_abort as well as error handling in and adp.
tom jackson
Not sure if I can attach the patch, but here goes:
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
t...@boron:~/cvs/aolserver/aolserver/nsd$ diff -u adpeval.c /web/tnt/aolserver/aolserver/nsd/adpeval.c
--- adpeval.c 2008-06-10 17:23:02.0 -0700
+++ /web/tnt/aolserver/aolserver/nsd/adpeval.c 2009-04-04 09:16:35.0 -0700
@@ -1017,7 +1017,11 @@
break;
case ADP_RETURN:
itPtr->adp.exception = ADP_OK;
- /* FALLTHROUGH */
+ result = TCL_OK;
+ break;
+case ADP_ABORT:
+result = TCL_ERROR;
+break;
default:
result = TCL_OK;
break;
t...@boron:~/cvs/aolserver/aolserver/nsd$ diff -u adprequest.c /web/tnt/aolserver/aolserver/nsd/adprequest.c
--- adprequest.c 2008-06-10 17:23:02.0 -0700
+++ /web/tnt/aolserver/aolserver/nsd/adprequest.c 2009-04-04 09:33:00.0 -0700
@@ -154,9 +154,15 @@
result = NsAdpInclude(itPtr, 2, objv, start, ttlPtr);
Tcl_DecrRefCount(objv[0]);
Tcl_DecrRefCount(objv[1]);
-if (NsAdpFlush(itPtr, 0) != TCL_OK || result != TCL_OK) {
- return NS_ERROR;
+if ((result != TCL_OK) && (itPtr->adp.exception == ADP_OK)) {
+ itPtr->adp.exception = ADP_ABORT;
+ NsAdpFlush(itPtr, 0);
+ return NS_ERROR;
}
+if (NsAdpFlush(itPtr, 0) != TCL_OK) {
+ return NS_ERROR;
+}
+
return NS_OK;
}
@@ -216,6 +222,7 @@
Tcl_ResetResult(interp);
if (itPtr->adp.exception == ADP_ABORT) {
Tcl_SetResult(interp, "adp flush disabled: adp aborted", TCL_STATIC);
+ result = TCL_OK;
} else if (len == 0 && stream) {
result = TCL_OK;
} else {
t...@boron:~/cvs/aolserver/aolserver/nsd$ diff -u queue.c /web/tnt/aolserver/aolserver/nsd/queue.c
--- queue.c 2009-04-04 08:43:56.0 -0700
+++ /web/tnt/aolserver/aolserver/nsd/queue.c 2009-04-03 16:17:46.0 -0700
@@ -595,6 +595,13 @@
status = NsRunFilters(conn, NS_FILTER_POST_AUTH);
if (status == NS_OK) {
status = Ns_ConnRunRequest(conn);
+ if (status != NS_OK) {
+ Ns_ConnReturnInternalError(conn);
+ status = NS_OK; /* to allow tracing to happen */
+ }
+ } else {
+ Ns_ConnReturnInternalError(conn);
+ status = NS_FILTER_RETURN; /* to allow tracing to happen */
}
break;
Re: [AOLSERVER] missing access log entries
On Fri, 2009-04-03 at 16:20 -0600, Jim Davidson wrote: > HI, > > Sorry -- I wrote the original and goofy code leading to this > confusion... > Thanks for monitoring our head scratching! I have a few random thoughts, and I'm not sure they add up to a particular conclusion or not. But here goes: * The adp code is squishy. It doesn't necessarily execute with the same precision as Tcl code. Under some configurations errors might not instantly terminate execution. * The adp code does not execute like an equivalent tcl page, probably due 100% to tcl pages using ns_tcl_abort and the generic tcl error handling. * The adp code has "evolved" over the years, actually there have been significant changes to the structure of the code. During the evolution, the detailed logic changed, sometimes bugs were introduced to fix perceived problems. It is amazing that nobody has noticed these differences. My guess is that nobody noticed because the changes have been uniquely backwards compatible, except when an actual error occurred. But since the errors were never logged, nobody was looking for the cause. * There is a good argument to be made that when an error occurs, everything that follows is crap. Therefore, further execution is pointless and may lead to compounded errors. * Trace filters could be thought of as a way to clean up stuff that was initialized during the request processing. But this is a hackish and currently invalid method in AOLserver. Why? The url can change during a connection, so code initialized in a preauth or postauth filter due to url matching might not get cleaned up with a matching url when trace filters run. * ns_atclose used to be a great way to clean up initialized code. It still works for connection based code, but it used to work for scheduled procs. ns_atclose has good qualities: it is registered only when code is initialized, so if the connection craps out before the initialization code runs, the ns_atclose code does not run. The other quality is that the code runs regardless of errors. It simply runs when the connection closes. This would be a great place for logging! * If the server experiences an internal error, it should attempt to return this information to the client. Maybe the client has dropped the connection, but this is not an internal server error (and AOLserver silently forgets about client drops). On error, the server should destroy all headers and all content and return a 500 response. The 500 response should get logged. This is the actual result of the request: an error. You have to tell the client what happened. Lots of code paths in AOLserver follow this rule, but not ADP code. * Access logging should happen whenever a response is returned, but we should keep in mind that an access log entry includes the response code and the length of the response, if these figures differ from reality, they become worse than useless. * Sometimes the error log is the best place to look for malfunctioning code. * AOLserver does a pretty good job of logging and offers many options for moderating/maximizing this important task. * I can't figure out why the AOLserver developers consider tcl pages to be a security risk when compared to ADP pages. AOL seemed to like adp pages, but OpenACS chose to use specialized filters. I have decided to use tcl pages as the primary "start page", and sometimes filters for generic modules/packages. * Filters seem uniquely superior when the url pattern determines which code should run. Unfortunately filters are many times registered to /*, the global pattern. This is not a filter in the typical sense. The only benefit is the ability to stage code to run in a particular order at a particular stage. The question is if there should be a separate stage for global filters, or a separate mechanism to register global code which runs at certain point, maybe conditioned on previous events. This is a like a generalized ns_atclose. * The access logging module is ancient, simple and in desperate need of professional help. * The Internal redirecting functionality is poorly documented and understood. These are configured as proxies or redirects. * A significant number of AOLserver API can be misused, that is these API cannot be used anywhere and everywhere. This is really no different from Tcl, where [break] must be executed inside of a loop. On first contact, it just isn't very obvious where the use of some AOLserver API is guaranteed to produce an error. (like calling ns_adp_return after an ns_returnXXX call). The result is understandable complaints about features which appear to be bugs. > Based on this discussion I think it's NOT working as intended. If > there was a time I thought ns_adp_abort should mean "return NS_ERROR > for connection status and thus no-traces..." I've long since > forgotten the rationale. What I remember is ns_adp_abort means > "somebody did something weird but valid, e.g., with ns_returnXXX, so > try to
Re: [AOLSERVER] missing access log entries
HI,
Sorry -- I wrote the original and goofy code leading to this
confusion...
Based on this discussion I think it's NOT working as intended. If
there was a time I thought ns_adp_abort should mean "return NS_ERROR
for connection status and thus no-traces..." I've long since
forgotten the rationale. What I remember is ns_adp_abort means
"somebody did something weird but valid, e.g., with ns_returnXXX, so
try to stop Tcl execution and don't send the buffer content (if
any)...". In contrast, ns_adp_break means "ADP buffer is good but
we're done so try to stop executing Tcl code and send what's
there...". The code is messy because the logical "break" is done by
raising a Tcl error which is why the ADP exception is stored
elsewhere. Also, I say "try to stop..." because I think one could
possibly use "catch" to catch the attempt to unwind the Tcl stack and
keep executing code. I'm not aware of any draconian logical "jump"
out of a script -- Tcl maintains state on the stack and it has to be
unwound in the end.
Related, on the trace/filter/cleanup discussion, the code was written
over successive versions and was never very smart or satisfying:
Traces: Stupid callbacks with no result code, they just all run if
the connection is "ok" run in FIFO order
Filters: Slightly less stupid callbacks that could signal "stop
running filters" or "don't bother with connection" (in case of pre-
auth) in FIFO order
Conn cleanup: More specific and perhaps not stupid: Callbacks run
unconditionally in LIFO order (suitable for cleanups). Evidently the
user could probe the connection context to see if things were bad or
good.
I think over the years I figured out that just skipping some callbacks
because the connection was "bad" (itself a poorly defined state) was
dumb so the conn-cleanup stuff was introduced.
And, just as old as the dumb trace code is the accesslog module -- it
was written when only the trace stuff was around and has stayed that
way. I'm not sure if switching accesslog to use a conn-cleanup would
work -- it may be accessing fields in the connection which may not be
initialized on a request cancelled very early on. Anyway, it seems
for the benefit of other filters (are there really any??), the ADP
code should be fixed so an "ns_adp_abort" is not an NS_ERROR.
BTW: I've wondered if accesslog is useful anyway -- seems like Google
Analytics gets you the insight you need on one end and a more specific
logging thing tied to the driver thread + cleanup would be useful for
the admin type folks. For example, I'm not sure you ever get a log
entry for a invalid connection request or aborted socket connection --
that's knowledge the driver thread would have (and would be
interesting to admin folks) but would never generate an accesslog
because there would never have been any connection context to provide
for logging.
-Jim
On Apr 3, 2009, at 3:11 PM, Tom Jackson wrote:
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
Re: [AOLSERVER] missing access log entries
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 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 u
Re: [AOLSERVER] missing access log entries
This is what I suggested a few emails ago :-)
> 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.
I'm fine with this patch.
-Andrew
On Fri, Apr 3, 2009 at 2:37 PM, Tom Jackson wrote:
> Hey,
>
> Hopefully this is my last post on this subject, I think I actually found
> the bug.
>
> The bug is in NsAdpFlush from nsd/adprequest.c:
>
> 214- */
> 215-
> 216-Tcl_ResetResult(interp);
> 217:if (itPtr->adp.exception == ADP_ABORT) {
> 218-Tcl_SetResult(interp, "adp flush disabled: adp aborted",
> TCL_STATIC);
> 219-result = TCL_OK;
> 220-} else if (len == 0 && stream) {
>
>
> The bug was a missing line setting result to TCL_OK. (line 219).
>
>
> Also, ns_adp_return cannot be used after and ns_returnxxx command as adp
> processing continues after calling it.
>
> Here are two test files:
>
> test-adp-abort.adp:
>
> <%
>
> ns_return 200 text/plain hi
>
> ns_adp_abort
>
> %>
>
> test-adp-return.adp:
>
> <%
>
> ns_adp_puts hi
>
> ns_adp_return
>
> %>
>
> Both of these result in an access.log entry.
>
> Before the change, ns_adp_abort would lead to an error message:
>
> adp flush failed: connection closed
>abort exception raised
> while processing connection #2:
>GET /test.adp HTTP/1.1
>Host: 127.0.0.1:8000
>User-Agent: ...
>Accept:
>Accept-Language: en-us,en;q=0.5
>Accept-Encoding: gzip,deflate
>Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
>Keep-Alive: 300
>Connection: keep-alive
>Cache-Control: max-age=0
>
>
> This error message is valid if ns_adp_return is used after and
> ns_returnxxx.
>
> tom jackson
>
>
>
> On Fri, 2009-04-03 at 08:33 -0700, Tom Jackson 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 ret
Re: [AOLSERVER] missing access log entries
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 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 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
Re: [AOLSERVER] missing access log entries
Hey,
Hopefully this is my last post on this subject, I think I actually found
the bug.
The bug is in NsAdpFlush from nsd/adprequest.c:
214- */
215-
216-Tcl_ResetResult(interp);
217:if (itPtr->adp.exception == ADP_ABORT) {
218-Tcl_SetResult(interp, "adp flush disabled: adp aborted",
TCL_STATIC);
219-result = TCL_OK;
220-} else if (len == 0 && stream) {
The bug was a missing line setting result to TCL_OK. (line 219).
Also, ns_adp_return cannot be used after and ns_returnxxx command as adp
processing continues after calling it.
Here are two test files:
test-adp-abort.adp:
<%
ns_return 200 text/plain hi
ns_adp_abort
%>
test-adp-return.adp:
<%
ns_adp_puts hi
ns_adp_return
%>
Both of these result in an access.log entry.
Before the change, ns_adp_abort would lead to an error message:
adp flush failed: connection closed
abort exception raised
while processing connection #2:
GET /test.adp HTTP/1.1
Host: 127.0.0.1:8000
User-Agent: ...
Accept:
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cache-Control: max-age=0
This error message is valid if ns_adp_return is used after and
ns_returnxxx.
tom jackson
On Fri, 2009-04-03 at 08:33 -0700, Tom Jackson 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 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
Re: [AOLSERVER] missing access log entries
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 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 >
Re: [AOLSERVER] missing access log entries
Andrew, Here is a link to the tiny bit of code which handles every request: http://junom.com/gitweb/gitweb.perl?p=aolserver.git;a=blob;f=aolserver/nsd/queue.c;hb=HEAD#l585 >From my reading of this, the problem must be that ns_adp_abort is not returning NS_OK or NS_FILTER_RETURN. It probably should return NS_OK once the entire adp stack is unwound (this will happen in the C code somewhere, but I haven't ever looked at how adp processing works). Otherwise on line 625 of nsd/queue.c, the trace filters are skipped. Looking at this code it appears that preauth, postauth and request proc errors are handled differently. Only errors thrown in a preauth filter are nullified, which allows trace filters to run. This seems strange. tom jackson 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 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 >
Re: [AOLSERVER] missing access log entries
The trace filters are filters which run at the end of a connection. Here is the basic order of processing: preauth filters (frfr) first register, first run auth proc (one only) postauth filters (frfr) registered proc (one only) trace filters (frlr) first to register, last to run There is also another system handled via ns_ictl which can run callbacks at other times. These are used to load libraries, maintain interps, etc. (ictl = interp control). There is also ns_atclose, which runs at the end of every connection thread. It used to run at the end of every schedule proc as well, but it doesn't anymore. I've replaced ns_atclose with ns_ictl when I need cleanup. Anyway, filters and registered procs are based upon the request url, which is very different from cleanup/ns_ictl handlers, which fire based upon a request reaching a particular point. ns_adp_abort should fastforward to the beginning of any trace filters, it should have no effect on anything configured via ns_atclose or ns_ictl, because this API is meant as a request flow control mechanism (like filter_return, filter_break or filter_ok (filter_ok is like continue)). Filter_return called inside a filter causes the intended fastforward which ns_adp_abort should be doing but isn't when called from inside an adp. tom jackson 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 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 > > ab
Re: [AOLSERVER] missing access log entries
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 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 < > lists...@listserv.aol.com> 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 < > lists...@listserv.aol.com> 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 with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
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 > 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 with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
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 with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
Hey again, I just noticed ns_adp_break: http://rmadilo.com/files/nsapi/ns_adp_break.html In contrast to ns_adp_abort. ns_adp_break flushes all output to the client then aborts further adp processing. So my guess is that you use ns_adp_break when you want to use the current ADP buffer, and you use ns_adp_abort when you have decided to call ns_returnxxx and discard the ADP buffer. I think that the ADP buffer is only flushed if you have executed ns_adp_stream, so you should always be able to abort knowing that nothing has been sent to the client. tom jackson -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
On Fri, 2009-03-27 at 09:56 +0100, Gustaf Neumann wrote:
> Andrew Steets schrieb:
> > As Scott suggested, we should probably log everything, at least for
> > some reasonable value of "everything." Even if you switch the access
> > log trace to the cleanup callback, you still don't get access entries
> > for clients who connect but don't issue a well formed HTTP request. I
> > don't have a huge problem with that, and I think it would be difficult
> > to log those types of events.
> >
> i am as well in favor of loging the adp_aborts, since this seems a used
> idiom.
> There is no advantage in omitting such entries in the log file, but it
> might be
> hard to figure out what happens without that.
>
> For example, in our production system, we use nginx, which logs these
> requests on its own. A problem show up, when we try to debug a situation,
> where some requests present in the nginx log are missing in the
> aolserver log.
Hey,
I just looked up some old manpage entries for ns_adp_abort.
Here is my copy: http://rmadilo.com/files/nsapi/ns_adp_abort.html
In short, ns_adp_abort is supposed to work just like ns_tcl_abort.
It should not have any effect on logging, so there must be a bug in the
current implementation. My guess is that it skips too much stuff,
including trace filters, etc. But reading the manpage, I don't see any
requirement to log anything either.
Basically this is to allow a deep unwind of ADP processing which doesn't
require a [catch]. Here's what the manpage says:
ns_adp_abort
Stop processing of ADP and throw away all output.
Syntax
ns_adp_abort ?return_value?
Description
This function aborts processing of the ADP file and any pending output
up to that point is deleted. However, if a streaming script was
processed before ns_adp_abort was called, the data will already have
been output. Also, if any functions that cause output (such as ns_return
or ns_write) were called before ns_adp_abort, their output will already
have been output also.
ns_adp_abort closes the connection without returning an empty HTML page.
Every ns_returnxxx call in an ADP should be followed with a call to
ns_adp_abort.
The return_value, if specified, becomes the return value of the ADP.
Note that this function returns all the way up the call stack. For
example, suppose a.adp includes b.adp which includes c.adp, and c.adp
calls ns_adp_abort. No code in b.adp or a.adp after the includes will be
executed. You can get around this in one of two ways:
* You can execute these calls in a.adp and b.adp, respectively:
catch {ns_adp_include b.adp} retval
catch {ns_adp_include c.adp} retval
* Or, you can execute this call in c.adp:
ns_adp_return ?retval?
The ns_adp_return function returns up only one level.
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
Re: [AOLSERVER] missing access log entries
Andrew Steets schrieb: I'm inclined to agree with you that the current behavior is a bug, but it raises the question: should there be such a function that says "this connection wasn't handled, don't even log it" - or, should ALL connections always be logged, even if it's aborted? As Scott suggested, we should probably log everything, at least for some reasonable value of "everything." Even if you switch the access log trace to the cleanup callback, you still don't get access entries for clients who connect but don't issue a well formed HTTP request. I don't have a huge problem with that, and I think it would be difficult to log those types of events. i am as well in favor of loging the adp_aborts, since this seems a used idiom. There is no advantage in omitting such entries in the log file, but it might be hard to figure out what happens without that. For example, in our production system, we use nginx, which logs these requests on its own. A problem show up, when we try to debug a situation, where some requests present in the nginx log are missing in the aolserver log. -gustaf neumann -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to 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 with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
Hello!
On Friday 27 March 2009 01:21:38 Dossy Shiobara wrote:
> Why are you using ns_adp_abort here instead of ns_adp_return?
=
$ cat test.adp
<%
ns_adp_puts "Test ADP"
ns_adp_include test.inc
%>
$ cat test.inc
<%
ns_adp_puts "Test inc"
ns_return 200 {text/html; charset=utf-8} {Stop processing of ADP and inc.
Buffer will be cleaned.}
ns_adp_abort
%>
$ GET http://mobigroup.ru/extension/test.adp
Stop processing of .inc.
There is no error in log.
$ sudo tail -f /var/log/aolserver4/mobigroup.ru.log
=
=
$ cat test.adp
<%
ns_adp_puts "Test ADP"
ns_adp_include test.inc
%>
$ cat test.inc
<%
ns_adp_puts "Test inc"
ns_return 200 {text/html; charset=utf-8} {Stop processing of ADP and inc.
Buffer will be cleaned.}
ns_adp_return
%>
$ GET http://mobigroup.ru/extension/test.adp
Stop processing of .inc.
$ sudo tail -f /var/log/aolserver4/mobigroup.ru.log
[27/Mar/2009:09:16:30][20306.3071187856][-default:0-] Error: Tcl exception:
adp flush failed: connection closed
abort exception raised
while processing connection #3:
GET /extension/test.adp HTTP/1.1
TE: deflate,gzip;q=0.3
Connection: TE, close
Host: mobigroup.ru
User-Agent: lwp-request/5.824 libwww-perl/5.825
X-Forwarded-For: 195.122.250.12
=
=
$ cat test.adp
<%
ns_adp_puts "Test ADP"
ns_adp_include test.inc
%>
$ cat test.inc
<%
ns_adp_puts "Test inc"
ns_return 200 {text/html; charset=utf-8} {Stop processing of ADP and inc.
Buffer will be cleaned.}
ns_adp_break
%>
$ GET http://mobigroup.ru/extension/test.adp
Stop processing of .inc.
$ sudo tail -f /var/log/aolserver4/mobigroup.ru.log
[27/Mar/2009:09:16:30][20306.3071187856][-default:0-] Error: Tcl exception:
adp flush failed: connection closed
abort exception raised
while processing connection #3:
GET /extension/test.adp HTTP/1.1
TE: deflate,gzip;q=0.3
Connection: TE, close
Host: mobigroup.ru
User-Agent: lwp-request/5.824 libwww-perl/5.825
X-Forwarded-For: 195.122.250.12
=
Best regards.
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
Re: [AOLSERVER] missing access log entries
This thread has turned into an interesting discussion of what may be a
fairly useful ADP programming idiom, but I don't want to focus too
much on ns_adp_abort. There are other cases that will cause the ADP
to run without generating an access log entry. For example, if you
call one of the ns_returnxxx family of functions within an ADP, no
access log entry will be created regardless of whether or not
ns_adp_abort was called. I think there are more cases but I can't
come up with any right now.
I suspect, though I have not had time to confirm, that in aolserver
4.0 this was not a problem. If anyone has a testing 4.0 instance can
you please run a quick test?
If we decouple the web developers from the people who monitor and
administer the web server I think it becomes more clear. If I am a
security administrator, I want to know all the URLs that have been
accessed on the server, regardless of what the ADP code does. If I am
a systems administrator, I want to know how much data was sent out in
response to any request, and how much time it took to process the
request (I'm a *huge* fan of logreqtime), regardless of what the ADP
did.
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.
-Andrew
On Thu, Mar 26, 2009 at 6:34 PM, Tom Jackson wrote:
> By a strange coincidence I needed had a similar issue with Tcl (tcl
> pages).
>
> I did a ns_returnredirect way deep into an application. I was hoping to
> abort further execution of Tcl code, but by design, script execution
> continues.
>
> I considered that only throwing an error would unwind everything
> correctly. Since I hate the idea of doing this inside Tcl code, I
> decided to live with the problem.
>
> Then I discovered ns_tcl_abort. Here's the def:
> (from modules/file.tcl):
> #
> # ns_tcl_abort is a work-alike ns_adp_abort.
> #
> proc ns_tcl_abort {} {
> error ns_tcl_abort "" NS_TCL_ABORT
> }
>
> So if this is a work-alike, the intent could be to stop processing deep
> within some code, but it shouldn't have any effect on the logging.
>
> Note that ns_sourceproc catches the above error:
> proc ns_sourceproc {..} {
> ...
> if {$code == 1 && $errorCode == "NS_TCL_ABORT"} {
> return
> }
>
> }
>
> So I think normal logging should take place.
>
> The best evidence for normal logging is that ns_adp_abort is called
> intentionally, so the programmer can decide when to do it.
>
> tom jackson
>
> On Thu, 2009-03-26 at 16:11 -0400, Scott Goodwin wrote:
>> All connections should be logged as requests that came from clients
>> along with details on how the server responds. Some indication that
>> the connection was aborted should be made in the log, perhaps with a
>> count of how many bytes were transferred. In cases where no response
>> is going to be sent and the connection aborted, the response code
>> shown in the log could be left blank or as a placeholder (e.g. "xxx").
>> The general principle is that we always want visibility into what
>> happens with every connection -- in many situations we are serving
>> anonymous clients who aren't going to call and complain or post a
>> trouble ticket, so it's nice to see such aborted conns in the logs as
>> an indication that we might need to investigate what's going on.
>>
>> /s.
>>
>> On Mar 26, 2009, at 2:40 PM, Dossy Shiobara wrote:
>>
>> > On 3/26/09 1:31 PM, Andrew Steets wrote:
>> >> Hello,
>> >>
>> >> There are certain cases where connections probably ought to generate
>> >> access log entries but do not. Specifically if an ADP exits via
>> >> ns_adp_abort no access log entry will be generated, but data may have
>> >> been returned to the client. This seems like a bug.
>> >
>> > I wonder - should this be the documented known behavior of
>> > ns_adp_abort vs. ns_adp_return? i.e., abort indicates that the
>> > connection is intentionally terminated, not logged, etc. vs.
>> > ns_adp_return which halts ADP processing but continues the
>> > connection, which includes logging, etc.
>> >
>> > I'm inclined to agree with you that the current behavior is a bug,
>> > but it raises the question: should there be such a function that
>> > says "this connection wasn't handled, don't even log it" - or,
>> > should ALL connections always be logged, even if it's aborted?
>> >
>> > Thanks, Andrew.
>> >
>> > --
>> > Dossy Shiobara | do...@panoptic.com | http://dossy.org/
>> > Panoptic Computer Network | http://panoptic.com/
>> > "He realized the fastest way to change is to laugh at your own
>> > folly -- then you can let go and quickly move on." (p. 70)
>> >
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
Re: [AOLSERVER] missing access log entries
By a strange coincidence I needed had a similar issue with Tcl (tcl
pages).
I did a ns_returnredirect way deep into an application. I was hoping to
abort further execution of Tcl code, but by design, script execution
continues.
I considered that only throwing an error would unwind everything
correctly. Since I hate the idea of doing this inside Tcl code, I
decided to live with the problem.
Then I discovered ns_tcl_abort. Here's the def:
(from modules/file.tcl):
#
# ns_tcl_abort is a work-alike ns_adp_abort.
#
proc ns_tcl_abort {} {
error ns_tcl_abort "" NS_TCL_ABORT
}
So if this is a work-alike, the intent could be to stop processing deep
within some code, but it shouldn't have any effect on the logging.
Note that ns_sourceproc catches the above error:
proc ns_sourceproc {..} {
...
if {$code == 1 && $errorCode == "NS_TCL_ABORT"} {
return
}
}
So I think normal logging should take place.
The best evidence for normal logging is that ns_adp_abort is called
intentionally, so the programmer can decide when to do it.
tom jackson
On Thu, 2009-03-26 at 16:11 -0400, Scott Goodwin wrote:
> All connections should be logged as requests that came from clients
> along with details on how the server responds. Some indication that
> the connection was aborted should be made in the log, perhaps with a
> count of how many bytes were transferred. In cases where no response
> is going to be sent and the connection aborted, the response code
> shown in the log could be left blank or as a placeholder (e.g. "xxx").
> The general principle is that we always want visibility into what
> happens with every connection -- in many situations we are serving
> anonymous clients who aren't going to call and complain or post a
> trouble ticket, so it's nice to see such aborted conns in the logs as
> an indication that we might need to investigate what's going on.
>
> /s.
>
> On Mar 26, 2009, at 2:40 PM, Dossy Shiobara wrote:
>
> > On 3/26/09 1:31 PM, Andrew Steets wrote:
> >> Hello,
> >>
> >> There are certain cases where connections probably ought to generate
> >> access log entries but do not. Specifically if an ADP exits via
> >> ns_adp_abort no access log entry will be generated, but data may have
> >> been returned to the client. This seems like a bug.
> >
> > I wonder - should this be the documented known behavior of
> > ns_adp_abort vs. ns_adp_return? i.e., abort indicates that the
> > connection is intentionally terminated, not logged, etc. vs.
> > ns_adp_return which halts ADP processing but continues the
> > connection, which includes logging, etc.
> >
> > I'm inclined to agree with you that the current behavior is a bug,
> > but it raises the question: should there be such a function that
> > says "this connection wasn't handled, don't even log it" - or,
> > should ALL connections always be logged, even if it's aborted?
> >
> > Thanks, Andrew.
> >
> > --
> > Dossy Shiobara | do...@panoptic.com | http://dossy.org/
> > Panoptic Computer Network | http://panoptic.com/
> > "He realized the fastest way to change is to laugh at your own
> >folly -- then you can let go and quickly move on." (p. 70)
> >
> >
> > --
> > AOLserver - http://www.aolserver.com/
> >
> > To Remove yourself from this list, simply send an email to
> > > > 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
> 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
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
Re: [AOLSERVER] missing access log entries
On 3/26/09 5:12 PM, Alexey Pechnikov wrote:
How about ADP or file is included into ADP with code
ns_return 200 {text/html; charset=utf-8} {some message}
ns_adp_abort
or
ns_returnfile 200 [ns_guesstype $fname] $fname
ns_adp_abort
This request _must be_ logged. ns_adp_break is not correct here because it
will send all output to closed connection.
Why are you using ns_adp_abort here instead of ns_adp_return?
--
Dossy Shiobara | do...@panoptic.com | http://dossy.org/
Panoptic Computer Network | http://panoptic.com/
"He realized the fastest way to change is to laugh at your own
folly -- then you can let go and quickly move on." (p. 70)
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
Re: [AOLSERVER] missing access log entries
Hello!
On Thursday 26 March 2009 21:40:05 Dossy Shiobara wrote:
> I wonder - should this be the documented known behavior of ns_adp_abort
> vs. ns_adp_return? i.e., abort indicates that the connection is
> intentionally terminated, not logged, etc. vs. ns_adp_return which halts
> ADP processing but continues the connection, which includes logging, etc.
>
> I'm inclined to agree with you that the current behavior is a bug, but
> it raises the question: should there be such a function that says "this
> connection wasn't handled, don't even log it" - or, should ALL
> connections always be logged, even if it's aborted?
How about ADP or file is included into ADP with code
ns_return 200 {text/html; charset=utf-8} {some message}
ns_adp_abort
or
ns_returnfile 200 [ns_guesstype $fname] $fname
ns_adp_abort
This request _must be_ logged. ns_adp_break is not correct here because it
will send all output to closed connection.
Best regards.
--
AOLserver - http://www.aolserver.com/
To Remove yourself from this list, simply send an email to
with the
body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject:
field of your email blank.
Re: [AOLSERVER] missing access log entries
On Thu, Mar 26, 2009 at 1:40 PM, Dossy Shiobara wrote: > I wonder - should this be the documented known behavior of ns_adp_abort vs. > ns_adp_return? i.e., abort indicates that the connection is intentionally > terminated, not logged, etc. vs. ns_adp_return which halts ADP processing > but continues the connection, which includes logging, etc. We have some ADP code that explicitly returns data via ns_return and then calls ns_adp_abort to discontinue processing. It isn't an error per se, just another way of getting data back to the client. Maybe it's a pathological case. I don't understand exactly why we do it that way (not my code), but the ns_adp_abort documentation mentions this type of strategy. > I'm inclined to agree with you that the current behavior is a bug, but it > raises the question: should there be such a function that says "this > connection wasn't handled, don't even log it" - or, should ALL connections > always be logged, even if it's aborted? As Scott suggested, we should probably log everything, at least for some reasonable value of "everything." Even if you switch the access log trace to the cleanup callback, you still don't get access entries for clients who connect but don't issue a well formed HTTP request. I don't have a huge problem with that, and I think it would be difficult to log those types of events. -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
On Thu, 2009-03-26 at 14:40 -0400, Dossy Shiobara wrote: > On 3/26/09 1:31 PM, Andrew Steets wrote: > > Hello, > > > > There are certain cases where connections probably ought to generate > > access log entries but do not. Specifically if an ADP exits via > > ns_adp_abort no access log entry will be generated, but data may have > > been returned to the client. This seems like a bug. > > I wonder - should this be the documented known behavior of ns_adp_abort > vs. ns_adp_return? i.e., abort indicates that the connection is > intentionally terminated, not logged, etc. vs. ns_adp_return which halts > ADP processing but continues the connection, which includes logging, etc. > > I'm inclined to agree with you that the current behavior is a bug, but > it raises the question: should there be such a function that says "this > connection wasn't handled, don't even log it" - or, should ALL > connections always be logged, even if it's aborted? I would think that an aborted connection isn't a complete connection, and shouldn't require logging. Maybe something in the error log, but you can do that just before you call ns_adp_abort. Under what conditions should ns_adp_abort be used? Does calling this actually close a connection, or does it just remove what is in the buffer? tom jackson -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
All connections should be logged as requests that came from clients along with details on how the server responds. Some indication that the connection was aborted should be made in the log, perhaps with a count of how many bytes were transferred. In cases where no response is going to be sent and the connection aborted, the response code shown in the log could be left blank or as a placeholder (e.g. "xxx"). The general principle is that we always want visibility into what happens with every connection -- in many situations we are serving anonymous clients who aren't going to call and complain or post a trouble ticket, so it's nice to see such aborted conns in the logs as an indication that we might need to investigate what's going on. /s. On Mar 26, 2009, at 2:40 PM, Dossy Shiobara wrote: On 3/26/09 1:31 PM, Andrew Steets wrote: Hello, There are certain cases where connections probably ought to generate access log entries but do not. Specifically if an ADP exits via ns_adp_abort no access log entry will be generated, but data may have been returned to the client. This seems like a bug. I wonder - should this be the documented known behavior of ns_adp_abort vs. ns_adp_return? i.e., abort indicates that the connection is intentionally terminated, not logged, etc. vs. ns_adp_return which halts ADP processing but continues the connection, which includes logging, etc. I'm inclined to agree with you that the current behavior is a bug, but it raises the question: should there be such a function that says "this connection wasn't handled, don't even log it" - or, should ALL connections always be logged, even if it's aborted? Thanks, Andrew. -- Dossy Shiobara | do...@panoptic.com | http://dossy.org/ Panoptic Computer Network | http://panoptic.com/ "He realized the fastest way to change is to laugh at your own folly -- then you can let go and quickly move on." (p. 70) -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to > 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 with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
Re: [AOLSERVER] missing access log entries
On 3/26/09 1:31 PM, Andrew Steets wrote: Hello, There are certain cases where connections probably ought to generate access log entries but do not. Specifically if an ADP exits via ns_adp_abort no access log entry will be generated, but data may have been returned to the client. This seems like a bug. I wonder - should this be the documented known behavior of ns_adp_abort vs. ns_adp_return? i.e., abort indicates that the connection is intentionally terminated, not logged, etc. vs. ns_adp_return which halts ADP processing but continues the connection, which includes logging, etc. I'm inclined to agree with you that the current behavior is a bug, but it raises the question: should there be such a function that says "this connection wasn't handled, don't even log it" - or, should ALL connections always be logged, even if it's aborted? Thanks, Andrew. -- Dossy Shiobara | do...@panoptic.com | http://dossy.org/ Panoptic Computer Network | http://panoptic.com/ "He realized the fastest way to change is to laugh at your own folly -- then you can let go and quickly move on." (p. 70) -- AOLserver - http://www.aolserver.com/ To Remove yourself from this list, simply send an email to with the body of "SIGNOFF AOLSERVER" in the email message. You can leave the Subject: field of your email blank.
