1/* -*- Mode: C; tab-width: 4; c-basic-offset: 4; indent-tabs-mode: nil -*- */23#include <arpa/inet.h>4#include <stdlib.h>5#include <stdio.h>6#include <string.h>7#include <errno.h>8#include <poll.h>9#include <stdarg.h>1011#if defined(__sun)12#include <atomic.h>13#endif1415#include "memcached.h"16#include "bipbuffer.h"1718#ifdef LOGGER_DEBUG19#define L_DEBUG(...) \20    do { \21        fprintf(stderr, __VA_ARGS__); \22    } while (0)23#else24#define L_DEBUG(...)25#endif262728/* TODO: put this in a struct and ditch the global vars. */29static logger *logger_stack_head = NULL;30static logger *logger_stack_tail = NULL;31static unsigned int logger_count = 0;32static volatile int do_run_logger_thread = 1;33static pthread_t logger_tid;34pthread_mutex_t logger_stack_lock = PTHREAD_MUTEX_INITIALIZER;35pthread_cond_t logger_stack_cond = PTHREAD_COND_INITIALIZER;3637pthread_key_t logger_key;3839#if !defined(HAVE_GCC_64ATOMICS) && !defined(__sun)40pthread_mutex_t logger_atomics_mutex = PTHREAD_MUTEX_INITIALIZER;41#endif4243#define WATCHER_LIMIT 2044logger_watcher *watchers[20];45struct pollfd watchers_pollfds[20];46int watcher_count = 0;4748#define WATCHER_ALL -149static int logger_thread_poll_watchers(int force_poll, int watcher);5051/* helpers for logger_log */5253static void _logger_log_text(logentry *e, const entry_details *d, const void *entry, va_list ap) {54    int reqlen = d->reqlen;55    int total = vsnprintf((char *) e->data, reqlen, d->format, ap);56    if (total <= 0) {57        fprintf(stderr, "LOGGER: Failed to vsnprintf a text entry: (total) %d\n", total);58    }59    e->size = total + 1; // null byte60}6162static void _logger_log_evictions(logentry *e, const entry_details *d, const void *entry, va_list ap) {63    item *it = (item *)entry;64    struct logentry_eviction *le = (struct logentry_eviction *) e->data;6566    le->exptime = (it->exptime > 0) ? (long long int)(it->exptime - current_time) : (long long int) -1;67    le->latime = current_time - it->time;68    le->it_flags = it->it_flags;69    le->nkey = it->nkey;70    le->nbytes = it->nbytes;71    le->clsid = ITEM_clsid(it);72    memcpy(le->key, ITEM_key(it), it->nkey);73    e->size = sizeof(struct logentry_eviction) + le->nkey;74}75#ifdef EXTSTORE76static void _logger_log_ext_write(logentry *e, const entry_details *d, const void *entry, va_list ap) {77    item *it = (item *)entry;78    int ew_bucket = va_arg(ap, int);7980    struct logentry_ext_write *le = (struct logentry_ext_write *) e->data;81    le->exptime = (it->exptime > 0) ? (long long int)(it->exptime - current_time) : (long long int) -1;82    le->latime = current_time - it->time;83    le->it_flags = it->it_flags;84    le->nkey = it->nkey;85    le->clsid = ITEM_clsid(it);86    le->bucket = (uint8_t)ew_bucket;87    memcpy(le->key, ITEM_key(it), it->nkey);88    e->size = sizeof(struct logentry_ext_write) + le->nkey;89}90#endif91// 0 == nf, 1 == found. 2 == flushed. 3 == expired.92// might be useful to store/print the flags an item has?93// could also collapse this and above code into an "item status" struct. wait94// for more endpoints to be written before making it generic, though.95static void _logger_log_item_get(logentry *e, const entry_details *d, const void *entry, va_list ap) {96    int was_found = va_arg(ap, int);97    char *key = va_arg(ap, char *);98    int nkey = va_arg(ap, int);99    int nbytes = va_arg(ap, int);100    uint8_t clsid = va_arg(ap, int);101    int sfd = va_arg(ap, int);102103    struct logentry_item_get *le = (struct logentry_item_get *) e->data;104    le->was_found = was_found;105    le->nkey = nkey;106    le->nbytes = nbytes;107    le->clsid = clsid;108    memcpy(le->key, key, nkey);109    le->sfd = sfd;110    e->size = sizeof(struct logentry_item_get) + nkey;111}112113static void _logger_log_item_store(logentry *e, const entry_details *d, const void *entry, va_list ap) {114    enum store_item_type status = va_arg(ap, enum store_item_type);115    int comm = va_arg(ap, int);116    char *key = va_arg(ap, char *);117    int nkey = va_arg(ap, int);118    int nbytes = va_arg(ap, int);119    rel_time_t ttl = va_arg(ap, rel_time_t);120    uint8_t clsid = va_arg(ap, int);121    int sfd = va_arg(ap, int);122123    struct logentry_item_store *le = (struct logentry_item_store *) e->data;124    le->status = status;125    le->cmd = comm;126    le->nkey = nkey;127    le->nbytes = nbytes;128    le->clsid = clsid;129    if (ttl != 0) {130        le->ttl = ttl - current_time;131    } else {132        le->ttl = 0;133    }134    memcpy(le->key, key, nkey);135    le->sfd = sfd;136    e->size = sizeof(struct logentry_item_store) + nkey;137}138139static void _logger_log_item_deleted(logentry *e, const entry_details *d, const void *entry, va_list ap) {140    item *it = (item *)entry;141    int comm = va_arg(ap, int);142    struct logentry_deletion *le = (struct logentry_deletion *) e->data;143    le->nkey = it->nkey;144    le->cmd = comm;145    le->nbytes = it->nbytes;146    le->clsid = ITEM_clsid(it);147    memcpy(le->key, ITEM_key(it), it->nkey);148    e->size = sizeof(struct logentry_deletion) + le->nkey;149}150151static void _logger_log_conn_event(logentry *e, const entry_details *d, const void *entry, va_list ap) {152    struct sockaddr_in6 *addr = va_arg(ap, struct sockaddr_in6 *);153    socklen_t addrlen = va_arg(ap, socklen_t);154    enum network_transport transport = va_arg(ap, enum network_transport);155    enum close_reasons reason = va_arg(ap, enum close_reasons);156    int sfd = va_arg(ap, int);157158    struct logentry_conn_event *le = (struct logentry_conn_event *) e->data;159160    memcpy(&le->addr, addr, addrlen);161    le->sfd = sfd;162    le->transport = transport;163    le->reason = reason;164    e->size = sizeof(struct logentry_conn_event);165}166167/*************************168 * Util functions used by the logger background thread169 *************************/170171static int _logger_util_addr_endpoint(struct sockaddr_in6 *addr, char *rip,172        size_t riplen, unsigned short *rport) {173    memset(rip, 0, riplen);174    *rport = 0;175176    switch (addr->sin6_family) {177        case AF_INET:178            inet_ntop(AF_INET, &((struct sockaddr_in *) addr)->sin_addr,179                    rip, riplen - 1);180            *rport = ntohs(((struct sockaddr_in *) addr)->sin_port);181            break;182        case AF_INET6:183            inet_ntop(AF_INET6, &((struct sockaddr_in6 *) addr)->sin6_addr,184                    rip, riplen - 1);185            *rport = ntohs(((struct sockaddr_in6 *) addr)->sin6_port);186            break;187#ifndef DISABLE_UNIX_SOCKET188        // Connections on Unix socket transports have c->request_addr zeroed out.189        case AF_UNSPEC:190        case AF_UNIX:191            strncpy(rip, "unix", strlen("unix") + 1);192            break;193#endif // #ifndef DISABLE_UNIX_SOCKET194    }195196    return 0;197}198199/*************************200 * Logger background thread functions. Aggregates per-worker buffers and201 * writes to any watchers.202 *************************/203204#define LOGGER_PARSE_SCRATCH 4096205206static int _logger_parse_text(logentry *e, char *scratch) {207    return snprintf(scratch, LOGGER_PARSE_SCRATCH, "ts=%lld.%d gid=%llu %s\n",208            (long long int)e->tv.tv_sec, (int)e->tv.tv_usec,209            (unsigned long long) e->gid, (char *) e->data);210}211212static int _logger_parse_ise(logentry *e, char *scratch) {213    int total;214    const char *cmd = "na";215    char keybuf[KEY_MAX_URI_ENCODED_LENGTH];216    struct logentry_item_store *le = (struct logentry_item_store *) e->data;217    const char * const status_map[] = {218        "not_stored", "stored", "exists", "not_found", "too_large", "no_memory" };219    const char * const cmd_map[] = {220        "null", "add", "set", "replace", "append", "prepend", "cas", "append", "prepend" };221222    if (le->cmd <= 8)223        cmd = cmd_map[le->cmd];224225    uriencode(le->key, keybuf, le->nkey, KEY_MAX_URI_ENCODED_LENGTH);226    total = snprintf(scratch, LOGGER_PARSE_SCRATCH,227            "ts=%lld.%d gid=%llu type=item_store key=%s status=%s cmd=%s ttl=%u clsid=%u cfd=%d size=%d\n",228            (long long int)e->tv.tv_sec, (int)e->tv.tv_usec, (unsigned long long) e->gid,229            keybuf, status_map[le->status], cmd, le->ttl, le->clsid, le->sfd,230            le->nbytes > 0 ? le->nbytes - 2 : 0); // CLRF231    return total;232}233234static int _logger_parse_ige(logentry *e, char *scratch) {235    int total;236    struct logentry_item_get *le = (struct logentry_item_get *) e->data;237    char keybuf[KEY_MAX_URI_ENCODED_LENGTH];238    const char * const was_found_map[] = {239        "not_found", "found", "flushed", "expired" };240241    uriencode(le->key, keybuf, le->nkey, KEY_MAX_URI_ENCODED_LENGTH);242    total = snprintf(scratch, LOGGER_PARSE_SCRATCH,243            "ts=%lld.%d gid=%llu type=item_get key=%s status=%s clsid=%u cfd=%d size=%d\n",244            (long long int)e->tv.tv_sec, (int)e->tv.tv_usec, (unsigned long long) e->gid,245            keybuf, was_found_map[le->was_found], le->clsid, le->sfd,246            le->nbytes > 0 ? le->nbytes - 2 : 0); // CLRF247    return total;248}249250static int _logger_parse_ee(logentry *e, char *scratch) {251    int total;252    char keybuf[KEY_MAX_URI_ENCODED_LENGTH];253    struct logentry_eviction *le = (struct logentry_eviction *) e->data;254    uriencode(le->key, keybuf, le->nkey, KEY_MAX_URI_ENCODED_LENGTH);255    total = snprintf(scratch, LOGGER_PARSE_SCRATCH,256            "ts=%lld.%d gid=%llu type=eviction key=%s fetch=%s ttl=%lld la=%d clsid=%u size=%d\n",257            (long long int)e->tv.tv_sec, (int)e->tv.tv_usec, (unsigned long long) e->gid,258            keybuf, (le->it_flags & ITEM_FETCHED) ? "yes" : "no",259            (long long int)le->exptime, le->latime, le->clsid,260            le->nbytes > 0 ? le->nbytes - 2 : 0); // CLRF261262    return total;263}264265static int _logger_parse_ide(logentry *e, char *scratch) {266    int total;267    const char *cmd = "na";268    const char * const cmd_map[] = {269            "null", "delete", "md" };270    char keybuf[KEY_MAX_URI_ENCODED_LENGTH];271    struct logentry_deletion *le = (struct logentry_deletion *) e->data;272    uriencode(le->key, keybuf, le->nkey, KEY_MAX_URI_ENCODED_LENGTH);273274    if (le->cmd <= 2)275        cmd = cmd_map[le->cmd];276277    total = snprintf(scratch, LOGGER_PARSE_SCRATCH,278                     "ts=%d.%d gid=%llu type=deleted key=%s cmd=%s clsid=%u size=%d\n",279                     (int)e->tv.tv_sec, (int)e->tv.tv_usec, (unsigned long long) e->gid,280                     keybuf, cmd, le->clsid,281                     le->nbytes > 0 ? le->nbytes - 2 : 0); // CLRF282    return total;283}284285#ifdef EXTSTORE286static int _logger_parse_extw(logentry *e, char *scratch) {287    int total;288    char keybuf[KEY_MAX_URI_ENCODED_LENGTH];289    struct logentry_ext_write *le = (struct logentry_ext_write *) e->data;290    uriencode(le->key, keybuf, le->nkey, KEY_MAX_URI_ENCODED_LENGTH);291    total = snprintf(scratch, LOGGER_PARSE_SCRATCH,292            "ts=%lld.%d gid=%llu type=extwrite key=%s fetch=%s ttl=%lld la=%d clsid=%u bucket=%u\n",293            (long long int)e->tv.tv_sec, (int)e->tv.tv_usec, (unsigned long long) e->gid,294            keybuf, (le->it_flags & ITEM_FETCHED) ? "yes" : "no",295            (long long int)le->exptime, le->latime, le->clsid, le->bucket);296297    return total;298}299#endif300301static int _logger_parse_cne(logentry *e, char *scratch) {302    int total;303    unsigned short rport = 0;304    char rip[64];305    struct logentry_conn_event *le = (struct logentry_conn_event *) e->data;306    const char * const transport_map[] = { "local", "tcp", "udp" };307308    _logger_util_addr_endpoint(&le->addr, rip, sizeof(rip), &rport);309310    total = snprintf(scratch, LOGGER_PARSE_SCRATCH,311            "ts=%lld.%d gid=%llu type=conn_new rip=%s rport=%hu transport=%s cfd=%d\n",312            (long long int) e->tv.tv_sec, (int) e->tv.tv_usec, (unsigned long long) e->gid,313            rip, rport, transport_map[le->transport], le->sfd);314315    return total;316}317318static int _logger_parse_cce(logentry *e, char *scratch) {319    int total;320    unsigned short rport = 0;321    char rip[64];322    struct logentry_conn_event *le = (struct logentry_conn_event *) e->data;323    const char * const transport_map[] = { "local", "tcp", "udp" };324    const char * const reason_map[] = { "error", "normal", "idle_timeout", "shutdown" };325326    _logger_util_addr_endpoint(&le->addr, rip, sizeof(rip), &rport);327328    total = snprintf(scratch, LOGGER_PARSE_SCRATCH,329            "ts=%lld.%d gid=%llu type=conn_close rip=%s rport=%hu transport=%s reason=%s cfd=%d\n",330            (long long int) e->tv.tv_sec, (int) e->tv.tv_usec, (unsigned long long) e->gid,331            rip, rport, transport_map[le->transport],332            reason_map[le->reason], le->sfd);333334    return total;335}336337#ifdef PROXY338// TODO (v2): the length caps here are all magic numbers. Haven't thought of339// something yet that I like better.340// Should at least make a define to the max log len (1024) and do some math341// here.342static void _logger_log_proxy_req(logentry *e, const entry_details *d, const void *entry, va_list ap) {343    char *req = va_arg(ap, char *);344    int reqlen = va_arg(ap, uint32_t);345    long elapsed = va_arg(ap, long);346    unsigned short type = va_arg(ap, int);347    unsigned short code = va_arg(ap, int);348    int status = va_arg(ap, int);349    int flag = va_arg(ap, int);350    int conn_fd = va_arg(ap, int);351    char *detail = va_arg(ap, char *);352    int dlen = va_arg(ap, int);353    char *be_name = va_arg(ap, char *);354    char *be_port = va_arg(ap, char *);355356    struct logentry_proxy_req *le = (void *)e->data;357    le->type = type;358    le->code = code;359    le->status = status;360    le->flag = flag;361    le->conn_fd = conn_fd;362    le->dlen = dlen;363    le->elapsed = elapsed;364    if (be_name && be_port) {365        le->be_namelen = strlen(be_name);366        le->be_portlen = strlen(be_port);367    } else {368        le->be_namelen = 0;369        le->be_portlen = 0;370    }371    char *data = le->data;372    if (req[reqlen-2] == '\r') {373        reqlen -= 2;374    } else {375        reqlen--;376    }377    if (reqlen > 300) {378        reqlen = 300;379    }380    if (dlen > 150) {381        dlen = 150;382        le->dlen = dlen;383    }384    // be_namelen and be_portlen can't be longer than 255+6385    le->reqlen = reqlen;386    memcpy(data, req, reqlen);387    data += reqlen;388    memcpy(data, detail, dlen);389    data += dlen;390    memcpy(data, be_name, le->be_namelen);391    data += le->be_namelen;392    memcpy(data, be_port, le->be_portlen);393    e->size = sizeof(struct logentry_proxy_req) + reqlen + dlen + le->be_namelen + le->be_portlen;394}395396// FIXME: if I ever get better discipline around headers we can include the397// proxy header. Since proxy.h includes memcached.h we need to redefine things398// here.399#define RQUEUE_R_GOOD (1<<3)400#define RQUEUE_R_OK (1<<4)401#define RQUEUE_R_ANY (1<<5)402static int _logger_parse_prx_req(logentry *e, char *scratch) {403    int total;404    struct logentry_proxy_req *le = (void *)e->data;405    const char *rqu_res = "any";406    if (le->flag & RQUEUE_R_GOOD) {407        rqu_res = "good";408    } else if (le->flag & RQUEUE_R_OK) {409        rqu_res = "ok";410    }411412    total = snprintf(scratch, LOGGER_PARSE_SCRATCH,413            "ts=%lld.%d gid=%llu type=proxy_req elapsed=%lu type=%d code=%d status=%d res=%s cfd=%d be=%.*s:%.*s detail=%.*s req=%.*s\n",414            (long long int) e->tv.tv_sec, (int) e->tv.tv_usec, (unsigned long long) e->gid,415            le->elapsed, le->type, le->code, le->status, rqu_res, le->conn_fd,416            (int)le->be_namelen, le->data+le->reqlen+le->dlen,417            (int)le->be_portlen, le->data+le->reqlen+le->dlen+le->be_namelen, // fml.418            (int)le->dlen, le->data+le->reqlen, (int)le->reqlen, le->data419            );420    return total;421}422423#define MAX_RBUF_READ 100424static void _logger_log_proxy_errbe(logentry *e, const entry_details *d, const void *entry, va_list ap) {425    char *errmsg = va_arg(ap, char *);426    char *be_name = va_arg(ap, char *);427    char *be_port = va_arg(ap, char *);428    char *be_label = va_arg(ap, char *);429    int be_depth = va_arg(ap, int);430    char *be_rbuf = va_arg(ap, char *);431    int be_rbuflen = va_arg(ap, int);432    int be_retry = va_arg(ap, int);433434    struct logentry_proxy_errbe *le = (void *)e->data;435    le->be_depth = be_depth;436    le->retry = be_retry;437    le->errlen = strlen(errmsg);438    if (be_name && be_port) {439        le->be_namelen = strlen(be_name);440        le->be_portlen = strlen(be_port);441    }442443    if (be_label) {444        le->be_labellen = strlen(be_label);445    }446447    le->be_rbuflen = be_rbuflen;448    if (be_rbuflen > MAX_RBUF_READ) {449        le->be_rbuflen = MAX_RBUF_READ;450    }451452    char *data = le->data;453    memcpy(data, errmsg, le->errlen);454    data += le->errlen;455    memcpy(data, be_name, le->be_namelen);456    data += le->be_namelen;457    memcpy(data, be_port, le->be_portlen);458    data += le->be_portlen;459    memcpy(data, be_label, le->be_labellen);460    data += le->be_labellen;461    memcpy(data, be_rbuf, le->be_rbuflen);462    data += le->be_rbuflen;463464    e->size = sizeof(struct logentry_proxy_errbe) + (data - le->data);465}466467static int _logger_parse_prx_errbe(logentry *e, char *scratch) {468    int total;469    char rbuf[MAX_RBUF_READ * 3]; // x 3 for worst case URI encoding.470    struct logentry_proxy_errbe *le = (void *)e->data;471    char *data = le->data;472    char *errmsg = data;473    data += le->errlen;474    char *be_name = data;475    data += le->be_namelen;476    char *be_port = data;477    data += le->be_portlen;478    char *be_label = data;479    data += le->be_labellen;480    char *be_rbuf = data;481482    uriencode(be_rbuf, rbuf, le->be_rbuflen, MAX_RBUF_READ * 3);483    if (le->retry) {484        total = snprintf(scratch, LOGGER_PARSE_SCRATCH,485                "ts=%lld.%d gid=%llu type=proxy_backend error=%.*s name=%.*s port=%.*s label=%.*s retry=%d\n",486                (long long int)e->tv.tv_sec, (int)e->tv.tv_usec, (unsigned long long) e->gid,487                (int)le->errlen, errmsg, (int)le->be_namelen, be_name,488                (int)le->be_portlen, be_port, (int)le->be_labellen, be_label, le->retry);489    } else {490        total = snprintf(scratch, LOGGER_PARSE_SCRATCH,491                "ts=%lld.%d gid=%llu type=proxy_backend error=%.*s name=%.*s port=%.*s label=%.*s depth=%d rbuf=%s\n",492                (long long int)e->tv.tv_sec, (int)e->tv.tv_usec, (unsigned long long) e->gid,493                (int)le->errlen, errmsg, (int)le->be_namelen, be_name,494                (int)le->be_portlen, be_port, (int)le->be_labellen, be_label, le->be_depth, rbuf);495    }496497    return total;498}499#endif500501/* Should this go somewhere else? */502static const entry_details default_entries[] = {503    [LOGGER_ASCII_CMD] = {512, LOG_RAWCMDS, _logger_log_text, _logger_parse_text, "<%d %s"},504    [LOGGER_EVICTION] = {512, LOG_EVICTIONS, _logger_log_evictions, _logger_parse_ee, NULL},505    [LOGGER_ITEM_GET] = {512, LOG_FETCHERS, _logger_log_item_get, _logger_parse_ige, NULL},506    [LOGGER_ITEM_STORE] = {512, LOG_MUTATIONS, _logger_log_item_store, _logger_parse_ise, NULL},507    [LOGGER_CRAWLER_STATUS] = {512, LOG_SYSEVENTS, _logger_log_text, _logger_parse_text,508        "type=lru_crawler crawler=%d lru=%s low_mark=%llu next_reclaims=%llu since_run=%u next_run=%d elapsed=%u examined=%llu reclaimed=%llu"509    },510    [LOGGER_SLAB_MOVE] = {512, LOG_SYSEVENTS, _logger_log_text, _logger_parse_text,511        "type=slab_move src=%d dst=%d state=%s"512    },513    [LOGGER_CONNECTION_NEW] = {512, LOG_CONNEVENTS, _logger_log_conn_event, _logger_parse_cne, NULL},514    [LOGGER_CONNECTION_CLOSE] = {512, LOG_CONNEVENTS, _logger_log_conn_event, _logger_parse_cce, NULL},515    [LOGGER_CONNECTION_ERROR] = {512, LOG_CONNEVENTS, _logger_log_text, _logger_parse_text,516        "type=connerr fd=%d msg=%s"517    },518    [LOGGER_CONNECTION_TLSERROR] = {512, LOG_CONNEVENTS, _logger_log_text, _logger_parse_text,519        "type=conntlserr fd=%d msg=%s"520    },521    [LOGGER_DELETIONS] = {512, LOG_DELETIONS, _logger_log_item_deleted, _logger_parse_ide, NULL},522#ifdef EXTSTORE523    [LOGGER_EXTSTORE_WRITE] = {512, LOG_EVICTIONS, _logger_log_ext_write, _logger_parse_extw, NULL},524    [LOGGER_COMPACT_START] = {512, LOG_SYSEVENTS, _logger_log_text, _logger_parse_text,525        "type=compact_start id=%lu version=%llu"526    },527    [LOGGER_COMPACT_ABORT] = {512, LOG_SYSEVENTS, _logger_log_text, _logger_parse_text,528        "type=compact_abort id=%lu"529    },530    [LOGGER_COMPACT_READ_START] = {512, LOG_SYSEVENTS, _logger_log_text, _logger_parse_text,531        "type=compact_read_start id=%lu offset=%llu"532    },533    [LOGGER_COMPACT_READ_END] = {512, LOG_SYSEVENTS, _logger_log_text, _logger_parse_text,534        "type=compact_read_end id=%lu offset=%llu rescues=%lu rescues_realloc=%lu lost=%lu lost_oom=%lu skipped=%lu"535    },536    [LOGGER_COMPACT_END] = {512, LOG_SYSEVENTS, _logger_log_text, _logger_parse_text,537        "type=compact_end id=%lu"538    },539    [LOGGER_COMPACT_FRAGINFO] = {512, LOG_SYSEVENTS, _logger_log_text, _logger_parse_text,540        "type=compact_fraginfo ratio=%.2f bytes=%lu"541    },542#endif543#ifdef PROXY544    [LOGGER_PROXY_CONFIG] = {512, LOG_PROXYEVENTS, _logger_log_text, _logger_parse_text,545        "type=proxy_conf status=%s"546    },547    [LOGGER_PROXY_REQ] = {1024, LOG_PROXYREQS, _logger_log_proxy_req, _logger_parse_prx_req, NULL},548    [LOGGER_PROXY_ERROR] = {512, LOG_PROXYEVENTS, _logger_log_text, _logger_parse_text,549        "type=proxy_error msg=%s"550    },551    [LOGGER_PROXY_USER] = {512, LOG_PROXYUSER, _logger_log_text, _logger_parse_text,552        "type=proxy_user msg=%s"553    },554    [LOGGER_PROXY_BE_ERROR] = {1024, LOG_PROXYEVENTS, _logger_log_proxy_errbe, _logger_parse_prx_errbe,555        NULL556    },557558#endif559};560561/*************************562 * Util functions shared between bg thread and workers563 *************************/564565/* Logger GID's can be used by watchers to put logs back into strict order566 */567static uint64_t logger_gid = 0;568uint64_t logger_get_gid(void) {569#ifdef HAVE_GCC_64ATOMICS570    return __sync_add_and_fetch(&logger_gid, 1);571#elif defined(__sun)572    return atomic_inc_64_nv(&logger_gid);573#else574    mutex_lock(&logger_atomics_mutex);575    uint64_t res = ++logger_gid;576    mutex_unlock(&logger_atomics_mutex);577    return res;578#endif579}580581void logger_set_gid(uint64_t gid) {582#ifdef HAVE_GCC_64ATOMICS583    __sync_add_and_fetch(&logger_gid, gid);584#elif defined(__sun)585    atomic_add_64(&logger_gid);586#else587    mutex_lock(&logger_atomics_mutex);588    logger_gid = gid;589    mutex_unlock(&logger_atomics_mutex);590#endif591}592593/* TODO: genericize lists. would be nice to import queue.h if the impact is594 * studied... otherwise can just write a local one.595 */596/* Add to the list of threads with a logger object */597static void logger_link_q(logger *l) {598    pthread_mutex_lock(&logger_stack_lock);599    assert(l != logger_stack_head);600601    l->prev = 0;602    l->next = logger_stack_head;603    if (l->next) l->next->prev = l;604    logger_stack_head = l;605    if (logger_stack_tail == 0) logger_stack_tail = l;606    logger_count++;607    pthread_mutex_unlock(&logger_stack_lock);608    return;609}610611/* Remove from the list of threads with a logger object */612/*static void logger_unlink_q(logger *l) {613    pthread_mutex_lock(&logger_stack_lock);614    if (logger_stack_head == l) {615        assert(l->prev == 0);616        logger_stack_head = l->next;617    }618    if (logger_stack_tail == l) {619        assert(l->next == 0);620        logger_stack_tail = l->prev;621    }622    assert(l->next != l);623    assert(l->prev != l);624625    if (l->next) l->next->prev = l->prev;626    if (l->prev) l->prev->next = l->next;627    logger_count--;628    pthread_mutex_unlock(&logger_stack_lock);629    return;630}*/631632/* Called with logger stack locked.633 * Iterates over every watcher collecting enabled flags.634 */635static void logger_set_flags(void) {636    logger *l = NULL;637    int x = 0;638    uint16_t f = 0; /* logger eflags */639640    for (x = 0; x < WATCHER_LIMIT; x++) {641        logger_watcher *w = watchers[x];642        if (w == NULL)643            continue;644645        f |= w->eflags;646    }647    for (l = logger_stack_head; l != NULL; l=l->next) {648        pthread_mutex_lock(&l->mutex);649        l->eflags = f;650        pthread_mutex_unlock(&l->mutex);651    }652    return;653}654655/* Completes rendering of log line. */656static enum logger_parse_entry_ret logger_thread_parse_entry(logentry *e, struct logger_stats *ls,657        char *scratch, int *scratch_len) {658    int total = 0;659    const entry_details *d = &default_entries[e->event];660    assert(d->parse_cb != NULL);661    total = d->parse_cb(e, scratch);662663    if (total >= LOGGER_PARSE_SCRATCH || total <= 0) {664        L_DEBUG("LOGGER: Failed to flatten log entry!\n");665        return LOGGER_PARSE_ENTRY_FAILED;666    } else {667        *scratch_len = total;668    }669670    return LOGGER_PARSE_ENTRY_OK;671}672673/* Writes flattened entry to available watchers */674static void logger_thread_write_entry(logentry *e, struct logger_stats *ls,675        char *scratch, int scratch_len) {676    int x, total;677    /* Write the line into available watchers with matching flags */678    for (x = 0; x < WATCHER_LIMIT; x++) {679        logger_watcher *w = watchers[x];680        char *skip_scr = NULL;681        if (w == NULL || (e->eflags & w->eflags) == 0 || (e->gid < w->min_gid))682            continue;683684         /* Avoid poll()'ing constantly when buffer is full by resetting a685         * flag periodically.686         */687        while (!w->failed_flush &&688                (skip_scr = (char *) bipbuf_request(w->buf, scratch_len + 128)) == NULL) {689            if (logger_thread_poll_watchers(0, x) <= 0) {690                L_DEBUG("LOGGER: Watcher had no free space for line of size (%d)\n", scratch_len + 128);691                // Oddity; poll_watchers can free *w, recheck it.692                if (watchers[x] == NULL) {693                    break;694                }695                w->failed_flush = true;696            }697        }698        // See oddity note above.699        if (watchers[x] == NULL) {700            continue;701        }702703        if (w->failed_flush) {704            L_DEBUG("LOGGER: Fast skipped for watcher [%d] due to failed_flush\n", w->sfd);705            w->skipped++;706            ls->watcher_skipped++;707            continue;708        }709710        if (w->skipped > 0) {711            total = snprintf(skip_scr, 128, "skipped=%llu\n", (unsigned long long) w->skipped);712            if (total >= 128 || total <= 0) {713                L_DEBUG("LOGGER: Failed to flatten skipped message into watcher [%d]\n", w->sfd);714                w->skipped++;715                ls->watcher_skipped++;716                continue;717            }718            bipbuf_push(w->buf, total);719            w->skipped = 0;720        }721        /* Can't fail because bipbuf_request succeeded. */722        bipbuf_offer(w->buf, (unsigned char *) scratch, scratch_len);723        ls->watcher_sent++;724    }725}726727/* Called with logger stack locked.728 * Releases every chunk associated with a watcher and closes the connection.729 * We can't presently send a connection back to the worker for further730 * processing.731 */732static void logger_thread_close_watcher(logger_watcher *w) {733    L_DEBUG("LOGGER: Closing dead watcher\n");734    watchers[w->id] = NULL;735    sidethread_conn_close(w->c);736    watcher_count--;737    bipbuf_free(w->buf);738    free(w);739    logger_set_flags();740}741742/* Reads a particular worker thread's available bipbuf bytes. Parses each log743 * entry into the watcher buffers.744 */745static int logger_thread_read(logger *l, struct logger_stats *ls) {746    unsigned int size;747    unsigned int pos = 0;748    unsigned char *data;749    char scratch[LOGGER_PARSE_SCRATCH];750    logentry *e;751    pthread_mutex_lock(&l->mutex);752    data = bipbuf_peek_all(l->buf, &size);753    pthread_mutex_unlock(&l->mutex);754755    if (data == NULL) {756        return 0;757    }758    L_DEBUG("LOGGER: Got %d bytes from bipbuffer\n", size);759760    /* parse buffer */761    while (pos < size && watcher_count > 0) {762        enum logger_parse_entry_ret ret;763        int scratch_len = 0;764        e = (logentry *) (data + pos);765        ret = logger_thread_parse_entry(e, ls, scratch, &scratch_len);766        if (ret != LOGGER_PARSE_ENTRY_OK) {767            /* TODO: stats counter */768            fprintf(stderr, "LOGGER: Failed to parse log entry\n");769        } else {770            logger_thread_write_entry(e, ls, scratch, scratch_len);771        }772        pos += sizeof(logentry) + e->size + e->pad;773    }774    assert(pos <= size);775776    pthread_mutex_lock(&l->mutex);777    data = bipbuf_poll(l->buf, size);778    ls->worker_written += l->written;779    ls->worker_dropped += l->dropped;780    l->written = 0;781    l->dropped = 0;782    pthread_mutex_unlock(&l->mutex);783    if (data == NULL) {784        fprintf(stderr, "LOGGER: unexpectedly couldn't advance buf pointer\n");785        assert(0);786    }787    return size; /* maybe the count of objects iterated? */788}789790/* Since the event loop code isn't reusable without a refactor, and we have a791 * limited number of potential watchers, we run our own poll loop.792 * This calls poll() unnecessarily during write flushes, should be possible to793 * micro-optimize later.794 *795 * This flushes buffers attached to watchers, iterating through the bytes set796 * to each worker. Also checks for readability in case client connection was797 * closed.798 *799 * Allows a specific watcher to be flushed (if buf full)800 */801static int logger_thread_poll_watchers(int force_poll, int watcher) {802    int x;803    int nfd = 0;804    unsigned char *data;805    unsigned int data_size = 0;806    int flushed = 0;807808    for (x = 0; x < WATCHER_LIMIT; x++) {809        logger_watcher *w = watchers[x];810        if (w == NULL || (watcher != WATCHER_ALL && x != watcher))811            continue;812813        data = bipbuf_peek_all(w->buf, &data_size);814        if (data != NULL) {815            watchers_pollfds[nfd].fd = w->sfd;816            watchers_pollfds[nfd].events = POLLOUT;817            nfd++;818        } else if (force_poll) {819            watchers_pollfds[nfd].fd = w->sfd;820            watchers_pollfds[nfd].events = POLLIN;821            nfd++;822        }823        /* This gets set after a call to poll, and should be used to gate on824         * calling poll again.825         */826        w->failed_flush = false;827    }828829    if (nfd == 0)830        return 0;831832    //L_DEBUG("LOGGER: calling poll() [data_size: %d]\n", data_size);833    int ret = poll(watchers_pollfds, nfd, 0);834835    if (ret < 0) {836        perror("something failed with logger thread watcher fd polling");837        return -1;838    }839840    nfd = 0;841    for (x = 0; x < WATCHER_LIMIT; x++) {842        logger_watcher *w = watchers[x];843        if (w == NULL || (watcher != WATCHER_ALL && x != watcher))844            continue;845846        data_size = 0;847        /* Early detection of a disconnect. Otherwise we have to wait until848         * the next write849         */850        if (watchers_pollfds[nfd].revents & POLLIN) {851            char buf[1];852            int res = ((conn*)w->c)->read(w->c, buf, 1);853            if (res == 0 || (res == -1 && (errno != EAGAIN && errno != EWOULDBLOCK))) {854                L_DEBUG("LOGGER: watcher closed remotely\n");855                logger_thread_close_watcher(w);856                nfd++;857                continue;858            }859        }860        if ((data = bipbuf_peek_all(w->buf, &data_size)) != NULL) {861            if (watchers_pollfds[nfd].revents & (POLLHUP|POLLERR)) {862                L_DEBUG("LOGGER: watcher closed during poll() call\n");863                logger_thread_close_watcher(w);864            } else if (watchers_pollfds[nfd].revents & POLLOUT) {865                int total = 0;866867                /* We can write a bit. */868                switch (w->t) {869                    case LOGGER_WATCHER_STDERR:870                        total = fwrite(data, 1, data_size, stderr);871                        break;872                    case LOGGER_WATCHER_CLIENT:873                        total = ((conn*)w->c)->write(w->c, data, data_size);874                        break;875                }876877                L_DEBUG("LOGGER: poll() wrote %d to %d (data_size: %d) (bipbuf_used: %d)\n", total, w->sfd,878                        data_size, bipbuf_used(w->buf));879                if (total == -1) {880                    if (errno != EAGAIN && errno != EWOULDBLOCK) {881                        logger_thread_close_watcher(w);882                    }883                    L_DEBUG("LOGGER: watcher hit EAGAIN\n");884                } else if (total == 0) {885                    logger_thread_close_watcher(w);886                } else {887                    bipbuf_poll(w->buf, total);888                    flushed += total;889                }890            }891        }892        nfd++;893    }894    return flushed;895}896897static void logger_thread_flush_stats(struct logger_stats *ls) {898    STATS_LOCK();899    stats.log_worker_dropped  += ls->worker_dropped;900    stats.log_worker_written  += ls->worker_written;901    stats.log_watcher_skipped += ls->watcher_skipped;902    stats.log_watcher_sent    += ls->watcher_sent;903    stats_state.log_watchers   = ls->watcher_count;904    STATS_UNLOCK();905}906907#define MAX_LOGGER_SLEEP 1000000908#define MIN_LOGGER_SLEEP 1000909910/* Primary logger thread routine */911static void *logger_thread(void *arg) {912    useconds_t to_sleep = MIN_LOGGER_SLEEP;913    L_DEBUG("LOGGER: Starting logger thread\n");914    // TODO: If we ever have item references in the logger code, will need to915    // ensure everything is dequeued before stopping the thread.916    while (do_run_logger_thread) {917        int found_logs = 0;918        logger *l;919        struct logger_stats ls;920        memset(&ls, 0, sizeof(struct logger_stats));921922        /* only sleep if we're *above* the minimum */923        if (to_sleep > MIN_LOGGER_SLEEP)924            usleep(to_sleep);925926        /* Call function to iterate each logger. */927        pthread_mutex_lock(&logger_stack_lock);928        if (watcher_count == 0) {929            // Not bothering to loop on the condition here since it's fine to930            // walk through with zero watchers.931            pthread_cond_wait(&logger_stack_cond, &logger_stack_lock);932        }933        for (l = logger_stack_head; l != NULL; l=l->next) {934            /* lock logger, call function to manipulate it */935            found_logs += logger_thread_read(l, &ls);936        }937938        logger_thread_poll_watchers(1, WATCHER_ALL);939940        /* capture the current count within mutual exclusion of the lock */941        ls.watcher_count = watcher_count;942943        pthread_mutex_unlock(&logger_stack_lock);944945        /* TODO: abstract into a function and share with lru_crawler */946        if (!found_logs) {947            if (to_sleep < MAX_LOGGER_SLEEP)948                to_sleep += to_sleep / 8;949            if (to_sleep > MAX_LOGGER_SLEEP)950                to_sleep = MAX_LOGGER_SLEEP;951        } else {952            to_sleep /= 2;953            if (to_sleep < MIN_LOGGER_SLEEP)954                to_sleep = MIN_LOGGER_SLEEP;955        }956        logger_thread_flush_stats(&ls);957    }958959    return NULL;960}961962static int start_logger_thread(void) {963    int ret;964    do_run_logger_thread = 1;965    if ((ret = pthread_create(&logger_tid, NULL,966                              logger_thread, NULL)) != 0) {967        fprintf(stderr, "Can't start logger thread: %s\n", strerror(ret));968        return -1;969    }970    thread_setname(logger_tid, "mc-log");971    return 0;972}973974static int stop_logger_thread(void) {975    // Guarantees that the logger thread is waiting on 'logger_stack_cond'976    // before we signal it.977    pthread_mutex_lock(&logger_stack_lock);978    do_run_logger_thread = 0;979    pthread_cond_signal(&logger_stack_cond);980    pthread_mutex_unlock(&logger_stack_lock);981    pthread_join(logger_tid, NULL);982    return 0;983}984985/*************************986 * Public functions for submitting logs and starting loggers from workers.987 *************************/988989/* Global logger thread start/init */990void logger_init(void) {991    /* TODO: auto destructor when threads exit */992    /* TODO: error handling */993994    /* init stack for iterating loggers */995    logger_stack_head = 0;996    logger_stack_tail = 0;997    pthread_key_create(&logger_key, NULL);998999    if (start_logger_thread() != 0) {1000        abort();1001    }10021003    /* This is what adding a STDERR watcher looks like. should replace old1004     * "verbose" settings. */1005    //logger_add_watcher(NULL, 0);1006    return;1007}10081009void logger_stop(void) {1010    stop_logger_thread();1011}10121013/* called *from* the thread using a logger.1014 * initializes the per-thread bipbuf, links it into the list of loggers1015 */1016logger *logger_create(void) {1017    L_DEBUG("LOGGER: Creating and linking new logger instance\n");1018    logger *l = calloc(1, sizeof(logger));1019    if (l == NULL) {1020        return NULL;1021    }10221023    l->buf = bipbuf_new(settings.logger_buf_size);1024    if (l->buf == NULL) {1025        free(l);1026        return NULL;1027    }10281029    l->entry_map = default_entries;10301031    pthread_mutex_init(&l->mutex, NULL);1032    pthread_setspecific(logger_key, l);10331034    /* add to list of loggers */1035    logger_link_q(l);1036    return l;1037}10381039/* Public function for logging an entry.1040 * Tries to encapsulate as much of the formatting as possible to simplify the1041 * caller's code.1042 */1043enum logger_ret_type logger_log(logger *l, const enum log_entry_type event, const void *entry, ...) {1044    bipbuf_t *buf = l->buf;1045    bool nospace = false;1046    va_list ap;1047    logentry *e;10481049    const entry_details *d = &l->entry_map[event];1050    int reqlen = d->reqlen;10511052    pthread_mutex_lock(&l->mutex);1053    /* Request a maximum length of data to write to */1054    e = (logentry *) bipbuf_request(buf, (sizeof(logentry) + reqlen));1055    if (e == NULL) {1056        l->dropped++;1057        pthread_mutex_unlock(&l->mutex);1058        return LOGGER_RET_NOSPACE;1059    }1060    e->event = event;1061    e->pad = 0;1062    e->gid = logger_get_gid();1063    /* TODO: Could pass this down as an argument now that we're using1064     * LOGGER_LOG() macro.1065     */1066    e->eflags = d->eflags;1067    /* Noting time isn't optional. A feature may be added to avoid rendering1068     * time and/or gid to a logger.1069     */1070    gettimeofday(&e->tv, NULL);10711072    va_start(ap, entry);1073    d->log_cb(e, d, entry, ap);1074    va_end(ap);10751076#ifdef NEED_ALIGN1077    /* Need to ensure *next* request is aligned. */1078    if (sizeof(logentry) + e->size % 8 != 0) {1079        e->pad = 8 - (sizeof(logentry) + e->size % 8);1080    }1081#endif10821083    /* Push pointer forward by the actual amount required */1084    if (bipbuf_push(buf, (sizeof(logentry) + e->size + e->pad)) == 0) {1085        fprintf(stderr, "LOGGER: Failed to bipbuf push a text entry\n");1086        pthread_mutex_unlock(&l->mutex);1087        return LOGGER_RET_ERR;1088    }1089    l->written++;1090    L_DEBUG("LOGGER: Requested %d bytes, wrote %lu bytes\n", reqlen,1091            (sizeof(logentry) + e->size));10921093    pthread_mutex_unlock(&l->mutex);10941095    if (nospace) {1096        return LOGGER_RET_NOSPACE;1097    } else {1098        return LOGGER_RET_OK;1099    }1100}11011102/* Passes a client connection socket from a primary worker thread to the1103 * logger thread. Caller *must* event_del() the client before handing it over.1104 * Presently there's no way to hand the client back to the worker thread.1105 */1106enum logger_add_watcher_ret logger_add_watcher(void *c, const int sfd, uint16_t f) {1107    int x;1108    logger_watcher *w = NULL;1109    pthread_mutex_lock(&logger_stack_lock);1110    if (watcher_count >= WATCHER_LIMIT) {1111        pthread_mutex_unlock(&logger_stack_lock);1112        return LOGGER_ADD_WATCHER_TOO_MANY;1113    }11141115    for (x = 0; x < WATCHER_LIMIT-1; x++) {1116        if (watchers[x] == NULL)1117            break;1118    }11191120    w = calloc(1, sizeof(logger_watcher));1121    if (w == NULL) {1122        pthread_mutex_unlock(&logger_stack_lock);1123        return LOGGER_ADD_WATCHER_FAILED;1124    }1125    w->c = c;1126    w->sfd = sfd;1127    if (sfd == 0 && c == NULL) {1128        w->t = LOGGER_WATCHER_STDERR;1129    } else {1130        w->t = LOGGER_WATCHER_CLIENT;1131    }1132    w->id = x;1133    w->eflags = f;1134    w->min_gid = logger_get_gid();1135    w->buf = bipbuf_new(settings.logger_watcher_buf_size);1136    if (w->buf == NULL) {1137        free(w);1138        pthread_mutex_unlock(&logger_stack_lock);1139        return LOGGER_ADD_WATCHER_FAILED;1140    }1141    bipbuf_offer(w->buf, (unsigned char *) "OK\r\n", 4);11421143    watchers[x] = w;1144    watcher_count++;1145    /* Update what flags the global logs will watch */1146    logger_set_flags();1147    pthread_cond_signal(&logger_stack_cond);11481149    pthread_mutex_unlock(&logger_stack_lock);1150    return LOGGER_ADD_WATCHER_OK;1151}