Received: by taz.hyperreal.com (8.6.12/8.6.5) id QAA04233; Fri, 2 Aug 1996 16:49:05 -0700 Received: from acidik.organic.com by taz.hyperreal.com (8.6.12/8.6.5) with ESMTP id QAA04173; Fri, 2 Aug 1996 16:48:57 -0700 Received: from localhost (akosut@localhost) by acidik.organic.com (8.7.5/8.6.12) with SMTP id QAA05658 for ; Fri, 2 Aug 1996 16:48:30 -0700 (PDT) X-Authentication-Warning: acidik.organic.com: akosut owned process doing -bs Date: Fri, 2 Aug 1996 16:48:29 -0700 (PDT) From: Alexei Kosut To: Apache Subject: ScriptLog patch Message-ID: MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII Sender: owner-new-httpd@apache.org Precedence: bulk Reply-To: new-httpd@HYPERREAL.COM Included is a patch that adds functionality to mod_cgi to log CGI errors to a seperate file, activated by a directive called "ScriptLog". When active, it logs the request and request headers, the POST arguments (if present), the script's output, any stderr output from the script, and other relavent pieces of information. It makes debugging CGI scripts easier, because you don't have to guess as much about what's gone wrong. It lets you configure how much of a POST request to log, using the ScriptLogBuffer directive (this is so someone can't send large files repeatedly and fill up your drive), and provides a ScriptLogLength directive that lets you set the maximum length of the script log - if it gets larger than this, it will not log to it. Anyhow, I think this patch would be useful to see in 1.2. It doesn't change Apache's behavior, unless turned on, but does change a lot of the CGI and general exec code, so it'd be nice if people could go through it, and maybe send comments or +1 votes. Thanks. Here's the patch: Index: alloc.c =================================================================== RCS file: /export/home/cvs/apache/src/alloc.c,v retrieving revision 1.8 diff -c -r1.8 alloc.c *** alloc.c 1996/07/25 19:32:25 1.8 --- alloc.c 1996/08/02 23:41:23 *************** *** 852,864 **** a->subprocesses = new; } ! int spawn_child (pool *p, void (*func)(void *), void *data, ! enum kill_conditions kill_how, ! FILE **pipe_in, FILE **pipe_out) { int pid; int in_fds[2]; int out_fds[2]; block_alarms(); --- 852,865 ---- a->subprocesses = new; } ! int spawn_child_err (pool *p, void (*func)(void *), void *data, ! enum kill_conditions kill_how, ! FILE **pipe_in, FILE **pipe_out, FILE **pipe_err) { int pid; int in_fds[2]; int out_fds[2]; + int err_fds[2]; block_alarms(); *************** *** 876,881 **** --- 877,893 ---- return 0; } + if (pipe_err && pipe (err_fds) < 0) { + if (pipe_in) { + close (in_fds[0]); close (in_fds[1]); + } + if (pipe_out) { + close (out_fds[0]); close (out_fds[1]); + } + unblock_alarms(); + return 0; + } + if ((pid = fork()) < 0) { if (pipe_in) { close (in_fds[0]); close (in_fds[1]); *************** *** 883,888 **** --- 895,903 ---- if (pipe_out) { close (out_fds[0]); close (out_fds[1]); } + if (pipe_err) { + close (err_fds[0]); close (err_fds[1]); + } unblock_alarms(); return 0; } *************** *** 902,907 **** --- 917,928 ---- close (in_fds[0]); } + if (pipe_err) { + close (err_fds[0]); + dup2 (err_fds[1], STDERR_FILENO); + close (err_fds[1]); + } + /* HP-UX SIGCHLD fix goes here, if someone will remind me what it is... */ signal (SIGCHLD, SIG_DFL); /* Was that it? */ *************** *** 935,940 **** --- 956,973 ---- #endif if (*pipe_in) note_cleanups_for_file (p, *pipe_in); + } + + if (pipe_err) { + close (err_fds[1]); + #ifdef __EMX__ + /* Need binary mode set for OS/2. */ + *pipe_err = fdopen (err_fds[0], "rb"); + #else + *pipe_err = fdopen (err_fds[0], "r"); + #endif + + if (*pipe_err) note_cleanups_for_file (p, *pipe_err); } unblock_alarms(); Index: alloc.h =================================================================== RCS file: /export/home/cvs/apache/src/alloc.h,v retrieving revision 1.7 diff -c -r1.7 alloc.h *** alloc.h 1996/07/25 19:32:26 1.7 --- alloc.h 1996/08/02 23:41:23 *************** *** 228,235 **** enum kill_conditions { kill_never, kill_always, kill_after_timeout, just_wait}; ! int spawn_child (pool *, void (*)(void *), void *, ! enum kill_conditions, FILE **pipe_in, FILE **pipe_out); #ifdef __EMX__ int spawn_child_os2 (pool *, void (*)(void *), void *, enum kill_conditions, FILE **pipe_in, FILE **pipe_out, char *buffer, int lenp); --- 228,238 ---- enum kill_conditions { kill_never, kill_always, kill_after_timeout, just_wait}; ! int spawn_child_err (pool *, void (*)(void *), void *, ! enum kill_conditions, FILE **pipe_in, FILE **pipe_out, ! FILE **pipe_err); ! #define spawn_child(p,f,v,k,in,out) spawn_child_err(p,f,v,k,in,out,NULL) ! #ifdef __EMX__ int spawn_child_os2 (pool *, void (*)(void *), void *, enum kill_conditions, FILE **pipe_in, FILE **pipe_out, char *buffer, int lenp); Index: mod_cgi.c =================================================================== RCS file: /export/home/cvs/apache/src/mod_cgi.c,v retrieving revision 1.12 diff -c -r1.12 mod_cgi.c *** mod_cgi.c 1996/07/28 19:27:48 1.12 --- mod_cgi.c 1996/08/02 23:41:23 *************** *** 51,57 **** * */ - /* * http_script: keeps all script-related ramblings together. * --- 51,56 ---- *************** *** 74,79 **** --- 73,80 ---- #include "http_log.h" #include "util_script.h" + module cgi_module; + /* KLUDGE --- for back-combatibility, we don't have to check ExecCGI * in ScriptAliased directories, which means we need to know if this * request came through ScriptAlias or not... so the Alias module *************** *** 86,91 **** --- 87,264 ---- return t && (!strcmp (t, "cgi-script")); } + /* Configuration stuff */ + + #define DEFAULT_LOGBYTES 10385760 + #define DEFAULT_BUFBYTES 1024 + + typedef struct { + char *logname; + long logbytes; + int bufbytes; + } cgi_server_conf; + + void *create_cgi_config (pool *p, server_rec *s) + { + cgi_server_conf *c = + (cgi_server_conf *)pcalloc (p, sizeof(cgi_server_conf)); + + c->logname = NULL; + c->logbytes = DEFAULT_LOGBYTES; + c->bufbytes = DEFAULT_BUFBYTES; + + return c; + } + + void *merge_cgi_config (pool *p, void *basev, void *overridesv) + { + cgi_server_conf *base = (cgi_server_conf *)basev, + *overrides = (cgi_server_conf *)overrides; + + return overrides->logname ? overrides : base; + } + + char *set_scriptlog (cmd_parms *cmd, void *dummy, char *arg) { + server_rec *s = cmd->server; + cgi_server_conf *conf = + (cgi_server_conf *)get_module_config(s->module_config, &cgi_module); + + conf->logname = arg; + return NULL; + } + + char *set_scriptlog_length (cmd_parms *cmd, void *dummy, char *arg) { + server_rec *s = cmd->server; + cgi_server_conf *conf = + (cgi_server_conf *)get_module_config(s->module_config, &cgi_module); + + conf->logbytes = atol (arg); + return NULL; + } + + char *set_scriptlog_buffer (cmd_parms *cmd, void *dummy, char *arg) { + server_rec *s = cmd->server; + cgi_server_conf *conf = + (cgi_server_conf *)get_module_config(s->module_config, &cgi_module); + + conf->bufbytes = atoi (arg); + return NULL; + } + + command_rec cgi_cmds[] = { + { "ScriptLog", set_scriptlog, NULL, RSRC_CONF, TAKE1, + "the name of a log for script debugging info"}, + { "ScriptLogLength", set_scriptlog_length, NULL, RSRC_CONF, TAKE1, + "the maximum length (in bytes) of the script debug log"}, + { "ScriptLogBuffer", set_scriptlog_buffer, NULL, RSRC_CONF, TAKE1, + "the maximum size (in bytes) to record of a POST request"}, + { NULL} + }; + + int log_scripterror(request_rec *r, cgi_server_conf *conf, int ret, + char *error) + { + FILE *f; + + log_reason(error, r->filename, r); + + if (!conf->logname || + ((stat(server_root_relative(r->pool, conf->logname), &r->finfo) == 0) + && (r->finfo.st_size > conf->logbytes)) || + ((f = pfopen(r->pool, server_root_relative(r->pool, conf->logname), + "a")) == NULL)) { + return ret; + } + + /* "%% [Wed Jun 19 10:53:21 1996] GET /cgi-bin/printenv HTTP/1.0" */ + fprintf(f, "%%%% [%s] %s %s%s%s %s\n", get_time(), r->method, r->uri, + r->args ? "?" : "", r->args ? r->args : "", r->protocol); + /* "%% 500 /usr/local/etc/httpd/cgi-bin */ + fprintf(f, "%%%% %d %s\n", ret, r->filename); + + fprintf(f, "%%error\n%s\n", error); + + pfclose(r->pool, f); + return ret; + } + + int log_script(request_rec *r, cgi_server_conf *conf, int ret, + char *dbuf, char *sbuf, FILE *script_in, FILE *script_err) + { + table *hdrs_arr = r->headers_in; + table_entry *hdrs = (table_entry *)hdrs_arr->elts; + char argsbuffer[HUGE_STRING_LEN]; + FILE *f; + int i; + + if (!conf->logname || + ((stat(server_root_relative(r->pool, conf->logname), &r->finfo) == 0) + && (r->finfo.st_size > conf->logbytes)) || + ((f = pfopen(r->pool, server_root_relative(r->pool, conf->logname), + "a")) == NULL)) { + /* Soak up script output */ + while (fgets(argsbuffer, MAX_STRING_LEN-1, script_in) != NULL) + continue; + while (fgets(argsbuffer, MAX_STRING_LEN-1, script_err) != NULL) + continue; + return ret; + } + + /* "%% [Wed Jun 19 10:53:21 1996] GET /cgi-bin/printenv HTTP/1.0" */ + fprintf(f, "%%%% [%s] %s %s%s%s %s\n", get_time(), r->method, r->uri, + r->args ? "?" : "", r->args ? r->args : "", r->protocol); + /* "%% 500 /usr/local/etc/httpd/cgi-bin */ + fprintf(f, "%%%% %d %s\n", ret, r->filename); + + fputs("%request\n", f); + for (i = 0; i < hdrs_arr->nelts; ++i) { + if (!hdrs[i].key) continue; + fprintf(f, "%s: %s\n", hdrs[i].key, hdrs[i].val); + } + if ((r->method_number == M_POST || r->method_number == M_PUT) + && *dbuf) { + fprintf(f, "\n%s\n", dbuf); + } + + fputs("%response\n", f); + hdrs_arr = r->err_headers_out; + hdrs = (table_entry *)hdrs_arr->elts; + + for (i = 0; i < hdrs_arr->nelts; ++i) { + if (!hdrs[i].key) continue; + fprintf(f, "%s: %s\n", hdrs[i].key, hdrs[i].val); + } + + if (sbuf && *sbuf) + fprintf(f, "%s\n", sbuf); + + *argsbuffer = '\0'; + fgets(argsbuffer, HUGE_STRING_LEN-1, script_in); + if (*argsbuffer) { + fputs("%stdout\n", f); + fputs(argsbuffer, f); + while (fgets(argsbuffer, HUGE_STRING_LEN-1, script_in) != NULL) + fputs(argsbuffer, f); + fputs("\n", f); + } + + *argsbuffer = '\0'; + fgets(argsbuffer, HUGE_STRING_LEN-1, script_err); + if (*argsbuffer) { + fputs("%stderr\n", f); + fputs(argsbuffer, f); + while (fgets(argsbuffer, HUGE_STRING_LEN-1, script_err) != NULL) + fputs(argsbuffer, f); + fputs("\n", f); + } + + pfclose(r->pool, script_in); + pfclose(r->pool, script_err); + + pfclose(r->pool, f); + return ret; + } + /**************************************************************** * * Actual CGI handling... *************** *** 95,100 **** --- 268,274 ---- struct cgi_child_stuff { request_rec *r; int nph; + int debug; char *argv0; }; *************** *** 132,138 **** #endif chdir_file (r->filename); ! error_log2stderr (r->server); #ifndef __EMX__ if (nph) client_to_stdout (r->connection); --- 306,313 ---- #endif chdir_file (r->filename); ! if (!cld->debug) ! error_log2stderr (r->server); #ifndef __EMX__ if (nph) client_to_stdout (r->connection); *************** *** 165,175 **** int cgi_handler (request_rec *r) { ! int retval, nph; ! char *argv0; ! FILE *script_out, *script_in; char argsbuffer[HUGE_STRING_LEN]; int is_included = !strcmp (r->protocol, "INCLUDED"); struct cgi_child_stuff cld; --- 340,353 ---- int cgi_handler (request_rec *r) { ! int retval, nph, dbpos = 0; ! char *argv0, *dbuf = NULL; ! FILE *script_out, *script_in, *script_err; char argsbuffer[HUGE_STRING_LEN]; int is_included = !strcmp (r->protocol, "INCLUDED"); + void *sconf = r->server->module_config; + cgi_server_conf *conf = + (cgi_server_conf *)get_module_config(sconf, &cgi_module); struct cgi_child_stuff cld; *************** *** 185,217 **** else argv0 = r->filename; nph = !(strncmp(argv0,"nph-",4)); - if (!(allow_options (r) & OPT_EXECCGI) && !is_scriptaliased (r)) { - log_reason("Options ExecCGI is off in this directory", r->filename, r); - return FORBIDDEN; - } - if (nph && is_included) { - log_reason("attempt to include NPH CGI script", r->filename, r); - return FORBIDDEN; - } - - if (S_ISDIR(r->finfo.st_mode)) { - log_reason("attempt to invoke directory as script", r->filename, r); - return FORBIDDEN; - } - if (r->finfo.st_mode == 0) { - log_reason("script not found or unable to stat", r->filename, r); - return NOT_FOUND; - } - if(!can_exec(&r->finfo)) { - log_reason("file permissions deny server execution", r->filename, r); - return FORBIDDEN; - } if ((retval = setup_client_block(r))) return retval; add_common_vars (r); cld.argv0 = argv0; cld.r = r; cld.nph = nph; #ifdef __EMX__ if (should_client_block (r)) { --- 363,392 ---- else argv0 = r->filename; nph = !(strncmp(argv0,"nph-",4)); + + if (!(allow_options (r) & OPT_EXECCGI) && !is_scriptaliased (r)) + return log_scripterror(r, conf, FORBIDDEN, + "Options ExecCGI is off in this directory"); + if (nph && is_included) + return log_scripterror(r, conf, FORBIDDEN, + "attempt to include NPH CGI script"); + + if (S_ISDIR(r->finfo.st_mode)) + return log_scripterror(r, conf, FORBIDDEN, + "attempt to invoke directory as script"); + if (r->finfo.st_mode == 0) + return log_scripterror(r, conf, NOT_FOUND, + "script not found or unable to stat"); + if(!can_exec(&r->finfo)) + return log_scripterror(r, conf, FORBIDDEN, + "file permissions deny server execution"); if ((retval = setup_client_block(r))) return retval; add_common_vars (r); cld.argv0 = argv0; cld.r = r; cld.nph = nph; + cld.debug = conf->logname ? 1 : 0; #ifdef __EMX__ if (should_client_block (r)) { *************** *** 234,242 **** } #else ! if (!spawn_child (r->connection->pool, cgi_child, (void *)&cld, ! nph ? just_wait : kill_after_timeout, ! &script_out, nph ? NULL : &script_in)) { log_reason ("couldn't spawn child process", r->filename, r); return SERVER_ERROR; } --- 409,418 ---- } #else ! if (!spawn_child_err (r->connection->pool, cgi_child, (void *)&cld, ! nph ? just_wait : kill_after_timeout, ! &script_out, nph ? NULL : &script_in, ! &script_err)) { log_reason ("couldn't spawn child process", r->filename, r); return SERVER_ERROR; } *************** *** 254,267 **** #ifndef __EMX__ if (should_client_block(r)) { void (*handler)(); ! int len_read; ! hard_timeout ("copy script args", r); handler = signal (SIGPIPE, SIG_IGN); while ((len_read = read_client_block (r, argsbuffer, HUGE_STRING_LEN))) if (fwrite (argsbuffer, 1, len_read, script_out) == 0) break; fflush (script_out); signal (SIGPIPE, handler); --- 430,457 ---- #ifndef __EMX__ if (should_client_block(r)) { void (*handler)(); ! int dbsize, len_read; ! ! if (conf->logname) { ! dbuf = pcalloc(r->pool, conf->bufbytes+1); ! dbpos = 0; ! } ! hard_timeout ("copy script args", r); handler = signal (SIGPIPE, SIG_IGN); while ((len_read = read_client_block (r, argsbuffer, HUGE_STRING_LEN))) + { if (fwrite (argsbuffer, 1, len_read, script_out) == 0) break; + if (conf->logname) { + if ((dbpos + len_read) > conf->bufbytes) + dbsize = conf->bufbytes - dbpos; + else dbsize = len_read; + strncpy(dbuf + dbpos, argsbuffer, dbsize); + dbpos += dbsize; + } + } fflush (script_out); signal (SIGPIPE, handler); *************** *** 274,293 **** /* Handle script return... */ if (script_in && !nph) { ! char *location; int ret; ! if ((ret = scan_script_header(r, script_in))) ! return ret; location = table_get (r->headers_out, "Location"); if (location && location[0] == '/' && r->status == 200) { ! /* Soak up all the script output */ hard_timeout ("read from script", r); while (fgets(argsbuffer, HUGE_STRING_LEN-1, script_in) != NULL) continue; kill_timeout (r); --- 464,485 ---- /* Handle script return... */ if (script_in && !nph) { ! char *location, sbuf[MAX_STRING_LEN]; int ret; ! if ((ret = scan_script_header_err(r, script_in, sbuf))) ! return log_script(r, conf, ret, dbuf, sbuf, script_in, script_err); location = table_get (r->headers_out, "Location"); if (location && location[0] == '/' && r->status == 200) { ! /* Soak up all the script output */ hard_timeout ("read from script", r); while (fgets(argsbuffer, HUGE_STRING_LEN-1, script_in) != NULL) continue; + while (fgets(argsbuffer, HUGE_STRING_LEN-1, script_err) != NULL) + continue; kill_timeout (r); *************** *** 310,317 **** --- 502,513 ---- hard_timeout ("send script output", r); send_http_header(r); if(!r->header_only) send_fd (script_in, r); + /* Soak up stderr */ + while (fgets(argsbuffer, HUGE_STRING_LEN-1, script_err) != NULL) + continue; kill_timeout (r); pfclose (r->connection->pool, script_in); + pfclose (r->connection->pool, script_err); } #ifdef __EMX__ *************** *** 336,346 **** NULL, /* initializer */ NULL, /* dir config creater */ NULL, /* dir merger --- default is to override */ ! NULL, /* server config */ ! NULL, /* merge server config */ ! NULL, /* command table */ cgi_handlers, /* handlers */ ! NULL, /* filename translation */ NULL, /* check_user_id */ NULL, /* check auth */ NULL, /* check access */ --- 532,542 ---- NULL, /* initializer */ NULL, /* dir config creater */ NULL, /* dir merger --- default is to override */ ! create_cgi_config, /* server config */ ! merge_cgi_config, /* merge server config */ ! cgi_cmds, /* command table */ cgi_handlers, /* handlers */ ! NULL, /* filename translation */ NULL, /* check_user_id */ NULL, /* check auth */ NULL, /* check access */ Index: util_script.c =================================================================== RCS file: /export/home/cvs/apache/src/util_script.c,v retrieving revision 1.16 diff -c -r1.16 util_script.c *** util_script.c 1996/08/02 20:39:16 1.16 --- util_script.c 1996/08/02 23:41:23 *************** *** 243,254 **** } } ! int scan_script_header(request_rec *r, FILE *f) { ! char w[MAX_STRING_LEN]; ! char *l; int p; hard_timeout ("read script header", r); while(1) { --- 243,257 ---- } } ! int scan_script_header_err(request_rec *r, FILE *f, char *buffer) { ! char x[MAX_STRING_LEN]; ! char *w, *l; int p; + if (buffer) *buffer = '\0'; + w = buffer ? buffer : x; + hard_timeout ("read script header", r); while(1) { *************** *** 278,286 **** char malformed[(sizeof MALFORMED_MESSAGE)+1+MALFORMED_HEADER_LENGTH_TO_SHOW]; strcpy(malformed, MALFORMED_MESSAGE); strncat(malformed, w, MALFORMED_HEADER_LENGTH_TO_SHOW); ! /* Soak up all the script output --- may save an outright kill */ ! while (fgets(w, MAX_STRING_LEN-1, f) != NULL) ! continue; kill_timeout (r); log_reason (malformed, r->filename, r); --- 281,291 ---- char malformed[(sizeof MALFORMED_MESSAGE)+1+MALFORMED_HEADER_LENGTH_TO_SHOW]; strcpy(malformed, MALFORMED_MESSAGE); strncat(malformed, w, MALFORMED_HEADER_LENGTH_TO_SHOW); ! ! if (!buffer) ! /* Soak up all the script output --- may save an outright kill */ ! while (fgets(w, MAX_STRING_LEN-1, f) != NULL) ! continue; kill_timeout (r); log_reason (malformed, r->filename, r); Index: util_script.h =================================================================== RCS file: /export/home/cvs/apache/src/util_script.h,v retrieving revision 1.4 diff -c -r1.4 util_script.h *** util_script.h 1996/07/21 20:03:46 1.4 --- util_script.h 1996/08/02 23:41:23 *************** *** 59,65 **** char **create_environment(pool *p, table *t); void add_cgi_vars(request_rec *r); void add_common_vars(request_rec *r); ! int scan_script_header(request_rec *r, FILE *f); void send_size(size_t size, request_rec *r); void call_exec (request_rec *r, char *argv0, char **env, int shellcmd); --- 59,66 ---- char **create_environment(pool *p, table *t); void add_cgi_vars(request_rec *r); void add_common_vars(request_rec *r); ! #define scan_script_header(a1,a2) scan_script_header_err(a1,a2,NULL) ! int scan_script_header_err(request_rec *r, FILE *f, char *buffer); void send_size(size_t size, request_rec *r); void call_exec (request_rec *r, char *argv0, char **env, int shellcmd); -- Alexei Kosut The Apache HTTP Server http://www.nueva.pvt.k12.ca.us/~akosut/ http://www.apache.org/