1.. include:: replace.txt 2.. highlight:: cpp 3 4 5Tweaking 6-------- 7 8.. _UsingLogging: 9 10Using the Logging Module 11************************ 12 13We have already taken a brief look at the |ns3| logging module while 14going over the ``first.cc`` script. We will now take a closer look and 15see what kind of use-cases the logging subsystem was designed to cover. 16 17Logging Overview 18++++++++++++++++ 19Many large systems support some kind of message logging facility, and 20|ns3| is not an exception. In some cases, only error messages are 21logged to the "operator console" (which is typically ``stderr`` in Unix- 22based systems). In other systems, warning messages may be output as well as 23more detailed informational messages. In some cases, logging facilities are 24used to output debug messages which can quickly turn the output into a blur. 25 26|ns3| takes the view that all of these verbosity levels are useful 27and we provide a selectable, multi-level approach to message logging. Logging 28can be disabled completely, enabled on a component-by-component basis, or 29enabled globally; and it provides selectable verbosity levels. The 30|ns3| log module provides a straightforward, relatively easy to use 31way to get useful information out of your simulation. 32 33You should understand that we do provide a general purpose mechanism --- 34tracing --- to get data out of your models which should be preferred for 35simulation output (see the tutorial section Using the Tracing System for 36more details on our tracing system). Logging should be preferred for 37debugging information, warnings, error messages, or any time you want to 38easily get a quick message out of your scripts or models. 39 40There are currently seven levels of log messages of increasing verbosity 41defined in the system. 42 43* LOG_ERROR --- Log error messages (associated macro: NS_LOG_ERROR); 44* LOG_WARN --- Log warning messages (associated macro: NS_LOG_WARN); 45* LOG_DEBUG --- Log relatively rare, ad-hoc debugging messages 46 (associated macro: NS_LOG_DEBUG); 47* LOG_INFO --- Log informational messages about program progress 48 (associated macro: NS_LOG_INFO); 49* LOG_FUNCTION --- Log a message describing each function called 50 (two associated macros: NS_LOG_FUNCTION, used for member functions, 51 and NS_LOG_FUNCTION_NOARGS, used for static functions); 52* LOG_LOGIC -- Log messages describing logical flow within a function 53 (associated macro: NS_LOG_LOGIC); 54* LOG_ALL --- Log everything mentioned above (no associated macro). 55 56For each LOG_TYPE there is also LOG_LEVEL_TYPE that, if used, enables 57logging of all the levels above it in addition to it's level. (As a 58consequence of this, LOG_ERROR and LOG_LEVEL_ERROR and also LOG_ALL 59and LOG_LEVEL_ALL are functionally equivalent.) For example, 60enabling LOG_INFO will only enable messages provided by NS_LOG_INFO macro, 61while enabling LOG_LEVEL_INFO will also enable messages provided by 62NS_LOG_DEBUG, NS_LOG_WARN and NS_LOG_ERROR macros. 63 64We also provide an unconditional logging macro that is always displayed, 65irrespective of logging levels or component selection. 66 67* NS_LOG_UNCOND -- Log the associated message unconditionally (no associated 68 log level). 69 70Each level can be requested singly or cumulatively; and logging can be set 71up using a shell environment variable (NS_LOG) or by logging system function 72call. As was seen earlier in the tutorial, the logging system has Doxygen 73documentation and now would be a good time to peruse the Logging Module 74documentation if you have not done so. 75 76Now that you have read the documentation in great detail, let's use some of 77that knowledge to get some interesting information out of the 78``scratch/myfirst.cc`` example script you have already built. 79 80Enabling Logging 81++++++++++++++++ 82Let's use the NS_LOG environment variable to turn on some more logging, but 83first, just to get our bearings, go ahead and run the last script just as you 84did previously, 85 86.. sourcecode:: bash 87 88 $ ./waf --run scratch/myfirst 89 90You should see the now familiar output of the first |ns3| example 91program 92 93.. sourcecode:: bash 94 95 $ Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 96 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 97 'build' finished successfully (0.413s) 98 Sent 1024 bytes to 10.1.1.2 99 Received 1024 bytes from 10.1.1.1 100 Received 1024 bytes from 10.1.1.2 101 102It turns out that the "Sent" and "Received" messages you see above are 103actually logging messages from the ``UdpEchoClientApplication`` and 104``UdpEchoServerApplication``. We can ask the client application, for 105example, to print more information by setting its logging level via the 106NS_LOG environment variable. 107 108I am going to assume from here on that you are using an sh-like shell that uses 109the"VARIABLE=value" syntax. If you are using a csh-like shell, then you 110will have to convert my examples to the "setenv VARIABLE value" syntax 111required by those shells. 112 113Right now, the UDP echo client application is responding to the following line 114of code in ``scratch/myfirst.cc``, 115 116:: 117 118 LogComponentEnable("UdpEchoClientApplication", LOG_LEVEL_INFO); 119 120This line of code enables the ``LOG_LEVEL_INFO`` level of logging. When 121we pass a logging level flag, we are actually enabling the given level and 122all lower levels. In this case, we have enabled ``NS_LOG_INFO``, 123``NS_LOG_DEBUG``, ``NS_LOG_WARN`` and ``NS_LOG_ERROR``. We can 124increase the logging level and get more information without changing the 125script and recompiling by setting the NS_LOG environment variable like this: 126 127.. sourcecode:: bash 128 129 $ export NS_LOG=UdpEchoClientApplication=level_all 130 131This sets the shell environment variable ``NS_LOG`` to the string, 132 133.. sourcecode:: bash 134 135 UdpEchoClientApplication=level_all 136 137The left hand side of the assignment is the name of the logging component we 138want to set, and the right hand side is the flag we want to use. In this case, 139we are going to turn on all of the debugging levels for the application. If 140you run the script with NS_LOG set this way, the |ns3| logging 141system will pick up the change and you should see the following output: 142 143.. sourcecode:: bash 144 145 Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 146 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 147 'build' finished successfully (0.404s) 148 UdpEchoClientApplication:UdpEchoClient() 149 UdpEchoClientApplication:SetDataSize(1024) 150 UdpEchoClientApplication:StartApplication() 151 UdpEchoClientApplication:ScheduleTransmit() 152 UdpEchoClientApplication:Send() 153 Sent 1024 bytes to 10.1.1.2 154 Received 1024 bytes from 10.1.1.1 155 UdpEchoClientApplication:HandleRead(0x6241e0, 0x624a20) 156 Received 1024 bytes from 10.1.1.2 157 UdpEchoClientApplication:StopApplication() 158 UdpEchoClientApplication:DoDispose() 159 UdpEchoClientApplication:~UdpEchoClient() 160 161The additional debug information provided by the application is from 162the NS_LOG_FUNCTION level. This shows every time a function in the application 163is called during script execution. Generally, use of (at least) 164NS_LOG_FUNCTION(this) in member functions is preferred. Use 165NS_LOG_FUNCTION_NOARGS() only in static functions. Note, however, that there 166are no requirements in the |ns3| system that models must support any particular 167logging functionality. The decision regarding how much information is logged 168is left to the individual model developer. In the case of the echo 169applications, a good deal of log output is available. 170 171You can now see a log of the function calls that were made to the application. 172If you look closely you will notice a single colon between the string 173``UdpEchoClientApplication`` and the method name where you might have 174expected a C++ scope operator (``::``). This is intentional. 175 176The name is not actually a class name, it is a logging component name. When 177there is a one-to-one correspondence between a source file and a class, this 178will generally be the class name but you should understand that it is not 179actually a class name, and there is a single colon there instead of a double 180colon to remind you in a relatively subtle way to conceptually separate the 181logging component name from the class name. 182 183It turns out that in some cases, it can be hard to determine which method 184actually generates a log message. If you look in the text above, you may 185wonder where the string "``Received 1024 bytes from 10.1.1.2``" comes 186from. You can resolve this by OR'ing the ``prefix_func`` level into the 187``NS_LOG`` environment variable. Try doing the following, 188 189.. sourcecode:: bash 190 191 $ export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func' 192 193Note that the quotes are required since the vertical bar we use to indicate an 194OR operation is also a Unix pipe connector. 195 196Now, if you run the script you will see that the logging system makes sure 197that every message from the given log component is prefixed with the component 198name. 199 200.. sourcecode:: bash 201 202 Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 203 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 204 'build' finished successfully (0.417s) 205 UdpEchoClientApplication:UdpEchoClient() 206 UdpEchoClientApplication:SetDataSize(1024) 207 UdpEchoClientApplication:StartApplication() 208 UdpEchoClientApplication:ScheduleTransmit() 209 UdpEchoClientApplication:Send() 210 UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2 211 Received 1024 bytes from 10.1.1.1 212 UdpEchoClientApplication:HandleRead(0x6241e0, 0x624a20) 213 UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2 214 UdpEchoClientApplication:StopApplication() 215 UdpEchoClientApplication:DoDispose() 216 UdpEchoClientApplication:~UdpEchoClient() 217 218You can now see all of the messages coming from the UDP echo client application 219are identified as such. The message "Received 1024 bytes from 10.1.1.2" is 220now clearly identified as coming from the echo client application. The 221remaining message must be coming from the UDP echo server application. We 222can enable that component by entering a colon separated list of components in 223the NS_LOG environment variable. 224 225.. sourcecode:: bash 226 227 $ export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func: 228 UdpEchoServerApplication=level_all|prefix_func' 229 230Warning: You will need to remove the newline after the ``:`` in the 231example text above which is only there for document formatting purposes. 232 233Now, if you run the script you will see all of the log messages from both the 234echo client and server applications. You may see that this can be very useful 235in debugging problems. 236 237.. sourcecode:: bash 238 239 Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 240 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 241 'build' finished successfully (0.406s) 242 UdpEchoServerApplication:UdpEchoServer() 243 UdpEchoClientApplication:UdpEchoClient() 244 UdpEchoClientApplication:SetDataSize(1024) 245 UdpEchoServerApplication:StartApplication() 246 UdpEchoClientApplication:StartApplication() 247 UdpEchoClientApplication:ScheduleTransmit() 248 UdpEchoClientApplication:Send() 249 UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2 250 UdpEchoServerApplication:HandleRead(): Received 1024 bytes from 10.1.1.1 251 UdpEchoServerApplication:HandleRead(): Echoing packet 252 UdpEchoClientApplication:HandleRead(0x624920, 0x625160) 253 UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2 254 UdpEchoServerApplication:StopApplication() 255 UdpEchoClientApplication:StopApplication() 256 UdpEchoClientApplication:DoDispose() 257 UdpEchoServerApplication:DoDispose() 258 UdpEchoClientApplication:~UdpEchoClient() 259 UdpEchoServerApplication:~UdpEchoServer() 260 261It is also sometimes useful to be able to see the simulation time at which a 262log message is generated. You can do this by ORing in the prefix_time bit. 263 264.. sourcecode:: bash 265 266 $ export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func|prefix_time: 267 UdpEchoServerApplication=level_all|prefix_func|prefix_time' 268 269Again, you will have to remove the newline above. If you run the script now, 270you should see the following output: 271 272.. sourcecode:: bash 273 274 Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 275 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 276 'build' finished successfully (0.418s) 277 0s UdpEchoServerApplication:UdpEchoServer() 278 0s UdpEchoClientApplication:UdpEchoClient() 279 0s UdpEchoClientApplication:SetDataSize(1024) 280 1s UdpEchoServerApplication:StartApplication() 281 2s UdpEchoClientApplication:StartApplication() 282 2s UdpEchoClientApplication:ScheduleTransmit() 283 2s UdpEchoClientApplication:Send() 284 2s UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2 285 2.00369s UdpEchoServerApplication:HandleRead(): Received 1024 bytes from 10.1.1.1 286 2.00369s UdpEchoServerApplication:HandleRead(): Echoing packet 287 2.00737s UdpEchoClientApplication:HandleRead(0x624290, 0x624ad0) 288 2.00737s UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2 289 10s UdpEchoServerApplication:StopApplication() 290 10s UdpEchoClientApplication:StopApplication() 291 UdpEchoClientApplication:DoDispose() 292 UdpEchoServerApplication:DoDispose() 293 UdpEchoClientApplication:~UdpEchoClient() 294 UdpEchoServerApplication:~UdpEchoServer() 295 296You can see that the constructor for the UdpEchoServer was called at a 297simulation time of 0 seconds. This is actually happening before the 298simulation starts, but the time is displayed as zero seconds. The same is true 299for the UdpEchoClient constructor message. 300 301Recall that the ``scratch/first.cc`` script started the echo server 302application at one second into the simulation. You can now see that the 303``StartApplication`` method of the server is, in fact, called at one second. 304You can also see that the echo client application is started at a simulation 305time of two seconds as we requested in the script. 306 307You can now follow the progress of the simulation from the 308``ScheduleTransmit`` call in the client that calls ``Send`` to the 309``HandleRead`` callback in the echo server application. Note that the 310elapsed time for the packet to be sent across the point-to-point link is 3.69 311milliseconds. You see the echo server logging a message telling you that it 312has echoed the packet and then, after another channel delay, you see the echo 313client receive the echoed packet in its ``HandleRead`` method. 314 315There is a lot that is happening under the covers in this simulation that you 316are not seeing as well. You can very easily follow the entire process by 317turning on all of the logging components in the system. Try setting the 318``NS_LOG`` variable to the following, 319 320.. sourcecode:: bash 321 322 $ export 'NS_LOG=*=level_all|prefix_func|prefix_time' 323 324The asterisk above is the logging component wildcard. This will turn on all 325of the logging in all of the components used in the simulation. I won't 326reproduce the output here (as of this writing it produces 1265 lines of output 327for the single packet echo) but you can redirect this information into a file 328and look through it with your favorite editor if you like, 329 330.. sourcecode:: bash 331 332 $ ./waf --run scratch/myfirst > log.out 2>&1 333 334I personally use this extremely verbose version of logging when I am presented 335with a problem and I have no idea where things are going wrong. I can follow the 336progress of the code quite easily without having to set breakpoints and step 337through code in a debugger. I can just edit up the output in my favorite editor 338and search around for things I expect, and see things happening that I don't 339expect. When I have a general idea about what is going wrong, I transition into 340a debugger for a fine-grained examination of the problem. This kind of output 341can be especially useful when your script does something completely unexpected. 342If you are stepping using a debugger you may miss an unexpected excursion 343completely. Logging the excursion makes it quickly visible. 344 345Adding Logging to your Code 346+++++++++++++++++++++++++++ 347You can add new logging to your simulations by making calls to the log 348component via several macros. Let's do so in the ``myfirst.cc`` script we 349have in the ``scratch`` directory. 350 351Recall that we have defined a logging component in that script: 352 353:: 354 355 NS_LOG_COMPONENT_DEFINE ("FirstScriptExample"); 356 357You now know that you can enable all of the logging for this component by 358setting the ``NS_LOG`` environment variable to the various levels. Let's 359go ahead and add some logging to the script. The macro used to add an 360informational level log message is ``NS_LOG_INFO``. Go ahead and add one 361(just before we start creating the nodes) that tells you that the script is 362"Creating Topology." This is done as in this code snippet, 363 364Open ``scratch/myfirst.cc`` in your favorite editor and add the line, 365 366:: 367 368 NS_LOG_INFO ("Creating Topology"); 369 370right before the lines, 371 372:: 373 374 NodeContainer nodes; 375 nodes.Create (2); 376 377Now build the script using waf and clear the ``NS_LOG`` variable to turn 378off the torrent of logging we previously enabled: 379 380.. sourcecode:: bash 381 382 $ ./waf 383 $ export NS_LOG= 384 385Now, if you run the script, 386 387.. sourcecode:: bash 388 389 $ ./waf --run scratch/myfirst 390 391you will ``not`` see your new message since its associated logging 392component (``FirstScriptExample``) has not been enabled. In order to see your 393message you will have to enable the ``FirstScriptExample`` logging component 394with a level greater than or equal to ``NS_LOG_INFO``. If you just want to 395see this particular level of logging, you can enable it by, 396 397.. sourcecode:: bash 398 399 $ export NS_LOG=FirstScriptExample=info 400 401If you now run the script you will see your new "Creating Topology" log 402message, 403 404.. sourcecode:: bash 405 406 Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 407 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 408 'build' finished successfully (0.404s) 409 Creating Topology 410 Sent 1024 bytes to 10.1.1.2 411 Received 1024 bytes from 10.1.1.1 412 Received 1024 bytes from 10.1.1.2 413 414Using Command Line Arguments 415**************************** 416 417.. _Attribute: 418 419Overriding Default Attributes 420+++++++++++++++++++++++++++++ 421Another way you can change how |ns3| scripts behave without editing 422and building is via *command line arguments.* We provide a mechanism to 423parse command line arguments and automatically set local and global variables 424based on those arguments. 425 426The first step in using the command line argument system is to declare the 427command line parser. This is done quite simply (in your main program) as 428in the following code, 429 430:: 431 432 int 433 main (int argc, char *argv[]) 434 { 435 ... 436 437 CommandLine cmd; 438 cmd.Parse (argc, argv); 439 440 ... 441 } 442 443This simple two line snippet is actually very useful by itself. It opens the 444door to the |ns3| global variable and ``Attribute`` systems. Go 445ahead and add that two lines of code to the ``scratch/myfirst.cc`` script at 446the start of ``main``. Go ahead and build the script and run it, but ask 447the script for help in the following way, 448 449.. sourcecode:: bash 450 451 $ ./waf --run "scratch/myfirst --PrintHelp" 452 453This will ask Waf to run the ``scratch/myfirst`` script and pass the command 454line argument ``--PrintHelp`` to the script. The quotes are required to 455sort out which program gets which argument. The command line parser will 456now see the ``--PrintHelp`` argument and respond with, 457 458.. sourcecode:: bash 459 460 Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 461 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 462 'build' finished successfully (0.413s) 463 TcpL4Protocol:TcpStateMachine() 464 CommandLine:HandleArgument(): Handle arg name=PrintHelp value= 465 --PrintHelp: Print this help message. 466 --PrintGroups: Print the list of groups. 467 --PrintTypeIds: Print all TypeIds. 468 --PrintGroup=[group]: Print all TypeIds of group. 469 --PrintAttributes=[typeid]: Print all attributes of typeid. 470 --PrintGlobals: Print the list of globals. 471 472Let's focus on the ``--PrintAttributes`` option. We have already hinted 473at the |ns3| ``Attribute`` system while walking through the 474``first.cc`` script. We looked at the following lines of code, 475 476:: 477 478 PointToPointHelper pointToPoint; 479 pointToPoint.SetDeviceAttribute ("DataRate", StringValue ("5Mbps")); 480 pointToPoint.SetChannelAttribute ("Delay", StringValue ("2ms")); 481 482and mentioned that ``DataRate`` was actually an ``Attribute`` of the 483``PointToPointNetDevice``. Let's use the command line argument parser 484to take a look at the ``Attributes`` of the PointToPointNetDevice. The help 485listing says that we should provide a ``TypeId``. This corresponds to the 486class name of the class to which the ``Attributes`` belong. In this case it 487will be ``ns3::PointToPointNetDevice``. Let's go ahead and type in, 488 489.. sourcecode:: bash 490 491 $ ./waf --run "scratch/myfirst --PrintAttributes=ns3::PointToPointNetDevice" 492 493The system will print out all of the ``Attributes`` of this kind of net device. 494Among the ``Attributes`` you will see listed is, 495 496.. sourcecode:: bash 497 498 --ns3::PointToPointNetDevice::DataRate=[32768bps]: 499 The default data rate for point to point links 500 501This is the default value that will be used when a ``PointToPointNetDevice`` 502is created in the system. We overrode this default with the ``Attribute`` 503setting in the ``PointToPointHelper`` above. Let's use the default values 504for the point-to-point devices and channels by deleting the 505``SetDeviceAttribute`` call and the ``SetChannelAttribute`` call from 506the ``myfirst.cc`` we have in the scratch directory. 507 508Your script should now just declare the ``PointToPointHelper`` and not do 509any ``set`` operations as in the following example, 510 511:: 512 513 ... 514 515 NodeContainer nodes; 516 nodes.Create (2); 517 518 PointToPointHelper pointToPoint; 519 520 NetDeviceContainer devices; 521 devices = pointToPoint.Install (nodes); 522 523 ... 524 525Go ahead and build the new script with Waf (``./waf``) and let's go back 526and enable some logging from the UDP echo server application and turn on the 527time prefix. 528 529.. sourcecode:: bash 530 531 $ export 'NS_LOG=UdpEchoServerApplication=level_all|prefix_time' 532 533If you run the script, you should now see the following output, 534 535.. sourcecode:: bash 536 537 Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 538 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 539 'build' finished successfully (0.405s) 540 0s UdpEchoServerApplication:UdpEchoServer() 541 1s UdpEchoServerApplication:StartApplication() 542 Sent 1024 bytes to 10.1.1.2 543 2.25732s Received 1024 bytes from 10.1.1.1 544 2.25732s Echoing packet 545 Received 1024 bytes from 10.1.1.2 546 10s UdpEchoServerApplication:StopApplication() 547 UdpEchoServerApplication:DoDispose() 548 UdpEchoServerApplication:~UdpEchoServer() 549 550Recall that the last time we looked at the simulation time at which the packet 551was received by the echo server, it was at 2.00369 seconds. 552 553.. sourcecode:: bash 554 555 2.00369s UdpEchoServerApplication:HandleRead(): Received 1024 bytes from 10.1.1.1 556 557Now it is receiving the packet at 2.25732 seconds. This is because we just dropped 558the data rate of the ``PointToPointNetDevice`` down to its default of 55932768 bits per second from five megabits per second. 560 561If we were to provide a new ``DataRate`` using the command line, we could 562speed our simulation up again. We do this in the following way, according to 563the formula implied by the help item: 564 565.. sourcecode:: bash 566 567 $ ./waf --run "scratch/myfirst --ns3::PointToPointNetDevice::DataRate=5Mbps" 568 569This will set the default value of the ``DataRate`` ``Attribute`` back to 570five megabits per second. Are you surprised by the result? It turns out that 571in order to get the original behavior of the script back, we will have to set 572the speed-of-light delay of the channel as well. We can ask the command line 573system to print out the ``Attributes`` of the channel just like we did for 574the net device: 575 576.. sourcecode:: bash 577 578 $ ./waf --run "scratch/myfirst --PrintAttributes=ns3::PointToPointChannel" 579 580We discover the ``Delay`` ``Attribute`` of the channel is set in the following 581way: 582 583.. sourcecode:: bash 584 585 --ns3::PointToPointChannel::Delay=[0ns]: 586 Transmission delay through the channel 587 588We can then set both of these default values through the command line system, 589 590.. sourcecode:: bash 591 592 $ ./waf --run "scratch/myfirst 593 --ns3::PointToPointNetDevice::DataRate=5Mbps 594 --ns3::PointToPointChannel::Delay=2ms" 595 596in which case we recover the timing we had when we explicitly set the 597``DataRate`` and ``Delay`` in the script: 598 599.. sourcecode:: bash 600 601 Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 602 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 603 'build' finished successfully (0.417s) 604 0s UdpEchoServerApplication:UdpEchoServer() 605 1s UdpEchoServerApplication:StartApplication() 606 Sent 1024 bytes to 10.1.1.2 607 2.00369s Received 1024 bytes from 10.1.1.1 608 2.00369s Echoing packet 609 Received 1024 bytes from 10.1.1.2 610 10s UdpEchoServerApplication:StopApplication() 611 UdpEchoServerApplication:DoDispose() 612 UdpEchoServerApplication:~UdpEchoServer() 613 614Note that the packet is again received by the server at 2.00369 seconds. We 615could actually set any of the ``Attributes`` used in the script in this way. 616In particular we could set the ``UdpEchoClient Attribute MaxPackets`` 617to some other value than one. 618 619How would you go about that? Give it a try. Remember you have to comment 620out the place we override the default ``Attribute`` and explicitly set 621``MaxPackets`` in the script. Then you have to rebuild the script. You 622will also have to find the syntax for actually setting the new default attribute 623value using the command line help facility. Once you have this figured out 624you should be able to control the number of packets echoed from the command 625line. Since we're nice folks, we'll tell you that your command line should 626end up looking something like, 627 628.. sourcecode:: bash 629 630 $ ./waf --run "scratch/myfirst 631 --ns3::PointToPointNetDevice::DataRate=5Mbps 632 --ns3::PointToPointChannel::Delay=2ms 633 --ns3::UdpEchoClient::MaxPackets=2" 634 635A natural question to arise at this point is how to learn about the existence 636of all of these attributes. Again, the command line help facility has 637a feature for this. If we ask for command line help we should see: 638 639.. sourcecode:: bash 640 641 $ ./waf --run "scratch/myfirst --PrintHelp" 642 myfirst [Program Arguments] [General Arguments] 643 644 General Arguments: 645 --PrintGlobals: Print the list of globals. 646 --PrintGroups: Print the list of groups. 647 --PrintGroup=[group]: Print all TypeIds of group. 648 --PrintTypeIds: Print all TypeIds. 649 --PrintAttributes=[typeid]: Print all attributes of typeid. 650 --PrintHelp: Print this help message. 651 652If you select the "PrintGroups" argument, you should see a list of all 653registered TypeId groups. The group names are aligned with the module names 654in the source directory (although with a leading capital letter). Printing 655out all of the information at once would be too much, so a further filter 656is available to print information on a per-group basis. So, focusing 657again on the point-to-point module: 658 659.. sourcecode:: bash 660 661 ./waf --run "scratch/myfirst --PrintGroup=PointToPoint" 662 TypeIds in group PointToPoint: 663 ns3::PointToPointChannel 664 ns3::PointToPointNetDevice 665 ns3::PointToPointRemoteChannel 666 ns3::PppHeader 667 668and from here, one can find the possible TypeId names to search for 669attributes, such as in the ``--PrintAttributes=ns3::PointToPointChannel`` 670example shown above. 671 672Another way to find out about attributes is through the ns-3 Doxygen; there 673is a page that lists out all of the registered attributes in the simulator. 674 675Hooking Your Own Values 676+++++++++++++++++++++++ 677You can also add your own hooks to the command line system. This is done 678quite simply by using the ``AddValue`` method to the command line parser. 679 680Let's use this facility to specify the number of packets to echo in a 681completely different way. Let's add a local variable called ``nPackets`` 682to the ``main`` function. We'll initialize it to one to match our previous 683default behavior. To allow the command line parser to change this value, we 684need to hook the value into the parser. We do this by adding a call to 685``AddValue``. Go ahead and change the ``scratch/myfirst.cc`` script to 686start with the following code, 687 688:: 689 690 int 691 main (int argc, char *argv[]) 692 { 693 uint32_t nPackets = 1; 694 695 CommandLine cmd; 696 cmd.AddValue("nPackets", "Number of packets to echo", nPackets); 697 cmd.Parse (argc, argv); 698 699 ... 700 701Scroll down to the point in the script where we set the ``MaxPackets`` 702``Attribute`` and change it so that it is set to the variable ``nPackets`` 703instead of the constant ``1`` as is shown below. 704 705:: 706 707 echoClient.SetAttribute ("MaxPackets", UintegerValue (nPackets)); 708 709Now if you run the script and provide the ``--PrintHelp`` argument, you 710should see your new ``User Argument`` listed in the help display. 711 712Try, 713 714.. sourcecode:: bash 715 716 $ ./waf --run "scratch/myfirst --PrintHelp" 717 718.. sourcecode:: bash 719 720 Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 721 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 722 'build' finished successfully (0.403s) 723 --PrintHelp: Print this help message. 724 --PrintGroups: Print the list of groups. 725 --PrintTypeIds: Print all TypeIds. 726 --PrintGroup=[group]: Print all TypeIds of group. 727 --PrintAttributes=[typeid]: Print all attributes of typeid. 728 --PrintGlobals: Print the list of globals. 729 User Arguments: 730 --nPackets: Number of packets to echo 731 732If you want to specify the number of packets to echo, you can now do so by 733setting the ``--nPackets`` argument in the command line, 734 735.. sourcecode:: bash 736 737 $ ./waf --run "scratch/myfirst --nPackets=2" 738 739You should now see 740 741.. sourcecode:: bash 742 743 Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 744 Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build' 745 'build' finished successfully (0.404s) 746 0s UdpEchoServerApplication:UdpEchoServer() 747 1s UdpEchoServerApplication:StartApplication() 748 Sent 1024 bytes to 10.1.1.2 749 2.25732s Received 1024 bytes from 10.1.1.1 750 2.25732s Echoing packet 751 Received 1024 bytes from 10.1.1.2 752 Sent 1024 bytes to 10.1.1.2 753 3.25732s Received 1024 bytes from 10.1.1.1 754 3.25732s Echoing packet 755 Received 1024 bytes from 10.1.1.2 756 10s UdpEchoServerApplication:StopApplication() 757 UdpEchoServerApplication:DoDispose() 758 UdpEchoServerApplication:~UdpEchoServer() 759 760You have now echoed two packets. Pretty easy, isn't it? 761 762You can see that if you are an |ns3| user, you can use the command 763line argument system to control global values and ``Attributes``. If you are 764a model author, you can add new ``Attributes`` to your ``Objects`` and 765they will automatically be available for setting by your users through the 766command line system. If you are a script author, you can add new variables to 767your scripts and hook them into the command line system quite painlessly. 768 769.. _UsingTracingSystem: 770 771Using the Tracing System 772************************ 773 774The whole point of simulation is to generate output for further study, and 775the |ns3| tracing system is a primary mechanism for this. Since 776|ns3| is a C++ program, standard facilities for generating output 777from C++ programs could be used: 778 779:: 780 781 #include <iostream> 782 ... 783 int main () 784 { 785 ... 786 std::cout << "The value of x is " << x << std::endl; 787 ... 788 } 789 790You could even use the logging module to add a little structure to your 791solution. There are many well-known problems generated by such approaches 792and so we have provided a generic event tracing subsystem to address the 793issues we thought were important. 794 795The basic goals of the |ns3| tracing system are: 796 797* For basic tasks, the tracing system should allow the user to generate 798 standard tracing for popular tracing sources, and to customize which objects 799 generate the tracing; 800* Intermediate users must be able to extend the tracing system to modify 801 the output format generated, or to insert new tracing sources, without 802 modifying the core of the simulator; 803* Advanced users can modify the simulator core to add new tracing sources 804 and sinks. 805 806The |ns3| tracing system is built on the concepts of independent 807tracing sources and tracing sinks, and a uniform mechanism for connecting 808sources to sinks. Trace sources are entities that can signal events that 809happen in a simulation and provide access to interesting underlying data. 810For example, a trace source could indicate when a packet is received by a net 811device and provide access to the packet contents for interested trace sinks. 812 813Trace sources are not useful by themselves, they must be "connected" to 814other pieces of code that actually do something useful with the information 815provided by the sink. Trace sinks are consumers of the events and data 816provided by the trace sources. For example, one could create a trace sink 817that would (when connected to the trace source of the previous example) print 818out interesting parts of the received packet. 819 820The rationale for this explicit division is to allow users to attach new 821types of sinks to existing tracing sources, without requiring editing and 822recompilation of the core of the simulator. Thus, in the example above, 823a user could define a new tracing sink in her script and attach it to an 824existing tracing source defined in the simulation core by editing only the 825user script. 826 827In this tutorial, we will walk through some pre-defined sources and sinks and 828show how they may be customized with little user effort. See the ns-3 manual 829or how-to sections for information on advanced tracing configuration including 830extending the tracing namespace and creating new tracing sources. 831 832ASCII Tracing 833+++++++++++++ 834|ns3| provides helper functionality that wraps the low-level tracing 835system to help you with the details involved in configuring some easily 836understood packet traces. If you enable this functionality, you will see 837output in a ASCII files --- thus the name. For those familiar with 838|ns2| output, this type of trace is analogous to the ``out.tr`` 839generated by many scripts. 840 841Let's just jump right in and add some ASCII tracing output to our 842``scratch/myfirst.cc`` script. Right before the call to 843``Simulator::Run ()``, add the following lines of code: 844 845:: 846 847 AsciiTraceHelper ascii; 848 pointToPoint.EnableAsciiAll (ascii.CreateFileStream ("myfirst.tr")); 849 850Like in many other |ns3| idioms, this code uses a helper object to 851help create ASCII traces. The second line contains two nested method calls. 852The "inside" method, ``CreateFileStream()`` uses an unnamed object idiom 853to create a file stream object on the stack (without an object name) and pass 854it down to the called method. We'll go into this more in the future, but all 855you have to know at this point is that you are creating an object representing 856a file named "myfirst.tr" and passing it into ``ns-3``. You are telling 857``ns-3`` to deal with the lifetime issues of the created object and also to 858deal with problems caused by a little-known (intentional) limitation of C++ 859ofstream objects relating to copy constructors. 860 861The outside call, to ``EnableAsciiAll()``, tells the helper that you 862want to enable ASCII tracing on all point-to-point devices in your simulation; 863and you want the (provided) trace sinks to write out information about packet 864movement in ASCII format. 865 866For those familiar with |ns2|, the traced events are equivalent to 867the popular trace points that log "+", "-", "d", and "r" events. 868 869You can now build the script and run it from the command line: 870 871.. sourcecode:: bash 872 873 $ ./waf --run scratch/myfirst 874 875Just as you have seen many times before, you will see some messages from Waf and then 876"'build' finished successfully" with some number of messages from 877the running program. 878 879When it ran, the program will have created a file named ``myfirst.tr``. 880Because of the way that Waf works, the file is not created in the local 881directory, it is created at the top-level directory of the repository by 882default. If you want to control where the traces are saved you can use the 883``--cwd`` option of Waf to specify this. We have not done so, thus we 884need to change into the top level directory of our repo and take a look at 885the ASCII trace file ``myfirst.tr`` in your favorite editor. 886 887Parsing Ascii Traces 888~~~~~~~~~~~~~~~~~~~~ 889There's a lot of information there in a pretty dense form, but the first thing 890to notice is that there are a number of distinct lines in this file. It may 891be difficult to see this clearly unless you widen your window considerably. 892 893Each line in the file corresponds to a *trace event*. In this case 894we are tracing events on the *transmit queue* present in every 895point-to-point net device in the simulation. The transmit queue is a queue 896through which every packet destined for a point-to-point channel must pass. 897Note that each line in the trace file begins with a lone character (has a 898space after it). This character will have the following meaning: 899 900* ``+``: An enqueue operation occurred on the device queue; 901* ``-``: A dequeue operation occurred on the device queue; 902* ``d``: A packet was dropped, typically because the queue was full; 903* ``r``: A packet was received by the net device. 904 905Let's take a more detailed view of the first line in the trace file. I'll 906break it down into sections (indented for clarity) with a reference 907number on the left side: 908 909.. sourcecode:: text 910 :linenos: 911 912 + 913 2 914 /NodeList/0/DeviceList/0/$ns3::PointToPointNetDevice/TxQueue/Enqueue 915 ns3::PppHeader ( 916 Point-to-Point Protocol: IP (0x0021)) 917 ns3::Ipv4Header ( 918 tos 0x0 ttl 64 id 0 protocol 17 offset 0 flags [none] 919 length: 1052 10.1.1.1 > 10.1.1.2) 920 ns3::UdpHeader ( 921 length: 1032 49153 > 9) 922 Payload (size=1024) 923 924The first section of this expanded trace event (reference number 0) is the 925operation. We have a ``+`` character, so this corresponds to an 926*enqueue* operation on the transmit queue. The second section (reference 1) 927is the simulation time expressed in seconds. You may recall that we asked the 928``UdpEchoClientApplication`` to start sending packets at two seconds. Here 929we see confirmation that this is, indeed, happening. 930 931The next section of the example trace (reference 2) tell us which trace source 932originated this event (expressed in the tracing namespace). You can think 933of the tracing namespace somewhat like you would a filesystem namespace. The 934root of the namespace is the ``NodeList``. This corresponds to a container 935managed in the |ns3| core code that contains all of the nodes that are 936created in a script. Just as a filesystem may have directories under the 937root, we may have node numbers in the ``NodeList``. The string 938``/NodeList/0`` therefore refers to the zeroth node in the ``NodeList`` 939which we typically think of as "node 0". In each node there is a list of 940devices that have been installed. This list appears next in the namespace. 941You can see that this trace event comes from ``DeviceList/0`` which is the 942zeroth device installed in the node. 943 944The next string, ``$ns3::PointToPointNetDevice`` tells you what kind of 945device is in the zeroth position of the device list for node zero. 946Recall that the operation ``+`` found at reference 00 meant that an enqueue 947operation happened on the transmit queue of the device. This is reflected in 948the final segments of the "trace path" which are ``TxQueue/Enqueue``. 949 950The remaining sections in the trace should be fairly intuitive. References 3-4 951indicate that the packet is encapsulated in the point-to-point protocol. 952References 5-7 show that the packet has an IP version four header and has 953originated from IP address 10.1.1.1 and is destined for 10.1.1.2. References 9548-9 show that this packet has a UDP header and, finally, reference 10 shows 955that the payload is the expected 1024 bytes. 956 957The next line in the trace file shows the same packet being dequeued from the 958transmit queue on the same node. 959 960The Third line in the trace file shows the packet being received by the net 961device on the node with the echo server. I have reproduced that event below. 962 963.. sourcecode:: text 964 :linenos: 965 966 r 967 2.25732 968 /NodeList/1/DeviceList/0/$ns3::PointToPointNetDevice/MacRx 969 ns3::Ipv4Header ( 970 tos 0x0 ttl 64 id 0 protocol 17 offset 0 flags [none] 971 length: 1052 10.1.1.1 > 10.1.1.2) 972 ns3::UdpHeader ( 973 length: 1032 49153 > 9) 974 Payload (size=1024) 975 976Notice that the trace operation is now ``r`` and the simulation time has 977increased to 2.25732 seconds. If you have been following the tutorial steps 978closely this means that you have left the ``DataRate`` of the net devices 979and the channel ``Delay`` set to their default values. This time should 980be familiar as you have seen it before in a previous section. 981 982The trace source namespace entry (reference 02) has changed to reflect that 983this event is coming from node 1 (``/NodeList/1``) and the packet reception 984trace source (``/MacRx``). It should be quite easy for you to follow the 985progress of the packet through the topology by looking at the rest of the 986traces in the file. 987 988PCAP Tracing 989++++++++++++ 990The |ns3| device helpers can also be used to create trace files in the 991``.pcap`` format. The acronym pcap (usually written in lower case) stands 992for packet capture, and is actually an API that includes the 993definition of a ``.pcap`` file format. The most popular program that can 994read and display this format is Wireshark (formerly called Ethereal). 995However, there are many traffic trace analyzers that use this packet format. 996We encourage users to exploit the many tools available for analyzing pcap 997traces. In this tutorial, we concentrate on viewing pcap traces with tcpdump. 998 999The code used to enable pcap tracing is a one-liner. 1000 1001:: 1002 1003 pointToPoint.EnablePcapAll ("myfirst"); 1004 1005Go ahead and insert this line of code after the ASCII tracing code we just 1006added to ``scratch/myfirst.cc``. Notice that we only passed the string 1007"myfirst," and not "myfirst.pcap" or something similar. This is because the 1008parameter is a prefix, not a complete file name. The helper will actually 1009create a trace file for every point-to-point device in the simulation. The 1010file names will be built using the prefix, the node number, the device number 1011and a ".pcap" suffix. 1012 1013In our example script, we will eventually see files named "myfirst-0-0.pcap" 1014and "myfirst-1-0.pcap" which are the pcap traces for node 0-device 0 and 1015node 1-device 0, respectively. 1016 1017Once you have added the line of code to enable pcap tracing, you can run the 1018script in the usual way: 1019 1020.. sourcecode:: bash 1021 1022 $ ./waf --run scratch/myfirst 1023 1024If you look at the top level directory of your distribution, you should now 1025see three log files: ``myfirst.tr`` is the ASCII trace file we have 1026previously examined. ``myfirst-0-0.pcap`` and ``myfirst-1-0.pcap`` 1027are the new pcap files we just generated. 1028 1029Reading output with tcpdump 1030~~~~~~~~~~~~~~~~~~~~~~~~~~~ 1031The easiest thing to do at this point will be to use ``tcpdump`` to look 1032at the ``pcap`` files. 1033 1034.. sourcecode:: bash 1035 1036 $ tcpdump -nn -tt -r myfirst-0-0.pcap 1037 reading from file myfirst-0-0.pcap, link-type PPP (PPP) 1038 2.000000 IP 10.1.1.1.49153 > 10.1.1.2.9: UDP, length 1024 1039 2.514648 IP 10.1.1.2.9 > 10.1.1.1.49153: UDP, length 1024 1040 1041 tcpdump -nn -tt -r myfirst-1-0.pcap 1042 reading from file myfirst-1-0.pcap, link-type PPP (PPP) 1043 2.257324 IP 10.1.1.1.49153 > 10.1.1.2.9: UDP, length 1024 1044 2.257324 IP 10.1.1.2.9 > 10.1.1.1.49153: UDP, length 1024 1045 1046You can see in the dump of ``myfirst-0-0.pcap`` (the client device) that the 1047echo packet is sent at 2 seconds into the simulation. If you look at the 1048second dump (``myfirst-1-0.pcap``) you can see that packet being received 1049at 2.257324 seconds. You see the packet being echoed back at 2.257324 seconds 1050in the second dump, and finally, you see the packet being received back at 1051the client in the first dump at 2.514648 seconds. 1052 1053Reading output with Wireshark 1054~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 1055If you are unfamiliar with Wireshark, there is a web site available from which 1056you can download programs and documentation: http://www.wireshark.org/. 1057 1058Wireshark is a graphical user interface which can be used for displaying these 1059trace files. If you have Wireshark available, you can open each of the trace 1060files and display the contents as if you had captured the packets using a 1061*packet sniffer*. 1062