Re: [AOLSERVER] missing access log entries

2009-04-16 Thread Tom Jackson
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;
}

status = NsRunFilters(conn, 

Re: [AOLSERVER] missing access log entries

2009-04-16 Thread Alexey Pechnikov
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 
lists...@listserv.aol.com 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

2009-04-16 Thread Tom Jackson
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 
lists...@listserv.aol.com 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

2009-04-15 Thread Gustaf Neumann

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) {
status = 

Re: [AOLSERVER] missing access log entries

2009-04-15 Thread Jim Davidson

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;
   }

   if (status == 

Re: [AOLSERVER] missing access log entries

2009-04-15 Thread Tom Jackson
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 
lists...@listserv.aol.com 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

2009-04-15 Thread Jim Davidson
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 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.


Re: [AOLSERVER] missing access log entries

2009-04-15 Thread Tom Jackson
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,
  connPtr-authUser, connPtr-authPasswd, connPtr-peer);
 
 switch (status) {
 case 

Re: [AOLSERVER] missing access log entries

2009-04-14 Thread Jim Davidson

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.
*
* Results:
*  NS_OK 

Re: [AOLSERVER] missing access log entries

2009-04-13 Thread Jim Davidson

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 these figures 

Re: [AOLSERVER] missing access log entries

2009-04-13 Thread Tom Jackson
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 
lists...@listserv.aol.com 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

2009-04-12 Thread Gustaf Neumann

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 
lists...@listserv.aol.com 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

2009-04-12 Thread Tom Jackson
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 
lists...@listserv.aol.com 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

2009-04-11 Thread Tom Jackson
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 notice
that the 

Re: [AOLSERVER] missing access log entries

2009-04-10 Thread Tom Jackson
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 t...@rmadilo.com 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 
 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.


Re: [AOLSERVER] missing access log entries

2009-04-10 Thread Gustaf Neumann

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 
lists...@listserv.aol.com 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

2009-04-09 Thread Andrew Steets
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 t...@rmadilo.com 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 
lists...@listserv.aol.com 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

2009-04-06 Thread Andrew Steets
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 t...@rmadilo.com 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 
 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.


Re: [AOLSERVER] missing access log entries

2009-04-05 Thread Tom Jackson
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 
lists...@listserv.aol.com 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

2009-04-04 Thread Tom Jackson
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 
lists...@listserv.aol.com 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

2009-04-04 Thread Andrew Steets
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 t...@rmadilo.com 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 
 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.


Re: [AOLSERVER] missing access log entries

2009-04-04 Thread Tom Jackson
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 t...@rmadilo.com 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 
  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 
lists...@listserv.aol.com 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

2009-04-03 Thread Tom Jackson
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 t...@rmadilo.com 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 

Re: [AOLSERVER] missing access log entries

2009-04-03 Thread Tom Jackson
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 t...@rmadilo.com 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 

Re: [AOLSERVER] missing access log entries

2009-04-03 Thread Andrew Steets
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 t...@rmadilo.com 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 t...@rmadilo.com 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 

Re: [AOLSERVER] missing access log entries

2009-04-03 Thread Andrew Steets
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 t...@rmadilo.com 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 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 

Re: [AOLSERVER] missing access log entries

2009-04-03 Thread Tom Jackson
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 t...@rmadilo.com 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 

Re: [AOLSERVER] missing access log entries

2009-04-03 Thread Jim Davidson

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 filter.  I think that the access log 

Re: [AOLSERVER] missing access log entries

2009-04-03 Thread Tom Jackson
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 stop Tcl 

Re: [AOLSERVER] missing access log entries

2009-04-02 Thread Gustaf Neumann

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.


Re: [AOLSERVER] missing access log entries

2009-04-02 Thread Tom Jackson
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.


Re: [AOLSERVER] missing access log entries

2009-04-02 Thread Tom Jackson
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 t...@rmadilo.com 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
 

Re: [AOLSERVER] missing access log entries

2009-04-02 Thread Tom Jackson
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 t...@rmadilo.com 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
 

Re: [AOLSERVER] missing access log entries

2009-03-29 Thread Tom Jackson
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 
lists...@listserv.aol.com 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

2009-03-29 Thread Tom Jackson
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 
lists...@listserv.aol.com 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

2009-03-27 Thread Alexey Pechnikov
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 
lists...@listserv.aol.com 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

2009-03-27 Thread Gustaf Neumann

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


Re: [AOLSERVER] missing access log entries

2009-03-26 Thread Dossy Shiobara

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 
lists...@listserv.aol.com 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

2009-03-26 Thread Scott Goodwin
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 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.


Re: [AOLSERVER] missing access log entries

2009-03-26 Thread Tom Jackson
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 
lists...@listserv.aol.com 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

2009-03-26 Thread Andrew Steets
On Thu, Mar 26, 2009 at 1:40 PM, Dossy Shiobara do...@panoptic.com 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 
lists...@listserv.aol.com 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

2009-03-26 Thread Alexey Pechnikov
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 
lists...@listserv.aol.com 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

2009-03-26 Thread Dossy Shiobara

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 
lists...@listserv.aol.com 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

2009-03-26 Thread Tom Jackson
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 
  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 
lists...@listserv.aol.com 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

2009-03-26 Thread Andrew Steets
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 t...@rmadilo.com 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 
lists...@listserv.aol.com with the
body of SIGNOFF AOLSERVER in the email message. You can leave the Subject: 
field of your email blank.