码迷,mamicode.com
首页 > 其他好文 > 详细

libvirt log系统分析

时间:2019-05-31 00:45:09      阅读:131      评论:0      收藏:0      [点我收藏+]

标签:复杂   初始化   error   code   nta   put   default   就是   priority   

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 1353
Breakpoint 1 at 0x17888: file libvirtd.c, line 1353.
(gdb) r
Starting 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.0
2018-08-17 02:25:46.299+0000: 21314: info : hostname: localhost.localdomain
2018-08-17 02:25:46.299+0000: 21314: debug : virLogParseFilters:1289 : filters=1:remote 4:event
2018-08-17 02:25:46.299+0000: 21314: debug : virLogParseFilter:1227 : filter=1:remote
2018-08-17 02:25:46.299+0000: 21314: debug : virLogParseFilter:1227 : filter=4:event
2018-08-17 02:25:46.299+0000: 21314: debug : virLogParseOutputs:1191 : outputs=1:file:/var/log/libvirt/libvirtd.log
2018-08-17 02:25:46.299+0000: 21314: debug : virLogParseOutput:1097 : output=1:file:/var/log/libvirt/libvirtd.log

Breakpoint 1, main (argc=<optimized out>, argv=0x7fffffffe638) at libvirtd.c:1353
1353        VIR_DEBUG("Decided on pid file path ‘%s‘", NULLSTR(pid_file));
(gdb) b virLogVMessage
Breakpoint 2 at 0x7ffff738d470: file util/virlog.c, line 549.

(gdb) c
Continuing.

 

进入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函数并且修改了变量,另外一个进程就不会在同一时刻进入此函数的临界区了。 

疑问

1.log_filters="3:remote 4:event"里面的remote和event是在哪定义的?具有什么意义?

A:不需要定义,只是字符串而已,详情见第5章

长期更新维护…

libvirt log系统分析

标签:复杂   初始化   error   code   nta   put   default   就是   priority   

原文地址:https://www.cnblogs.com/daxiatou/p/10952722.html

(0)
(0)
   
举报
评论 一句话评论(0
登录后才能评论!
© 2014 mamicode.com 版权所有  联系我们:gaon5@hotmail.com
迷上了代码!