Browse Source

[multiple] de-dup file and piped loggers (fixes #3101)

de-dup file and piped loggers for error logs and access logs

x-ref:
  "RFE: de-dup file and piped loggers"
  https://redmine.lighttpd.net/issues/3101
master
Glenn Strauss 3 months ago
parent
commit
7b615d5d24
  1. 10
      src/CMakeLists.txt
  2. 19
      src/Makefile.am
  3. 1
      src/SConscript
  4. 5
      src/base_decls.h
  5. 3
      src/chunk.h
  6. 166
      src/configfile.c
  7. 3
      src/fdevent.h
  8. 205
      src/fdlog.c
  9. 36
      src/fdlog.h
  10. 338
      src/fdlog_maint.c
  11. 48
      src/log.c
  12. 15
      src/log.h
  13. 10
      src/meson.build
  14. 195
      src/mod_accesslog.c
  15. 3
      src/mod_cgi.c
  16. 3
      src/mod_ssi.c
  17. 3
      src/plugin_config.h
  18. 5
      src/request.h
  19. 14
      src/server.c
  20. 7
      src/t/test_configfile.c
  21. 6
      src/t/test_keyvalue.c
  22. 7
      src/t/test_mod_indexfile.c
  23. 7
      src/t/test_mod_staticfile.c
  24. 7
      src/t/test_mod_userdir.c
  25. 7
      src/t/test_request.c

10
src/CMakeLists.txt

@ -768,6 +768,7 @@ set(COMMON_SRC
request.c
sock_addr.c
rand.c
fdlog_maint.c
fdlog.c
ck.c
)
@ -887,6 +888,7 @@ add_executable(test_configfile
http_kv.c
vector.c
log.c
fdlog.c
sock_addr.c
ck.c
)
@ -899,6 +901,7 @@ add_executable(test_keyvalue
base64.c
array.c
log.c
fdlog.c
ck.c
)
add_test(NAME test_keyvalue COMMAND test_keyvalue)
@ -908,6 +911,7 @@ add_executable(test_mod_access
buffer.c
array.c
log.c
fdlog.c
ck.c
)
add_test(NAME test_mod_access COMMAND test_mod_access)
@ -917,6 +921,7 @@ add_executable(test_mod_evhost
buffer.c
array.c
log.c
fdlog.c
ck.c
)
add_test(NAME test_mod_evhost COMMAND test_mod_evhost)
@ -933,6 +938,7 @@ add_executable(test_mod_indexfile
http_header.c
http_kv.c
log.c
fdlog.c
sock_addr.c
stat_cache.c
algo_splaytree.c
@ -945,6 +951,7 @@ add_executable(test_mod_simple_vhost
buffer.c
array.c
log.c
fdlog.c
ck.c
)
add_test(NAME test_mod_simple_vhost COMMAND test_mod_simple_vhost)
@ -966,6 +973,7 @@ add_executable(test_mod_staticfile
http_header.c
http_kv.c
log.c
fdlog.c
sock_addr.c
stat_cache.c
algo_splaytree.c
@ -978,6 +986,7 @@ add_executable(test_mod_userdir
buffer.c
array.c
log.c
fdlog.c
ck.c
)
add_test(NAME test_mod_userdir COMMAND test_mod_userdir)
@ -991,6 +1000,7 @@ add_executable(test_request
http_header.c
http_kv.c
log.c
fdlog.c
sock_addr.c
ck.c
)

19
src/Makefile.am

@ -89,6 +89,7 @@ common_src=base64.c buffer.c burl.c log.c \
rand.c \
request.c \
sock_addr.c \
fdlog_maint.c \
fdlog.c \
ck.c
@ -654,31 +655,31 @@ t_test_base64_LDADD = $(LIBUNWIND_LIBS)
t_test_burl_SOURCES = t/test_burl.c burl.c buffer.c base64.c ck.c
t_test_burl_LDADD = $(LIBUNWIND_LIBS)
t_test_configfile_SOURCES = t/test_configfile.c buffer.c array.c data_config.c http_header.c http_kv.c vector.c log.c sock_addr.c ck.c
t_test_configfile_SOURCES = t/test_configfile.c buffer.c array.c data_config.c http_header.c http_kv.c vector.c log.c fdlog.c sock_addr.c ck.c
t_test_configfile_LDADD = $(PCRE_LIB) $(LIBUNWIND_LIBS)
t_test_keyvalue_SOURCES = t/test_keyvalue.c burl.c buffer.c base64.c array.c log.c ck.c
t_test_keyvalue_SOURCES = t/test_keyvalue.c burl.c buffer.c base64.c array.c log.c fdlog.c ck.c
t_test_keyvalue_LDADD = $(PCRE_LIB) $(LIBUNWIND_LIBS)
t_test_mod_access_SOURCES = t/test_mod_access.c buffer.c array.c log.c ck.c
t_test_mod_access_SOURCES = t/test_mod_access.c buffer.c array.c log.c fdlog.c ck.c
t_test_mod_access_LDADD = $(LIBUNWIND_LIBS)
t_test_mod_evhost_SOURCES = t/test_mod_evhost.c buffer.c array.c log.c ck.c
t_test_mod_evhost_SOURCES = t/test_mod_evhost.c buffer.c array.c log.c fdlog.c ck.c
t_test_mod_evhost_LDADD = $(LIBUNWIND_LIBS)
t_test_mod_indexfile_SOURCES = t/test_mod_indexfile.c request.c base64.c buffer.c burl.c array.c fdevent.c http_etag.c http_header.c http_kv.c log.c sock_addr.c stat_cache.c algo_splaytree.c ck.c
t_test_mod_indexfile_SOURCES = t/test_mod_indexfile.c request.c base64.c buffer.c burl.c array.c fdevent.c http_etag.c http_header.c http_kv.c log.c fdlog.c sock_addr.c stat_cache.c algo_splaytree.c ck.c
t_test_mod_indexfile_LDADD = $(LIBUNWIND_LIBS) $(FAM_LIBS)
t_test_mod_simple_vhost_SOURCES = t/test_mod_simple_vhost.c buffer.c array.c log.c ck.c
t_test_mod_simple_vhost_SOURCES = t/test_mod_simple_vhost.c buffer.c array.c log.c fdlog.c ck.c
t_test_mod_simple_vhost_LDADD = $(LIBUNWIND_LIBS)
t_test_mod_staticfile_SOURCES = t/test_mod_staticfile.c request.c base64.c buffer.c burl.c array.c chunk.c fdevent.c http-header-glue.c http_cgi.c http_chunk.c http_date.c http_etag.c http_header.c http_kv.c log.c sock_addr.c stat_cache.c algo_splaytree.c ck.c
t_test_mod_staticfile_SOURCES = t/test_mod_staticfile.c request.c base64.c buffer.c burl.c array.c chunk.c fdevent.c http-header-glue.c http_cgi.c http_chunk.c http_date.c http_etag.c http_header.c http_kv.c log.c fdlog.c sock_addr.c stat_cache.c algo_splaytree.c ck.c
t_test_mod_staticfile_LDADD = $(LIBUNWIND_LIBS) $(FAM_LIBS)
t_test_mod_userdir_SOURCES = t/test_mod_userdir.c buffer.c array.c log.c ck.c
t_test_mod_userdir_SOURCES = t/test_mod_userdir.c buffer.c array.c log.c fdlog.c ck.c
t_test_mod_userdir_LDADD = $(LIBUNWIND_LIBS)
t_test_request_SOURCES = t/test_request.c base64.c buffer.c burl.c array.c http_header.c http_kv.c log.c sock_addr.c ck.c
t_test_request_SOURCES = t/test_request.c base64.c buffer.c burl.c array.c http_header.c http_kv.c log.c fdlog.c sock_addr.c ck.c
t_test_request_LDADD = $(LIBUNWIND_LIBS)
noinst_HEADERS = $(hdr)

1
src/SConscript

@ -71,6 +71,7 @@ common_src = Split("base64.c buffer.c burl.c log.c \
request.c \
sock_addr.c \
rand.c \
fdlog_maint.c \
fdlog.c \
ck.c \
")

5
src/base_decls.h

@ -24,8 +24,9 @@ typedef union sock_addr sock_addr;
struct fdnode_st;
typedef struct fdnode_st fdnode;
struct log_error_st;
typedef struct log_error_st log_error_st;
struct fdlog_st;
typedef struct fdlog_st fdlog_st;
typedef struct fdlog_st log_error_st;
enum handler_t {
HANDLER_GO_ON,

3
src/chunk.h

@ -13,7 +13,8 @@
#define MAX_READ_LIMIT (256*1024)
#define MAX_WRITE_LIMIT (256*1024)
struct log_error_st; /*(declaration)*/
struct fdlog_st; /*(declaration)*/
#define log_error_st fdlog_st
typedef struct chunk {
struct chunk *next;

166
src/configfile.c

@ -1440,7 +1440,10 @@ void config_init(server *srv) {
static void config_log_error_open_syslog(server *srv, log_error_st *errh, const buffer *syslog_facility) {
#ifdef HAVE_SYSLOG_H
errh->errorlog_mode = ERRORLOG_SYSLOG;
/*assert(errh->mode == FDLOG_FD);*/
/*assert(errh->fd == STDERR_FILENO);*/
errh->mode = FDLOG_SYSLOG;
errh->fd = -1;
/* perhaps someone wants to use syslog() */
int facility = -1;
if (syslog_facility) {
@ -1508,20 +1511,6 @@ static void config_log_error_open_syslog(server *srv, log_error_st *errh, const
#endif
}
static int config_log_error_open_fn(server *srv, log_error_st *errh, const char *fn) {
int fd = fdlog_open(fn);
if (-1 == fd) {
log_perror(srv->errh, __FILE__, __LINE__,
"opening errorlog '%s' failed", fn);
return -1;
}
errh->errorlog_fd = fd;
errh->errorlog_mode = fn[0] == '|' ? ERRORLOG_PIPE : ERRORLOG_FILE;
errh->fn = fn;
return 0;
}
int config_log_error_open(server *srv) {
/* logs are opened after preflight check (srv->srvconf.preflight_check)
* and after dropping privileges instead of being opened during config
@ -1530,8 +1519,6 @@ int config_log_error_open(server *srv) {
force_assert(srv->errh);
#endif
/* Note: implementation does not de-dup repeated files or pipe commands */
config_data_base * const p = srv->config_data_base;
log_error_st *serrh = NULL;
@ -1561,11 +1548,22 @@ int config_log_error_open(server *srv) {
if (NULL == fn) continue;
if (NULL == errh) errh = log_error_st_init();
cpv->v.v = errh;
cpv->vtype = T_CONFIG_LOCAL;
fdlog_st * const fdlog = fdlog_open(fn);
if (NULL == fdlog) {
log_perror(srv->errh, __FILE__, __LINE__,
"opening errorlog '%s' failed", fn);
return -1;
}
if (0 != config_log_error_open_fn(srv, errh, fn)) return -1;
if (errh) {
/*(logfiles are opened early in setup; this function is called
* prior to set_defaults hook, and modules should not save a
* pointer to srv->errh until set_defaults hook or later)*/
p->defaults.errh = srv->errh = fdlog;
fdlog_free(errh);
}
cpv->v.v = errh = fdlog;
cpv->vtype = T_CONFIG_LOCAL;
if (0 == i && errh != srv->errh) /*(top-level server.breakagelog)*/
serrh = errh;
@ -1575,9 +1573,8 @@ int config_log_error_open(server *srv) {
if (srv->srvconf.errorlog_use_syslog) /*(restricted to global scope)*/
config_log_error_open_syslog(srv, srv->errh,
srv->srvconf.syslog_facility);
else if (srv->errh->errorlog_mode == ERRORLOG_FD
&& !srv->srvconf.dont_daemonize)
srv->errh->errorlog_fd = -1;
else if (srv->errh->mode == FDLOG_FD && !srv->srvconf.dont_daemonize)
srv->errh->fd = -1;
/* We can only log to stderr in dont-daemonize mode;
* if we do daemonize and no errorlog file is specified,
* we log into /dev/null
@ -1590,12 +1587,12 @@ int config_log_error_open(server *srv) {
int errfd;
if (NULL != serrh) {
if (srv->errh->errorlog_mode == ERRORLOG_FD) {
srv->errh->errorlog_fd = dup(STDERR_FILENO);
fdevent_setfd_cloexec(srv->errh->errorlog_fd);
if (srv->errh->mode == FDLOG_FD) {
srv->errh->fd = dup(STDERR_FILENO);
fdevent_setfd_cloexec(srv->errh->fd);
}
errfd = serrh->errorlog_fd;
errfd = serrh->fd;
if (*serrh->fn == '|') fdlog_pipe_serrh(errfd); /* breakagelog */
}
else if (!srv->srvconf.dont_daemonize) {
@ -1622,122 +1619,25 @@ int config_log_error_open(server *srv) {
#endif
if (NULL != serrh) {
close(errfd); /* serrh->errorlog_fd */
serrh->errorlog_fd = STDERR_FILENO;
close(errfd); /* serrh->fd */
serrh->fd = STDERR_FILENO;
}
return 0;
}
/**
* cycle the errorlog
*
*/
void config_log_error_cycle(server *srv) {
/* All logs are rotated in parent and children workers so that all have
* valid filehandles. The parent might reap a child and respawn, so the
* parent needs valid handles for more than top-level srv->errh */
/*(no need to flush error log before cycling; error logs are not buffered)*/
config_data_base * const p = srv->config_data_base;
/* future: might be slightly faster to have allocated array of open files
* rather than walking config, but only might matter with many directives */
/* (init i to 0 if global context; to 1 to skip empty global context) */
for (int i = !p->cvlist[0].v.u2[1]; i < p->nconfig; ++i) {
config_plugin_value_t *cpv = p->cvlist + p->cvlist[i].v.u2[0];
for (; -1 != cpv->k_id; ++cpv) {
if (cpv->vtype != T_CONFIG_LOCAL || NULL == cpv->v.v) continue;
log_error_st *errh;
switch (cpv->k_id) {
case 31:/* server.errorlog */
case 32:/* server.breakagelog */
errh = cpv->v.v; /* cycle only if the error log is a file */
if (errh->errorlog_mode != ERRORLOG_FILE) continue;
if (-1 == fdlog_cycle(errh->fn, &errh->errorlog_fd)) {
/* write to top-level error log
* (the prior log if srv->errh is the one being cycled) */
log_perror(srv->errh, __FILE__, __LINE__,
"cycling errorlog '%s' failed", errh->fn);
}
else if (0 == i && errh != srv->errh) { /*(server.breakagelog)*/
int fd = errh->errorlog_fd;
if (STDERR_FILENO != dup2(fd, STDERR_FILENO)) {
errh->errorlog_fd = STDERR_FILENO;
close(fd);
}
else {
log_perror(srv->errh, __FILE__, __LINE__,
"dup2() %s to STDERR failed", errh->fn);
}
}
break;
default:
break;
}
}
}
}
void config_log_error_close(server *srv) {
config_data_base * const p = srv->config_data_base;
if (NULL == p) return;
/* future: might be slightly faster to have allocated array of open files
* rather than walking config, but only might matter with many directives */
/* (init i to 0 if global context; to 1 to skip empty global context) */
for (int i = !p->cvlist[0].v.u2[1]; i < p->nconfig; ++i) {
config_plugin_value_t *cpv = p->cvlist + p->cvlist[i].v.u2[0];
for (; -1 != cpv->k_id; ++cpv) {
if (cpv->vtype != T_CONFIG_LOCAL || NULL == cpv->v.v) continue;
log_error_st *errh = NULL;
switch (cpv->k_id) {
/* NB: these indexes are repeated below switch() block
* and all must stay in sync with configfile.c */
case 31:/* server.errorlog */
if (0 == i) continue; /*(srv->errh is free'd later)*/
__attribute_fallthrough__
case 32:/* server.breakagelog */
errh = cpv->v.v; /* cycle only if the error log is a file */
break;
default:
break;
}
if (NULL == errh) continue;
switch(errh->errorlog_mode) {
case ERRORLOG_PIPE:
case ERRORLOG_FILE:
case ERRORLOG_FD:
if (-1 != errh->errorlog_fd) {
/* don't close STDERR */
/* fdlog_pipes_close() closes ERRORLOG_PIPE */
if (STDERR_FILENO != errh->errorlog_fd
&& ERRORLOG_PIPE != errh->errorlog_mode) {
close(errh->errorlog_fd);
}
errh->errorlog_fd = -1;
}
break;
case ERRORLOG_SYSLOG: /*(restricted to global scope)*/
#ifdef HAVE_SYSLOG_H
closelog();
#endif
break;
}
log_error_st_free(errh);
}
}
/*(reset serrh just in case; should not be used after this func returns)*/
p->defaults.serrh = NULL;
fdlog_pipes_close();
fdlog_closeall(srv->errh); /*(close all except srv->errh)*/
if (srv->errh->errorlog_mode == ERRORLOG_SYSLOG) {
srv->errh->errorlog_mode = ERRORLOG_FD;
srv->errh->errorlog_fd = STDERR_FILENO;
if (srv->errh->mode == FDLOG_SYSLOG) {
srv->errh->mode = FDLOG_FD;
srv->errh->fd = STDERR_FILENO;
#ifdef HAVE_SYSLOG_H
closelog();
#endif

3
src/fdevent.h

@ -4,7 +4,8 @@
#include "base_decls.h" /* handler_t */
struct log_error_st; /* declaration */
struct fdlog_st; /*(declaration)*/
#define log_error_st fdlog_st
struct fdevents; /* declaration */
typedef struct fdevents fdevents;

205
src/fdlog.c

@ -1,203 +1,28 @@
#include "first.h"
#include "fdlog.h"
#include <sys/types.h>
#include <errno.h>
#include <fcntl.h>
#include <stdlib.h>
#include <unistd.h>
#include "fdevent.h"
#include "log.h"
typedef struct fdlog_pipe {
pid_t pid;
int fds[2];
const char *cmd;
unix_time64_t start;
} fdlog_pipe;
struct fdlog_pipes_t {
fdlog_pipe *ptr;
uint32_t used;
uint32_t size;
};
static struct fdlog_pipes_t fdlog_pipes;
static pid_t
fdlog_pipe_spawn (const char * const fn, const int rfd)
{
char *args[4];
int devnull = fdevent_open_devnull();
pid_t pid;
if (-1 == devnull) {
return -1;
}
*(const char **)&args[0] = "/bin/sh";
*(const char **)&args[1] = "-c";
*(const char **)&args[2] = fn;
args[3] = NULL;
pid = fdevent_fork_execve(args[0], args, NULL, rfd, devnull, devnull, -1);
if (pid > 0) {
close(devnull);
}
else {
int errnum = errno;
close(devnull);
errno = errnum;
}
return pid;
}
#include <unistd.h> /* close() STDERR_FILENO */
#include "ck.h"
__attribute_noinline__
static int
fdlog_pipe_restart (fdlog_pipe * const fdp, const unix_time64_t ts)
fdlog_st *
fdlog_init (const char * const fn, const int fd, const int mode)
{
if (fdp->start + 5 < ts) { /* limit restart to once every 5 sec */
/* restart child process using existing pipe fds */
fdp->start = ts;
fdp->pid = fdlog_pipe_spawn(fdp->cmd, fdp->fds[0]);
}
return (fdp->pid > 0) ? 1 : -1;
fdlog_st * const fdlog = calloc(1, sizeof(fdlog_st));
ck_assert(fdlog);
fdlog->fn = fn; /* note: fn must persist in memory (or else copy here) */
fdlog->fd = fd >= 0 ? fd : STDERR_FILENO;
fdlog->mode = mode;
return fdlog;
}
void
fdlog_pipes_restart (const unix_time64_t ts)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_pipe * const fdp = fdlog_pipes.ptr+i;
if (fdp->pid > 0) continue;
fdlog_pipe_restart(fdp, ts);
}
}
int
fdlog_pipes_waitpid_cb (const pid_t pid)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_pipe * const fdp = fdlog_pipes.ptr+i;
if (fdp->pid != pid) continue;
fdp->pid = -1;
return fdlog_pipe_restart(fdp, log_monotonic_secs);
}
return 0;
}
void
fdlog_pipes_close (void)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_pipe * const fdp = fdlog_pipes.ptr+i;
close(fdp->fds[0]);
if (fdp->fds[1] != STDERR_FILENO) close(fdp->fds[1]);
}
free(fdlog_pipes.ptr);
fdlog_pipes.ptr = NULL;
fdlog_pipes.used = 0;
fdlog_pipes.size = 0;
}
void
fdlog_pipes_abandon_pids (void)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_pipe * const fdp = fdlog_pipes.ptr+i;
fdp->pid = -1;
}
}
void
fdlog_pipe_serrh (const int fd)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_pipe * const fdp = fdlog_pipes.ptr+i;
if (fdp->fds[1] != fd) continue;
fdp->fds[1] = STDERR_FILENO;
break;
}
}
static void
fdlog_pipe_init (const char * const cmd, const int fds[2], const pid_t pid)
{
if (fdlog_pipes.used == fdlog_pipes.size) {
fdlog_pipes.size += 4;
fdlog_pipes.ptr =
realloc(fdlog_pipes.ptr, fdlog_pipes.size * sizeof(fdlog_pipe));
force_assert(fdlog_pipes.ptr);
}
fdlog_pipe * const fdp = fdlog_pipes.ptr + fdlog_pipes.used++;
fdp->cmd = cmd; /* note: cmd must persist in memory (or else copy here) */
fdp->fds[0] = fds[0];
fdp->fds[1] = fds[1];
fdp->pid = pid;
fdp->start = log_monotonic_secs;
}
static int
fdlog_pipe_open (const char * const fn)
{
int fds[2];
if (pipe(fds))
return -1;
fdevent_setfd_cloexec(fds[0]);
fdevent_setfd_cloexec(fds[1]);
pid_t pid = fdlog_pipe_spawn(fn, fds[0]);
if (pid > 0) {
/*(nonblocking write() from lighttpd)*/
if (0 != fdevent_fcntl_set_nb(fds[1])) { /*(ignore)*/ }
fdlog_pipe_init(fn, fds, pid);
return fds[1];
}
else {
int errnum = errno;
close(fds[0]);
close(fds[1]);
errno = errnum;
return -1;
}
}
int
fdlog_open (const char * const fn)
{
if (fn[0] != '|') { /*(permit symlinks)*/
int flags = O_APPEND | O_WRONLY | O_CREAT;
return fdevent_open_cloexec(fn, 1, flags, 0644);
}
else {
return fdlog_pipe_open(fn+1); /*(skip the '|')*/
}
}
int
fdlog_cycle (const char * const fn, int * const curfd)
fdlog_free (fdlog_st * const fdlog)
{
if (fn[0] != '|') {
int fd = fdlog_open(fn);
if (-1 == fd) return -1; /*(error; leave *curfd as-is)*/
if (-1 != *curfd) close(*curfd);
*curfd = fd;
}
return *curfd;
if (fdlog->fd != STDERR_FILENO)
close(fdlog->fd);
free(fdlog->b.ptr);
free(fdlog);
}

36
src/fdlog.h

@ -2,20 +2,46 @@
#define INCLUDED_FDLOG_H
#include "first.h"
#include "base_decls.h"
#include "buffer.h"
typedef struct fdlog_st {
enum { FDLOG_FILE, FDLOG_FD, FDLOG_SYSLOG, FDLOG_PIPE } mode;
int fd;
buffer b;
const char *fn;
} fdlog_st;
__attribute_cold__
int fdlog_open (const char *fn);
__attribute_malloc__
__attribute_returns_nonnull__
fdlog_st * fdlog_init (const char *fn, int fd, int mode);
__attribute_cold__
int fdlog_cycle (const char *fn, int *curfd);
void fdlog_free (fdlog_st *fdlog);
/* fdlog_maint.c */
__attribute_cold__
int fdlog_pipes_waitpid_cb (pid_t pid);
fdlog_st * fdlog_open (const char *fn);
__attribute_cold__
void fdlog_pipes_restart (unix_time64_t ts);
void fdlog_closeall (fdlog_st *errh);
__attribute_cold__
void fdlog_flushall (fdlog_st *errh);
__attribute_cold__
void fdlog_pipes_close (void);
void fdlog_files_flush (fdlog_st *errh, int memrel);
__attribute_cold__
void fdlog_files_cycle (fdlog_st *errh);
__attribute_cold__
int fdlog_pipes_waitpid_cb (pid_t pid);
__attribute_cold__
void fdlog_pipes_restart (unix_time64_t ts);
__attribute_cold__
void fdlog_pipes_abandon_pids (void);

338
src/fdlog_maint.c

@ -0,0 +1,338 @@
#include "first.h"
#include "fdlog.h"
#include <sys/types.h>
#include <errno.h>
#include <fcntl.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include "fdevent.h"
#include "ck.h"
#include "log.h"
/*
* Notes:
* - Use of "/dev/stdin" and "/dev/stdout" is not recommended
* since those are manipulated at startup in server_main_setup()
* "/dev/stderr" might similarly be manipulated at startup.
* - Use of "/proc/self/fd/..." is permitted, and admin may use a shell script
* to dup standard fds to higher numbers before starting lighttpd if admin
* wants to direct logs to the standard fds on which lighttpd was started.
* Future: might detect and use the open fd rather than open() a new fd to the
* already-open path. If so, should stat() to check that fd actually exists,
* and must check for and not close() those paths when closing fdlog_st fds.
*/
struct fdlog_files_t {
fdlog_st **ptr;
uint32_t used;
uint32_t size;
};
static struct fdlog_files_t fdlog_files;
typedef struct fdlog_pipe {
/* ((fdlog_st *) is ptr rather than inlined struct since multiple callers
* might have reference to (fdlog_st *), and if fdlog_pipes.ptr is
* reallocated those ptrs could be invalided if inlined struct) */
fdlog_st *fdlog; /*(contains write-side of pipe)*/
pid_t pid;
int fd; /*(contains read-side of pipe)*/
unix_time64_t start;
} fdlog_pipe;
struct fdlog_pipes_t {
fdlog_pipe *ptr;
uint32_t used;
uint32_t size;
};
static struct fdlog_pipes_t fdlog_pipes;
static pid_t
fdlog_pipe_spawn (const char * const fn, const int rfd)
{
char *args[4];
int devnull = fdevent_open_devnull();
pid_t pid;
if (-1 == devnull) {
return -1;
}
*(const char **)&args[0] = "/bin/sh";
*(const char **)&args[1] = "-c";
*(const char **)&args[2] = fn;
args[3] = NULL;
pid = fdevent_fork_execve(args[0], args, NULL, rfd, devnull, devnull, -1);
if (pid > 0) {
close(devnull);
}
else {
int errnum = errno;
close(devnull);
errno = errnum;
}
return pid;
}
__attribute_noinline__
static int
fdlog_pipe_restart (fdlog_pipe * const fdp, const unix_time64_t ts)
{
if (fdp->start + 5 < ts) { /* limit restart to once every 5 sec */
/* restart child process using existing pipe fds */
fdp->start = ts;
fdp->pid = fdlog_pipe_spawn(fdp->fdlog->fn, fdp->fd);
}
return (fdp->pid > 0) ? 1 : -1;
}
void
fdlog_pipes_restart (const unix_time64_t ts)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_pipe * const fdp = fdlog_pipes.ptr+i;
if (fdp->pid > 0) continue;
fdlog_pipe_restart(fdp, ts);
}
}
int
fdlog_pipes_waitpid_cb (const pid_t pid)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_pipe * const fdp = fdlog_pipes.ptr+i;
if (fdp->pid != pid) continue;
fdp->pid = -1;
return fdlog_pipe_restart(fdp, log_monotonic_secs);
}
return 0;
}
static void
fdlog_pipes_close (fdlog_st * const retain)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_pipe * const fdp = fdlog_pipes.ptr+i;
fdlog_st * const fdlog = fdp->fdlog;
close(fdp->fd);
fdp->fd = -1;
if (fdlog == retain) continue; /*(free'd later)*/
fdlog_free(fdlog);
}
free(fdlog_pipes.ptr);
fdlog_pipes.ptr = NULL;
fdlog_pipes.used = 0;
fdlog_pipes.size = 0;
}
void
fdlog_pipes_abandon_pids (void)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_pipe * const fdp = fdlog_pipes.ptr+i;
fdp->pid = -1;
}
}
void
fdlog_pipe_serrh (const int fd)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_st * const fdlog = fdlog_pipes.ptr[i].fdlog;
if (fdlog->fd != fd) continue;
fdlog->fd = STDERR_FILENO;
break;
}
}
static fdlog_st *
fdlog_pipe_init (const char * const fn, const int fds[2], const pid_t pid)
{
if (fdlog_pipes.used == fdlog_pipes.size) {
fdlog_pipes.size += 4;
fdlog_pipes.ptr =
realloc(fdlog_pipes.ptr, fdlog_pipes.size * sizeof(fdlog_pipe));
force_assert(fdlog_pipes.ptr);
}
fdlog_pipe * const fdp = fdlog_pipes.ptr + fdlog_pipes.used++;
fdp->fd = fds[0];
fdp->pid = pid;
fdp->start = log_monotonic_secs;
return (fdp->fdlog = fdlog_init(fn, fds[1], FDLOG_PIPE));
}
static fdlog_st *
fdlog_pipe_open (const char * const fn)
{
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
fdlog_st * const fdlog = fdlog_pipes.ptr[i].fdlog;
if (0 != strcmp(fdlog->fn, fn)) continue;
return fdlog;
}
int fds[2];
if (pipe(fds))
return NULL;
fdevent_setfd_cloexec(fds[0]);
fdevent_setfd_cloexec(fds[1]);
pid_t pid = fdlog_pipe_spawn(fn, fds[0]);
if (pid > 0) {
/*(nonblocking write() from lighttpd)*/
if (0 != fdevent_fcntl_set_nb(fds[1])) { /*(ignore)*/ }
return fdlog_pipe_init(fn, fds, pid);
}
else {
int errnum = errno;
close(fds[0]);
close(fds[1]);
errno = errnum;
return NULL;
}
}
static fdlog_st *
fdlog_file_init (const char * const fn, const int fd)
{
if (fdlog_files.used == fdlog_files.size) {
fdlog_files.size += 4;
fdlog_files.ptr =
realloc(fdlog_files.ptr, fdlog_files.size * sizeof(fdlog_st *));
force_assert(fdlog_files.ptr);
}
return (fdlog_files.ptr[fdlog_files.used++] = fdlog_init(fn,fd,FDLOG_FILE));
}
static int
fdlog_file_open_fd (const char * const fn)
{
int flags = O_APPEND | O_WRONLY | O_CREAT;
return fdevent_open_cloexec(fn, 1, flags, 0644); /*(permit symlinks)*/
}
static fdlog_st *
fdlog_file_open (const char * const fn)
{
for (uint32_t i = 0; i < fdlog_files.used; ++i) {
fdlog_st * const fdlog = fdlog_files.ptr[i];
if (0 != strcmp(fdlog->fn, fn)) continue;
return fdlog;
}
int fd = fdlog_file_open_fd(fn);
return (-1 != fd) ? fdlog_file_init(fn, fd) : NULL;
}
fdlog_st *
fdlog_open (const char * const fn)
{
return (fn[0] != '|')
? fdlog_file_open(fn)
: fdlog_pipe_open(fn+1); /*(skip the '|')*/
}
void
fdlog_files_flush (fdlog_st * const errh, const int memrel)
{
for (uint32_t i = 0; i < fdlog_files.used; ++i) {
fdlog_st * const fdlog = fdlog_files.ptr[i];
buffer * const b = &fdlog->b;
if (!buffer_is_blank(b)) {
const ssize_t wr = write_all(fdlog->fd, BUF_PTR_LEN(b));
buffer_clear(b); /*(clear buffer, even on error)*/
if (-1 == wr)
log_perror(errh, __FILE__, __LINE__,
"error flushing log %s", fdlog->fn);
}
if (memrel && b->ptr) buffer_free_ptr(b);
}
}
void
fdlog_files_cycle (fdlog_st * const errh)
{
fdlog_files_flush(errh, 0);
for (uint32_t i = 0; i < fdlog_files.used; ++i) {
fdlog_st * const fdlog = fdlog_files.ptr[i];
int fd = fdlog_file_open_fd(fdlog->fn);
if (-1 != fd) {
if (fdlog->fd != STDERR_FILENO) {
close(fdlog->fd);
fdlog->fd = fd;
}
else if (STDERR_FILENO == dup2(fd, STDERR_FILENO))
close(fd);
else
log_perror(errh, __FILE__, __LINE__,
"dup2() %s to STDERR", fdlog->fn);
}
else {
log_perror(errh, __FILE__, __LINE__,
"error cycling log %s", fdlog->fn);
/*(leave prior log file open)*/
}
}
}
static void
fdlog_files_close (fdlog_st * const retain)
{
fdlog_files_flush(retain, 0);
for (uint32_t i = 0; i < fdlog_files.used; ++i) {
fdlog_st * const fdlog = fdlog_files.ptr[i];
if (fdlog == retain) continue; /*(free'd later)*/
fdlog_free(fdlog);
}
free(fdlog_files.ptr);
fdlog_files.ptr = NULL;
fdlog_files.used = 0;
fdlog_files.size = 0;
}
void
fdlog_closeall (fdlog_st * const errh)
{
fdlog_files_close(errh);
fdlog_pipes_close(errh);
}
void
fdlog_flushall (fdlog_st * const errh)
{
fdlog_files_flush(errh, 1); /*(flush, then release buffer memory)*/
/*(at the moment, pipe loggers clear buffer after each write attempt,
* so there is nothing to flush, though there are buffers to be freed)*/
for (uint32_t i = 0; i < fdlog_pipes.used; ++i) {
buffer * const b = &fdlog_pipes.ptr[i].fdlog->b;
if (b->ptr) buffer_free_ptr(b);
}
if (errh->b.ptr) buffer_free_ptr(&errh->b);
}

48
src/log.c

@ -5,7 +5,6 @@
#include "first.h"
#include "ck.h"
#include "log.h"
#include <sys/types.h>
@ -21,6 +20,9 @@
# include <syslog.h>
#endif
#include "ck.h"
#include "fdlog.h"
/* log_con_jqueue instance here to be defined in shared object (see base.h) */
connection *log_con_jqueue;
@ -92,11 +94,11 @@ static int log_buffer_prepare(const log_error_st *errh, const char *filename, un
static unix_time64_t tlast;
static uint32_t tlen;
static char tstr[24]; /* 20 "%F %T" incl '\0' +3 ": (" */
switch(errh->errorlog_mode) {
case ERRORLOG_PIPE:
case ERRORLOG_FILE:
case ERRORLOG_FD:
if (-1 == errh->errorlog_fd) return -1;
switch(errh->mode) {
case FDLOG_PIPE:
case FDLOG_FILE:
case FDLOG_FD:
if (-1 == errh->fd) return -1;
/* cache the generated timestamp */
if (__builtin_expect( (tlast != log_epoch_secs), 0)) {
struct tm tm;
@ -112,7 +114,7 @@ static int log_buffer_prepare(const log_error_st *errh, const char *filename, un
buffer_copy_string_len(b, tstr, tlen);
break;
case ERRORLOG_SYSLOG:
case FDLOG_SYSLOG:
/* syslog is generating its own timestamps */
buffer_copy_string_len(b, CONST_STR_LEN("("));
break;
@ -127,14 +129,14 @@ static int log_buffer_prepare(const log_error_st *errh, const char *filename, un
}
static void log_write(const log_error_st *errh, buffer *b) {
switch(errh->errorlog_mode) {
case ERRORLOG_PIPE:
case ERRORLOG_FILE:
case ERRORLOG_FD:
switch(errh->mode) {
case FDLOG_PIPE:
case FDLOG_FILE:
case FDLOG_FD:
buffer_append_string_len(b, CONST_STR_LEN("\n"));
write_all(errh->errorlog_fd, BUF_PTR_LEN(b));
write_all(errh->fd, BUF_PTR_LEN(b));
break;
case ERRORLOG_SYSLOG:
case FDLOG_SYSLOG:
syslog(LOG_ERR, "%s", b->ptr);
break;
}
@ -281,23 +283,3 @@ log_error_multiline (log_error_st * const restrict errh,
errno = errnum;
}
log_error_st *
log_error_st_init (void)
{
log_error_st *errh = calloc(1, sizeof(log_error_st));
force_assert(errh);
errh->errorlog_fd = STDERR_FILENO;
errh->errorlog_mode = ERRORLOG_FD;
return errh;
}
void
log_error_st_free (log_error_st *errh)
{
if (NULL == errh) return;
free(errh->b.ptr);
free(errh);
}

15
src/log.h

@ -18,21 +18,6 @@ int log_clock_gettime_realtime (unix_timespec64_t *ts);
ssize_t write_all(int fd, const void* buf, size_t count);
struct log_error_st {
enum { ERRORLOG_FILE, ERRORLOG_FD, ERRORLOG_SYSLOG, ERRORLOG_PIPE } errorlog_mode;
int errorlog_fd;
buffer b;
const char *fn;
};
__attribute_cold__
__attribute_malloc__
__attribute_returns_nonnull__
log_error_st * log_error_st_init (void);
__attribute_cold__
void log_error_st_free (log_error_st *errh);
__attribute_cold__
__attribute_format__((__printf__, 4, 5))
void log_error(log_error_st *errh, const char *filename, unsigned int line, const char *fmt, ...);

10
src/meson.build

@ -730,6 +730,7 @@ common_src = [
'fdevent_solaris_devpoll.c',
'fdevent_solaris_port.c',
'fdevent.c',
'fdlog_maint.c',
'fdlog.c',
'gw_backend.c',
'http_cgi.c',
@ -898,6 +899,7 @@ test('test_configfile', executable('test_configfile',
'http_kv.c',
'vector.c',
'log.c',
'fdlog.c',
'sock_addr.c',
'ck.c',
],
@ -917,6 +919,7 @@ test('test_keyvalue', executable('test_keyvalue',
'base64.c',
'array.c',
'log.c',
'fdlog.c',
'ck.c',
],
dependencies: common_flags + libpcre + libunwind,
@ -929,6 +932,7 @@ test('test_mod_access', executable('test_mod_access',
'buffer.c',
'array.c',
'log.c',
'fdlog.c',
'ck.c',
],
dependencies: common_flags + libunwind,
@ -941,6 +945,7 @@ test('test_mod_evhost', executable('test_mod_evhost',
'buffer.c',
'array.c',
'log.c',
'fdlog.c',
'ck.c',
],
dependencies: common_flags + libunwind,
@ -960,6 +965,7 @@ test('test_mod_indexfile', executable('test_mod_indexfile',
'http_header.c',
'http_kv.c',
'log.c',
'fdlog.c',
'sock_addr.c',
'stat_cache.c',
'algo_splaytree.c',
@ -980,6 +986,7 @@ test('test_mod_simple_vhost', executable('test_mod_simple_vhost',
'buffer.c',
'array.c',
'log.c',
'fdlog.c',
'ck.c',
],
dependencies: common_flags + libunwind,
@ -1004,6 +1011,7 @@ test('test_mod_staticfile', executable('test_mod_staticfile',
'http_header.c',
'http_kv.c',
'log.c',
'fdlog.c',
'sock_addr.c',
'stat_cache.c',
'algo_splaytree.c',
@ -1024,6 +1032,7 @@ test('test_mod_userdir', executable('test_mod_userdir',
'buffer.c',
'array.c',
'log.c',
'fdlog.c',
'ck.c',
],
dependencies: common_flags + libunwind,
@ -1040,6 +1049,7 @@ test('test_request', executable('test_request',
'http_header.c',
'http_kv.c',
'log.c',
'fdlog.c',
'sock_addr.c',
'ck.c',
],

195
src/mod_accesslog.c

@ -148,30 +148,18 @@ typedef struct {
} format_fields;
typedef struct {
int log_access_fd;
fdlog_st *fdlog;
char use_syslog; /* syslog has global buffer */
char piped_logger;
unsigned short syslog_level;
buffer *access_logbuffer; /* each logfile has a separate buffer */
const buffer *access_logfile;
format_fields *parsed_format;
} plugin_config;
typedef struct {
int log_access_fd;
char piped_logger;
const buffer *access_logfile;
buffer access_logbuffer; /* each logfile has a separate buffer */
} accesslog_st;
typedef struct {
PLUGIN_DATA;
plugin_config defaults;
plugin_config conf;
buffer syslog_logbuffer; /* syslog has global buffer. no caching, always written directly */
log_error_st *errh; /* copy of srv->errh */
format_fields *default_format;/* allocated if default format */
} plugin_data;
@ -179,12 +167,6 @@ INIT_FUNC(mod_accesslog_init) {
return calloc(1, sizeof(plugin_data));
}
static int accesslog_write_all(const int fd, buffer * const b) {
const ssize_t wr = (fd >= 0) ? write_all(fd, BUF_PTR_LEN(b)) : 0;
buffer_clear(b); /*(clear buffer, even if fd < 0)*/
return (-1 != wr);
}
static void accesslog_append_escaped_str(buffer * const dest, const char * const str, const size_t len) {
const char *ptr, *start, *end;
@ -421,19 +403,6 @@ static format_fields * accesslog_parse_format(const char * const format, const s
return fields;
}
static void mod_accesslog_free_accesslog(accesslog_st * const x, plugin_data *p) {
/*(piped loggers are closed in fdlog_pipes_close())*/
if (!x->piped_logger && -1 != x->log_access_fd) {
if (!accesslog_write_all(x->log_access_fd, &x->access_logbuffer)) {
log_perror(p->errh, __FILE__, __LINE__,
"writing access log entry failed: %s", x->access_logfile->ptr);
}
close(x->log_access_fd);
}
free(x->access_logbuffer.ptr);
free(x);
}
static void mod_accesslog_free_format_fields(format_fields * const ff) {
for (format_field *f = ff->ptr; f->type != FIELD_UNSET; ++f)
free(f->string.ptr);
@ -443,7 +412,6 @@ static void mod_accesslog_free_format_fields(format_fields * const ff) {
FREE_FUNC(mod_accesslog_free) {
plugin_data * const p = p_d;
free(p->syslog_logbuffer.ptr);
if (NULL == p->cvlist) return;
/* (init i to 0 if global context; to 1 to skip empty global context) */
for (int i = !p->cvlist[0].v.u2[1], used = p->nconfig; i < used; ++i) {
@ -452,7 +420,7 @@ FREE_FUNC(mod_accesslog_free) {
if (cpv->vtype != T_CONFIG_LOCAL || NULL == cpv->v.v) continue;
switch (cpv->k_id) {
case 0: /* accesslog.filename */
mod_accesslog_free_accesslog(cpv->v.v, p);
/*(handled by fdlog_closeall())*/
break;
case 1: /* accesslog.format */
mod_accesslog_free_format_fields(cpv->v.v);
@ -472,11 +440,7 @@ static void mod_accesslog_merge_config_cpv(plugin_config * const pconf, const co
switch (cpv->k_id) { /* index into static config_plugin_keys_t cpk[] */
case 0:{/* accesslog.filename */
if (cpv->vtype != T_CONFIG_LOCAL) break;
accesslog_st * const x = cpv->v.v;
pconf->log_access_fd = x->log_access_fd;
pconf->piped_logger = x->piped_logger;
pconf->access_logfile = x->access_logfile;
pconf->access_logbuffer = &x->access_logbuffer;
pconf->fdlog = cpv->v.v;
break;
}
case 1:{/* accesslog.format */
@ -531,7 +495,6 @@ SETDEFAULTS_FUNC(mod_accesslog_set_defaults) {
};
plugin_data * const p = p_d;
p->errh = srv->errh;
if (!config_plugin_values_init(srv, p, cpk, "mod_accesslog"))
return HANDLER_ERROR;
@ -540,17 +503,16 @@ SETDEFAULTS_FUNC(mod_accesslog_set_defaults) {
for (int i = !p->cvlist[0].v.u2[1]; i < p->nconfig; ++i) {
config_plugin_value_t *cpv = p->cvlist + p->cvlist[i].v.u2[0];
int use_syslog = 0;
accesslog_st *x = NULL;
config_plugin_value_t *cpvfile = NULL;
for (; -1 != cpv->k_id; ++cpv) {
switch (cpv->k_id) {
case 0: /* accesslog.filename */
x = calloc(1, sizeof(accesslog_st));
force_assert(x);
x->log_access_fd = -1;
x->piped_logger = (cpv->v.b->ptr[0] == '|');
x->access_logfile = cpv->v.b;
cpv->vtype = T_CONFIG_LOCAL;
cpv->v.v = x;
if (!buffer_is_blank(cpv->v.b))
cpvfile = cpv;
else {
cpv->v.v = NULL;
cpv->vtype = T_CONFIG_LOCAL;
}
break;
case 1: /* accesslog.format */
if (NULL != strchr(cpv->v.b->ptr, '\\')) {
@ -594,17 +556,18 @@ SETDEFAULTS_FUNC(mod_accesslog_set_defaults) {
if (srv->srvconf.preflight_check) continue;
if (use_syslog) continue; /* ignore the next checks */
if (NULL == x || buffer_is_blank(x->access_logfile)) continue;
x->log_access_fd = fdlog_open(x->access_logfile->ptr);
if (-1 == x->log_access_fd) {
cpv = cpvfile; /* accesslog.filename handled after preflight_check */
if (NULL == cpv) continue;
const char * const fn = cpv->v.b->ptr;
cpv->v.v = fdlog_open(fn);
cpv->vtype = T_CONFIG_LOCAL;
if (NULL == cpv->v.v) {
log_perror(srv->errh, __FILE__, __LINE__,
"opening log '%s' failed", x->access_logfile->ptr);
"opening log '%s' failed", fn);
return HANDLER_ERROR;
}
}
p->defaults.log_access_fd = -1;
p->defaults.syslog_level = LOG_INFO;
/* initialize p->defaults from global config context */
@ -722,72 +685,10 @@ static format_fields * mod_accesslog_process_format(const char * const format, c
return parsed_format;
}
static void log_access_flush(plugin_data * const p) {
/* future: might be slightly faster to have allocated array of open files
* rather than walking config, but only might matter with many directives */
/* (init i to 0 if global context; to 1 to skip empty global context) */
for (int i = !p->cvlist[0].v.u2[1]; i < p->nconfig; ++i) {
config_plugin_value_t *cpv = p->cvlist + p->cvlist[i].v.u2[0];
for (; -1 != cpv->k_id; ++cpv) {
switch (cpv->k_id) {
case 0: /* accesslog.filename */
if (cpv->vtype == T_CONFIG_LOCAL && NULL != cpv->v.v) {
accesslog_st * const x = cpv->v.v;
if (buffer_is_blank(&x->access_logbuffer)) continue;
if (!accesslog_write_all(x->log_access_fd,
&x->access_logbuffer)) {
log_perror(p->errh, __FILE__, __LINE__,
"writing access log entry failed: %s",
x->access_logfile->ptr);
}
}
break;
default:
break;
}
}
}
}
TRIGGER_FUNC(log_access_periodic_flush) {
UNUSED(p_d);
/* flush buffered access logs every 4 seconds */
if (0 == (log_monotonic_secs & 3)) log_access_flush((plugin_data *)p_d);
UNUSED(srv);
return HANDLER_GO_ON;
}
SIGHUP_FUNC(log_access_cycle) {
plugin_data * const p = p_d;
log_access_flush(p);
/* future: might be slightly faster to have allocated array of open files
* rather than walking config, but only might matter with many directives */
/* (init i to 0 if global context; to 1 to skip empty global context) */
for (int i = !p->cvlist[0].v.u2[1]; i < p->nconfig; ++i) {
config_plugin_value_t *cpv = p->cvlist + p->cvlist[i].v.u2[0];
for (; -1 != cpv->k_id; ++cpv) {
if (cpv->vtype != T_CONFIG_LOCAL || NULL == cpv->v.v) continue;
switch (cpv->k_id) {
case 0:{/* accesslog.filename */
accesslog_st * const x = cpv->v.v;
if (x->piped_logger) continue;
if (buffer_is_blank(x->access_logfile)) continue;
if (-1 == fdlog_cycle(x->access_logfile->ptr,
&x->log_access_fd)) {
log_perror(srv->errh, __FILE__, __LINE__,
"cycling access log failed: %s", x->access_logfile->ptr);
}
/*(update p->defaults after cycling log)*/
if (0 == i) p->defaults.log_access_fd = x->log_access_fd;
break;
}
default:
break;
}