Tutorial 5: Advanced examples

In this tutorial you will learn how to list all debugging channels and how to write a loop that runs over all existing debug channels.  You will make four debug channels in their own namespace and write debug output to a combination of them.  You will also learn how to add an error message after a debug message, how to format a debug message, how to supress the label and how to supress the newline at the end.  Finally you will learn how to write interrupted debug output in an example that prints the call to a system call and the result of that.

5.1 Running over all Debug Channels

In tutorial 2 you have learned how to create new Debug Channels.  Each new Debug Channel is stored in an internal list, allowing you to loop over all debug channels without knowing exactly which ones exist.  For example, the following code will turn on all debug channels.  It is not allowed to call on() for a Debug Channel that is already on: that will result in a runtime error.

A special shortcut function is provided to list all debug channels, the following code prints a list of all channels after they have been turned on.

Compile as: g++ -g -DCWDEBUG test5.1.1.cc -lcwd -o turn_on

[download]

#include "sys.h"		// See tutorial 2
#include "debug.h"

int main(void)
{
  // Turn on debug object `libcw_do'.
  Debug( libcw_do.on() );

  // Turn on all debug channels that are off.
  ForAllDebugChannels(
    if (!debugChannel.is_on())
      debugChannel.on();
  );

  // Print a listing of all debug channels to debug object `libcw_do'.
  Debug( list_channels_on(libcw_do) );

  return 0;
}

This program outputs:

BFD     : Enabled
DEBUG   : Enabled
DUMBO   : Enabled
EINSTEIN: Enabled
FELIX   : Enabled
HILDAGO : Enabled
MALLOC  : Enabled
NOTICE  : Enabled
SYSTEM  : Enabled
WARNING : Enabled

5.2 Debug Channels and name spaces

The custom debug channel dc::ghost that you created in tutorial 2 was put in namespace debug_channels.  The debug channels of libcwd are put in namespace libcwd::channels.  Nevertheless, it is not necessary to type

Dout(libcwd::channels::dc::notice, "Hello World");

By default, the macro Dout et al. automatically include a using namespace libcwd::channels.  It is possible to change this default namespace by defining DEBUGCHANNELS before including the header file libcwd/debug.h.  This is will be shown below.

Of course, you can put your own debug channels also in namespace libcwd::channels but that wouldn't garantee not to collide with a new debug channel added to libcwd in the future, or with debug channels of other libraries that would do the same.

In the following example we will define four new debug channels in their own name space example::debug::channels by creating a project specific header file "debug.h" which needs to be included instead of the debug.h from libcwd.

The example application below uses the fictitious libraries libbooster and libturbo, both of which use libcwd themselfs and declare their own debug channel namespaces booster::debug::channels and turbo::debug::channels according to the rules as mentioned in the reference manual.

The project header file "debug.h":

[download]

#ifndef EXAMPLE_DEBUG_H
#define EXAMPLE_DEBUG_H

#ifdef CWDEBUG

#ifndef DEBUGCHANNELS				// This test is only necessary in libraries
#define DEBUGCHANNELS ::example::debug::channels
#endif
#include <libbooster/debug.h>			// Note that these will include
#include <libturbo/debug.h>			//   libcwd/debug.h for us.

namespace example {
  namespace debug {
    namespace channels {
      namespace dc {
	using namespace libcwd;		// For class channel_ct

	// The list of debug channel namespaces of the libraries that we use:
	// (These two already include libcwd::channels::dc)
	using namespace ::booster::debug::channels::dc;
	using namespace ::turbo::debug::channels::dc;

	// Our own debug channels:
	extern channel_ct elephant;
	extern channel_ct cat;
	extern channel_ct mouse;
	extern channel_ct owl;

	// When the libraries use the same name for any debug channels,
	// then here is the place to `hide' these channels by redefining them.
	// For example, if `libbooster' defined `notice' too (as does libcwd)
	// then we have to redefine it again:
	using libcwd::channels::dc::notice;

      } // namespace dc
    } // namespace channels
  } // namespace debug
} // namespace example

// The following is only necessary for libraries.
// Libraries should not use Dout() et al. in their own header files,
// instead we define our own macros here for use in those header files:
#define MyLibHeaderDout(cntrl, data) \
      LibcwDout(::example::debug::channels, ::libcwd::libcw_do, cntrl, data)
#define MyLibHeaderDoutFatal(cntrl, data) \
      LibcwDoutFatal(::example::debug::channels, ::libcwd::libcw_do, cntrl, data)

#else // !CWDEBUG

// This is needed so people who don't have libcwd installed can still compile it.
// The file "nodebug.h" is provided in the libcwd and needs to be included in your
// own package.
#include "nodebug.h"
#define MyLibHeaderDout(cntrl, data)
#define MyLibHeaderDoutFatal(cntrl, data) LibcwDoutFatal(::std, /*nothing*/, cntrl, data)

#endif // !CWDEBUG

#endif // EXAMPLE_DEBUG_H

The source file "debug.cc":

[download]

#include "sys.h"	// See tutorial 2
#include "debug.h"

#ifdef CWDEBUG
using namespace libcwd;

namespace example {
  namespace debug {
    namespace channels {
      namespace dc {
	channel_ct elephant("DUMBO");
	channel_ct cat("FELIX");
	channel_ct mouse("HILDAGO");
	channel_ct owl("EINSTEIN");
      }
    }
  }
}
#endif

5.3 Combining channels

Debug channels can be on or off and they have a label.  Sometimes you might want to write certain debug output to a debug object when any of a given list of debug channels is turned on.  The syntax to do that is based on the fact that debug channels can be viewed upon as a bit mask: using operator|.  In the following example we will write debug output to several different combinations of the custom debug channels that we defined in the previous paragraph.

The source file "test5.3.1.cc":

[download]

#include "sys.h"		// See § 2
#include "debug.h"		// See § 5.2

int main(void)
{
  // Start with everything turned on:
  Debug( libcw_do.on() );
  ForAllDebugChannels( if (!debugChannel.is_on()) debugChannel.on() );

  Dout(dc::elephant|dc::owl, "The elephant is called Dumbo, the owl is called Einstein.");

  return 0;
}

This program outputs:

DUMBO   : The elephant is called Dumbo, the owl is called Einstein.

using the label of the left most channel that is turned on.

If we turn off dc::elephant:

[download]

#include "sys.h"
#include "debug.h"

int main(void)
{
  // Start with everything turned on:
  Debug( libcw_do.on() );
  ForAllDebugChannels( if (!debugChannel.is_on()) debugChannel.on() );

  Debug( dc::elephant.off() );
  Dout(dc::elephant|dc::owl, "The elephant is called Dumbo, the owl is called Einstein.");

  return 0;
}

Then the program outputs

EINSTEIN: The elephant is called Dumbo, the owl is called Einstein.

5.4 Formatting debug output

It is possible to control the format of debug output in two different ways:

1. Per call to Dout, using control flags.
2. Persistantly per debug object, using methods of the debug object.

5.4.1 Control flags

Control flags are unsigned integer bit-masks and are passed along to Dout together with the debug channel(s).  For example, in the following code the newline that is normally printed after each output is suppressed in the first call:

[download]

#include "sys.h"
#include "debug.h"

int main(void)
{
  Debug( libcw_do.on() );
  Debug( dc::notice.on() );

  Dout(dc::notice|nonewline_cf, "Hello, ");
  Dout(dc::notice, "World");

  return 0;
}

This program outputs:

NOTICE  : Hello, NOTICE  : World

In order to supress the prefix in the second call we use noprefix_cf:

[download]

#include "sys.h"
#include "debug.h"

int main(void)
{
  Debug( libcw_do.on() );
  Debug( dc::notice.on() );

  Dout(dc::notice|nonewline_cf, "Hello, ");
  Dout(dc::notice|noprefix_cf, "World");

  return 0;
}

Now the output is

NOTICE  : Hello, World

There are in total eleven control flags, see the Reference Manual for an overview.

Lets get a little bit more practical now.  In the next example we perform a system call and write this fact to dc::notice in the same way as strace(1) would do; the fact that the call is made is printed first.  After the call returns we print the results.

[download]

#include "sys.h"
#include "debug.h"
#include <sys/stat.h>
#include <cstdlib>

std::ostream& operator<<(std::ostream& os, struct stat const buf)
{
  os << "inode:" << buf.st_ino << "; " << "size:" << buf.st_size;
  return os;
}

std::ostream& operator<<(std::ostream& os, struct stat const* bufp)
{
  os << "{ " << *bufp << " }";
  return os;
}

int main(int argc, char* argv[])
{
  Debug( libcw_do.on() );
  Debug( dc::notice.on() );

  if (argc != 2)
  {
    std::cerr << "Usage: " << argv[0] << " <file_name>\n";
    exit(-1);
  }

  char const* file_name = argv[1];
  struct stat buf;

  // Warning: this is NOT the correct way to do this (see below)
  Dout(dc::notice|nonewline_cf,
       "stat(\"" << file_name << "\", ");

  int ret = stat(file_name, &buf);

  Dout(dc::notice|noprefix_cf|cond_error_cf(ret != 0),
       &buf << ") = " << ret);

  return 0;
}

Note the use of cond_error_cf(condition) which is equal to error_cf if the condition passed is true, or zero otherwise.  The result of error_cf is that an error message is printed after the debug output according to the current value of errno.  When we run this program with parameter "/bin/ls" we get something like:

NOTICE  : stat("/bin/ls", { inode:1310862; size:141936 }) = 0

And when we use a file that doesn't exist, we get something like:

NOTICE       : stat("foobar", { inode:134572072; size:1 }) = -1: ENOENT (No such file or directory)

As you already might have noticed from the comment in the program, this is not the correct way to do this.  The reason that it is wrong is because the call to stat could cause debug output itself.  Well, it couldn't in this case, but in a more general case it could :).

Let us replace the call to stat by a function of ourselfs that allocates memory (as certain system calls could do too!):

[download]

#include "sys.h"
#include "debug.h"
#include <sys/stat.h>
#include <cstdlib>

std::ostream& operator<<(std::ostream& os, struct stat const buf)
{
  os << "inode:" << buf.st_ino << "; " << "size:" << buf.st_size;
  return os;
}

std::ostream& operator<<(std::ostream& os, struct stat const* bufp)
{
  os << "{ " << *bufp << " }";
  return os;
}

// We only use this function to show what happens with the debug output,
// you shouldn't do anything like this in a real program.
int stat_with_buf_alloc(char const* file_name, struct stat*& bufp)
{
  bufp = new struct stat;
  return stat(file_name, bufp);
}

int main(int argc, char* argv[])
{
  Debug( libcw_do.on() );
  Debug( dc::notice.on() );
  Debug( dc::malloc.on() );

  if (argc != 2)
  {
    std::cerr << "Usage: " << argv[0] << " <file_name>\n";
    exit(-1);
  }

  char const* file_name = argv[1];
  struct stat* bufp;

  // This is NOT the correct way to do this.
  Dout(dc::notice|nonewline_cf,
       "stat_with_buf_alloc(\"" << file_name << "\", ");

  int ret = stat_with_buf_alloc(file_name, bufp);

  Dout(dc::notice|noprefix_cf|cond_error_cf(ret != 0),
       bufp << ") = " << ret);

  
  Debug( dc::malloc.off() );
  delete bufp;
  return 0;
}

Now the call (to stat_with_buf_alloc) writes debug output itself which is completely messing up our beautiful attempt to look like the output of strace(1):

NOTICE  : stat_with_buf_alloc("/bin/ls", MALLOC  : operator new (size = 144) = 0x55cf2ef80540 [test5.4.4.cc:22]
{ inode:1310862; size:141936 }) = 0

Therefore it isn't a good idea to use nonewline_cf and noprefix_cf like this.  Use instead continued_cf, dc::continued and dc::finish which are designed especially for interrupted debug output:

[download]

#include "sys.h"
#include "debug.h"
#include <sys/stat.h>
#include <cstdlib>

std::ostream& operator<<(std::ostream& os, struct stat const buf)
{
  os << "inode:" << buf.st_ino << "; " << "size:" << buf.st_size;
  return os;
}

std::ostream& operator<<(std::ostream& os, struct stat const* bufp)
{
  os << "{ " << *bufp << " }";
  return os;
}

// We only use this function to show what happens with the debug output.
// You shouldn't do anything like this in a real program.
int stat_with_buf_alloc(char const* file_name, struct stat*& bufp)
{
  bufp = new struct stat;
  return stat(file_name, bufp);
}

int main(int argc, char* argv[])
{
  Debug( libcw_do.on() );
  Debug( dc::notice.on() );
  Debug( dc::malloc.on() );

  if (argc != 2)
  {
    std::cerr << "Usage: " << argv[0] << " <file_name>\n";
    exit(-1);
  }

  char const* file_name = argv[1];
  struct stat* bufp;

  Dout(dc::notice|continued_cf,
       "stat_with_buf_alloc(\"" << file_name << "\", ");

  int ret = stat_with_buf_alloc(file_name, bufp);

  Dout(dc::finish|cond_error_cf(ret != 0),
       bufp << ") = " << ret);

  Debug( dc::malloc.off() );
  delete bufp;
  return 0;
}

Now the output looks like

NOTICE  : stat_with_buf_alloc("/bin/ls", <unfinished>
MALLOC  :     operator new (size = 144) = 0x5557db1f5830 [test5.4.5.cc:22]
NOTICE  : <continued> { inode:1310862; size:141936 }) = 0

5.4.2 Methods of the debug object

You can also change the format of debug output by calling methods of the debug object.  Consider the following example:

[download]

#include "sys.h"
#include "debug.h"

int main(void)
{
  Debug( libcw_do.on() );
  ForAllDebugChannels( if (!debugChannel.is_on()) debugChannel.on() );

  Debug( libcw_do.margin().assign("<-- margin -->", 14) );
  Debug( libcw_do.marker().assign("<-- marker -->", 14) );
  Dout(dc::cat|dc::mouse, "The cat chases the mouse.");
  Dout(dc::mouse|dc::elephant, "The mouse chases the elephant.");
  Dout(dc::notice|nolabel_cf, "Setting indentation to 8 spaces:");
  Dout(dc::notice|blank_label_cf, "<------>");
  Debug( libcw_do.set_indent(8) );
  Dout(dc::cat, "The cat sleeps.");
  Dout(dc::elephant, "The elephant looks around:");
  Dout(dc::elephant|blank_label_cf|blank_marker_cf, "where did the mouse go?");

  return 0;
}

This program outputs:

<-- margin -->FELIX   <-- marker -->The cat chases the mouse.
<-- margin -->HILDAGO <-- marker -->The mouse chases the elephant.
<-- margin -->Setting indentation to 8 spaces:
<-- margin -->        <-- marker --><------>
<-- margin -->FELIX   <-- marker -->        The cat sleeps.
<-- margin -->DUMBO   <-- marker -->        The elephant looks around:
<-- margin -->                              where did the mouse go?

This concludes the first part of this tutorial about debug output.  The following chapters handle the memory allocation debugging support of libcwd.