libvirt log系统分析

阅读量：5365 次

发布时间：2019-06-15

本文共 9429 字，大约阅读时间需要 31 分钟。

1.编译和安装

配置参数需要加上–enable-debug=yes，相关定义在src/util/virlog.h文件中定义

图1-1 ENABLE_DEBUG宏

如果没有加这个编译参数，调用VIR_DEBUG_INT宏的函数或者其他宏，就没有任何效果，这是一切的一切的基础。其他编译安装省略，可见其他。

2.查看libvirtd配置文件

#从libvirtd入手，打开libvirtd的配置文件

[root@localhost ~]# vi /etc/libvirt/libvirtd.conf################################################################### Logging controls##log_level = 3#log_filters="3:remote 4:event"#log_outputs="3:syslog:libvirtd"#    1: DEBUG#    2: INFO#    3: WARNING#    4: ERROR

省略了一些介绍性的文字，只列出# Logging controls部分最重要的三个配置选项，以及几个日志等级，虽然每个配置都有自己的等级的介绍，但是这几个其实是一样的，在源码中只有一份定义，如图所示

图2-1 日志等级定义

后面还有一个#log_buffer_size = 6，根据注释说明，该配置项已经不再使用，应该是已经过时的项，后面就是# Auditing部分，虽然从技术上讲和log子系统没什么区别，但是侧重点不同，是属于安全审计一类的信息记录，和本文档讨论的内容无关，本文不会进行分析。

3.libvirtd日志输出方式log_outputs

先看log_outpus, 以下是配置文件中完整的注释信息

# Logging outputs:# An output is one of the places to save logging information# The format for an output can be:#    x:stderr#      output goes to stderr#    x:syslog:name#      use syslog for the output and use the given name as the ident#    x:file:file_path#      output to a file, with the given filepath#    x:journald#      output to journald logging system# In all case the x prefix is the minimal level, acting as a filter#    1: DEBUG#    2: INFO#    3: WARNING#    4: ERROR## Multiple outputs can be defined, they just need to be separated by spaces.# e.g. to log all warnings and errors to syslog under the libvirtd ident:#log_outputs="3:syslog:libvirtd"

可以看到，前面的数字表示了打印的等级，第二位和第三位是根据输出类型不同，意义也不同，例如默认的 log_outputs=“3:syslog:libvirtd” 中，代表输出的内容的等级为3: WARNING，并且使用linux系统自身的syslog来进行记录日志，日志条目的名字为libvirtd。目前libvirtd默认用的什么配置没有研究过，并且我们不想借用系统自带的syslog系统，因为那样可能会和系统其他程序或者系统自身的log信息混在一起，不方便调试，因此选择打印到独立的文件中

log_level = 4//决定了待打印的log信息的等级

log_outputs=“1:file:/var/log/libvirt/libvirtd.log”//这两个配置表示日志信息会被当作ERROR的级别，并且在输出的控制是DEBUG，即只要log级别大于等于DEBUG都可以被输出到/var/log/libvirt/libvirtd.log文件。

查看libvirtd.c的main函数1353行：

VIR_DEBUG("Decided on pid file path '%s'", NULLSTR(pid_file));

#重新启动libvirtd进程

[root@localhost ~]# systemctl restart libvirtd.service

#查看日志文件

[root@localhost ~]# cat /var/log/libvirt/libvirtd.log|grep "Decided on pid file path"

并没有看到相关日志信息，这是什么原因呢？下一节再分析，此处先做一个workaround，不深究原因，更改log_level的数值

log_level = 1

之后再重启libvirtd服务，可以看到，log信息确实写入了log_outputs指定的文件里。

[root@localhost ~]# cat /var/log/libvirt/libvirtd.log|grep "Decided on pid file path"2018-08-17 02:12:40.573+0000: 21095: debug : main:1353 : Decided on pid file path '/var/run/libvirtd.pid'

4.libvirtd日志输入级别log_level

从上一节可以看到，log_level确实可以影响日志是否能正常被打印到log_outputs所指定的文件中。具体如何影响的，分析代码。先将log_level改成4，分析为什么无法打印。

#关闭后台进程，直接用gdb跟踪

[root@localhost ~]# systemctl stop libvirtd.service(gdb) b 1353Breakpoint 1 at 0x17888: file libvirtd.c, line 1353.(gdb) rStarting program: /usr/sbin/libvirtd [Thread debugging using libthread_db enabled]Using host libthread_db library "/lib64/libthread_db.so.1".2018-08-17 02:25:46.299+0000: 21314: info : libvirt version: 2.0.02018-08-17 02:25:46.299+0000: 21314: info : hostname: localhost.localdomain2018-08-17 02:25:46.299+0000: 21314: debug : virLogParseFilters:1289 : filters=1:remote 4:event2018-08-17 02:25:46.299+0000: 21314: debug : virLogParseFilter:1227 : filter=1:remote2018-08-17 02:25:46.299+0000: 21314: debug : virLogParseFilter:1227 : filter=4:event2018-08-17 02:25:46.299+0000: 21314: debug : virLogParseOutputs:1191 : outputs=1:file:/var/log/libvirt/libvirtd.log2018-08-17 02:25:46.299+0000: 21314: debug : virLogParseOutput:1097 : output=1:file:/var/log/libvirt/libvirtd.logBreakpoint 1, main (argc=
      
       , argv=0x7fffffffe638) at libvirtd.c:13531353        VIR_DEBUG("Decided on pid file path '%s'", NULLSTR(pid_file));(gdb) b virLogVMessageBreakpoint 2 at 0x7ffff738d470: file util/virlog.c, line 549.(gdb) cContinuing.

进入virLogVMessage函数后，列出各种变量信息

图4-1列出变量信息

可以看到source的priority为3，在log_level等三个配置中没有任何地方配置的是3，这里会误导人，因为后面还会有变化，从代码中可以看到

图4-2

图4-3

source->priority的值是会在virLogSourceUpdate函数中刷新的，只要virLogSourceUpdate被调用，继续跟踪断点可以看到，猜测是正确的，如下图所示：

图4-4 virLogSourceUpdate内部

可以看到，virLogSourceUpdate函数给source->priority进行了重新赋值，使之成为了配置文件中log_level设定的数值4，至于virLogSourceUpdate具体做了什么，这要结合最后一个filter参数来参数，比较复杂，不影响此处的理解，之后再来分析，这里可以不用深究。接下来：

图4-5 判断是否打印

第575行可以看到这里的prioriy为VIR_LOG_DEBUG=1，而source->priority=4，会执行goto clean语句，因此无法打印。而此处的priority来源于调用此函数的宏本身的设置

图4-6-1

图4-6-2

所以，这种设计思路就是允许通过log_level来设定log内容的级别，如果log_level小于log_outputs设定的输出的级别，就可以打印到log文件中，但是一定要使用级别正确（够资格）的宏，这里用VIR_ERROR，就可以了，经过验证，分析无误。为什么要log_level不能大于log_outputs设定的输出的级别，按理说大优先级的内容应该可以更加优先的输出，这种理解在信息安全领域是不正确的，根据分级安全的理论，读操作的时候，低级别的reader无法读取高级别的内容，但是可以做write操作，直观的看就是低安全级别的人员可以把自身的信息暴露给上级，而不用担心泄密；反过来，高级别的writer就不能像低级别的地方做write操作，这样就会泄露信息，这个log的模型也是一个write操作，因此也是用的这种思路，但是不涉及read操作。

[root@localhost ~]# cat /var/log/libvirt/libvirtd.log|grep "Decided on pid file path"2018-08-17 08:07:37.838+0000: 27663: error : main:1354 : Decided on pid file path '/var/run/libvirtd.pid'

可以看到，VIR_ERROR宏具有最高权限，随后是VIR_WARN，VIR_INFO，VIR_DEBUG，高级别的宏可以打印低级别的log_level的log日志，但是反过来不行。注意，这个地方是控制打印的宏是否有资格做出打印这个动作，但是无法决定是否有权力写到某个文件中，如果打印的动作都无法做出，就会跳转到clean之后直接返回了，不会执行以下代码。log信息决定是否有权力写到某个文件中是由log_outputs参数决定的，如下图所示，这样两种行为的区别就分清楚了。

图4-7判断是否允许打印到输出对象（文件或者标准输出等）

# util/virlog.c:619 virLogOutputs[i].f(source, priority,                               filename, linenr, funcname,                               timestamp, metadata, filterflags,                               str, msg, virLogOutputs[i].data);=>virLogOutputToFd

通过循环语句，把所有log_outputs所描述的输出途径都遍历一遍并且进行输出，真正写入是调用这个函数。整个日志大致框架就是这样。

5.libvirtd过滤器log_filter

5.1.virLogSourceUpdate函数分析

上一章图4-2和图4-3可以看到，当满足source->serial < virLogFiltersSerial的时候，就会调用virLogSourceUpdate(source)，在这个函数内部，会对source的各种变量进行重新设置，依据就是前一章提到的log_level，以及本章要提到的filter。首先分析这个函数：

图5-1 virLogSourceUpdate

474行有一个判断条件if (source->serial < virLogFiltersSerial) ，这个地方先不管，这是另外一个机制，比较难以理解，不影响filter本身的功能。 475行的unsigned int priority = virLogDefaultPriority;//用一个全局变量给当前的priority赋值，这个全局变量来源于libvirtd.conf配置文件中的log_level。还有一个全局变量virLogNbFilters，代表filter的数量，默认是0，而virLogFilters数组就代表了filter的内容，如果没有设置filter，此处也为空。该函数就会执行到486行，相当于filter没有生效，但是这不是我们要看到的效果，因此在配置文件中配置一下filter log_filters="3:daemon4:event" 调试进入1virLogSourceUpdate函数，打印信息如下：

(gdb) p virLogFiltersSerial$2 = 4(gdb) p virLogNbFilters$3 = 2(gdb) p virLogFilters$4 = (virLogFilterPtr) 0x5555557e11b0(gdb) p virLogFilters[0]$5 = {match = 0x5555557ec040 "daemon", priority = VIR_LOG_WARN, flags = 0}(gdb) p source[0]$6 = {name = 0x5555555ad318 "daemon.libvirtd", priority = 3, serial = 1, flags = 0}(gdb) p virLogFilters[1]$7 = {match = 0x5555557ebfa0 "event", priority = VIR_LOG_ERROR, flags = 0}

可以看到virLogNbFilters就是对应的两个filter的数量，virLogFilters就是两个filter的内容，"daemon"的优先级为 VIR_LOG_WARN，"event"的优先级为VIR_LOG_ERROR，也就是log_filters中设置的3和4。

479行的循环会遍历virLogFilters数组，用if (strstr(source->name, virLogFilters[i].match)) 来判断，filter数组virLogFilters里面的内容是不是source->name的子串，是的话，则匹配成功。

此处，virLogFilters[0]的daemon就可以和source->name匹配，这样source的优先级也会被filter中定义的优先级给刷新。

可以看到，log_outputs, log_level, log_filter三者组合起来使用就可以很灵活的控制LOG打印，三者之间的关系是log_level会指定默认的输入数据（source）的级别（级别不够的宏无法被打印，因此打印出来的一定是级别够的），而过滤器log_filter会改变这种级别，使之以过滤器处理过的级别来输出（可以理解成是一种中间人攻击，中途篡改了优先级），log_filter定义的输出通道决定了输出的级别，如果source数据的级别小于输出通道的级别，就无法从这个通道输出。

5.2.使用VIR_LOG_INIT宏

上一节可以看到，log_filter可以对信息进行过滤，既然能过滤，说明log信息一定存在某种标识符，这个就是VIR_LOG_INIT决定的，例如src/qemu/qemu_process.c文件里面开头的VIR_LOG_INIT(“qemu.qemu_process”);

这样，如果配置log_filters=“1:qemu.qemu_process”，该文件下的所有信息都可以被转化为优先级1，并且这一步是在与log_level比较之前生效的，从而小于等于log_level，因此都可以被打印出来，这里filter的功能不涉及优先级大小的条件，只要是满足VIR_LOG_INIT宏所定义的字符串的的前驱值，都能任意替换掉优先级，无论放大还是放小。

5.3.分析VIR_LOG_INIT宏

图5-2 声明本文件的log标志

图5-3 宏的具体信息

这里的内存纯粹初始化，没有任何实际意义，除了name以外的东西都会变化 (gdb) p virLogSelf $11 = {name = 0x7f8f7d3e8ef0 "util.log", priority = 3, serial = 2, flags = 0} 这个virLogSelf是静态变量，之所以每次看到的都是这个，是因为当前断点打到该文件里了，因此次次都是同样的值，static标记的变量对单个文件全局有效，而5.1节中virLogSourceUpdate的参数source就是调用VIR_DEBUG或者其他宏的代码所在的文件的virLogSelf静态变量，再和virLogFilters全局变量进行比较，用来确定该文件中的log是否改变优先级并且打印到log中。

6.libvirtd日志序列化（serialization）

6.1.virLogFiltersSerial的意义

前面章节中忽略掉的最后一样东西，就是本章要提到的序列化（这样称呼不确定是否合理，暂且这么称呼），当调用virLogSourceUpdate函数之前，要用以下语句作为判断

if (source->serial < virLogFiltersSerial)        virLogSourceUpdate(source);

图6-1解析filter

跟踪给全局变量virLogFiltersSerial赋值的流程可以看到，virLogParseFilters函数会解析log_filters中参数的个数，并且使得virLogFiltersSerial每次循环都加1，而virLogFiltersSerial在libvirtd初始化的时候会变成2，因此virLogFiltersSerial = 2+virLogNbFilters，经过验证，此处代码分析无误。

在每次调用virLogSourceUpdate结束前，都会把source->serial 更新为 virLogFiltersSerial，这样代表源数据的信息已经经过filter更新过了，不需要再执行这个函数，从这个角度看，用一个bool型的变量也可以完成此功能，比如说flag属性，但是当前的设计可以应对filter的数量动态增加的情况，这样，virLogSourceUpdate就会被再次调用了，只是目前没在使用和分析中发现filter数量动态增加的情况，背后的设计思路还未知，这里不用深究。 ## 6.2.LogLock的意义上一小节里面提到的virLogSourceUpdate所有内容，都是在一对virLogLock()和virLogUnlock();之间的，这样做的意义何在，按照代码注释描述：

/*     * 3 intentionally non-thread safe variable reads.     * Since writes to the variable are serialized on     * virLogLock, worst case result is a log message     * is accidentally dropped or emitted, if another     * thread is updating log filter list concurrently     * with a log message emission.     */

大致意思就是多线程同时写log的时候，为了防止冲突，增加了一个锁，在virLogSourceUpdate函数被调用之前增加一个打印，在bash下启动libvirtd

图6-2增加打印信息

可以看到诸如下图所示的信息，直观的显示了这种设计在宏观上遇到的场景。

图6-3 log打印抢占

红色字体部分即为发生抢占了，两个name为util.file的source想调用virLogSourceUpdate函数并利用virLogFiltersSerial全局变量修改自身的序列号，由于锁的存在，发生的抢占，只有一个成功调用了virLogSourceUpdate函数并且修改了变量，另外一个进程就不会在同一时刻进入此函数的临界区了。