# C Logging Function

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);
}

$$$$


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


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

threadA timestamp


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


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

threadB 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
}


# 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

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 '__'

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));
`