File: log.c

package info (click to toggle)
gdnsd 3.8.3-2.1
  • links: PTS, VCS
  • area: main
  • in suites: forky, sid
  • size: 4,584 kB
  • sloc: ansic: 30,669; sh: 4,872; perl: 1,047; makefile: 401; pascal: 108
file content (368 lines) | stat: -rw-r--r-- 10,802 bytes parent folder | download | duplicates (3)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
/* Copyright © 2012 Brandon L Black <blblack@gmail.com>
 *
 * This file is part of gdnsd.
 *
 * gdnsd is free software: you can redistribute it and/or modify
 * it under the terms of the GNU General Public License as published by
 * the Free Software Foundation, either version 3 of the License, or
 * (at your option) any later version.
 *
 * gdnsd is distributed in the hope that it will be useful,
 * but WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 * GNU General Public License for more details.
 *
 * You should have received a copy of the GNU General Public License
 * along with gdnsd.  If not, see <http://www.gnu.org/licenses/>.
 *
 */

#include <config.h>

#include <gdnsd/log.h>
#include <gdnsd/compiler.h>
#include <gdnsd/net.h>
#include <gdnsd/stats.h>
#include <gdnsd/paths.h>
#include <gdnsd/dname.h>

#include <stdbool.h>
#include <inttypes.h>
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#include <syslog.h>
#include <stdarg.h>
#include <pthread.h>
#include <stddef.h>
#include <errno.h>
#include <unistd.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/socket.h>

#ifdef HAVE_LIBUNWIND
#  define UNW_LOCAL_ONLY
#  include <libunwind.h>
#endif

/***********************************************************
***** Constants ********************************************
***********************************************************/

// Text log message prefixes when using stderr
static const char PFX_DEBUG[] = "debug: ";
static const char PFX_INFO[] = "info: ";
static const char PFX_WARNING[] = "warning: ";
static const char PFX_ERR[] = "error: ";
static const char PFX_CRIT[] = "fatal: ";
static const char PFX_UNKNOWN[] = "???: ";

// If passed format string is stupidly-long:
static const char FMT_TOO_LONG[] = "BUG: log format string is way too long!";

// Max length of an errno string (for our buffer purposes)
#define GDNSD_ERRNO_MAXLEN 256U

/***********************************************************
***** Static process-global data ***************************
***********************************************************/

static bool do_dbg = false;
static bool do_syslog = false;

/***********************************************************
***** Logging **********************************************
***********************************************************/

void gdnsd_log_set_debug(bool debug)
{
    do_dbg = debug;
}

bool gdnsd_log_get_debug(void)
{
    return do_dbg;
}

void gdnsd_log_set_syslog(bool set_syslog, const char* ident)
{
    if (!do_syslog && set_syslog)
        openlog(ident ? ident : PACKAGE_NAME, LOG_NDELAY | LOG_PID, LOG_DAEMON);
    do_syslog = set_syslog;
}

bool gdnsd_log_get_syslog(void)
{
    return do_syslog;
}

// gdnsd_log_neterr_rate_ok(): used by logging macros to implement a
// per-thread-ratelimited log output for network-driven log events, so that
// they can't excessively spam syslog when things go off the rails.  It's
// per-thread so that we don't have to harm scaling with some kind of
// synchronization in a critical path.
//
// For calling macros: if this function returns true, log the original message
// using gdnsd_logger().  If it returns false, do nothing.
//
// The behavior is fairly simple:  Time is binned (imprecisely in edge cases,
// which is fine for a rough sanity-check like this) by time() return values.
// If more than 10 messages happen during a single clock second, this code will
// replace the 10th message with a meta-message about suppressing excessive
// events and then suppress them for the remainder of the second.  Once this
// happens the code goes into a defensive mode which supresses all further
// messages and sends at most one new message per second about the ongoing
// suppression.
//
// Defensive mode can be exited by either of:
// (a) A full second (or more) passing with zero attempted log messages
// (b) 2 consecutive seconds pass during which there are messages (which are
//     all suppressed), but the rate of them does not re-trip the threshold
bool gdnsd_log_neterr_rate_ok(void)
{
    static __thread time_t rate_second = 0;
    static __thread unsigned count = 0;
    static __thread unsigned defensive = 0;

    static const unsigned rate_limit = 10U;

    const time_t now_second = time(NULL);

    // The clock has advanced one or more seconds
    if (now_second != rate_second) {
        // If we were already being defensive...
        if (defensive) {
            if (now_second > (rate_second + 1U)) {
                // If the clock jumped by more than one, we had at least a full
                // second of radio silence, so let's clear defensive state:
                defensive = 0;
            } else if (count < rate_limit) {
                // Otherwise for a single-second jump, decrement our defensiveness
                // by one if the previous second managed to stay under the limit:
                defensive--;
            }
        }

        // Update the clock and reset the count
        rate_second = now_second;
        count = 0;
    } else {
        // Clock didn't change, just update count:
        count++;
    }

    // Allow the original message if under the threshold and not defensive
    if (count < rate_limit && !defensive)
        return true;

    // Otherwise...

    // Meta-log and reset defenses at the threshold
    if (count == rate_limit) {
        defensive = 2U;
        gdnsd_logger(LOG_ERR, "Excessive network error messages are being suppressed");
    }

    // At-or-above the threshold (or defensive), do not allow the original message
    return false;
}

// 4K is the limit for all strings formatted by the log formatters to use in a
// single log message.  In other words, for any invocation like:
// log_warn("...", logf_dname(x), logf_strerror(y))
// The space allocated by logf_dname() + logf_strerror() must be <= 4096.
#define FMTBUF_SIZE 4096U
// fmtbuf_common is private to the two functions below it
static char* fmtbuf_common(const size_t size)
{
    static __thread size_t buf_used = 0;
    static __thread char buf[FMTBUF_SIZE] = { 0 };

    char* rv = NULL;

    // Allocate a chunk from the per-thread format buffer
    if (size) {
        if ((FMTBUF_SIZE - buf_used) >= size) {
            rv = &buf[buf_used];
            buf_used += size;
        }
    } else {
        // Reset (free allocations within) the format buffer,
        buf_used = 0;
    }

    return rv;
}

// Public (including this file) interfaces to fmtbuf_common()

char* gdnsd_fmtbuf_alloc(const size_t size)
{
    if (!size)
        log_fatal("BUG: fmtbuf alloc of zero bytes");
    char* rv = fmtbuf_common(size);
    if (!rv)
        log_fatal("BUG: format buffer exhausted");
    return rv;
}

void gdnsd_fmtbuf_reset(void)
{
    fmtbuf_common(0);
}

// gdnsd_logf_strerror(), which hides GNU or POSIX strerror_r() thread-safe
//  errno->string translation behind a more strerror()-like interface
//  using gdnsd_fmtbuf_alloc()
const char* gdnsd_logf_strerror(const int errnum)
{
    char tmpbuf[GDNSD_ERRNO_MAXLEN];
    const char* tmpbuf_ptr;

#ifdef STRERROR_R_CHAR_P
    // GNU-style
    tmpbuf_ptr = strerror_r(errnum, tmpbuf, GDNSD_ERRNO_MAXLEN);
#else
    // POSIX style (+ older glibc bug-compat)
    int rv = strerror_r(errnum, tmpbuf, GDNSD_ERRNO_MAXLEN);
    if (rv) {
        if (rv == EINVAL || (rv < 0 && errno == EINVAL))
            snprintf(tmpbuf, GDNSD_ERRNO_MAXLEN, "Invalid errno: %i", errnum);
        else
            log_fatal("strerror_r(,,%u) failed", GDNSD_ERRNO_MAXLEN);
    }
    tmpbuf_ptr = tmpbuf;
#endif

    const unsigned len = strlen(tmpbuf_ptr) + 1;
    char* buf = gdnsd_fmtbuf_alloc(len);
    memcpy(buf, tmpbuf_ptr, len);
    return buf;
}

GDNSD_DIAG_PUSH_IGNORED("-Wformat-nonliteral")

static void gdnsd_loggerv(int level, const char* fmt, va_list ap)
{
    if (do_syslog) {
        vsyslog(level, fmt, ap);
        gdnsd_fmtbuf_reset();
        return;
    }

    const char* pfx;

    switch (level) {
    case LOG_DEBUG:
        pfx = PFX_DEBUG;
        break;
    case LOG_INFO:
        pfx = PFX_INFO;
        break;
    case LOG_WARNING:
        pfx = PFX_WARNING;
        break;
    case LOG_ERR:
        pfx = PFX_ERR;
        break;
    case LOG_CRIT:
        pfx = PFX_CRIT;
        break;
    default:
        pfx = PFX_UNKNOWN;
        break;
    }

    char f[1024];
    const int snp_rv = snprintf(f, 1024, "%s%s\n", pfx, fmt);
    if (unlikely(snp_rv >= 1024))
        memcpy(f, FMT_TOO_LONG, sizeof(FMT_TOO_LONG));

    va_list apcpy;
    va_copy(apcpy, ap);
    vdprintf(STDERR_FILENO, f, apcpy);
    va_end(apcpy);

    gdnsd_fmtbuf_reset();
}

void gdnsd_logger(int level, const char* fmt, ...)
{
    va_list ap;
    va_start(ap, fmt);
    gdnsd_loggerv(level, fmt, ap);
    va_end(ap);
}

GDNSD_DIAG_POP

#define BT_SIZE 2048LU
#define BT_MAX_NAME 60LU

const char* gdnsd_logf_bt(void)
{
#ifdef HAVE_LIBUNWIND
    char* tbuf = gdnsd_fmtbuf_alloc(BT_SIZE);
    size_t tbuf_pos = 0;
    tbuf[tbuf_pos] = '\0'; // in case no output below

    unw_cursor_t cursor;
    unw_context_t uc;
    unw_getcontext(&uc);
    unw_init_local(&cursor, &uc);

    while (unw_step(&cursor) > 0) {
        unw_word_t ip = 0;
        unw_word_t sp = 0;
        unw_word_t offset = 0;
        unw_get_reg(&cursor, UNW_REG_IP, &ip);
        unw_get_reg(&cursor, UNW_REG_SP, &sp);

        char cbuf[BT_MAX_NAME];
        cbuf[0] = '\0'; // in case no output below
        (void)unw_get_proc_name(&cursor, cbuf, BT_MAX_NAME, &offset);

        const size_t size_rem = BT_SIZE - tbuf_pos;
        int snp_rv = snprintf(&tbuf[tbuf_pos],
                              size_rem, "\n[ip:%#.16lx sp:%#.16lx] %s+%#lx",
                              (unsigned long)ip, (unsigned long)sp,
                              cbuf, (unsigned long)offset);
        if (snp_rv < 0 || (size_t)snp_rv >= size_rem)
            break;
        tbuf_pos += (size_t)snp_rv;
    }
    return tbuf;
#else
    return "(no libunwind)";
#endif
}

static const char generic_nullstr[] = "(null)";

const char* gdnsd_logf_ipv6(const uint8_t* ipv6)
{
    gdnsd_anysin_t tempsin;
    memset(&tempsin, 0, sizeof(tempsin));
    tempsin.sa.sa_family = AF_INET6;
    memcpy(tempsin.sin6.sin6_addr.s6_addr, ipv6, 16);
    tempsin.len = sizeof(struct sockaddr_in6);
    return gdnsd_logf_anysin_noport(&tempsin);
}

const char* gdnsd_logf_in6a(const struct in6_addr* in6a)
{
    return gdnsd_logf_ipv6(in6a->s6_addr);
}

const char* gdnsd_logf_dname(const uint8_t* dname)
{
    if (!dname)
        return generic_nullstr;

    char tmpbuf[1024];
    const unsigned len = gdnsd_dname_to_string(dname, tmpbuf);
    char* dnbuf = gdnsd_fmtbuf_alloc(len);
    memcpy(dnbuf, tmpbuf, len);
    return dnbuf;
}