.. include:: replace.txt

.. highlight:: cpp

Tweaking

--------

.. _UsingLogging:

Using the Logging Module

************************

We have already taken a brief look at the |ns3| logging module while

going over the ``first.cc`` script.  We will now take a closer look and 

see what kind of use-cases the logging subsystem was designed to cover.

Logging Overview

++++++++++++++++

Many large systems support some kind of message logging facility, and 

|ns3| is not an exception.  In some cases, only error messages are 

logged to the "operator console" (which is typically ``stderr`` in Unix-

based systems).  In other systems, warning messages may be output as well as 

more detailed informational messages.  In some cases, logging facilities are 

used to output debug messages which can quickly turn the output into a blur.

|ns3| takes the view that all of these verbosity levels are useful 

and we provide a selectable, multi-level approach to message logging.  Logging

can be disabled completely, enabled on a component-by-component basis, or

enabled globally; and it provides selectable verbosity levels.  The 

|ns3| log module provides a straightforward, relatively easy to use

way to get useful information out of your simulation.

You should understand that we do provide a general purpose mechanism --- 

tracing --- to get data out of your models which should be preferred for 

simulation output (see the tutorial section Using the Tracing System for

more details on our tracing system).  Logging should be preferred for 

debugging information, warnings, error messages, or any time you want to 

easily get a quick message out of your scripts or models.

There are currently seven levels of log messages of increasing verbosity

defined in the system.  

* LOG_ERROR --- Log error messages (associated macro: NS_LOG_ERROR);

* LOG_WARN --- Log warning messages (associated macro: NS_LOG_WARN);

* LOG_DEBUG --- Log relatively rare, ad-hoc debugging messages

  (associated macro: NS_LOG_DEBUG);

* LOG_INFO --- Log informational messages about program progress

  (associated macro: NS_LOG_INFO);

* LOG_FUNCTION --- Log a message describing each function called

  (two associated macros: NS_LOG_FUNCTION, used for member functions,

  and NS_LOG_FUNCTION_NOARGS, used for static functions);

* LOG_LOGIC -- Log messages describing logical flow within a function

  (associated macro: NS_LOG_LOGIC);

* LOG_ALL --- Log everything mentioned above (no associated macro).

For each LOG_TYPE there is also LOG_LEVEL_TYPE that, if used, enables

logging of all the levels above it in addition to it's level.  (As a

consequence of this, LOG_ERROR and LOG_LEVEL_ERROR and also LOG_ALL

and LOG_LEVEL_ALL are functionally equivalent.)  For example,

enabling LOG_INFO will only enable messages provided by NS_LOG_INFO macro,

while enabling LOG_LEVEL_INFO will also enable messages provided by

NS_LOG_DEBUG, NS_LOG_WARN and NS_LOG_ERROR macros.  

We also provide an unconditional logging macro that is always displayed,

irrespective of logging levels or component selection.

* NS_LOG_UNCOND -- Log the associated message unconditionally (no associated

  log level).

Each level can be requested singly or cumulatively; and logging can be set 

up using a shell environment variable (NS_LOG) or by logging system function 

call.  As was seen earlier in the tutorial, the logging system has Doxygen 

documentation and now would be a good time to peruse the Logging Module 

documentation if you have not done so.

Now that you have read the documentation in great detail, let's use some of

that knowledge to get some interesting information out of the 

``scratch/myfirst.cc`` example script you have already built.

Enabling Logging

++++++++++++++++

Let's use the NS_LOG environment variable to turn on some more logging, but

first, just to get our bearings, go ahead and run the last script just as you 

did previously,

.. sourcecode:: bash

  $ ./waf --run scratch/myfirst

You should see the now familiar output of the first |ns3| example

program

.. sourcecode:: bash

  $ Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  'build' finished successfully (0.413s)

  Sent 1024 bytes to 10.1.1.2

  Received 1024 bytes from 10.1.1.1

  Received 1024 bytes from 10.1.1.2

It turns out that the "Sent" and "Received" messages you see above are

actually logging messages from the ``UdpEchoClientApplication`` and 

``UdpEchoServerApplication``.  We can ask the client application, for 

example, to print more information by setting its logging level via the 

NS_LOG environment variable.  

I am going to assume from here on that you are using an sh-like shell that uses 

the"VARIABLE=value" syntax.  If you are using a csh-like shell, then you 

will have to convert my examples to the "setenv VARIABLE value" syntax 

required by those shells.

Right now, the UDP echo client application is responding to the following line

of code in ``scratch/myfirst.cc``,

::

  LogComponentEnable("UdpEchoClientApplication", LOG_LEVEL_INFO);

This line of code enables the ``LOG_LEVEL_INFO`` level of logging.  When 

we pass a logging level flag, we are actually enabling the given level and

all lower levels.  In this case, we have enabled ``NS_LOG_INFO``,

``NS_LOG_DEBUG``, ``NS_LOG_WARN`` and ``NS_LOG_ERROR``.  We can

increase the logging level and get more information without changing the

script and recompiling by setting the NS_LOG environment variable like this:

.. sourcecode:: bash

  $ export NS_LOG=UdpEchoClientApplication=level_all

This sets the shell environment variable ``NS_LOG`` to the string,

.. sourcecode:: bash

  UdpEchoClientApplication=level_all

The left hand side of the assignment is the name of the logging component we

want to set, and the right hand side is the flag we want to use.  In this case,

we are going to turn on all of the debugging levels for the application.  If

you run the script with NS_LOG set this way, the |ns3| logging 

system will pick up the change and you should see the following output:

.. sourcecode:: bash

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  'build' finished successfully (0.404s)

  UdpEchoClientApplication:UdpEchoClient()

  UdpEchoClientApplication:SetDataSize(1024)

  UdpEchoClientApplication:StartApplication()

  UdpEchoClientApplication:ScheduleTransmit()

  UdpEchoClientApplication:Send()

  Sent 1024 bytes to 10.1.1.2

  Received 1024 bytes from 10.1.1.1

  UdpEchoClientApplication:HandleRead(0x6241e0, 0x624a20)

  Received 1024 bytes from 10.1.1.2

  UdpEchoClientApplication:StopApplication()

  UdpEchoClientApplication:DoDispose()

  UdpEchoClientApplication:~UdpEchoClient()

The additional debug information provided by the application is from

the NS_LOG_FUNCTION level.  This shows every time a function in the application

is called during script execution.  Generally, use of (at least)

NS_LOG_FUNCTION(this) in member functions is preferred. Use

NS_LOG_FUNCTION_NOARGS() only in static functions.  Note, however, that there

are no requirements in the |ns3| system that models must support any particular

logging  functionality.  The decision regarding how much information is logged

is left to the individual model developer.  In the case of the echo

applications, a good deal of log output is available.

You can now see a log of the function calls that were made to the application.

If you look closely you will notice a single colon between the string 

``UdpEchoClientApplication`` and the method name where you might have 

expected a C++ scope operator (``::``).  This is intentional.  

The name is not actually a class name, it is a logging component name.  When 

there is a one-to-one correspondence between a source file and a class, this 

will generally be the class name but you should understand that it is not 

actually a class name, and there is a single colon there instead of a double

colon to remind you in a relatively subtle way to conceptually separate the 

logging component name from the class name.

It turns out that in some cases, it can be hard to determine which method

actually generates a log message.  If you look in the text above, you may

wonder where the string "``Received 1024 bytes from 10.1.1.2``" comes

from.  You can resolve this by OR'ing the ``prefix_func`` level into the

``NS_LOG`` environment variable.  Try doing the following,

.. sourcecode:: bash

  $ export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func'

Note that the quotes are required since the vertical bar we use to indicate an

OR operation is also a Unix pipe connector.

Now, if you run the script you will see that the logging system makes sure 

that every message from the given log component is prefixed with the component

name.

.. sourcecode:: bash

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  'build' finished successfully (0.417s)

  UdpEchoClientApplication:UdpEchoClient()

  UdpEchoClientApplication:SetDataSize(1024)

  UdpEchoClientApplication:StartApplication()

  UdpEchoClientApplication:ScheduleTransmit()

  UdpEchoClientApplication:Send()

  UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2

  Received 1024 bytes from 10.1.1.1

  UdpEchoClientApplication:HandleRead(0x6241e0, 0x624a20)

  UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2

  UdpEchoClientApplication:StopApplication()

  UdpEchoClientApplication:DoDispose()

  UdpEchoClientApplication:~UdpEchoClient()

You can now see all of the messages coming from the UDP echo client application

are identified as such.  The message "Received 1024 bytes from 10.1.1.2" is

now clearly identified as coming from the echo client application.  The 

remaining message must be coming from the UDP echo server application.  We 

can enable that component by entering a colon separated list of components in

the NS_LOG environment variable.

.. sourcecode:: bash

  $ export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func:

                 UdpEchoServerApplication=level_all|prefix_func'

Warning:  You will need to remove the newline after the ``:`` in the

example text above which is only there for document formatting purposes.

Now, if you run the script you will see all of the log messages from both the

echo client and server applications.  You may see that this can be very useful

in debugging problems.

.. sourcecode:: bash

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  'build' finished successfully (0.406s)

  UdpEchoServerApplication:UdpEchoServer()

  UdpEchoClientApplication:UdpEchoClient()

  UdpEchoClientApplication:SetDataSize(1024)

  UdpEchoServerApplication:StartApplication()

  UdpEchoClientApplication:StartApplication()

  UdpEchoClientApplication:ScheduleTransmit()

  UdpEchoClientApplication:Send()

  UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2

  UdpEchoServerApplication:HandleRead(): Received 1024 bytes from 10.1.1.1

  UdpEchoServerApplication:HandleRead(): Echoing packet

  UdpEchoClientApplication:HandleRead(0x624920, 0x625160)

  UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2

  UdpEchoServerApplication:StopApplication()

  UdpEchoClientApplication:StopApplication()

  UdpEchoClientApplication:DoDispose()

  UdpEchoServerApplication:DoDispose()

  UdpEchoClientApplication:~UdpEchoClient()

  UdpEchoServerApplication:~UdpEchoServer()

It is also sometimes useful to be able to see the simulation time at which a

log message is generated.  You can do this by ORing in the prefix_time bit.

.. sourcecode:: bash

  $ export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func|prefix_time:

                 UdpEchoServerApplication=level_all|prefix_func|prefix_time'

Again, you will have to remove the newline above.  If you run the script now,

you should see the following output:

.. sourcecode:: bash

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  'build' finished successfully (0.418s)

  0s UdpEchoServerApplication:UdpEchoServer()

  0s UdpEchoClientApplication:UdpEchoClient()

  0s UdpEchoClientApplication:SetDataSize(1024)

  1s UdpEchoServerApplication:StartApplication()

  2s UdpEchoClientApplication:StartApplication()

  2s UdpEchoClientApplication:ScheduleTransmit()

  2s UdpEchoClientApplication:Send()

  2s UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2

  2.00369s UdpEchoServerApplication:HandleRead(): Received 1024 bytes from 10.1.1.1

  2.00369s UdpEchoServerApplication:HandleRead(): Echoing packet

  2.00737s UdpEchoClientApplication:HandleRead(0x624290, 0x624ad0)

  2.00737s UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2

  10s UdpEchoServerApplication:StopApplication()

  10s UdpEchoClientApplication:StopApplication()

  UdpEchoClientApplication:DoDispose()

  UdpEchoServerApplication:DoDispose()

  UdpEchoClientApplication:~UdpEchoClient()

  UdpEchoServerApplication:~UdpEchoServer()

You can see that the constructor for the UdpEchoServer was called at a 

simulation time of 0 seconds.  This is actually happening before the 

simulation starts, but the time is displayed as zero seconds.  The same is true

for the UdpEchoClient constructor message.

Recall that the ``scratch/first.cc`` script started the echo server 

application at one second into the simulation.  You can now see that the 

``StartApplication`` method of the server is, in fact, called at one second.

You can also see that the echo client application is started at a simulation 

time of two seconds as we requested in the script.

You can now follow the progress of the simulation from the 

``ScheduleTransmit`` call in the client that calls ``Send`` to the 

``HandleRead`` callback in the echo server application.  Note that the 

elapsed time for the packet to be sent across the point-to-point link is 3.69

milliseconds.  You see the echo server logging a message telling you that it

has echoed the packet and then, after another channel delay, you see the echo

client receive the echoed packet in its ``HandleRead`` method.

There is a lot that is happening under the covers in this simulation that you

are not seeing as well.  You can very easily follow the entire process by

turning on all of the logging components in the system.  Try setting the 

``NS_LOG`` variable to the following,

.. sourcecode:: bash

  $ export 'NS_LOG=*=level_all|prefix_func|prefix_time'

The asterisk above is the logging component wildcard.  This will turn on all 

of the logging in all of the components used in the simulation.  I won't 

reproduce the output here (as of this writing it produces 1265 lines of output

for the single packet echo) but you can redirect this information into a file 

and look through it with your favorite editor if you like,

.. sourcecode:: bash

  $ ./waf --run scratch/myfirst > log.out 2>&1

I personally use this extremely verbose version of logging when I am presented 

with a problem and I have no idea where things are going wrong.  I can follow the 

progress of the code quite easily without having to set breakpoints and step 

through code in a debugger.  I can just edit up the output in my favorite editor

and search around for things I expect, and see things happening that I don't 

expect.  When I have a general idea about what is going wrong, I transition into

a debugger for a fine-grained examination of the problem.  This kind of output 

can be especially useful when your script does something completely unexpected.

If you are stepping using a debugger you may miss an unexpected excursion 

completely.  Logging the excursion makes it quickly visible.

Adding Logging to your Code

+++++++++++++++++++++++++++

You can add new logging to your simulations by making calls to the log 

component via several macros.  Let's do so in the ``myfirst.cc`` script we

have in the ``scratch`` directory.

Recall that we have defined a logging component in that script:

::

  NS_LOG_COMPONENT_DEFINE ("FirstScriptExample");

You now know that you can enable all of the logging for this component by

setting the ``NS_LOG`` environment variable to the various levels.  Let's

go ahead and add some logging to the script.  The macro used to add an 

informational level log message is ``NS_LOG_INFO``.  Go ahead and add one 

(just before we start creating the nodes) that tells you that the script is 

"Creating Topology."  This is done as in this code snippet,

Open ``scratch/myfirst.cc`` in your favorite editor and add the line,

::

  NS_LOG_INFO ("Creating Topology");

right before the lines,

::

  NodeContainer nodes;

  nodes.Create (2);

Now build the script using waf and clear the ``NS_LOG`` variable to turn 

off the torrent of logging we previously enabled:

.. sourcecode:: bash

  $ ./waf

  $ export NS_LOG=

Now, if you run the script, 

.. sourcecode:: bash

  $ ./waf --run scratch/myfirst

you will ``not`` see your new message since its associated logging 

component (``FirstScriptExample``) has not been enabled.  In order to see your

message you will have to enable the ``FirstScriptExample`` logging component

with a level greater than or equal to ``NS_LOG_INFO``.  If you just want to 

see this particular level of logging, you can enable it by,

.. sourcecode:: bash

  $ export NS_LOG=FirstScriptExample=info

If you now run the script you will see your new "Creating Topology" log

message,

.. sourcecode:: bash

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  'build' finished successfully (0.404s)

  Creating Topology

  Sent 1024 bytes to 10.1.1.2

  Received 1024 bytes from 10.1.1.1

  Received 1024 bytes from 10.1.1.2

Using Command Line Arguments

****************************

.. _Attribute:

Overriding Default Attributes

+++++++++++++++++++++++++++++

Another way you can change how |ns3| scripts behave without editing

and building is via *command line arguments.*  We provide a mechanism to 

parse command line arguments and automatically set local and global variables

based on those arguments.

The first step in using the command line argument system is to declare the

command line parser.  This is done quite simply (in your main program) as

in the following code,

::

  int

  main (int argc, char *argv[])

  {

    ...  

    CommandLine cmd;

    cmd.Parse (argc, argv);

    ...

  }

This simple two line snippet is actually very useful by itself.  It opens the

door to the |ns3| global variable and ``Attribute`` systems.  Go 

ahead and add that two lines of code to the ``scratch/myfirst.cc`` script at

the start of ``main``.  Go ahead and build the script and run it, but ask 

the script for help in the following way,

.. sourcecode:: bash

  $ ./waf --run "scratch/myfirst --PrintHelp"

This will ask Waf to run the ``scratch/myfirst`` script and pass the command

line argument ``--PrintHelp`` to the script.  The quotes are required to 

sort out which program gets which argument.  The command line parser will

now see the ``--PrintHelp`` argument and respond with,

.. sourcecode:: bash

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'

  'build' finished successfully (0.413s)

  TcpL4Protocol:TcpStateMachine()

  CommandLine:HandleArgument(): Handle arg name=PrintHelp value=

  --PrintHelp: Print this help message.

  --PrintGroups: Print the list of groups.

  --PrintTypeIds: Print all TypeIds.

  --PrintGroup=[group]: Print all TypeIds of group.

  --PrintAttributes=[typeid]: Print all attributes of typeid.

  --PrintGlobals: Print the list of globals.

Let's focus on the ``--PrintAttributes`` option.  We have already hinted

at the |ns3| ``Attribute`` system while walking through the 

``first.cc`` script.  We looked at the following lines of code,

::

    PointToPointHelper pointToPoint;

    pointToPoint.SetDeviceAttribute ("DataRate", StringValue ("5Mbps"));

    pointToPoint.SetChannelAttribute ("Delay", StringValue ("2ms"));

and mentioned that ``DataRate`` was actually an ``Attribute`` of the 

``PointToPointNetDevice``.  Let's use the command line argument parser

to take a look at the ``Attributes`` of the PointToPointNetDevice.  The help

listing says that we should provide a ``TypeId``.  This corresponds to the

class name of the class to which the ``Attributes`` belong.  In this case it

will be ``ns3::PointToPointNetDevice``.  Let's go ahead and type in,

.. sourcecode:: bash

  $ ./waf --run "scratch/myfirst --PrintAttributes=ns3::PointToPointNetDevice"

The system will print out all of the ``Attributes`` of this kind of net device.

Among the ``Attributes`` you will see listed is,

.. sourcecode:: bash

  --ns3::PointToPointNetDevice::DataRate=[32768bps]:

    The default data rate for point to point links

This is the default value that will be used when a ``PointToPointNetDevice``

is created in the system.  We overrode this default with the ``Attribute``

setting in the ``PointToPointHelper`` above.  Let's use the default values 

for the point-to-point devices and channels by deleting the 

``SetDeviceAttribute`` call and the ``SetChannelAttribute`` call from 

the ``myfirst.cc`` we have in the scratch directory.

Your script should now just declare the ``PointToPointHelper`` and not do 

any ``set`` operations as in the following example,

::

  ...

  NodeContainer nodes;

  nodes.Create (2);

  PointToPointHelper pointToPoint;