13
\$\begingroup\$

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;
}
\$\endgroup\$
1
  • 1
    \$\begingroup\$ Logger modules are like compilers. You should definitively write one to get the satisfaction and the experience to appreciate and then use what others have done. \$\endgroup\$ Commented Nov 17, 2020 at 11:45

3 Answers 3

Reset to default
11
\$\begingroup\$

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);
}
\$\endgroup\$
11
  • 1
    \$\begingroup\$ The whole ANSI color sequences deserves abstraction. Perhaps later. \$\endgroup\$ Commented Nov 17, 2020 at 2:39
  • 1
    \$\begingroup\$ @766F6964 Certainly it is related to passing args1. Will review later. I can not see the .png right now. Hopefully it shows your code and what compiler/options you used. If not, is the code exactly as posted here? What compiler/options used? \$\endgroup\$ Commented Nov 17, 2020 at 14:43
  • 1
    \$\begingroup\$ The compiler options are the default ones of gcc. Essentially just running gcc -o logger logger.c. I was also able to reproduce the same problem on a different machine (Ubuntu VM). The code is exactly yours, 1:1. I'll play around with some more compiler options and see if that helps to pinpoint the problem. \$\endgroup\$ Commented Nov 17, 2020 at 14:50
  • 1
    \$\begingroup\$ @766F6964 1) I am confident that some form of va_..., vsprintf() will work where the lion share of code is in log_general(). 2) I, so far, failed to reproduce your failing output 3) As answered "va_list parameter is tricky" It is easy to post something that "works", yet not portable. 4) log_general() may need to use va_copy(). See posted alternate code - both work for me. \$\endgroup\$ Commented Nov 18, 2020 at 11:51
  • 1
    \$\begingroup\$ @766F6964 On review, I am more certain that my initial lack of va_copy with a 2nd vsnprintf() call is the oops. va_copy appears necessary. What are your results? \$\endgroup\$ Commented Nov 18, 2020 at 12:02
5
\$\begingroup\$

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.

\$\endgroup\$
4
\$\begingroup\$

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.

\$\endgroup\$
2
  • \$\begingroup\$ Thanks for the suggestion. I am a bit hesitant to add another dependency. What is the advantage of termcap of, say, storing all the color-bound escape sequences in an array? \$\endgroup\$ Commented Nov 17, 2020 at 14:58
  • \$\begingroup\$ The main advantage is that all the work of identifying different terminals and recording the necessary control sequences for each one (and keeping all the data updated) is already done for you. Like most libraries, it saves a lot of developer time. \$\endgroup\$ Commented Nov 17, 2020 at 15:19

You must log in to answer this question.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.