HOWTO use NS LOG to find a problem

From Nsnam
Revision as of 03:09, 14 May 2009 by Craigdo (Talk | contribs) (HOWTO use NS LOG as a learning tool)

Jump to: navigation, search

Main Page - Current Development - Developer FAQ - Tools - Related Projects - Project Ideas - Summer Projects

Installation - Troubleshooting - User FAQ - HOWTOs - Samples - Models - Education - Contributed Code - Papers

One of the easiest ways a person can narrow down the location of a problem in ns-3 is by using NS_LOG and our predefined logging components. Typically one uses NS_LOG in a case where the exact nature of the problem is not yet understood. Logging provides a way to narrow down the problem location to an extent where either the log message will indicate the source of the problem orit will be easy to fire up the script in a debugger and take a closer look.

A tried and true method for quickly locating a problem is via binary search. You can use binary search to locate a bug just as easily as you can use binary search to locate an item in the usual sense. In the case of debugging a network simulation script, you will usually first consider the end-to-end path of a packet and then take a look at what is happening half-way. If the problem is visible at the half-way point, you think of what is half-wat to that point and take a look there. If the problem is not manifested at the halfway point, you take a look at what is happening half-way again towards the end point. Using this technique, you can quickly narrow down the location of a problem.

Of course, you can do this in a debugger just as easily as with NS_LOG if you know exactly where to set your breakpoints a priori. An interesting feature of NS_LOG is that you can really do the same thing without knowing what is going on other than in a general network knowledge sense.

In this HOWTO, I demonstrate how one could use the binary search technique to locate a hypothetical problem in the our first.cc example. As a bonus, look at the end for how to use NS_LOG as a learning tool for understanding the system.

HOWTO use NS LOG to find a problem

The first.cc example uses an echo client on a single client node and an echo server on a single server node. It orchesrates an echo across a point-to-point link. A moment's thought will tell you that the halfway point in this simulation is at the point-to-point link. The ns-3 model is that there is a net device and a channel so you will want to enable logging for the point-to-point channel.

If you know something about the structure of the source, you'll just know to look in

 src/devices/point-to-point/point-to-point-channel.cc 

for the NS_LOG_COMPONENT_DEFINE of the logging component. If you don't you can just go to the top level directory and do

 find . -name '*.cc' | xargs grep NS_LOG_COMPONENT_DEFINE

This might seem like brute force and awkwardness, but you'll only find a couple of pages of them. If you really don't want to wade through the two pages, you can also narrow the search

 find . -name '*.cc' | xargs grep NS_LOG_COMPONENT_DEFINE | grep -i point

and you'll currently see

 ./devices/point-to-point/point-to-point-channel.cc:NS_LOG_COMPONENT_DEFINE ("PointToPointChannel");
 ./devices/point-to-point/ppp-header.cc:NS_LOG_COMPONENT_DEFINE ("PppHeader");
 ./devices/point-to-point/point-to-point-net-device.cc:NS_LOG_COMPONENT_DEFINE ("PointToPointNetDevice");
 ./internet-stack/ipv4-end-point-demux.cc:NS_LOG_COMPONENT_DEFINE ("Ipv4EndPointDemux");
 ./internet-stack/ipv4-end-point.cc:NS_LOG_COMPONENT_DEFINE ("Ipv4EndPoint");

You can easily see that the log component to enable is, not too surprisingly, PointToPointChannel.

Go ahead and enable the log component and run the program to see what's happening.

 export NS_LOG=PointToPointChannel
 ./waf --run first

You'll immediately see that the packet made it down to the channel from the client.

 2s PointToPointChannel:TransmitStart(0x634910, 0x6256f0, 0x622510)
 2s PointToPointChannel:TransmitStart(): UID is 0)

So, now you know that a packet has made it from the echo client application down through the protocol stack on the client node, into the net device and starts off to the server on the channel. Now, think to yourself, what's halfway up the protocol stack on the server side? Well, how about UDP. Again, the question is, what log component to turn on? The answer if you don't know anything about what's happening in the system is grep, but this time, look for udp.

 find . -name '*.cc' | xargs grep NS_LOG_COMPONENT_DEFINE | grep -i udp

You'll see that we have log components containing the case-independent string udp for

 ./examples/emu-udp-echo.cc:NS_LOG_COMPONENT_DEFINE ("EmulatedUdpEchoExample");
 ./examples/realtime-udp-echo.cc:NS_LOG_COMPONENT_DEFINE ("RealtimeUdpEchoExample");
 ./examples/udp-echo.cc:NS_LOG_COMPONENT_DEFINE ("UdpEchoExample");
 ./src/node/udp-socket.cc:NS_LOG_COMPONENT_DEFINE ("UdpSocket");
 ./src/applications/udp-echo/udp-echo-server.cc:NS_LOG_COMPONENT_DEFINE ("UdpEchoServerApplication");
 ./src/applications/udp-echo/udp-echo-client.cc:NS_LOG_COMPONENT_DEFINE ("UdpEchoClientApplication");
 ./src/internet-stack/udp-socket-impl.cc:NS_LOG_COMPONENT_DEFINE ("UdpSocketImpl");
 ./src/internet-stack/udp-l4-protocol.cc:NS_LOG_COMPONENT_DEFINE ("UdpL4Protocol");

You can really play this by ear. How about turning on UdpL4Protocol. You know what an L4 protocol is, right? UdpSocketImpl or UdpSocket sound kindof high in the stack, so as a wild guess just turn on UdpL4Protocol.

 export NS_LOG=UdpL4Protocol
 ./waf --run first

Among other things, you'll see

 Sent 1024 bytes to 10.1.1.2
 2.00369s UdpL4Protocol:Receive(0x635d30, 0x625250, 10.1.1.1, 10.1.1.2)

This tells you that a packet from 10.1.1.1 to 10.1.1.2 has made it as far as the UdpL4Protocol::Receive method (which you might not have known existed) and also gives you a method name that you can search for and begin seeing what is happening. Again, grep is your friend

 find . -name '*.cc' | xargs grep UdpL4Protocol::Receive

and you will see

 ./internet-stack/udp-l4-protocol.cc:UdpL4Protocol::Receive(Ptr<Packet> packet,

Now you have a file and a method so your knowledge of what is happening is increasing. You can spend some time perusing the file if you like just to get a handle on what is happening at this point in the stack.

Focusing at the problem at hand, you know know that the packet has made it about three quarters of the way from the client to the server. The find and grep for udp above tells you that you really only have the udp socket left between you and the server application. The UdpSocketImpl component sounds like a good place to look, so turn it on.

 export NS_LOG=UdpSocketImpl
 ./waf --run first

You will see

 Sent 1024 bytes to 10.1.1.2
 2.00369s UdpSocketImpl:ForwardUp(0x624900, 0x625a20, 10.1.1.1, 49153)
 2.00369s UdpSocketImpl:RecvFrom(0x624900, 4294967295, 0)
 2.00369s UdpSocketImpl:Recv(0x624900, 4294967295, 0)

The socket gets the packet from 10.1.1.1 and then forwards it up the stack and eventually wants to call the recv function which gives the client the data.

Anyway, I think you get the picture. Binary search for problems using NS_LOG. While you are doing the binary search, look at what is being displayed to help you understand what is going on in the stack. Use grep and find to locate the methods you see and then go read the code to get a better understanding of the system. If you want to understand what *should* be happening, do this exercise using one of the examples and watch the packet flow across a similar case and then go back to your code and see where it diverges from what you saw in the example.

HOWTO use NS LOG as a learning tool

You can also use NS_LOG as a learning tool to dig down into the system. If you want to figure out more about ns-3 routing, one way is to find some routing log components and find out where $#!^ happens.

 find . -name '*.cc' | xargs grep NS_LOG_COMPONENT_DEFINE | grep -i routing
 ./src/routing/olsr/olsr-header.cc:NS_LOG_COMPONENT_DEFINE("OlsrHeader");
 ./src/routing/olsr/olsr-routing-protocol.cc:NS_LOG_COMPONENT_DEFINE ("OlsrAgent");
 ./src/routing/global-routing/global-route-manager-impl.cc:NS_LOG_COMPONENT_DEFINE ("GlobalRouteManager");
 ./src/routing/global-routing/candidate-queue.cc:NS_LOG_COMPONENT_DEFINE ("CandidateQueue");
 ./src/routing/global-routing/global-router-interface.cc:NS_LOG_COMPONENT_DEFINE ("GlobalRouter");
 ./src/internet-stack/ipv4-static-routing.cc:NS_LOG_COMPONENT_DEFINE ("Ipv4StaticRouting");
 ./src/internet-stack/ipv4-global-routing.cc:NS_LOG_COMPONENT_DEFINE ("Ipv4GlobalRouting");

Look in examples for a file with the root of the word "routing" in its name.

 ls examples/*rout*

As of this writing, you'll see

 examples/dynamic-global-routing.cc  examples/mixed-global-routing.cc      examples/simple-global-routing.cc
 examples/global-routing-slash32.cc  examples/simple-alternate-routing.cc  examples/static-routing-slash32.cc

Why not take a look at something with simple in its name too. It seems reasonable that the log component Ipv4GlobalRouting will have something to do with the example file simple-global-routing. See what happens:

 export NS_LOG=Ipv4GlobalRouting
 ./waf --run simple-global-routing

When you run this, you will get lots and lots of log messages. You can redirect the run output to a file and you can just start poking around.

Take a look at some output. This is interesting setup information

 0s Ipv4GlobalRouting:AddHostRouteTo(10.1.1.2, 10.1.1.2, 1)
 0s Ipv4GlobalRouting:AddHostRouteTo(10.1.2.2, 10.1.1.2, 1)
 0s Ipv4GlobalRouting:AddHostRouteTo(10.1.3.2, 10.1.1.2, 1)
 0s Ipv4GlobalRouting:AddHostRouteTo(10.1.2.1, 10.1.1.2, 1)
 0s Ipv4GlobalRouting:AddHostRouteTo(10.1.3.1, 10.1.1.2, 1)
 0s Ipv4GlobalRouting:AddNetworkRouteTo(10.1.1.0, 255.255.255.0, 10.1.1.2, 1)
 0s Ipv4GlobalRouting:AddNetworkRouteTo(10.1.2.0, 255.255.255.0, 10.1.1.2, 1)
 0s Ipv4GlobalRouting:AddNetworkRouteTo(10.1.3.0, 255.255.255.0, 10.1.1.2, 1)
 0s Ipv4GlobalRouting:AddNetworkRouteTo(10.1.2.0, 255.255.255.0, 10.1.1.2, 1)
 0s Ipv4GlobalRouting:AddNetworkRouteTo(10.1.3.0, 255.255.255.0, 10.1.1.2, 1)

Further down notice that the timestamps seem to be grouped.

 8.70113s Ipv4GlobalRouting:RequestRoute(0x648950, 1, 0x7fffe3cded30, 0x65db70, 0x7fffe3cde8e0)
 8.70113s Ipv4GlobalRouting:RequestRoute(): source = 10.1.1.1
 8.70113s Ipv4GlobalRouting:RequestRoute(): destination = 10.1.3.1
 8.70113s Ipv4GlobalRouting:RequestRoute(): Unicast destination- looking up
 8.70113s Ipv4GlobalRouting:LookupGlobal()
 8.70113s Ipv4GlobalRouting:LookupGlobal(): Found global host route0x649bf0

You can probably already get a sense for what must be going on. You can now go and find the code using grep.

 find . -name '*.cc' | xargs grep Ipv4GlobalRouting::RequestRoute
 ./src/internet-stack/ipv4-global-routing.cc:Ipv4GlobalRouting::RequestRoute (

tells you where to look for global routing-related code. From the log messages you can see the basic idea before you get there.

You can also see that there are other components GlobalRouteManager and GlobalRouter that live in a directory called src/routing/global-routing that you can take a look at. Armed with some of this information you can also look in the manual where you will find a routing chapter. Using NS_LOG you can see the interfaces described in the manual at work and follow what is happening in real code.

Anyway, NS_LOG is really a very powerful tool. Most people don't appreciate it since they learned in programming 101 that debugging with printfs is for kids. Don't kid yourself, though. Use every tool available to help yourself out. Debugging with printfs in an intelligent way can give you an edge on folks that don't use it and really help your work.


Craigdo 02:39, 14 May 2009 (UTC)