C Logging Function

Question

I wrote this log function and it works but is there a better way to write into the file stream and console at the same time?

//The function
void log(int lvl, const char * format, ...) {
 va_list args;
 va_start(args, format);
 //If lvl < 0 the prefix will not be used
 if (lvl>=lINFO) {
 time_t now = time(NULL);
 struct tm tm = *localtime(&now);
 //Printing to the console
 printf("[%d-%02d-%02d %02d:%02d:%02d %s] [%s] : ",
 tm.tm_year+1900,
 tm.tm_mon+1,
 tm.tm_mday,
 tm.tm_hour,
 tm.tm_min,
 tm.tm_sec,
 __log_name,
 parse_lvl(lvl)
 );
 //Printing into the file
 //Checking if NULL(if yes the file wont be used)
 if(__log_filestream)
 fprintf(__log_filestream,
 "[%d-%02d-%02d %02d:%02d:%02d %s] [%s] : ",
 tm.tm_year+1900,
 tm.tm_mon+1,
 tm.tm_mday,
 tm.tm_hour,
 tm.tm_min,
 tm.tm_sec,
 __log_name,
 parse_lvl(lvl)
 );
 }
 //Printing to the console
 vprintf(format, args);
 printf("\n");
 //Printing into the file
 if (__log_filestream) {
 vfprintf(__log_filestream, format, args);
 fprintf(__log_filestream, "\n");
 }
 va_end(args);
}
```

Answer 1

You're doing printf and fprintf twice for the same arguments.

So, it's replicating code.

*printf is somewhat heavyweight. So, I'd do sprintf [or snprintf] to a buffer (e.g):

len = sprintf(buf,...);

And then do:

fwrite(buf,1,len,stdout);
if (__log_filestream)
 fwrite(buf,1,len,__log_filestream);

The overhead of using the buffer is less than calling a printf function twice. I'd repeat the same buffering for the vprintf/vfprintf

---

Or, better yet, just keep concatenating to the buffer and do a single [pair of] fwrite at the end. This is [yet] better performance.

And, this is especially helpful if there are multiple threads doing logging because the given log message will come out on a single line (e.g.):

threadA timestamp | threadA message
threadB timestamp | threadB message

With two separate writes to a stream, two threads could intersperse partial parts of their message [not nearly as nice]:

threadA timestamp
threadB timestamp
threadA message
threadB message

Note that this is enough to guarantee that we see nice/whole lines. But, it doesn't prevent a race for the ordering of two lines for each stream. That is, we could have [on stdout]:

threadA line
threadB line

But, it might not prevent [on the logfile stream]:

threadB line
threadA line

So, we could wrap the fwrite calls in a mutex. Or, we could just wrap the calls in a flockfile(stdout) / funlockfile(stdout) pairing (See: FORCE_SEQUENTIAL in the example below)

---

If this function is the only function writing to the logfile and/or stdout, you might get even better performance by using write instead of fwrite [YMMV]

---

Here's how I would refactor the code [and, if you're paranoid, you could use snprintf]:

// The function
void
log(int lvl,const char *format,...)
{
 va_list args;
 char buf[1000];
 char *cur = buf;
 // If lvl < 0 the prefix will not be used
 if (lvl >= lINFO) {
 time_t now = time(NULL);
 struct tm tm;
 localtime_r(&now,&tm);
 // Printing to the console
 cur += sprintf(cur,"[%d-%02d-%02d %02d:%02d:%02d %s] [%s] : ",
 tm.tm_year + 1900,tm.tm_mon + 1,tm.tm_mday,
 tm.tm_hour,tm.tm_min,tm.tm_sec,
 __log_name,parse_lvl(lvl));
 }
 va_start(args, format);
 cur += sprintf(cur,format,args);
 va_end(args);
 *cur++ = '\n';
 *cur = 0;
 size_t len = cur - buf;
 // lock [either] stream to force both streams to come out "atomically" in
 // the same order
#ifdef FORCE_SEQUENTIAL
 flockfile(stdout);
#endif
 // Printing to the console
 fwrite(buf,1,len,stdout);
 // Printing into the file
 if (__log_filestream)
 fwrite(buf,1,len,__log_filestream);
#ifdef FORCE_SEQUENTIAL
 funlockfile(stdout);
#endif
}

Answer 2

Time detail

When the clock goes from daylight savings time to standard time, the below code can print the same time that was reported one hour earlier.

//Printing to the console
printf("[%d-%02d-%02d %02d:%02d:%02d %s] [%s] : ",
 tm.tm_year+1900,
 tm.tm_mon+1,
 tm.tm_mday,
 tm.tm_hour,
 tm.tm_min,
 tm.tm_sec,
 __log_name,
 parse_lvl(lvl)
);

To help distinguish times, consider printing tm.tm_isdst.

Alternatively, research strftime() and IS0 8601.

char buf[100];
strftime(buf, sizeof buf, "%FT%T%Z", &tm);
printf("[%s %s] [%s] : ", buf, __log_name, parse_lvl(lvl));

---

Or use UTC and skip timezones

time_t now = time(NULL);
struct tm tm = *gmtime(&now);
char buf[100];
strftime(buf, sizeof buf, "%FT%TZ", &tm);
printf("[%s %s] [%s] : ", buf, __log_name, parse_lvl(lvl));

Answer 3

API

You only provide one function, but it seems worthwhile documenting the expectations:

• log(level, format, ...)
• level appears to expect a set of pre-defined values, notably lINFO. Is there an enum somewhere? Should the type of level by an enum typedef?
• format should not include a trailing newline

Implementation

Comments

Your comments seem to indicate the code you wish you had written. Perhaps you should trust your instincts?

In general, comments that describe what is happening are bad comments: the code describes what is happening! These types of comments only serve to drift slowly out of date, forgetting to mention things that are added later. Eventually, they turn into a sort of dotty grandmother, who remembers what you were like at version 1, but doesn't remember that you're integrated with another package now, with one major plugin already and a new one on the way...

Instead, write comments to draw attention to things that might be non-obvious, or to highlight negative information (Negative as in "the dog that didn't bark", like the default in a switch statement except at a higher level).

Organization

I meant it when I said you should trust your instincts! If you're writing a comment to give a name to more than one line of code, maybe that code is a function.

(And dundernames*, like __log_filestream, are reserved. Don't use them.)

void log ... etc ...
{
 if (level >= lINFO) {
 time_t now = time(NULL);
 struct tm tm = *localtime(&now);
 log_prefix_to_stream(stdout, lvl, &tm);
 log_prefix_to_stream(log_filestream, lvl, &tm);
 }
 va_list args;
 va_start(args, format);
 log_vprint_to_stream(lvl, format, args, stdout);
 log_vprint_to_stream(lvl, format, args, log_filestream);
 va_end(args);
}

And seeing that refactoring puts two things in my head: first, that the prefix should probably be a function by itself, and second that the doubled printing lines could probably go into a single function, if only we were smart enough!

Something like this:

void log ... etc ...
{
 if (lvl >= lINFO) 
 log_prefix(lvl);
 va_list args;
 va_start(args, format);
 log_vprintf(format, args);
 log_append_newline();
 va_end(args);
}

Which then leads to log_prefix wanting to call log_vprint, but needing an intermediate function to make a va_list:

void log_printf(format, ...);

Which might call log_vprintf, in the interest of DRY, and we've found the missing if statement(s)!

void log_vprintf(format, args)
{
 if (log_filestream != NULL)
 vfprintf(log_filestream, format, args);
 vfprintf(stdout, format, args);
}

=====

(*): "dundernames" are double-underscore-names -- that is, names that start with '__'