| [ < ] | [ > ] | [ << ] | [ Up ] | [ >> ] | [Top] | [Contents] | [Index] | [ ? ] |
We have already taken a brief look at the ns-3 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.
| [ < ] | [ > ] | [ << ] | [ Up ] | [ >> ] | [Top] | [Contents] | [Index] | [ ? ] |
Many large systems support some kind of message logging facility, and
ns-3 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.
Ns-3 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
ns-3 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.
We also provide an unconditional logging level that is always displayed, irrespective of logging levels or component selection.
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.
| [ < ] | [ > ] | [ << ] | [ Up ] | [ >> ] | [Top] | [Contents] | [Index] | [ ? ] |
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,
./waf --run scratch/myfirst
You should see the now familiar output of the first ns-3 example
program
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:
export NS_LOG=UdpEchoClientApplication=level_all
This sets the shell environment variable NS_LOG to the string,
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 ns-3 logging
system will pick up the change and you should see the following output:
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. Note that there are no requirements in the
ns-3 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,
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.
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.
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.
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.
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:
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,
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,
./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.
| [ < ] | [ > ] | [ << ] | [ Up ] | [ >> ] | [Top] | [Contents] | [Index] | [ ? ] |
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:
./waf export NS_LOG=
Now, if you run the script,
./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,
export NS_LOG=FirstScriptExample=info
If you now run the script you will see your new “Creating Topology” log message,
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
| [ < ] | [ > ] | [ << ] | [ Up ] | [ >> ] |
This document was generated on August 20, 2010 using texi2html 1.82.