今天解决的一个bug，分享过程（低级错误铸就不小的麻烦。）

1万 · 2015-3-11 15:24

本程序功能：任务分发服务器
程序环境：centos(redhat的一个linux系统)
系统构成：请求端 + 任务分发服务器 + 功能服务器

系统功能：首先，系统启动，任务分发服务器从TCP某端口接收到请求端一个命令后，通过TCP另外端口连接调用一个远端方法。
然后返回结果给请求端。

1万 · 2015-3-11 15:27

问题出在返回结果给请求端的时候，任务分发服务器程序crash掉。
报的错误是SIGBUS,bus error.GDB将错误定位到具体行。如下：

OnTaskResult, result:0, session:8890336 ***************

Program received signal SIGBUS, Bus error.
event_assign (ev=0x888c30, base=0x786966657270222c, fd=16, events=4, callback=0x4412ac <on_connect(int, short, void*)>, arg=0x889360) at event.c:1752
1752 ev->ev_pri = base->nactivequeues / 2;

1万 · 2015-3-11 15:28

检查堆栈，结果如下：

(gdb) bt
#0  event_assign (ev=0x888c30, base=0x786966657270222c, fd=16, events=4, callback=0x4412ac <on_connect(int, short, void*)>, arg=0x889360) at event.c:1752
#1  0x0000000000529e1b in event_new (base=0x786966657270222c, fd=16, events=4, cb=0x4412ac <on_connect(int, short, void*)>, arg=0x889360) at event.c:1791
#2  0x00000000004415d9 in cdy::ConnectorImp::Connect (this=0x889360, timeout=3000) at ../src/connbaseimp.cpp:274
#3  0x000000000044164a in cdy::Connector::Connect (this=0x822b30, timeout=3000) at ../src/connbaseimp.cpp:33
#4  0x00000000004395e9 in SessionManagerImp::SendAppMessage (this=0x7ff180, appMessage=...) at ../src/SessionManagerimp.cpp:106
#5  0x000000000043c5a0 in SessionManager::SendAppMessage (this=0x7ff368, appMessage=...) at ../src/SessionManager.cpp:54
#6  0x0000000000412d14 in DsManage::OnTaskResult (this=0x7dbd80, taskResult=..., session=...) at ../src/disptask.cpp:416
#7  0x000000000043d412 in TsSessionImp::OnFrame (this=0x87e1f0, frame=
"{\n \"errorcode\" : \"19\",\n \"errordetail\" : \"/usr/local/MountTmpDir/10.1.150.120/data/teleconference/document/a5/88/85/29ed49b5-4576-4b38-975c-fa229451b163.pptx not exitsted\",\n \"file\" : \"/usr/local/"...)
at ../src/SessionImp.cpp:223
#8  0x000000000043d721 in SessionImp::ProcessFrame (this=0x87e1f0,
buf=0x87e7a8 "{\n \"errorcode\" : \"19\",\n \"errordetail\" : \"/usr/local/MountTmpDir/10.1.150.120/data/teleconference/document/a5/88/85/29ed49b5-4576-4b38-975c-fa229451b163.pptx not exitsted\",\n \"file\" : \"/usr/local/"..., length=593) at ../src/SessionImp.cpp:49
#9  0x000000000043d7f9 in TsSessionImp::OnData (this=0x87e1f0,
buf=0x87e7a8 "{\n \"errorcode\" : \"19\",\n \"errordetail\" : \"/usr/local/MountTmpDir/10.1.150.120/data/teleconference/document/a5/88/85/29ed49b5-4576-4b38-975c-fa229451b163.pptx not exitsted\",\n \"file\" : \"/usr/local/"..., length=593, conn=0x87e770) at ../src/SessionImp.cpp:160
#10 0x000000000043ff78 in cdy::ConnectionImp::OnRead (this=0x87e770, sock=14) at ../src/connbaseimp.cpp:380
#11 0x000000000043ffb3 in on_read (sock=14, events=2, args=0x87e770) at ../src/connbaseimp.cpp:161
#12 0x000000000052c6c8 in event_process_active_single_queue (base=0x87a810, flags=0) at event.c:1346
#13 event_process_active (base=0x87a810, flags=0) at event.c:1416
#14 event_base_loop (base=0x87a810, flags=0) at event.c:1617
#15 0x000000000043f0de in cdy::EventLooperImp::RunEventLoop (this=0x7ff3a0) at ../src/eventlooperimp.cpp:60
#16 0x00000000004094e4 in main (argc=1, argv=0x7fffffffe928) at ../src/main.cpp:105

1万 · 2015-3-11 15:34

获取以上信息后，第一遍因为没有注意堆栈细节，没有看到问题所在。

于是漫无目的得看一下反汇编，如下：

(gdb)  disas event_assign
Dump of assembler code for function event_assign:
0x0000000000529af0 <event_assign+0>: push %r15
0x0000000000529af2 <event_assign+2>: mov %edx,%r15d
0x0000000000529af5 <event_assign+5>: push %r14
0x0000000000529af7 <event_assign+7>: mov %r9,%r14
0x0000000000529afa <event_assign+10>: push %r13
0x0000000000529afc <event_assign+12>: mov %r8,%r13
0x0000000000529aff <event_assign+15>: push %r12
0x0000000000529b01 <event_assign+17>: mov %ecx,%r12d
0x0000000000529b04 <event_assign+20>: push %rbp
0x0000000000529b05 <event_assign+21>: mov %rsi,%rbp
0x0000000000529b08 <event_assign+24>: push %rbx
0x0000000000529b09 <event_assign+25>: mov %rdi,%rbx
0x0000000000529b0c <event_assign+28>: sub $0x8,%rsp
0x0000000000529b10 <event_assign+32>: mov 0x2e9a1a(%rip),%eax       # 0x813530 <_event_debug_mode_on>
0x0000000000529b16 <event_assign+38>: test %rsi,%rsi
0x0000000000529b19 <event_assign+41>: cmove  0x2e9a07(%rip),%rbp       # 0x813528 <event_global_current_base_>
0x0000000000529b21 <event_assign+49>: test %eax,%eax
0x0000000000529b23 <event_assign+51>: je    0x529b96 <event_assign+166>
0x0000000000529b25 <event_assign+53>: mov 0x2e9a0c(%rip),%rsi       # 0x813538 <_event_debug_map_lock>
0x0000000000529b2c <event_assign+60>: test %rsi,%rsi
0x0000000000529b2f <event_assign+63>: je    0x529b39 <event_assign+73>
0x0000000000529b31 <event_assign+65>: xor %edi,%edi
0x0000000000529b33 <event_assign+67>: callq  *0x2e9a7f(%rip)       # 0x8135b8 <_evthread_lock_fns+24>
0x0000000000529b39 <event_assign+73>: mov 0x2b19a0(%rip),%rcx       # 0x7db4e0 <global_debug_map>
0x0000000000529b40 <event_assign+80>: test %rcx,%rcx
0x0000000000529b43 <event_assign+83>: je    0x529b82 <event_assign+146>
0x0000000000529b45 <event_assign+85>: mov %ebx,%eax
0x0000000000529b47 <event_assign+87>: xor %edx,%edx
0x0000000000529b49 <event_assign+89>: shr $0x6,%eax
0x0000000000529b4c <event_assign+92>: divl 0x2b1996(%rip)       # 0x7db4e8 <global_debug_map+8>
0x0000000000529b52 <event_assign+98>: mov %edx,%edx
0x0000000000529b54 <event_assign+100>:  mov (%rcx,%rdx,8),%rdx
0x0000000000529b58 <event_assign+104>:  test %rdx,%rdx
0x0000000000529b5b <event_assign+107>:  mov %rdx,%rax
0x0000000000529b5e <event_assign+110>:  je    0x529b82 <event_assign+146>
0x0000000000529b60 <event_assign+112>:  cmp %rbx,0x8(%rdx)
0x0000000000529b64 <event_assign+116>:  jne 0x529b7a <event_assign+138>
0x0000000000529b66 <event_assign+118>:  jmpq 0x529d51 <event_assign+609>
0x0000000000529b6b <event_assign+123>:  nopl 0x0(%rax,%rax,1)
0x0000000000529b70 <event_assign+128>:  cmp %rbx,0x8(%rax)
0x0000000000529b74 <event_assign+132>:  je    0x529d4e <event_assign+606>
0x0000000000529b7a <event_assign+138>:  mov (%rax),%rax
0x0000000000529b7d <event_assign+141>:  test %rax,%rax
0x0000000000529b80 <event_assign+144>:  jne 0x529b70 <event_assign+128>
0x0000000000529b82 <event_assign+146>:  mov 0x2e99af(%rip),%rsi       # 0x813538 <_event_debug_map_lock>
0x0000000000529b89 <event_assign+153>:  test %rsi,%rsi
0x0000000000529b8c <event_assign+156>:  je    0x529b96 <event_assign+166>
0x0000000000529b8e <event_assign+158>:  xor %edi,%edi
0x0000000000529b90 <event_assign+160>:  callq  *0x2e9a2a(%rip)       # 0x8135c0 <_evthread_lock_fns+32>
0x0000000000529b96 <event_assign+166>:  movswl %r12w,%eax
0x0000000000529b9a <event_assign+170>:  mov %rbp,0x38(%rbx)
0x0000000000529b9e <event_assign+174>:  mov %r13,0x80(%rbx)
0x0000000000529ba5 <event_assign+181>:  test $0x8,%al
0x0000000000529ba7 <event_assign+183>:  mov %r14,0x88(%rbx)
0x0000000000529bae <event_assign+190>:  mov %r15d,0x30(%rbx)
0x0000000000529bb2 <event_assign+194>:  mov %r12w,0x64(%rbx)
0x0000000000529bb7 <event_assign+199>:  movw $0x0,0x66(%rbx)
0x0000000000529bbd <event_assign+205>:  movw $0x80,0x68(%rbx)
0x0000000000529bc3 <event_assign+211>:  movw $0x0,0x50(%rbx)
0x0000000000529bc9 <event_assign+217>:  movq $0x0,0x58(%rbx)
0x0000000000529bd1 <event_assign+225>:  je    0x529d10 <event_assign+544>
0x0000000000529bd7 <event_assign+231>:  test $0x6,%al
0x0000000000529bd9 <event_assign+233>:  jne 0x529d90 <event_assign+672>
0x0000000000529bdf <event_assign+239>:  movb $0x1,0x6b(%rbx)
0x0000000000529be3 <event_assign+243>:  test %rbp,%rbp
0x0000000000529be6 <event_assign+246>:  movl $0xffffffff,0x20(%rbx)
0x0000000000529bed <event_assign+253>:  je    0x529c01 <event_assign+273>
---Type <return> to continue, or q <return> to quit---
0x0000000000529bef <event_assign+255>:  mov 0x100(%rbp),%edx
0x0000000000529bf5 <event_assign+261>:  mov %edx,%eax
0x0000000000529bf7 <event_assign+263>:  shr $0x1f,%eax
0x0000000000529bfa <event_assign+266>:  add %edx,%eax
0x0000000000529bfc <event_assign+268>:  sar %eax
0x0000000000529bfe <event_assign+270>:  mov %eax,0x60(%rbx)
0x0000000000529c01 <event_assign+273>:  mov 0x2e9929(%rip),%eax       # 0x813530 <_event_debug_mode_on>
0x0000000000529c07 <event_assign+279>:  test %eax,%eax
0x0000000000529c09 <event_assign+281>:  je    0x529cf1 <event_assign+513>
0x0000000000529c0f <event_assign+287>:  mov 0x2e9922(%rip),%rsi       # 0x813538 <_event_debug_map_lock>
0x0000000000529c16 <event_assign+294>:  test %rsi,%rsi
0x0000000000529c19 <event_assign+297>:  je    0x529c23 <event_assign+307>
0x0000000000529c1b <event_assign+299>:  xor %edi,%edi
0x0000000000529c1d <event_assign+301>:  callq  *0x2e9995(%rip)       # 0x8135b8 <_evthread_lock_fns+24>
0x0000000000529c23 <event_assign+307>:  mov 0x2b18b6(%rip),%rcx       # 0x7db4e0 <global_debug_map>
0x0000000000529c2a <event_assign+314>:  test %rcx,%rcx
0x0000000000529c2d <event_assign+317>:  je    0x529c72 <event_assign+386>
0x0000000000529c2f <event_assign+319>:  mov %ebx,%eax
0x0000000000529c31 <event_assign+321>:  xor %edx,%edx
0x0000000000529c33 <event_assign+323>:  shr $0x6,%eax
0x0000000000529c36 <event_assign+326>:  divl 0x2b18ac(%rip)       # 0x7db4e8 <global_debug_map+8>
0x0000000000529c3c <event_assign+332>:  mov %edx,%edx
0x0000000000529c3e <event_assign+334>:  mov (%rcx,%rdx,8),%rdx
0x0000000000529c42 <event_assign+338>:  test %rdx,%rdx
0x0000000000529c45 <event_assign+341>:  mov %rdx,%rax
0x0000000000529c48 <event_assign+344>:  je    0x529c72 <event_assign+386>
0x0000000000529c4a <event_assign+346>:  cmp 0x8(%rdx),%rbx
0x0000000000529c4e <event_assign+350>:  jne 0x529c66 <event_assign+374>
0x0000000000529c50 <event_assign+352>:  jmpq 0x529d87 <event_assign+663>
0x0000000000529c55 <event_assign+357>:  cmp 0x8(%rax),%rbx
0x0000000000529c59 <event_assign+361>:  nopl 0x0(%rax)
0x0000000000529c60 <event_assign+368>:  je    0x529d84 <event_assign+660>
0x0000000000529c66 <event_assign+374>:  mov (%rax),%rax
0x0000000000529c69 <event_assign+377>:  test %rax,%rax
0x0000000000529c6c <event_assign+380>:  nopl 0x0(%rax)
0x0000000000529c70 <event_assign+384>:  jne 0x529c55 <event_assign+357>
0x0000000000529c72 <event_assign+386>:  mov $0x18,%edi
0x0000000000529c77 <event_assign+391>:  callq  0x5282d0 <event_mm_malloc_>
0x0000000000529c7c <event_assign+396>:  test %rax,%rax
0x0000000000529c7f <event_assign+399>:  mov %rax,%rbp
0x0000000000529c82 <event_assign+402>:  je    0x529dab <event_assign+699>
0x0000000000529c88 <event_assign+408>:  andb $0xfe,0x10(%rax)
0x0000000000529c8c <event_assign+412>:  mov %rbx,0x8(%rax)
0x0000000000529c90 <event_assign+416>:  cmpq $0x0,0x2b1848(%rip)       # 0x7db4e0 <global_debug_map>
0x0000000000529c98 <event_assign+424>:  je    0x529d36 <event_assign+582>
0x0000000000529c9e <event_assign+430>:  mov 0x2b1848(%rip),%eax       # 0x7db4ec <global_debug_map+12>
0x0000000000529ca4 <event_assign+436>:  cmp 0x2b1846(%rip),%eax       # 0x7db4f0 <global_debug_map+16>
0x0000000000529caa <event_assign+442>:  jae 0x529d36 <event_assign+582>
0x0000000000529cb0 <event_assign+448>:  addl $0x1,0x2b1835(%rip)       # 0x7db4ec <global_debug_map+12>
0x0000000000529cb7 <event_assign+455>:  xor %edx,%edx
0x0000000000529cb9 <event_assign+457>:  mov 0x8(%rbp),%rax
0x0000000000529cbd <event_assign+461>:  shr $0x6,%eax
0x0000000000529cc0 <event_assign+464>:  divl 0x2b1822(%rip)       # 0x7db4e8 <global_debug_map+8>
0x0000000000529cc6 <event_assign+470>:  mov %edx,%edx
0x0000000000529cc8 <event_assign+472>:  shl $0x3,%rdx
0x0000000000529ccc <event_assign+476>:  add 0x2b180d(%rip),%rdx       # 0x7db4e0 <global_debug_map>
0x0000000000529cd3 <event_assign+483>:  mov (%rdx),%rax
0x0000000000529cd6 <event_assign+486>:  mov %rax,0x0(%rbp)
0x0000000000529cda <event_assign+490>:  mov %rbp,(%rdx)
0x0000000000529cdd <event_assign+493>:  mov 0x2e9854(%rip),%rsi       # 0x813538 <_event_debug_map_lock>
0x0000000000529ce4 <event_assign+500>:  test %rsi,%rsi
0x0000000000529ce7 <event_assign+503>:  je    0x529cf1 <event_assign+513>
0x0000000000529ce9 <event_assign+505>:  xor %edi,%edi
0x0000000000529ceb <event_assign+507>:  callq  *0x2e98cf(%rip)       # 0x8135c0 <_evthread_lock_fns+32>
0x0000000000529cf1 <event_assign+513>:  movl $0x1,0x2e985d(%rip)       # 0x813558 <event_debug_mode_too_late>
0x0000000000529cfb <event_assign+523>:  xor %eax,%eax
0x0000000000529cfd <event_assign+525>:  add $0x8,%rsp
0x0000000000529d01 <event_assign+529>:  pop %rbx
---Type <return> to continue, or q <return> to quit---
0x0000000000529d02 <event_assign+530>:  pop %rbp
0x0000000000529d03 <event_assign+531>:  pop %r12
0x0000000000529d05 <event_assign+533>:  pop %r13
0x0000000000529d07 <event_assign+535>:  pop %r14
0x0000000000529d09 <event_assign+537>:  pop %r15
0x0000000000529d0b <event_assign+539>:  retq
0x0000000000529d0c <event_assign+540>:  nopl 0x0(%rax)
0x0000000000529d10 <event_assign+544>:  test $0x10,%al
0x0000000000529d12 <event_assign+546>:  je    0x529d2d <event_assign+573>
0x0000000000529d14 <event_assign+548>:  movq $0x0,0x58(%rbx)
0x0000000000529d1c <event_assign+556>:  movq $0x0,0x50(%rbx)
0x0000000000529d24 <event_assign+564>:  movb $0x2,0x6b(%rbx)
0x0000000000529d28 <event_assign+568>:  jmpq 0x529be3 <event_assign+243>
0x0000000000529d2d <event_assign+573>:  movb $0x0,0x6b(%rbx)
0x0000000000529d31 <event_assign+577>:  jmpq 0x529be3 <event_assign+243>
0x0000000000529d36 <event_assign+582>:  mov 0x2b17b0(%rip),%esi       # 0x7db4ec <global_debug_map+12>
0x0000000000529d3c <event_assign+588>:  mov $0x7db4e0,%edi
0x0000000000529d41 <event_assign+593>:  add $0x1,%esi
0x0000000000529d44 <event_assign+596>:  callq  0x528370 <event_debug_map_HT_GROW>
0x0000000000529d49 <event_assign+601>:  jmpq 0x529cb0 <event_assign+448>
0x0000000000529d4e <event_assign+606>:  mov %rax,%rdx
0x0000000000529d51 <event_assign+609>:  testb  $0x1,0x10(%rdx)
0x0000000000529d55 <event_assign+613>:  je    0x529b82 <event_assign+146>
0x0000000000529d5b <event_assign+619>:  movswl 0x68(%rbx),%eax
0x0000000000529d5f <event_assign+623>:  movswl 0x64(%rbx),%r8d
0x0000000000529d64 <event_assign+628>:  mov %rbx,%rcx
0x0000000000529d67 <event_assign+631>:  mov 0x30(%rbx),%r9d
0x0000000000529d6b <event_assign+635>:  mov $0x57bc79,%edx
0x0000000000529d70 <event_assign+640>:  mov $0x57b610,%esi
0x0000000000529d75 <event_assign+645>:  mov $0xdeaddead,%edi
0x0000000000529d7a <event_assign+650>:  mov %eax,(%rsp)
0x0000000000529d7d <event_assign+653>:  xor %eax,%eax
0x0000000000529d7f <event_assign+655>:  callq  0x5368e0 <event_errx>
0x0000000000529d84 <event_assign+660>:  mov %rax,%rdx
0x0000000000529d87 <event_assign+663>:  andb $0xfe,0x10(%rdx)
0x0000000000529d8b <event_assign+667>:  jmpq 0x529cdd <event_assign+493>
0x0000000000529d90 <event_assign+672>:  xor %eax,%eax
0x0000000000529d92 <event_assign+674>:  mov $0x57bc79,%esi
0x0000000000529d97 <event_assign+679>:  mov $0x57b660,%edi
0x0000000000529d9c <event_assign+684>:  callq  0x536810 <event_warnx>
0x0000000000529da1 <event_assign+689>:  mov $0xffffffff,%eax
0x0000000000529da6 <event_assign+694>:  jmpq 0x529cfd <event_assign+525>
0x0000000000529dab <event_assign+699>:  mov $0x57b6a0,%esi
0x0000000000529db0 <event_assign+704>:  mov $0x1,%edi
0x0000000000529db5 <event_assign+709>:  xor %eax,%eax
0x0000000000529db7 <event_assign+711>:  callq  0x536bb0 <event_err>
End of assembler dump.

1万 · 2015-3-11 15:36

使用gdb命令获取当前pc(程序计数器)，用来确定当前执行位置位于上述反汇编代码的位置。
(gdb) i r pc

1万 · 2015-3-11 15:39

然后使用，gdb指令查看当前执行指令所操作的寄存器或者地址。类似：
(gdb) i r xxx

其中xxx为所要查看寄存器。

1万 · 2015-3-11 15:44

本帖最后由 keer_zu 于 2015-3-11 15:46 编辑

忽然，再看到堆栈：

#0 event_assign (ev=0x888c30, base=0x786966657270222c, fd=16, events=4, callback=0x4412ac <on_connect(int, short, void*)>, arg=0x889360

的时候，发现 base=0x786966657270222c 这个异常地址，并且c语言也定位在：
event.c:1752
1752 ev->ev_pri = base->nactivequeues / 2;

看来不用反汇编那么麻烦了。问题就出在base上。再看一下堆栈第12层：

#12 0x000000000052c6c8 in event_process_active_single_queue (base=0x87a810, flags=0) at event.c:1346

base=0x87a810，因为base的值是全局唯一的，所以一定是在某处被错误修改了。

至此找到了努力的方向：就是到底在哪里base被错误修改，怎么被错误修改的。难道是某处溢出？

要想知道到底为何，且听下回分解！

1万 · 2015-3-11 15:57

base是全局的，任何地方都有可能被错误的操作改变。

难道需要到处都添加打印吗？那样真的累死人。

1万 · 2015-3-11 15:59

:L分享经验呢，居然没人响应。。。。。。

只看该作者 · 2015-3-11 17:02

不明觉厉:lol

只看该作者 · 2015-3-11 17:20

要下班了来顶个贴

2万 · 2015-3-11 20:37

哈哈支持原创

2万 · 2015-3-11 20:56

0000000000000000 - 00007fffffffffff (=47 bits) user space,

一定要有这个敏感性，看一眼就得发现base地址有问题。

1万 · 2015-3-11 20:59

原野之狼发表于 2015-3-11 20:56
0000000000000000 - 00007fffffffffff (=47 bits) user space,

一定要有这个敏感性，看一眼就得发现base地 ...

刚过完节，心思不在上面，却是很明显。

只看该作者 · 2015-3-11 21:43

不明觉厉

1万 · 2015-3-11 22:55

没有心情看你的汇编,太长了.
看到 786966657270222c = ASCII(xiferp",) 全部都是ASCII, 就感觉可能是string copy等的时候溢出的. 不过不知道是否多线程.
分享个经验, 对付内存野指针和堆栈, 就是用C#写代码. 再也不用c++年代的codeguard或者fastmemory等了,修改new和malloc等C run time library 往往很难做到兼容性特别好.

1万 · 2015-3-11 23:03

怀疑在 cdy::ConnectorImp::Connect (this=0x889360, timeout=3000) at ../src/connbaseimp.cpp:274 这个函数里面,单步走一下看看.
第12级和第0级堆栈有base, 而中间的很多函数没有, 这个base是全局变量么? 看前面的堆栈都还好着. 单线程的话还是单步走来的快.