1

I have a function log_info (copied from printf's implementation) that accepts variable no. of arguments and passes it to vprintf:

int log_info(const char *format, ...) {
  va_list arg;
  int done;

  va_start (arg, format);
  done = vfprintf (stdout, format, arg);
  va_end (arg);

  return done;
}

I want to prepend and append strings to these arguments. So if a user calls the above function this way:

log_info("at iteration %d, float value is %f", i, f);

instead of printing

at iteration 4, float value is 102.34

I want to print

[INFO] [at iteration 4, float value is 102.34] [timestamp: xxxx]

I could do it in 3 separate steps

fprintf(stdout, "[INFO] [");
vprintf(stdout, format, arg);
fprintf(stdout, "] [timestamp:%f]", ts);

But the program is multi-threaded, and hence I want all data to be written in a single call to vprintf (vprintf being thread-safe).

The other option is to lock a mutex and then write it in 3 steps as shown above, but if appending strings to the args is not too complex, I would like to try that.

Edit: Performance overhead due to use of mutex is not really an issue, but I dont want to use one unless necessary.

Thanks in advance

Korizon
  • 3,677
  • 7
  • 37
  • 52

2 Answers2

5

You want to add new fields to the output, so just construct a new format string.

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

int loginfo(const char *format, ...) {
    int ret;
    int len;
    va_list ap;
    char *new_fmt;
    char *timestamp;
    const char fmt_template[] = "[INFO] [%s] [timestamp: %s]";

    /* Grab the timestamp now, since if we call it twice, it may change in length */
    timestamp = get_time_string();

    /* Calculate length for the augmented format string and allocate. */
    len = snprintf(NULL, 0, fmt_template, format, timestamp);
    new_fmt = malloc(len + 1);

    /* Construct the new format string */
    snprintf(new_fmt, len + 1, fmt_template, format, timestamp);

    /* Print as before, using new format string */
    va_start (ap, format);
    ret = vfprintf (stdout, new_fmt, ap);
    va_end (ap);

    free(new_fmt);
    return ret;
}
jared_schmitz
  • 583
  • 2
  • 10
  • Thanks. One question: why do you need `va_list ap` ? – Korizon Dec 10 '13 at 19:56
  • I was keeping with C89 by declaring it at the beginning of the block. I've made the code sample complete for clarity. – jared_schmitz Dec 10 '13 at 20:02
  • I am not happy with `malloc (strlen(format) + METADATA_CHARS`. It cannot give the correct length. I think I will have to use `len = vsnprintf(NULL, 0, format, arg);` – Korizon Dec 10 '13 at 20:27
  • Assuming the timestamp is a fixed length (e.g. hh:mm:ss), then you simply have to determine the proper value for METADATA_CHARS. If it's likely to change or can't be determined, I would use `vsnprintf`. Be aware that the MSVC implementation has non-standard semantics, and returns -1 instead of the needed number of bytes if there is truncation. – jared_schmitz Dec 10 '13 at 20:32
  • 1
    Copying it to another va_list and then calculating the len sounds like a more correct way – Korizon Dec 10 '13 at 20:36
  • if you would be kind enough to edit to add va_copy and len calculation, i can accept it as an answer – Korizon Dec 10 '13 at 21:22
  • @KVM: The arguments are only iterated over once. The length is calculated for the format string, not the entire output, so we just need the prepended and appended strings. Edited now. – jared_schmitz Dec 10 '13 at 22:05
  • Since your `get_time_string();` function seems to return an heap allocated string, you also must free it at the end of `loginfo()`. – rumpelsepp Jun 13 '17 at 13:00
3

One approach is to use vsnprintf to write the original message to a (dynamically allocated) string. Then use fprintf to output the metadata plus original message:

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

static const char * get_timestamp_str()
{
    ...
}

static void Log(const char *format, ...)
{
    va_list arg;
    int len;
    char * orig_msg;

    /* Compute length of original message */
    va_start(arg, format);
    len = vsnprintf(NULL, 0, format, arg);
    va_end(arg);

    /* Allocate space for original message */
    orig_msg = (char *)calloc(len+1, sizeof(char));

    /* Write original message to string */
    va_start(arg, format);
    vsnprintf(orig_msg, len+1, format, arg);
    va_end(arg);

    /* Write metadata plus original message to stderr */
    fprintf(stderr, "[INFO] [timestamp %s] %s\n", get_timestamp_str(), orig_msg);
    free(orig_msg);
}
Greg Prisament
  • 2,166
  • 1
  • 17
  • 18
  • Good catch @Devolus, I've added the `free` now. – Greg Prisament Dec 10 '13 at 19:18
  • `vsnprintf` will consume `arg`, so `va_copy` should be used to copy it to a second va_list before the call. – jared_schmitz Dec 10 '13 at 19:24
  • @jared_schmitz: The second va_start will re-initialize arg, correct? – Greg Prisament Dec 10 '13 at 19:26
  • @GregPrisament: No. It probably will on most major systems. See this question: http://stackoverflow.com/questions/9309246/repeated-use-of-a-variadic-function-argument-doesnt-work – jared_schmitz Dec 10 '13 at 19:39
  • 1
    @jared_schmitz: Beg to differ. The man page for "va_end" states: "Each invocation of va_start() must be matched by a corresponding invocation of va_end() in the same function. After the call va_end(ap) the variable ap is undefined. Multiple traversals of the list, each bracketed by va_start() and va_end() are possible." – Greg Prisament Dec 10 '13 at 19:47
  • @jared_schmitz: Makes me wonder what's going on in that question you linked to... – Greg Prisament Dec 10 '13 at 19:52