How to log?

S

syncman

In C, I would always make a log() function instead of using printfs,
so that I could disable the messages or otherwise process them, all in
one place. This worked in 1 line, for constant strings, but not for
variable values, as in:
char s[99];
sprintf (s, "The value is %d \n", value);
log (s); // 3 lines!!

In C++, is it really as bad as it was? If I use streams:
ostringstream oss;
oss << "The value is " << value << endl;
log (oss.str());
No better!

I suspect the answer might be to use clog:
clog << "The value is " << value << endl;
But I don't see any place where I can later customize or disable.
(I read that clog is the same as cerr, but clog is buffered.)

So, how do people log?
 
R

Ron Natalie

syncman said:
In C, I would always make a log() function instead of using printfs,

So, how do people log?

We have our own function called
LogPrintf
And our own stream called
LogOut

Based on the programmers inclination, he can either use either one.
 
G

Gianni Mariani

syncman said:
In C, I would always make a log() function instead of using printfs,
so that I could disable the messages or otherwise process them, all in
one place. This worked in 1 line, for constant strings, but not for
variable values, as in:
char s[99];
sprintf (s, "The value is %d \n", value);
log (s); // 3 lines!!

In C++, is it really as bad as it was? If I use streams:
ostringstream oss;
oss << "The value is " << value << endl;
log (oss.str());
No better!

I suspect the answer might be to use clog:
clog << "The value is " << value << endl;
But I don't see any place where I can later customize or disable.
(I read that clog is the same as cerr, but clog is buffered.)

So, how do people log?

I've used a scheme like this one in the past. The actual logging class
was far more flexible than the one below but this example gives you an idea.

The interface is through the macro "LOG" and you pass it a logging level
and a title. The actual levels should be an enum but I just used an int
here for sake of simplicity (in a real system I would use mask).

LOG creates an object named "lout" which upon destruction will output
the log string.

i.e.

LOG( ERROR_LEVEL, "This is an error log" );

of

LOG( WARNING_LEVEL, "This is a warning" )
{
lout.attr( "oil_level" ) << oil_level << " is too low";
} // <<< message string is sent here

If logging is not enabled, no messages are created at all.

If you set the WARNING_LEVEL value to 0, the compiler will eliminate the
warning level logging code entirely.

THE one and only problem I've seen with this technique is that
occationally someone misses the ";" at the end and when logging is
turned on, the code works and when it is not it fails .... cute

I toyed with changing the interface to:

LOG( LOG_LEVEL, "Title" ) END_LOG

to eliminate this possibility of this kind of error but I'm still not
sure it's the best answer. Simplicity is better.

..... here is an example ....

#include <sstream>
#include <iostream>

#define LOG( LEVEL, TITLE ) \
if ( int x_level = (LEVEL) ) \
if ( Logger lout = x_level ) \
if ( lout.Title(TITLE) )
// end

struct LoggerContext
{
std::eek:stringstream m_oss;
int m_level;
mutable int m_count;

LoggerContext( int l_level )
: m_level( l_level ),
m_count( 1 )
{
}

};

struct Logger
{
LoggerContext * m_context;

static int min_level;

Logger( int l_level )
: m_context( l_level >= min_level ? new LoggerContext( l_level )
: 0 )
{
}

bool Title( const char * l_title )
{
m_context->m_oss << l_title << " : ";
return m_context;
}

template <typename T>
Logger & operator << ( const T & value )
{
m_context->m_oss << value;
return * this;
}

Logger & attr( const char * s_attr )
{
m_context->m_oss << " " << s_attr << " = ";
return * this;
}

~Logger()
{
if ( m_context )
{
-- m_context->m_count;
if ( m_context->m_count == 0 )
{
m_context->m_oss << "\n";
/// write log here
std::cout << m_context->m_oss.str();
delete m_context;
}
}
}

operator bool()
{
return m_context;
}

Logger( const Logger & l_rhs )
: m_context( l_rhs.getref() )
{
}

LoggerContext * getref() const
{
++ ( m_context->m_count );
return m_context;
}


};


int Logger::min_level = 2;


int main()
{
LOG( 3, "Thing 1" );

LOG( 4, "Thing 2" )
{
lout << "Really " << 33;
lout.attr( "Some value" ) << "54";
lout.attr( "Some other value" ) << 99.33;
}

LOG( 1, "Thing 3" )
{
lout << "Not really";
}

}
 
C

Chrisw

Gianni Mariani said:
syncman said:
In C, I would always make a log() function instead of using printfs,
so that I could disable the messages or otherwise process them, all in
one place. This worked in 1 line, for constant strings, but not for
variable values, as in:
char s[99];
sprintf (s, "The value is %d \n", value);
log (s); // 3 lines!!

In C++, is it really as bad as it was? If I use streams:
ostringstream oss;
oss << "The value is " << value << endl;
log (oss.str());
No better!

I suspect the answer might be to use clog:
clog << "The value is " << value << endl;
But I don't see any place where I can later customize or disable.
(I read that clog is the same as cerr, but clog is buffered.)

So, how do people log?

I've used a scheme like this one in the past. The actual logging class
was far more flexible than the one below but this example gives you an idea.

The interface is through the macro "LOG" and you pass it a logging level
and a title. The actual levels should be an enum but I just used an int
here for sake of simplicity (in a real system I would use mask).

LOG creates an object named "lout" which upon destruction will output
the log string.

i.e.

LOG( ERROR_LEVEL, "This is an error log" );

of

LOG( WARNING_LEVEL, "This is a warning" )
{
lout.attr( "oil_level" ) << oil_level << " is too low";
} // <<< message string is sent here

If logging is not enabled, no messages are created at all.

If you set the WARNING_LEVEL value to 0, the compiler will eliminate the
warning level logging code entirely.

THE one and only problem I've seen with this technique is that
occationally someone misses the ";" at the end and when logging is
turned on, the code works and when it is not it fails .... cute

I toyed with changing the interface to:

LOG( LOG_LEVEL, "Title" ) END_LOG

to eliminate this possibility of this kind of error but I'm still not
sure it's the best answer. Simplicity is better.

.... here is an example ....

#include <sstream>
#include <iostream>

#define LOG( LEVEL, TITLE ) \
if ( int x_level = (LEVEL) ) \
if ( Logger lout = x_level ) \
if ( lout.Title(TITLE) )
// end

struct LoggerContext
{
std::eek:stringstream m_oss;
int m_level;
mutable int m_count;

LoggerContext( int l_level )
: m_level( l_level ),
m_count( 1 )
{
}

};

struct Logger
{
LoggerContext * m_context;

static int min_level;

Logger( int l_level )
: m_context( l_level >= min_level ? new LoggerContext( l_level )
: 0 )
{
}

bool Title( const char * l_title )
{
m_context->m_oss << l_title << " : ";
return m_context;
}

template <typename T>
Logger & operator << ( const T & value )
{
m_context->m_oss << value;
return * this;
}

Logger & attr( const char * s_attr )
{
m_context->m_oss << " " << s_attr << " = ";
return * this;
}

~Logger()
{
if ( m_context )
{
-- m_context->m_count;
if ( m_context->m_count == 0 )
{
m_context->m_oss << "\n";
/// write log here
std::cout << m_context->m_oss.str();
delete m_context;
}
}
}

operator bool()
{
return m_context;
}

Logger( const Logger & l_rhs )
: m_context( l_rhs.getref() )
{
}

LoggerContext * getref() const
{
++ ( m_context->m_count );
return m_context;
}


};


int Logger::min_level = 2;


int main()
{
LOG( 3, "Thing 1" );

LOG( 4, "Thing 2" )
{
lout << "Really " << 33;
lout.attr( "Some value" ) << "54";
lout.attr( "Some other value" ) << 99.33;
}

LOG( 1, "Thing 3" )
{
lout << "Not really";
}

}

all you have to do is somehting like this:

// log.h
#ifdef LOG_ON
#define LOGNAME "debuglog.txt"
#define LOG( _S_) { lstream << _S_; }
extern std::eek:fstream lstream;
#else
#define LOG( _S_)
#endif

//////////////////
// log.cpp
#include "log.h"
#ifdef LOG_ON
#include <fstream>
std::eek:fstream lstream( LOGNAME );
#endif


// somefile.cpp
#include "log.h"
void func( int n )
{
LOG( "func called with " << n << std::endl );
}


all you have to do to turn logging on/ off is define ( or not, to turn off
logging ) LOG_ON

-Chris
 
J

Jarmo

syncman said:
In C, I would always make a log() function instead of using printfs,
so that I could disable the messages or otherwise process them, all in
one place. This worked in 1 line, for constant strings, but not for
variable values, as in:
char s[99];
sprintf (s, "The value is %d \n", value);
log (s); // 3 lines!!

In C++, is it really as bad as it was? If I use streams:
ostringstream oss;
oss << "The value is " << value << endl;
log (oss.str());
No better!

I suspect the answer might be to use clog:
clog << "The value is " << value << endl;
But I don't see any place where I can later customize or disable.
(I read that clog is the same as cerr, but clog is buffered.)

So, how do people log?

Here's an idea in C that makes use of a slightly sneaky preprocessor
feature. No doubt could be made a lot better for C++.

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

#if defined(DEBUG)
#define TRACE(X) tracefunc X
#else
#define TRACE (void)
#endif

#if defined(DEBUG)
static void tracefunc(char *format, ...)
{
va_list marker;
static FILE *fp = NULL;

if (!fp)
{
fp = fopen("tracef.trc", "w+t"); // open
}

if (fp)
{
va_start(marker, format);
vfprintf(fp, format, marker);
va_end(marker);
fputc('\n', fp);
fflush(fp);
}
}
#endif

void main(void)
{
int a = 1;
char *b = "BBBB";

TRACE(("a=%d, b=%s", a, b));
TRACE(("b=%s, a=%d", b, a));
}
 
G

Gianni Mariani

Chrisw wrote:
....
all you have to do is somehting like this:

// log.h
#ifdef LOG_ON
#define LOGNAME "debuglog.txt"
#define LOG( _S_) { lstream << _S_; }
extern std::eek:fstream lstream;
#else
#define LOG( _S_)
#endif

//////////////////
// log.cpp
#include "log.h"
#ifdef LOG_ON
#include <fstream>
std::eek:fstream lstream( LOGNAME );
#endif


// somefile.cpp
#include "log.h"
void func( int n )
{
LOG( "func called with " << n << std::endl );
}


all you have to do to turn logging on/ off is define ( or not, to turn off
logging ) LOG_ON

That's neat but:

a) I want all the code compiled all the time - this reduces errors from
conditionally compiled code. You could fix that here by placing an "if"
around the {}.

b) Logging can become intermixed if the logging itself causes logging to
be used. This also happens when multiple threads are used. I suspect
you could easily fix the macro to do that too.

c) Often what you need to log is more complex than just a message with
fixed parameters

LOG( INFORM_LEVEL, "Attribute dump" )
{
for ( attr_iter = attrs.begin(); ....
lout.attr( *attr.name ) << *attr.value ;
etc...

You could do somthing like:

LOG(
"Log title";
for ( int i = 0; i < 10; i ++ ) {
lstream << i;
}
)

However, now you can't use the operator ,() because the
preprocessor won't know what you mean.
 
T

The Directive

[Snipped]
#include <stdio.h>
#include <stdarg.h>

#if defined(DEBUG)
#define TRACE(X) tracefunc X
#else
#define TRACE (void)

Why not #define TRACE(X) to nothing, why "(void)"?

#define TRACE(X)

--The Directive
 
G

Gianni Mariani

Jarmo said:
In C, I would always make a log() function instead of using printfs,
so that I could disable the messages or otherwise process them, all in
one place. This worked in 1 line, for constant strings, but not for
variable values, as in:
char s[99];
sprintf (s, "The value is %d \n", value);
log (s); // 3 lines!!

In C++, is it really as bad as it was? If I use streams:
ostringstream oss;
oss << "The value is " << value << endl;
log (oss.str());
No better!

I suspect the answer might be to use clog:
clog << "The value is " << value << endl;
But I don't see any place where I can later customize or disable.
(I read that clog is the same as cerr, but clog is buffered.)

So, how do people log?


Here's an idea in C that makes use of a slightly sneaky preprocessor
feature. No doubt could be made a lot better for C++.

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

#if defined(DEBUG)
#define TRACE(X) tracefunc X
#else
#define TRACE (void)
#endif

One of *my* biggest issues with conditional complication is that
compiling code conditionally often introduces undetected compilation errors.

#if defined(DEBUG)
#define DOING_DEBUG true
#else
#define DOING_DEBUG false
#endif

#define TRACE(X) if (DOING_DEBUG) { tracefunc X; }

I'd also like to be able to change the behaviour at run time and have
different "levels" of debugging .... but that's another story.
 
J

Jorge Rivera

There is a very powerful logging facility called log4cplus. It is a
logging framework for C++ very similar to log4j (for Java, of course).

It allows as simple or as complex logging as you want, and you can set
the logging level dynamically.

I suggest you give that a try, as it might be useful to reuse this
framework instead of having to always write your own custom logging
facilities.

Jorge L
 
J

Jarmo

The Directive said:
[Snipped]
#include <stdio.h>
#include <stdarg.h>

#if defined(DEBUG)
#define TRACE(X) tracefunc X
#else
#define TRACE (void)

Why not #define TRACE(X) to nothing, why "(void)"?

Good question. If I recall, it was intended to eliminate compiler warnings
on some cranky, old compilers.
 
J

Jarmo

Gianni Mariani said:
One of *my* biggest issues with conditional complication is that
compiling code conditionally often introduces undetected compilation
errors.

I'm not sure how a compilation error could be undetected, or do you mean a
programming error? Obviously, for performance and occupancy reasons, it's
very unusual for production code to include tracing so you do need some way
to build two versions (release & debug) from the same code.
 
G

Gianni Mariani

Jarmo said:
errors.

I'm not sure how a compilation error could be undetected, or do you mean a
programming error? Obviously, for performance and occupancy reasons, it's
very unusual for production code to include tracing so you do need some way
to build two versions (release & debug) from the same code.

This is a common problem with conditionally compiled code. Someone
updates an interface and breaks code that is not being compiled (because
of conditionally compiled elements) and someone else finds the problems
when they do compile those elements. One of the rules of good
programming is to find errors as soon as possible in the development cycle.

Code below is equivalent:


#if DO_STUFF

for ( .... lotsa code ... )
{
more code
}

#endif

.............. and ..........

if ( DO_STUFF )
for ( .... lotsa code ... )
{
more code
}


The code is essentially identical and if someone introduces an interface
issue in the "more code" section, it is found even if DO_STUFF is false
in the second version while not in the first.
 
J

Jarmo

Gianni Mariani said:
This is a common problem with conditionally compiled code. Someone
updates an interface and breaks code that is not being compiled (because
of conditionally compiled elements) and someone else finds the problems
when they do compile those elements. One of the rules of good
programming is to find errors as soon as possible in the development
cycle.

I think we're talking at cross-purposes. All I'm talking about here is
trace vs. non-trace, not about code that includes certain production
features depending upon how you compile it. There's no production code in
my conditional sections.
 
G

Gianni Mariani

Jarmo said:
cycle.

I think we're talking at cross-purposes. All I'm talking about here is
trace vs. non-trace, not about code that includes certain production
features depending upon how you compile it. There's no production code in
my conditional sections.

To eliminate the problem I mentioned above, the goal should be to
eliminate *ALL* conditionally compiled code. It is not allways possible
but these cases are rare. In other words, use constant if() expressions
instead of conditionally compiled code (separared in #if/#endif)
whenever possible as an alternative. This is regardless of
production/vs non production segments of the code.

In your example, why would you not want use the suggested alternative i.e.:

#if defined(DEBUG)
#define DOING_DEBUG true
#else
#define DOING_DEBUG false
#endif

#define TRACE(X) { if (DOING_DEBUG) { tracefunc X; } }
 
J

Jarmo

Gianni Mariani said:
In your example, why would you not want use the suggested alternative i.e.:

#if defined(DEBUG)
#define DOING_DEBUG true
#else
#define DOING_DEBUG false
#endif

#define TRACE(X) { if (DOING_DEBUG) { tracefunc X; } }

If the compiler completely optimizes out the TRACE code in the non-DEBUG
case, then that's fine. Otherwise the executable is larger than it has to
be, is slower to load, consumes more RAM, and conceivably suffers from at
least one unnecessary test for every single line of trace.
 
G

Gianni Mariani

Jarmo wrote:
....
If the compiler completely optimizes out the TRACE code in the non-DEBUG
case, then that's fine. Otherwise the executable is larger than it has to
be, is slower to load, consumes more RAM, and conceivably suffers from at
least one unnecessary test for every single line of trace.

Consider it a bug if a compiler does not eliminate dead code.
 
J

Jarmo

Gianni Mariani said:
Jarmo wrote:
...

Consider it a bug if a compiler does not eliminate dead code.

My regular (and reasonably up to date) win32 compiler produces executables
of identical size in both trace and non-trace mode with your method. With
my method they are different sizes (non-trace being smaller).

Also, and this is quite significant, the compiler generates numerous
"Condition is always true/false" warnings with your method (in both builds).

Now quite possibly I might find command line switches and/or pragmas for
this particular compiler that affect both of these (negative) outcomes but I
can pretty much guarantee that one cannot generally do so and hence any
attempt to write portable code for dozens of (old and new) compilers that
both compiles cleanly and is the optimal size probably cannot be done with
your method.
 
G

Gianni Mariani

Jarmo said:
My regular (and reasonably up to date) win32 compiler produces executables
of identical size in both trace and non-trace mode with your method. With
my method they are different sizes (non-trace being smaller).

I just tried VC++7.1 and gcc 3.3.1, both of them eliminated dead code
and the .o/.obj file contained none of the dead code.
Also, and this is quite significant, the compiler generates numerous
"Condition is always true/false" warnings with your method (in both builds).

Neither of the VC++7.1 or gcc 3.3.1 produced warnings.
Now quite possibly I might find command line switches and/or pragmas for
this particular compiler that affect both of these (negative) outcomes but I
can pretty much guarantee that one cannot generally do so and hence any
attempt to write portable code for dozens of (old and new) compilers that
both compiles cleanly and is the optimal size probably cannot be done with
your method.

Is the compiler broken ?

A size test with gcc gives:

DEBUG
- no-conditional code 3284 bytes (stripped)
- conditional code 3284 bytes (stripped)

NO DEBUG
- no-conditional code 2804 bytes (stripped)
- conditional code 2804 bytes (stripped) (has warnings)

i.e. identical results.

VC++7.1 gave identical sizes for all versions, however with disasssebly
listings it was obvious that the non conditional code example was
identical to the conditional code disassembly.

The code I used is below. Check it for yourself.
.............................................

#include <cstdio>
#include <cstdarg>

#if TEST1

#if defined(DEBUG)
#define TRACE(X) tracefunc X
#else
#define TRACE (void)

#endif

#else // TEST1

#if defined(DEBUG)
#define DOING_DEBUG 1
#else
#define DOING_DEBUG 0
#endif

#define TRACE(X) { if ( DOING_DEBUG ) { tracefunc X; } }

#endif // TEST1

#if defined(DEBUG)
namespace {

void tracefunc(char *format, ...)
{
va_list marker;
static FILE *fp = NULL;

if (!fp)
{
fp = fopen("tracef.trc", "w+t"); // open
}

if (fp)
{
va_start(marker, format);
vfprintf(fp, format, marker);
va_end(marker);
fputc('\n', fp);
fflush(fp);
}
}

};
#else
void tracefunc(char *format, ...);
#endif

int main(void)
{
int a = 1;
char *b = "BBBB";

TRACE(("a=%d, b=%s", a, b));
TRACE(("b=%s, a=%d", b, a));
}


Commands used :

setenv INL_CXXFLAGS "-DTEST1=1" ; rm deadcode2 ; m deadcode2 ; strip
deadcode2 ; ls -l deadcode2


setenv INL_CXXFLAGS "-DTEST1=1 -DDEBUG=1" ; rm deadcode2 ; m deadcode2 ;
strip deadcode2 ; ls -l deadcode2


setenv INL_CXXFLAGS "-DDEBUG=1" ; rm deadcode2 ; m deadcode2 ; strip
deadcode2 ; ls -l deadcode2


setenv INL_CXXFLAGS "" ; rm deadcode2 ; m deadcode2 ; strip deadcode2 ;
ls -l deadcode2
 
G

Graham Dumpleton

In C, I would always make a log() function instead of using printfs,
so that I could disable the messages or otherwise process them, all in
one place. This worked in 1 line, for constant strings, but not for
variable values, as in:
char s[99];
sprintf (s, "The value is %d \n", value);
log (s); // 3 lines!!

In C++, is it really as bad as it was? If I use streams:
ostringstream oss;
oss << "The value is " << value << endl;
log (oss.str());
No better!

I suspect the answer might be to use clog:
clog << "The value is " << value << endl;
But I don't see any place where I can later customize or disable.
(I read that clog is the same as cerr, but clog is buffered.)

So, how do people log?

Following is an exact cut and past of a response to a similar query not two
weeks ago. This sort of question about debugging macros etc, comes up
quite frequently yet I never tend to see anyone suggesting the following.


A better scheme is to harness the use of the C++ streams classes.

#ifdef DEBUG
#define tracer if (0) ; else cerr
#else
#define tracer if (1) ; else cerr
#endif

tracer << "something bad happened" << endl;

What is good about this is that you can format more than text strings, ie.,
anything which can be formatted into a stream. The code also looks more
natural as a result. And no the code will not be present when DEBUG isn't
defined as any sane compiler will realise the code in the else part can't
ever be called and leave it out.

For a look at a quite comprehensive debugging mechanism using these
concepts, look at the OSE library at "http://ose.sourceforge.net". There
is a chapter in the library manual on the program debugging support.
This might give you some ideas even if you want to stear clear of third
party libraries.
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Members online

No members online now.

Forum statistics

Threads
474,159
Messages
2,570,879
Members
47,416
Latest member
LionelQ387

Latest Threads

Top