Log.c

Go to the documentation of this file.

/*******************************************************************************
 * Copyright (c) 2009, 2018 IBM Corp.
 *
 * All rights reserved. This program and the accompanying materials
 * are made available under the terms of the Eclipse Public License v2.0
 * and Eclipse Distribution License v1.0 which accompany this distribution.
 *
 * The Eclipse Public License is available at
 *    https://www.eclipse.org/legal/epl-2.0/
 * and the Eclipse Distribution License is available at
 *   http://www.eclipse.org/org/documents/edl-v10.php.
 *
 * Contributors:
 *    Ian Craggs - initial API and implementation and/or initial documentation
 *    Ian Craggs - updates for the async client
 *    Ian Craggs - fix for bug #427028
 *******************************************************************************/

#include "Log.h"
#include "MQTTPacket.h"
#include "MQTTProtocol.h"
#include "MQTTProtocolClient.h"
#include "Messages.h"
#include "LinkedList.h"
#include "StackTrace.h"
#include "Thread.h"

#include <stdio.h>
#include <stdlib.h>
#include <stdarg.h>
#include <time.h>
#include <string.h>

#if !defined(_WIN32) && !defined(_WIN64)
#include <syslog.h>
#include <sys/stat.h>
#define GETTIMEOFDAY 1
#else
#define snprintf _snprintf
#endif

#if defined(GETTIMEOFDAY)
        #include <sys/time.h>
#else
        #include <sys/timeb.h>
#endif

#if !defined(_WIN32) && !defined(_WIN64)

#define _unlink unlink
#endif


#if !defined(min)
#define min(A,B) ( (A) < (B) ? (A):(B))
#endif

trace_settings_type trace_settings =
{
        TRACE_MINIMUM,
        400,
        INVALID_LEVEL
};

#define MAX_FUNCTION_NAME_LENGTH 256

typedef struct
{
#if defined(GETTIMEOFDAY)
        struct timeval ts;
#else
        struct timeb ts;
#endif
        int sametime_count;
        int number;
        int thread_id;
        int depth;
        char name[MAX_FUNCTION_NAME_LENGTH + 1];
        int line;
        int has_rc;
        int rc;
        enum LOG_LEVELS level;
} traceEntry;

static int start_index = -1,
                        next_index = 0;
static traceEntry* trace_queue = NULL;
static int trace_queue_size = 0;

static FILE* trace_destination = NULL;  
static char* trace_destination_name = NULL; 
static char* trace_destination_backup_name = NULL; 
static int lines_written = 0; 
static int max_lines_per_file = 1000; 
static enum LOG_LEVELS trace_output_level = INVALID_LEVEL;
static Log_traceCallback* trace_callback = NULL;
static traceEntry* Log_pretrace(void);
static char* Log_formatTraceEntry(traceEntry* cur_entry);
static void Log_output(enum LOG_LEVELS log_level, const char *msg);
static void Log_posttrace(enum LOG_LEVELS log_level, traceEntry* cur_entry);
static void Log_trace(enum LOG_LEVELS log_level, const char *buf);
#if 0
static FILE* Log_destToFile(const char *dest);
static int Log_compareEntries(const char *entry1, const char *entry2);
#endif

static int sametime_count = 0;
#if defined(GETTIMEOFDAY)
struct timeval now_ts, last_ts;
#else
struct timeb now_ts, last_ts;
#endif
static char msg_buf[512];

#if defined(_WIN32) || defined(_WIN64)
mutex_type log_mutex;
#else
static pthread_mutex_t log_mutex_store = PTHREAD_MUTEX_INITIALIZER;
static mutex_type log_mutex = &log_mutex_store;
#endif


int Log_initialize(Log_nameValue* info)
{
        int rc = SOCKET_ERROR;
        char* envval = NULL;
#if !defined(_WIN32) && !defined(_WIN64)
        struct stat buf;
#endif

        if ((trace_queue = malloc(sizeof(traceEntry) * trace_settings.max_trace_entries)) == NULL)
                goto exit;
        trace_queue_size = trace_settings.max_trace_entries;

        if ((envval = getenv("MQTT_C_CLIENT_TRACE")) != NULL && strlen(envval) > 0)
        {
                if (strcmp(envval, "ON") == 0 || (trace_destination = fopen(envval, "w")) == NULL)
                        trace_destination = stdout;
                else
                {
                        if ((trace_destination_name = malloc(strlen(envval) + 1)) == NULL)
                        {
                                free(trace_queue);
                                goto exit;
                        }
                        strcpy(trace_destination_name, envval);
                        if ((trace_destination_backup_name = malloc(strlen(envval) + 3)) == NULL)
                        {
                                free(trace_queue);
                                free(trace_destination_name);
                                goto exit;
                        }
                        sprintf(trace_destination_backup_name, "%s.0", trace_destination_name);
                }
        }
        if ((envval = getenv("MQTT_C_CLIENT_TRACE_MAX_LINES")) != NULL && strlen(envval) > 0)
        {
                max_lines_per_file = atoi(envval);
                if (max_lines_per_file <= 0)
                        max_lines_per_file = 1000;
        }
        if ((envval = getenv("MQTT_C_CLIENT_TRACE_LEVEL")) != NULL && strlen(envval) > 0)
        {
                if (strcmp(envval, "MAXIMUM") == 0 || strcmp(envval, "TRACE_MAXIMUM") == 0)
                        trace_settings.trace_level = TRACE_MAXIMUM;
                else if (strcmp(envval, "MEDIUM") == 0 || strcmp(envval, "TRACE_MEDIUM") == 0)
                        trace_settings.trace_level = TRACE_MEDIUM;
                else if (strcmp(envval, "MINIMUM") == 0 || strcmp(envval, "TRACE_MINIMUM") == 0)
                        trace_settings.trace_level = TRACE_MINIMUM;
                else if (strcmp(envval, "PROTOCOL") == 0  || strcmp(envval, "TRACE_PROTOCOL") == 0)
                        trace_output_level = TRACE_PROTOCOL;
                else if (strcmp(envval, "ERROR") == 0  || strcmp(envval, "TRACE_ERROR") == 0)
                        trace_output_level = LOG_ERROR;
        }
        Log_output(TRACE_MINIMUM, "=========================================================");
        Log_output(TRACE_MINIMUM, "                   Trace Output");
        if (info)
        {
                while (info->name)
                {
                        snprintf(msg_buf, sizeof(msg_buf), "%s: %s", info->name, info->value);
                        Log_output(TRACE_MINIMUM, msg_buf);
                        info++;
                }
        }
#if !defined(_WIN32) && !defined(_WIN64)
        if (stat("/proc/version", &buf) != -1)
        {
                FILE* vfile;

                if ((vfile = fopen("/proc/version", "r")) != NULL)
                {
                        int len;

                        strcpy(msg_buf, "/proc/version: ");
                        len = strlen(msg_buf);
                        if (fgets(&msg_buf[len], sizeof(msg_buf) - len, vfile))
                                Log_output(TRACE_MINIMUM, msg_buf);
                        fclose(vfile);
                }
        }
#endif
        Log_output(TRACE_MINIMUM, "=========================================================");
exit:
        return rc;
}


void Log_setTraceCallback(Log_traceCallback* callback)
{
        trace_callback = callback;
}


void Log_setTraceLevel(enum LOG_LEVELS level)
{
        if (level < TRACE_MINIMUM) /* the lowest we can go is TRACE_MINIMUM*/
                trace_settings.trace_level = level;
        trace_output_level = level;
}


void Log_terminate(void)
{
        free(trace_queue);
        trace_queue = NULL;
        trace_queue_size = 0;
        if (trace_destination)
        {
                if (trace_destination != stdout)
                        fclose(trace_destination);
                trace_destination = NULL;
        }
        if (trace_destination_name) {
                free(trace_destination_name);
                trace_destination_name = NULL;
        }
        if (trace_destination_backup_name) {
                free(trace_destination_backup_name);
                trace_destination_backup_name = NULL;
        }
        start_index = -1;
        next_index = 0;
        trace_output_level = INVALID_LEVEL;
        sametime_count = 0;
}


static traceEntry* Log_pretrace(void)
{
        traceEntry *cur_entry = NULL;

        /* calling ftime/gettimeofday seems to be comparatively expensive, so we need to limit its use */
        if (++sametime_count % 20 == 0)
        {
#if defined(GETTIMEOFDAY)
                gettimeofday(&now_ts, NULL);
                if (now_ts.tv_sec != last_ts.tv_sec || now_ts.tv_usec != last_ts.tv_usec)
#else
                ftime(&now_ts);
                if (now_ts.time != last_ts.time || now_ts.millitm != last_ts.millitm)
#endif
                {
                        sametime_count = 0;
                        last_ts = now_ts;
                }
        }

        if (trace_queue_size != trace_settings.max_trace_entries)
        {
                traceEntry* new_trace_queue = malloc(sizeof(traceEntry) * trace_settings.max_trace_entries);

                if (new_trace_queue == NULL)
                        goto exit;
                memcpy(new_trace_queue, trace_queue, min(trace_queue_size, trace_settings.max_trace_entries) * sizeof(traceEntry));
                free(trace_queue);
                trace_queue = new_trace_queue;
                trace_queue_size = trace_settings.max_trace_entries;

                if (start_index > trace_settings.max_trace_entries + 1 ||
                                next_index > trace_settings.max_trace_entries + 1)
                {
                        start_index = -1;
                        next_index = 0;
                }
        }

        /* add to trace buffer */
        cur_entry = &trace_queue[next_index];
        if (next_index == start_index) /* means the buffer is full */
        {
                if (++start_index == trace_settings.max_trace_entries)
                        start_index = 0;
        } else if (start_index == -1)
                start_index = 0;
        if (++next_index == trace_settings.max_trace_entries)
                next_index = 0;
exit:
        return cur_entry;
}

static char* Log_formatTraceEntry(traceEntry* cur_entry)
{
        struct tm *timeinfo;
        int buf_pos = 31;

#if defined(GETTIMEOFDAY)
        timeinfo = localtime((time_t *)&cur_entry->ts.tv_sec);
#else
        timeinfo = localtime(&cur_entry->ts.time);
#endif
        strftime(&msg_buf[7], 80, "%Y%m%d %H%M%S ", timeinfo);
#if defined(GETTIMEOFDAY)
        sprintf(&msg_buf[22], ".%.3lu ", cur_entry->ts.tv_usec / 1000L);
#else
        sprintf(&msg_buf[22], ".%.3hu ", cur_entry->ts.millitm);
#endif
        buf_pos = 27;

        sprintf(msg_buf, "(%.4d)", cur_entry->sametime_count);
        msg_buf[6] = ' ';

        if (cur_entry->has_rc == 2)
                strncpy(&msg_buf[buf_pos], cur_entry->name, sizeof(msg_buf)-buf_pos);
        else
        {
                const char *format = Messages_get(cur_entry->number, cur_entry->level);
                if (cur_entry->has_rc == 1)
                        snprintf(&msg_buf[buf_pos], sizeof(msg_buf)-buf_pos, format, cur_entry->thread_id,
                                        cur_entry->depth, "", cur_entry->depth, cur_entry->name, cur_entry->line, cur_entry->rc);
                else
                        snprintf(&msg_buf[buf_pos], sizeof(msg_buf)-buf_pos, format, cur_entry->thread_id,
                                        cur_entry->depth, "", cur_entry->depth, cur_entry->name, cur_entry->line);
        }
        return msg_buf;
}


static void Log_output(enum LOG_LEVELS log_level, const char *msg)
{
        if (trace_destination)
        {
                fprintf(trace_destination, "%s\n", msg);

                if (trace_destination != stdout && ++lines_written >= max_lines_per_file)
                {

                        fclose(trace_destination);
                        _unlink(trace_destination_backup_name); /* remove any old backup trace file */
                        rename(trace_destination_name, trace_destination_backup_name); /* rename recently closed to backup */
                        trace_destination = fopen(trace_destination_name, "w"); /* open new trace file */
                        if (trace_destination == NULL)
                                trace_destination = stdout;
                        lines_written = 0;
                }
                else
                        fflush(trace_destination);
        }

        if (trace_callback)
                (*trace_callback)(log_level, msg);
}


static void Log_posttrace(enum LOG_LEVELS log_level, traceEntry* cur_entry)
{
        if (((trace_output_level == -1) ? log_level >= trace_settings.trace_level : log_level >= trace_output_level))
        {
                char* msg = NULL;

                if (trace_destination || trace_callback)
                        msg = &Log_formatTraceEntry(cur_entry)[7];

                Log_output(log_level, msg);
        }
}


static void Log_trace(enum LOG_LEVELS log_level, const char *buf)
{
        traceEntry *cur_entry = NULL;

        if (trace_queue == NULL)
                return;

        cur_entry = Log_pretrace();

        memcpy(&(cur_entry->ts), &now_ts, sizeof(now_ts));
        cur_entry->sametime_count = sametime_count;

        cur_entry->has_rc = 2;
        strncpy(cur_entry->name, buf, sizeof(cur_entry->name));
        cur_entry->name[MAX_FUNCTION_NAME_LENGTH] = '\0';

        Log_posttrace(log_level, cur_entry);
}


void Log(enum LOG_LEVELS log_level, int msgno, const char *format, ...)
{
        if (log_level >= trace_settings.trace_level)
        {
                const char *temp = NULL;
                va_list args;

                /* we're using a static character buffer, so we need to make sure only one thread uses it at a time */
                Thread_lock_mutex(log_mutex);
                if (format == NULL && (temp = Messages_get(msgno, log_level)) != NULL)
                        format = temp;

                va_start(args, format);
                vsnprintf(msg_buf, sizeof(msg_buf), format, args);

                Log_trace(log_level, msg_buf);
                va_end(args);
                Thread_unlock_mutex(log_mutex);
        }
}


void Log_stackTrace(enum LOG_LEVELS log_level, int msgno, int thread_id, int current_depth, const char* name, int line, int* rc)
{
        traceEntry *cur_entry = NULL;

        if (trace_queue == NULL)
                return;

        if (log_level < trace_settings.trace_level)
                return;

        Thread_lock_mutex(log_mutex);
        cur_entry = Log_pretrace();

        memcpy(&(cur_entry->ts), &now_ts, sizeof(now_ts));
        cur_entry->sametime_count = sametime_count;
        cur_entry->number = msgno;
        cur_entry->thread_id = thread_id;
        cur_entry->depth = current_depth;
        strcpy(cur_entry->name, name);
        cur_entry->level = log_level;
        cur_entry->line = line;
        if (rc == NULL)
                cur_entry->has_rc = 0;
        else
        {
                cur_entry->has_rc = 1;
                cur_entry->rc = *rc;
        }

        Log_posttrace(log_level, cur_entry);
        Thread_unlock_mutex(log_mutex);
}


#if 0
static FILE* Log_destToFile(const char *dest)
{
        FILE* file = NULL;

        if (strcmp(dest, "stdout") == 0)
                file = stdout;
        else if (strcmp(dest, "stderr") == 0)
                file = stderr;
        else
        {
                if (strstr(dest, "FFDC"))
                        file = fopen(dest, "ab");
                else
                        file = fopen(dest, "wb");
        }
        return file;
}


static int Log_compareEntries(const char *entry1, const char *entry2)
{
        int comp = strncmp(&entry1[7], &entry2[7], 19);

        /* if timestamps are equal, use the sequence numbers */
        if (comp == 0)
                comp = strncmp(&entry1[1], &entry2[1], 4);

        return comp;
}


int Log_dumpTrace(char* dest)
{
        FILE* file = NULL;
        ListElement* cur_trace_entry = NULL;
        const int msgstart = 7;
        int rc = -1;
        int trace_queue_index = 0;

        if ((file = Log_destToFile(dest)) == NULL)
        {
                Log(LOG_ERROR, 9, NULL, "trace", dest, "trace entries");
                goto exit;
        }

        fprintf(file, "=========== Start of trace dump ==========\n");
        /* Interleave the log and trace entries together appropriately */
        ListNextElement(trace_buffer, &cur_trace_entry);
        trace_queue_index = start_index;
        if (trace_queue_index == -1)
                trace_queue_index = next_index;
        else
        {
                Log_formatTraceEntry(&trace_queue[trace_queue_index++]);
                if (trace_queue_index == trace_settings.max_trace_entries)
                        trace_queue_index = 0;
        }
        while (cur_trace_entry || trace_queue_index != next_index)
        {
                if (cur_trace_entry && trace_queue_index != -1)
                {       /* compare these timestamps */
                        if (Log_compareEntries((char*)cur_trace_entry->content, msg_buf) > 0)
                                cur_trace_entry = NULL;
                }

                if (cur_trace_entry)
                {
                        fprintf(file, "%s\n", &((char*)(cur_trace_entry->content))[msgstart]);
                        ListNextElement(trace_buffer, &cur_trace_entry);
                }
                else
                {
                        fprintf(file, "%s\n", &msg_buf[7]);
                        if (trace_queue_index != next_index)
                        {
                                Log_formatTraceEntry(&trace_queue[trace_queue_index++]);
                                if (trace_queue_index == trace_settings.max_trace_entries)
                                        trace_queue_index = 0;
                        }
                }
        }
        fprintf(file, "========== End of trace dump ==========\n\n");
        if (file != stdout && file != stderr && file != NULL)
                fclose(file);
        rc = 0;
exit:
        return rc;
}
#endif