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