Logging library for C

Question

Over the past couple of weeks I have been working on a general purpose logging library for C in my free time. At the moment I have stabilized the API and most of the features I wanted to implement have been implemented. I am looking for general suggestions (note I haven't done much API documentation yet) on code quality and correctness (especially the synchronization techniques, IO methods, and message building functions).

You can find the full repository here.

And below I have included the sample usage that appears in the repo:

#include <stdio.h>
#include <stdlib.h>
#include "scribe.h"

int main(void)
{
    if (SCRB_Success != scrb_init()) {
        return EXIT_FAILURE;
    }

    // We open a new file called `example.log` in write mode without synchronization that only
    // listens to info level log messages.
    struct scrb_stream * const logstream = scrb_open_stream("example.log", "w", false, LVL_INFO);

    // We define a log format to tell scribe how to format our messages.
    // This format prints out the file, method, and line locations followed by the message itself.
    struct scrb_format const * const fmt = scrb_create_format("[%F:%L:%M] %m", NULL);

    // Now we're ready to go.
    scrb_logln(logstream, fmt, LVL_INFO, "Hello from the example program!");

    // We can do formatted output as well.
    scrb_flogln(logstream, fmt, LVL_INFO, "Hello for the %dnd time!", 2);

    // If we want to write directly to the file without formatting or location/time info
    // (or paying attention to log levels) we can use the `scrb_putstrln` method to write directly to the file.
    scrb_putstrln(logstream, "Now we're done.");

    scrb_format_release(&fmt);
    scrb_close_stream(&logstream);
    return EXIT_SUCCESS;
}

I have written a synchronized version similar to the above wherein 4 separate threads all log to the same file, which you may find the the examples folder.

Here is the scribe.h header file (as per request):

#ifndef SCRIBE_H
#define SCRIBE_H

#ifdef __cplusplus
extern "C" {
#endif

#include <stdarg.h>
#include <stdbool.h>
#include <stdint.h>
#include <stdio.h>
#include <stdlib.h>

#include "scribe_conf.h"
#include "scribe_debug.h"
#include "scribe_format.h"
#include "scribe_io.h"
#include "scribe_loglevel.h"
#include "scribe_metainfo.h"
#include "scribe_return_types.h"
#include "scribe_stream.h"
#include "scribe_utils.h"
#include "spinlock.h"

#if defined(SCRIBE_WINDOWS)
#include "Windows.h"
#endif

#define LVL_TO_DEBUG  (LVL_DEBUG)
#define LVL_TO_TRACE  (LVL_DEBUG | LVL_TRACE)
#define LVL_TO_INFO   (LVL_DEBUG | LVL_TRACE | LVL_INFO)
#define LVL_TO_NOTICE (LVL_DEBUG | LVL_TRACE | LVL_INFO | LVL_NOTICE)
#define LVL_TO_WARN   (LVL_DEBUG | LVL_TRACE | LVL_INFO | LVL_NOTICE | LVL_WARN)
#define LVL_TO_ALERT  (LVL_DEBUG | LVL_TRACE | LVL_INFO | LVL_NOTICE | LVL_WARN | LVL_ALERT)
#define LVL_TO_ERROR  (LVL_DEBUG | LVL_TRACE | LVL_INFO | LVL_NOTICE | LVL_WARN | LVL_ALERT | LVL_ERROR)
#define LVL_TO_EMERG  (LVL_DEBUG | LVL_TRACE | LVL_INFO | LVL_NOTICE | LVL_WARN | LVL_ALERT | LVL_ERROR | LVL_EMERG)
#define LVL_ALL       (LVL_DEBUG | LVL_TRACE | LVL_INFO | LVL_NOTICE | LVL_WARN | LVL_ALERT | LVL_ERROR | LVL_EMERG)

static
struct scrb_stream * const scrb_stdout = &stream_out_default;

static
struct scrb_stream * const scrb_stdin  = &stream_in_default;

static
struct scrb_stream * const scrb_stderr = &stream_err_default;

#if SCRIBE_DEBUG
static
struct scrb_stream const * const scrb_debug  = &scrb_dbg_default;
#endif

// `scrb_init`
// doc...
static inline
int scrb_init(void)
{
#if defined(SCRIBE_WINDOWS)
    static volatile LONG initialized = 0;
    if (0 == InterlockedCompareExchange(&initialized, 1, 0)) {
#else    
    static volatile int initialized = 0;
    if (__sync_bool_compare_and_swap(&initialized, 0, 1)) {
#endif
        struct scrb_stream outstream = (struct scrb_stream) {
            .name        = "stdout",
            .synchronize = true,
            .severity    = LVL_ALL, 
            .stream = {
                .mode       = NULL,
                .filestream = stdout,
            },
            .rwlock = spinlock_init(SCRIBE_RWLOCK_DELAY)
        };

        struct scrb_stream instream = (struct scrb_stream) {
            .name        = "stdin",
            .synchronize = true,
            .severity    = LVL_ALL,
            .stream = {
                .mode       = NULL,
                .filestream = stdin,
            },
            .rwlock = spinlock_init(SCRIBE_RWLOCK_DELAY)
        };

        struct scrb_stream errstream = (struct scrb_stream) {
            .name        = "stderr",
            .synchronize = true,
            .severity    = LVL_ALL,
            .stream = {
                .mode       = NULL,
                .filestream = stderr,
            },
            .rwlock = spinlock_init(SCRIBE_RWLOCK_DELAY) 
        };

#if SCRIBE_DEBUG
        FILE * const dbg_filestream = fopen("scribedebug.log", "a");
        struct scrb_stream dbgstream = (struct scrb_stream) {
            .name        = "debug",
            .synchronize = true,
            .severity    = LVL_ALL,
            .stream = {
                .mode       = NULL,
                .filestream = dbg_filestream,
            },
            .rwlock = spinlock_init(SCRIBE_RWLOCK_DELAY)
        };

        if (NULL == dbgstream.stream.filestream) {
            return (SCRB_Failure);
        }

        scrb_init_defaults(&outstream, &instream, &errstream, &dbgstream);
        fprintf(dbgstream.stream.filestream, "----- scribe init :: version (%s) :: compile date (%s %s) :: compiled as "SCRB_LANGUAGE" by "SCRB_CC" ver. " SCRB_CC_VER " :: pid (%d) -----\n",
                SCRIBE_VERSION, __DATE__, __TIME__, (int) scrb_getpid());
#else
        scrb_init_defaults(&outstream, &instream, &errstream);
#endif
    }
    return (SCRB_Success);
}

// `scrb_create_format`
// doc...
static inline
struct scrb_format * scrb_create_format(char const * const fmtstr, 
                                        void (*timehook)(char ** buff, 
                                                         size_t * len, 
                                                         SCRIBE_TIME_T ts))
{
    return scrb_create_format__internal(fmtstr, timehook);
}

//
//
static inline
void (scrb_format_release)(struct scrb_format ** fmtptr)
{
    scrb_format_release__internal(fmtptr);
}
#define scrb_format_release(fmtptr) (scrb_format_release)((struct scrb_format **) (fmtptr))

// `scrb_stream_name`
// doc...
static inline
char const * scrb_stream_name(struct scrb_stream const * const st)
{
    return scrb_stream_name__internal(st);
}

// `scrb_stream_severity`
// doc...
static inline
uint16_t scrb_stream_severity(struct scrb_stream const * const st)
{
    return scrb_stream_severity__internal(st);
}

// `scribe_open_file`
// doc...
static inline
struct scrb_stream * scrb_open_stream(char const * const path, 
                                      char const * const mode, 
                                      bool const synchronize,
                                      uint16_t const severity)
{
    return scrb_open_stream__internal(path, mode, synchronize, severity);
}

// `scribe_close`
// doc...
static inline
void (scrb_close_stream)(struct scrb_stream ** streamptr)
{
    scrb_close_stream__internal(streamptr);
}
#define scrb_close_stream(streamptr) (scrb_close_stream)((struct scrb_stream **)(streamptr))

// `scribe_flush_stream`
// doc...
static inline
void scrb_flush_stream(struct scrb_stream * const st)
{
    scrb_flush_stream__internal(st);
}

// `scribe_write`
// doc...
static inline
int (scrb_log)(struct scrb_meta_info const mi, 
               struct scrb_stream * const st, 
               struct scrb_format const * const fmt, 
               uint16_t const severity,
               char const * const msg)
{
    if (severity & st->severity) {
        return scrb_log__internal(mi, st, fmt, severity, msg, false); 
    } else {
        return SCRB_Success;
    }
}
#define scrb_log(st, fmt, sv, msg) (scrb_log)(get_meta_info((st)->name), (st), (fmt), (sv), (msg))

// `scribe_writeln`
// doc...
static inline
int (scrb_logln)(struct scrb_meta_info const mi, 
                 struct scrb_stream * const st, 
                 struct scrb_format const * const fmt, 
                 uint16_t const severity,
                 char const * const msg)
{
    if (severity & st->severity) {
        return scrb_log__internal(mi, st, fmt, severity, msg, true); 
    } else {
        return SCRB_Success;
    }
}
#define scrb_logln(st, fmt, sv, msg) (scrb_logln)(get_meta_info((st)->name), (st), (fmt), (sv), (msg))

// `scribe_writestr`
// doc...
static inline
int scrb_putstr(struct scrb_stream * const st, char const * const msg)
{
    return scrb_putstr__internal(st, msg, false);
}

// `scribe_writestrln`
// doc...
static inline
int scrb_putstrln(struct scrb_stream * const st, char const * const msg)
{
    return scrb_putstr__internal(st, msg, true);
}

// `fscribe_write`
// doc...
static inline
int (scrb_flog)(struct scrb_meta_info const mi, 
                struct scrb_stream * const st,
                struct scrb_format const * const fmt, 
                uint16_t const severity,
                char const * const msgfmt, ...)
{
    if (severity & st->severity) {
        va_list ap;
        va_start (ap, msgfmt);
        int const rval = scrb_flog__internal(mi, st, fmt, severity, msgfmt, false, ap);
        va_end (ap);
        return rval;
    } else {
        return SCRB_Success;
    }
}
#define scrb_flog(st, fmt, sv, msg, ...) (scrb_flog)(get_meta_info((st)->name), (st), (fmt), (sv), (msg), ##__VA_ARGS__)

// `fscribe_writeln`
// doc...
static inline
int (scrb_flogln)(struct scrb_meta_info const mi, 
                  struct scrb_stream * const st,
                  struct scrb_format const * const fmt, 
                  uint16_t const severity,
                  char const * const msgfmt, ...)
{
    if (severity & st->severity) {
        va_list ap;
        va_start (ap, msgfmt);
        int const rval = scrb_flog__internal(mi, st, fmt, severity, msgfmt, true, ap);
        va_end (ap);
        return rval;
    } else {
        return SCRB_Success;
    }
}
#define scrb_flogln(st, fmt, sv, msg, ...) (scrb_flogln)(get_meta_info((st)->name), (st), (fmt), (sv), (msg), ##__VA_ARGS__)

#ifdef __cplusplus
}
#endif

#endif

Jonathan Leffler · Accepted Answer · 2014-12-18 00:28:35Z

It'll take some time to describe everything, and I need to pretend to do some work at some point too. However...

In scribe.h:

struct scrb_stream outstream = (struct scrb_stream) { ... }; you are assigning a compound literal instead of just initializing the structure. Lose the (struct scrb_stream) cast notation in these lines.

Another way of writing:

if (severity & st->severity) {
    va_list ap;
    va_start (ap, msgfmt);
    int const rval = scrb_flog__internal(mi, st, fmt, severity, msgfmt, false, ap);
    va_end (ap);
    return rval;
} else {
    return SCRB_Success;
}

is:

int rval = SCRB_SUCCESS;
if (severity & st->severity) {
    va_list ap;
    va_start(ap, msgfmt);
    rval = scrb_flog__internal(mi, st, fmt, severity, msgfmt, false, ap);
    va_end(ap);
}
return rval;

You have a collection of functions such as:
```
static inline
void (scrb_close_stream)(struct scrb_stream ** streamptr)
{
    scrb_close_stream__internal(streamptr);
}
#define scrb_close_stream(streamptr) (scrb_close_stream)((struct scrb_stream **)(streamptr))
```
I see multiple issues, some serious and some less serious.
- Serious: Why do you want to throw away type safety with the macro? The cast in the macro expansion means that you can pass an integer to the function, or a FILE *, or a struct scrb_stream * (rather than the address of a struct scrb_stream *) and the cast suppresses the error messages that the compiler would otherwise generate. Drop the cast; don't suppress the limited protections that the compiler can provide.
- Serious: You are embedding double underscores into the names. You care about C++ since you've included #ifdef __cplusplus, but C++ reserves double-underscore anywhere in any name for use by the implementation. Don't do it!
- With the cast removed, the macro serves no purpose here.
- What is the perceived benefit of the static inline functions that call onto the *_internal name? In this example, I see no benefit.

Some of the macro and inline function combinations worry me:

static inline
int (scrb_flog)(struct scrb_meta_info const mi, 
                struct scrb_stream * const st,
                struct scrb_format const * const fmt, 
                uint16_t const severity,
                char const * const msgfmt, ...)
{
    if (severity & st->severity) {
        va_list ap;
        va_start (ap, msgfmt);
        int const rval = scrb_flog__internal(mi, st, fmt, severity, msgfmt, false, ap);
        va_end (ap);
        return rval;
    } else {
        return SCRB_Success;
    }
}
#define scrb_flog(st, fmt, sv, msg, ...) (scrb_flog)(get_meta_info((st)->name), (st), (fmt), (sv), (msg), ##__VA_ARGS__)

Apart from the issues previously raised, here we have a macro scrb_flog() that calls a function scrb_flog() with an extra argument. This will lead to confusion somewhere along the line. It also really isn't necessary; you can avoid the overhead of the get_meta_info() function call in the 'not used' case by writing this as:

static inline
int (scrb_flog)(struct scrb_stream * const st,
                struct scrb_format const * const fmt, 
                uint16_t const severity,
                char const * const msgfmt, ...)
{
    int rval = SCRB_SUCCESS;
    if (severity & st->severity) {
        va_list ap;
        va_start(ap, msgfmt);
        rval = scrb_flog_internal(get_meta_info(st->name), st, fmt, severity, msgfmt, false, ap);
        va_end(ap);

    }
    return rval;
}
#define scrb_flog(st, fmt, sv, msg, ...) (scrb_flog)((st), (fmt), (sv), (msg), ##__VA_ARGS__)

Clearly, the goal here is to avoid moving the if test into the called function. I've not seen measurements to justify that; my suspicion is that the extra code built into the calling functions may be worse than the function call.

If the meta information is determined from the stream, I wonder why the internal function can't determine the meta information from the stream. Without studying the code in more detail than I'm going to, it is not clear why the scrb_meta_info * argument is passed to scrb_flog_internal() rather than letting the function determine the meta info from the stream.

You currently have the header doing:
```
static struct scrb_stream * const scrb_stdout = &stream_out_default;
static struct scrb_stream * const scrb_stdin  = &stream_in_default;
static struct scrb_stream * const scrb_stderr = &stream_err_default;
```
Defining static variables in a header is dubious. The non-systematic names on the RHS are a red flag; they should be scrb_stream_out_default etc. More significantly, what is the scrb_init_default() function doing, and when might those pointers be changed, and if they're never changed, why don't you just have
```
extern struct scrb_stream *scrb_stdout;
```
I'm not sure what flexibility you think you're buying with this extra level of indirection repeated in each object file where the source file uses the header.
My gut feel is that the scrb_init() code should be in a regular function, not an inline function.
I also think it would be better to hide the compilation issues (Windows vs non-Windows) in the implementation file rather than expose it in the header file that the general public uses.
I've probably missed the code that uses anything from <stdlib.h>, but superficially, that is an unnecessary header.
I wonder why you chose severity & st->severity rather than severity >= st->severity with a straight enumeration of different severities, rather than the bitmask approach. Under what circumstances is it sensible to have LVL_DEBUG set, but LVL_TRACE and LVL_INFO unset, with LVL_NOTICE, LVL_WARN, LVL_ALERT all set?
You have some provision for thread-support. Should the meta information include a thread ID so you can identify messages from different threads? If so, how should the code determine whether thread IDs are relevant — how can the code tell, or be told, that it is in a multi-threaded application vs a single-threaded application?
You have a stringdup() function in scrib_utils.h:
```
static inline
char * stringdup(char const * const str)
{
    uint64_t const len = strlen(str);
    char * const new   = malloc(len + 1);
    if (NULL == new) {
        errno = ENOMEM;
        return NULL;
    }
    memcpy(new, str, len);
    new[len] = '\0';
    return new;
}
```
I have reservations about making that an inline function (but measurements of code size might convince me it doesn't matter).

You can simply use memcpy(new, str, len+1); without the separate assignment; the string is null-terminated because you use strlen() to determine its length, so the extra byte copied is a null byte, and the separate assignment is therefore unnecessary.

Overall, what I'm seeing looks a bit over-engineered in places, but it has a lot of good features too. There are some dubious practices in the code.

It's an interesting attempt to use inline functions. You're doing that in the way that makes most sense in C99 or later, making the functions static inline in a header, but my preferred technique would almost certainly be to have simple function declarations in the header and not worry about the 'performance overhead' of the function calls until you can demonstrate that they're a measurable overhead.

Thank you for the comments. I'll begin fixing all of these immediately. One thing about the "meta information" macro, however: it's used to gather the function invocation location (that is the file name, method name, line number, invoking process ID, and timestamp where the *log methods are used). This is why it cannot be included in the function body instead of where it is currently gathered (at the invocation point in user-code) using the macro. I have not found another way around this issue besides the macros. — Dalton
– Dalton, Commented Dec 17, 2014 at 23:37
That's the problem with not having all the code to review in the question. It's also the problem with macros. And while I sympathize with not wanting to overload the question with code, there's also a problem with not showing enough code. I debated whether to paste some or all of a 150-line header of mine (of which, 93 lines are non-blank, non-comment lines) which performs more or less the same job. I decided not to. It has its own legacy baggage from more than 25 years of honing. — Jonathan Leffler
– Jonathan Leffler, Commented Dec 17, 2014 at 23:45
Thank you once more for all of the issues you've pointed out. I have (mostly) addressed points 1-9 and 11 listed above. The changes have been committed and pushed to the repository. — Dalton
– Dalton, Commented Dec 18, 2014 at 1:01
Also, is there a standard way to obtain a thread-id? That is dependent on what thread model is being used, as well as which OS, correct? — Dalton
– Dalton, Commented Dec 18, 2014 at 1:02
There isn't really a good way to get the thread ID. The gettid() system call in Linux does one job, but it is not wrapped as a function in the C library. The example in syscall(2) man page shows how to get to the gettid() system call, though. There's also pthread_self(), but the details of the thread_t type it returns are unspecified, so there isn't a good way to print the value. I've no idea what Windows provides. C11 (and C++11) provide thrd_current() which returns a thrd_t. And so the list goes on. — Jonathan Leffler
– Jonathan Leffler, Commented Dec 18, 2014 at 18:10

Stack Exchange Network

Logging library for C

1 Answer 1

You must log in to answer this question.

Hot Network Questions

Logging library for C

1 Answer 1

You must log in to answer this question.

Related

Hot Network Questions