logging.c 32.9 KB
Newer Older
1 2 3
/*
 * logging.c: internal logging and debugging
 *
4
 * Copyright (C) 2008, 2010-2012 Red Hat, Inc.
5 6 7 8 9 10 11 12 13 14 15 16
 *
 * This library is free software; you can redistribute it and/or
 * modify it under the terms of the GNU Lesser General Public
 * License as published by the Free Software Foundation; either
 * version 2.1 of the License, or (at your option) any later version.
 *
 * This library 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
 * Lesser General Public License for more details.
 *
 * You should have received a copy of the GNU Lesser General Public
O
Osier Yang 已提交
17 18
 * License along with this library;  If not, see
 * <http://www.gnu.org/licenses/>.
19 20 21 22 23
 *
 */

#include <config.h>

D
Daniel Veillard 已提交
24 25 26 27 28 29 30 31
#include <stdio.h>
#include <stdarg.h>
#include <stdlib.h>
#include <time.h>
#include <sys/time.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
32
#include <unistd.h>
33
#include <signal.h>
D
Daniel Veillard 已提交
34
#if HAVE_SYSLOG_H
35
# include <syslog.h>
D
Daniel Veillard 已提交
36
#endif
37 38 39
#ifdef HAVE_EXECINFO_H
# include <execinfo.h>
#endif
D
Daniel Veillard 已提交
40

41
#include "virterror_internal.h"
42
#include "logging.h"
D
Daniel Veillard 已提交
43 44
#include "memory.h"
#include "util.h"
45
#include "buf.h"
46
#include "threads.h"
E
Eric Blake 已提交
47
#include "virfile.h"
48
#include "virtime.h"
49

50 51
#define VIR_FROM_THIS VIR_FROM_NONE

D
Daniel Veillard 已提交
52 53 54 55
/*
 * A logging buffer to keep some history over logs
 */

56 57
static int virLogSize = 64 * 1024;
static char *virLogBuffer = NULL;
D
Daniel Veillard 已提交
58 59 60 61 62 63 64 65 66 67 68
static int virLogLen = 0;
static int virLogStart = 0;
static int virLogEnd = 0;

/*
 * Filters are used to refine the rules on what to keep or drop
 * based on a matching pattern (currently a substring)
 */
struct _virLogFilter {
    const char *match;
    int priority;
69
    unsigned int flags;
D
Daniel Veillard 已提交
70 71 72 73 74 75 76 77 78 79 80 81
};
typedef struct _virLogFilter virLogFilter;
typedef virLogFilter *virLogFilterPtr;

static virLogFilterPtr virLogFilters = NULL;
static int virLogNbFilters = 0;

/*
 * Outputs are used to emit the messages retained
 * after filtering, multiple output can be used simultaneously
 */
struct _virLogOutput {
82
    bool logVersion;
D
Daniel Veillard 已提交
83 84 85 86
    void *data;
    virLogOutputFunc f;
    virLogCloseFunc c;
    int priority;
87 88
    virLogDestination dest;
    const char *name;
D
Daniel Veillard 已提交
89 90 91 92 93 94 95 96 97 98
};
typedef struct _virLogOutput virLogOutput;
typedef virLogOutput *virLogOutputPtr;

static virLogOutputPtr virLogOutputs = NULL;
static int virLogNbOutputs = 0;

/*
 * Default priorities
 */
99
static virLogPriority virLogDefaultPriority = VIR_LOG_DEFAULT;
D
Daniel Veillard 已提交
100 101 102

static int virLogResetFilters(void);
static int virLogResetOutputs(void);
103 104
static int virLogOutputToFd(const char *category, int priority,
                            const char *funcname, long long linenr,
105 106 107
                            const char *timestamp,
                            unsigned int flags,
                            const char *str,
108
                            void *data);
D
Daniel Veillard 已提交
109 110 111 112

/*
 * Logs accesses must be serialized though a mutex
 */
113
virMutex virLogMutex;
D
Daniel Veillard 已提交
114

115
void virLogLock(void)
D
Daniel Veillard 已提交
116
{
117
    virMutexLock(&virLogMutex);
D
Daniel Veillard 已提交
118
}
119
void virLogUnlock(void)
D
Daniel Veillard 已提交
120
{
121
    virMutexUnlock(&virLogMutex);
D
Daniel Veillard 已提交
122 123
}

124 125
static const char *virLogOutputString(virLogDestination ldest) {
    switch (ldest) {
126 127 128 129 130 131
    case VIR_LOG_TO_STDERR:
        return "stderr";
    case VIR_LOG_TO_SYSLOG:
        return "syslog";
    case VIR_LOG_TO_FILE:
        return "file";
132
    }
133
    return "unknown";
134
}
D
Daniel Veillard 已提交
135 136 137

static const char *virLogPriorityString(virLogPriority lvl) {
    switch (lvl) {
138 139 140 141 142 143 144 145
    case VIR_LOG_DEBUG:
        return "debug";
    case VIR_LOG_INFO:
        return "info";
    case VIR_LOG_WARN:
        return "warning";
    case VIR_LOG_ERROR:
        return "error";
D
Daniel Veillard 已提交
146
    }
147
    return "unknown";
D
Daniel Veillard 已提交
148 149 150
}


151 152
static int virLogOnceInit(void)
{
153 154
    const char *pbm = NULL;

155 156 157
    if (virMutexInit(&virLogMutex) < 0)
        return -1;

D
Daniel Veillard 已提交
158
    virLogLock();
159
    if (VIR_ALLOC_N(virLogBuffer, virLogSize + 1) < 0) {
160 161 162 163 164 165
        /*
         * The debug buffer is not a critical component, allow startup
         * even in case of failure to allocate it in case of a
         * configuration mistake.
         */
        virLogSize = 64 * 1024;
166
        if (VIR_ALLOC_N(virLogBuffer, virLogSize + 1) < 0) {
167 168 169 170 171 172
            pbm = "Failed to allocate debug buffer: deactivating debug log\n";
            virLogSize = 0;
        } else {
            pbm = "Failed to allocate debug buffer: reduced to 64 kB\n";
        }
    }
D
Daniel Veillard 已提交
173 174 175
    virLogLen = 0;
    virLogStart = 0;
    virLogEnd = 0;
176
    virLogDefaultPriority = VIR_LOG_DEFAULT;
D
Daniel Veillard 已提交
177
    virLogUnlock();
178
    if (pbm)
179
        VIR_WARN("%s", pbm);
180
    return 0;
D
Daniel Veillard 已提交
181 182
}

183 184
VIR_ONCE_GLOBAL_INIT(virLog)

185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204
/**
 * virLogSetBufferSize:
 * @size: size of the buffer in kilobytes or <= 0 to deactivate
 *
 * Dynamically set the size or deactivate the logging buffer used to keep
 * a trace of all recent debug output. Note that the content of the buffer
 * is lost if it gets reallocated.
 *
 * Return -1 in case of failure or 0 in case of success
 */
extern int
virLogSetBufferSize(int size) {
    int ret = 0;
    int oldsize;
    char *oldLogBuffer;
    const char *pbm = NULL;

    if (size < 0)
        size = 0;

205 206 207 208
    if (virLogInitialize() < 0)
        return -1;

    if (size * 1024 == virLogSize)
209 210 211 212 213 214 215
        return ret;

    virLogLock();

    oldsize = virLogSize;
    oldLogBuffer = virLogBuffer;

216
    if (INT_MAX / 1024 <= size) {
217 218 219 220 221 222
        pbm = "Requested log size of %d kB too large\n";
        ret = -1;
        goto error;
    }

    virLogSize = size * 1024;
223
    if (VIR_ALLOC_N(virLogBuffer, virLogSize + 1) < 0) {
224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241
        pbm = "Failed to allocate debug buffer of %d kB\n";
        virLogBuffer = oldLogBuffer;
        virLogSize = oldsize;
        ret = -1;
        goto error;
    }
    VIR_FREE(oldLogBuffer);
    virLogLen = 0;
    virLogStart = 0;
    virLogEnd = 0;

error:
    virLogUnlock();
    if (pbm)
        VIR_ERROR(pbm, size);
    return ret;
}

D
Daniel Veillard 已提交
242 243 244 245 246 247 248 249
/**
 * virLogReset:
 *
 * Reset the logging module to its default initial state
 *
 * Returns 0 if successful, and -1 in case or error
 */
int virLogReset(void) {
250 251
    if (virLogInitialize() < 0)
        return -1;
D
Daniel Veillard 已提交
252 253 254 255 256 257 258

    virLogLock();
    virLogResetFilters();
    virLogResetOutputs();
    virLogLen = 0;
    virLogStart = 0;
    virLogEnd = 0;
259
    virLogDefaultPriority = VIR_LOG_DEFAULT;
D
Daniel Veillard 已提交
260
    virLogUnlock();
261
    return 0;
D
Daniel Veillard 已提交
262 263 264 265 266
}

/*
 * Store a string in the ring buffer
 */
267 268
static void virLogStr(const char *str)
{
D
Daniel Veillard 已提交
269
    int tmp;
270
    int len;
D
Daniel Veillard 已提交
271

272
    if ((str == NULL) || (virLogBuffer == NULL) || (virLogSize <= 0))
D
Daniel Veillard 已提交
273
        return;
274
    len = strlen(str);
E
Eric Blake 已提交
275
    if (len >= virLogSize)
D
Daniel Veillard 已提交
276 277 278 279 280
        return;

    /*
     * copy the data and reset the end, we cycle over the end of the buffer
     */
281 282
    if (virLogEnd + len >= virLogSize) {
        tmp = virLogSize - virLogEnd;
D
Daniel Veillard 已提交
283
        memcpy(&virLogBuffer[virLogEnd], str, tmp);
284
        memcpy(&virLogBuffer[0], &str[tmp], len - tmp);
D
Daniel Veillard 已提交
285 286 287 288 289
        virLogEnd = len - tmp;
    } else {
        memcpy(&virLogBuffer[virLogEnd], str, len);
        virLogEnd += len;
    }
E
Eric Blake 已提交
290
    virLogBuffer[virLogEnd] = 0;
D
Daniel Veillard 已提交
291 292 293 294
    /*
     * Update the log length, and if full move the start index
     */
    virLogLen += len;
295 296 297
    if (virLogLen > virLogSize) {
        tmp = virLogLen - virLogSize;
        virLogLen = virLogSize;
D
Daniel Veillard 已提交
298
        virLogStart += tmp;
299 300
        if (virLogStart >= virLogSize)
            virLogStart -= virLogSize;
D
Daniel Veillard 已提交
301 302 303
    }
}

304 305 306
static void virLogDumpAllFD(const char *msg, int len) {
    int i, found = 0;

307 308 309
    if (len <= 0)
        len = strlen(msg);

310 311
    for (i = 0; i < virLogNbOutputs;i++) {
        if (virLogOutputs[i].f == virLogOutputToFd) {
312
            int fd = (intptr_t) virLogOutputs[i].data;
313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331

            if (fd >= 0) {
                ignore_value (safewrite(fd, msg, len));
                found = 1;
            }
        }
    }
    if (!found)
        ignore_value (safewrite(STDERR_FILENO, msg, len));
}

/**
 * virLogEmergencyDumpAll:
 * @signum: the signal number
 *
 * Emergency function called, possibly from a signal handler.
 * It need to output the debug ring buffer through the log
 * output which are safe to use from a signal handler.
 * In case none is found it is emitted to standard error.
D
Daniel Veillard 已提交
332
 */
333 334
void
virLogEmergencyDumpAll(int signum) {
335
    int len;
C
Christophe Fergeau 已提交
336
    int oldLogStart, oldLogLen;
D
Daniel Veillard 已提交
337

338
    switch (signum) {
D
Daniel Veillard 已提交
339
#ifdef SIGFPE
340 341 342
        case SIGFPE:
            virLogDumpAllFD( "Caught signal Floating-point exception", -1);
            break;
D
Daniel Veillard 已提交
343 344
#endif
#ifdef SIGSEGV
345 346 347
        case SIGSEGV:
            virLogDumpAllFD( "Caught Segmentation violation", -1);
            break;
D
Daniel Veillard 已提交
348 349
#endif
#ifdef SIGILL
350 351 352
        case SIGILL:
            virLogDumpAllFD( "Caught illegal instruction", -1);
            break;
D
Daniel Veillard 已提交
353 354
#endif
#ifdef SIGABRT
355 356 357
        case SIGABRT:
            virLogDumpAllFD( "Caught abort signal", -1);
            break;
D
Daniel Veillard 已提交
358 359
#endif
#ifdef SIGBUS
360 361 362
        case SIGBUS:
            virLogDumpAllFD( "Caught bus error", -1);
            break;
D
Daniel Veillard 已提交
363 364
#endif
#ifdef SIGUSR2
365 366 367
        case SIGUSR2:
            virLogDumpAllFD( "Caught User-defined signal 2", -1);
            break;
D
Daniel Veillard 已提交
368
#endif
369 370 371 372
        default:
            virLogDumpAllFD( "Caught unexpected signal", -1);
            break;
    }
373 374
    if ((virLogBuffer == NULL) || (virLogSize <= 0)) {
        virLogDumpAllFD(" internal log buffer deactivated\n", -1);
375
        return;
376
    }
377

378 379
    virLogDumpAllFD(" dumping internal log buffer:\n", -1);
    virLogDumpAllFD("\n\n    ====== start of log =====\n\n", -1);
380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401

    /*
     * Since we can't lock the buffer safely from a signal handler
     * we mark it as empty in case of concurrent access, and proceed
     * with the data, at worse we will output something a bit weird
     * if another thread start logging messages at the same time.
     * Note that virLogStr() uses virLogEnd for the computations and
     * writes to the buffer and only then updates virLogLen and virLogStart
     * so it's best to reset it first.
     */
    oldLogStart = virLogStart;
    oldLogLen = virLogLen;
    virLogEnd = 0;
    virLogLen = 0;
    virLogStart = 0;

    while (oldLogLen > 0) {
        if (oldLogStart + oldLogLen < virLogSize) {
            virLogBuffer[oldLogStart + oldLogLen] = 0;
            virLogDumpAllFD(&virLogBuffer[oldLogStart], oldLogLen);
            oldLogStart += oldLogLen;
            oldLogLen = 0;
D
Daniel Veillard 已提交
402
        } else {
403
            len = virLogSize - oldLogStart;
404
            virLogBuffer[virLogSize] = 0;
405 406 407
            virLogDumpAllFD(&virLogBuffer[oldLogStart], len);
            oldLogLen -= len;
            oldLogStart = 0;
D
Daniel Veillard 已提交
408 409
        }
    }
410
    virLogDumpAllFD("\n\n     ====== end of log =====\n\n", -1);
D
Daniel Veillard 已提交
411
}
412

D
Daniel Veillard 已提交
413 414 415 416 417 418 419 420 421 422 423
/**
 * virLogSetDefaultPriority:
 * @priority: the default priority level
 *
 * Set the default priority level, i.e. any logged data of a priority
 * equal or superior to this level will be logged, unless a specific rule
 * was defined for the log category of the message.
 *
 * Returns 0 if successful, -1 in case of error.
 */
int virLogSetDefaultPriority(int priority) {
424
    if ((priority < VIR_LOG_DEBUG) || (priority > VIR_LOG_ERROR)) {
425
        VIR_WARN("Ignoring invalid log level setting.");
426
        return -1;
427
    }
428 429 430
    if (virLogInitialize() < 0)
        return -1;

D
Daniel Veillard 已提交
431
    virLogDefaultPriority = priority;
432
    return 0;
D
Daniel Veillard 已提交
433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448
}

/**
 * virLogResetFilters:
 *
 * Removes the set of logging filters defined.
 *
 * Returns the number of filters removed
 */
static int virLogResetFilters(void) {
    int i;

    for (i = 0; i < virLogNbFilters;i++)
        VIR_FREE(virLogFilters[i].match);
    VIR_FREE(virLogFilters);
    virLogNbFilters = 0;
449
    return i;
D
Daniel Veillard 已提交
450 451 452 453 454 455
}

/**
 * virLogDefineFilter:
 * @match: the pattern to match
 * @priority: the priority to give to messages matching the pattern
456
 * @flags: extra flags, see virLogFilterFlags enum
D
Daniel Veillard 已提交
457 458 459 460 461 462 463 464 465
 *
 * Defines a pattern used for log filtering, it allow to select or
 * reject messages independently of the default priority.
 * The filter defines a rules that will apply only to messages matching
 * the pattern (currently if @match is a substring of the message category)
 *
 * Returns -1 in case of failure or the filter number if successful
 */
int virLogDefineFilter(const char *match, int priority,
466 467
                       unsigned int flags)
{
D
Daniel Veillard 已提交
468 469 470
    int i;
    char *mdup = NULL;

471
    virCheckFlags(VIR_LOG_STACK_TRACE, -1);
472

D
Daniel Veillard 已提交
473 474
    if ((match == NULL) || (priority < VIR_LOG_DEBUG) ||
        (priority > VIR_LOG_ERROR))
475
        return -1;
D
Daniel Veillard 已提交
476 477 478 479 480 481 482 483 484 485

    virLogLock();
    for (i = 0;i < virLogNbFilters;i++) {
        if (STREQ(virLogFilters[i].match, match)) {
            virLogFilters[i].priority = priority;
            goto cleanup;
        }
    }

    mdup = strdup(match);
486
    if (mdup == NULL) {
D
Daniel Veillard 已提交
487 488 489 490 491 492 493 494 495 496 497
        i = -1;
        goto cleanup;
    }
    i = virLogNbFilters;
    if (VIR_REALLOC_N(virLogFilters, virLogNbFilters + 1)) {
        i = -1;
        VIR_FREE(mdup);
        goto cleanup;
    }
    virLogFilters[i].match = mdup;
    virLogFilters[i].priority = priority;
498
    virLogFilters[i].flags = flags;
D
Daniel Veillard 已提交
499 500 501
    virLogNbFilters++;
cleanup:
    virLogUnlock();
502
    return i;
D
Daniel Veillard 已提交
503 504 505 506 507 508 509 510 511 512 513 514
}

/**
 * virLogFiltersCheck:
 * @input: the input string
 *
 * Check the input of the message against the existing filters. Currently
 * the match is just a substring check of the category used as the input
 * string, a more subtle approach could be used instead
 *
 * Returns 0 if not matched or the new priority if found.
 */
515 516
static int virLogFiltersCheck(const char *input,
                              unsigned int *flags) {
D
Daniel Veillard 已提交
517 518 519 520 521 522 523
    int ret = 0;
    int i;

    virLogLock();
    for (i = 0;i < virLogNbFilters;i++) {
        if (strstr(input, virLogFilters[i].match)) {
            ret = virLogFilters[i].priority;
524
            *flags = virLogFilters[i].flags;
D
Daniel Veillard 已提交
525 526 527 528
            break;
        }
    }
    virLogUnlock();
529
    return ret;
D
Daniel Veillard 已提交
530 531 532 533 534 535 536 537 538 539 540 541 542 543 544
}

/**
 * virLogResetOutputs:
 *
 * Removes the set of logging output defined.
 *
 * Returns the number of output removed
 */
static int virLogResetOutputs(void) {
    int i;

    for (i = 0;i < virLogNbOutputs;i++) {
        if (virLogOutputs[i].c != NULL)
            virLogOutputs[i].c(virLogOutputs[i].data);
545
        VIR_FREE(virLogOutputs[i].name);
D
Daniel Veillard 已提交
546 547 548 549
    }
    VIR_FREE(virLogOutputs);
    i = virLogNbOutputs;
    virLogNbOutputs = 0;
550
    return i;
D
Daniel Veillard 已提交
551 552 553 554 555
}

/**
 * virLogDefineOutput:
 * @f: the function to call to output a message
556
 * @c: the function to call to close the output (or NULL)
D
Daniel Veillard 已提交
557 558
 * @data: extra data passed as first arg to the function
 * @priority: minimal priority for this filter, use 0 for none
559 560
 * @dest: where to send output of this priority
 * @name: optional name data associated with an output
D
Daniel Veillard 已提交
561 562 563 564 565 566 567 568
 * @flags: extra flag, currently unused
 *
 * Defines an output function for log messages. Each message once
 * gone though filtering is emitted through each registered output.
 *
 * Returns -1 in case of failure or the output number if successful
 */
int virLogDefineOutput(virLogOutputFunc f, virLogCloseFunc c, void *data,
569
                       int priority, int dest, const char *name,
570 571
                       unsigned int flags)
{
D
Daniel Veillard 已提交
572
    int ret = -1;
573
    char *ndup = NULL;
D
Daniel Veillard 已提交
574

575 576
    virCheckFlags(0, -1);

D
Daniel Veillard 已提交
577
    if (f == NULL)
578
        return -1;
D
Daniel Veillard 已提交
579

580 581
    if (dest == VIR_LOG_TO_SYSLOG || dest == VIR_LOG_TO_FILE) {
        if (name == NULL)
582
            return -1;
583 584
        ndup = strdup(name);
        if (ndup == NULL)
585
            return -1;
586 587
    }

D
Daniel Veillard 已提交
588 589
    virLogLock();
    if (VIR_REALLOC_N(virLogOutputs, virLogNbOutputs + 1)) {
590
        VIR_FREE(ndup);
D
Daniel Veillard 已提交
591 592 593
        goto cleanup;
    }
    ret = virLogNbOutputs++;
594
    virLogOutputs[ret].logVersion = true;
D
Daniel Veillard 已提交
595 596 597 598
    virLogOutputs[ret].f = f;
    virLogOutputs[ret].c = c;
    virLogOutputs[ret].data = data;
    virLogOutputs[ret].priority = priority;
599 600
    virLogOutputs[ret].dest = dest;
    virLogOutputs[ret].name = ndup;
D
Daniel Veillard 已提交
601 602
cleanup:
    virLogUnlock();
603
    return ret;
D
Daniel Veillard 已提交
604 605
}

606

607 608 609 610 611 612 613 614
static int
virLogFormatString(char **msg,
                   const char *funcname,
                   long long linenr,
                   int priority,
                   const char *str)
{
    int ret;
615 616 617 618 619 620 621 622

    /*
     * Be careful when changing the following log message formatting, we rely
     * on it when stripping libvirt debug messages from qemu log files. So when
     * changing this, you might also need to change the code there.
     * virLogFormatString() function name is mentioned there so it's sufficient
     * to just grep for it to find the right place.
     */
623
    if ((funcname != NULL)) {
624 625 626
        ret = virAsprintf(msg, "%d: %s : %s:%lld : %s\n",
                          virThreadSelfID(), virLogPriorityString(priority),
                          funcname, linenr, str);
627
    } else {
628 629 630
        ret = virAsprintf(msg, "%d: %s : %s\n",
                          virThreadSelfID(), virLogPriorityString(priority),
                          str);
631 632 633 634 635
    }
    return ret;
}

static int
636
virLogVersionString(char **msg)
637 638 639 640 641 642 643 644 645 646 647 648 649 650
{
#ifdef PACKAGER_VERSION
# ifdef PACKAGER
#  define LOG_VERSION_STRING \
    "libvirt version: " VERSION ", package: " PACKAGER_VERSION " (" PACKAGER ")"
# else
#  define LOG_VERSION_STRING \
    "libvirt version: " VERSION ", package: " PACKAGER_VERSION
# endif
#else
# define LOG_VERSION_STRING  \
    "libvirt version: " VERSION
#endif

651
    return virLogFormatString(msg, NULL, 0, VIR_LOG_INFO, LOG_VERSION_STRING);
652 653
}

D
Daniel Veillard 已提交
654 655 656 657
/**
 * virLogMessage:
 * @category: where is that message coming from
 * @priority: the priority level
658 659
 * @funcname: the function emitting the (debug) message
 * @linenr: line where the message was emitted
D
Daniel Veillard 已提交
660 661 662 663
 * @flags: extra flags, 1 if coming from the error handler
 * @fmt: the string format
 * @...: the arguments
 *
E
Eric Blake 已提交
664
 * Call the libvirt logger with some information. Based on the configuration
D
Daniel Veillard 已提交
665 666
 * the message may be stored, sent to output or just discarded
 */
667
void virLogMessage(const char *category, int priority, const char *funcname,
668
                   long long linenr, unsigned int flags, const char *fmt, ...)
669 670 671 672 673 674 675 676 677 678 679 680 681 682 683 684 685 686 687 688 689 690 691
{
    va_list ap;
    va_start(ap, fmt);
    virLogVMessage(category, priority, funcname, linenr, flags, fmt, ap);
    va_end(ap);
}

/**
 * virLogVMessage:
 * @category: where is that message coming from
 * @priority: the priority level
 * @funcname: the function emitting the (debug) message
 * @linenr: line where the message was emitted
 * @flags: extra flags, 1 if coming from the error handler
 * @fmt: the string format
 * @vargs: format args
 *
 * Call the libvirt logger with some information. Based on the configuration
 * the message may be stored, sent to output or just discarded
 */
void virLogVMessage(const char *category, int priority, const char *funcname,
                    long long linenr, unsigned int flags, const char *fmt,
                    va_list vargs)
692
{
693
    static bool logVersionStderr = true;
D
Daniel Veillard 已提交
694
    char *str = NULL;
695
    char *msg = NULL;
696
    char timestamp[VIR_TIME_STRING_BUFLEN];
697
    int fprio, i, ret;
698
    int saved_errno = errno;
699
    int emit = 1;
700
    unsigned int filterflags = 0;
D
Daniel Veillard 已提交
701

702 703
    if (virLogInitialize() < 0)
        return;
D
Daniel Veillard 已提交
704 705

    if (fmt == NULL)
706
        goto cleanup;
D
Daniel Veillard 已提交
707 708 709 710

    /*
     * check against list of specific logging patterns
     */
711
    fprio = virLogFiltersCheck(category, &filterflags);
D
Daniel Veillard 已提交
712 713
    if (fprio == 0) {
        if (priority < virLogDefaultPriority)
714
            emit = 0;
715
    } else if (priority < fprio) {
716
        emit = 0;
717
    }
D
Daniel Veillard 已提交
718

719 720 721
    if ((emit == 0) && ((virLogBuffer == NULL) || (virLogSize <= 0)))
        goto cleanup;

D
Daniel Veillard 已提交
722 723 724
    /*
     * serialize the error message, add level and timestamp
     */
725
    if (virVasprintf(&str, fmt, vargs) < 0) {
726
        goto cleanup;
E
Eric Blake 已提交
727
    }
D
Daniel Veillard 已提交
728

729
    ret = virLogFormatString(&msg, funcname, linenr, priority, str);
730
    VIR_FREE(str);
731 732
    if (ret < 0)
        goto cleanup;
D
Daniel Veillard 已提交
733

734 735
    if (virTimeStringNowRaw(timestamp) < 0)
        timestamp[0] = '\0';
736

D
Daniel Veillard 已提交
737
    /*
738 739
     * Log based on defaults, first store in the history buffer,
     * then if emit push the message on the outputs defined, if none
D
Daniel Veillard 已提交
740 741 742 743 744
     * use stderr.
     * NOTE: the locking is a single point of contention for multiple
     *       threads, but avoid intermixing. Maybe set up locks per output
     *       to improve paralellism.
     */
745 746 747 748
    virLogLock();
    virLogStr(timestamp);
    virLogStr(msg);
    virLogUnlock();
749 750 751
    if (emit == 0)
        goto cleanup;

D
Daniel Veillard 已提交
752
    virLogLock();
753
    for (i = 0; i < virLogNbOutputs; i++) {
754 755 756
        if (priority >= virLogOutputs[i].priority) {
            if (virLogOutputs[i].logVersion) {
                char *ver = NULL;
757 758 759
                if (virLogVersionString(&ver) >= 0)
                    virLogOutputs[i].f(category, VIR_LOG_INFO,
                                       __func__, __LINE__,
760
                                       timestamp, 0, ver,
761 762 763 764
                                       virLogOutputs[i].data);
                VIR_FREE(ver);
                virLogOutputs[i].logVersion = false;
            }
765
            virLogOutputs[i].f(category, priority, funcname, linenr,
766 767
                               timestamp, filterflags,
                               msg, virLogOutputs[i].data);
768
        }
D
Daniel Veillard 已提交
769
    }
770 771 772
    if ((virLogNbOutputs == 0) && (flags != 1)) {
        if (logVersionStderr) {
            char *ver = NULL;
773 774 775
            if (virLogVersionString(&ver) >= 0)
                virLogOutputToFd(category, VIR_LOG_INFO,
                                 __func__, __LINE__,
776
                                 timestamp, 0, ver,
777
                                 (void *) STDERR_FILENO);
778 779 780
            VIR_FREE(ver);
            logVersionStderr = false;
        }
781
        virLogOutputToFd(category, priority, funcname, linenr,
782 783
                         timestamp, filterflags,
                         msg, (void *) STDERR_FILENO);
784
    }
D
Daniel Veillard 已提交
785 786
    virLogUnlock();

787
cleanup:
788
    VIR_FREE(msg);
789
    errno = saved_errno;
D
Daniel Veillard 已提交
790 791
}

792 793 794 795 796 797 798 799 800 801 802 803 804 805 806 807 808 809 810 811 812 813

static void virLogStackTraceToFd(int fd)
{
#ifdef HAVE_EXECINFO_H
    void *array[100];
    int size;

# define STRIP_DEPTH 3

    size = backtrace(array, ARRAY_CARDINALITY(array));
    backtrace_symbols_fd(array +  STRIP_DEPTH, size - STRIP_DEPTH, fd);
    ignore_value(safewrite(fd, "\n", 1));
#else
    static bool doneWarning = false;
    const char *msg = "Stack trace not available on this platform\n";
    if (!doneWarning) {
        ignore_value(safewrite(fd, msg, strlen(msg)));
        doneWarning = true;
    }
#endif
}

814
static int virLogOutputToFd(const char *category ATTRIBUTE_UNUSED,
D
Daniel Veillard 已提交
815
                            int priority ATTRIBUTE_UNUSED,
816 817
                            const char *funcname ATTRIBUTE_UNUSED,
                            long long linenr ATTRIBUTE_UNUSED,
818
                            const char *timestamp,
819
                            unsigned int flags,
820 821 822
                            const char *str,
                            void *data)
{
823
    int fd = (intptr_t) data;
D
Daniel Veillard 已提交
824
    int ret;
825
    char *msg;
D
Daniel Veillard 已提交
826 827

    if (fd < 0)
828
        return -1;
829 830 831 832 833 834 835

    if (virAsprintf(&msg, "%s: %s", timestamp, str) < 0)
        return -1;

    ret = safewrite(fd, msg, strlen(msg));
    VIR_FREE(msg);

836 837 838
    if (flags & VIR_LOG_STACK_TRACE)
        virLogStackTraceToFd(fd);

839
    return ret;
D
Daniel Veillard 已提交
840 841
}

842 843
static void virLogCloseFd(void *data)
{
844
    int fd = (intptr_t) data;
D
Daniel Veillard 已提交
845

846
    VIR_LOG_CLOSE(fd);
D
Daniel Veillard 已提交
847 848 849
}

static int virLogAddOutputToStderr(int priority) {
850 851
    if (virLogDefineOutput(virLogOutputToFd, NULL, (void *)2L, priority,
                           VIR_LOG_TO_STDERR, NULL, 0) < 0)
852 853
        return -1;
    return 0;
D
Daniel Veillard 已提交
854 855 856 857 858
}

static int virLogAddOutputToFile(int priority, const char *file) {
    int fd;

859
    fd = open(file, O_CREAT | O_APPEND | O_WRONLY, S_IRUSR | S_IWUSR);
D
Daniel Veillard 已提交
860
    if (fd < 0)
861
        return -1;
862 863
    if (virLogDefineOutput(virLogOutputToFd, virLogCloseFd,
                           (void *)(intptr_t)fd,
864
                           priority, VIR_LOG_TO_FILE, file, 0) < 0) {
865
        VIR_FORCE_CLOSE(fd);
866
        return -1;
D
Daniel Veillard 已提交
867
    }
868
    return 0;
D
Daniel Veillard 已提交
869 870 871
}

#if HAVE_SYSLOG_H
872 873 874 875
static int virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED,
                                int priority,
                                const char *funcname ATTRIBUTE_UNUSED,
                                long long linenr ATTRIBUTE_UNUSED,
876
                                const char *timestamp ATTRIBUTE_UNUSED,
877
                                unsigned int flags,
878 879 880
                                const char *str,
                                void *data ATTRIBUTE_UNUSED)
{
D
Daniel Veillard 已提交
881 882
    int prio;

883 884
    virCheckFlags(VIR_LOG_STACK_TRACE, -1);

D
Daniel Veillard 已提交
885 886 887 888 889 890 891 892 893 894 895 896 897 898 899 900 901
    switch (priority) {
        case VIR_LOG_DEBUG:
            prio = LOG_DEBUG;
            break;
        case VIR_LOG_INFO:
            prio = LOG_INFO;
            break;
        case VIR_LOG_WARN:
            prio = LOG_WARNING;
            break;
        case VIR_LOG_ERROR:
            prio = LOG_ERR;
            break;
        default:
            prio = LOG_ERR;
    }
    syslog(prio, "%s", str);
902
    return strlen(str);
D
Daniel Veillard 已提交
903 904
}

905 906
static char *current_ident = NULL;

D
Daniel Veillard 已提交
907 908
static void virLogCloseSyslog(void *data ATTRIBUTE_UNUSED) {
    closelog();
909
    VIR_FREE(current_ident);
D
Daniel Veillard 已提交
910 911 912
}

static int virLogAddOutputToSyslog(int priority, const char *ident) {
913 914 915 916 917 918
    /*
     * ident needs to be kept around on Solaris
     */
    VIR_FREE(current_ident);
    current_ident = strdup(ident);
    if (current_ident == NULL)
919
        return -1;
920 921

    openlog(current_ident, 0, 0);
D
Daniel Veillard 已提交
922
    if (virLogDefineOutput(virLogOutputToSyslog, virLogCloseSyslog, NULL,
923
                           priority, VIR_LOG_TO_SYSLOG, ident, 0) < 0) {
D
Daniel Veillard 已提交
924
        closelog();
925
        VIR_FREE(current_ident);
926
        return -1;
D
Daniel Veillard 已提交
927
    }
928
    return 0;
D
Daniel Veillard 已提交
929 930 931 932 933 934 935 936 937 938 939 940 941 942 943 944 945 946 947 948 949 950 951 952 953 954 955 956 957 958 959 960 961
}
#endif /* HAVE_SYSLOG_H */

#define IS_SPACE(cur)                                                   \
    ((*cur == ' ') || (*cur == '\t') || (*cur == '\n') ||               \
     (*cur == '\r') || (*cur == '\\'))

/**
 * virLogParseOutputs:
 * @outputs: string defining a (set of) output(s)
 *
 * The format for an output can be:
 *    x:stderr
 *       output goes to stderr
 *    x:syslog:name
 *       use syslog for the output and use the given name as the ident
 *    x:file:file_path
 *       output to a file, with the given filepath
 * In all case the x prefix is the minimal level, acting as a filter
 *    0: everything
 *    1: DEBUG
 *    2: INFO
 *    3: WARNING
 *    4: ERROR
 *
 * Multiple output can be defined in a single @output, they just need to be
 * separated by spaces.
 *
 * Returns the number of output parsed and installed or -1 in case of error
 */
int virLogParseOutputs(const char *outputs) {
    const char *cur = outputs, *str;
    char *name;
962
    char *abspath;
D
Daniel Veillard 已提交
963
    int prio;
964 965
    int ret = -1;
    int count = 0;
D
Daniel Veillard 已提交
966 967

    if (cur == NULL)
968
        return -1;
D
Daniel Veillard 已提交
969 970 971 972

    virSkipSpaces(&cur);
    while (*cur != 0) {
        prio= virParseNumber(&cur);
973
        if ((prio < VIR_LOG_DEBUG) || (prio > VIR_LOG_ERROR))
974
            goto cleanup;
D
Daniel Veillard 已提交
975
        if (*cur != ':')
976
            goto cleanup;
D
Daniel Veillard 已提交
977 978 979 980
        cur++;
        if (STREQLEN(cur, "stderr", 6)) {
            cur += 6;
            if (virLogAddOutputToStderr(prio) == 0)
981
                count++;
D
Daniel Veillard 已提交
982 983 984
        } else if (STREQLEN(cur, "syslog", 6)) {
            cur += 6;
            if (*cur != ':')
985
                goto cleanup;
D
Daniel Veillard 已提交
986 987 988 989 990
            cur++;
            str = cur;
            while ((*cur != 0) && (!IS_SPACE(cur)))
                cur++;
            if (str == cur)
991
                goto cleanup;
D
Daniel Veillard 已提交
992 993 994
#if HAVE_SYSLOG_H
            name = strndup(str, cur - str);
            if (name == NULL)
995
                goto cleanup;
D
Daniel Veillard 已提交
996
            if (virLogAddOutputToSyslog(prio, name) == 0)
997
                count++;
D
Daniel Veillard 已提交
998 999 1000 1001 1002
            VIR_FREE(name);
#endif /* HAVE_SYSLOG_H */
        } else if (STREQLEN(cur, "file", 4)) {
            cur += 4;
            if (*cur != ':')
1003
                goto cleanup;
D
Daniel Veillard 已提交
1004 1005 1006 1007 1008
            cur++;
            str = cur;
            while ((*cur != 0) && (!IS_SPACE(cur)))
                cur++;
            if (str == cur)
1009
                goto cleanup;
D
Daniel Veillard 已提交
1010 1011
            name = strndup(str, cur - str);
            if (name == NULL)
1012
                goto cleanup;
1013 1014 1015 1016 1017
            if (virFileAbsPath(name, &abspath) < 0) {
                VIR_FREE(name);
                return -1; /* skip warning here because setting was fine */
            }
            if (virLogAddOutputToFile(prio, abspath) == 0)
1018
                count++;
D
Daniel Veillard 已提交
1019
            VIR_FREE(name);
1020
            VIR_FREE(abspath);
D
Daniel Veillard 已提交
1021
        } else {
1022
            goto cleanup;
D
Daniel Veillard 已提交
1023 1024 1025
        }
        virSkipSpaces(&cur);
    }
1026 1027 1028
    ret = count;
cleanup:
    if (ret == -1)
1029
        VIR_WARN("Ignoring invalid log output setting.");
1030
    return ret;
D
Daniel Veillard 已提交
1031 1032 1033 1034 1035 1036 1037 1038 1039 1040 1041 1042 1043 1044 1045 1046 1047 1048 1049 1050 1051 1052 1053 1054
}

/**
 * virLogParseFilters:
 * @filters: string defining a (set of) filter(s)
 *
 * The format for a filter is:
 *    x:name
 *       where name is a match string
 * the x prefix is the minimal level where the messages should be logged
 *    1: DEBUG
 *    2: INFO
 *    3: WARNING
 *    4: ERROR
 *
 * Multiple filter can be defined in a single @filters, they just need to be
 * separated by spaces.
 *
 * Returns the number of filter parsed and installed or -1 in case of error
 */
int virLogParseFilters(const char *filters) {
    const char *cur = filters, *str;
    char *name;
    int prio;
1055 1056
    int ret = -1;
    int count = 0;
D
Daniel Veillard 已提交
1057 1058

    if (cur == NULL)
1059
        return -1;
D
Daniel Veillard 已提交
1060 1061 1062

    virSkipSpaces(&cur);
    while (*cur != 0) {
1063
        unsigned int flags = 0;
D
Daniel Veillard 已提交
1064
        prio= virParseNumber(&cur);
1065
        if ((prio < VIR_LOG_DEBUG) || (prio > VIR_LOG_ERROR))
1066
            goto cleanup;
D
Daniel Veillard 已提交
1067
        if (*cur != ':')
1068
            goto cleanup;
D
Daniel Veillard 已提交
1069
        cur++;
1070 1071 1072 1073
        if (*cur == '+') {
            flags |= VIR_LOG_STACK_TRACE;
            cur++;
        }
D
Daniel Veillard 已提交
1074 1075 1076 1077
        str = cur;
        while ((*cur != 0) && (!IS_SPACE(cur)))
            cur++;
        if (str == cur)
1078
            goto cleanup;
D
Daniel Veillard 已提交
1079 1080
        name = strndup(str, cur - str);
        if (name == NULL)
1081
            goto cleanup;
1082
        if (virLogDefineFilter(name, prio, flags) >= 0)
1083
            count++;
D
Daniel Veillard 已提交
1084 1085 1086
        VIR_FREE(name);
        virSkipSpaces(&cur);
    }
1087 1088 1089
    ret = count;
cleanup:
    if (ret == -1)
1090
        VIR_WARN("Ignoring invalid log filter setting.");
1091
    return ret;
D
Daniel Veillard 已提交
1092
}
1093 1094 1095 1096 1097 1098 1099

/**
 * virLogGetDefaultPriority:
 *
 * Returns the current logging priority level.
 */
int virLogGetDefaultPriority(void) {
1100
    return virLogDefaultPriority;
1101 1102
}

1103 1104 1105 1106 1107 1108 1109 1110 1111 1112 1113 1114 1115
/**
 * virLogGetFilters:
 *
 * Returns a string listing the current filters, in the format originally
 * specified in the config file or environment. Caller must free the
 * result.
 */
char *virLogGetFilters(void) {
    int i;
    virBuffer filterbuf = VIR_BUFFER_INITIALIZER;

    virLogLock();
    for (i = 0; i < virLogNbFilters; i++) {
1116 1117 1118 1119 1120 1121
        const char *sep = ":";
        if (virLogFilters[i].flags & VIR_LOG_STACK_TRACE)
            sep = ":+";
        virBufferAsprintf(&filterbuf, "%d%s%s ",
                          virLogFilters[i].priority,
                          sep,
1122 1123 1124 1125
                          virLogFilters[i].match);
    }
    virLogUnlock();

1126 1127
    if (virBufferError(&filterbuf)) {
        virBufferFreeAndReset(&filterbuf);
1128
        return NULL;
1129
    }
1130 1131 1132 1133 1134 1135 1136 1137 1138 1139 1140 1141 1142 1143 1144 1145 1146 1147 1148

    return virBufferContentAndReset(&filterbuf);
}

/**
 * virLogGetOutputs:
 *
 * Returns a string listing the current outputs, in the format originally
 * specified in the config file or environment. Caller must free the
 * result.
 */
char *virLogGetOutputs(void) {
    int i;
    virBuffer outputbuf = VIR_BUFFER_INITIALIZER;

    virLogLock();
    for (i = 0; i < virLogNbOutputs; i++) {
        int dest = virLogOutputs[i].dest;
        if (i)
1149
            virBufferAsprintf(&outputbuf, " ");
1150 1151 1152
        switch (dest) {
            case VIR_LOG_TO_SYSLOG:
            case VIR_LOG_TO_FILE:
1153
                virBufferAsprintf(&outputbuf, "%d:%s:%s",
1154 1155 1156 1157 1158
                                  virLogOutputs[i].priority,
                                  virLogOutputString(dest),
                                  virLogOutputs[i].name);
                break;
            default:
1159
                virBufferAsprintf(&outputbuf, "%d:%s",
1160 1161 1162 1163 1164 1165
                                  virLogOutputs[i].priority,
                                  virLogOutputString(dest));
        }
    }
    virLogUnlock();

1166 1167
    if (virBufferError(&outputbuf)) {
        virBufferFreeAndReset(&outputbuf);
1168
        return NULL;
1169
    }
1170 1171 1172 1173

    return virBufferContentAndReset(&outputbuf);
}

1174 1175 1176 1177 1178 1179
/**
 * virLogGetNbFilters:
 *
 * Returns the current number of defined log filters.
 */
int virLogGetNbFilters(void) {
1180
    return virLogNbFilters;
1181 1182 1183 1184 1185 1186 1187 1188
}

/**
 * virLogGetNbOutputs:
 *
 * Returns the current number of defined log outputs.
 */
int virLogGetNbOutputs(void) {
1189
    return virLogNbOutputs;
1190
}
1191 1192 1193 1194 1195 1196 1197 1198 1199 1200 1201 1202 1203 1204 1205 1206 1207 1208 1209 1210 1211 1212 1213 1214 1215 1216

/**
 * virLogParseDefaultPriority:
 * @priority: string defining the desired logging level
 *
 * Parses and sets the default log priority level. It can take a string or
 * number corresponding to the following levels:
 *    1: DEBUG
 *    2: INFO
 *    3: WARNING
 *    4: ERROR
 *
 * Returns the parsed log level or -1 on error.
 */
int virLogParseDefaultPriority(const char *priority) {
    int ret = -1;

    if (STREQ(priority, "1") || STREQ(priority, "debug"))
        ret = virLogSetDefaultPriority(VIR_LOG_DEBUG);
    else if (STREQ(priority, "2") || STREQ(priority, "info"))
        ret = virLogSetDefaultPriority(VIR_LOG_INFO);
    else if (STREQ(priority, "3") || STREQ(priority, "warning"))
        ret = virLogSetDefaultPriority(VIR_LOG_WARN);
    else if (STREQ(priority, "4") || STREQ(priority, "error"))
        ret = virLogSetDefaultPriority(VIR_LOG_ERROR);
    else
1217
        VIR_WARN("Ignoring invalid log level setting");
1218 1219 1220 1221 1222 1223 1224 1225 1226 1227 1228 1229 1230 1231 1232 1233 1234 1235

    return ret;
}

/**
 * virLogSetFromEnv:
 *
 * Sets virLogDefaultPriority, virLogFilters and virLogOutputs based on
 * environment variables.
 */
void virLogSetFromEnv(void) {
    char *debugEnv;

    debugEnv = getenv("LIBVIRT_DEBUG");
    if (debugEnv && *debugEnv)
        virLogParseDefaultPriority(debugEnv);
    debugEnv = getenv("LIBVIRT_LOG_FILTERS");
    if (debugEnv && *debugEnv)
1236
        virLogParseFilters(debugEnv);
1237 1238
    debugEnv = getenv("LIBVIRT_LOG_OUTPUTS");
    if (debugEnv && *debugEnv)
1239
        virLogParseOutputs(debugEnv);
1240
}