Check-in [273835a798]
Overview
Comment:Updated to generate log entry only after transfer completes
Downloads: Tarball | ZIP archive | SQL archive
Timelines: family | ancestors | descendants | both | trunk
Files: files | file ages | folders
SHA1:273835a798634c328b5ddb0997ec0564ff7f1c28
User & Date: rkeene on 2014-02-11 04:26:18
Other Links: manifest | tags
Context
2014-02-11
04:32
Whitespace fix check-in: bbd721a8cc user: rkeene tags: trunk
04:26
Updated to generate log entry only after transfer completes check-in: 273835a798 user: rkeene tags: trunk
2014-02-08
08:52
Updated to log message at startup check-in: 0802341b53 user: rkeene tags: trunk
Changes

Modified filed.c from [5335f1802e] to [1d3989ed81].

    20     20   #include <pwd.h>
    21     21   
    22     22   /* Compile time constants */
    23     23   #define FILED_VERSION "1.1"
    24     24   #define FILED_SENDFILE_MAX 16777215
    25     25   #define FILED_MAX_FAILURE_COUNT 30
    26     26   #define FILED_DEFAULT_TYPE "application/octet-stream"
           27  +#define FILED_PATH_BUFFER_SIZE 1010
    27     28   
    28     29   /* Default values */
    29     30   #define PORT 80
    30     31   #define THREAD_COUNT 5
    31     32   #define BIND_ADDR "::"
    32     33   #define CACHE_SIZE 8209
    33     34   #define LOG_FILE "-"
................................................................................
    53     54   	const char *type;
    54     55   };
    55     56   
    56     57   /* Request variables */
    57     58   struct filed_http_request {
    58     59   	/** Buffers **/
    59     60   	struct filed_fileinfo fileinfo;
    60         -	char path_b[1010];
           61  +	char path_b[FILED_PATH_BUFFER_SIZE];
    61     62   	char tmpbuf[1010];
    62     63   
    63     64   	/** HTTP Request information **/
    64     65   	char *path;     /*** Path being requested ***/
    65     66   
    66     67   	struct {
    67     68   		struct {
................................................................................
    70     71   			off_t length;   /*** Range length ***/
    71     72   		} range;
    72     73   	} headers;
    73     74   };
    74     75   
    75     76   /* Log record */
    76     77   struct filed_log_entry {
           78  +	/* Type of log entry */
           79  +	enum {
           80  +		FILED_LOG_TYPE_MESSAGE,
           81  +		FILED_LOG_TYPE_TRANSFER
           82  +	} type;
           83  +
           84  +	/* Linked list head/tail */
    77     85   	struct filed_log_entry *_next;
    78     86   	struct filed_log_entry *_prev;
           87  +
           88  +	/* Thread from which this log entry eminates */
    79     89   	pthread_t thread;
    80         -	char buffer[1010];
    81         -	int level;
           90  +
           91  +	/* Message buffer for type = MESSAGE */
           92  +	/* Path buffer for type = TRANSFER */
           93  +	char buffer[FILED_PATH_BUFFER_SIZE];
           94  +
           95  +	/* Items for type = TRANSFER */
           96  +	int http_code;
           97  +	const char *reason;
           98  +	time_t starttime;
           99  +	time_t endtime;
          100  +	off_t req_offset;
          101  +	off_t req_length;
          102  +	off_t sent_length;
          103  +	off_t file_length;
          104  +	char ip[128];
          105  +	int port;
    82    106   };
    83    107   
    84    108   /* Global variables */
    85    109   /** Open File cache **/
    86    110   struct filed_fileinfo *filed_fileinfo_fdcache = NULL;
    87    111   unsigned int filed_fileinfo_fdcache_size = 0;
    88    112   
................................................................................
   202    226   	}
   203    227   
   204    228   	return(fd);
   205    229   }
   206    230   
   207    231   /* Log a message */
   208    232   #ifdef FILED_DONT_LOG
          233  +struct filed_log_entry filed_dummy_log_entry;
   209    234   #  define filed_logging_thread_init(x) 0
   210    235   #  define filed_log_msg_debug(x, ...) /**/
   211    236   #  define filed_log_msg(x, ...) /**/
   212         -#  define filed_log_ip(x, ...) "<unknown>"
          237  +#  define filed_log_entry(x) /**/
          238  +#  define filed_log_ip(x, ...) NULL
          239  +#  define filed_log_new(x) &filed_dummy_log_entry
   213    240   #else
   214    241   #ifdef FILED_DEBUG
   215    242   #  define filed_log_msg_debug(x, ...) { fprintf(stderr, x, __VA_ARGS__); fprintf(stderr, "\n"); fflush(stderr); }
   216    243   #else
   217    244   #  define filed_log_msg_debug(x, ...) /**/
   218    245   #endif
   219    246   
................................................................................
   244    271   			curr->_prev = prev;
   245    272   
   246    273   			prev = curr;
   247    274   		}
   248    275   
   249    276   		curr = prev;
   250    277   		while (curr) {
   251         -			fprintf(fp, "%s THREAD=%llu TIME=%llu\n",
   252         -				curr->buffer,
          278  +			switch (curr->type) {
          279  +				case FILED_LOG_TYPE_MESSAGE:
          280  +					fprintf(fp, "%s", curr->buffer);
          281  +
          282  +					break;
          283  +				case FILED_LOG_TYPE_TRANSFER:
          284  +					if (curr->endtime == ((time_t) -1)) {
          285  +						curr->endtime = now;
          286  +					}
          287  +
          288  +					fprintf(fp, "TRANSFER PATH=%s SRC=%s:%i TIME.START=%llu TIME.END=%llu CODE.VALUE=%u CODE.REASON=%s REQUEST.OFFSET=%llu REQUEST.LENGTH=%llu FILE.LENGTH=%llu TRANSFER.LENGTH=%llu",
          289  +						curr->buffer,
          290  +						curr->ip, curr->port,
          291  +						(unsigned long long) curr->starttime,
          292  +						(unsigned long long) curr->endtime,
          293  +						curr->http_code, curr->reason,
          294  +						(unsigned long long) curr->req_offset,
          295  +						(unsigned long long) curr->req_length,
          296  +						(unsigned long long) curr->file_length,
          297  +						(unsigned long long) curr->sent_length
          298  +					);
          299  +
          300  +					break;
          301  +			}
          302  +			fprintf(fp, " THREAD=%llu TIME=%llu\n",
   253    303   				(unsigned long long) curr->thread,
   254    304   				(unsigned long long) now
   255    305   			);
   256    306   			fflush(fp);
   257    307   
   258    308   			prev = curr;
   259    309   			curr = curr->_prev;
................................................................................
   261    311   			free(prev);
   262    312   		}
   263    313   	}
   264    314   
   265    315   	return(NULL);
   266    316   }
   267    317   
   268         -static void filed_log_msg(const char *fmt, ...) {
   269         -	struct filed_log_entry *entry;
   270         -	va_list args;
   271         -
   272         -	entry = malloc(sizeof(*entry));
   273         -
   274         -	va_start(args, fmt);
   275         -
   276         -	vsnprintf(entry->buffer, sizeof(entry->buffer), fmt, args);
   277         -
   278         -	va_end(args);
   279         -
          318  +static void filed_log_entry(struct filed_log_entry *entry) {
   280    319   	entry->thread = pthread_self();
   281         -	entry->level = 0;
   282    320   
   283    321   	pthread_mutex_lock(&filed_log_msg_list_mutex);
   284    322   
   285    323   	entry->_next = filed_log_msg_list;
   286    324   	filed_log_msg_list = entry;
   287    325   
   288    326   	pthread_mutex_unlock(&filed_log_msg_list_mutex);
   289    327   
   290    328   	pthread_cond_signal(&filed_log_msg_list_ready);
   291    329   
          330  +	return;
          331  +}
          332  +
          333  +static struct filed_log_entry *filed_log_new(int initialize) {
          334  +	struct filed_log_entry *retval;
          335  +
          336  +	retval = malloc(sizeof(*retval));
          337  +
          338  +	if (initialize) {
          339  +		retval->buffer[0] = '\0';
          340  +		retval->http_code = -1;
          341  +		retval->starttime = 0;
          342  +		retval->endtime = 0;
          343  +		retval->req_offset = 0;
          344  +		retval->req_length = 0;
          345  +		retval->sent_length = 0;
          346  +		retval->file_length = 0;
          347  +		retval->ip[0] = '\0';
          348  +		retval->port = -1;
          349  +	}
          350  +
          351  +	return(retval);
          352  +}
          353  +
          354  +static void filed_log_msg(const char *fmt, ...) {
          355  +	struct filed_log_entry *entry;
          356  +	va_list args;
          357  +
          358  +	entry = filed_log_new(0);
          359  +
          360  +	va_start(args, fmt);
          361  +
          362  +	vsnprintf(entry->buffer, sizeof(entry->buffer), fmt, args);
          363  +
          364  +	va_end(args);
          365  +
          366  +	entry->type = FILED_LOG_TYPE_MESSAGE;
          367  +
          368  +	filed_log_entry(entry);
          369  +
   292    370   	return;
   293    371   }
   294    372   
   295    373   static const char *filed_log_ip(struct sockaddr *addr, char *buffer, size_t bufferlen) {
   296    374   	struct sockaddr_in *addr_v4;
   297    375   	struct sockaddr_in6 *addr_v6;
   298    376   	const char *retval = NULL;
................................................................................
   305    383   			retval = inet_ntop(AF_INET, &addr_v4->sin_addr, buffer, bufferlen);
   306    384   			break;
   307    385   		case AF_INET6:
   308    386   			retval = inet_ntop(AF_INET6, &addr_v6->sin6_addr, buffer, bufferlen);
   309    387   			break;
   310    388   	}
   311    389   
   312         -	if (retval == NULL) {
   313         -		retval = "<unknown>";
   314         -	}
   315         -
   316    390   	return(retval);
   317    391   }
   318    392   
   319    393   static int filed_logging_thread_init(FILE *logfp) {
   320    394   	struct filed_logging_thread_args *args;
   321    395   	pthread_t thread_id;
   322    396   
................................................................................
   502    576   
   503    577   	buffer = buffer_st->path_b;
   504    578   	buffer_len = sizeof(buffer_st->path_b);
   505    579   
   506    580   	tmpbuffer = buffer_st->tmpbuf;
   507    581   	tmpbuffer_len = sizeof(buffer_st->tmpbuf);
   508    582   
   509         -	filed_log_msg("WAIT_FOR_REQUEST FD=%i", fd);
   510         -
   511    583   	fgets(buffer, buffer_len, fp);
   512    584   
   513    585   	method = buffer;
   514    586   
   515    587   	buffer = strchr(buffer, ' ');
   516    588   	if (buffer == NULL) {
   517         -		filed_log_msg("GOT_REQUEST FD=%i ERROR=format", fd);
   518         -
   519    589   		return(NULL);
   520    590   	}
   521    591   
   522    592   	*buffer = '\0';
   523    593   	buffer++;
   524    594   
   525    595   	path = buffer;
................................................................................
   526    596   
   527    597   	buffer = strchr(buffer, ' ');
   528    598   	if (buffer != NULL) {
   529    599   		*buffer = '\0';
   530    600   		buffer++;
   531    601   	}
   532    602   
   533         -	filed_log_msg("GOT_REQUEST FD=%i PATH=%s", fd, path);
   534         -
   535         -	filed_log_msg("WAIT_FOR_HEADERS FD=%i", fd);
   536         -
   537    603   	for (i = 0; i < 100; i++) {
   538    604   		fgets(tmpbuffer, tmpbuffer_len, fp);
   539    605   
   540    606   		if (strncasecmp(tmpbuffer, "Range: ", 7) == 0) {
   541    607   			workbuffer = tmpbuffer + 7;
   542    608   
   543    609   			if (strncasecmp(workbuffer, "bytes=", 6) == 0) {
................................................................................
   560    626   		}
   561    627   
   562    628   		if (memcmp(tmpbuffer, "\r\n", 2) == 0) {
   563    629   			break;
   564    630   		}
   565    631   	}
   566    632   
   567         -	filed_log_msg("GOT_HEADERS FD=%i", fd);
   568         -
   569    633   	/* We only handle the "GET" method */
   570    634   	if (strcasecmp(method, "get") != 0) {
   571    635   		return(NULL);
   572    636   	}
   573    637   
   574    638   	/* Determine range */
   575    639   	if (range_end != 0) {
................................................................................
   609    673   		(unsigned long long) strlen(error_string),
   610    674   		"text/html",
   611    675   		error_string
   612    676   	);
   613    677   }
   614    678   
   615    679   /* Handle a single request from a client */
   616         -static void filed_handle_client(int fd, struct filed_http_request *request) {
          680  +static void filed_handle_client(int fd, struct filed_http_request *request, struct filed_log_entry *log) {
   617    681   	struct filed_fileinfo *fileinfo;
   618    682   	ssize_t sendfile_ret;
   619    683   	size_t sendfile_size;
   620    684   	off_t sendfile_offset, sendfile_sent, sendfile_len;
   621    685   	char *path;
   622    686   	char *date_current, date_current_b[64];
   623    687   	int http_code;
................................................................................
   635    699   	}
   636    700   
   637    701   	request = filed_get_http_request(fp, request);
   638    702   
   639    703   	if (request == NULL || request->path == NULL) {
   640    704   		filed_error_page(fp, date_current, 500);
   641    705   
   642         -		filed_log_msg("INVALID_REQUEST FD=%i ERROR=500", fd);
          706  +		log->buffer[0] = '\0';
          707  +		log->http_code = 500;
          708  +		log->reason = "format";
          709  +
          710  +		filed_log_entry(log);
   643    711   
   644    712   		fclose(fp);
   645    713   
   646    714   		return;
   647    715   	}
   648    716   
   649         -	if (request->headers.range.present) {
   650         -		filed_log_msg("PROCESS_REPLY_START FD=%i PATH=%s RANGE_START=%llu RANGE_LENGTH=%lli",
   651         -			fd,
   652         -			request->path,
   653         -			(unsigned long long) request->headers.range.offset,
   654         -			(long long) request->headers.range.length
   655         -		);
   656         -	} else {
   657         -		filed_log_msg("PROCESS_REPLY_START FD=%i PATH=%s", fd, request->path);
   658         -	}
   659         -
   660    717   	path = request->path;
          718  +	strcpy(log->buffer, path);
   661    719   
   662    720   	http_code = -1;
   663    721   
   664    722   	fileinfo = filed_open_file(path, &request->fileinfo);
   665    723   	if (fileinfo == NULL) {
   666    724   		filed_error_page(fp, date_current, 404);
   667    725   
   668         -		filed_log_msg("PROCESS_REPLY_COMPLETE FD=%i ERROR=404", fd);
          726  +		log->http_code = 404;
          727  +		log->reason = "open_failed";
          728  +
          729  +		filed_log_entry(log);
   669    730   	} else {
   670    731   		if (request->headers.range.offset != 0 || request->headers.range.length >= 0) {
   671    732   			if (request->headers.range.offset >= fileinfo->len) {
   672         -				filed_log_msg("PROCESS_REPLY_COMPLETE FD=%i ERROR=416", fd);
   673         -
   674    733   				filed_error_page(fp, date_current, 416);
          734  +
          735  +				log->http_code = 416;
          736  +				log->reason = "range_invalid";
          737  +
          738  +				filed_log_entry(log);
   675    739   			} else {
   676    740   				if (request->headers.range.length == ((off_t) -1)) {
   677    741   					filed_log_msg_debug("Computing length to fit in bounds: fileinfo->len = %llu, request->headers.range.offset = %llu",
   678    742   						(unsigned long long) fileinfo->len,
   679    743   						(unsigned long long) request->headers.range.offset
   680    744   					);
   681    745   
................................................................................
   713    777   					(unsigned long long) (request->headers.range.offset + request->headers.range.length - 1),
   714    778   					(unsigned long long) fileinfo->len
   715    779   				);
   716    780   			}
   717    781   			fprintf(fp, "\r\n");
   718    782   			fflush(fp);
   719    783   
   720         -			filed_log_msg("PROCESS_REPLY_COMPLETE FD=%i STATUS=%i", fd, http_code);
          784  +			log->http_code = http_code;
          785  +			log->reason = "OK";
          786  +			log->starttime = time(NULL);
          787  +			log->req_offset = request->headers.range.offset;
          788  +			log->req_length = request->headers.range.length;
          789  +			log->file_length = fileinfo->len;
   721    790   
   722    791   #ifdef FILED_NONBLOCK_HTTP
   723    792   			int socket_flags;
   724    793   			fd_set rfd, wfd;
   725    794   			char sinkbuf[8192];
   726    795   			ssize_t read_ret;
   727    796   
................................................................................
   730    799   			FD_SET(fd, &rfd);
   731    800   			FD_SET(fd, &wfd);
   732    801   
   733    802   			socket_flags = fcntl(fd, F_GETFL);
   734    803   			fcntl(fd, F_SETFL, socket_flags | O_NONBLOCK);
   735    804   #endif
   736    805   
   737         -			filed_log_msg("SEND_START FILE_FD=%i FD=%i BYTES=%llu OFFSET=%llu",
   738         -				fileinfo->fd,
   739         -				fd,
   740         -				(unsigned long long) request->headers.range.length,
   741         -				(unsigned long long) request->headers.range.offset
   742         -			);
   743         -
   744    806   			sendfile_offset = request->headers.range.offset;
   745    807   			sendfile_len = request->headers.range.length;
   746    808   			sendfile_sent = 0;
   747    809   			while (1) {
   748    810   				if (sendfile_len > FILED_SENDFILE_MAX) {
   749    811   					sendfile_size = FILED_SENDFILE_MAX;
   750    812   				} else {
................................................................................
   788    850   				sendfile_len -= sendfile_ret;
   789    851   				sendfile_sent += sendfile_ret;
   790    852   				if (sendfile_len == 0) {
   791    853   					break;
   792    854   				}
   793    855   			}
   794    856   
   795         -			filed_log_msg("SEND_COMPLETE STATUS=%s FILE_FD=%i FD=%i BYTES=%llu BYTES_SENT=%llu",
   796         -				(sendfile_sent == request->headers.range.length) ? "OK" : "PARTIAL",
   797         -				fileinfo->fd,
   798         -				fd,
   799         -				(unsigned long long) request->headers.range.length,
   800         -				(unsigned long long) sendfile_sent
   801         -			);
          857  +			log->endtime = (time_t) -1;
          858  +			log->sent_length = sendfile_sent;
          859  +
          860  +			filed_log_entry(log);
   802    861   		}
   803    862   
   804    863   		close(fileinfo->fd);
   805         -
   806         -		filed_log_msg("CLOSE_FILE FD=%i", fd);
   807    864   	}
   808    865   
   809         -	filed_log_msg("CLOSE_CONNECTION FD=%i", fd);
   810         -
   811    866   	fclose(fp);
   812    867   
   813    868   	return;
   814    869   }
   815    870   
   816    871   /* Handle incoming connections */
   817    872   static void *filed_worker_thread(void *arg_v) {
   818    873   	struct filed_worker_thread_args *arg;
   819    874   	struct filed_http_request request;
          875  +	struct filed_log_entry *log;
   820    876   	struct sockaddr_in6 addr;
   821    877   	char logbuf_ip[128];
   822    878   	socklen_t addrlen;
   823    879   	int failure_count = 0, max_failure_count = FILED_MAX_FAILURE_COUNT;
   824    880   	int master_fd, fd;
   825    881   
   826    882   	/* Read arguments */
................................................................................
   848    904   
   849    905   			failure_count++;
   850    906   
   851    907   			continue;
   852    908   		}
   853    909   
   854    910   		/* Log the new connection */
   855         -		filed_log_msg("NEW_CONNECTION SRC_ADDR=%s SRC_PORT=%lu FD=%i",
   856         -			filed_log_ip((struct sockaddr *) &addr, logbuf_ip, sizeof(logbuf_ip)),
   857         -			(unsigned long) addr.sin6_port,
   858         -			fd
   859         -		);
          911  +		log = filed_log_new(1);
          912  +		if (log == NULL) {
          913  +			close(fd);
          914  +
          915  +			continue;
          916  +		}
          917  +
          918  +		log->type = FILED_LOG_TYPE_TRANSFER;
          919  +		if (filed_log_ip((struct sockaddr *) &addr, log->ip, sizeof(log->ip)) == NULL) {
          920  +			log->ip[0] = '\0';
          921  +		}
          922  +		log->port = addr.sin6_port;
   860    923   
   861    924   		/* Reset failure count*/
   862    925   		failure_count = 0;
   863    926   
   864    927   		/* Handle socket */
   865         -		filed_handle_client(fd, &request);
          928  +		filed_handle_client(fd, &request, log);
   866    929   	}
   867    930   
   868    931   	/* Report error */
   869    932   	filed_log_msg("THREAD_DIED ABNORMAL");
   870    933   
   871    934   	return(NULL);
   872    935