FYI, hard-to-reproduce segfault at start-up (clone/getenv race?)

emacs-devel
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
FYI, hard-to-reproduce segfault at start-up (clone/getenv race?)

From:	Jim Meyering
Subject:	FYI, hard-to-reproduce segfault at start-up (clone/getenv race?)
Date:	Wed, 02 Apr 2008 00:33:50 +0200
Hello,

I've been experiencing rare segfaults at start-up, and finally made
time to catch one in the debugger today.  It took at least 12 attempts;
numerous changes in scenario made it unreproducible altogether.

I've noticed this in snapshots built at least during the last week or so.
Maybe as far back as March 14.  I haven't explored that dimension at
all yet, since the failure is not easily reproducible.

This is using a git snapshot built a few hours ago.

Here's the backtrace:

#0  0x00002ab4184303a1 in getenv () from /lib/libc.so.6
#1  0x00002ab418429509 in __dcigettext () from /lib/libc.so.6
#2  0x00002ab4147863c0 in ?? () from /usr/lib/libgtk-x11-2.0.so.0
#3  0x00002ab415d15c29 in g_type_class_ref () from /usr/lib/libgobject-2.0.so.0
#4  0x00002ab415cfca87 in g_object_newv () from /usr/lib/libgobject-2.0.so.0
#5  0x00002ab415cfcfc2 in g_object_new_valist ()
   from /usr/lib/libgobject-2.0.so.0
#6  0x00002ab415cfd101 in g_object_new () from /usr/lib/libgobject-2.0.so.0
#7  0x00002ab41478627d in gtk_alignment_new () from /usr/lib/libgtk-x11-2.0.so.0
#8  0x00002ab41492121e in ?? () from /usr/lib/libgtk-x11-2.0.so.0
#9  0x00002ab415d16463 in g_type_create_instance ()
   from /usr/lib/libgobject-2.0.so.0
#10 0x00002ab415cfbedd in ?? () from /usr/lib/libgobject-2.0.so.0
#11 0x00002ab415cfc4d0 in g_object_newv () from /usr/lib/libgobject-2.0.so.0
#12 0x00002ab415cfcfc2 in g_object_new_valist ()
   from /usr/lib/libgobject-2.0.so.0
#13 0x00002ab415cfd101 in g_object_new () from /usr/lib/libgobject-2.0.so.0
#14 0x00002ab414920a07 in ?? () from /usr/lib/libgtk-x11-2.0.so.0
#15 0x00002ab41485572f in gtk_main_do_event () from /usr/lib/libgtk-x11-2.0.so.0
#16 0x00002ab414d1314c in ?? () from /usr/lib/libgdk-x11-2.0.so.0
#17 0x00002ab41636cf92 in g_main_context_dispatch ()
   from /usr/lib/libglib-2.0.so.0
#18 0x00002ab416370236 in ?? () from /usr/lib/libglib-2.0.so.0
#19 0x00002ab4163706cf in g_main_context_iteration ()
   from /usr/lib/libglib-2.0.so.0
#20 0x00002ab414855a21 in gtk_main_iteration ()
   from /usr/lib/libgtk-x11-2.0.so.0
#21 0x000000000049cd4b in XTread_socket (terminal=0x129c480,
    expected=<value optimized out>, hold_quit=0x7fff9659eb80)
    at /mirror/d/emacs/src/xterm.c:7442
#22 0x00000000004e2465 in read_avail_input (expected=1)
    at /mirror/d/emacs/src/keyboard.c:7123
#23 0x00000000004e255a in handle_async_input ()
    at /mirror/d/emacs/src/keyboard.c:7354
#24 0x0000000000582c15 in Fcall_process (nargs=7, args=0x7fff965af208)
    at /mirror/d/emacs/src/callproc.c:597
#25 0x000000000054b2d5 in Ffuncall (nargs=8, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3006
#26 0x000000000054c909 in Fapply (nargs=6, args=0x7fff965af328)
    at /mirror/d/emacs/src/eval.c:2513
#27 0x000000000054b2d5 in Ffuncall (nargs=7, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3006
#28 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11326049, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#29 0x000000000054ac58 in funcall_lambda (fun=8932252, nargs=7,
    arg_vector=0x7fff965af508) at /mirror/d/emacs/src/eval.c:3212
#30 0x000000000054b014 in Ffuncall (nargs=8, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#31 0x000000000054c909 in Fapply (nargs=7, args=0x7fff965af628)
    at /mirror/d/emacs/src/eval.c:2513
#32 0x000000000054b2d5 in Ffuncall (nargs=8, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3006
#33 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11326049, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#34 0x000000000054ac58 in funcall_lambda (fun=18702244, nargs=4,
    arg_vector=0x7fff965af7f8) at /mirror/d/emacs/src/eval.c:3212
#35 0x000000000054b014 in Ffuncall (nargs=5, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#36 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=17366340, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#37 0x000000000054ac58 in funcall_lambda (fun=18274116, nargs=0,
    arg_vector=0x7fff965af9b8) at /mirror/d/emacs/src/eval.c:3212
#38 0x000000000054b014 in Ffuncall (nargs=1, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#39 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>, vector=0,
    maxdepth=<value optimized out>) at /mirror/d/emacs/src/bytecode.c:679
#40 0x000000000054ac58 in funcall_lambda (fun=17824740, nargs=1,
    arg_vector=0x7fff965afc60) at /mirror/d/emacs/src/eval.c:3212
#41 0x000000000054b014 in Ffuncall (nargs=2, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#42 0x000000000054ca16 in Fapply (nargs=2, args=0x7fff965afc58)
    at /mirror/d/emacs/src/eval.c:2458
#43 0x000000000054b2d5 in Ffuncall (nargs=3, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3006
#44 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11326049, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#45 0x000000000054ac58 in funcall_lambda (fun=25038868, nargs=3,
    arg_vector=0x7fff965afe28) at /mirror/d/emacs/src/eval.c:3212
#46 0x000000000054b014 in Ffuncall (nargs=4, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#47 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11294785, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#48 0x000000000054ac58 in funcall_lambda (fun=24676468, nargs=2,
    arg_vector=0x7fff965b00b0) at /mirror/d/emacs/src/eval.c:3212
#49 0x000000000054b014 in Ffuncall (nargs=3, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#50 0x000000000054ca16 in Fapply (nargs=3, args=0x7fff965b00a8)
    at /mirror/d/emacs/src/eval.c:2458
#51 0x000000000054b2d5 in Ffuncall (nargs=4, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3006
#52 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11326049, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#53 0x000000000054ac58 in funcall_lambda (fun=25038868, nargs=3,
    arg_vector=0x7fff965b0290) at /mirror/d/emacs/src/eval.c:3212
#54 0x000000000054b014 in Ffuncall (nargs=4, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#55 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11294785, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#56 0x000000000054ac58 in funcall_lambda (fun=16698372, nargs=1,
    arg_vector=0x7fff965b0448) at /mirror/d/emacs/src/eval.c:3212
#57 0x000000000054b014 in Ffuncall (nargs=2, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#58 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11294785, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#59 0x000000000054ac58 in funcall_lambda (fun=14930868, nargs=2,
    arg_vector=0x7fff965b0618) at /mirror/d/emacs/src/eval.c:3212
#60 0x000000000054b014 in Ffuncall (nargs=3, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#61 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11294785, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#62 0x000000000054ac58 in funcall_lambda (fun=17288276, nargs=1,
    arg_vector=0x7fff965b08b0) at /mirror/d/emacs/src/eval.c:3212
#63 0x000000000054b014 in Ffuncall (nargs=2, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#64 0x000000000054ca16 in Fapply (nargs=2, args=0x7fff965b08a8)
    at /mirror/d/emacs/src/eval.c:2458
#65 0x000000000054b2d5 in Ffuncall (nargs=3, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3006
#66 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11326049, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#67 0x000000000054ac58 in funcall_lambda (fun=25038868, nargs=3,
    arg_vector=0x7fff965b0a78) at /mirror/d/emacs/src/eval.c:3212
#68 0x000000000054b014 in Ffuncall (nargs=4, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#69 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11294785, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#70 0x000000000054ac58 in funcall_lambda (fun=23837700, nargs=1,
    arg_vector=0x7fff965b0c58) at /mirror/d/emacs/src/eval.c:3212
#71 0x000000000054b014 in Ffuncall (nargs=2, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#72 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11012961, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#73 0x000000000054ac58 in funcall_lambda (fun=15884676, nargs=0,
    arg_vector=0x7fff965b0e58) at /mirror/d/emacs/src/eval.c:3212
#74 0x000000000054b014 in Ffuncall (nargs=1, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#75 0x000000000054c6a5 in run_hook_with_args (nargs=1, args=0x7fff965b0e50,
    cond=to_completion) at /mirror/d/emacs/src/eval.c:2684
#76 0x000000000054c7e3 in Frun_hooks (nargs=1, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:2547
#77 0x000000000054b2d5 in Ffuncall (nargs=2, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3006
#78 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>, vector=1,
    maxdepth=<value optimized out>) at /mirror/d/emacs/src/bytecode.c:679
#79 0x000000000054ac58 in funcall_lambda (fun=8606636, nargs=2,
    arg_vector=0x7fff965b10e8) at /mirror/d/emacs/src/eval.c:3212
#80 0x000000000054b014 in Ffuncall (nargs=3, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#81 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=20842737, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#82 0x000000000054ac58 in funcall_lambda (fun=8603188, nargs=6,
    arg_vector=0x7fff965b1298) at /mirror/d/emacs/src/eval.c:3212
#83 0x000000000054b014 in Ffuncall (nargs=7, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#84 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11081105, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#85 0x000000000054ac58 in funcall_lambda (fun=8601324, nargs=4,
    arg_vector=0x7fff965b1468) at /mirror/d/emacs/src/eval.c:3212
#86 0x000000000054b014 in Ffuncall (nargs=5, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#87 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=10938593, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#88 0x000000000054ac58 in funcall_lambda (fun=8592268, nargs=2,
    arg_vector=0x7fff965b1590) at /mirror/d/emacs/src/eval.c:3212
#89 0x000000000054adae in apply_lambda (fun=8592268, args=10764001, eval_flag=1)
    at /mirror/d/emacs/src/eval.c:3136
#90 0x000000000054a456 in Feval (form=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:2416
#91 0x000000000054a8ed in Fsetq (args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:553
#92 0x000000000054a857 in Feval (form=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:2303
#93 0x000000000054aa21 in Fprogn (args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:451
#94 0x000000000054d08b in Flet (args=17315157)
    at /mirror/d/emacs/src/eval.c:1072
#95 0x000000000054a857 in Feval (form=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:2303
#96 0x000000000054aa21 in Fprogn (args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:451
#97 0x000000000054acaf in funcall_lambda (fun=17315248, nargs=1,
    arg_vector=0x7fff965b1a18) at /mirror/d/emacs/src/eval.c:3205
#98 0x000000000054b014 in Ffuncall (nargs=2, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#99 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11294785, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#100 0x000000000054ac58 in funcall_lambda (fun=8787204, nargs=1,
    arg_vector=0x7fff965b1bf8) at /mirror/d/emacs/src/eval.c:3212
#101 0x000000000054b014 in Ffuncall (nargs=2, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#102 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11065009, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#103 0x000000000054ac58 in funcall_lambda (fun=8760484, nargs=0,
    arg_vector=0x7fff965b1dc8) at /mirror/d/emacs/src/eval.c:3212
#104 0x000000000054b014 in Ffuncall (nargs=1, args=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:3082
#105 0x00000000005757b7 in Fbyte_code (bytestr=<value optimized out>,
    vector=11012865, maxdepth=<value optimized out>)
    at /mirror/d/emacs/src/bytecode.c:679
#106 0x000000000054ac58 in funcall_lambda (fun=8753956, nargs=0,
    arg_vector=0x7fff965b1ef0) at /mirror/d/emacs/src/eval.c:3212
#107 0x000000000054adae in apply_lambda (fun=8753956, args=10764001,
    eval_flag=1) at /mirror/d/emacs/src/eval.c:3136
#108 0x000000000054a456 in Feval (form=<value optimized out>)
    at /mirror/d/emacs/src/eval.c:2416
#109 0x0000000000549a3f in internal_condition_case (
    bfun=0x4e2060 <top_level_2>, handlers=10851025, hfun=0x4e7460 <cmd_error>)
    at /mirror/d/emacs/src/eval.c:1494
#110 0x00000000004e67ba in top_level_1 () at /mirror/d/emacs/src/keyboard.c:1387
#111 0x0000000000549b57 in internal_catch (tag=<value optimized out>,
    func=0x4e6790 <top_level_1>, arg=10764001)
    at /mirror/d/emacs/src/eval.c:1230
#112 0x00000000004e728b in command_loop ()
    at /mirror/d/emacs/src/keyboard.c:1342
#113 0x00000000004e763a in recursive_edit_1 ()
    at /mirror/d/emacs/src/keyboard.c:958
#114 0x00000000004e778f in Frecursive_edit ()
    at /mirror/d/emacs/src/keyboard.c:1020
#115 0x00000000004dafac in main (argc=4, argv=0x7fff965b2728)
    at /mirror/d/emacs/src/emacs.c:1784

I'll leave the gdb session around, in case someone wants
more info from it.

I was running this command on a uniprocessor AMD-64:

  gdb --args /f/p/bin/emacs ../misc-scripts/find_iscsi_devices.sh \
    ../misc-scripts/gencerts.sh ../misc-scripts/mount-livecd.sh

Since it's getenv that's failing, I suspect that one thread
changes the environment at just the wrong moment, while the one
above is calling getenv.

The system: debian unstable, libc6 2.7-10, linux-2.6.24-1-amd64.
Emacs was configured/bootstrapped with --disable-nls and CFLAGS='-O2 -g'
So far, I've been unable to reproduce the failure on a rawhide-based
system, so this may be debian-specific.

I'll try to spend more time on it tomorrow.

Before using gdb, I got some details with strace.
Here's the tail of one run:
[note that this is visiting git-version-controlled files,
 and I do enable git in vc-mode.
  (add-to-list 'vc-handled-backends 'GIT)
 Also (2nd case below), I enable flyspell-prog-mode:
  (add-hook 'sh-mode-hook 'flyspell-prog-mode)
]

----------------------------
...
geteuid()                               = 1000
getegid()                               = 1000
getuid()                                = 1000
getgid()                                = 1000
access("/mirror/d/ovirt/misc-scripts", X_OK) = 0
open("/dev/null", O_RDONLY)             = 4
stat("/e/meyering/bin/perl/git", 0x7fff1870a930) = -1 ENOENT (No such file or 
directory)
stat("/e/meyering/bin/git", 0x7fff1870a930) = -1 ENOENT (No such file or 
directory)
stat("/p/p/git/bin/git", {st_mode=S_IFREG|0755, st_size=3712294, ...}) = 0
access("/p/p/git/bin/git", X_OK)        = 0
pipe([5, 7])                            = 0
open("/dev/null", O_WRONLY)             = 8
vfork()                                 = ? ERESTARTNOINTR (To be restarted)
--- SIGIO (I/O possible) @ 0 (0) ---
rt_sigreturn(0x1d)                      = 56
clone(child_stack=0x1587, 
flags=CLONE_VM|CLONE_FS|CLONE_PTRACE|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_DETACHED|SIGSTKFLT,
 parent_tidptr=0xffffea79, tls=0x18b18f0) = 5536

And the strace log for the child PID, 5536 contained only two lines:

--- SIGSEGV (Segmentation fault) @ 0 (0) ---
--- SIGSEGV (Segmentation fault) @ 0 (0) ---
----------------------------

And another very similar one:

...
stat("/mirror/d/ovirt/ovirt-host-creator", {st_mode=S_IFDIR|0755, 
st_size=12288, ...}) = 0
geteuid()                               = 1000
getegid()                               = 1000
getuid()                                = 1000
getgid()                                = 1000
access("/mirror/d/ovirt/ovirt-host-creator", X_OK) = 0
open("/dev/null", O_RDONLY)             = 6
stat("/usr/bin/aspell", {st_mode=S_IFREG|0755, st_size=176136, ...}) = 0
access("/usr/bin/aspell", X_OK)         = 0
pipe([7, 8])                            = 0
vfork()                                 = ? ERESTARTNOINTR (To be restarted)
--- SIGIO (I/O possible) @ 0 (0) ---
rt_sigreturn(0x1d)                      = 56
clone(child_stack=0x39a, 
flags=CLONE_VM|CLONE_FS|CLONE_PTRACE|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_DETACHED|SIGSTKFLT,
 parent_tidptr=0xfffffc66, tls=0) = 937

where the child strace log file contained the same two SIGSEGV lines.
[Prev in Thread]
Current Thread
[Next in Thread]
FYI, hard-to-reproduce segfault at start-up (clone/getenv race?), Jim Meyering <=
Prev by Date: Re: undo bug?
Next by Date: Re: Exchange 2007 Issues When Copying Between Folders
Previous by thread: parse-partial-sexp parses only Lisp?
Next by thread: Re: 23.0.60; Resizing may delete windows
Index(es):
- Date
- Thread