ns3 Tutorial 中的日志模块（翻译）

 

转载地址：http://blog.sina.com.cn/s/blog_8ecca79b0101d7fe.html

 

 

1  日志模块的使用

 

在运行 first.cc 脚本时，我们已经简单了解了日志模块。现在，我们将更深入地了解日志子系统是为哪些用户案例设计的。 

 

1.1 日志概述

 

很多大型系统支持某种消息记录功能，ns3 也不例外。在某些情况下，只有错误消息会被记录到操作控制台（在基于 Unix 的系统中通常是标准错误输出）。在其他系统中，警告消息可能跟详细的信息消息一起被输出。在某些情况下，日志功能被用来输出令人费解的调试信息。

 

在 NS-3 中，我们认为这些不同详尽级别的日志都是非常有用的。ns3 还提供了一个可供选择的、多级别的方法来记录日志。日志可以完全被禁用，或仅对部分组件可用，或全局可用。并且 ns3 提供了不同详尽程度的日志级别供选。NS-3 日志模块提供了直观的、相对简单的使用方法来帮助用户获得仿真过程的所需信息。

 

应当了解的是，我们也提供了一个一般性的记录机制——tracing，来获得仿真结果之外的数据（要获取更多 tracing 系统的知识，参见 tutorial 的章节 “ Using the Tracing System”）。日志应当作为快速获得你的脚本和模型的调试信息、警告信息、错误信息、或是其他信息的首要选择。

 

在现有的系统中，有7个详尽程度递增的日志级别，这些级别对应的宏从低到高排列为：

 

• LOG_ERROR — Log error messages （相关的宏：NS_LOG_ERROR）；
• LOG_WARN — Log warning messages （相关的宏： NS_LOG_WARN）；
• LOG_DEBUG — Log relatively rare, ad-hoc debugging messages （相关的宏： NS_LOG_DEBUG）；
• LOG_INFO — Log informational messages about program progress（相关的宏： NS_LOG_INFO）；
• LOG_FUNCTION — Log a message describing each function called（两个相关的宏 ： NS_LOG_FUNCTION 用于成员函数， NS_LOG_FUNCTION_NOARGS 用于静态函数）；
• LOG_LOGIC – Log messages describing logical flow within a function （相关的宏： NS_LOG_LOGIC）；
• LOG_ALL — Log everything mentioned above（无相关的宏）。

 

我们也提供了一种一直被使用的无条件日志级别，它跟日志详尽级别和组件选择无关。

 

•           NS_LOG_UNCOND – Log the associated message unconditionally（没有相关日志级别）

 

每一个级别能够被单独地被调用或逐级递增的被调用。日志的配置可以使用一个 shell 环境变量（NS_LOG），或是使用日志系统函数进行。正如在本教程之前部分看到的，日志系统有 Doxygen 文档，如果你还没有阅读日志模型文档现在是个好的时机。既然你已经很详细地阅读了文档，我们使用日志来获得之前建立的 first.cc 脚本的一些有用信息。 

 

1.2 启用日志 

 

我们将使用 NS_LOG 环境变量来打开一些日志功能。首先，需要耐心点，像之前那样运行脚本，

  

./war --run scratch/myfirst

 

你应当看到熟悉的、第一个ns-3例子程序的结果

 

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  'build' finished successfully (0.413s)
  Sent 1024 bytes to 10.1.1.2
  Received 1024 bytes from 10.1.1.1
  Received 1024 bytes from 10.1.1.2

上面看到的 "Sent" 和 "Received" 消息实际上是来自 UdpEchoClientApplication 和 UdpEchoServerApplication 的日志消息。我们通过 NS_LOG 环境变量设置日志级别让客户端程序输出更多信息。

假设你在使用一个类 sh 的 shell。此类 shell 使用 “VARIABLE=value” 的语法格式设置环境变量。如果使用类 csh 的 shell，必须将例句改成 "setenv VARIABLE value" 语法格式的语句。

现在，scratch/myfirst.cc 中 UDP 回显客户端应用在使用下面的代码行进行响应，

 

LogComponentEnable("UdpEchoClientApplication", LOG_LEVEL_INFO);

 

这行代码设置日志为 LOG_LEVEL_INFO 级别。当我们传递一个日志级别标志时，我们实际上打开了这个日志级别和它之下的所有级别。本例中，我们打开了NS_LOG_INFO、 NS_LOG_DEBUG、NS_LOG_WARN  和 NS_LOG_ERROR 级别。我们可以通过设置 NS_LOG 环境变量在不改变脚本或重新编译的情况下来增加日志级别，获得更多信息，

 

export NS_LOG=UdpEchoClientApplication=level_all

 

这个设置 shell 环境变量 NS_LOG 为字符串：

  

UdpEchoClientApplication=level_all

 

等号左边是我们想要设置日志级别的组件的名字，等号右边是我们想要使用的日志级别。本例中，我们要为应用打开所有的调试信息级别。我们把 NS_LOG 设为这个样子，NS-3 日志系统将识别出日志级别改变，输出下面的结果：

 

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build
  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  'build' finished successfully (0.404s)
  UdpEchoClientApplication:UdpEchoClient()
  UdpEchoClientApplication:SetDataSize(1024)
  UdpEchoClientApplication:StartApplication()
  UdpEchoClientApplication:ScheduleTransmit()
  UdpEchoClientApplication:Send()
  Sent 1024 bytes to 10.1.1.2
  Received 1024 bytes from 10.1.1.1
  UdpEchoClientApplication:HandleRead(0x6241e0, 0x624a20)
  Received 1024 bytes from 10.1.1.2
  UdpEchoClientApplication:StopApplication()
  UdpEchoClientApplication:DoDispose()
  UdpEchoClientApplication:~UdpEchoClient()

这些额外的调试信息是来自 NS_LOG_FUNTION 级别的日志。这些信息显示了在脚本运行期间程序中每个函数调用过程。注意，ns-3 中模型对日志的支持并不是必须的。有关被记录信息的多少是由模型的开发者决定的。在本例中，有很多日志输出。

你可以看到回显客户端程序中调用函数的日志。如果仔细看，会注意到字符串 UdpEchoClientApplication 和方法名之间是单冒号，而不是你预期的 C++ 域操作符(::)（双冒号）。这里是有意这样做的。

 

名称 UdpEchoClientApplication 并非一个类名，而是日志组件名。当一个类仅由一个源文件代表时，这个位置的显示通常是这个类的名字。这里用一个冒号来替代两个冒号，来提醒用户区分日志组件名和类名的细微差别：这个位置显示的是组件名，而并不是类名。

 

在某些情况下，确定哪个方法生成了某条日志消息是很困难的。如果你看过上面的文档，你或许想知道字符串 “Received 1024 bytes from 10.1.1.2” 来自哪里。我们可以通过在 NS_LOG 环境变量中设置 prefix_func 级别来解决。试着按照下面的语句做：

 

 export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func'

注意，这里引号是必须的，因为我们用的竖线表示或操作，而在 Unix 中竖线表示管道连接。

 

现在如果运行脚本你将看到每条日志都有产生此条日志的组件名做前缀了。

  

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  'build' finished successfully (0.417s)
  UdpEchoClientApplication:UdpEchoClient()
  UdpEchoClientApplication:SetDataSize(1024)
  UdpEchoClientApplication:StartApplication()
  UdpEchoClientApplication:ScheduleTransmit()
  UdpEchoClientApplication:Send()
  UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2
  Received 1024 bytes from 10.1.1.1
  UdpEchoClientApplication:HandleRead(0x6241e0, 0x624a20)
  UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2
  UdpEchoClientApplication:StopApplication()
  UdpEchoClientApplication:DoDispose()
  UdpEchoClientApplication:~UdpEchoClient()  

你现在看到来自 UDP 回显客户端程序的消息这样被识别了。消息 “Received 1024 bytes from 10.1.1.2” 明显来自回显客户端程序。剩下的消息一定是来自 UDP 回显服务器程序。我们可以通过在 NS_LOG 环境变量中键入一个单冒号隔开的组件列表来启用回显服务器应用组件。

 

export 'NS_LOG=UdpEchoClientApplication=level_all|prefix_func:
               UdpEchoServerApplication=level_all|prefix_func'

 

警告：你必须删除单冒号后的换行符，在例子文本中仅仅只是为了编排格式。

 

现在，如果你运行脚本，你将看到来自回显客户端和服务器的所有日志消息。这对于调试问题很有用。

 

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  'build' finished successfully (0.406s)
  UdpEchoServerApplication:UdpEchoServer()
  UdpEchoClientApplication:UdpEchoClient()
  UdpEchoClientApplication:SetDataSize(1024)
  UdpEchoServerApplication:StartApplication()
  UdpEchoClientApplication:StartApplication()
  UdpEchoClientApplication:ScheduleTransmit()
  UdpEchoClientApplication:Send()
  UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2
  UdpEchoServerApplication:HandleRead(): Received 1024 bytes from 10.1.1.1
  UdpEchoServerApplication:HandleRead(): Echoing packet
  UdpEchoClientApplication:HandleRead(0x624920, 0x625160)
  UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2
  UdpEchoServerApplication:StopApplication()
  UdpEchoClientApplication:StopApplication()
  UdpEchoClientApplication:DoDispose()
  UdpEchoServerApplication:DoDispose()
  UdpEchoClientApplication:~UdpEchoClient()
  UdpEchoServerApplication:~UdpEchoServer()

有时能够看到日志生成的仿真时间也是很有用的。可以通过使用 prefix_time 位来实现。

 

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

 

输入时你必须先移除上面的换行符。如果你现在运行此脚本，你将看到下面的结果：

 

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  'build' finished successfully (0.418s)
  0s UdpEchoServerApplication:UdpEchoServer()
  0s UdpEchoClientApplication:UdpEchoClient()
  0s UdpEchoClientApplication:SetDataSize(1024)
  1s UdpEchoServerApplication:StartApplication()
  2s UdpEchoClientApplication:StartApplication()
  2s UdpEchoClientApplication:ScheduleTransmit()
  2s UdpEchoClientApplication:Send()
  2s UdpEchoClientApplication:Send(): Sent 1024 bytes to 10.1.1.2
  2.00369s UdpEchoServerApplication:HandleRead(): Received 1024 bytes from 10.1.1.1
  2.00369s UdpEchoServerApplication:HandleRead(): Echoing packet
  2.00737s UdpEchoClientApplication:HandleRead(0x624290, 0x624ad0)
  2.00737s UdpEchoClientApplication:HandleRead(): Received 1024 bytes from 10.1.1.2
  10s UdpEchoServerApplication:StopApplication()
  10s UdpEchoClientApplication:StopApplication()
  UdpEchoClientApplication:DoDispose()
  UdpEchoServerApplication:DoDispose()
  UdpEchoClientApplication:~UdpEchoClient()
  UdpEchoServerApplication:~UdpEchoServer()

 

可以看到 UdpEchoServer 的构造函数在仿真的第 0 秒被调用。事实上这实在仿真开始之前就完成了，只是时间显示的是 0 秒。UdpEchoClient 的构造函数也是一样。

 

回忆在 scratch/first.cc 脚本中，1 秒时启动回显服务器应用。可以看到服务器的 StartApplication实际上是在 1 秒时被调用。同样，客户端响应程序正如我们所预料的在仿真 2 秒时开始。

 

我们现在可以看到仿真的进度了，我们可以看到从 ScheduleTransmit 函数在客户端中调用 send 函数，到回显服务器中调用 HandleRead 函数的整个过程了。注意到通过点到点连接发送包消耗时间是3.69毫秒。查看回显服务器日志记录了一条消息告诉你已经响应了数据包。在另一个通道延迟后，可以看到响应客户端用它的 HandleRead 方法收到响应包。

 

在仿真过程中发生了很多你所没有看到的事情。现在可以很容易的打开系统的日志组件，察看整个过程了。现在试着设置 NS_LOG 变量为，

 

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

 

上面的星号是日志组件通配符。将打开在仿真过程中使用的所有组件的日志功能。这里不列出结果了。可以将这些信息重定向到一个文件，并且用自己喜欢的编辑器打开查看。

  

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

 

就个人而言，当我碰到一个问题或是不知道那里出错了，我会使用最详细的日志功能。可以很简单的跟踪程序，而无需设置断点并且在调试器中一步步运行代码。我可以用我喜欢的编辑器来打开查看日志，寻找问题所在。当我对错误有了大致了解之后，我会使用调试器对问题进行非常详细的检查。当你的脚本做了完全非预期的事情时，这种输出将是非常有用的。如果你使用调试器单步运行，或许你会错过偏差的部分，而日志使得这些偏差非常明显。 

 

 

1.3 为你的代码增加日志功能 

可以通过几个宏调用日志组件给仿真增加新的日志功能。我们可以在scratch目录中的myfirst.cc中实现这一点。

 

也许你还记得在脚本中我们已经定义过一个日志组件：

 

NS_LOG_COMPONENT_DEFINE ("FirstScriptExample");

 

我们已经了解了通过设置 NS_LOG 环境变量来给组件启用日志功能。我们可以给脚本增加一些日志功能。用来增加信息级别的日志消息的宏是 NS_LOG_INFO。现在我们来增加一行显示本脚本在创建拓扑的语句。此操作是在通过下代码段完成的。

 

用你钟爱的编辑器打开 scratch/myfirst.cc 文件并且在以下代码

 

NodeContainer nodes; nodes.Create(2);

 

之前加上一行，

 

NS_LOG_INFO ("Creating Topology");

现在用 waf 编译脚本并且清除 NS_LOG 环境变量来关掉我们之前启用的日志文件：

$ ./waf
$ export NS_LOG=

 

现在，运行脚本，

 

 ./waf --run scratch/myfirst

 

你将不会看到新的日志消息，因为与它相关的日志组件（FirstScriptExample）没有被启用。为了看到新的消息，必须使用大于或等于 NS_LOG_INFO 的日志级别来启用 FirstScriptExample 日志组件。如果只是想要看某个级别的日志，你可以通过下面的语句来启用它，

 

export NS_LOG=FirstScriptExample=info

 

如果现在运行脚本，你将看到新建的 "Creating Topology" 日志消息，

 

  Waf: Entering directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  Waf: Leaving directory `/home/craigdo/repos/ns-3-allinone/ns-3-dev/build'
  'build' finished successfully (0.404s)
  Creating Topology
  Sent 1024 bytes to 10.1.1.2
  Received 1024 bytes from 10.1.1.1
  Received 1024 bytes from 10.1.1.2