Logger using variadic macros

Question

I'm getting back into C and I wrote this variadic logger as part of a chess application I'm writing. As such I'm looking for feedback about the general approach (I'm going to give it another pass to catch any possible errors, edge cases etc... later on). Mainly I'm concerned with side effects and trade-offs that I may not be aware of by using a solution like this.

The goal is to have a relatively portable, easy to use, and safe (as far as you can go without type checking) logger, that behaves like printf() but with some extra options.

So with all of that being said, please tell me why this is probably a bad idea in some shape or form.

Is variadic logging in C a sensible thing to do?

log.h

#ifndef CHX_LOG_H
#define CHX_LOG_H

typedef enum
{
    CHX_LOG_DEBUG,
    CHX_LOG_INFO,
    CHX_LOG_WARNING,
    CHX_LOG_ERROR,
    CHX_LOG_SILENT,
}chx_log_lvl;

typedef enum
{
    CHX_TAG_CLI,
    CHX_TAG_CORE,
    CHX_TAG_ERRORS,
}chx_tag;

#define CHX_LOG_ENABLED
#ifdef CHX_LOG_ENABLED

void chx_log(chx_log_lvl lvl, chx_tag tag, char* msg_tmpl, ...);

#define CHX_LOG(...) chx_log(__VA_ARGS__)
#define CHX_LOG_DEBUG(...) chx_log (CHX_LOG_DEBUG, __VA_ARGS__)
#define CHX_LOG_INFO(...) chx_log (CHX_LOG_INFO, __VA_ARGS__)
#define CHX_LOG_WARNING(...) chx_log (CHX_LOG_WARNING, __VA_ARGS__)
#define CHX_LOG_ERROR(...) chx_log (CHX_LOG_ERROR, __VA_ARGS__)

#else
#define CHX_LOG(...)
#define CHX_LOG_DEBUG(...)
#define CHX_LOG_INFO(...)
#define CHX_LOG_WARNING(...)
#define CHX_LOG_ERROR(...)
#endif

#endif

log.c

#include "log.h"
#include <stdarg.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>

#ifdef CHX_LOG_ENABLED
void chx_log(chx_log_lvl lvl, chx_tag tag, char* msg_tmpl, ...)
{
    va_list msg_args;
    va_start(msg_args, msg_tmpl);
    char *chx_msg;
    if(vasprintf(&chx_msg, msg_tmpl, msg_args) == -1)
    {
            printf("Error formatting log... %s\n", msg_tmpl);
            exit(1);
    }
    va_end(msg_args);
    printf("%s", chx_msg);
    free(chx_msg);
}
#endif

---

Usage:

CHX_LOG_DEBUG(CHX_TAG_CLI, "cli_args:\n --player_side: %d\n --depth: %d\n --fen_path %s\n",
        cli_opts.player_side, cli_opts.depth, cli_opts.fen_path);

Answer 1

Reinventing the wheel

I have to do a big project. Let's start by rolling a logger. Bad idea, procrastination, there are plenty of loggers available. Also this is not so well suited for learning as having a look at other loggers will teach you more efficiently.

Non-standard concepts

Your "tag" is somewhat special. While the values "client" and "core" resemble what other loggers implement as "logger" or "logger_name", the value "error" on the other hand sounds much like log level. Currently the tag is ignored, indicating it is not required. Be careful not to add stuff which turns out to be useless or badly designed. I especially doubt the type. A generic string might be more useful (logger name, context, ...).

Log macros

Macros like LOG_DEBUG(...) are used by other loggers as well, but why? You use macros only for switching off logging completely during compile time. Something you usually do not want to do in a real project (maybe in a library). The real advantages of log macros are

• you have access to predefined macros __FILE__, __LINE__
• you may dynamically check the log level and avoid potentially costly parameter evaluations and the subsequent function call completely

Pass file name and line number to your logger and implement a level check within the macro.

Other stuff

• The big #ifdef clause in the c-file is strange. Either do not include the file in your project or leave it to the linker to remove unreferenced code.
• exit(1) - libraries exiting a program - usually a bad idea. Killing a mission critical program because of a null pointer passed. Print/log the problem, but do not exit.

Answer 2

Is variadic logging in C a sensible thing to do?

Yes.

IMO, the logging length should have a length limit, say 256?
A log is not a place to dump a tome. Since sample code uses "%s", long dumps are possible and of questionable value. We do not want logging to get in the way of normal program flow.

---

... goal is to have a relatively portable

vasprintf() is not part of the standard C library

I reviewed vasprintf() and find it troubling with its "If memory allocation wasn't possible, or some other error occurs, these functions will return -1, and the contents of strp is undefined." This allows for memory leaks as it is unclear if free(*strp) should happened.

Instead, consider alternatives.

• One issue I have with ... logging is the potential for a long entry. The whole nature of logging is close to error handling and I prefer to avoid allocating during errors.
• Impose a sane limit of log length - perhaps system 256 or BUFSIZ?
• Use a const format.
• Add sentinel characters to strings for clarity.
• Be sure to flush if logging relates to an error. We definitely want to see this one.
• System errors deserve to go out on stderr.

To that end, perhaps:

void chx_log_alt(chx_log_lvl lvl, chx_tag tag, const char* msg_tmpl, ...) {
  va_list msg_args;
  va_start(msg_args, msg_tmpl);
  char chx_msg[BUFSIZ];
  if (vsnprintf(chx_msg, BUFSIZ, msg_tmpl, msg_args) < 0) {
    fprintf(stderr, "Error formatting log... \"%s\"\n", msg_tmpl);
    exit(EXIT_FAILURE);
  }
  va_end(msg_args);
  printf("%s", chx_msg);
  if (lvl == CHX_LOG_ERROR) {
    fflush(stdout);
  }
}

vsnprintf() is part of the standard library.

Source

Consider adding into the CHX_LOG_... macros the caller's function name and maybe line number via __func__, __LINE__.