1 .. include:: replace.txt

     2 

     3 

     4 Tweaking

     5 --------

     6 

     7 Using the Logging Module

     8 ************************

     9 

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

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

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

    13 

    14 Logging Overview

    15 ++++++++++++++++

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

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

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

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

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

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

    22 

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

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

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

    26 enabled globally; and it provides selectable verbosity levels.  The 

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

    28 way to get useful information out of your simulation.

    29 

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

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

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

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

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

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

    36 

    37 There are currently seven levels of log messages of increasing verbosity

    38 defined in the system.  

    39 

    40 * NS_LOG_ERROR --- Log error messages;

    41 * NS_LOG_WARN --- Log warning messages;

    42 * NS_LOG_DEBUG --- Log relatively rare, ad-hoc debugging messages;

    43 * NS_LOG_INFO --- Log informational messages about program progress;

    44 * NS_LOG_FUNCTION --- Log a message describing each function called;

    45 * NS_LOG_LOGIC -- Log messages describing logical flow within a function;

    46 * NS_LOG_ALL --- Log everything.

    47 

    48 We also provide an unconditional logging level that is always displayed,

    49 irrespective of logging levels or component selection.

    50 

    51 *  NS_LOG_UNCOND -- Log the associated message unconditionally.

    52 

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

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

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

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

    57 documentation if you have not done so.

    58 

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

    60 that knowledge to get some interesting information out of the 

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

    62 

    63 Enabling Logging

    64 ++++++++++++++++

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

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

    67 did previously,

    68 

    69 ::

    70 

    71   ./waf --run scratch/myfirst

    72 

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

    74 program

    75 

    76 ::

    77 

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

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

    80   'build' finished successfully (0.413s)

    81   Sent 1024 bytes to 10.1.1.2

    82   Received 1024 bytes from 10.1.1.1

    83   Received 1024 bytes from 10.1.1.2

    84 

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

    86 actually logging messages from the ``UdpEchoClientApplication`` and 

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

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

    89 NS_LOG environment variable.  

    90 

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

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

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

    94 required by those shells.

    95 

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

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

    98 

    99 ::

   100 

   101   LogComponentEnable("UdpEchoClientApplication", LOG_LEVEL_INFO);

   102 

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

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

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

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

   107 increase the logging level and get more information without changing the

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

   109 

   110 ::

   111 

   112   export NS_LOG=UdpEchoClientApplication=level_all

   113 

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

   115 

   116 ::

   117 

   118   UdpEchoClientApplication=level_all

   119 

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

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

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

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

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

   125 

   126 ::

   127 

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

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

   130   'build' finished successfully (0.404s)

   131   UdpEchoClientApplication:UdpEchoClient()

   132   UdpEchoClientApplication:SetDataSize(1024)

   133   UdpEchoClientApplication:StartApplication()

   134   UdpEchoClientApplication:ScheduleTransmit()

   135   UdpEchoClientApplication:Send()

   136   Sent 1024 bytes to 10.1.1.2

   137   Received 1024 bytes from 10.1.1.1

   138   UdpEchoClientApplication:HandleRead(0x6241e0, 0x624a20)

   139   Received 1024 bytes from 10.1.1.2

   140   UdpEchoClientApplication:StopApplication()

   141   UdpEchoClientApplication:DoDispose()

   142   UdpEchoClientApplication:~UdpEchoClient()

   143 

   144 The additional debug information provided by the application is from

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

   146 is called during script execution.  Note that there are no requirements in the

   147 |ns3| system that models must support any particular logging 

   148 functionality.  The decision regarding how much information is logged

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

   150 applications, a good deal of log output is available.

   151 

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

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

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

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

   156 

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

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

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

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

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

   162 logging component name from the class name.

   163 

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

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

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

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

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

   169 

   170 ::

   171 

   172   export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func'

   173 

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

   175 OR operation is also a Unix pipe connector.

   176 

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

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

   179 name.

   180 

   181 ::

   182 

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

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

   185   'build' finished successfully (0.417s)

   186   UdpEchoClientApplication:UdpEchoClient()

   187   UdpEchoClientApplication:SetDataSize(1024)

   188   UdpEchoClientApplication:StartApplication()

   189   UdpEchoClientApplication:ScheduleTransmit()

   190   UdpEchoClientApplication:Send()

   191   UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2

   192   Received 1024 bytes from 10.1.1.1

   193   UdpEchoClientApplication:HandleRead(0x6241e0, 0x624a20)

   194   UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2

   195   UdpEchoClientApplication:StopApplication()

   196   UdpEchoClientApplication:DoDispose()

   197   UdpEchoClientApplication:~UdpEchoClient()

   198 

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

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

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

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

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

   204 the NS_LOG environment variable.

   205 

   206 ::

   207 

   208   export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func:

   209                  UdpEchoServerApplication=level_all|prefix_func'

   210 

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

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

   213 

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

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

   216 in debugging problems.

   217 

   218 ::

   219 

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

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

   222   'build' finished successfully (0.406s)

   223   UdpEchoServerApplication:UdpEchoServer()

   224   UdpEchoClientApplication:UdpEchoClient()

   225   UdpEchoClientApplication:SetDataSize(1024)

   226   UdpEchoServerApplication:StartApplication()

   227   UdpEchoClientApplication:StartApplication()

   228   UdpEchoClientApplication:ScheduleTransmit()

   229   UdpEchoClientApplication:Send()

   230   UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2

   231   UdpEchoServerApplication:HandleRead(): Received 1024 bytes from 10.1.1.1

   232   UdpEchoServerApplication:HandleRead(): Echoing packet

   233   UdpEchoClientApplication:HandleRead(0x624920, 0x625160)

   234   UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2

   235   UdpEchoServerApplication:StopApplication()

   236   UdpEchoClientApplication:StopApplication()

   237   UdpEchoClientApplication:DoDispose()

   238   UdpEchoServerApplication:DoDispose()

   239   UdpEchoClientApplication:~UdpEchoClient()

   240   UdpEchoServerApplication:~UdpEchoServer()

   241 

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

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

   244 

   245 ::

   246 

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

   248                  UdpEchoServerApplication=level_all|prefix_func|prefix_time'

   249 

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

   251 you should see the following output:

   252 

   253 ::

   254 

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

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

   257   'build' finished successfully (0.418s)

   258   0s UdpEchoServerApplication:UdpEchoServer()

   259   0s UdpEchoClientApplication:UdpEchoClient()

   260   0s UdpEchoClientApplication:SetDataSize(1024)

   261   1s UdpEchoServerApplication:StartApplication()

   262   2s UdpEchoClientApplication:StartApplication()

   263   2s UdpEchoClientApplication:ScheduleTransmit()

   264   2s UdpEchoClientApplication:Send()

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

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

   267   2.00369s UdpEchoServerApplication:HandleRead(): Echoing packet

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

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

   270   10s UdpEchoServerApplication:StopApplication()

   271   10s UdpEchoClientApplication:StopApplication()

   272   UdpEchoClientApplication:DoDispose()

   273   UdpEchoServerApplication:DoDispose()

   274   UdpEchoClientApplication:~UdpEchoClient()

   275   UdpEchoServerApplication:~UdpEchoServer()

   276 

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

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

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

   280 for the UdpEchoClient constructor message.

   281 

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

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

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

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

   286 time of two seconds as we requested in the script.

   287 

   288 You can now follow the progress of the simulation from the 

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

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

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

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

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

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

   295 

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

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

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

   299 ``NS_LOG`` variable to the following,

   300 

   301 ::

   302 

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

   304 

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

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

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

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

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

   310 

   311 ::

   312 

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

   314 

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

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

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

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

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

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

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

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

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

   324 completely.  Logging the excursion makes it quickly visible.

   325 

   326 Adding Logging to your Code

   327 +++++++++++++++++++++++++++

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

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

   330 have in the ``scratch`` directory.

   331 

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

   333 

   334 ::

   335 

   336   NS_LOG_COMPONENT_DEFINE ("FirstScriptExample");

   337 

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

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

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

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

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

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

   344 

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

   346 

   347 ::

   348 

   349   NS_LOG_INFO ("Creating Topology");

   350 

   351 right before the lines,

   352 

   353 ::

   354 

   355   NodeContainer nodes;

   356   nodes.Create (2);

   357 

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

   359 off the torrent of logging we previously enabled:

   360 

   361 ::

   362 

   363   ./waf

   364   export NS_LOG=

   365 

   366 Now, if you run the script, 

   367 

   368 ::

   369 

   370   ./waf --run scratch/myfirst

   371 

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

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

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

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

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

   377 

   378 ::

   379 

   380   export NS_LOG=FirstScriptExample=info

   381 

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

   383 message,

   384 

   385 ::

   386 

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

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

   389   'build' finished successfully (0.404s)

   390   Creating Topology

   391   Sent 1024 bytes to 10.1.1.2

   392   Received 1024 bytes from 10.1.1.1

   393   Received 1024 bytes from 10.1.1.2

   394 

   395 Using Command Line Arguments

   396 ****************************

   397 

   398 Overriding Default Attributes

   399 +++++++++++++++++++++++++++++

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

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

   402 parse command line arguments and automatically set local and global variables

   403 based on those arguments.

   404 

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

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

   407 in the following code,

   408 

   409 ::

   410 

   411     int

   412   main (int argc, char *argv[])

   413   {

   414     ...  

   415 

   416     CommandLine cmd;

   417     cmd.Parse (argc, argv);

   418 

   419     ...

   420   }

   421 

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

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

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

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

   426 the script for help in the following way,

   427 

   428 ::

   429 

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

   431 

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

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

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

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

   436 

   437 ::

   438 

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

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

   441   'build' finished successfully (0.413s)

   442   TcpL4Protocol:TcpStateMachine()

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

   444   --PrintHelp: Print this help message.

   445   --PrintGroups: Print the list of groups.

   446   --PrintTypeIds: Print all TypeIds.

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

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

   449   --PrintGlobals: Print the list of globals.

   450 

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

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

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

   454 

   455 ::

   456 

   457     PointToPointHelper pointToPoint;

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

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

   460 

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

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

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

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

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

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

   467 

   468 ::

   469 

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

   471 

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

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

   474 

   475 ::

   476 

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

   478     The default data rate for point to point links

   479 

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

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

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

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

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

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

   486 

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

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

   489 

   490 ::

   491 

   492   ...

   493 

   494   NodeContainer nodes;

   495   nodes.Create (2);

   496 

   497   PointToPointHelper pointToPoint;

   498 

   499   NetDeviceContainer devices;

   500   devices = pointToPoint.Install (nodes);

   501 

   502   ...

   503 

   504 Go ahead and build the new script with Waf (``./waf``) and let's go back 

   505 and enable some logging from the UDP echo server application and turn on the 

   506 time prefix.

   507 

   508 ::

   509 

   510   export 'NS_LOG=UdpEchoServerApplication=level_all|prefix_time'

   511 

   512 If you run the script, you should now see the following output,

   513 

   514 ::

   515 

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

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

   518   'build' finished successfully (0.405s)

   519   0s UdpEchoServerApplication:UdpEchoServer()

   520   1s UdpEchoServerApplication:StartApplication()

   521   Sent 1024 bytes to 10.1.1.2

   522   2.25732s Received 1024 bytes from 10.1.1.1

   523   2.25732s Echoing packet

   524   Received 1024 bytes from 10.1.1.2

   525   10s UdpEchoServerApplication:StopApplication()

   526   UdpEchoServerApplication:DoDispose()

   527   UdpEchoServerApplication:~UdpEchoServer()

   528 

   529 Recall that the last time we looked at the simulation time at which the packet

   530 was received by the echo server, it was at 2.00369 seconds.

   531 

   532 ::

   533 

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

   535 

   536 Now it is receiving the packet at 2.25732 seconds.  This is because we just dropped

   537 the data rate of the ``PointToPointNetDevice`` down to its default of 

   538 32768 bits per second from five megabits per second.

   539 

   540 If we were to provide a new ``DataRate`` using the command line, we could 

   541 speed our simulation up again.  We do this in the following way, according to

   542 the formula implied by the help item:

   543 

   544 ::

   545 

   546   ./waf --run "scratch/myfirst --ns3::PointToPointNetDevice::DataRate=5Mbps"

   547 

   548 This will set the default value of the ``DataRate`` ``Attribute`` back to 

   549 five megabits per second.  Are you surprised by the result?  It turns out that

   550 in order to get the original behavior of the script back, we will have to set 

   551 the speed-of-light delay of the channel as well.  We can ask the command line 

   552 system to print out the ``Attributes`` of the channel just like we did for

   553 the net device:

   554 

   555 ::

   556 

   557   ./waf --run "scratch/myfirst --PrintAttributes=ns3::PointToPointChannel"

   558 

   559 We discover the ``Delay`` ``Attribute`` of the channel is set in the following

   560 way:

   561 

   562 ::

   563 

   564   --ns3::PointToPointChannel::Delay=[0ns]:

   565     Transmission delay through the channel

   566 

   567 We can then set both of these default values through the command line system,

   568 

   569 ::

   570 

   571   ./waf --run "scratch/myfirst

   572     --ns3::PointToPointNetDevice::DataRate=5Mbps

   573     --ns3::PointToPointChannel::Delay=2ms"

   574 

   575 in which case we recover the timing we had when we explicitly set the

   576 ``DataRate`` and ``Delay`` in the script:

   577 

   578 ::

   579 

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

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

   582   'build' finished successfully (0.417s)

   583   0s UdpEchoServerApplication:UdpEchoServer()

   584   1s UdpEchoServerApplication:StartApplication()

   585   Sent 1024 bytes to 10.1.1.2

   586   2.00369s Received 1024 bytes from 10.1.1.1

   587   2.00369s Echoing packet

   588   Received 1024 bytes from 10.1.1.2

   589   10s UdpEchoServerApplication:StopApplication()

   590   UdpEchoServerApplication:DoDispose()

   591   UdpEchoServerApplication:~UdpEchoServer()

   592 

   593 Note that the packet is again received by the server at 2.00369 seconds.  We 

   594 could actually set any of the ``Attributes`` used in the script in this way.

   595 In particular we could set the ``UdpEchoClient Attribute MaxPackets`` 

   596 to some other value than one.

   597 

   598 How would you go about that?  Give it a try.  Remember you have to comment 

   599 out the place we override the default ``Attribute`` and explicitly set 

   600 ``MaxPackets`` in the script.  Then you have to rebuild the script.  You 

   601 will also have to find the syntax for actually setting the new default attribute

   602 value using the command line help facility.  Once you have this figured out 

   603 you should be able to control the number of packets echoed from the command 

   604 line.  Since we're nice folks, we'll tell you that your command line should 

   605 end up looking something like,

   606 

   607 ::

   608 

   609   ./waf --run "scratch/myfirst 

   610     --ns3::PointToPointNetDevice::DataRate=5Mbps 

   611     --ns3::PointToPointChannel::Delay=2ms 

   612     --ns3::UdpEchoClient::MaxPackets=2"

   613 

   614 Hooking Your Own Values

   615 +++++++++++++++++++++++

   616 You can also add your own hooks to the command line system.  This is done

   617 quite simply by using the ``AddValue`` method to the command line parser.

   618 

   619 Let's use this facility to specify the number of packets to echo in a 

   620 completely different way.  Let's add a local variable called ``nPackets``

   621 to the ``main`` function.  We'll initialize it to one to match our previous 

   622 default behavior.  To allow the command line parser to change this value, we

   623 need to hook the value into the parser.  We do this by adding a call to 

   624 ``AddValue``.  Go ahead and change the ``scratch/myfirst.cc`` script to

   625 start with the following code,

   626 

   627 ::

   628 

   629   int

   630   main (int argc, char *argv[])

   631   {

   632     uint32_t nPackets = 1;

   633 

   634     CommandLine cmd;

   635     cmd.AddValue("nPackets", "Number of packets to echo", nPackets);

   636     cmd.Parse (argc, argv);

   637 

   638     ...

   639 

   640 Scroll down to the point in the script where we set the ``MaxPackets``

   641 ``Attribute`` and change it so that it is set to the variable ``nPackets``

   642 instead of the constant ``1`` as is shown below.

   643 

   644 ::

   645 

   646   echoClient.SetAttribute ("MaxPackets", UintegerValue (nPackets));

   647 

   648 Now if you run the script and provide the ``--PrintHelp`` argument, you 

   649 should see your new ``User Argument`` listed in the help display.

   650 

   651 Try,

   652 

   653 ::

   654 

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

   656 

   657 ::

   658 

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

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

   661   'build' finished successfully (0.403s)

   662   --PrintHelp: Print this help message.

   663   --PrintGroups: Print the list of groups.

   664   --PrintTypeIds: Print all TypeIds.

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

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

   667   --PrintGlobals: Print the list of globals.

   668   User Arguments:

   669       --nPackets: Number of packets to echo

   670 

   671 If you want to specify the number of packets to echo, you can now do so by

   672 setting the ``--nPackets`` argument in the command line,

   673 

   674 ::

   675 

   676   ./waf --run "scratch/myfirst --nPackets=2"

   677 

   678 You should now see

   679 

   680 ::

   681 

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

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

   684   'build' finished successfully (0.404s)

   685   0s UdpEchoServerApplication:UdpEchoServer()

   686   1s UdpEchoServerApplication:StartApplication()

   687   Sent 1024 bytes to 10.1.1.2

   688   2.25732s Received 1024 bytes from 10.1.1.1

   689   2.25732s Echoing packet

   690   Received 1024 bytes from 10.1.1.2

   691   Sent 1024 bytes to 10.1.1.2

   692   3.25732s Received 1024 bytes from 10.1.1.1

   693   3.25732s Echoing packet

   694   Received 1024 bytes from 10.1.1.2

   695   10s UdpEchoServerApplication:StopApplication()

   696   UdpEchoServerApplication:DoDispose()

   697   UdpEchoServerApplication:~UdpEchoServer()

   698 

   699 You have now echoed two packets.  Pretty easy, isn't it?

   700 

   701 You can see that if you are an |ns3| user, you can use the command 

   702 line argument system to control global values and ``Attributes``.  If you are

   703 a model author, you can add new ``Attributes`` to your ``Objects`` and 

   704 they will automatically be available for setting by your users through the

   705 command line system.  If you are a script author, you can add new variables to 

   706 your scripts and hook them into the command line system quite painlessly.

   707 

   708 Using the Tracing System

   709 ************************

   710 

   711 The whole point of simulation is to generate output for further study, and 

   712 the |ns3| tracing system is a primary mechanism for this.  Since 

   713 |ns3| is a C++ program, standard facilities for generating output 

   714 from C++ programs could be used:  

   715 

   716 ::

   717 

   718   #include <iostream>

   719   ...

   720   int main ()

   721   {

   722     ...

   723     std::cout << "The value of x is " << x << std::endl;

   724     ...

   725   } 

   726 

   727 You could even use the logging module to add a little structure to your 

   728 solution.  There are many well-known problems generated by such approaches

   729 and so we have provided a generic event tracing subsystem to address the 

   730 issues we thought were important.

   731 

   732 The basic goals of the |ns3| tracing system are:

   733 

   734 * For basic tasks, the tracing system should allow the user to generate 

   735   standard tracing for popular tracing sources, and to customize which objects

   736   generate the tracing;

   737 * Intermediate users must be able to extend the tracing system to modify

   738   the output format generated, or to insert new tracing sources, without 

   739   modifying the core of the simulator;

   740 * Advanced users can modify the simulator core to add new tracing sources

   741   and sinks.

   742 

   743 The |ns3| tracing system is built on the concepts of independent 

   744 tracing sources and tracing sinks, and a uniform mechanism for connecting

   745 sources to sinks.  Trace sources are entities that can signal events that

   746 happen in a simulation and provide access to interesting underlying data. 

   747 For example, a trace source could indicate when a packet is received by a net

   748 device and provide access to the packet contents for interested trace sinks.

   749 

   750 Trace sources are not useful by themselves, they must be "connected" to

   751 other pieces of code that actually do something useful with the information 

   752 provided by the sink.  Trace sinks are consumers of the events and data

   753 provided by the trace sources.  For example, one could create a trace sink 

   754 that would (when connected to the trace source of the previous example) print 

   755 out interesting parts of the received packet.

   756 

   757 The rationale for this explicit division is to allow users to attach new

   758 types of sinks to existing tracing sources, without requiring editing and 

   759 recompilation of the core of the simulator.  Thus, in the example above, 

   760 a user could define a new tracing sink in her script and attach it to an 

   761 existing tracing source defined in the simulation core by editing only the 

   762 user script.

   763 

   764 In this tutorial, we will walk through some pre-defined sources and sinks and

   765 show how they may be customized with little user effort.  See the ns-3 manual

   766 or how-to sections for information on advanced tracing configuration including

   767 extending the tracing namespace and creating new tracing sources.

   768 

   769 ASCII Tracing

   770 +++++++++++++

   771 |ns3| provides helper functionality that wraps the low-level tracing

   772 system to help you with the details involved in configuring some easily 

   773 understood packet traces.  If you enable this functionality, you will see

   774 output in a ASCII files --- thus the name.  For those familiar with 

   775 |ns2| output, this type of trace is analogous to the ``out.tr``

   776 generated by many scripts.

   777 

   778 Let's just jump right in and add some ASCII tracing output to our 

   779 ``scratch/myfirst.cc`` script.  Right before the call to 

   780 ``Simulator::Run ()``, add the following lines of code:

   781 

   782 ::

   783 

   784   AsciiTraceHelper ascii;

   785   pointToPoint.EnableAsciiAll (ascii.CreateFileStream ("myfirst.tr"));

   786 

   787 Like in many other |ns3| idioms, this code uses a  helper object to 

   788 help create ASCII traces.  The second line contains two nested method calls.  

   789 The "inside" method, ``CreateFileStream()`` uses an unnamed object idiom

   790 to create a file stream object on the stack (without an object  name) and pass

   791 it down to the called method.  We'll go into this more in the future, but all

   792 you have to know at this point is that you are creating an object representing

   793 a file named "myfirst.tr" and passing it into ``ns-3``.  You are telling 

   794 ``ns-3`` to deal with the lifetime issues of the created object and also to 

   795 deal with problems caused by a little-known (intentional) limitation of C++ 

   796 ofstream objects relating to copy constructors.

   797 

   798 The outside call, to ``EnableAsciiAll()``, tells the helper that you 

   799 want to enable ASCII tracing on all point-to-point devices in your simulation; 

   800 and you want the (provided) trace sinks to write out information about packet 

   801 movement in ASCII format.

   802 

   803 For those familiar with |ns2|, the traced events are equivalent to 

   804 the popular trace points that log "+", "-", "d", and "r" events.

   805 

   806 You can now build the script and run it from the command line:

   807 

   808 ::

   809 

   810   ./waf --run scratch/myfirst

   811 

   812 Just as you have seen many times before, you will see some messages from Waf and then

   813 "'build' finished successfully" with some number of messages from 

   814 the running program.  

   815 

   816 When it ran, the program will have created a file named ``myfirst.tr``.  

   817 Because of the way that Waf works, the file is not created in the local 

   818 directory, it is created at the top-level directory of the repository by 

   819 default.  If you want to control where the traces are saved you can use the 

   820 ``--cwd`` option of Waf to specify this.  We have not done so, thus we 

   821 need to change into the top level directory of our repo and take a look at 

   822 the ASCII trace file ``myfirst.tr`` in your favorite editor.

   823 

   824 Parsing Ascii Traces

   825 ~~~~~~~~~~~~~~~~~~~~

   826 There's a lot of information there in a pretty dense form, but the first thing

   827 to notice is that there are a number of distinct lines in this file.  It may

   828 be difficult to see this clearly unless you widen your window considerably.

   829 

   830 Each line in the file corresponds to a *trace event*.  In this case

   831 we are tracing events on the *transmit queue* present in every 

   832 point-to-point net device in the simulation.  The transmit queue is a queue 

   833 through which every packet destined for a point-to-point channel must pass.

   834 Note that each line in the trace file begins with a lone character (has a 

   835 space after it).  This character will have the following meaning:

   836 

   837 * ``+``: An enqueue operation occurred on the device queue;

   838 * ``-``: A dequeue operation occurred on the device queue;

   839 * ``d``: A packet was dropped, typically because the queue was full;

   840 * ``r``: A packet was received by the net device.

   841 

   842 Let's take a more detailed view of the first line in the trace file.  I'll 

   843 break it down into sections (indented for clarity) with a two digit reference

   844 number on the left side:

   845 

   846 ::

   847 

   848   00 + 

   849   01 2 

   850   02 /NodeList/0/DeviceList/0/$ns3::PointToPointNetDevice/TxQueue/Enqueue 

   851   03 ns3::PppHeader (

   852   04   Point-to-Point Protocol: IP (0x0021)) 

   853   05   ns3::Ipv4Header (

   854   06     tos 0x0 ttl 64 id 0 protocol 17 offset 0 flags [none] 

   855   07     length: 1052 10.1.1.1 > 10.1.1.2)

   856   08     ns3::UdpHeader (

   857   09       length: 1032 49153 > 9) 

   858   10       Payload (size=1024)

   859 

   860 The first line of this expanded trace event (reference number 00) is the 

   861 operation.  We have a ``+`` character, so this corresponds to an

   862 *enqueue* operation on the transmit queue.  The second line (reference 01)

   863 is the simulation time expressed in seconds.  You may recall that we asked the 

   864 ``UdpEchoClientApplication`` to start sending packets at two seconds.  Here

   865 we see confirmation that this is, indeed, happening.

   866 

   867 The next line of the example trace (reference 02) tell us which trace source

   868 originated this event (expressed in the tracing namespace).  You can think

   869 of the tracing namespace somewhat like you would a filesystem namespace.  The 

   870 root of the namespace is the ``NodeList``.  This corresponds to a container

   871 managed in the |ns3| core code that contains all of the nodes that are

   872 created in a script.  Just as a filesystem may have directories under the 

   873 root, we may have node numbers in the ``NodeList``.  The string 

   874 ``/NodeList/0`` therefore refers to the zeroth node in the ``NodeList``

   875 which we typically think of as "node 0".  In each node there is a list of 

   876 devices that have been installed.  This list appears next in the namespace.

   877 You can see that this trace event comes from ``DeviceList/0`` which is the 

   878 zeroth device installed in the node. 

   879 

   880 The next string, ``$ns3::PointToPointNetDevice`` tells you what kind of 

   881 device is in the zeroth position of the device list for node zero.

   882 Recall that the operation ``+`` found at reference 00 meant that an enqueue 

   883 operation happened on the transmit queue of the device.  This is reflected in 

   884 the final segments of the "trace path" which are ``TxQueue/Enqueue``.

   885 

   886 The remaining lines in the trace should be fairly intuitive.  References 03-04

   887 indicate that the packet is encapsulated in the point-to-point protocol.  

   888 References 05-07 show that the packet has an IP version four header and has

   889 originated from IP address 10.1.1.1 and is destined for 10.1.1.2.  References

   890 08-09 show that this packet has a UDP header and, finally, reference 10 shows

   891 that the payload is the expected 1024 bytes.

   892 

   893 The next line in the trace file shows the same packet being dequeued from the

   894 transmit queue on the same node. 

   895 

   896 The Third line in the trace file shows the packet being received by the net

   897 device on the node with the echo server. I have reproduced that event below.

   898 

   899 ::

   900 

   901   00 r 

   902   01 2.25732 

   903   02 /NodeList/1/DeviceList/0/$ns3::PointToPointNetDevice/MacRx 

   904   03   ns3::Ipv4Header (

   905   04     tos 0x0 ttl 64 id 0 protocol 17 offset 0 flags [none]

   906   05     length: 1052 10.1.1.1 > 10.1.1.2)

   907   06     ns3::UdpHeader (

   908   07       length: 1032 49153 > 9) 

   909   08       Payload (size=1024)

   910 

   911 Notice that the trace operation is now ``r`` and the simulation time has

   912 increased to 2.25732 seconds.  If you have been following the tutorial steps

   913 closely this means that you have left the ``DataRate`` of the net devices

   914 and the channel ``Delay`` set to their default values.  This time should 

   915 be familiar as you have seen it before in a previous section.

   916 

   917 The trace source namespace entry (reference 02) has changed to reflect that

   918 this event is coming from node 1 (``/NodeList/1``) and the packet reception

   919 trace source (``/MacRx``).  It should be quite easy for you to follow the 

   920 progress of the packet through the topology by looking at the rest of the 

   921 traces in the file.

   922 

   923 PCAP Tracing

   924 ++++++++++++

   925 The |ns3| device helpers can also be used to create trace files in the

   926 ``.pcap`` format.  The acronym pcap (usually written in lower case) stands

   927 for packet capture, and is actually an API that includes the 

   928 definition of a ``.pcap`` file format.  The most popular program that can

   929 read and display this format is Wireshark (formerly called Ethereal).

   930 However, there are many traffic trace analyzers that use this packet format.

   931 We encourage users to exploit the many tools available for analyzing pcap

   932 traces.  In this tutorial, we concentrate on viewing pcap traces with tcpdump.

   933 

   934 The code used to enable pcap tracing is a one-liner.  

   935 

   936 ::

   937 

   938   pointToPoint.EnablePcapAll ("myfirst");

   939 

   940 Go ahead and insert this line of code after the ASCII tracing code we just 

   941 added to ``scratch/myfirst.cc``.  Notice that we only passed the string

   942 "myfirst," and not "myfirst.pcap" or something similar.  This is because the 

   943 parameter is a prefix, not a complete file name.  The helper will actually 

   944 create a trace file for every point-to-point device in the simulation.  The 

   945 file names will be built using the prefix, the node number, the device number

   946 and a ".pcap" suffix.

   947 

   948 In our example script, we will eventually see files named "myfirst-0-0.pcap" 

   949 and "myfirst-1-0.pcap" which are the pcap traces for node 0-device 0 and 

   950 node 1-device 0, respectively.

   951 

   952 Once you have added the line of code to enable pcap tracing, you can run the

   953 script in the usual way:

   954 

   955 ::

   956 

   957   ./waf --run scratch/myfirst

   958 

   959 If you look at the top level directory of your distribution, you should now

   960 see three log files:  ``myfirst.tr`` is the ASCII trace file we have 

   961 previously examined.  ``myfirst-0-0.pcap`` and ``myfirst-1-0.pcap``

   962 are the new pcap files we just generated.  

   963 

   964 Reading output with tcpdump

   965 ~~~~~~~~~~~~~~~~~~~~~~~~~~~

   966 The easiest thing to do at this point will be to use ``tcpdump`` to look

   967 at the ``pcap`` files.  

   968 

   969 ::

   970 

   971   tcpdump -nn -tt -r myfirst-0-0.pcap

   972   reading from file myfirst-0-0.pcap, link-type PPP (PPP)

   973   2.000000 IP 10.1.1.1.49153 > 10.1.1.2.9: UDP, length 1024

   974   2.514648 IP 10.1.1.2.9 > 10.1.1.1.49153: UDP, length 1024

   975 

   976   tcpdump -nn -tt -r myfirst-1-0.pcap

   977   reading from file myfirst-1-0.pcap, link-type PPP (PPP)

   978   2.257324 IP 10.1.1.1.49153 > 10.1.1.2.9: UDP, length 1024

   979   2.257324 IP 10.1.1.2.9 > 10.1.1.1.49153: UDP, length 1024

   980 

   981 You can see in the dump of ``myfirst-0-0.pcap`` (the client device) that the 

   982 echo packet is sent at 2 seconds into the simulation.  If you look at the

   983 second dump (``myfirst-1-0.pcap``) you can see that packet being received

   984 at 2.257324 seconds.  You see the packet being echoed back at 2.257324 seconds

   985 in the second dump, and finally, you see the packet being received back at 

   986 the client in the first dump at 2.514648 seconds.

   987 

   988 Reading output with Wireshark

   989 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

   990 If you are unfamiliar with Wireshark, there is a web site available from which

   991 you can download programs and documentation:  http://www.wireshark.org/.

   992 

   993 Wireshark is a graphical user interface which can be used for displaying these

   994 trace files.  If you have Wireshark available, you can open each of the trace

   995 files and display the contents as if you had captured the packets using a

   996 *packet sniffer*.