多进程访问共享库全局变量问题简单实例——全局变量被踩debug方法辑录

发表于 | 分类于 | | 阅读次数:
字数统计: 4,037 字 | 阅读时长 ≈ 18 分钟

　　上周处理一个问题，发现一个so的结构体全局变量数据异常。一开始怀疑是没dump成功，后面加log发现异常时对象全为0了。确认打印发现该结构体某成员一会为0一会为1，便初步定性为全局变量被踩，最终经过各种手段、alpha和kent大的助攻定位到原因。实际该问题是一个多进程环境共享对象内全局变量分配问题。很好玩的一个问题，就此简要分享。

　　“错误包含丰富的信息”　—— Nassim Nicholas Taleb《Antifragile》
　　前置说明：如下log均是构造出来的，仅作模拟的例子，所以全部log的时间是一样的。这次由于一开始错误的思维定势以及debug过程被各种打断，导致没记录好debug结论，实际debug过程比这篇文章描述的复杂且乱。也正因如此，有了梳理下这个问题处理过程的想法，借以总结下全局变量数据异常时候的处理方法，便于以后参考借鉴。

1. 确定是否有异常读写行为

　　debug就是从最基础的开始，收集各种信息，然后做推断，再找证据证明推断，循序渐进，抽丝剥茧，最终找到问题的根源。对问题的起始定义很重要，比如这次这个问题，首先加log，获取得如下信息。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
1. 所有用到该结构体的函数入口皆加入如下打印：
printf("%s-%d >> stConfig.bUsing[%d] [%p]\r\n", __FUNCTION__,__LINE__ ,stConfig.bUsing, &stConfig);
2. 异常log如下：
01-01 08:00:02.913 2048 2048 I Process:  _XXXMAP_DumpTable_U2-2869  >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:02.913 2048 2048 I Process:  XXX_DumpPanelInfo-1706     >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:02.914 2048 2048 I Process:  _SetXXXParams-644          >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.146 2048 2048 I Process:  _GetStatusEx_U2-1846       >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.146 2048 2048 I Process:  GetDataFromRegister-1872   >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.146 2048 2048 I Process:  _GetStatusEx_U2-2009       >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2048 2048 I Process:  GetDataFromRegister-1872   >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2048 2048 I Process:  _GetStatusEx_U2-2009       >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2048 2048 I Process:  GetDataFromRegister-1872   >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2048 2048 I Process:  _GetStatusEx_U2-2009       >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:06.265 2048 2048 I Process:  SetXXX_Fmodulation-1953    >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.265 2048 2048 I Process:  SetXXX_Rdeviation-2034     >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.265 2048 2048 I Process:  SetXXX_En-1928             >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.267 2048 2048 I Process:  SetXXX_Fmodulation-1953    >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.267 2048 2048 I Process:  SetXXX_Rdeviation-2034     >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.267 2048 2048 I Process:  SetXXX_En-1928             >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:08.594 2048 2048 I Process:  GetDataFromRegister-1872   >> stConfig.bUsing[1] [0xea00795c]

　　从如上log可以看出，所有用到这个变量的函数都在同个进程同个线程内（PID-2048），这也就可以排除多线程并发引发的全局变量数据篡改问题(我在这里有怀疑过是动态库全局变量问题，但因为进程号相同，直接推翻)。接下来怀疑是在这些函数中有地方去操作这个变量，于是Read the Fucking Source Code，却发现整个程序中只有XXX_DumpPanelInfo这个函数会去操作这个对象，大致代码如下，可见函数执行后stConfig便不会为0，而注释掉memset，问题依旧。下一个需要确认的就是是否有对这个全局变量的指针引用，指针操作也可以写坏数据，但review了一轮source code，发现并没有，同时也没有发现同名全局变量的存在，也就排除so链接过程出现同名全局变量覆盖问题(有两种，一种是两个so都有同名全局变量，比如Linux系统下DSO同名全局变量浅析，一种是bin和so都有全局变量，比如linux so 动态库中全局变量 被覆盖问题。)。

1
2
3
4
5
6
void XXX_DumpPanelInfo(&stConfig)
{   
    memset(&stConfig, 0, sizeof(stConfig))；
    stConfig.bUsing = TRUE;
    ... // 对stConfig其他成员的操作
}

2. 上GDB确认问题

　　经过这上一轮debug，我们排除了一些常见的可能，也就以此初步推断可能是其他全局变量越界踩内存的问题。在说明我所用的gdb debug方式之前，我们先讲下gdb的watch功能，详细可以参看gdb online documentSetting Watchpoints。一般而言，如果不方便review code却又想尽快抓到修改变量的地方，我们可以通过gdb watch功能来实现。但他也有局限性，具体实例如下。我们可以看出，watch适用于同进程内直接对变量访问时的监控，对于越界访问检测没有太大的助力。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
(gdb) l
1       #include <stdio.h>
2       int gVar[2]={0,0};
3       int gVar2 = 0;
4
5       int main(void)
6       {
7           printf("gVar>>%p, gVar2>>%p\r\n", gVar,&gVar2 );
8           gVar[2] = 2;
9           printf("global_uninit_var>>%d\r\n", gVar2);
10          return 0;
11      }
(gdb) watch gVar2
Hardware watchpoint 1: gVar2
(gdb) run
Starting program: /home/donald-zhuang/Desktop/demo/a.out 
gVar>>0x601040, gVar2>>0x601048

Hardware watchpoint 1: gVar2

Old value = 0
New value = 2
main () at SimpleSection.c:9
9           printf("global_uninit_var>>%d\r\n", gVar2);

　　不过gdb的x功能（具体参考x command）能弥补如上缺陷。当watch抓到变量异常时，我们可以通过x命令第一时间查看进程内存布局。如下这段gdb续上一过程，首先通过print获取gVar2的地址，然后我们在其地址减1的地址上dump数据找到他的上家，继而定位到是谁越界了。这个例子中，我们可以看到就是gVar了。找到调用这个数组的地方，review code即可发现问题所在。

1
2
3
4
5
6
7
8
Old value = 0
New value = 2
main () at SimpleSection.c:9
9           printf("global_uninit_var>>%d\r\n", gVar2);
(gdb) p &gVar2
$1 = (int *) 0x601048 <gVar2>
(gdb) x/4x 0x601048-1
0x601047 <gVar+7>:      0x00000200      0x00000000      0x00000000      0x00000000

　　因为其他原因，我的做法是在抓到异常数据的地方，也就是在SetXXX_Fmodulation-1953入口处加了一个abort，让它coredump，然后通过coredump解析当前内存布局和进程情况。解析coredump可以看到如下信息，其中被踩的对象就是config那一块，其前面的对象是两个锁，还有m_vTag这个对象，通过print m_vTag这个对象，可以看到其成员数据合法、非零，故此不存在前面数据大范围越界踩到stConfig的问题。那就迷糊了，难不成是其他地方的虚地址错误然后神奇得踩到这个位置。

3. mprotect与kernel hardware breakpoint

　　对于这种无厘头的问题，就要上利器了，mprotect与kernel hardware breakpoint，前者是跨进程的，后者是进程内有效。因为我们的code中有支持kernel hardware breakpoint，所以我就直接上了，这部分有兴趣大家可以参考这篇博文内核模块踩内存问题定位利器- hardware breakpoint，参考的实例代码如下。

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
static void sample_hbp_handler(struct perf_event *bp,
			       struct perf_sample_data *data,
			       struct pt_regs *regs)
{
	printk(KERN_INFO "%s value is changed\n", ksym_name);
	dump_stack();
	printk(KERN_INFO "Dump stack from sample_hbp_handler\n");
}
 
static int __init hw_break_module_init(void)
{
	int ret;
	struct perf_event_attr attr;
    
	hw_breakpoint_init(&attr);
	attr.bp_addr = kallsyms_lookup_name(ksym_name);//待监视的地址，指令和数据地址均可以
	attr.bp_len = HW_BREAKPOINT_LEN_4;
	attr.bp_type = HW_BREAKPOINT_W | HW_BREAKPOINT_R;//待监视的访问类型
       //sample_hbp_handler为待监视的地址被访问时调用
	sample_hbp = register_wide_hw_breakpoint(&attr, sample_hbp_handler, NULL);
	if (IS_ERR((void __force *)sample_hbp)) {
		ret = PTR_ERR((void __force *)sample_hbp);
		goto fail;
	}
	printk(KERN_INFO "HW Breakpoint for %s write installed\n", ksym_name);
	return 0;
    
fail:
	printk(KERN_INFO "Breakpoint registration failed\n");
	return ret;
}
 
static void __exit hw_break_module_exit(void)
{
	unregister_wide_hw_breakpoint(sample_hbp);
	printk(KERN_INFO "HW Breakpoint for %s write uninstalled\n", ksym_name);
}

　　不过不幸的是，功能并没有支持好，导致没能顺利抓到异常访问行为，就此作罢。既然被踩，那还可以上一招，mprotect，这个函数是通过设置进程内页属性，来实现对内存的读写保护，因为是设置页的属性，这也就决定了该函数能保护的内存需要4K对齐且大小也需要为4K倍数。具体可参考Linux Programmer’s Manual。我们的全局变量没有4K大，也就需要构造下，然后验证下问题是否还能复现，具体的操作是根据实际情况对结构体定义调整，类似如下方式塞入dummy数据，然后复现问题，加完之后发现问题依旧复现得到（我在这里怀疑人生了…后加打印发现编译器优化了结构体布局，stConfig.bUsing仍然在首部）。

1
2
3
4
5
6
7
struct STCONFIG
{
    char dummy[4095];
    BOOL bUsing;
    ...
    char dummy2[4095];
};

　　既然复现得到，就可以加mprotect保护。我们必须在dump数据后对该区域进行保护，其中第三行是保证地址是4K对齐的，PROT_READ表示将该页设置为只读的。这个函数执行完后，进程内其他地方如果尝试写或执行便会引发页错误，导致coredump，这样我们也就抓到异常点了。

1
2
3
4
5
6
7
8
9
XXX_DumpPanelInfo(&stConfig);   // ensure the data have been initialized
#define PAGE_ALIGN_SIZE (4096)  // the size of page
char *pstConfig = (char*)(((int)(&stConfig) + PAGE_ALIGN_SIZE - 1) & (~(PAGE_ALIGN_SIZE-1))); // align to page size
if(mprotect((void*)pstConfig, PAGE_ALIGN_SIZE, PROT_READ))
{
    printf("protect failed!\r\n")
}
保护执行的打印
printf("%s-%d >> stConfig.bUsing[%d] [%p]\r\n", __FUNCTION__,__LINE__, stConfig.bUsing, &(stConfig.bUsing));

　　调整后得到如下log，我们可以看到加粗的两行log，软件不仅进了两次保护，还写了两次！然后没有任何coredump。于是我在加保护之后，尝试补一个写操作，结果如期出现coredump，也就证明保护实际是起效。在这情况下，我老板提醒了我mprotect是同进程内有效，跨进程无效，故以此为根基进入下一个debug。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
01-01 08:00:02.913 2048 2048 I Process:  _XXXMAP_DumpTable_U2-2869  >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:02.913 2048 2048 I Process:  XXX_DumpPanelInfo-1706     >> stConfig.bUsing[1] [0xea00795c]
__01-01 08:00:02.913 2048 2048 I Process:  XXX_DumpPanelInfo - 2874   >> mprotect addr 0xea00795c >> 0xea00795c__
01-01 08:00:02.914 2048 2048 I Process:  _SetXXXParams-644        >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.146 2048 2048 I Process:  _GetStatusEx_U2-1846       >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.146 2048 2048 I Process:  GetDataFromRegister-1872   >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.146 2048 2048 I Process:  _GetStatusEx_U2-2009       >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2048 2048 I Process:  GetDataFromRegister-1872   >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2048 2048 I Process:  _GetStatusEx_U2-2009       >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2048 2048 I Process:  GetDataFromRegister-1872   >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2048 2048 I Process:  _GetStatusEx_U2-2009       >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:06.265 2048 2048 I Process:  SetXXX_Fmodulation-1953    >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.265 2048 2048 I Process:  SetXXX_Rdeviation-2034     >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.265 2048 2048 I Process:  SetXXX_En-1928             >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.267 2048 2048 I Process:  SetXXX_Fmodulation-1953    >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.267 2048 2048 I Process:  SetXXX_Rdeviation-2034     >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.267 2048 2048 I Process:  SetXXX_En-1928             >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:08.594 2048 2048 I Process:  GetDataFromRegister-1872   >> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:08.913 2048 2048 I Process:  _XXXMAP_DumpTable_U2-2869  >> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:08.913 2048 2048 I Process:  XXX_DumpPanelInfo-1706     >> stConfig.bUsing[1] [0xea00795c]
__01-01 08:00:08.913 2048 2048 I Process:  XXX_DumpPanelInfo - 2874   >> mprotect addr 0xea00795c >> 0xea00795c __

4. 印PID，共享库全局变量问题

　　基于各种对变量被踩debug的不合理现象，问题的本质实际在不断展露。不过我还没能抓到点，找老板指点，在如上基础上，我老板让我在log上印pid，结果如下。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
printf("%s-%d PID(%d)>> stConfig.bUsing[%d] [%p]\r\n", __FUNCTION__,__LINE__, getpid(),stConfig.bUsing, &stConfig);

01-01 08:00:02.913 2052 2052 I Process:  _XXXMAP_DumpTable_U2-2869  (PID-2065)>> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:02.913 2052 2052 I Process:  XXX_DumpPanelInfo-1706     (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
__01-01 08:00:02.913 2052 2052 I Process:  XXX_DumpPanelInfo - 2874   (PID-2065)>> mprotect addr 0xea00795c >> 0xea00795c__
01-01 08:00:02.914 2052 2052 I Process:  _SetXXXParams-644        (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.146 2052 2052 I Process:  _GetStatusEx_U2-1846       (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.146 2052 2052 I Process:  GetDataFromRegister-1872   (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.146 2052 2052 I Process:  _GetStatusEx_U2-2009       (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2052 2052 I Process:  GetDataFromRegister-1872   (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2052 2052 I Process:  _GetStatusEx_U2-2009       (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2052 2052 I Process:  GetDataFromRegister-1872   (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:03.351 2052 2052 I Process:  _GetStatusEx_U2-2009       (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:06.265 2052 2052 I Process:  SetXXX_Fmodulation-1953    (PID-2066)>> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.265 2052 2052 I Process:  SetXXX_Rdeviation-2034     (PID-2066)>> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.265 2052 2052 I Process:  SetXXX_En-1928             (PID-2066)>> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.267 2052 2052 I Process:  SetXXX_Fmodulation-1953    (PID-2066)>> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.267 2052 2052 I Process:  SetXXX_Rdeviation-2034     (PID-2066)>> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:06.267 2052 2052 I Process:  SetXXX_En-1928             (PID-2066)>> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:08.594 2052 2052 I Process:  GetDataFromRegister-1872   (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
01-01 08:00:08.913 2052 2052 I Process:  _XXXMAP_DumpTable_U2-2869  (PID-2066)>> stConfig.bUsing[0] [0xea00795c]
01-01 08:00:08.913 2052 2052 I Process:  XXX_DumpPanelInfo-1706     (PID-2065)>> stConfig.bUsing[1] [0xea00795c]
__01-01 08:00:08.913 2052 2052 I Process:  XXX_DumpPanelInfo - 2874   (PID-2066)>> mprotect addr 0xea00795c >> 0xea00795c __

　　打印相关进程的PID信息如下，根据进程文件可知，如下多个进程都是同一个bin档实现的服务，然后经过2052的logwrapper将log打印出来，因此log上的PID都是logwrapper的，至此问题原因昭然若揭，上面debug的各种不合理之处也就有了明确的解释了。如上所看为何变量地址一样，为何mprotect“起效和失效”，在这里可以看到，原来这是一个典型的动态库内全局变量问题。

1
2
3
4
5
6
console:/# busybox ps | grep Process
1984 0        0:00 /application/bin/Process
2052 0        0:00 {logwrapper}/application/bin/Process
2065 0        0:43 /application/bin/Process
2066 0        6:52 {ServiceAProcess}/application/bin/Process
2067 0        0:00 {ServiceBProcess}/application/bin/Process

　　关于这个问题，本质是共享对象中的全局变量会在可执行档中有一个副本，并且实际运行中采用的便是这个副本，不同进程对同一个共享对象的全局变量引用是各自独立的。前阵子看了程序员自我修养的196页中，有如下解释

由于可执行文件在运行时并不进行代码重定位，所以变量的地址必须在链接过程中确定下来，为了能使得链接过程正常进行，链接器会在创建可执行文件时，在它的.bss段创建一个global变量的副本。那么问题就很明显了，现在global变量定义在原先的共享对象中，而在可执行文件的bss段中还有一个副本，如果同一变量同时存在于多个位置中，这在程序的实际运行过程中肯定是不可行的。
于是解决办法只有一个，那就是所有的使用这个变量的指令都指向位于可执行文件中的那个副本。elf共享库编译时，默认都把定义在模块内部的全局变量当做定义在其他模块的全局变量。…

5. 终章，我要去赶飞机了

　　至此问题也就解决了，根本原因也就是两个不同的进程对同一个共享库的全局变量进行引用，而我们的多个服务进程是基于同一个bin通过不同参数启动，coder没有注意到两个module不在同个service进程中，导致采用的全局变量没能正确初始化，继而导致异常的发生。当然实际问题比这个更复杂，debug理清过程也花了我两天的时间，不过这次也是有收获的，哈哈，读书有用啊。我要赶飞机了，梳理就暂时到此，下次再调整下文章和引用的。