NS-3学习笔记（二）：NS-3的日志系统

发表于 | 更新于 | 分类于 ， ， | 评论数： | 阅读次数：

在程序设计的时候，我们一般都会在程序中输出一些信息。无论是记录程序的运行过程也好，还是输出程序的结果，都需要输出一些信息。这些输出的信息我们称为日志。本章主要介绍NS-3的日志系统：日志的级别，如何记录日志，如何启用和禁用日志等。

1. NS-3日志概述

在程序中，经常都需要输出一些信息。例如为了程序调试的时候方便，我们需要输出程序的运行过程的记录，或者需要输出一些中间结果。或者程序运行出现逻辑错误的时候，我们需要输出一些错误信息等等。有些程序直接将结果输出到标准输出（stdout）或者是标准错误（stderr）。除此之外，一些大型的软件系统提供一种更灵活的方式来记录这些程序输出的信息，这种机制称为日志系统。日志系统可以灵活地控制输出的信息的详细程度、输出方式等。

在NS-3当中，日志系统主要是用来提供程序的调试信息的，例如输出警告、错误、程序逻辑等信息或者输出一些程序的中间结果以提供验证。对于仿真的结果数据，NS-3提供了跟踪机制(tracing)来收集这些结果，而不应该直接使用日志来进行输出。跟踪机制将在后面的章节进行介绍。

2. 日志的级别

在NS-3当中，日志是继续组件（Component）定义的，能够方便地控制开启和关闭一个组件的日志。同时，NS-3提供了七个级别的日志水平，可以在输出日志是选择相应的级别，那么在显示日志是可以控制日志的显示详细程度。这些级别由粗到细依次为：

  1. LOG_ERROR：记录错误信息，程序中使用NS_LOG_ERROR来输出信息
  2. LOG_WARN：记录警告信息，程序中使用NS_LOG_WARN来输出信息
  3. LOG_DEBUG：记录一些不常见出现、奇怪的调试信息，程序中使用NS_LOG_DEBUG来输出信息
  4. LOG_INFO：记录记录程序运行进度的信息，程序中使用NS_LOG_INFO来输出信息
  5. LOG_FUNCTION：记录函数调用的信息，程序中使用NS_LOG_FUNCTION来输出信息
  6. LOG_LOGIC：记录程序中执行流程的信息，程序中使用NS_LOG_LOGIC来输出信息
  7. LOG_ALL：显示任何级别的日志

除此之外，NS-3还提供了一种特殊的输出方式：

  • NS_LOG_UNCOND：这种输出方式不会绑定到上述任何一个级别当中，只要所属组件的日志开启，不论当前显示哪个级别，都将输出日志信息。

3. 定义和使用日志组件

3.1. 定义日志组件

要输出日志，首先需要定义一个日志组件。其语法如下：

1
NS_LOG_COMPONENT_DEFINE("MyTestComponent");

其中NS_LOG_COMPONENT_DEFINE是NS-3定义的一个宏，用于定义一个日志组件，在该组件中输出的日志，可以一次性启用或者禁用。组件的名字使用字符串表示。此外，要注意组件的名字不可重复。因此前面最好加上前缀，以免和NS-3官方的组件或者第三方的组件名称冲突。

3.2. 启用日志组件

在NS-3当中，有多种方法可以启用日志组件。这里介绍一种最简单的方法，即在程序中通过编程方式，直接启用某个组件的日志输出。其语法如下：

1
LogComponentEnable("MyTestComponent", LOG_INFO);

这个语句启用了MyTestComponent组件当中的INFO级别的日志。

3.3. 示例程序

下面的程序，定义了一个日志组件，然后输出了一些日志信息：

test-log-component.cc
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */

/*
 * test-log-component.cc
 *
 *  Created on: Apr 1, 2018
 *      Author: Yu Xia <rainsia@163.com>
 */


#include "ns3/core-module.h"

using namespace ns3;

NS_LOG_COMPONENT_DEFINE ("MyTestComponent");

int 
main (int argc, char *argv[])
{
    LogComponentEnable("MyTestComponent", LOG_INFO);

    NS_LOG_ERROR("test error");
    NS_LOG_WARN("test warn");
    NS_LOG_DEBUG("test debug");
    NS_LOG_INFO("test info");
    NS_LOG_FUNCTION("test function");
    NS_LOG_LOGIC("test logic");
}

输入./waf –run “test-log-component”运行该程序，得到输出结果：

1
2
3
4
5
Waf: Entering directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
Waf: Leaving directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
Build commands will be stored in build/compile_commands.json
'build' finished successfully (1.084s)
test info

可见，启用了LOG_INFO级别的日志，就只能输出INFO级别的日志内容。如果注释掉启用的语句：

test-log-component.cc
1
2
3
4
5
6
7
8
……
int 
main (int argc, char *argv[])
{
    // LogComponentEnable("MyTestComponent", LOG_INFO);

    ……
}

则运行程序后，将没有任何输出，因为只有启用日志组件之后，在该组件内输出的日志信息才有效。

随后，我们将程序更改为：

test-log-component.cc
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */

/*
 * test-log-component.cc
 *
 *  Created on: Apr 1, 2018
 *      Author: Yu Xia <rainsia@163.com>
 */


#include "ns3/core-module.h"

using namespace ns3;

NS_LOG_COMPONENT_DEFINE ("MyTestComponent");

int 
main (int argc, char *argv[])
{
    // LogComponentEnable("MyTestComponent", LOG_INFO);

    NS_LOG_ERROR("test error");
    NS_LOG_WARN("test warn");
    NS_LOG_DEBUG("test debug");
    NS_LOG_INFO("test info");
    NS_LOG_FUNCTION("test function");
    NS_LOG_LOGIC("test logic");
    NS_LOG_UNCOND("test uncond");

}

运行程序后，输出结果为：

1
2
3
4
5
6
7
Waf: Entering directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
[1732/1881] Compiling scratch/test-log-component.cc
[1840/1881] Linking build/scratch/test-log-component
Waf: Leaving directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
Build commands will be stored in build/compile_commands.json
'build' finished successfully (2.143s)
test uncond

由此可见，使用NS_LOG_UNCOND输出的日志，无论日志组件启用与否，或者使用了任何的日志级别，其内容一定会输出。

最后，如果想禁用所有级别的日志，可以使用LOG_NONE。

4. 累计日志级别

在启用日志组件时，除了使用类似LOG_INFO或者LOG_WARN这样的单一级别之外，还可以使用LOG_LEVEL_INFO或者LOG_LEVEL_WARN这样的累计日志级别。其累计原则是，排在，编号越小的级别输出的级别越高。例如，如果启用LOG_LEVEL_WARN级别，那么其上的ERROR级别的日志也会同时输出，但是其下的任何一个级别都将不输出。

其中LOG_LEVEL_ERROR和LOG_ERROR是一样的，因为他们都只显示自己级别的日志，此外LOG_LEVEL_ALL和LOG_ALL是一致的，因为他们都显示所有级别的日志。

来看以下程序：

test-log-level.cc
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */

/*
 * test-log-level.cc
 *
 *  Created on: Apr 1, 2018
 *      Author: Yu Xia <rainsia@163.com>
 */


#include "ns3/core-module.h"

using namespace ns3;

NS_LOG_COMPONENT_DEFINE ("MyTestLevel");

int 
main (int argc, char *argv[])
{
    LogComponentEnable("MyTestLevel", LOG_LEVEL_INFO);

    NS_LOG_ERROR("test error");
    NS_LOG_WARN("test warn");
    NS_LOG_DEBUG("test debug");
    NS_LOG_INFO("test info");
    NS_LOG_FUNCTION("test function");
    NS_LOG_LOGIC("test logic");
    NS_LOG_UNCOND("test uncond");

}

运行后将得到以下输出：

1
2
3
4
5
6
7
8
9
10
11
Waf: Entering directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
[ 885/1883] Compiling scratch/test-log-level.cc
[1851/1883] Linking build/scratch/test-log-level
Waf: Leaving directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
Build commands will be stored in build/compile_commands.json
'build' finished successfully (1.788s)
test error
test warn
test debug
test info
test uncond

由此可见，所有INFO以上的级别的日志都将输出，而INFO以下的级别的日志都将不输出。此外，UNCOND级别不受任何影响。

5. 函数日志

NS-3提供了函数日志来跟踪函数的调用情况。NS-3中一共有两个宏命令来协助跟踪函数日志：

  • NS_LOG_FUNCTION：必须带一个参数，适用于类的方法，或带参数的静态方法。
  • NS_LOG_FUNCTION_NOARGS：可以不带参数，适用于不带参数的静态方法。

在记录非静态方法调用的时候，一般将this传入作为第一个参数，如果后面还有参数，则继续传入参数列表，例如：

lang: cpp
1
2
3
4
5
6
7
8
void MyClass::Check (int value, char * item)
{
  NS_LOG_FUNCTION (this << value << item);
  if (value > 10)
    {
    ...
    }
}

记录静态有参方法的时候，除了不需传入this作为第一个参数以外，其他和非静态方法一致，例如：

1
2
3
4
5
6
7
8
9
//static method
void MyClass::CheckIt (int value, char * item)
{
  NS_LOG_FUNCTION (value << item);
  if (value > 10)
    {
    ...
    }
}

此外，如果静态方法没有参数，则使用NS_LOG_FUNCTION_NOARGS来记录调用日志，而不需要传入任何参数，例如：

1
2
3
4
5
6
//static method
void MyClass::CheckItTwice ()
{
  NS_LOG_FUNCTION_NOARGS ();
  ...
}

来看一个完整的例子：

test-log-function.cc
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */

/*
 * test-log-level.cc
 *
 *  Created on: Apr 1, 2018
 *      Author: Yu Xia <rainsia@163.com>
 */


#include "ns3/core-module.h"

using namespace ns3;

//NS_LOG_COMPONENT_DEFINE ("MyClass");
NS_LOG_COMPONENT_DEFINE ("MyTestFunction");

class MyClass {
public:
    void Check (int value, const char * item);
    static void CheckIt(int value, const char * item);
    static void CheckItTwice();
};

void MyClass::Check (int value, const char * item)
{
  NS_LOG_FUNCTION (this << value << item);
  if (value > 10)
    {
	  NS_LOG_INFO("value larger than 10");
    }
  NS_LOG_INFO("value less than or equal to 10");
  CheckIt(value, item);
}

void MyClass::CheckIt (int value, const char * item)
{
  NS_LOG_FUNCTION (value << item);
  if (value > 10)
    {
	  NS_LOG_INFO("value larger than 10");
    }
  NS_LOG_INFO("less than 10 indeed, the item is " << item);
  CheckItTwice();
}

void MyClass::CheckItTwice ()
{
  NS_LOG_FUNCTION_NOARGS ();
  NS_LOG_INFO("let me check it again");
}


int 
main (int argc, char *argv[])
{
    LogComponentEnable("MyTestFunction", LOG_LEVEL_LOGIC);

    const char * item = "test item";

    MyClass myClass;
    myClass.Check(5, item);

}

其运行结果为：

1
2
3
4
5
6
7
8
9
10
11
12
Waf: Entering directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
[1736/1885] Compiling scratch/test-log-function.cc
[1839/1885] Linking build/scratch/test-log-function
Waf: Leaving directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
Build commands will be stored in build/compile_commands.json
'build' finished successfully (2.323s)
MyTestFunction:Check(0x7ffe415382ef, 5, test item)
value less than or equal to 10
MyTestFunction:CheckIt(5, test item)
less than 10 indeed, the item is test item
MyTestFunction:CheckItTwice()
let me check it again

可以看出，无论是NS_LOG_FUNCTION还是NS_LOG_FUNCTION_NOARGS都可能正常记录函数的调用过程，包括函数的名称和参数。然而，值得注意的是，函数名前面的前缀，并不是类的名字，而是模块的名字，而NS-3使用的前缀分隔符是冒号（:），而不是C++当中的两个冒号（::），也从侧面提示了这并不是类名，而是模块名。

最佳实践：在编写程序时应该始终提供函数日志，这样调试程序会比较方便。

6. 日志前缀

除了可以控制显示什么级别的日志之外，NS-3还提供了日志前缀，来控制显示日志的来源，从而更加方便我们进行调试。NS-3中可用的前缀有如下几种：

  • LOG_PREFIX_FUNC：输出日志所在的函数
  • LOG_PREFIX_TIME：输出日志产生的时间（注意此时间是仿真时间）
  • LOG_PREFIX_NODE：输出日志所在的节点编号
  • LOG_PREFIX_LEVEL：输出日志的级别
  • LOG_PREFIX_ALL：输出以上所有信息

可以使用LogComponentEnable和级别叠加使用，例如：

1
2
LogComponentEnable("MyTestLevel", LOG_LEVEL_INFO);
<marked style="border-bottom: 2px solid red;">LogComponentEnable("MyTestLevel", LOG_PREFIX_LEVEL);</marked>

需要注意的是，日志产生时间指的是仿真时间，而非机器的实际时间。如果仿真并没有启动，则不会输出任何时间。只有在Simulation::Run()运行之后输出的日志才会具有时间。同样的，只有绑定在节点中的NS-3模块在仿真过程中输出的日志才会具有节点前缀。

下面是一个使用前缀的完整例子：

test-log-prefix.cc
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */

/*
 * test-log-prefix.cc
 *
 *  Created on: Apr 1, 2018
 *      Author: Yu Xia <rainsia@163.com>
 */


#include "ns3/core-module.h"
#include "ns3/network-module.h"

using namespace ns3;

//NS_LOG_COMPONENT_DEFINE ("MyClass");
NS_LOG_COMPONENT_DEFINE ("MyTestPrefix");


void func1() {
    NS_LOG_WARN("this is a warn from func1");
}


class MyApplication: public Application{
public:
    static TypeId GetTypeId();
    MyApplication();
    virtual ~MyApplication();

    void DoAction();
protected:
    virtual void DoDispose();
    virtual void DoInitialize();

private:
    virtual void StartApplication();
    virtual void StopApplication();

private:
    Ptr<Node> m_node;

};

NS_OBJECT_ENSURE_REGISTERED(MyApplication);

TypeId
MyApplication::GetTypeId ()
{
    static TypeId tid = TypeId("ns3::MyApplication")
	    .SetParent<Application>()
	    .AddConstructor<MyApplication>()
	    ;

    return tid;
}

MyApplication::MyApplication ()
{
    NS_LOG_FUNCTION (this);
}

MyApplication::~MyApplication ()
{
    NS_LOG_FUNCTION (this);
}

void
MyApplication::StartApplication()
{
    NS_LOG_FUNCTION (this);
    Simulator::Schedule(Seconds(1.1), &MyApplication::DoAction, this);
}

void
MyApplication::StopApplication()
{
    NS_LOG_FUNCTION (this);
}

void
MyApplication::DoAction ()
{
    NS_LOG_FUNCTION (this);
    NS_LOG_UNCOND(Simulator::GetContext());
    NS_LOG_LOGIC("this is a logic from class");
}

void
MyApplication::DoDispose ()
{
    NS_LOG_FUNCTION (this);
    Application::DoDispose();
}

void
MyApplication::DoInitialize ()
{
    NS_LOG_FUNCTION (this);
    Application::DoInitialize();
}

int
main (int argc, char *argv[])
{
    LogComponentEnable("MyTestPrefix", LOG_LEVEL_LOGIC);
    LogComponentEnable("MyTestPrefix", LOG_PREFIX_ALL);

    NS_LOG_INFO("this is an info from main");
    NS_LOG_ERROR("this is an error from main");

    Simulator::Schedule(Seconds(1.0), func1);

    Ptr<Application> myApplication = CreateObject<MyApplication>();
    myApplication->SetStartTime(Seconds(0.0));
    myApplication->SetStopTime(Seconds(2.0));

    Ptr<Node> node = CreateObject<Node>();
    node->AddApplication(myApplication);
    myApplication->SetNode(node);

    Simulator::Run();
    Simulator::Destroy();
}

运行程序后得到如下的结果：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
Waf: Entering directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
[ 886/1887] Compiling scratch/test-log-prefix.cc
[1876/1887] Linking build/scratch/test-log-prefix
Waf: Leaving directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
Build commands will be stored in build/compile_commands.json
'build' finished successfully (2.180s)
MyTestPrefix:main(): [INFO ] this is an info from main
MyTestPrefix:main(): [ERROR] this is an error from main
0s -1 MyTestPrefix:MyApplication(0xd712f0)
0s 0 MyTestPrefix:DoInitialize(0xd712f0)
0s 0 MyTestPrefix:StartApplication(0xd712f0)
1s -1 MyTestPrefix:func1(): [WARN ] this is a warn from func1
1.1s 0 MyTestPrefix:DoAction(0xd712f0)
0
1.1s 0 MyTestPrefix:DoAction(): [LOGIC] this is a logic from class
2s 0 MyTestPrefix:StopApplication(0xd712f0)
MyTestPrefix:DoDispose(0xd712f0)
MyTestPrefix:~MyApplication(0xd712f0)

从程序和输出结果可以看出：

  • 所有输出都有级别作为前缀，例如：[INFO]或者[LOGIC]
  • 在仿真开始之前的输出是不会有时间前缀的
  • 输出带有函数前缀，函数的名字和NS_LOG_FUNCTION的输出结果一致，冒号前面始终是日志组件的名字而不是类名
  • 未提供函数日志的函数也可以具有函数前缀
  • 在仿真时间开始之前输出的结果，或者不在节点中的函数输出的结果其节点编号为-1
  • 在节点中的模块输出的结果，具有节点编号作为前缀
  • NS_LOG_UNCOND的输出不受前缀的影响
  • NS-3中节点的编号从0开始

由这个例子可以看出，NS-3提供的日志前缀机制可以方便地获取任何日志输出的时间、节点号、从哪个函数中打印的。充分、合理地利用这个机制，我们可以更快地查找问题，并修正问题。

7. 命令行控制日志

除了在程序中使用编程的方式控制日志的开启与否、输出级别、前缀等选项之外，还可以使用命令行进行控制。相对于在程序中控制日志，使用命令行控制最大的好处在于更新配置后不需要重新编译程序。

7.1. 语法

命令行控制的方式主要是通过设置环境变量NS_LOG来实现的。一般是在启动具体的仿真之前设置，具体方法如下：

1
$ NS_LOG="日志模块1=level|prefix:日志模块2=level|prefix:..." ./waf --run "test"

7.2. 日志级别

在命令行中，可以使用的级别和程序控制中一致，但是有更简洁的写法：

  • error （level_error）
  • warn （level_warn）
  • debug （level_debug）
  • info （level_info）
  • function （level_function）
  • logic （level_logic）
  • all (level_all)
  • *

前面的部分是单个的级别，括号中的部分是累计级别。

7.3. 日志前缀

和程序中一样，也可以使用前缀定义日志输出，写法更加简洁：

  • func
  • time
  • node
  • level
  • all
  • *

日志级别可以和日志前缀组合使用，之间使用竖线（|）分隔。

7.4. 使用方法

在上一个程序中，我们使用程序的方式定义了日志模块MyTestPrefix的日志为LOGIC级别以上，并且同时输出所有前缀。这次，我们使用命令行的方法定义输出级别和前缀，首先注释程序中的LogComponentEnable语句，然后在命令行中输入：

1
$ NS_LOG="MyTestPrefix=level_warn|level" ./waf --run "my-test-prefix"

需要注意的是，由于竖线（|）在linux命令当中表示管道，因此NS_LOG变量的值一定要用引号包裹起来。运行上面的命令，可以得到输出结果：

1
2
3
4
5
6
7
8
9
Waf: Entering directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
[ 886/1887] Compiling scratch/test-log-prefix.cc
[1855/1887] Linking build/scratch/test-log-prefix
Waf: Leaving directory `/home/rainsia/Applications/ns-allinone-3.24.1/ns-3.24.1/build'
Build commands will be stored in build/compile_commands.json
'build' finished successfully (2.178s)
[ERROR] this is an error from main
[WARN ] this is a warn from func1
0

由此可见，程序中设置日志级别优先级比命令行中设置要高。要命令行控制起效，必须将程序中的日志启用语句注释。命令行的控制将更加简介，并且更改日志的配置不需要重新编译程序。

本文标题:NS-3学习笔记（二）：NS-3的日志系统

文章作者:Rain Sia

发布时间:2018年03月30日 - 18:03

最后更新:2018年10月29日 - 10:10

原始链接: http://rainsia.github.io/2018/03/30/ns3-002/

版权信息:本文为作者原创文章，如需进行非商业性转载，请注明出处并保留原文链接及作者。如要进行商业性转载，请获得作者授权！

联系方式:rainsia@163.com