Re: Why doesn't Apache/Stronghold like Linux 2.0.x?

Adam D. Bradley (bradley@cs.unca.edu)
Tue, 10 Dec 1996 14:26:44 -0500 (EST)


> I've run Stronghold 1.3.2 for a long time without problems; I'm at 2.1.7
> now on the Web server. I've never seen the runaway daemon problem, though
> I've heard others have.

Do you allow inline CGI?

> > In the continuing saga of those of us plauged by problems with running
> > Apache 1.1.1 (or, in my case, Stronghold 1.3.2 -- same thing but with SSL
> > support), I'm having some damned strange problems since I went up to
> > 2.0.26/27. This problem predates my use of Stronghold (I was having it
> > back when I ran plain vanilla Apache 1.1.1), so i don't think it's related
> > to Stronghold.
> >
> > Originally, i was having the problem many others were having -- I would
> > end up with httpd processes stuck in the R state, eating up huge amounts
> > .....

We run NCSA httpd on a Digital Unix 4.0 machine as our department web
server, and I've been tracking a _very_ similar bug there. Very
particular conditions: an inline CGI script is started, but before it
completes, the connection is closed. httpd terms/kills it (SIGTERM, wait
a few secs, SIGKILL). There will, on on eof the next two requests, be
some sort of string handling error, leading to a SEGV (actually caused by
something in getpwnam() call !?!?)...the httpd then spins somewhere in the
shutdown routine started by the SEGV handler.

I implemented a "request_log" in NCSA httpd that tracks incoming requests
_before_ they are handled (access_log is updated _after_), this has helped
in diagnosing the prob. I also added a "PID:" field to the logs, this
helps in figuring out which error_log messages are associated with the
"spinning" httpd.

Anyway, I get the feeling this is a prob w/ NCSA/Apache handling of inline
CGI, but haven't had enough time to decipher their code (they use that
awful 2-space emacs indentation...bleh!). Either a string-handling or a
signal-handling issue, coupled perhaps w/ a subtle libc or syscall bug.
Perhaps I'll be able to attack the prob a little more aggressively over
Christmas break....

Patch attached, applies cleanly to NCSA httpd 1.5.2, untested against
apache (but it is derivative, so it shouldn't be _too_ hard to adapt...)

Adam

--
He feeds on ashes; a deluded mind has led him    Adam Bradley, UNCA Senior
astray, and he cannot deliver himself or say,             Computer Science
"Is there not a lie in my right hand?"   Isaiah 44:20
        bradley@cs.unca.edu       http://www.cs.unca.edu/~bradley      <><

diff -c src/config.h src.beta/config.h *** src/config.h Tue Nov 12 13:12:38 1996 --- src.beta/config.h Mon Nov 11 17:25:14 1996 *************** *** 166,171 **** --- 166,172 ---- #define DEFAULT_REFERERLOG "logs/referer_log" #define DEFAULT_ERRORLOG "logs/error_log" #define DEFAULT_PIDLOG "logs/httpd.pid" + #define DEFAULT_REQUESTLOG "logs/request_log" #define DEFAULT_REFERERIGNORE "" diff -c src/constants.h src.beta/constants.h *** src/constants.h Tue Nov 12 13:12:38 1996 --- src.beta/constants.h Mon Nov 11 15:51:56 1996 *************** *** 289,294 **** --- 289,295 ---- int httpd_conf; char *error_fname; char *xfer_fname; + char *request_fname; char *agent_fname; char *referer_fname; char *referer_ignore; *************** *** 304,309 **** --- 305,311 ---- FILE *agent_log; FILE *referer_log; int xfer_log; + int request_log; int virtualhost; char *called_hostname; diff -c src/host_config.c src.beta/host_config.c *** src/host_config.c Tue Nov 12 13:12:41 1996 --- src.beta/host_config.c Mon Nov 11 17:40:17 1996 *************** *** 55,60 **** --- 55,61 ---- } newInfo->error_fname = hostInfo->error_fname; newInfo->xfer_fname = hostInfo->xfer_fname; + newInfo->request_fname = hostInfo->request_fname; newInfo->agent_fname = hostInfo->agent_fname; newInfo->referer_fname = hostInfo->referer_fname; newInfo->referer_ignore = hostInfo->referer_ignore; *************** *** 69,74 **** --- 70,76 ---- newInfo->agent_log = hostInfo->agent_log; newInfo->referer_log = hostInfo->referer_log; newInfo->xfer_log = hostInfo->xfer_log; + newInfo->request_log = hostInfo->request_log; newInfo->user_dir = hostInfo->user_dir; newInfo->index_names = hostInfo->index_names; *************** *** 105,110 **** --- 107,113 ---- close_logs(host); if (host->httpd_conf & HC_ERROR_FNAME) free(host->error_fname); if (host->httpd_conf & HC_XFER_FNAME) free(host->xfer_fname); + if (host->httpd_conf & HC_REQUEST_FNAME) free(host->request_fname); if (host->httpd_conf & HC_AGENT_FNAME) free(host->agent_fname); if (host->httpd_conf & HC_REFERER_FNAME) free(host->referer_fname); if (host->httpd_conf & HC_REFERER_IGNORE) free(host->referer_ignore); *************** *** 165,170 **** --- 168,178 ---- if (hostInfo->httpd_conf & option) free(hostInfo->xfer_fname); hostInfo->xfer_fname = tmp; + break; + case HC_REQUEST_FNAME: + if (hostInfo->httpd_conf & option) + free(hostInfo->request_fname); + hostInfo->request_fname = tmp; break; case HC_AGENT_FNAME: if (hostInfo->httpd_conf & option) diff -c src/host_config.h src.beta/host_config.h *** src/host_config.h Tue Nov 12 13:12:42 1996 --- src.beta/host_config.h Mon Nov 11 15:45:51 1996 *************** *** 34,39 **** --- 34,40 ---- #define HC_SERVER_ADMIN 128 #define HC_SERVER_HOSTNAME 256 #define HC_SRM_CONFNAME 512 + #define HC_REQUEST_FNAME 1024 #define HC_ANNOT_SERVER 4096 /* SRM_CONF OPTS */ diff -c src/http_config.c src.beta/http_config.c *** src/http_config.c Tue Nov 12 13:12:44 1996 --- src.beta/http_config.c Tue Nov 12 13:11:51 1996 *************** *** 132,137 **** --- 132,140 ---- make_full_path(server_root,DEFAULT_ERRORLOG,tmp); set_host_conf(host,PH_HTTPD_CONF,HC_ERROR_FNAME,tmp); + make_full_path(server_root,DEFAULT_REQUESTLOG,tmp); + set_host_conf(host,PH_HTTPD_CONF,HC_REQUEST_FNAME,tmp); + make_full_path(server_root,DEFAULT_XFERLOG,tmp); set_host_conf(host,PH_HTTPD_CONF,HC_XFER_FNAME,tmp); strcpy(core_dir,server_root); *************** *** 287,292 **** --- 290,297 ---- strcpy(core_dir,w); make_full_path(server_root,DEFAULT_ERRORLOG,tmp); set_host_conf(host,PH_HTTPD_CONF,HC_ERROR_FNAME,tmp); + make_full_path(server_root,DEFAULT_REQUESTLOG,tmp); + set_host_conf(host,PH_HTTPD_CONF,HC_REQUEST_FNAME,tmp); make_full_path(server_root,DEFAULT_XFERLOG,tmp); set_host_conf(host,PH_HTTPD_CONF,HC_XFER_FNAME,tmp); make_full_path(server_root,DEFAULT_AGENTLOG,tmp); *************** *** 315,320 **** --- 320,332 ---- make_full_path(server_root,w,tmp); else strcpy(tmp,w); set_host_conf(host,PH_HTTPD_CONF,HC_XFER_FNAME,tmp); + } + else if(!strcasecmp(w,"RequestLog")) { + cfg_getword(w,l); + if(w[0] != '/') + make_full_path(server_root,w,tmp); + else strcpy(tmp,w); + set_host_conf(host,PH_HTTPD_CONF,HC_REQUEST_FNAME,tmp); } else if(!strcasecmp(w,"AgentLog")) { cfg_getword(w,l); diff -c src/http_log.c src.beta/http_log.c *** src/http_log.c Tue Nov 12 13:12:47 1996 --- src.beta/http_log.c Tue Nov 12 13:05:01 1996 *************** *** 71,76 **** --- 71,78 ---- static int xfer_flags = ( O_WRONLY | O_APPEND | O_CREAT ); static mode_t xfer_mode = ( S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH ); + static int request_flags = ( O_WRONLY | O_APPEND | O_CREAT ); + static mode_t request_mode = ( S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH ); void open_logs(per_host *host) { #ifdef SECURE_LOGS *************** *** 85,90 **** --- 87,100 ---- exit(1); } } + if (host->httpd_conf & HC_REQUEST_FNAME) { + if((host->request_log = open_logfile(host->request_fname,request_flags,request_mode)) < 0) { + fprintf(stderr,"HTTPd: could not open request log file %s.\n", + host->request_fname); + perror("open"); + exit(1); + } + } if (host->httpd_conf & HC_XFER_FNAME) { if((host->xfer_log = open_logfile(host->xfer_fname,xfer_flags, xfer_mode)) < 0) { fprintf(stderr,"HTTPd: could not open transfer log file %s.\n", *************** *** 142,147 **** --- 152,160 ---- fflush(host->referer_log); fclose(host->referer_log); } + if (host->httpd_conf & HC_REQUEST_FNAME) { + close(host->request_log); + } if (host->httpd_conf & HC_XFER_FNAME) { close(host->xfer_log); } *************** *** 167,174 **** extern int num_children; ! void log_transaction(per_request *reqInfo) { char *str; long timz; struct tm *t; --- 180,201 ---- extern int num_children; ! #define FLAG_LOG_XACTION 1 ! #define FLAG_LOG_REQUEST 2 ! ! void log_transaction(per_request *reqInfo) /* ADB */ ! { ! do_log_transaction(reqInfo,FLAG_LOG_XACTION); ! } ! ! void log_request(per_request *reqInfo) /* ADB */ { + do_log_transaction(reqInfo,FLAG_LOG_REQUEST); + } + + void do_log_transaction(per_request *reqInfo, int logclass) + { + int logfd; /* ADB */ char *str; long timz; struct tm *t; *************** *** 178,194 **** time_t duration = request_time ? (time(NULL) - request_time) : 0; #endif /* LOG_DURATION */ str = newString(HUGE_STRING_LEN,STR_TMP); tstr = newString(MAX_STRING_LEN,STR_TMP); - t = get_gmtoff(&timz); sign = (timz < 0 ? '-' : '+'); if(timz < 0) timz = -timz; strftime(tstr,MAX_STRING_LEN,"%d/%b/%Y:%H:%M:%S",t); sprintf(str,"%s %s %s [%s %c%02ld%02d] \"%s\" ", (reqInfo->remote_name ? reqInfo->remote_name : "-"), (do_rfc931 ? remote_logname : "-"), (reqInfo->auth_user[0] ? reqInfo->auth_user : "-"), --- 205,235 ---- time_t duration = request_time ? (time(NULL) - request_time) : 0; #endif /* LOG_DURATION */ + switch(logclass) { /* ADB */ + case FLAG_LOG_XACTION: + logfd = reqInfo->hostInfo->xfer_log; + break; + case FLAG_LOG_REQUEST: + logfd = reqInfo->hostInfo->request_log; + break; + default: + return; + } + str = newString(HUGE_STRING_LEN,STR_TMP); tstr = newString(MAX_STRING_LEN,STR_TMP); t = get_gmtoff(&timz); sign = (timz < 0 ? '-' : '+'); if(timz < 0) timz = -timz; strftime(tstr,MAX_STRING_LEN,"%d/%b/%Y:%H:%M:%S",t); + #ifndef LOGPID sprintf(str,"%s %s %s [%s %c%02ld%02d] \"%s\" ", + #else + sprintf(str,"%s %s %s [%s %c%02ld%02d] \"%s\" PID:%d ", + #endif (reqInfo->remote_name ? reqInfo->remote_name : "-"), (do_rfc931 ? remote_logname : "-"), (reqInfo->auth_user[0] ? reqInfo->auth_user : "-"), *************** *** 196,211 **** sign, timz/3600, timz%3600, ! the_request); if(reqInfo->status != -1) sprintf(str,"%s%d ",str,reqInfo->status); else strcat(str,"- "); ! if(reqInfo->bytes_sent != -1) sprintf(str,"%s%ld",str,reqInfo->bytes_sent); ! else strcat(str,"-"); if (reqInfo->hostInfo->log_opts & LOG_SERVERNAME) { if (reqInfo->hostInfo->server_hostname) sprintf(str,"%s %s",str,reqInfo->hostInfo->server_hostname); --- 237,260 ---- sign, timz/3600, timz%3600, ! #ifdef LOGPID ! the_request, ! getpid()); ! #else ! the_request); ! #endif ! if(reqInfo->status != -1) sprintf(str,"%s%d ",str,reqInfo->status); else strcat(str,"- "); ! if(logclass != FLAG_LOG_REQUEST) { ! if(reqInfo->bytes_sent != -1) sprintf(str,"%s%ld",str,reqInfo->bytes_sent); ! else strcat(str,"-"); + } if (reqInfo->hostInfo->log_opts & LOG_SERVERNAME) { if (reqInfo->hostInfo->server_hostname) sprintf(str,"%s %s",str,reqInfo->hostInfo->server_hostname); *************** *** 240,265 **** if (!(reqInfo->hostInfo->log_opts & LOG_COMBINED)) { strcat(str,"\n"); ! write(reqInfo->hostInfo->xfer_log,str,strlen(str)); ! /* log the user agent */ ! if (reqInfo->inh_agent[0]) { ! if (reqInfo->hostInfo->log_opts & LOG_DATE) ! fprintf(reqInfo->hostInfo->agent_log, "[%s] %s\n",tstr, ! reqInfo->inh_agent); ! else ! fprintf(reqInfo->hostInfo->agent_log, "%s\n", reqInfo->inh_agent); ! fflush(reqInfo->hostInfo->agent_log); ! } ! /* log the referer */ ! if (reqInfo->inh_referer[0]) { ! if (reqInfo->hostInfo->log_opts & LOG_DATE) ! fprintf(reqInfo->hostInfo->referer_log, "[%s] %s -> %s\n",tstr, reqInfo->inh_referer, reqInfo->url); ! else ! fprintf(reqInfo->hostInfo->referer_log, "%s -> %s\n", ! reqInfo->inh_referer, reqInfo->url); ! fflush(reqInfo->hostInfo->referer_log); } } else { if (reqInfo->inh_referer[0]) --- 289,316 ---- if (!(reqInfo->hostInfo->log_opts & LOG_COMBINED)) { strcat(str,"\n"); ! write(logfd,str,strlen(str)); ! if (logclass == FLAG_LOG_XACTION) { ! /* log the user agent */ ! if (reqInfo->inh_agent[0]) { ! if (reqInfo->hostInfo->log_opts & LOG_DATE) ! fprintf(reqInfo->hostInfo->agent_log, "[%s] %s\n",tstr, ! reqInfo->inh_agent); ! else ! fprintf(reqInfo->hostInfo->agent_log, "%s\n", reqInfo->inh_agent); ! fflush(reqInfo->hostInfo->agent_log); ! } ! /* log the referer */ ! if (reqInfo->inh_referer[0]) { ! if (reqInfo->hostInfo->log_opts & LOG_DATE) ! fprintf(reqInfo->hostInfo->referer_log, "[%s] %s -> %s\n",tstr, reqInfo->inh_referer, reqInfo->url); ! else ! fprintf(reqInfo->hostInfo->referer_log, "%s -> %s\n", ! reqInfo->inh_referer, reqInfo->url); ! fflush(reqInfo->hostInfo->referer_log); ! } } } else { if (reqInfo->inh_referer[0]) *************** *** 270,283 **** sprintf(str,"%s \"%s\"\n",str,reqInfo->inh_agent); else strcat(str," \"\"\n"); ! write(reqInfo->hostInfo->xfer_log,str,strlen(str)); } freeString(str); freeString(tstr); } void log_error(char *err, FILE *fp) { fprintf(fp, "[%s] %s\n",get_time(),err); fflush(fp); } --- 321,338 ---- sprintf(str,"%s \"%s\"\n",str,reqInfo->inh_agent); else strcat(str," \"\"\n"); ! write(logfd,str,strlen(str)); } freeString(str); freeString(tstr); } void log_error(char *err, FILE *fp) { + #ifdef LOGPID + fprintf(fp, "[%s] %s PID:%d\n",get_time(),err,getpid()); + #else fprintf(fp, "[%s] %s\n",get_time(),err); + #endif fflush(fp); } diff -c src/http_log.h src.beta/http_log.h *** src/http_log.h Tue Nov 12 13:12:48 1996 --- src.beta/http_log.h Mon Nov 11 15:35:09 1996 *************** *** 28,33 **** --- 28,36 ---- /* constants used in this module */ + /* If you want PID's logged in request/error/access-log files, define: */ + #define LOGPID 1 + #define LOG_NONE 0 #define LOG_COMBINED 1 #define LOG_SEPARATE ~(LOG_COMBINED) *************** *** 62,68 **** --- 65,73 ---- void log_pid(void); void log_error(char *err, FILE *fp); void log_reason(per_request *reqInfo, char *reason, char *file); + void log_request(per_request *reqInfo); void log_transaction(per_request *reqInfo); + void do_log_transaction(per_request *reqInfo, int logClass); void open_logs(per_host *host); void close_logs(per_host *host); void error_log2stderr(FILE *error_log); diff -c src/http_request.c src.beta/http_request.c *** src/http_request.c Tue Nov 12 13:12:49 1996 --- src.beta/http_request.c Tue Nov 12 13:00:40 1996 *************** *** 643,648 **** --- 643,649 ---- get_remote_host(reqInfo); } + log_request(reqInfo); process_request(reqInfo); }