glusterfs

1
/*
2
  Copyright (c) 2008-2012 Red Hat, Inc. <http://www.redhat.com>
3
  This file is part of GlusterFS.
4

5
  This file is licensed to you under your choice of the GNU Lesser
6
  General Public License, version 3 or any later version (LGPLv3 or
7
  later), or the GNU General Public License, version 2 (GPLv2), in all
8
  cases as published by the Free Software Foundation.
9
*/
10

11
#include <errno.h>
12
#include <pthread.h>
13
#include <stdio.h>
14
#include <stdarg.h>
15
#include <time.h>
16
#include <locale.h>
17
#include <string.h>
18
#include <stdlib.h>
19
#include <syslog.h>
20
#include <sys/resource.h>
21

22
#ifdef HAVE_BACKTRACE
23
#include <execinfo.h>
24
#else
25
#include "execinfo_compat.h"
26
#endif
27

28
#include <sys/stat.h>
29

30
#include "glusterfs/syscall.h"
31

32
#define GF_JSON_MSG_LENGTH 8192
33
#define GF_SYSLOG_CEE_FORMAT                                                   \
34
    "@cee: {\"msg\": \"%s\", \"gf_code\": \"%u\", \"gf_message\": \"%s\"}"
35
#define GF_LOG_CONTROL_FILE "/etc/glusterfs/logger.conf"
36
#define GF_LOG_BACKTRACE_DEPTH 5
37
#define GF_LOG_BACKTRACE_SIZE 4096
38
#define GF_MAX_SLOG_PAIR_COUNT 100
39

40
#define SET_LOG_PRIO(level, priority)                                          \
41
    do {                                                                       \
42
        if (GF_LOG_TRACE == (level) || GF_LOG_NONE == (level)) {               \
43
            priority = LOG_DEBUG;                                              \
44
        } else {                                                               \
45
            priority = (level)-1;                                              \
46
        }                                                                      \
47
    } while (0)
48

49
/* extract just the file name from the path */
50
#define GET_FILE_NAME_TO_LOG(file, basename)                                   \
51
    do {                                                                       \
52
        basename = strrchr((file), '/');                                       \
53
        if (basename)                                                          \
54
            basename++;                                                        \
55
        else                                                                   \
56
            basename = (file);                                                 \
57
    } while (0)
58

59
#define PRINT_SIZE_CHECK(ret, label, strsize)                                  \
60
    do {                                                                       \
61
        if (ret < 0)                                                           \
62
            goto label;                                                        \
63
        if ((strsize - ret) > 0) {                                             \
64
            strsize -= ret;                                                    \
65
        } else {                                                               \
66
            ret = 0;                                                           \
67
            goto label;                                                        \
68
        }                                                                      \
69
    } while (0)
70

71
#include "glusterfs/logging.h"
72
#include "glusterfs/timer.h"
73
#include "glusterfs/libglusterfs-messages.h"
74

75
/* Do not replace gf_log in TEST_LOG with gf_msg, as there is a slight chance
76
 * that it could lead to an infinite recursion.*/
77
#define TEST_LOG(__msg, __args...)                                             \
78
    gf_log("logging-infra", GF_LOG_DEBUG, __msg, ##__args);
79

80
static void
81
gf_log_flush_timeout_cbk(void *data);
82

83
int
84
gf_log_inject_timer_event(glusterfs_ctx_t *ctx);
85

86
static void
87
gf_log_flush_extra_msgs(gf_log_handle_t *log, uint32_t new);
88

89
static int
90
log_buf_init(log_buf_t *buf, const char *domain, const char *file,
91
             const char *function, int32_t line, gf_loglevel_t level,
92
             int errnum, uint64_t msgid, char *appmsgstr, int graph_id);
93
static void
94
gf_log_rotate(gf_log_handle_t *log);
95

96
static char gf_level_strings[] = {
97
    ' ', /* NONE */
98
    'M', /* EMERGENCY */
99
    'A', /* ALERT */
100
    'C', /* CRITICAL */
101
    'E', /* ERROR */
102
    'W', /* WARNING */
103
    'N', /* NOTICE */
104
    'I', /* INFO */
105
    'D', /* DEBUG */
106
    'T', /* TRACE */
107
};
108

109
void
110
gf_log_logrotate(int signum)
111
{
112
    xlator_t *this = THIS;
113
    if (this->ctx) {
114
        this->ctx->log.logrotate = 1;
115
        this->ctx->log.cmd_history_logrotate = 1;
116
    }
117
}
118

119
void
120
gf_log_enable_syslog(glusterfs_ctx_t *ctx)
121
{
122
    if (ctx)
123
        ctx->log.gf_log_syslog = 1;
124
}
125

126
void
127
gf_log_disable_syslog(glusterfs_ctx_t *ctx)
128
{
129
    if (ctx)
130
        ctx->log.gf_log_syslog = 0;
131
}
132

133
gf_loglevel_t
134
gf_log_get_loglevel(void)
135
{
136
    xlator_t *this = THIS;
137
    if (this->ctx)
138
        return this->ctx->log.loglevel;
139
    else
140
        /* return global defaults (see gf_log_globals_init) */
141
        return GF_LOG_INFO;
142
}
143

144
void
145
gf_log_set_loglevel(glusterfs_ctx_t *ctx, gf_loglevel_t level)
146
{
147
    if (ctx)
148
        ctx->log.loglevel = level;
149
}
150

151
int
152
gf_log_get_localtime(void)
153
{
154
    xlator_t *this = THIS;
155
    if (this->ctx)
156
        return this->ctx->log.localtime;
157
    else
158
        /* return global defaults (see gf_log_globals_init) */
159
        return 0;
160
}
161

162
void
163
gf_log_set_localtime(int on_off)
164
{
165
    xlator_t *this = THIS;
166
    if (this->ctx)
167
        this->ctx->log.localtime = on_off;
168
}
169

170
void
171
gf_log_flush(glusterfs_ctx_t *ctx)
172
{
173
    if (ctx && ctx->log.logger == gf_logger_glusterlog) {
174
        pthread_mutex_lock(&ctx->log.logfile_mutex);
175
        fflush(ctx->log.gf_log_logfile);
176
        pthread_mutex_unlock(&ctx->log.logfile_mutex);
177
    }
178

179
    return;
180
}
181

182
void
183
gf_log_set_xl_loglevel(void *this, gf_loglevel_t level)
184
{
185
    xlator_t *xl = this;
186
    if (xl)
187
        xl->loglevel = level;
188
}
189

190
/* TODO: The following get/set functions are yet not invoked from anywhere
191
 * in the code. The _intention_ is to pass CLI arguments to various daemons
192
 * that are started, which would then invoke these set APIs as required.
193
 *
194
 * glusterd would read the defaults from its .vol file configuration shipped
195
 * as a part of the packages distributed.
196
 *
197
 * For any gluster* daemon that is started the shipped configuration becomes the
198
 * default, if a volume has to change its logging format or logger, then a
199
 * gluster CLI is invoked to set this property for the volume in question.
200
 *
201
 * The property is maintained by glusterd, and passed to the daemon as a CLI
202
 * option, IOW persistence of the option is maintained by glusterd persistent
203
 * storage (i.e .vol file) only
204
 *
205
 * care needs to be taken to configure and start daemons based on the versions
206
 * that supports these features */
207

208
void
209
gf_log_set_logformat(gf_log_format_t format)
210
{
211
    xlator_t *this = THIS;
212
    if (this->ctx)
213
        this->ctx->log.logformat = format;
214
}
215

216
void
217
gf_log_set_logger(gf_log_logger_t logger)
218
{
219
    xlator_t *this = THIS;
220
    if (this->ctx)
221
        this->ctx->log.logger = logger;
222
}
223

224
gf_loglevel_t
225
gf_log_get_xl_loglevel(void *this)
226
{
227
    xlator_t *xl = this;
228
    if (xl)
229
        return xl->loglevel;
230
    return 0;
231
}
232

233
void
234
gf_log_set_log_buf_size(glusterfs_ctx_t *ctx, uint32_t buf_size)
235
{
236
    uint32_t old = 0;
237

238
    if (ctx == NULL)
239
        return;
240

241
    pthread_mutex_lock(&ctx->log.log_buf_lock);
242
    {
243
        old = ctx->log.lru_size;
244
        ctx->log.lru_size = buf_size;
245
    }
246
    pthread_mutex_unlock(&ctx->log.log_buf_lock);
247

248
    /* If the old size is less than/equal to the new size, then do nothing.
249
     *
250
     * But if the new size is less than the old size, then
251
     *   a. If the cur size of the buf is less than or equal the new size,
252
     *      then do nothing.
253
     *   b. But if the current size of the buf is greater than the new size,
254
     *      then flush the least recently used (cur size - new_size) msgs
255
     *      to disk.
256
     */
257
    if (buf_size < old)
258
        gf_log_flush_extra_msgs(&ctx->log, buf_size);
259
}
260

261
void
262
gf_log_set_log_flush_timeout(glusterfs_ctx_t *ctx, uint32_t timeout)
263
{
264
    if (ctx)
265
        ctx->log.timeout = timeout;
266
}
267

268
/* If log_buf_init() fails (indicated by a return value of -1),
269
 * call log_buf_destroy() to clean up memory allocated in heap and to return
270
 * the log_buf_t object back to its memory pool.
271
 */
272
static int
273
log_buf_init(log_buf_t *buf, const char *domain, const char *file,
274
             const char *function, int32_t line, gf_loglevel_t level,
275
             int errnum, uint64_t msgid, char *appmsgstr, int graph_id)
276
{
277
    int ret = -1;
278

279
    if (!buf || !domain || !file || !function || !appmsgstr)
280
        goto out;
281

282
    buf->msg = gf_strdup(appmsgstr);
283
    if (!buf->msg)
284
        goto out;
285

286
    buf->msg_id = msgid;
287
    buf->errnum = errnum;
288
    buf->domain = gf_strdup(domain);
289
    if (!buf->domain)
290
        goto out;
291

292
    buf->file = gf_strdup(file);
293
    if (!buf->file)
294
        goto out;
295

296
    buf->function = gf_strdup(function);
297
    if (!buf->function)
298
        goto out;
299

300
    buf->line = line;
301
    buf->level = level;
302
    buf->refcount = 0;
303
    buf->graph_id = graph_id;
304
    INIT_LIST_HEAD(&buf->msg_list);
305

306
    ret = 0;
307
out:
308
    return ret;
309
}
310

311
static int
312
log_buf_destroy(log_buf_t *buf)
313
{
314
    if (!buf)
315
        return -1;
316

317
    GF_FREE(buf->msg);
318
    GF_FREE(buf->domain);
319
    GF_FREE(buf->file);
320
    GF_FREE(buf->function);
321

322
    mem_put(buf);
323
    return 0;
324
}
325

326
static void
327
gf_log_rotate(gf_log_handle_t *log)
328
{
329
    int fd = -1;
330
    FILE *new_logfile = NULL;
331
    FILE *old_logfile = NULL;
332

333
    /* not involving locks on initial check to speed it up */
334
    if (log->logrotate) {
335
        /* let only one winner through on races */
336
        pthread_mutex_lock(&log->logfile_mutex);
337

338
        if (!log->logrotate) {
339
            pthread_mutex_unlock(&log->logfile_mutex);
340
            return;
341
        } else {
342
            log->logrotate = 0;
343
            pthread_mutex_unlock(&log->logfile_mutex);
344
        }
345

346
        fd = sys_open(log->filename, O_CREAT | O_WRONLY | O_APPEND,
347
                      S_IRUSR | S_IWUSR);
348
        if (fd < 0) {
349
            gf_smsg("logrotate", GF_LOG_ERROR, errno,
350
                    LG_MSG_OPEN_LOGFILE_FAILED, NULL);
351
            return;
352
        }
353

354
        new_logfile = fdopen(fd, "a");
355
        if (!new_logfile) {
356
            gf_smsg("logrotate", GF_LOG_CRITICAL, errno,
357
                    LG_MSG_OPEN_LOGFILE_FAILED, "filename=%s", log->filename,
358
                    NULL);
359
            sys_close(fd);
360
            return;
361
        }
362

363
        pthread_mutex_lock(&log->logfile_mutex);
364
        {
365
            if (log->logfile)
366
                old_logfile = log->logfile;
367

368
            log->gf_log_logfile = log->logfile = new_logfile;
369
        }
370
        pthread_mutex_unlock(&log->logfile_mutex);
371

372
        if (old_logfile != NULL)
373
            fclose(old_logfile);
374
    }
375

376
    return;
377
}
378

379
void
380
gf_log_globals_fini(void)
381
{
382
    xlator_t *this = THIS;
383
    /* TODO: Nobody is invoking the fini, but cleanup needs to happen here,
384
     * needs cleanup for, log.ident, log.filename, closelog, log file close
385
     * rotate state, possibly under a lock */
386
    pthread_mutex_destroy(&this->ctx->log.logfile_mutex);
387
    pthread_mutex_destroy(&this->ctx->log.log_buf_lock);
388
}
389

390
void
391
gf_log_disable_suppression_before_exit(glusterfs_ctx_t *ctx)
392
{
393
    /*
394
     * First set log buf size to 0. This would ensure two things:
395
     * i. that all outstanding log messages are flushed to disk, and
396
     * ii. all subsequent calls to gf_msg will result in the logs getting
397
     *     directly flushed to disk without being buffered.
398
     *
399
     * Then, cancel the current log timer event.
400
     */
401

402
    gf_log_set_log_buf_size(ctx, 0);
403
    pthread_mutex_lock(&ctx->log.log_buf_lock);
404
    {
405
        if (ctx->log.log_flush_timer) {
406
            gf_timer_call_cancel(ctx, ctx->log.log_flush_timer);
407
            ctx->log.log_flush_timer = NULL;
408
        }
409
    }
410
    pthread_mutex_unlock(&ctx->log.log_buf_lock);
411
}
412

413
/** gf_log_fini - function to perform the cleanup of the log information
414
 * @data - glusterfs context
415
 * @return: success: 0
416
 *          failure: -1
417
 */
418
int
419
gf_log_fini(void *data)
420
{
421
    glusterfs_ctx_t *ctx = data;
422
    int ret = 0;
423
    FILE *old_logfile = NULL;
424

425
    if (ctx == NULL) {
426
        ret = -1;
427
        goto out;
428
    }
429

430
    gf_log_disable_suppression_before_exit(ctx);
431

432
    pthread_mutex_lock(&ctx->log.logfile_mutex);
433
    {
434
        if (ctx->log.logfile) {
435
            old_logfile = ctx->log.logfile;
436

437
            /* Logfile needs to be set to NULL, so that any
438
               call to gf_log after calling gf_log_fini, will
439
               log the message to stderr.
440
            */
441
            ctx->log.loglevel = GF_LOG_NONE;
442
            ctx->log.logfile = NULL;
443
        }
444
    }
445
    pthread_mutex_unlock(&ctx->log.logfile_mutex);
446

447
    if (old_logfile && (fclose(old_logfile) != 0))
448
        ret = -1;
449

450
    GF_FREE(ctx->log.ident);
451
    GF_FREE(ctx->log.filename);
452

453
out:
454
    return ret;
455
}
456

457
/**
458
 * gf_openlog -function to open syslog specific to gluster based on
459
 *             existence of file /etc/glusterfs/logger.conf
460
 * @ident:    optional identification string similar to openlog()
461
 * @option:   optional value to option to openlog().  Passing -1 uses
462
 *            'LOG_PID | LOG_NDELAY' as default
463
 * @facility: optional facility code similar to openlog().  Passing -1
464
 *            uses LOG_DAEMON as default
465
 *
466
 * @return: void
467
 */
468
static void
469
gf_openlog(const char *ident, int option, int facility)
470
{
471
    int _option = option;
472
    int _facility = facility;
473
    char *language = NULL;
474

475
    if (-1 == _option) {
476
        _option = LOG_PID | LOG_NDELAY;
477
    }
478
    if (-1 == _facility) {
479
        _facility = LOG_LOCAL1;
480
    }
481

482
    /* TODO: Should check for errors here and return appropriately */
483
    language = setlocale(LC_ALL, "en_US.UTF-8");
484
    if (!language)
485
        setlocale(LC_ALL, "");
486

487
    setlocale(LC_NUMERIC, "C"); /* C-locale for strtod, ... */
488
    /* close the previous syslog if open as we are changing settings */
489
    closelog();
490
    openlog(ident, _option, _facility);
491
}
492

493
/**
494
 * _json_escape -function to convert string to json encoded string
495
 * @str: input string
496
 * @buf: buffer to store encoded string
497
 * @len: length of @buf
498
 *
499
 * @return: success: last unprocessed character position by pointer in @str
500
 *          failure: NULL
501
 *
502
 * Internal function. Heavily inspired by _ul_str_escape() function in
503
 * libumberlog
504
 *
505
 * Sample output:
506
 * [1] str = "devel error"
507
 *     buf = "devel error"
508
 * [2] str = "devel	error"
509
 *     buf = "devel\terror"
510
 * [3] str = "I/O error on "/tmp/foo" file"
511
 *     buf = "I/O error on \"/tmp/foo\" file"
512
 * [4] str = "I/O erroron /tmp/bar file"
513
 *     buf = "I/O error\u001bon /tmp/bar file"
514
 *
515
 */
516
static char *
517
_json_escape(const char *str, char *buf, size_t len)
518
{
519
    static const unsigned char json_exceptions[UCHAR_MAX + 1] = {
520
        [0x01] = 1, [0x02] = 1, [0x03] = 1, [0x04] = 1, [0x05] = 1, [0x06] = 1,
521
        [0x07] = 1, [0x08] = 1, [0x09] = 1, [0x0a] = 1, [0x0b] = 1, [0x0c] = 1,
522
        [0x0d] = 1, [0x0e] = 1, [0x0f] = 1, [0x10] = 1, [0x11] = 1, [0x12] = 1,
523
        [0x13] = 1, [0x14] = 1, [0x15] = 1, [0x16] = 1, [0x17] = 1, [0x18] = 1,
524
        [0x19] = 1, [0x1a] = 1, [0x1b] = 1, [0x1c] = 1, [0x1d] = 1, [0x1e] = 1,
525
        [0x1f] = 1, ['\\'] = 1, ['"'] = 1};
526
    static const char json_hex_chars[16] = "0123456789abcdef";
527
    unsigned char *p = NULL;
528
    size_t pos = 0;
529

530
    if (!str || !buf || len <= 0) {
531
        return NULL;
532
    }
533

534
    for (p = (unsigned char *)str; *p && (pos + 1) < len; p++) {
535
        if (json_exceptions[*p] == 0) {
536
            buf[pos++] = *p;
537
            continue;
538
        }
539

540
        if ((pos + 2) >= len) {
541
            break;
542
        }
543

544
        switch (*p) {
545
            case '\b':
546
                buf[pos++] = '\\';
547
                buf[pos++] = 'b';
548
                break;
549
            case '\n':
550
                buf[pos++] = '\\';
551
                buf[pos++] = 'n';
552
                break;
553
            case '\r':
554
                buf[pos++] = '\\';
555
                buf[pos++] = 'r';
556
                break;
557
            case '\t':
558
                buf[pos++] = '\\';
559
                buf[pos++] = 't';
560
                break;
561
            case '\\':
562
                buf[pos++] = '\\';
563
                buf[pos++] = '\\';
564
                break;
565
            case '"':
566
                buf[pos++] = '\\';
567
                buf[pos++] = '"';
568
                break;
569
            default:
570
                if ((pos + 6) >= len) {
571
                    buf[pos] = '\0';
572
                    return (char *)p;
573
                }
574
                buf[pos++] = '\\';
575
                buf[pos++] = 'u';
576
                buf[pos++] = '0';
577
                buf[pos++] = '0';
578
                buf[pos++] = json_hex_chars[(*p) >> 4];
579
                buf[pos++] = json_hex_chars[(*p) & 0xf];
580
                break;
581
        }
582
    }
583

584
    buf[pos] = '\0';
585
    return (char *)p;
586
}
587

588
/**
589
 * gf_syslog -function to submit message to syslog specific to gluster
590
 * @facility_priority: facility_priority of syslog()
591
 * @format:            optional format string to syslog()
592
 *
593
 * @return: void
594
 */
595
static void
596
gf_syslog(int facility_priority, char *format, ...)
597
{
598
    char *msg = NULL;
599
    char json_msg[GF_JSON_MSG_LENGTH];
600
    GF_UNUSED char *p = NULL;
601
    va_list ap;
602

603
    GF_ASSERT(format);
604

605
    va_start(ap, format);
606
    if (vasprintf(&msg, format, ap) != -1) {
607
        p = _json_escape(msg, json_msg, GF_JSON_MSG_LENGTH);
608
        syslog(facility_priority, "%s", msg);
609
        free(msg);
610
    } else
611
        syslog(GF_LOG_CRITICAL, "vasprintf() failed, out of memory?");
612
    va_end(ap);
613
}
614

615
void
616
gf_log_globals_init(void *data, gf_loglevel_t level)
617
{
618
    glusterfs_ctx_t *ctx = data;
619
    pthread_mutexattr_t log_m_attr;
620
    int ret;
621

622
    ret = pthread_mutexattr_init(&log_m_attr);
623

624
    pthread_mutex_init(&ctx->log.logfile_mutex, NULL);
625

626
    ctx->log.loglevel = level;
627
    ctx->log.gf_log_syslog = 1;
628
    ctx->log.sys_log_level = GF_LOG_CRITICAL;
629
    ctx->log.logger = gf_logger_glusterlog;
630
    ctx->log.logformat = gf_logformat_withmsgid;
631
    ctx->log.lru_size = GF_LOG_LRU_BUFSIZE_DEFAULT;
632
    ctx->log.timeout = GF_LOG_FLUSH_TIMEOUT_DEFAULT;
633
    ctx->log.localtime = GF_LOG_LOCALTIME_DEFAULT;
634

635
    if (ret) {
636
        pthread_mutex_init(&ctx->log.log_buf_lock, NULL);
637
    } else {
638
        pthread_mutexattr_settype(&log_m_attr, PTHREAD_MUTEX_RECURSIVE);
639
        pthread_mutex_init(&ctx->log.log_buf_lock, &log_m_attr);
640
    }
641

642
    INIT_LIST_HEAD(&ctx->log.lru_queue);
643

644
#ifdef GF_LINUX_HOST_OS
645
    /* For the 'syslog' output. one can grep 'GlusterFS' in syslog
646
       for serious logs */
647
    openlog("GlusterFS", LOG_PID, LOG_DAEMON);
648
#endif
649
}
650

651
int
652
gf_log_init(void *data, const char *file, const char *ident)
653
{
654
    glusterfs_ctx_t *ctx = data;
655
    int fd = -1;
656
    struct stat buf;
657

658
    if (ctx == NULL) {
659
        fprintf(stderr, "ERROR: ctx is NULL\n");
660
        return -1;
661
    }
662
    if (ident) {
663
        GF_FREE(ctx->log.ident);
664
        ctx->log.ident = gf_strdup(ident);
665
    }
666

667
    /* we keep the files and the syslog open, so that on logger change, we
668
     * are ready to log anywhere, that the new value specifies */
669
    if (ctx->log.ident) {
670
        gf_openlog(ctx->log.ident, -1, LOG_DAEMON);
671
    } else {
672
        gf_openlog(NULL, -1, LOG_DAEMON);
673
    }
674
    /* TODO: make FACILITY configurable than LOG_DAEMON */
675
    if (sys_stat(GF_LOG_CONTROL_FILE, &buf) == 0) {
676
        /* use syslog logging */
677
        ctx->log.log_control_file_found = 1;
678
    } else {
679
        /* use old style logging */
680
        ctx->log.log_control_file_found = 0;
681
    }
682

683
    if (!file) {
684
        fprintf(stderr, "ERROR: no filename specified\n");
685
        return -1;
686
    }
687

688
    /* free the (possible) previous filename */
689
    GF_FREE(ctx->log.filename);
690
    ctx->log.filename = NULL;
691

692
    /* close and reopen logfile for log rotate */
693
    if (ctx->log.logfile) {
694
        fclose(ctx->log.logfile);
695
        ctx->log.logfile = NULL;
696
        ctx->log.gf_log_logfile = NULL;
697
    }
698

699
    if (strcmp(file, "-") == 0) {
700
        int dupfd = -1;
701

702
        ctx->log.filename = gf_strdup("/dev/stderr");
703
        if (!ctx->log.filename) {
704
            fprintf(stderr, "ERROR: strdup failed\n");
705
            return -1;
706
        }
707

708
        dupfd = dup(fileno(stderr));
709
        if (dupfd == -1) {
710
            fprintf(stderr, "ERROR: could not dup %d (%s)\n", fileno(stderr),
711
                    strerror(errno));
712
            return -1;
713
        }
714

715
        ctx->log.logfile = fdopen(dupfd, "a");
716
        if (!ctx->log.logfile) {
717
            fprintf(stderr, "ERROR: could not fdopen on %d (%s)\n", dupfd,
718
                    strerror(errno));
719
            sys_close(dupfd);
720
            return -1;
721
        }
722
    } else {
723
        /* Also create parent dir */
724
        char *logdir = gf_strdup(file);
725
        if (!logdir) {
726
            return -1;
727
        }
728
        char *tmp_index = rindex(logdir, '/');
729
        if (tmp_index) {
730
            tmp_index[0] = '\0';
731
        }
732
        if (mkdir_p(logdir, 0755, true)) {
733
            /* EEXIST is handled in mkdir_p() itself */
734
            gf_smsg("logging", GF_LOG_ERROR, 0, LG_MSG_STRDUP_ERROR,
735
                    "logdir=%s", logdir, "errno=%s", strerror(errno), NULL);
736
            GF_FREE(logdir);
737
            return -1;
738
        }
739
        /* no need of this variable */
740
        GF_FREE(logdir);
741

742
        ctx->log.filename = gf_strdup(file);
743
        if (!ctx->log.filename) {
744
            fprintf(stderr,
745
                    "ERROR: updating log-filename failed: "
746
                    "%s\n",
747
                    strerror(errno));
748
            return -1;
749
        }
750

751
        fd = sys_open(file, O_CREAT | O_WRONLY | O_APPEND, S_IRUSR | S_IWUSR);
752
        if (fd < 0) {
753
            fprintf(stderr,
754
                    "ERROR: failed to create logfile"
755
                    " \"%s\" (%s)\n",
756
                    file, strerror(errno));
757
            return -1;
758
        }
759

760
        ctx->log.logfile = fdopen(fd, "a");
761
        if (!ctx->log.logfile) {
762
            fprintf(stderr,
763
                    "ERROR: failed to open logfile \"%s\" "
764
                    "(%s)\n",
765
                    file, strerror(errno));
766
            sys_close(fd);
767
            return -1;
768
        }
769
    }
770

771
    ctx->log.gf_log_logfile = ctx->log.logfile;
772

773
    return 0;
774
}
775

776
void
777
set_sys_log_level(gf_loglevel_t level)
778
{
779
    xlator_t *xl = THIS;
780
    if (xl->ctx)
781
        xl->ctx->log.sys_log_level = level;
782
}
783

784
/* Check if we should be logging
785
 * Return value: _gf_false : Print the log
786
 *               _gf_true : Do not Print the log
787
 */
788
static gf_boolean_t
789
skip_logging(xlator_t *this, gf_loglevel_t level)
790
{
791
    gf_loglevel_t existing_level = this->loglevel ? this->loglevel
792
                                                  : this->ctx->log.loglevel;
793
    if (level > existing_level) {
794
        return _gf_true;
795
    }
796

797
    if (level == GF_LOG_NONE) {
798
        return _gf_true;
799
    }
800

801
    return _gf_false;
802
}
803

804
int
805
_gf_log_callingfn(const char *domain, const char *file, const char *function,
806
                  int line, gf_loglevel_t level, const char *fmt, ...)
807
{
808
    const char *basename = NULL;
809
    xlator_t *this = THIS;
810
    char *logline = NULL;
811
    char *msg = NULL;
812
    char timestr[GF_TIMESTR_SIZE] = {
813
        0,
814
    };
815
    char *callstr = NULL;
816
    struct timeval tv = {
817
        0,
818
    };
819
    int ret = 0;
820
    va_list ap;
821
    glusterfs_ctx_t *ctx = this->ctx;
822

823
    if (!ctx)
824
        goto out;
825

826
    if (skip_logging(this, level))
827
        goto out;
828

829
    if (!domain || !file || !function || !fmt) {
830
        fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__,
831
                __PRETTY_FUNCTION__, __LINE__);
832
        return -1;
833
    }
834

835
    basename = strrchr(file, '/');
836
    if (basename)
837
        basename++;
838
    else
839
        basename = file;
840

841
    /*Saving the backtrace to pre-allocated ctx->btbuf
842
     * to avoid allocating memory from the heap*/
843
    callstr = gf_backtrace_save(NULL);
844

845
    va_start(ap, fmt);
846
    ret = vasprintf(&msg, fmt, ap);
847
    va_end(ap);
848
    if (-1 == ret) {
849
        goto out;
850
    }
851

852
    if (ctx->log.log_control_file_found) {
853
        int priority;
854
        /* treat GF_LOG_TRACE and GF_LOG_NONE as LOG_DEBUG and
855
           other level as is */
856
        if (GF_LOG_TRACE == level || GF_LOG_NONE == level) {
857
            priority = LOG_DEBUG;
858
        } else {
859
            priority = level - 1;
860
        }
861

862
        gf_syslog(priority, "[%s:%d:%s] %s %d-%s: %s", basename, line, function,
863
                  callstr, ((this->graph) ? this->graph->id : 0), domain, msg);
864

865
        goto out;
866
    }
867

868
    ret = gettimeofday(&tv, NULL);
869
    if (-1 == ret)
870
        goto out;
871

872
    gf_time_fmt_tv_FT(timestr, sizeof timestr, &tv, &ctx->log);
873

874
    ret = gf_asprintf(&logline, "[%s] %c [%s:%d:%s] %s %d-%s: %s\n", timestr,
875
                      gf_level_strings[level], basename, line, function,
876
                      callstr, ((this->graph) ? this->graph->id : 0), domain,
877
                      msg);
878
    if (-1 == ret) {
879
        goto out;
880
    }
881

882
    pthread_mutex_lock(&ctx->log.logfile_mutex);
883
    {
884
        if (ctx->log.logfile) {
885
            fputs(logline, ctx->log.logfile);
886
            fflush(ctx->log.logfile);
887
        } else if (ctx->log.loglevel >= level) {
888
            fputs(logline, stderr);
889
            fflush(stderr);
890
        }
891

892
#ifdef GF_LINUX_HOST_OS
893
        /* We want only serious log in 'syslog', not our debug
894
           and trace logs */
895
        if (ctx->log.gf_log_syslog && level &&
896
            (level <= ctx->log.sys_log_level))
897
            syslog((level - 1), "%s", logline);
898
#endif
899
    }
900

901
    pthread_mutex_unlock(&ctx->log.logfile_mutex);
902

903
out:
904

905
    GF_FREE(logline);
906

907
    FREE(msg);
908

909
    return ret;
910
}
911

912
static int
913
_gf_msg_plain_internal(gf_log_handle_t *log, gf_loglevel_t level,
914
                       const char *msg)
915
{
916
    int priority;
917

918
    if (!log)
919
        return -1;
920

921
    /* log to the configured logging service */
922
    switch (log->logger) {
923
        case gf_logger_syslog:
924
            if (log->log_control_file_found && log->gf_log_syslog) {
925
                SET_LOG_PRIO(level, priority);
926

927
                syslog(priority, "%s", msg);
928
                break;
929
            }
930
            /* NOTE: If syslog control file is absent, which is another
931
             * way to control logging to syslog, then we will fall through
932
             * to the gluster log. The ideal way to do things would be to
933
             * not have the extra control file check */
934
        case gf_logger_glusterlog:
935
            pthread_mutex_lock(&log->logfile_mutex);
936
            {
937
                if (log->logfile) {
938
                    fprintf(log->logfile, "%s\n", msg);
939
                    fflush(log->logfile);
940
                } else {
941
                    fprintf(stderr, "%s\n", msg);
942
                    fflush(stderr);
943
                }
944

945
#ifdef GF_LINUX_HOST_OS
946
                /* We want only serious logs in 'syslog', not our debug
947
                 * and trace logs */
948
                if (level && log->gf_log_syslog &&
949
                    (level <= log->sys_log_level))
950
                    syslog((level - 1), "%s\n", msg);
951
#endif
952
            }
953
            pthread_mutex_unlock(&log->logfile_mutex);
954

955
            break;
956
    }
957

958
    return 0;
959
}
960

961
int
962
_gf_msg_plain(gf_loglevel_t level, const char *fmt, ...)
963
{
964
    xlator_t *this = NULL;
965
    int ret = 0;
966
    va_list ap;
967
    char *msg = NULL;
968
    glusterfs_ctx_t *ctx = NULL;
969

970
    this = THIS;
971
    ctx = this->ctx;
972

973
    if (!ctx)
974
        goto out;
975

976
    if (skip_logging(this, level))
977
        goto out;
978

979
    va_start(ap, fmt);
980
    ret = vasprintf(&msg, fmt, ap);
981
    va_end(ap);
982
    if (-1 == ret) {
983
        goto out;
984
    }
985

986
    ret = _gf_msg_plain_internal(&ctx->log, level, msg);
987

988
    FREE(msg);
989

990
out:
991
    return ret;
992
}
993

994
int
995
_gf_msg_plain_nomem(gf_loglevel_t level, const char *msg)
996
{
997
    xlator_t *this = NULL;
998
    int ret = 0;
999
    glusterfs_ctx_t *ctx = NULL;
1000

1001
    this = THIS;
1002
    ctx = this->ctx;
1003

1004
    if (!ctx)
1005
        goto out;
1006

1007
    if (skip_logging(this, level))
1008
        goto out;
1009

1010
    ret = _gf_msg_plain_internal(&ctx->log, level, msg);
1011

1012
out:
1013
    return ret;
1014
}
1015

1016
void
1017
_gf_msg_backtrace_nomem(gf_loglevel_t level, int stacksize)
1018
{
1019
    xlator_t *this = NULL;
1020
    glusterfs_ctx_t *ctx = NULL;
1021
    void *array[200];
1022
    size_t bt_size = 0;
1023
    int fd = -1;
1024

1025
    this = THIS;
1026
    ctx = this->ctx;
1027

1028
    if (!ctx)
1029
        goto out;
1030

1031
    /* syslog does not have fd support, hence no no-mem variant */
1032
    if (ctx->log.logger != gf_logger_glusterlog)
1033
        goto out;
1034

1035
    if (skip_logging(this, level))
1036
        goto out;
1037

1038
    bt_size = backtrace(array, ((stacksize <= 200) ? stacksize : 200));
1039
    if (!bt_size)
1040
        goto out;
1041
    pthread_mutex_lock(&ctx->log.logfile_mutex);
1042
    {
1043
        fd = ctx->log.logfile ? fileno(ctx->log.logfile) : fileno(stderr);
1044
        if (fd != -1) {
1045
            /* print to the file fd, to prevent any
1046
               allocations from backtrace_symbols
1047
             */
1048
            backtrace_symbols_fd(&array[0], bt_size, fd);
1049
        }
1050
    }
1051
    pthread_mutex_unlock(&ctx->log.logfile_mutex);
1052

1053
out:
1054
    return;
1055
}
1056

1057
static int
1058
_gf_msg_backtrace(int stacksize, char *callstr, size_t strsize)
1059
{
1060
    int ret = -1;
1061
    int i = 0;
1062
    int size = 0;
1063
    int savstrsize = strsize;
1064
    void *array[200];
1065
    char **callingfn = NULL;
1066

1067
    /* We chop off last 2 anyway, so if request is less than tolerance
1068
     * nothing to do */
1069
    if (stacksize < 3)
1070
        goto out;
1071

1072
    size = backtrace(array, ((stacksize <= 200) ? stacksize : 200));
1073
    if ((size - 3) < 0)
1074
        goto out;
1075
    if (size)
1076
        callingfn = backtrace_symbols(&array[2], size - 2);
1077
    if (!callingfn)
1078
        goto out;
1079

1080
    ret = snprintf(callstr, strsize, "(");
1081
    PRINT_SIZE_CHECK(ret, out, strsize);
1082

1083
    for ((i = size - 3); i >= 0; i--) {
1084
        ret = snprintf(callstr + savstrsize - strsize, strsize, "-->%s ",
1085
                       callingfn[i]);
1086
        PRINT_SIZE_CHECK(ret, out, strsize);
1087
    }
1088

1089
    ret = snprintf(callstr + savstrsize - strsize, strsize, ")");
1090
    PRINT_SIZE_CHECK(ret, out, strsize);
1091
out:
1092
    FREE(callingfn);
1093
    return ret;
1094
}
1095

1096
int
1097
_gf_msg_nomem(const char *domain, const char *file, const char *function,
1098
              int line, gf_loglevel_t level, size_t size)
1099
{
1100
    const char *basename = NULL;
1101
    xlator_t *this = NULL;
1102
    struct timeval tv = {
1103
        0,
1104
    };
1105
    int ret = 0;
1106
    int fd = -1;
1107
    char msg[2048] = {
1108
        0,
1109
    };
1110
    char timestr[GF_TIMESTR_SIZE] = {
1111
        0,
1112
    };
1113
    glusterfs_ctx_t *ctx = NULL;
1114
    int wlen = 0;
1115
    int priority;
1116
    struct rusage r_usage;
1117

1118
    this = THIS;
1119
    ctx = this->ctx;
1120

1121
    if (!ctx)
1122
        goto out;
1123

1124
    if (skip_logging(this, level))
1125
        goto out;
1126

1127
    if (!domain || !file || !function) {
1128
        fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__,
1129
                __PRETTY_FUNCTION__, __LINE__);
1130
        return -1;
1131
    }
1132

1133
    GET_FILE_NAME_TO_LOG(file, basename);
1134

1135
    ret = gettimeofday(&tv, NULL);
1136
    if (-1 == ret)
1137
        goto out;
1138
    gf_time_fmt_tv_FT(timestr, sizeof timestr, &tv, &ctx->log);
1139

1140
    /* TODO: Currently we print in the enhanced format, with a message ID
1141
     * of 0. Need to enhance this to support format as configured */
1142
    wlen = snprintf(
1143
        msg, sizeof msg,
1144
        "[%s] %c [MSGID: %" PRIu64
1145
        "]"
1146
        " [%s:%d:%s] %s: no memory "
1147
        "available for size (%" GF_PRI_SIZET
1148
        ") current memory usage in kilobytes %ld"
1149
        " [call stack follows]\n",
1150
        timestr, gf_level_strings[level], (uint64_t)0, basename, line, function,
1151
        domain, size,
1152
        (!getrusage(RUSAGE_SELF, &r_usage) ? r_usage.ru_maxrss : 0));
1153
    if (-1 == wlen) {
1154
        ret = -1;
1155
        goto out;
1156
    }
1157

1158
    /* log to the configured logging service */
1159
    switch (ctx->log.logger) {
1160
        case gf_logger_syslog:
1161
            if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) {
1162
                SET_LOG_PRIO(level, priority);
1163

1164
                /* if syslog allocates, then this may fail, but we
1165
                 * cannot do much about it at the moment */
1166
                /* There is no fd for syslog, hence no stack printed */
1167
                syslog(priority, "%s", msg);
1168
                break;
1169
            }
1170
            /* NOTE: If syslog control file is absent, which is another
1171
             * way to control logging to syslog, then we will fall through
1172
             * to the gluster log. The ideal way to do things would be to
1173
             * not have the extra control file check */
1174
        case gf_logger_glusterlog:
1175
            pthread_mutex_lock(&ctx->log.logfile_mutex);
1176
            {
1177
                fd = ctx->log.logfile ? fileno(ctx->log.logfile)
1178
                                      : fileno(stderr);
1179
                if (fd == -1) {
1180
                    pthread_mutex_unlock(&ctx->log.logfile_mutex);
1181
                    goto out;
1182
                }
1183

1184
                /* write directly to the fd to prevent out of order
1185
                 * message and stack */
1186
                ret = sys_write(fd, msg, wlen);
1187
                if (ret == -1) {
1188
                    pthread_mutex_unlock(&ctx->log.logfile_mutex);
1189
                    goto out;
1190
                }
1191
#ifdef GF_LINUX_HOST_OS
1192
                /* We want only serious log in 'syslog', not our debug
1193
                 * and trace logs */
1194
                if (ctx->log.gf_log_syslog && level &&
1195
                    (level <= ctx->log.sys_log_level))
1196
                    syslog((level - 1), "%s\n", msg);
1197
#endif
1198
            }
1199
            pthread_mutex_unlock(&ctx->log.logfile_mutex);
1200

1201
            _gf_msg_backtrace_nomem(level, GF_LOG_BACKTRACE_DEPTH);
1202

1203
            break;
1204
    }
1205

1206
out:
1207
    return ret;
1208
}
1209

1210
static int
1211
gf_log_syslog(const char *domain, const char *file, const char *function,
1212
              int32_t line, gf_loglevel_t level, int errnum, uint64_t msgid,
1213
              char *appmsgstr, char *callstr, int graph_id, gf_log_format_t fmt)
1214
{
1215
    int priority;
1216

1217
    SET_LOG_PRIO(level, priority);
1218

1219
    /* log with appropriate format */
1220
    switch (fmt) {
1221
        case gf_logformat_traditional:
1222
            if (!callstr) {
1223
                if (errnum)
1224
                    syslog(priority, "[%s:%d:%s] %d-%s: %s [%s]", file, line,
1225
                           function, graph_id, domain, appmsgstr,
1226
                           strerror(errnum));
1227
                else
1228
                    syslog(priority, "[%s:%d:%s] %d-%s: %s", file, line,
1229
                           function, graph_id, domain, appmsgstr);
1230
            } else {
1231
                if (errnum)
1232
                    syslog(priority,
1233
                           "[%s:%d:%s] %s %d-%s:"
1234
                           " %s [%s]",
1235
                           file, line, function, callstr, graph_id, domain,
1236
                           appmsgstr, strerror(errnum));
1237
                else
1238
                    syslog(priority, "[%s:%d:%s] %s %d-%s: %s", file, line,
1239
                           function, callstr, graph_id, domain, appmsgstr);
1240
            }
1241
            break;
1242
        case gf_logformat_withmsgid:
1243
            if (!callstr) {
1244
                if (errnum)
1245
                    syslog(priority,
1246
                           "[MSGID: %" PRIu64
1247
                           "]"
1248
                           " [%s:%d:%s] %d-%s: %s [%s]",
1249
                           msgid, file, line, function, graph_id, domain,
1250
                           appmsgstr, strerror(errnum));
1251
                else
1252
                    syslog(priority,
1253
                           "[MSGID: %" PRIu64
1254
                           "]"
1255
                           " [%s:%d:%s] %d-%s: %s",
1256
                           msgid, file, line, function, graph_id, domain,
1257
                           appmsgstr);
1258
            } else {
1259
                if (errnum)
1260
                    syslog(priority,
1261
                           "[MSGID: %" PRIu64
1262
                           "]"
1263
                           " [%s:%d:%s] %s %d-%s: %s [%s]",
1264
                           msgid, file, line, function, callstr, graph_id,
1265
                           domain, appmsgstr, strerror(errnum));
1266
                else
1267
                    syslog(priority,
1268
                           "[MSGID: %" PRIu64
1269
                           "]"
1270
                           " [%s:%d:%s] %s %d-%s: %s",
1271
                           msgid, file, line, function, callstr, graph_id,
1272
                           domain, appmsgstr);
1273
            }
1274
            break;
1275
        case gf_logformat_cee:
1276
            /* TODO: Enhance CEE with additional parameters */
1277
            gf_syslog(priority, "[%s:%d:%s] %d-%s: %s", file, line, function,
1278
                      graph_id, domain, appmsgstr);
1279
            break;
1280

1281
        default:
1282
            /* NOTE: should not get here without logging */
1283
            break;
1284
    }
1285

1286
    /* TODO: There can be no errors from gf_syslog? */
1287
    return 0;
1288
}
1289

1290
static int
1291
gf_log_glusterlog(gf_log_handle_t *log, const char *domain, const char *file,
1292
                  const char *function, int32_t line, gf_loglevel_t level,
1293
                  int errnum, uint64_t msgid, char *appmsgstr, char *callstr,
1294
                  struct timeval tv, int graph_id, gf_log_format_t fmt)
1295
{
1296
    char timestr[GF_TIMESTR_SIZE] = {
1297
        0,
1298
    };
1299
    char *header = NULL;
1300
    char *footer = NULL;
1301
    int ret = 0;
1302

1303
    /* rotate if required */
1304
    gf_log_rotate(log);
1305

1306
    /* format the time stamp */
1307
    gf_time_fmt_tv_FT(timestr, sizeof timestr, &tv, log);
1308

1309
    /* generate footer */
1310
    if (errnum) {
1311
        ret = gf_asprintf(&footer, " [%s]\n", strerror(errnum));
1312
    } else {
1313
        ret = gf_asprintf(&footer, " \n");
1314
    }
1315
    if (-1 == ret) {
1316
        goto err;
1317
    }
1318

1319
    /* generate message, inc. the header */
1320
    if (fmt == gf_logformat_traditional) {
1321
        if (!callstr) {
1322
            ret = gf_asprintf(&header,
1323
                              "[%s] %c [%s:%d:%s]"
1324
                              " %d-%s: %s",
1325
                              timestr, gf_level_strings[level], file, line,
1326
                              function, graph_id, domain, appmsgstr);
1327
        } else {
1328
            ret = gf_asprintf(&header,
1329
                              "[%s] %c [%s:%d:%s] %s"
1330
                              " %d-%s: %s",
1331
                              timestr, gf_level_strings[level], file, line,
1332
                              function, callstr, graph_id, domain, appmsgstr);
1333
        }
1334
    } else { /* gf_logformat_withmsgid */
1335
        /* CEE log format unsupported in logger_glusterlog, so just
1336
         * print enhanced log format */
1337
        if (!callstr) {
1338
            ret = gf_asprintf(&header,
1339
                              "[%s] %c [MSGID: %" PRIu64
1340
                              "]"
1341
                              " [%s:%d:%s] %d-%s: %s",
1342
                              timestr, gf_level_strings[level], msgid, file,
1343
                              line, function, graph_id, domain, appmsgstr);
1344
        } else {
1345
            ret = gf_asprintf(&header,
1346
                              "[%s] %c [MSGID: %" PRIu64
1347
                              "]"
1348
                              " [%s:%d:%s] %s %d-%s: %s",
1349
                              timestr, gf_level_strings[level], msgid, file,
1350
                              line, function, callstr, graph_id, domain,
1351
                              appmsgstr);
1352
        }
1353
    }
1354
    if (-1 == ret) {
1355
        goto err;
1356
    }
1357

1358
    /* send the full message to log */
1359

1360
    pthread_mutex_lock(&log->logfile_mutex);
1361
    {
1362
        if (log->logfile) {
1363
            fprintf(log->logfile, "%s%s", header, footer);
1364
            fflush(log->logfile);
1365
        } else if (log->loglevel >= level) {
1366
            fprintf(stderr, "%s%s", header, footer);
1367
            fflush(stderr);
1368
        }
1369

1370
#ifdef GF_LINUX_HOST_OS
1371
        /* We want only serious logs in 'syslog', not our debug
1372
         * and trace logs */
1373
        if (log->gf_log_syslog && level && (level <= log->sys_log_level)) {
1374
            syslog((level - 1), "%s%s", header, footer);
1375
        }
1376
#endif
1377
    }
1378

1379
    /* TODO: Plugin in memory log buffer retention here. For logs not
1380
     * flushed during cores, it would be useful to retain some of the last
1381
     * few messages in memory */
1382
    pthread_mutex_unlock(&log->logfile_mutex);
1383
    ret = 0;
1384

1385
err:
1386
    GF_FREE(header);
1387
    GF_FREE(footer);
1388

1389
    return ret;
1390
}
1391

1392
static int
1393
gf_syslog_log_repetitions(log_buf_t *buf, gf_log_handle_t *log)
1394
{
1395
    int priority;
1396
    char timestr_latest[GF_TIMESTR_SIZE] = {
1397
        0,
1398
    };
1399
    char timestr_oldest[GF_TIMESTR_SIZE] = {
1400
        0,
1401
    };
1402

1403
    SET_LOG_PRIO(buf->level, priority);
1404

1405
    gf_time_fmt_tv_FT(timestr_latest, sizeof timestr_latest, &buf->latest, log);
1406
    gf_time_fmt_tv_FT(timestr_oldest, sizeof timestr_oldest, &buf->oldest, log);
1407

1408
    if (buf->errnum) {
1409
        syslog(priority,
1410
               "The message \"[MSGID: %" PRIu64
1411
               "] [%s:%d:%s] "
1412
               "%d-%s: %s [%s] \" repeated %d times between %s"
1413
               " and %s",
1414
               buf->msg_id, buf->file, buf->line, buf->function, buf->graph_id,
1415
               buf->domain, buf->msg, strerror(buf->errnum), buf->refcount,
1416
               timestr_oldest, timestr_latest);
1417
    } else {
1418
        syslog(priority,
1419
               "The message \"[MSGID: %" PRIu64
1420
               "] [%s:%d:%s] "
1421
               "%d-%s: %s \" repeated %d times between %s"
1422
               " and %s",
1423
               buf->msg_id, buf->file, buf->line, buf->function, buf->graph_id,
1424
               buf->domain, buf->msg, buf->refcount, timestr_oldest,
1425
               timestr_latest);
1426
    }
1427
    return 0;
1428
}
1429

1430
static int
1431
gf_glusterlog_log_repetitions(log_buf_t *buf, gf_log_handle_t *log)
1432
{
1433
    int ret = 0;
1434
    char timestr_latest[GF_TIMESTR_SIZE] = {
1435
        0,
1436
    };
1437
    char timestr_oldest[GF_TIMESTR_SIZE] = {
1438
        0,
1439
    };
1440
    char errstr[256] = {
1441
        0,
1442
    };
1443
    char *header = NULL;
1444
    char *footer = NULL;
1445

1446
    gf_log_rotate(log);
1447

1448
    ret = gf_asprintf(&header,
1449
                      "The message \"%c [MSGID: %" PRIu64
1450
                      "]"
1451
                      " [%s:%d:%s] %d-%s: %s",
1452
                      gf_level_strings[buf->level], buf->msg_id, buf->file,
1453
                      buf->line, buf->function, buf->graph_id, buf->domain,
1454
                      buf->msg);
1455
    if (-1 == ret) {
1456
        goto err;
1457
    }
1458

1459
    gf_time_fmt_tv_FT(timestr_latest, sizeof timestr_latest, &buf->latest, log);
1460

1461
    gf_time_fmt_tv_FT(timestr_oldest, sizeof timestr_oldest, &buf->oldest, log);
1462

1463
    if (buf->errnum)
1464
        snprintf(errstr, sizeof(errstr) - 1, " [%s]", strerror(buf->errnum));
1465

1466
    ret = gf_asprintf(&footer, "%s\" repeated %d times between [%s] and [%s]",
1467
                      errstr, buf->refcount, timestr_oldest, timestr_latest);
1468
    if (-1 == ret) {
1469
        ret = -1;
1470
        goto err;
1471
    }
1472

1473
    pthread_mutex_lock(&log->logfile_mutex);
1474
    {
1475
        if (log->logfile) {
1476
            fprintf(log->logfile, "%s%s\n", header, footer);
1477
            fflush(log->logfile);
1478
        } else if (log->loglevel >= buf->level) {
1479
            fprintf(stderr, "%s%s\n", header, footer);
1480
            fflush(stderr);
1481
        }
1482

1483
#ifdef GF_LINUX_HOST_OS
1484
        /* We want only serious logs in 'syslog', not our debug
1485
         * and trace logs */
1486
        if (log->gf_log_syslog && buf->level &&
1487
            (buf->level <= log->sys_log_level))
1488
            syslog((buf->level - 1), "%s%s\n", header, footer);
1489
#endif
1490
    }
1491

1492
    /* TODO: Plugin in memory log buffer retention here. For logs not
1493
     * flushed during cores, it would be useful to retain some of the last
1494
     * few messages in memory */
1495
    pthread_mutex_unlock(&log->logfile_mutex);
1496
    ret = 0;
1497

1498
err:
1499
    GF_FREE(header);
1500
    GF_FREE(footer);
1501

1502
    return ret;
1503
}
1504

1505
static int
1506
gf_log_print_with_repetitions(log_buf_t *buf, gf_log_handle_t *log)
1507
{
1508
    int ret = -1;
1509
    gf_log_logger_t logger = log->logger;
1510

1511
    switch (logger) {
1512
        case gf_logger_syslog:
1513
            if (log->log_control_file_found && log->gf_log_syslog) {
1514
                ret = gf_syslog_log_repetitions(buf, log);
1515
                break;
1516
            }
1517
            /* NOTE: If syslog control file is absent, which is another
1518
             * way to control logging to syslog, then we will fall through
1519
             * to the gluster log. The ideal way to do things would be to
1520
             * not have the extra control file check */
1521

1522
        case gf_logger_glusterlog:
1523
            ret = gf_glusterlog_log_repetitions(buf, log);
1524
            break;
1525
    }
1526

1527
    return ret;
1528
}
1529

1530
static int
1531
gf_log_print_plain_fmt(gf_log_handle_t *log, const char *domain,
1532
                       const char *file, const char *function, int32_t line,
1533
                       gf_loglevel_t level, int errnum, uint64_t msgid,
1534
                       char *appmsgstr, char *callstr, struct timeval tv,
1535
                       int graph_id, gf_log_format_t fmt)
1536
{
1537
    int ret = -1;
1538
    gf_log_logger_t logger = 0;
1539

1540
    logger = log->logger;
1541

1542
    /* log to the configured logging service */
1543
    switch (logger) {
1544
        case gf_logger_syslog:
1545
            if (log->log_control_file_found && log->gf_log_syslog) {
1546
                ret = gf_log_syslog(domain, file, function, line, level, errnum,
1547
                                    msgid, appmsgstr, callstr, graph_id, fmt);
1548
                break;
1549
            }
1550
            /* NOTE: If syslog control file is absent, which is another
1551
             * way to control logging to syslog, then we will fall through
1552
             * to the gluster log. The ideal way to do things would be to
1553
             * not have the extra control file check */
1554
        case gf_logger_glusterlog:
1555
            ret = gf_log_glusterlog(log, domain, file, function, line, level,
1556
                                    errnum, msgid, appmsgstr, callstr, tv,
1557
                                    graph_id, fmt);
1558
            break;
1559
    }
1560

1561
    return ret;
1562
}
1563

1564
static void
1565
gf_log_flush_message(log_buf_t *buf, gf_log_handle_t *log)
1566
{
1567
    if (buf->refcount == 1) {
1568
        (void)gf_log_print_plain_fmt(log, buf->domain, buf->file, buf->function,
1569
                                     buf->line, buf->level, buf->errnum,
1570
                                     buf->msg_id, buf->msg, NULL, buf->latest,
1571
                                     buf->graph_id, gf_logformat_withmsgid);
1572
    }
1573

1574
    if (buf->refcount > 1) {
1575
        gf_log_print_with_repetitions(buf, log);
1576
    }
1577
    return;
1578
}
1579

1580
static void
1581
gf_log_flush_list(struct list_head *copy, gf_log_handle_t *log)
1582
{
1583
    log_buf_t *iter = NULL;
1584
    log_buf_t *tmp = NULL;
1585

1586
    list_for_each_entry_safe(iter, tmp, copy, msg_list)
1587
    {
1588
        gf_log_flush_message(iter, log);
1589
        list_del_init(&iter->msg_list);
1590
        log_buf_destroy(iter);
1591
    }
1592
}
1593

1594
static void
1595
gf_log_flush_msgs(gf_log_handle_t *log)
1596
{
1597
    struct list_head copy;
1598

1599
    INIT_LIST_HEAD(&copy);
1600

1601
    pthread_mutex_lock(&log->log_buf_lock);
1602
    {
1603
        list_splice_init(&log->lru_queue, &copy);
1604
        log->lru_cur_size = 0;
1605
    }
1606
    pthread_mutex_unlock(&log->log_buf_lock);
1607

1608
    gf_log_flush_list(&copy, log);
1609

1610
    return;
1611
}
1612

1613
static void
1614
gf_log_flush_extra_msgs(gf_log_handle_t *log, uint32_t new)
1615
{
1616
    int count = 0;
1617
    int i = 0;
1618
    log_buf_t *iter = NULL;
1619
    log_buf_t *tmp = NULL;
1620
    struct list_head copy;
1621

1622
    INIT_LIST_HEAD(&copy);
1623

1624
    /* If the number of outstanding log messages does not cause list
1625
     * overflow even after reducing the size of the list, then do nothing.
1626
     * Otherwise (that is if there are more items in the list than there
1627
     * need to be after reducing its size), move the least recently used
1628
     * 'diff' elements to be flushed into a separate list...
1629
     */
1630

1631
    pthread_mutex_lock(&log->log_buf_lock);
1632
    {
1633
        if (log->lru_cur_size <= new)
1634
            goto unlock;
1635
        count = log->lru_cur_size - new;
1636
        list_for_each_entry_safe(iter, tmp, &log->lru_queue, msg_list)
1637
        {
1638
            if (i == count)
1639
                break;
1640

1641
            list_del_init(&iter->msg_list);
1642
            list_add_tail(&iter->msg_list, &copy);
1643
            i++;
1644
        }
1645
        log->lru_cur_size = log->lru_cur_size - count;
1646
    }
1647
    // ... quickly unlock ...
1648
unlock:
1649
    pthread_mutex_unlock(&log->log_buf_lock);
1650
    if (list_empty(&copy))
1651
        return;
1652

1653
    TEST_LOG(
1654
        "Log buffer size reduced. About to flush %d extra log "
1655
        "messages",
1656
        count);
1657
    // ... and then flush them outside the lock.
1658
    gf_log_flush_list(&copy, log);
1659
    TEST_LOG("Just flushed %d extra log messages", count);
1660

1661
    return;
1662
}
1663

1664
static int
1665
__gf_log_inject_timer_event(glusterfs_ctx_t *ctx)
1666
{
1667
    int ret = -1;
1668
    struct timespec timeout = {
1669
        0,
1670
    };
1671

1672
    if (ctx->log.log_flush_timer) {
1673
        gf_timer_call_cancel(ctx, ctx->log.log_flush_timer);
1674
        ctx->log.log_flush_timer = NULL;
1675
    }
1676

1677
    timeout.tv_sec = ctx->log.timeout;
1678
    timeout.tv_nsec = 0;
1679

1680
    TEST_LOG("Starting timer now. Timeout = %u, current buf size = %d",
1681
             ctx->log.timeout, ctx->log.lru_size);
1682
    ctx->log.log_flush_timer = gf_timer_call_after(
1683
        ctx, timeout, gf_log_flush_timeout_cbk, (void *)ctx);
1684
    if (!ctx->log.log_flush_timer)
1685
        goto out;
1686

1687
    ret = 0;
1688

1689
out:
1690
    return ret;
1691
}
1692

1693
int
1694
gf_log_inject_timer_event(glusterfs_ctx_t *ctx)
1695
{
1696
    int ret = -1;
1697

1698
    if (!ctx)
1699
        return -1;
1700

1701
    pthread_mutex_lock(&ctx->log.log_buf_lock);
1702
    {
1703
        ret = __gf_log_inject_timer_event(ctx);
1704
    }
1705
    pthread_mutex_unlock(&ctx->log.log_buf_lock);
1706

1707
    return ret;
1708
}
1709

1710
static void
1711
gf_log_flush_timeout_cbk(void *data)
1712
{
1713
    glusterfs_ctx_t *ctx = NULL;
1714

1715
    ctx = (glusterfs_ctx_t *)data;
1716

1717
    TEST_LOG(
1718
        "Log timer timed out. About to flush outstanding messages if "
1719
        "present");
1720
    gf_log_flush_msgs(&ctx->log);
1721

1722
    (void)gf_log_inject_timer_event(ctx);
1723

1724
    return;
1725
}
1726

1727
static int
1728
_gf_msg_internal(glusterfs_ctx_t *ctx, const char *domain, const char *file,
1729
                 const char *function, int32_t line, gf_loglevel_t level,
1730
                 int errnum, uint64_t msgid, char *appmsgstr, char *callstr,
1731
                 int graph_id)
1732
{
1733
    int ret = -1;
1734
    uint32_t size = 0;
1735
    const char *basename = NULL;
1736
    log_buf_t *iter = NULL;
1737
    log_buf_t *buf_tmp = NULL;
1738
    log_buf_t *buf_new = NULL;
1739
    log_buf_t *first = NULL;
1740
    struct timeval tv = {
1741
        0,
1742
    };
1743
    gf_boolean_t flush_lru = _gf_false;
1744
    gf_boolean_t flush_logged_msg = _gf_false;
1745

1746
    GET_FILE_NAME_TO_LOG(file, basename);
1747

1748
    ret = gettimeofday(&tv, NULL);
1749
    if (ret)
1750
        goto out;
1751

1752
    /* If this function is called via _gf_msg_callingfn () (indicated by a
1753
     * non-NULL callstr), or if the logformat is traditional, flush the
1754
     * message directly to disk.
1755
     */
1756

1757
    if ((callstr) || (ctx->log.logformat == gf_logformat_traditional)) {
1758
        ret = gf_log_print_plain_fmt(
1759
            &ctx->log, domain, basename, function, line, level, errnum, msgid,
1760
            appmsgstr, callstr, tv, graph_id, gf_logformat_traditional);
1761
        goto out;
1762
    }
1763

1764
    pthread_mutex_lock(&ctx->log.log_buf_lock);
1765
    {
1766
        /* Check if the msg being logged is already part of the list */
1767
        list_for_each_entry_safe_reverse(iter, buf_tmp, &ctx->log.lru_queue,
1768
                                         msg_list)
1769
        {
1770
            if (first == NULL)
1771
                // Remember the first (lru) element in first ptr
1772
                first = iter;
1773

1774
            /* Try to fail the search early on by doing the less
1775
             * expensive integer comparisons and continue to string
1776
             * parameter comparisons only after all int parameters
1777
             * are found to be matching.
1778
             */
1779
            if (line != iter->line)
1780
                continue;
1781

1782
            if (errnum != iter->errnum)
1783
                continue;
1784

1785
            if (msgid != iter->msg_id)
1786
                continue;
1787

1788
            if (level != iter->level)
1789
                continue;
1790

1791
            if (graph_id != iter->graph_id)
1792
                continue;
1793

1794
            if (strcmp(domain, iter->domain))
1795
                continue;
1796

1797
            if (strcmp(basename, iter->file))
1798
                continue;
1799

1800
            if (strcmp(function, iter->function))
1801
                continue;
1802

1803
            if (strcmp(appmsgstr, iter->msg))
1804
                continue;
1805

1806
            // Ah! Found a match!
1807
            list_move_tail(&iter->msg_list, &ctx->log.lru_queue);
1808
            iter->refcount++;
1809
            // Update the 'latest' timestamp.
1810
            memcpy((void *)&(iter->latest), (void *)&tv,
1811
                   sizeof(struct timeval));
1812
            pthread_mutex_unlock(&ctx->log.log_buf_lock);
1813
            ret = 0;
1814
            goto out;
1815
        }
1816
        // did not find a match ...
1817

1818
        size = ctx->log.lru_size;
1819
        /* If the upper limit on the log buf size is 0, flush the msg to
1820
         * disk directly after unlock. There's no need to buffer the
1821
         * msg here.
1822
         */
1823
        if (size == 0) {
1824
            flush_logged_msg = _gf_true;
1825
            goto unlock;
1826
        } else if (((ctx->log.lru_cur_size + 1) > size) && (first)) {
1827
            /* If the list is full, flush the lru msg to disk and also
1828
             * release it after unlock, and ...
1829
             * */
1830
            if (first->refcount >= 1)
1831
                TEST_LOG(
1832
                    "Buffer overflow of a buffer whose size limit "
1833
                    "is %d. About to flush least recently used log"
1834
                    " message to disk",
1835
                    size);
1836
            list_del_init(&first->msg_list);
1837
            ctx->log.lru_cur_size--;
1838
            flush_lru = _gf_true;
1839
        }
1840
        /* create a new list element, initialise and enqueue it.
1841
         * Additionally, this being the first occurrence of the msg,
1842
         * log it directly to disk after unlock. */
1843
        buf_new = mem_get0(ctx->logbuf_pool);
1844
        if (!buf_new) {
1845
            ret = -1;
1846
            goto unlock;
1847
        }
1848
        ret = log_buf_init(buf_new, domain, basename, function, line, level,
1849
                           errnum, msgid, appmsgstr, graph_id);
1850
        if (ret) {
1851
            log_buf_destroy(buf_new);
1852
            goto unlock;
1853
        }
1854

1855
        memcpy((void *)&(buf_new->latest), (void *)&tv, sizeof(struct timeval));
1856
        memcpy((void *)&(buf_new->oldest), (void *)&tv, sizeof(struct timeval));
1857

1858
        list_add_tail(&buf_new->msg_list, &ctx->log.lru_queue);
1859
        ctx->log.lru_cur_size++;
1860
        flush_logged_msg = _gf_true;
1861
        ret = 0;
1862
    }
1863
unlock:
1864
    pthread_mutex_unlock(&ctx->log.log_buf_lock);
1865

1866
    /* Value of @ret is a don't-care below since irrespective of success or
1867
     * failure post setting of @flush_lru, @first must be flushed and freed.
1868
     */
1869
    if (flush_lru) {
1870
        gf_log_flush_message(first, &ctx->log);
1871
        log_buf_destroy(first);
1872
    }
1873
    /* Similarly, irrespective of whether all operations since setting of
1874
     * @flush_logged_msg were successful or not, flush the message being
1875
     * logged to disk in the plain format.
1876
     */
1877
    if (flush_logged_msg) {
1878
        ret = gf_log_print_plain_fmt(
1879
            &ctx->log, domain, basename, function, line, level, errnum, msgid,
1880
            appmsgstr, callstr, tv, graph_id, gf_logformat_withmsgid);
1881
    }
1882

1883
out:
1884
    return ret;
1885
}
1886

1887
int
1888
_gf_msg(const char *domain, const char *file, const char *function,
1889
        int32_t line, gf_loglevel_t level, int errnum, int trace,
1890
        uint64_t msgid, const char *fmt, ...)
1891
{
1892
    int ret = 0;
1893
    char *msgstr = NULL;
1894
    va_list ap;
1895
    xlator_t *this = THIS;
1896
    glusterfs_ctx_t *ctx = NULL;
1897
    char *callstr = NULL;
1898
    int log_inited = 0;
1899

1900
    if (this == NULL)
1901
        return -1;
1902

1903
    ctx = this->ctx;
1904
    if (ctx == NULL) {
1905
        /* messages before context initialization are ignored */
1906
        return -1;
1907
    }
1908

1909
    /* check if we should be logging */
1910
    if (skip_logging(this, level))
1911
        goto out;
1912

1913
    /* in args check */
1914
    if (!domain || !file || !function || !fmt) {
1915
        fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__,
1916
                __PRETTY_FUNCTION__, __LINE__);
1917
        return -1;
1918
    }
1919

1920
    /* form the message */
1921
    va_start(ap, fmt);
1922
    ret = vasprintf(&msgstr, fmt, ap);
1923
    va_end(ap);
1924

1925
    /* log */
1926
    if (ret != -1) {
1927
        if (trace) {
1928
            callstr = GF_MALLOC(GF_LOG_BACKTRACE_SIZE, gf_common_mt_char);
1929
            if (callstr == NULL)
1930
                return -1;
1931

1932
            ret = _gf_msg_backtrace(GF_LOG_BACKTRACE_DEPTH, callstr,
1933
                                    GF_LOG_BACKTRACE_SIZE);
1934
            if (ret < 0) {
1935
                GF_FREE(callstr);
1936
                callstr = NULL;
1937
            }
1938
        }
1939

1940
        pthread_mutex_lock(&ctx->log.logfile_mutex);
1941
        {
1942
            if (ctx->log.logfile) {
1943
                log_inited = 1;
1944
            }
1945
        }
1946
        pthread_mutex_unlock(&ctx->log.logfile_mutex);
1947

1948
        if (!log_inited && ctx->log.gf_log_syslog) {
1949
            ret = gf_log_syslog(domain, file, function, line, level, errnum,
1950
                                msgid, msgstr, (callstr ? callstr : NULL),
1951
                                (this->graph) ? this->graph->id : 0,
1952
                                gf_logformat_traditional);
1953
        } else {
1954
            ret = _gf_msg_internal(ctx, domain, file, function, line, level,
1955
                                   errnum, msgid, msgstr,
1956
                                   (callstr ? callstr : NULL),
1957
                                   (this->graph) ? this->graph->id : 0);
1958
        }
1959
    } else {
1960
        /* man (3) vasprintf states on error strp contents
1961
         * are undefined, be safe */
1962
        msgstr = NULL;
1963
    }
1964
    if (callstr)
1965
        GF_FREE(callstr);
1966
    FREE(msgstr);
1967

1968
out:
1969
    return ret;
1970
}
1971

1972
/* TODO: Deprecate (delete) _gf_log, _gf_log_callingfn,
1973
 * once messages are changed to use _gf_msgXXX APIs for logging */
1974
int
1975
_gf_log(const char *domain, const char *file, const char *function, int line,
1976
        gf_loglevel_t level, const char *fmt, ...)
1977
{
1978
    const char *basename = NULL;
1979
    FILE *new_logfile = NULL;
1980
    va_list ap;
1981
    char timestr[GF_TIMESTR_SIZE] = {
1982
        0,
1983
    };
1984
    struct timeval tv = {
1985
        0,
1986
    };
1987
    char *logline = NULL;
1988
    char *msg = NULL;
1989
    int ret = 0;
1990
    int fd = -1;
1991
    xlator_t *this = THIS;
1992
    glusterfs_ctx_t *ctx = this->ctx;
1993

1994
    if (!ctx)
1995
        goto out;
1996

1997
    if (skip_logging(this, level))
1998
        goto out;
1999

2000
    if (!domain || !file || !function || !fmt) {
2001
        fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__,
2002
                __PRETTY_FUNCTION__, __LINE__);
2003
        return -1;
2004
    }
2005

2006
    basename = strrchr(file, '/');
2007
    if (basename)
2008
        basename++;
2009
    else
2010
        basename = file;
2011

2012
    va_start(ap, fmt);
2013
    ret = vasprintf(&msg, fmt, ap);
2014
    va_end(ap);
2015
    if (-1 == ret) {
2016
        goto err;
2017
    }
2018

2019
    if (ctx->log.log_control_file_found) {
2020
        int priority;
2021
        /* treat GF_LOG_TRACE and GF_LOG_NONE as LOG_DEBUG and
2022
           other level as is */
2023
        if (GF_LOG_TRACE == level || GF_LOG_NONE == level) {
2024
            priority = LOG_DEBUG;
2025
        } else {
2026
            priority = level - 1;
2027
        }
2028

2029
        gf_syslog(priority, "[%s:%d:%s] %d-%s: %s", basename, line, function,
2030
                  ((this->graph) ? this->graph->id : 0), domain, msg);
2031
        goto err;
2032
    }
2033

2034
    if (ctx->log.logrotate) {
2035
        ctx->log.logrotate = 0;
2036

2037
        fd = sys_open(ctx->log.filename, O_CREAT | O_RDONLY, S_IRUSR | S_IWUSR);
2038
        if (fd < 0) {
2039
            gf_smsg("logrotate", GF_LOG_ERROR, errno,
2040
                    LG_MSG_OPEN_LOGFILE_FAILED, NULL);
2041
            return -1;
2042
        }
2043
        sys_close(fd);
2044

2045
        new_logfile = fopen(ctx->log.filename, "a");
2046
        if (!new_logfile) {
2047
            gf_smsg("logrotate", GF_LOG_CRITICAL, errno,
2048
                    LG_MSG_OPEN_LOGFILE_FAILED, "filename=%s",
2049
                    ctx->log.filename, NULL);
2050
            goto log;
2051
        }
2052

2053
        pthread_mutex_lock(&ctx->log.logfile_mutex);
2054
        {
2055
            if (ctx->log.logfile)
2056
                fclose(ctx->log.logfile);
2057

2058
            ctx->log.gf_log_logfile = ctx->log.logfile = new_logfile;
2059
        }
2060
        pthread_mutex_unlock(&ctx->log.logfile_mutex);
2061
    }
2062

2063
log:
2064
    ret = gettimeofday(&tv, NULL);
2065
    if (-1 == ret)
2066
        goto out;
2067

2068
    gf_time_fmt_tv_FT(timestr, sizeof timestr, &tv, &ctx->log);
2069

2070
    ret = gf_asprintf(&logline, "[%s] %c [%s:%d:%s] %d-%s: %s\n", timestr,
2071
                      gf_level_strings[level], basename, line, function,
2072
                      ((this->graph) ? this->graph->id : 0), domain, msg);
2073
    if (-1 == ret) {
2074
        goto err;
2075
    }
2076

2077
    pthread_mutex_lock(&ctx->log.logfile_mutex);
2078
    {
2079
        if (ctx->log.logfile) {
2080
            fputs(logline, ctx->log.logfile);
2081
            fflush(ctx->log.logfile);
2082
        } else if (ctx->log.loglevel >= level) {
2083
            fputs(logline, stderr);
2084
            fflush(stderr);
2085
        }
2086

2087
#ifdef GF_LINUX_HOST_OS
2088
        /* We want only serious log in 'syslog', not our debug
2089
           and trace logs */
2090
        if (ctx->log.gf_log_syslog && level &&
2091
            (level <= ctx->log.sys_log_level))
2092
            syslog((level - 1), "%s", logline);
2093
#endif
2094
    }
2095

2096
    pthread_mutex_unlock(&ctx->log.logfile_mutex);
2097

2098
err:
2099
    GF_FREE(logline);
2100

2101
    FREE(msg);
2102

2103
out:
2104
    return (0);
2105
}
2106

2107
int
2108
_gf_log_eh(const char *function, const char *fmt, ...)
2109
{
2110
    int ret = -1;
2111
    va_list ap;
2112
    char *logline = NULL;
2113
    char *msg = NULL;
2114
    xlator_t *this = NULL;
2115

2116
    this = THIS;
2117

2118
    va_start(ap, fmt);
2119
    ret = vasprintf(&msg, fmt, ap);
2120
    va_end(ap);
2121
    if (-1 == ret) {
2122
        goto out;
2123
    }
2124

2125
    ret = gf_asprintf(&logline, "[%d] %s: %s",
2126
                      ((this->graph) ? this->graph->id : 0), function, msg);
2127
    if (-1 == ret) {
2128
        goto out;
2129
    }
2130

2131
    ret = eh_save_history(this->history, logline);
2132

2133
out:
2134
    GF_FREE(logline);
2135

2136
    FREE(msg);
2137

2138
    return ret;
2139
}
2140

2141
int
2142
gf_cmd_log_init(const char *filename)
2143
{
2144
    int fd = -1;
2145
    xlator_t *this = NULL;
2146
    glusterfs_ctx_t *ctx = NULL;
2147

2148
    this = THIS;
2149
    ctx = this->ctx;
2150

2151
    if (!ctx)
2152
        return -1;
2153

2154
    if (!filename) {
2155
        gf_smsg(this->name, GF_LOG_CRITICAL, 0, LG_MSG_FILENAME_NOT_SPECIFIED,
2156
                "gf_cmd_log_init", NULL);
2157
        return -1;
2158
    }
2159

2160
    ctx->log.cmd_log_filename = gf_strdup(filename);
2161
    if (!ctx->log.cmd_log_filename) {
2162
        return -1;
2163
    }
2164
    /* close and reopen cmdlogfile for log rotate*/
2165
    if (ctx->log.cmdlogfile) {
2166
        fclose(ctx->log.cmdlogfile);
2167
        ctx->log.cmdlogfile = NULL;
2168
    }
2169

2170
    fd = sys_open(ctx->log.cmd_log_filename, O_CREAT | O_WRONLY | O_APPEND,
2171
                  S_IRUSR | S_IWUSR);
2172
    if (fd < 0) {
2173
        gf_smsg(this->name, GF_LOG_CRITICAL, errno, LG_MSG_OPEN_LOGFILE_FAILED,
2174
                "cmd_log_file", NULL);
2175
        return -1;
2176
    }
2177

2178
    ctx->log.cmdlogfile = fdopen(fd, "a");
2179
    if (!ctx->log.cmdlogfile) {
2180
        gf_smsg(this->name, GF_LOG_CRITICAL, errno, LG_MSG_OPEN_LOGFILE_FAILED,
2181
                "gf_cmd_log_init: %s", ctx->log.cmd_log_filename, NULL);
2182
        sys_close(fd);
2183
        return -1;
2184
    }
2185
    return 0;
2186
}
2187

2188
int
2189
gf_cmd_log(const char *domain, const char *fmt, ...)
2190
{
2191
    va_list ap;
2192
    char timestr[GF_TIMESTR_SIZE];
2193
    struct timeval tv = {
2194
        0,
2195
    };
2196
    char *logline = NULL;
2197
    char *msg = NULL;
2198
    int ret = 0;
2199
    int fd = -1;
2200
    glusterfs_ctx_t *ctx = NULL;
2201

2202
    ctx = THIS->ctx;
2203

2204
    if (!ctx)
2205
        return -1;
2206

2207
    if (!ctx->log.cmdlogfile)
2208
        return -1;
2209

2210
    if (!domain || !fmt) {
2211
        gf_msg_trace("glusterd", 0, "logging: invalid argument\n");
2212
        return -1;
2213
    }
2214

2215
    ret = gettimeofday(&tv, NULL);
2216
    if (ret == -1)
2217
        goto out;
2218
    va_start(ap, fmt);
2219
    ret = vasprintf(&msg, fmt, ap);
2220
    va_end(ap);
2221
    if (ret == -1) {
2222
        goto out;
2223
    }
2224

2225
    gf_time_fmt_tv_FT(timestr, sizeof timestr, &tv, &ctx->log);
2226

2227
    ret = gf_asprintf(&logline, "[%s] %s : %s\n", timestr, domain, msg);
2228
    if (ret == -1) {
2229
        goto out;
2230
    }
2231

2232
    /* close and reopen cmdlogfile fd for in case of log rotate*/
2233
    if (ctx->log.cmd_history_logrotate) {
2234
        ctx->log.cmd_history_logrotate = 0;
2235

2236
        if (ctx->log.cmdlogfile) {
2237
            fclose(ctx->log.cmdlogfile);
2238
            ctx->log.cmdlogfile = NULL;
2239
        }
2240

2241
        fd = sys_open(ctx->log.cmd_log_filename, O_CREAT | O_WRONLY | O_APPEND,
2242
                      S_IRUSR | S_IWUSR);
2243
        if (fd < 0) {
2244
            gf_smsg(THIS->name, GF_LOG_CRITICAL, errno,
2245
                    LG_MSG_OPEN_LOGFILE_FAILED, "name=%s",
2246
                    ctx->log.cmd_log_filename, NULL);
2247
            ret = -1;
2248
            goto out;
2249
        }
2250

2251
        ctx->log.cmdlogfile = fdopen(fd, "a");
2252
        if (!ctx->log.cmdlogfile) {
2253
            gf_smsg(THIS->name, GF_LOG_CRITICAL, errno,
2254
                    LG_MSG_OPEN_LOGFILE_FAILED, "name=%s",
2255
                    ctx->log.cmd_log_filename, NULL);
2256
            ret = -1;
2257
            sys_close(fd);
2258
            goto out;
2259
        }
2260
    }
2261

2262
    fputs(logline, ctx->log.cmdlogfile);
2263
    fflush(ctx->log.cmdlogfile);
2264

2265
out:
2266
    GF_FREE(logline);
2267

2268
    FREE(msg);
2269

2270
    return ret;
2271
}
2272

2273
static int
2274
_do_slog_format(int errnum, const char *event, va_list inp, char **msg)
2275
{
2276
    va_list valist_tmp;
2277
    int i = 0;
2278
    int j = 0;
2279
    int k = 0;
2280
    int ret = 0;
2281
    char *fmt = NULL;
2282
    char *buffer = NULL;
2283
    int num_format_chars = 0;
2284
    char format_char = '%';
2285
    char *tmp1 = NULL;
2286
    char *tmp2 = NULL;
2287
    char temp_sep[3] = "";
2288

2289
    tmp2 = gf_strdup("");
2290
    if (!tmp2) {
2291
        ret = -1;
2292
        goto out;
2293
    }
2294

2295
    /* Hardcoded value for max key value pairs, exits early */
2296
    /* from loop if found NULL */
2297
    for (i = 0; i < GF_MAX_SLOG_PAIR_COUNT; i++) {
2298
        fmt = va_arg(inp, char *);
2299
        if (fmt == NULL) {
2300
            break;
2301
        }
2302

2303
        /* Get number of times % is used in input for formatting, */
2304
        /* this count will be used to skip those many args from the */
2305
        /* main list and will be used to format inner format */
2306
        num_format_chars = 0;
2307
        for (k = 0; fmt[k] != '\0'; k++) {
2308
            /* If %% is used then that is escaped */
2309
            if (fmt[k] == format_char && fmt[k + 1] == format_char) {
2310
                k++;
2311
            } else if (fmt[k] == format_char) {
2312
                num_format_chars++;
2313
            }
2314
        }
2315

2316
        tmp1 = gf_strdup(tmp2);
2317
        if (!tmp1) {
2318
            ret = -1;
2319
            goto out;
2320
        }
2321

2322
        GF_FREE(tmp2);
2323
        tmp2 = NULL;
2324

2325
        if (num_format_chars > 0) {
2326
            /* Make separate valist and format the string */
2327
            va_copy(valist_tmp, inp);
2328
            ret = gf_vasprintf(&buffer, fmt, valist_tmp);
2329
            if (ret < 0) {
2330
                va_end(valist_tmp);
2331
                goto out;
2332
            }
2333
            va_end(valist_tmp);
2334

2335
            for (j = 0; j < num_format_chars; j++) {
2336
                /* Skip the va_arg value since these values
2337
                   are already used for internal formatting */
2338
                (void)va_arg(inp, void *);
2339
            }
2340

2341
            ret = gf_asprintf(&tmp2, "%s%s{%s}", tmp1, temp_sep, buffer);
2342
            if (ret < 0)
2343
                goto out;
2344

2345
            GF_FREE(buffer);
2346
            buffer = NULL;
2347
        } else {
2348
            ret = gf_asprintf(&tmp2, "%s%s{%s}", tmp1, temp_sep, fmt);
2349
            if (ret < 0)
2350
                goto out;
2351
        }
2352

2353
        /* Set seperator for next iteration */
2354
        temp_sep[0] = ',';
2355
        temp_sep[1] = ' ';
2356
        temp_sep[2] = 0;
2357

2358
        GF_FREE(tmp1);
2359
        tmp1 = NULL;
2360
    }
2361

2362
    tmp1 = gf_strdup(tmp2);
2363
    if (!tmp1) {
2364
        ret = -1;
2365
        goto out;
2366
    }
2367
    GF_FREE(tmp2);
2368
    tmp2 = NULL;
2369

2370
    if (errnum) {
2371
        ret = gf_asprintf(&tmp2, "%s [%s%s{errno=%d}, {error=%s}]", event, tmp1,
2372
                          temp_sep, errnum, strerror(errnum));
2373
    } else {
2374
        ret = gf_asprintf(&tmp2, "%s [%s]", event, tmp1);
2375
    }
2376

2377
    if (ret == -1)
2378
        goto out;
2379

2380
    *msg = gf_strdup(tmp2);
2381
    if (!*msg)
2382
        ret = -1;
2383

2384
out:
2385
    if (buffer)
2386
        GF_FREE(buffer);
2387

2388
    if (tmp1)
2389
        GF_FREE(tmp1);
2390

2391
    if (tmp2)
2392
        GF_FREE(tmp2);
2393

2394
    return ret;
2395
}
2396

2397
int
2398
_gf_smsg(const char *domain, const char *file, const char *function,
2399
         int32_t line, gf_loglevel_t level, int errnum, int trace,
2400
         uint64_t msgid, const char *event, ...)
2401
{
2402
    va_list valist;
2403
    char *msg = NULL;
2404
    int ret = 0;
2405
    xlator_t *this = THIS;
2406

2407
    if (skip_logging(this, level))
2408
        return ret;
2409

2410
    va_start(valist, event);
2411
    ret = _do_slog_format(errnum, event, valist, &msg);
2412
    if (ret == -1)
2413
        goto out;
2414

2415
    /* Pass errnum as zero since it is already formated as required */
2416
    ret = _gf_msg(domain, file, function, line, level, 0, trace, msgid, "%s",
2417
                  msg);
2418

2419
out:
2420
    va_end(valist);
2421
    if (msg)
2422
        GF_FREE(msg);
2423
    return ret;
2424
}
2425