PyFCGI/src/logger.c

#include "logger.h"

int pyfcgi_logger_init()
{
	pyfcgi_conf_logger_t *conf;
	conf = &PyFCGI_conf.logs;
	memset(conf, 0, sizeof(pyfcgi_conf_logger_t));

	return 0;
}

int pyfcgi_logger_stop()
{
	pyfcgi_conf_logger_t *conf;
	pyfcgi_logger_format_t *fmt;
	size_t i, j;

	conf = &PyFCGI_conf.logs;
	for(i=0; i<conf->logger_sz; i++)
	{
		_pyfcgi_logger_free(&(conf->loggers[i]));
	}
	for(i=0; i<conf->format_sz; i++)
	{
		fmt = &(conf->formats[i]);
		for(j=0; j<fmt->nfield; j++)
		{
			pyfcgi_logger_field_free(&(fmt->fields[j]));
		}
		free(conf->formats[i].buf);
	}
	
	return 0;
}

void pyfcgi_logger_enable_syslog(const char* nident)
{
	pyfcgi_conf_logger_t *conf;
	char ident[64];
	size_t ret;

	conf = &PyFCGI_conf.logs;
	if(conf->flags & PYFCGI_LOG_FSYSLOG)
	{
		closelog();
	}
	conf->flags |= PYFCGI_LOG_FSYSLOG;

	ret = 0;
	if(nident)
	{
		ret = snprintf(ident, 64, PYFCGI_SYSLOG_IDENT_FMT,
			getpid(), nident);
	}
	if(!nident || ret >= 64)
	{
		ret = snprintf(ident, 64, PYFCGI_SYSLOG_IDENT_FMT_SHORT,
			getpid());
		if(ret <= 64)
		{
			snprintf(ident, 64, "pyfcgi");
		}
	}
	if(conf->syslog_ident)
	{
		free(conf->syslog_ident);
	}
	conf->syslog_ident = strdup(ident);
	openlog(conf->syslog_ident, LOG_CONS | LOG_PERROR, LOG_DAEMON | LOG_USER);
}

void _pyfcgi_logger_free(pyfcgi_logger_t *logger)
{
	free(logger->filename);
}

int pyfcgi_logger_add(const char *filename, logmask_t loglvl, logmask_t logtyp,
                      const char *format)
{
	pyfcgi_conf_logger_t *conf;
	pyfcgi_logger_t logger;
	size_t new_idx;
	int err;

	conf = &PyFCGI_conf.logs;

	if(conf->logger_sz >= PYFCGI_LOGGER_MAX)
	{
		pyfcgi_log(LOG_ERR, "Maximum of 255 logger reached, unable to add this one...");
		return PYFCGI_ERR;
	}

	if(pyfcgi_logger_format_add(format, &(logger.fmt_id)))
	{
		return PYFCGI_FATAL;
	}

	logger.loglvl = loglvl;
	logger.logtyp = logtyp;
	if(!filename)
	{
		logger.filename = NULL;
	}
	else
	{
		logger.filename = strdup(filename);
		if(!logger.filename)
		{
			err = errno;
			pyfcgi_log(LOG_ALERT,
				"Unable to duplicate logger filename : %s",
				strerror(err));
			return PYFCGI_FATAL;	
		}
	}
	new_idx = conf->logger_sz;
	conf->logger_sz++;
	conf->loggers[new_idx] = logger;
	pyfcgi_logger_open(&(conf->loggers[new_idx]));
	return 0;
}

int pyfcgi_logger_format_add(const char* format, size_t* idx)
{
	size_t i;
	pyfcgi_conf_logger_t *conf;
	int ret;

	conf = &PyFCGI_conf.logs;

	if(!format)
	{
		format = PYFCGI_LOGGER_FMT_DEFAULT;
	}

	for(i=0; i<conf->format_sz; i++)
	{
		if(!strcmp(format, conf->formats[i].fmt)) { break; }
	}
	if(idx) { *idx = i; }
	if( i<conf->format_sz )
	{
		return 0;
	}
	conf->format_sz++;
	if( !(ret = pyfcgi_logger_parse_format(format, &(conf->formats[i]))) )
	{ // No error, allocating format buffer
		pyfcgi_logger_format_bufinit(&(conf->formats[i]));
	}
	return ret;
}

int pyfcgi_logger_parse_format(const char* fmt,
                               pyfcgi_logger_format_t* fmt_data)
{
	const char *ptr, *str_start;
	int err;
	char reason_err[PYFCGI_LOGGER_FMT_PARSE_ERRSZ];
	pyfcgi_logger_fmt_field_t *cur_field;

	memset(fmt_data, 0, sizeof(pyfcgi_logger_format_t));

	if( !(fmt_data->fmt = strdup(fmt)) )
	{
		pyfcgi_log(LOG_ALERT, "Fails to strdup new format : %s",
			   strerror(errno));
		return PYFCGI_FATAL;
	}

	ptr = fmt;
	fmt_data->nfield = 0;
	cur_field = fmt_data->fields;

	while(*ptr)
	{
		if(fmt_data->nfield >= PYFCGI_LOGGER_FIELD_MAX)
		{
			//TODO error truncate !
			//break; 
			goto parse_err;
		}
		str_start = ptr;
		cur_field->len = 0;
		while(*ptr && (*ptr != '{' || *(ptr+1) == '{'))
		{ // handling const chr fields
			//TODO : issue warning/error when unescaped '}' found
			if(*ptr == '{' && *(ptr+1) == '{')
			{
				cur_field->len++;
				ptr++;
			}
			cur_field->len++;
			ptr++;
		}
		if(cur_field->len)
		{
			cur_field->known_length = 1;
			cur_field->type = pyfcgi_logger_field_const;
			cur_field->val = strndup(str_start, cur_field->len);
			if(!cur_field->val)
			{
				err = errno;
				pyfcgi_log(LOG_ALERT,
				           "Unable to strdup part of format : %s",
					   strerror(err));
				goto exit_err;
			}
			fmt_data->nfield++;
			cur_field = &(fmt_data->fields[fmt_data->nfield]); // next_field
			continue; // to check fmt_data->nfield
		}
		if(*ptr == '{') //should be this or '\0'...
		{
			ptr++;
			if( pyfcgi_logger_parse_field(&ptr, fmt,  cur_field, 
			                              reason_err) )
			{
				goto parse_err;
			}
			fmt_data->nfield++;
			cur_field = &(fmt_data->fields[fmt_data->nfield]); // next_field
		}
		ptr++;
	};
	

	return 0;

parse_err:
	pyfcgi_log(LOG_ERR, "Logger format parse error at chr %ld : %s",
	           ptr - fmt, reason_err);
exit_err:
	//TODO free const str from fields
	memset(fmt_data, 0, sizeof(pyfcgi_logger_format_t));
	return PYFCGI_ERR;
}

int pyfcgi_logger_format_bufinit(pyfcgi_logger_format_t* fmt)
{
	volatile unsigned short i;
	size_t pre_sz, suf_sz;
	char *cur, pid[PYFCGI_LOG_PID_LEN];
	fmt->buf = fmt->prefix = fmt->suffix = NULL;
	if(!fmt || !fmt->nfield)
	{
		return 1;
	}
	if(fmt->nfield == 1 && fmt->fields[0].type == pyfcgi_logger_field_msg)
	{
		// no other field than message, buf, prefix & suffix are NULL
		return 0;
	}
	if(fmt->buf)
	{ // if it is not the first call
		free(fmt->buf);
	}
	if(fmt->_msg)
	{ // delete message buffer to force prefix copy
		free(fmt->_msg);
		fmt->_msg = NULL;
	}

	i = 0;
	pre_sz = 0;
	while(i<fmt->nfield && fmt->fields[i].type != pyfcgi_logger_field_msg)
	{
		fmt->fields[i].buf_off = pre_sz;
		fmt->fields[i].suff = 0;
		pre_sz+=fmt->fields[i].len;
		i++;
	}
	i++;
	suf_sz = 0;
	while(i<fmt->nfield && fmt->fields[i].type != pyfcgi_logger_field_msg)
	{
		fmt->fields[i].buf_off = suf_sz;
		fmt->fields[i].suff = 1;
		suf_sz+=fmt->fields[i].len;
		i++;
	}
	pre_sz += pre_sz?1:0;
	suf_sz += suf_sz?1:0;
	fmt->buf = malloc(sizeof(char) * (pre_sz + suf_sz));
	if(!fmt->buf)
	{
		fmt->buf = fmt->prefix = fmt->suffix = NULL;
		pyfcgi_log(LOG_ALERT, "Unable to allocate logger buffer : %s",
		           strerror(errno));
		return PYFCGI_ERR;
	}
	memset(fmt->buf, ' ', (pre_sz + suf_sz));
	fmt->prefix = pre_sz?fmt->buf:NULL;
	fmt->suffix = suf_sz?(fmt->buf + pre_sz):NULL;
	fmt->prefix[pre_sz-1] = '\0';
	if(fmt->suffix)
	{
		fmt->suffix[suf_sz-1] = '\0';
	}
	fmt->buflen[0] = pre_sz - 1;//not counting '\0'
	fmt->buflen[1] = suf_sz;

	i=0;
	cur = fmt->prefix;
	while(i<fmt->nfield)
	{
		while(i<fmt->nfield &&
			fmt->fields[i].type != pyfcgi_logger_field_msg)
		{
			fmt->fields[i].buf_ptr = cur;
			memset(cur, ' ', fmt->fields[i].len);
			switch(fmt->fields[i].type)
			{
				
				case pyfcgi_logger_field_const:
					memcpy(cur, fmt->fields[i].val,
						fmt->fields[i].len);
					break;
				case pyfcgi_logger_field_ident:
					memcpy(cur, PyFCGI_conf.logs.ident,
						fmt->fields[i].len);
					break;
				case pyfcgi_logger_field_pid:
					snprintf(pid, PYFCGI_LOG_PID_LEN+1,
						PYFCGI_LOG_PID_FMT,
						*((pid_t*)fmt->fields[i].val));
					memcpy(cur, pid, PYFCGI_LOG_PID_LEN);
					break;
				default:
					break;
			}
//dprintf(2, "field %d type %d off %ld len %ld '%s' p'%s' s'%s'\n", i, fmt->fields[i].type, fmt->fields[i].buf_off, fmt->fields[i].len, cur, fmt->prefix, fmt->suffix);
			cur += fmt->fields[i].len;
			i++;
		}
		if(fmt->fields[i].type == pyfcgi_logger_field_msg)
		{
			cur = fmt->suffix;
			i++;
		}
	}
	return 0;
}

int pyfcgi_logger_parse_field(const char** ptr, const char *start,
                              pyfcgi_logger_fmt_field_t* cur_field,
			      char fail_reason[PYFCGI_LOGGER_FMT_PARSE_ERRSZ])
{
	
	const char *str_start, *field_start;
	int ret;
	char **name, *cname, **format;
	size_t default_len;
	pyfcgi_logger_field_type_e *type;
	char *field_names[] = {"datetime", "level", "facility", "pid", "ident",
	                       "msg", NULL};
	pyfcgi_logger_field_type_e field_types[] = {
		pyfcgi_logger_field_datetime, pyfcgi_logger_field_level,
		pyfcgi_logger_field_facility, pyfcgi_logger_field_pid,
		pyfcgi_logger_field_ident, pyfcgi_logger_field_msg};

	str_start = *ptr;
	field_start = *ptr;
	name = field_names;
	type = field_types;
	while(*name)
	{
		cname = *name;
		if(*cname != **ptr)
		{
			name++;
			type++;
			continue;
		}
		// Name found ?
		while(**ptr && *cname && **ptr != ':' && **ptr != '}' &&
		      **ptr == *cname)
		{
			(*ptr)++;
			cname++;
		}
		if(**ptr == ':' || **ptr == '}')
		{
			cur_field->type = *type;
			break;
		}
		else
		{
			*name = field_names[6]; // NULL
			break;
		}
	}
	if(!name)
	{
			snprintf(fail_reason, PYFCGI_LOGGER_FMT_PARSE_ERRSZ,
				 "unknown field type '%s' chr %ld",
				 str_start, str_start - start);
			return 1;
	}
	if(**ptr == ':') { (*ptr)++; } // next option
	if(pyfcgi_logger_parse_field_sz(ptr, &(cur_field->len)))
	{
		snprintf(fail_reason, PYFCGI_LOGGER_FMT_PARSE_ERRSZ,
			 "Unable to parse field size chr %ld '%s'",
			 str_start - start, str_start);
		return 1;
	}
	if(**ptr == ':') { (*ptr)++; } // next option
	str_start = *ptr;
	cur_field->known_length = 1;
	switch(cur_field->type)
	{
		case pyfcgi_logger_field_datetime:
			default_len = PYFCGI_LOG_DTM_LEN;
			cur_field->val = (void*)strftime;
			format = &(cur_field->args.datetime.format);
			ret = pyfcgi_logger_parse_field_dtfmt(ptr,format);
			if(ret){
				return ret;
			}
			break;
		case pyfcgi_logger_field_level:
			default_len = PYFCGI_LOG_LVL_LEN;
			cur_field->val = (void*)pyfcgi_logger_value_level;
			break;
		case pyfcgi_logger_field_facility:
			default_len = PYFCGI_LOG_TYP_LEN;
			cur_field->val = (void*)pyfcgi_logger_value_facility;
			break;
		case pyfcgi_logger_field_pid:
			default_len = PYFCGI_LOG_PID_LEN;
			cur_field->val = &(PyFCGI_conf.context.pid);
			break;
		case pyfcgi_logger_field_ident:
			default_len = PyFCGI_conf.logs.ident?strlen(PyFCGI_conf.logs.ident):0;
			cur_field->val = &(PyFCGI_conf.logs.ident);
			break;
		case pyfcgi_logger_field_msg:
			cur_field->known_length = 0;
			default_len = 0;
			break;
		default:
			snprintf(fail_reason, PYFCGI_LOGGER_FMT_PARSE_ERRSZ,
				 "Unknown error parsing field '%s' at chr %ld",
				 field_start , *ptr - start);
			return 1;
	}
	if(!cur_field->len && default_len)
	{
		cur_field->len = default_len;
	}
	return 0;
}

void pyfcgi_logger_field_free(pyfcgi_logger_fmt_field_t* field)
{
	switch(field->type)
	{
		case pyfcgi_logger_field_const:
			if(field->val)
			{
				free(field->val);
			}
			break;
		case pyfcgi_logger_field_datetime:
			if(field->args.datetime.format)
			{
				free(field->args.datetime.format);
			}
			break;
		case pyfcgi_logger_field_null:
		case pyfcgi_logger_field_level:
		case pyfcgi_logger_field_facility:
		case pyfcgi_logger_field_pid:
		case pyfcgi_logger_field_ppid:
		case pyfcgi_logger_field_ident:
		case pyfcgi_logger_field_msg:
			break;
	}
}


int pyfcgi_logger_parse_field_dtfmt(const char** ptr, char** format)
{
	const char *fmt;
	size_t fmt_len;

	fmt_len = 0;
	fmt = *ptr;
	while(**ptr && **ptr != '}' && *((*ptr)+1) != '}')
	{
		(*ptr)++;
		fmt_len++;
	}
	if(!(**ptr))
	{
		//TODO error
	}
	if(!fmt_len)
	{
		fmt_len = sizeof(PYFCGI_LOGGER_TIME_FMT_DEFAULT);
		fmt = PYFCGI_LOGGER_TIME_FMT_DEFAULT;
	}
	if(!(*format = strndup(fmt, fmt_len+1)))
	{
		pyfcgi_log(LOG_ALERT,
		           "Unable to strdup field datetime format : %s",
			   strerror(errno));
		return PYFCGI_FATAL;
	}
	return 0;
}

int pyfcgi_logger_parse_field_sz(const char **ptr, size_t *size)
{
	char *end;
	*size = 0;
	if(**ptr == '}' || **ptr == ':')
	{
		return 0;
	}

	if(**ptr < '0' || **ptr > '9')
	{
		return 1; // parse error
	}
	*size = strtoull(*ptr, &end, 10);
	*ptr = end;
	return 0;
}

const char* pyfcgi_logger_value_level(short lvl)
{
	short idx;
	idx = ((lvl & 0xF0) >> 4)-1;
	if(idx < 0 || idx > 7)
	{
		return NULL;
	}
	return PYFCGI_LOGGER_LVLNAME[idx];
}


const char* pyfcgi_logger_value_facility(short typ)
{
	short idx;
	idx = typ & 0x0F;
	if(idx < 0 || idx >= sizeof(PYFCGI_LOGGER_TYPNAME))
	{
		return NULL;
	}
	return PYFCGI_LOGGER_TYPNAME[idx];
}

int pyfcgi_logger_open(pyfcgi_logger_t *logger)
{
	if(!logger->filename)
	{
		logger->fd = 2;
		return 0;
	}

	if( ((logger->fd = open(logger->filename,
		O_WRONLY | O_APPEND | O_CREAT, 00640)) < 0) )
	{
		pyfcgi_log(LOG_ERR,
		           "Unable to open log file '%s' : %s",
			   strerror(errno));
		return PYFCGI_ERR;
	}
	return 0;
}

int pyfcgi_logger_set_ident(const char* new_ident)
{
	pyfcgi_conf_logger_t *conf;
	pyfcgi_logger_format_t *fmt;
	pyfcgi_logger_fmt_field_t *field;
	size_t i, j, len;
	short upd;

	conf = &PyFCGI_conf.logs;
	if(conf->ident)
	{
		free(conf->ident);
	}

	if( !(conf->ident = strdup(new_ident)) )
	{
		pyfcgi_log(LOG_ALERT,
			"Error duplicating identity for logger : %s",
			strerror(errno));
		return PYFCGI_FATAL;
	}

	if(conf->flags & PYFCGI_LOG_FSYSLOG)
	{
		pyfcgi_logger_enable_syslog(new_ident);
	}

	len = strlen(conf->ident);
	for(i=0; i<conf->format_sz; i++)
	{
		fmt = &(conf->formats[i]);
		upd = 0;
		for(j=0; j<fmt->nfield; j++)
		{
			field = &(fmt->fields[j]);
			if(field->type == pyfcgi_logger_field_ident)
			{
				field->len = len;
				upd = 1;
			}
		}
		if(upd)
		{
			pyfcgi_logger_format_bufinit(fmt);
		}
	}
	return 0;
}

char* vpyfcgi_logger_format_message(pyfcgi_logger_format_t *fmt,
	loglvl_t lvl, const char* message, size_t fmt_msg_len)
{
	/**@todo Add '\n' when suffix is used ! */
	char *_msgptr;
	size_t maxlen;
	int ret;
	void *tmp;
	size_t i, suff_off;
	pyfcgi_logger_fmt_field_t *field;
	struct tm *curtime;
	time_t _curtime;
	size_t (*_strftime)(char*, size_t, const char*, const struct tm*);


	if(!fmt->_msg)
	{ //first message, allocating message buffer
		fmt->_msglen = fmt->buflen[0] + fmt->buflen[1] + fmt_msg_len + 1;
		// rounding upper
		fmt->_msglen >>= 6;
		fmt->_msglen++;
		fmt->_msglen <<= 6;
		fmt->_msg = malloc(sizeof(char) * fmt->_msglen);
		if(!fmt->_msg)
		{
			//TODO : error
dprintf(2, "ERROR ALLOC _msg : %s\n", strerror(errno));
			return NULL;
		}
		memset(fmt->_msg, ' ', sizeof(char)*fmt->_msglen);
		fmt->_msg[fmt->_msglen - 1] = '\0';
		memcpy(fmt->_msg, fmt->prefix, fmt->buflen[0]);
	}
	while(1)
	{
		maxlen = fmt->_msglen - (fmt->buflen[0] + fmt->buflen[1]);
		if(fmt_msg_len < maxlen)
		{
			// TODO check errors
			break;
		}
		fmt->_msglen = fmt_msg_len + fmt->buflen[0] + fmt->buflen[1] + 1;
		fmt->_msglen >>= 6;
		fmt->_msglen++;
		fmt->_msglen <<= 6;
		tmp = realloc(fmt->_msg, sizeof(char) * fmt->_msglen);
		if(!tmp)
		{
			//TODO : error
dprintf(2, "ERROR REALLOC _msg : %s", strerror(errno));
			return NULL;
		}
		fmt->_msg = tmp;
	}
	memcpy(fmt->_msg + fmt->buflen[0], message, fmt_msg_len);
	suff_off = fmt->buflen[0] + fmt_msg_len;
	if(fmt->buflen[1])
	{
		strncpy(fmt->_msg + suff_off, fmt->suffix,
			fmt->buflen[1]);
		//TODO check errors
		fmt->_msg[suff_off+fmt->buflen[1]] = '\n';
		fmt->_msg[suff_off+fmt->buflen[1]+1] = '\0';
	}
	else
	{
		fmt->_msg[suff_off] = '\n';
		fmt->_msg[suff_off+1] = '\0';
	}
	// update fmt->_msg dynamic fields
	time(&_curtime);
	curtime = localtime(&_curtime);
	for(i=0; i<fmt->nfield; i++)
	{
		field = &(fmt->fields[i]);
		_msgptr = fmt->_msg;
		_msgptr += fmt->fields->suff?suff_off:0;
		_msgptr += field->buf_off;
		switch(field->type)
		{
			case pyfcgi_logger_field_datetime:
				_strftime = field->val?field->val:strftime;
				ret = _strftime(_msgptr, field->len,
					field->args.datetime.format,
					curtime);
				if(!ret)
				{
					//TODO ERROR
dprintf(2,"Not enough space to write datetime in '%s', need more than %ld\n",
	fmt->fmt, field->len);
				}
				_msgptr[ret] = ' ';
				break;
			case pyfcgi_logger_field_level:
				memcpy(_msgptr,
					pyfcgi_logger_value_level(lvl),
					field->len);
				break;
			default:
				break;
		}
	}
	return fmt->_msg;
}

int pyfcgi_log(loglvl_t lvl, const char *fmt, ...)
{
	int ret;
	va_list ap;
	va_start(ap, fmt);
	ret = vpyfcgi_log(lvl, fmt, ap);
	va_end(ap);
	return ret;
}

int vpyfcgi_log(loglvl_t lvl, const char *fmt, va_list ap)
{
	int len, ret;
	pyfcgi_conf_logger_t *conf;
	pyfcgi_logger_t *logger;
	unsigned char i;
	size_t msglen, real_len;
	void *tmp;
	va_list o_ap;


	conf = &PyFCGI_conf.logs;

	va_copy(o_ap, ap);
	_vsyslog(lvl, fmt, o_ap);
	va_end(o_ap);

	ret = 0;
	// processing message before sending it to formats
	while(1)
	{
		va_copy(o_ap, ap);
		msglen = vsnprintf(conf->msg_buf, conf->msg_buf_sz, fmt, o_ap);
		real_len = msglen;
		va_end(o_ap);
		// Rounding msglen
		msglen >>=6;
		msglen++;
		msglen <<=6;
		if(msglen <= conf->msg_buf_sz)
		{
			break;
		}
		conf->msg_buf_sz = msglen;
		tmp = realloc(conf->msg_buf,
			sizeof(char)*conf->msg_buf_sz);
		if(!tmp)
		{
			// TODO : error
dprintf(2, "ERROR REALLOC conf_msg : %s", strerror(errno));
			if(conf->msg_buf) { free(conf->msg_buf); }
			return PYFCGI_FATAL;
		}
		conf->msg_buf = tmp;
	}

	// populating format messages
	for(i=0; i<conf->format_sz; i++)
	{
		vpyfcgi_logger_format_message(&(conf->formats[i]), lvl,
			conf->msg_buf, real_len);
	}
	for(i=0; i<conf->logger_sz; i++)
	{
		logger = &(conf->loggers[i]);
		len = dprintf(logger->fd, conf->formats[logger->fmt_id]._msg);
		if(len < 0)
		{
			_syslog(LOG_ALERT, 
			       "Unable to write to single FD to '%s' when trying to log : %s",
			       conf->loggers[i].filename, strerror(errno));
			ret = PYFCGI_FATAL;
		}
	}
	return ret;
}