Logger module in C

Question

I wrote a logger module in C, that is essentially a printf wrapper + some additional color coding:

I'd like get feedback how I can improve performance and also use better coding style. Right now, I feel like a lot of the code is redundant/can be written in a better way.

log.c

#include <stdarg.h>
#include <stdio.h>
#include <time.h>
#include "log.h"

bool time_prefix = false;

void log_use_time_prefix(bool toggle)
{
    time_prefix = toggle;
}

void log_info(char *format_string, ...)
{
    va_list args1;
    va_start(args1, format_string);
    va_list args2;
    va_copy(args2, args1);
    char buf[1 + vsnprintf(NULL, 0, format_string, args1)];
    va_end(args1);
    vsnprintf(buf, sizeof buf, format_string, args2);
    va_end(args2);

    if (time_prefix)
    {
        time_t t = time(NULL);
        struct tm tm = *localtime(&t);
        printf("%d:%d:%d \033[0m\033[1;34m[INFO]\033[0m %s", tm.tm_hour, tm.tm_min, tm.tm_sec, buf);
    }
    else
    {
        printf("\033[0m\033[1;34m[INFO]\033[0m %s", buf);
    }
}

void log_error(char *format_string, ...)
{
    va_list args1;
    va_start(args1, format_string);
    va_list args2;
    va_copy(args2, args1);
    char buf[1 + vsnprintf(NULL, 0, format_string, args1)];
    va_end(args1);
    vsnprintf(buf, sizeof buf, format_string, args2);
    va_end(args2);
    if (time_prefix)
    {
        time_t t = time(NULL);
        struct tm tm = *localtime(&t);
        printf("%d:%d:%d \033[0m\033[1;31m[FAIL]\033[0m %s", tm.tm_hour, tm.tm_min, tm.tm_sec, buf);
    }
    else
    {
        printf("\033[0m\033[1;31m[FAIL]\033[0m %s", buf);
    }
}

void log_success(char *format_string, ...)
{
    va_list args1;
    va_start(args1, format_string);
    va_list args2;
    va_copy(args2, args1);
    char buf[1 + vsnprintf(NULL, 0, format_string, args1)];
    va_end(args1);
    vsnprintf(buf, sizeof buf, format_string, args2);
    va_end(args2);
    if (time_prefix)
    {
        time_t t = time(NULL);
        struct tm tm = *localtime(&t);
        printf("%d:%d:%d \033[0m\033[1;32m[PASS]\033[0m %s", tm.tm_hour, tm.tm_min, tm.tm_sec, buf);
    }
    else
    {
        printf("\033[0m\033[1;32m[PASS]\033[0m %s", buf);
    }
}

void log_warning(char *format_string, ...)
{
    va_list args1;
    va_start(args1, format_string);
    va_list args2;
    va_copy(args2, args1);
    char buf[1 + vsnprintf(NULL, 0, format_string, args1)];
    va_end(args1);
    vsnprintf(buf, sizeof buf, format_string, args2);
    va_end(args2);
    if (time_prefix)
    {
        time_t t = time(NULL);
        struct tm tm = *localtime(&t);
        printf("%d:%d:%d \033[0m\033[1;33m[WARN]\033[0m %s", tm.tm_hour, tm.tm_min, tm.tm_sec, buf);
    }
    else
    {
        printf("\033[0m\033[1;33m[WARN]\033[0m %s", buf);
    }
}

log.h

#include <stdbool.h>

void log_use_time_prefix(bool toggle);

void log_info(char* message, ...);

void log_error(char* message, ...);

void log_success(char* message, ...);

void log_warning(char* message, ...);

main.c

#include "log.h"
#include <stdio.h>
#include <stdarg.h>
#include <time.h>

int main(){

    log_use_time_prefix(true);

    log_info("Loading level number %#x ...\n", 123456);
    log_error("Failed to load level. Error code: %d\n", 123);
    log_warning("Deprecated function %s used.\n", "puts");
    log_success("Level loaded successfully.\n");
    return 0;
}

Answer 1

Redundant code

As the 4 functions are nearly identical, consider coding helper functions.

At a minimum, I recommend a printf_prefix(const char *ansi_color, const char *pass);

To form a helper function of the first part with a va_list parameter is tricky. See below.

Time

I'd code for a fixed width time

// %d:%d:%d
%02d:%02d:%02d

Flush

For the more critical outputs like fail,warn, consider fflush(stdout) to insure data is seen.

'\n'

Perhaps code the '\n' in the print function and not oblige the user to code it. I am on the fence on this one.

Fixed buffer

The nature of failures, warnings, etc. hint that something is wrong. To insure things like "Error, code is about to die due to blah blah blah ...." gets printed out, I'd consider avoiding a VLA like char buf[1 + vsnprintf(...)]; and use a generous fixed length buffer. I'd rather get a truncated noticed than have the last words of errant code fail to print due to a buffer overrun/stack-overflow.

Sentinels

When printing an error message, consider sentinels when printing the string. Error string sometimes are themselves dubious and good to know just were the message starts and stops.

//printf("... %s", ... buf);
printf("... \"%s\"\n", ... buf);
//          ^^  ^^

Error checking

Since this is code to debug errors, extra precaution should occur to test is the log functions themselves generate any error.

Check the return value of vsnprintf(), time(), localtime(), printf() for potential errors.

In other words, assume when printing error messages, the system itself in on thin ice.

No color

Consider a global flag to print/not print the ANSI color sequences.

Missing include

#include <stdarg.h>

log.h first, guards

For log.c, consider first including log.h before <> includes to test that log.h compiles on its own without additional includes.

I expected the idiomatic include guard in log.h.

Sample

Sample code to fold in the 4 functions. See Pass va_list or pointer to va_list?.

#include <stdbool.h>
#include <stdarg.h>
#include <stdio.h>
#include <time.h>

bool time_prefix = false;

void log_general(bool time_prefix, const char *color, const char *name,
    const char *format_string, va_list *arg) {
  va_list argCopy;
  va_copy(argCopy, *arg);
  int len = vsnprintf(NULL, 0, format_string, argCopy);
  va_end(argCopy);
  if (len < 0) {
    return;
  }
  char buf[len + 1];
  len = vsnprintf(buf, sizeof buf, format_string, *arg);
  if (len < 0) {
    return;
  }
  if (time_prefix) {
    time_t t = time(NULL);
    if (t == -1) {
      return;
    }
    struct tm *tm = localtime(&t);
    if (tm == NULL) {
      return;
    }
    printf("%02d:%02d:%02d ", tm->tm_hour, tm->tm_min, tm->tm_sec);
  }
  printf("\033[0m\033[%sm[%s]\033[0m %s\n", color, name, buf);
}


void log_warning(const char *format_string, ...) {
  va_list args1;
  va_start(args1, format_string);
  log_general(time_prefix, "1;33", "WARN", format_string, &args1);
  va_end(args1);
  fflush(stdout);
}

void log_info(const char *format_string, ...) {
  va_list args1;
  va_start(args1, format_string);
  log_general(time_prefix, "1;34", "INFO", format_string, &args1);
  va_end(args1);
  // fflush(stdout); // No need for flush info messages.
}

int main() {
  time_prefix = true;
  log_warning("%d", 123);
  log_info("%f", 123.0);
}

Answer 2

Yes, there is a plenty of redundancy here. Let's start with if (time_prefix) part. Consider

    if (time_prefix) {
        printf("%d:%d:%d ", tm.tm_hour, tm.tm_min, tm.tm_sec);
    }
    printf("\033[0m\033[1;34m[INFO]\033[0m %s", buf);

Next step is to unify INFO, WARNING, ERROR, SUCCESS. All of them are identical, except the coloured prefix. Factor out the functionality, and pass the prefix down, e.g.

 void log_info(char* format_string, ...)
 {
     va_list args;
     va_start(args, format_string);
     do_log(INFO_PREFIX, format_string, args);
 }

etc, with

void do_log(char prefix, char format_string, va_list args)
{
    if (time_prefix) {
        printf("%d:%d:%d ", tm.tm_hour, tm.tm_min, tm.tm_sec);
    }
    printf("\033[0m\033[1;34m[INFO]\033[0m %s", buf);
    
    char buf[1 + vsnprintf(NULL, 0, format_string, args)];
    vsnprintf(buf, sizeof buf, format_string, args);
    va_end(args);
}

It is worth noticing that neither of your functions invoke va_arg(). It means that from the function standpoint va_list never changes. va_copy is not necessary.

Answer 3

Output stream is not necessarily a terminal, and even if it is, it's not necessarily an ANSI terminal.

Hard-coding those terminal control sequences makes it harder to process the output with other tools such as grep.

Libraries such as termcap exist to abstract the handling of terminal escapes, so that your program adapts to what it's connected to.